[syzbot] [kernel?] KMSAN: uninit-value in profile_hits (3)

[syzbot] [kernel?] KMSAN: uninit-value in profile_hits (3)

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit:    1978a14f70af x86: kmsan: enable KMSAN builds for x86
git tree:       https://github.com/google/kmsan.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=13b7a95b700000
kernel config:  https://syzkaller.appspot.com/x/.config?x=d830111cc3be873
dashboard link: https://syzkaller.appspot.com/bug?extid=b1a83ab2a9eb9321fbdd
compiler:       clang version 14.0.0 (/usr/local/google/src/llvm-git-monorepo 2b554920f11c8b763cd9ed9003f4e19b919b8e1f), GNU ld (GNU Binutils for Debian) 2.35.2
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=14b5476b700000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=142c9237700000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com

=====================================================
BUG: KMSAN: uninit-value in do_profile_hits kernel/profile.c:236 [inline]
BUG: KMSAN: uninit-value in profile_hits+0xaf2/0x1260 kernel/profile.c:326
 do_profile_hits kernel/profile.c:236 [inline]
 profile_hits+0xaf2/0x1260 kernel/profile.c:326
 profile_hit include/linux/profile.h:58 [inline]
 profile_tick+0x241/0x250 kernel/profile.c:336
 tick_sched_handle kernel/time/tick-sched.c:227 [inline]
 tick_sched_timer+0x4bd/0x610 kernel/time/tick-sched.c:1428
 __run_hrtimer+0x49f/0xc50 kernel/time/hrtimer.c:1685
 __hrtimer_run_queues kernel/time/hrtimer.c:1749 [inline]
 hrtimer_interrupt+0x7f7/0x2100 kernel/time/hrtimer.c:1811
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1086 [inline]
 __sysvec_apic_timer_interrupt+0x178/0x5e0 arch/x86/kernel/apic/apic.c:1103
 sysvec_apic_timer_interrupt+0x9d/0xc0 arch/x86/kernel/apic/apic.c:1097
 asm_sysvec_apic_timer_interrupt+0x12/0x20
 __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:160 [inline]
 _raw_spin_unlock_irq+0x36/0x60 kernel/locking/spinlock.c:202
 spin_unlock_irq include/linux/spinlock.h:399 [inline]
 __set_current_blocked+0xb0c/0xb90 kernel/signal.c:3051
 sigprocmask kernel/signal.c:3085 [inline]
 __do_sys_rt_sigprocmask kernel/signal.c:3162 [inline]
 __se_sys_rt_sigprocmask+0x438/0x5b0 kernel/signal.c:3145
 __x64_sys_rt_sigprocmask+0x11e/0x170 kernel/signal.c:3145
 do_syscall_x64 arch/x86/entry/common.c:51 [inline]
 do_syscall_64+0x54/0xd0 arch/x86/entry/common.c:81
 entry_SYSCALL_64_after_hwframe+0x44/0xae

Local variable iter.i created at:
 new_sync_read fs/read_write.c:393 [inline]
 vfs_read+0xb8a/0x1980 fs/read_write.c:481
 ksys_read+0x28b/0x510 fs/read_write.c:619

CPU: 1 PID: 3474 Comm: sshd Not tainted 5.17.0-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
=====================================================


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the report is already addressed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

If you want to overwrite report's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the report is a duplicate of another one, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

Re: [syzbot] [kernel?] KMSAN: uninit-value in profile_hits (3)

[Tetsuo Handa]

[PATCH] profiling: initialize prof_cpu_mask from profile_online_cpu()

syzbot is reporting uninit-value at profile_hits(), for commit acd895795d35
("profiling: fix broken profiling regression") by error initialized
prof_cpu_mask too early.

do_profile_hits() is called from profile_tick() from timer interrupt
only if cpumask_test_cpu(smp_processor_id(), prof_cpu_mask) is true and
prof_buffer is not NULL. But the syzbot's report says that profile_hits()
was called while current thread is still doing vzalloc(buffer_bytes)
where prof_buffer is NULL at this moment. This indicates two things.

One is that cpumask_set_cpu(cpu, prof_cpu_mask) should have been called
 from profile_online_cpu() from cpuhp_setup_state() only after
profile_init() completed. Fix this by explicitly calling cpumask_copy()
 from create_proc_profile() on only UP kernels.

The other is that multiple threads concurrently tried to write to
/sys/kernel/profiling interface, which caused that somebody else tried
to re-initialize prof_buffer despite somebody has already initialized
prof_buffer. Fix this by using serialization.

Reported-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
Closes: https://syzkaller.appspot.com/bug?extid=b1a83ab2a9eb9321fbdd
Fixes: acd895795d35 ("profiling: fix broken profiling regression")
Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
Please test before applying this patch; I don't know how to test this functionality.

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

 kernel/ksysfs.c  | 27 ++++++++++++++++++++++-----
 kernel/profile.c |  6 +++---
 2 files changed, 25 insertions(+), 8 deletions(-)

diff --git a/kernel/ksysfs.c b/kernel/ksysfs.c
index 1d4bc493b2f4..66bc712f590c 100644
--- a/kernel/ksysfs.c
+++ b/kernel/ksysfs.c
@@ -91,10 +91,23 @@ static ssize_t profiling_store(struct kobject *kobj,
 				   struct kobj_attribute *attr,
 				   const char *buf, size_t count)
 {
+	static DEFINE_MUTEX(lock);
 	int ret;
 
-	if (prof_on)
-		return -EEXIST;
+	/*
+	 * We need serialization, for profile_setup() initializes prof_on
+	 * value. Also, use killable wait in case memory allocation from
+	 * profile_init() triggered the OOM killer and chose current thread
+	 * blocked here.
+	 */
+	if (mutex_lock_killable(&lock))
+		return -EINTR;
+
+	if (prof_on) {
+		count = -EEXIST;
+		goto out;
+	}
+
 	/*
 	 * This eventually calls into get_option() which
 	 * has a ton of callers and is not const.  It is
@@ -102,11 +115,15 @@ static ssize_t profiling_store(struct kobject *kobj,
 	 */
 	profile_setup((char *)buf);
 	ret = profile_init();
-	if (ret)
-		return ret;
+	if (ret) {
+		count = ret;
+		goto out;
+	}
 	ret = create_proc_profile();
 	if (ret)
-		return ret;
+		count = ret;
+out:
+	mutex_unlock(&lock);
 	return count;
 }
 KERNEL_ATTR_RW(profiling);
diff --git a/kernel/profile.c b/kernel/profile.c
index 8a77769bc4b4..7575747e2ac6 100644
--- a/kernel/profile.c
+++ b/kernel/profile.c
@@ -114,11 +114,9 @@ int __ref profile_init(void)
 
 	buffer_bytes = prof_len*sizeof(atomic_t);
 
-	if (!alloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
+	if (!zalloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
 		return -ENOMEM;
 
-	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
-
 	prof_buffer = kzalloc(buffer_bytes, GFP_KERNEL|__GFP_NOWARN);
 	if (prof_buffer)
 		return 0;
@@ -481,6 +479,8 @@ int __ref create_proc_profile(void)
 		goto err_state_prep;
 	online_state = err;
 	err = 0;
+#else
+	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
 #endif
 	entry = proc_create("profile", S_IWUSR | S_IRUGO,
 			    NULL, &profile_proc_ops);
-- 
2.18.4

Re: [syzbot] [kernel?] KMSAN: uninit-value in profile_hits (3)

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com

Tested on:

commit:         8735c7c8 Merge tag '6.7rc7-smb3-srv-fix' of git://git...
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=122dcf81e80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=b2fd2f495c90e6b7
dashboard link: https://syzkaller.appspot.com/bug?extid=b1a83ab2a9eb9321fbdd
compiler:       gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch:          https://syzkaller.appspot.com/x/patch.diff?x=13f021b5e80000

Note: testing is done by a robot and is best-effort only.

Re: [syzbot] Re: [syzbot] [kernel?] KMSAN: uninit-value in profile_hits (3)

[syzbot]

For archival purposes, forwarding an incoming command email to
linux-kernel@vger.kernel.org.

***

Subject: Re: [syzbot] [kernel?] KMSAN: uninit-value in profile_hits (3)
Author: eadavis@qq.com

please test uninit-value in profile_hits

#syz test https://github.com/google/kmsan.git master

diff --git a/kernel/profile.c b/kernel/profile.c
index 8a77769bc4b4..37f30292b626 100644
--- a/kernel/profile.c
+++ b/kernel/profile.c
@@ -114,7 +114,7 @@ int __ref profile_init(void)
 
 	buffer_bytes = prof_len*sizeof(atomic_t);
 
-	if (!alloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
+	if (!zalloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
 		return -ENOMEM;
 
 	cpumask_copy(prof_cpu_mask, cpu_possible_mask);

[PATCH] profiling: initialize prof_cpu_mask from profile_online_cpu()

[Tetsuo Handa]

syzbot is reporting uninit-value at profile_hits(), for commit acd895795d35
("profiling: fix broken profiling regression") by error initialized
prof_cpu_mask too early.

do_profile_hits() is called from profile_tick() from timer interrupt
only if cpumask_test_cpu(smp_processor_id(), prof_cpu_mask) is true and
prof_buffer is not NULL. But the syzbot's report says that profile_hits()
was called while current thread is still doing vzalloc(buffer_bytes)
where prof_buffer is NULL at this moment. This indicates two things.

One is that cpumask_set_cpu(cpu, prof_cpu_mask) should have been called
 from profile_online_cpu() from cpuhp_setup_state() only after
profile_init() completed. Fix this by explicitly calling cpumask_copy()
 from create_proc_profile() on only UP kernels.

The other is that multiple threads concurrently tried to write to
/sys/kernel/profiling interface, which caused that somebody else tried
to re-initialize prof_buffer despite somebody has already initialized
prof_buffer. Fix this by using serialization.

Reported-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
Closes: https://syzkaller.appspot.com/bug?extid=b1a83ab2a9eb9321fbdd
Fixes: acd895795d35 ("profiling: fix broken profiling regression")
Tested-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
 kernel/ksysfs.c  | 27 ++++++++++++++++++++++-----
 kernel/profile.c |  6 +++---
 2 files changed, 25 insertions(+), 8 deletions(-)

diff --git a/kernel/ksysfs.c b/kernel/ksysfs.c
index 1d4bc493b2f4..66bc712f590c 100644
--- a/kernel/ksysfs.c
+++ b/kernel/ksysfs.c
@@ -91,10 +91,23 @@ static ssize_t profiling_store(struct kobject *kobj,
 				   struct kobj_attribute *attr,
 				   const char *buf, size_t count)
 {
+	static DEFINE_MUTEX(lock);
 	int ret;
 
-	if (prof_on)
-		return -EEXIST;
+	/*
+	 * We need serialization, for profile_setup() initializes prof_on
+	 * value. Also, use killable wait in case memory allocation from
+	 * profile_init() triggered the OOM killer and chose current thread
+	 * blocked here.
+	 */
+	if (mutex_lock_killable(&lock))
+		return -EINTR;
+
+	if (prof_on) {
+		count = -EEXIST;
+		goto out;
+	}
+
 	/*
 	 * This eventually calls into get_option() which
 	 * has a ton of callers and is not const.  It is
@@ -102,11 +115,15 @@ static ssize_t profiling_store(struct kobject *kobj,
 	 */
 	profile_setup((char *)buf);
 	ret = profile_init();
-	if (ret)
-		return ret;
+	if (ret) {
+		count = ret;
+		goto out;
+	}
 	ret = create_proc_profile();
 	if (ret)
-		return ret;
+		count = ret;
+out:
+	mutex_unlock(&lock);
 	return count;
 }
 KERNEL_ATTR_RW(profiling);
diff --git a/kernel/profile.c b/kernel/profile.c
index 8a77769bc4b4..7575747e2ac6 100644
--- a/kernel/profile.c
+++ b/kernel/profile.c
@@ -114,11 +114,9 @@ int __ref profile_init(void)
 
 	buffer_bytes = prof_len*sizeof(atomic_t);
 
-	if (!alloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
+	if (!zalloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
 		return -ENOMEM;
 
-	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
-
 	prof_buffer = kzalloc(buffer_bytes, GFP_KERNEL|__GFP_NOWARN);
 	if (prof_buffer)
 		return 0;
@@ -481,6 +479,8 @@ int __ref create_proc_profile(void)
 		goto err_state_prep;
 	online_state = err;
 	err = 0;
+#else
+	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
 #endif
 	entry = proc_create("profile", S_IWUSR | S_IRUGO,
 			    NULL, &profile_proc_ops);
-- 
2.18.4

Re: [PATCH] profiling: initialize prof_cpu_mask from profile_online_cpu()

[Tetsuo Handa]

Hello, Linus.

It seems that nobody maintains this code.

Can I directly send this patch to you, as "THE REST" rule of MAINTAINERS file?
Is some tag like [PATCH ORPHANED] available?

On 2024/01/31 23:06, Tetsuo Handa wrote:
> syzbot is reporting uninit-value at profile_hits(), for commit acd895795d35
> ("profiling: fix broken profiling regression") by error initialized
> prof_cpu_mask too early.
> 
> do_profile_hits() is called from profile_tick() from timer interrupt
> only if cpumask_test_cpu(smp_processor_id(), prof_cpu_mask) is true and
> prof_buffer is not NULL. But the syzbot's report says that profile_hits()
> was called while current thread is still doing vzalloc(buffer_bytes)
> where prof_buffer is NULL at this moment. This indicates two things.
> 
> One is that cpumask_set_cpu(cpu, prof_cpu_mask) should have been called
>  from profile_online_cpu() from cpuhp_setup_state() only after
> profile_init() completed. Fix this by explicitly calling cpumask_copy()
>  from create_proc_profile() on only UP kernels.
> 
> The other is that multiple threads concurrently tried to write to
> /sys/kernel/profiling interface, which caused that somebody else tried
> to re-initialize prof_buffer despite somebody has already initialized
> prof_buffer. Fix this by using serialization.
> 
> Reported-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
> Closes: https://syzkaller.appspot.com/bug?extid=b1a83ab2a9eb9321fbdd
> Fixes: acd895795d35 ("profiling: fix broken profiling regression")
> Tested-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> ---
>  kernel/ksysfs.c  | 27 ++++++++++++++++++++++-----
>  kernel/profile.c |  6 +++---
>  2 files changed, 25 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/ksysfs.c b/kernel/ksysfs.c
> index 1d4bc493b2f4..66bc712f590c 100644
> --- a/kernel/ksysfs.c
> +++ b/kernel/ksysfs.c
> @@ -91,10 +91,23 @@ static ssize_t profiling_store(struct kobject *kobj,
>  				   struct kobj_attribute *attr,
>  				   const char *buf, size_t count)
>  {
> +	static DEFINE_MUTEX(lock);
>  	int ret;
>  
> -	if (prof_on)
> -		return -EEXIST;
> +	/*
> +	 * We need serialization, for profile_setup() initializes prof_on
> +	 * value. Also, use killable wait in case memory allocation from
> +	 * profile_init() triggered the OOM killer and chose current thread
> +	 * blocked here.
> +	 */
> +	if (mutex_lock_killable(&lock))
> +		return -EINTR;
> +
> +	if (prof_on) {
> +		count = -EEXIST;
> +		goto out;
> +	}
> +
>  	/*
>  	 * This eventually calls into get_option() which
>  	 * has a ton of callers and is not const.  It is
> @@ -102,11 +115,15 @@ static ssize_t profiling_store(struct kobject *kobj,
>  	 */
>  	profile_setup((char *)buf);
>  	ret = profile_init();
> -	if (ret)
> -		return ret;
> +	if (ret) {
> +		count = ret;
> +		goto out;
> +	}
>  	ret = create_proc_profile();
>  	if (ret)
> -		return ret;
> +		count = ret;
> +out:
> +	mutex_unlock(&lock);
>  	return count;
>  }
>  KERNEL_ATTR_RW(profiling);
> diff --git a/kernel/profile.c b/kernel/profile.c
> index 8a77769bc4b4..7575747e2ac6 100644
> --- a/kernel/profile.c
> +++ b/kernel/profile.c
> @@ -114,11 +114,9 @@ int __ref profile_init(void)
>  
>  	buffer_bytes = prof_len*sizeof(atomic_t);
>  
> -	if (!alloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
> +	if (!zalloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
>  		return -ENOMEM;
>  
> -	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
> -
>  	prof_buffer = kzalloc(buffer_bytes, GFP_KERNEL|__GFP_NOWARN);
>  	if (prof_buffer)
>  		return 0;
> @@ -481,6 +479,8 @@ int __ref create_proc_profile(void)
>  		goto err_state_prep;
>  	online_state = err;
>  	err = 0;
> +#else
> +	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
>  #endif
>  	entry = proc_create("profile", S_IWUSR | S_IRUGO,
>  			    NULL, &profile_proc_ops);

[PATCH (REPOST)] profiling: initialize prof_cpu_mask from profile_online_cpu()

[Tetsuo Handa]

syzbot is reporting uninit-value at profile_hits(), for commit acd895795d35
("profiling: fix broken profiling regression") by error initialized
prof_cpu_mask too early.

do_profile_hits() is called from profile_tick() from timer interrupt
only if cpumask_test_cpu(smp_processor_id(), prof_cpu_mask) is true and
prof_buffer is not NULL. But the syzbot's report says that profile_hits()
was called while current thread is still doing vzalloc(buffer_bytes)
where prof_buffer is NULL at this moment. This indicates two things.

One is that cpumask_set_cpu(cpu, prof_cpu_mask) should have been called
 from profile_online_cpu() from cpuhp_setup_state() only after
profile_init() completed. Fix this by explicitly calling cpumask_copy()
 from create_proc_profile() on only UP kernels.

The other is that multiple threads concurrently tried to write to
/sys/kernel/profiling interface, which caused that somebody else tried
to re-initialize prof_buffer despite somebody has already initialized
prof_buffer. Fix this by using serialization.

Reported-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
Closes: https://syzkaller.appspot.com/bug?extid=b1a83ab2a9eb9321fbdd
Fixes: acd895795d35 ("profiling: fix broken profiling regression")
Tested-by: syzbot+b1a83ab2a9eb9321fbdd@syzkaller.appspotmail.com
Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
Can somebody test this patch? I don't know how not using
cpu_possible_mask affects expected profile data collection
(especially when written to /sys/kernel/profiling interface
when some of CPUs are offline).

 kernel/ksysfs.c  | 27 ++++++++++++++++++++++-----
 kernel/profile.c |  6 +++---
 2 files changed, 25 insertions(+), 8 deletions(-)

diff --git a/kernel/ksysfs.c b/kernel/ksysfs.c
index 495b69a71a5d..0540483ae7f0 100644
--- a/kernel/ksysfs.c
+++ b/kernel/ksysfs.c
@@ -91,10 +91,23 @@ static ssize_t profiling_store(struct kobject *kobj,
 				   struct kobj_attribute *attr,
 				   const char *buf, size_t count)
 {
+	static DEFINE_MUTEX(lock);
 	int ret;
 
-	if (prof_on)
-		return -EEXIST;
+	/*
+	 * We need serialization, for profile_setup() initializes prof_on
+	 * value. Also, use killable wait in case memory allocation from
+	 * profile_init() triggered the OOM killer and chose current thread
+	 * blocked here.
+	 */
+	if (mutex_lock_killable(&lock))
+		return -EINTR;
+
+	if (prof_on) {
+		count = -EEXIST;
+		goto out;
+	}
+
 	/*
 	 * This eventually calls into get_option() which
 	 * has a ton of callers and is not const.  It is
@@ -102,11 +115,15 @@ static ssize_t profiling_store(struct kobject *kobj,
 	 */
 	profile_setup((char *)buf);
 	ret = profile_init();
-	if (ret)
-		return ret;
+	if (ret) {
+		count = ret;
+		goto out;
+	}
 	ret = create_proc_profile();
 	if (ret)
-		return ret;
+		count = ret;
+out:
+	mutex_unlock(&lock);
 	return count;
 }
 KERNEL_ATTR_RW(profiling);
diff --git a/kernel/profile.c b/kernel/profile.c
index 2b775cc5c28f..1a6c1cf98485 100644
--- a/kernel/profile.c
+++ b/kernel/profile.c
@@ -114,11 +114,9 @@ int __ref profile_init(void)
 
 	buffer_bytes = prof_len*sizeof(atomic_t);
 
-	if (!alloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
+	if (!zalloc_cpumask_var(&prof_cpu_mask, GFP_KERNEL))
 		return -ENOMEM;
 
-	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
-
 	prof_buffer = kzalloc(buffer_bytes, GFP_KERNEL|__GFP_NOWARN);
 	if (prof_buffer)
 		return 0;
@@ -438,6 +436,8 @@ int __ref create_proc_profile(void)
 		goto err_state_prep;
 	online_state = err;
 	err = 0;
+#else
+	cpumask_copy(prof_cpu_mask, cpu_possible_mask);
 #endif
 	entry = proc_create("profile", S_IWUSR | S_IRUGO,
 			    NULL, &profile_proc_ops);
-- 
2.18.4

Re: [PATCH (REPOST)] profiling: initialize prof_cpu_mask from profile_online_cpu()

[Tetsuo Handa]

On 2024/04/27 15:51, Tetsuo Handa wrote:
> Can somebody test this patch? I don't know how not using
> cpu_possible_mask affects expected profile data collection
> (especially when written to /sys/kernel/profiling interface
> when some of CPUs are offline).

I confirmed that writing to /sys/kernel/profiling while some of
/sys/devices/system/cpu/cpu$num/online are 0 will not affect profile data
collection, for profile_online_cpu() is called (and corresponding bit is set)
when /sys/devices/system/cpu/cpu$num/online becomes 1. Thus, I consider that
this patch itself is correct and safe.

But I found a different problem with current code. Just running

# echo -n sleep > /sys/kernel/profiling

after boot causes the system to lock up. ;-)



[  102.002703] kernel profiling enabled schedstats, disable via kernel.sched_schedstats.
[  102.013462] kernel sleep profiling enabled (shift: 0)
[  102.019515] 
[  102.021862] ======================================================
[  102.028037] WARNING: possible circular locking dependency detected
[  102.034940] 6.9.0-rc6+ #64 Not tainted
[  102.039178] ------------------------------------------------------
[  102.045236] swapper/1/0 is trying to acquire lock:
[  102.050140] ffff9a3d809a0e30 (&p->pi_lock){-.-.}-{2:2}, at: get_wchan+0x33/0x80
[  102.057446] 
[  102.057446] but task is already holding lock:
[  102.062449] ffff9a3e1a3f79d8 (&rq->__lock){-.-.}-{2:2}, at: _raw_spin_rq_lock_irqsave+0x27/0x50
[  102.071546] 
[  102.071546] which lock already depends on the new lock.
[  102.071546] 
[  102.079435] 
[  102.079435] the existing dependency chain (in reverse order) is:
[  102.085407] 
[  102.085407] -> #1 (&rq->__lock){-.-.}-{2:2}:
[  102.090805]        lock_acquire+0xca/0x2d0
[  102.095400]        _raw_spin_lock_nested+0x32/0x80
[  102.100616]        raw_spin_rq_lock_nested+0x15/0x30
[  102.104595]        task_fork_fair+0x3a/0xe0
[  102.109176]        sched_cgroup_fork+0x11e/0x160
[  102.113277]        copy_process+0x15b5/0x2140
[  102.117990]        kernel_clone+0x9e/0x6d0
[  102.122376]        user_mode_thread+0x5f/0x90
[  102.127207]        rest_init+0x1e/0x1d0
[  102.131843]        start_kernel+0x64a/0x730
[  102.136213]        x86_64_start_reservations+0x18/0x30
[  102.141857]        x86_64_start_kernel+0x91/0xa0
[  102.147018]        common_startup_64+0x13e/0x141
[  102.152186] 
[  102.152186] -> #0 (&p->pi_lock){-.-.}-{2:2}:
[  102.158338]        check_prevs_add+0x1e2/0xc60
[  102.162335]        __lock_acquire+0x10d4/0x12b0
[  102.167147]        lock_acquire+0xca/0x2d0
[  102.171738]        _raw_spin_lock_irq+0x48/0x90
[  102.176284]        get_wchan+0x33/0x80
[  102.180519]        __update_stats_enqueue_sleeper+0x156/0x390
[  102.185878]        enqueue_entity+0x34c/0x3e0
[  102.190237]        enqueue_task_fair+0xa3/0x350
[  102.195030]        activate_task+0x4c/0xe0
[  102.199643]        ttwu_do_activate+0x5d/0x1f0
[  102.203992]        sched_ttwu_pending+0xe2/0x1a0
[  102.209097]        __flush_smp_call_function_queue+0x1e8/0x6e0
[  102.214120]        __sysvec_call_function_single+0x36/0x150
[  102.220072]        sysvec_call_function_single+0x65/0x80
[  102.224282]        asm_sysvec_call_function_single+0x1a/0x20
[  102.229298]        pv_native_safe_halt+0xf/0x20
[  102.233969]        acpi_safe_halt+0x14/0x20
[  102.238649]        acpi_idle_enter+0x7f/0xd0
[  102.242926]        cpuidle_enter_state+0x93/0x570
[  102.248198]        cpuidle_enter+0x2d/0x40
[  102.252902]        do_idle+0x213/0x270
[  102.257070]        cpu_startup_entry+0x29/0x30
[  102.262396]        start_secondary+0x123/0x140
[  102.267423]        common_startup_64+0x13e/0x141
[  102.272129] 
[  102.272129] other info that might help us debug this:
[  102.272129] 
[  102.280775]  Possible unsafe locking scenario:
[  102.280775] 
[  102.285824]        CPU0                    CPU1
[  102.289461]        ----                    ----
[  102.294154]   lock(&rq->__lock);
[  102.297868]                                lock(&p->pi_lock);
[  102.303641]                                lock(&rq->__lock);
[  102.310000]   lock(&p->pi_lock);
[  102.311916] 
[  102.311916]  *** DEADLOCK ***
[  102.311916] 
[  102.318184] 1 lock held by swapper/1/0:
[  102.321543]  #0: ffff9a3e1a3f79d8 (&rq->__lock){-.-.}-{2:2}, at: _raw_spin_rq_lock_irqsave+0x27/0x50
[  102.331290] 
[  102.331290] stack backtrace:
[  102.336159] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 6.9.0-rc6+ #64
[  102.342814] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[  102.354177] Call Trace:
[  102.356981]  <IRQ>
[  102.359373]  dump_stack_lvl+0x77/0xb0
[  102.363183]  check_noncircular+0x131/0x150
[  102.367844]  check_prevs_add+0x1e2/0xc60
[  102.372341]  __lock_acquire+0x10d4/0x12b0
[  102.376757]  lock_acquire+0xca/0x2d0
[  102.380836]  ? get_wchan+0x33/0x80
[  102.383514]  ? lock_is_held_type+0xac/0x120
[  102.387749]  _raw_spin_lock_irq+0x48/0x90
[  102.391997]  ? get_wchan+0x33/0x80
[  102.395911]  get_wchan+0x33/0x80
[  102.399713]  __update_stats_enqueue_sleeper+0x156/0x390
[  102.405394]  enqueue_entity+0x34c/0x3e0
[  102.409721]  enqueue_task_fair+0xa3/0x350
[  102.413522]  activate_task+0x4c/0xe0
[  102.417455]  ttwu_do_activate+0x5d/0x1f0
[  102.421393]  sched_ttwu_pending+0xe2/0x1a0
[  102.424410]  __flush_smp_call_function_queue+0x1e8/0x6e0
[  102.430129]  __sysvec_call_function_single+0x36/0x150
[  102.435543]  sysvec_call_function_single+0x65/0x80
[  102.441465]  </IRQ>
[  102.443080]  <TASK>
[  102.445524]  asm_sysvec_call_function_single+0x1a/0x20
[  102.451011] RIP: 0010:pv_native_safe_halt+0xf/0x20
[  102.456052] Code: 22 d7 c3 cc cc cc cc 0f 1f 40 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa eb 07 0f 00 2d 55 af 26 00 fb f4 <c3> cc cc cc cc 66 90 66 2e 0f 1f 84 00 00 00 00 00 90 90 90 90 90
[  102.474565] RSP: 0018:ffffbba0000dfe60 EFLAGS: 00000246
[  102.481811] RAX: 0000000000004000 RBX: 0000000000000001 RCX: ffff9a3e1a200000
[  102.488391] RDX: 00000000001f37e8 RSI: ffffffff88961bc0 RDI: ffff9a3e39030464
[  102.496168] RBP: ffff9a3e39030464 R08: ffff9a3e39030400 R09: 0000000000000001
[  102.503844] R10: 0000000000000001 R11: ffffffff888d2648 R12: ffff9a3e238ac000
[  102.510614] R13: ffffffff88961bc0 R14: 0000000000000001 R15: 0000000000000000
[  102.517439]  acpi_safe_halt+0x14/0x20
[  102.522052]  acpi_idle_enter+0x7f/0xd0
[  102.525629]  cpuidle_enter_state+0x93/0x570
[  102.530429]  cpuidle_enter+0x2d/0x40
[  102.534386]  do_idle+0x213/0x270
[  102.536860]  cpu_startup_entry+0x29/0x30
[  102.540286]  start_secondary+0x123/0x140
[  102.542516]  common_startup_64+0x13e/0x141
[  102.545389]  </TASK>



[   93.099702] kernel profiling enabled schedstats, disable via kernel.sched_schedstats.
[   93.110562] kernel sleep profiling enabled (shift: 0)
[   93.118228] 
[   93.121032] ============================================
[   93.127279] WARNING: possible recursive locking detected
[   93.133167] 6.9.0-rc6+ #65 Not tainted
[   93.136486] --------------------------------------------
[   93.142349] swapper/8/0 is trying to acquire lock:
[   93.147140] ffff9227c0998e30 (&p->pi_lock){-.-.}-{2:2}, at: get_wchan+0x33/0x80
[   93.154036] 
[   93.154036] but task is already holding lock:
[   93.160368] ffff9227c0998e30 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x56/0x580
[   93.166995] 
[   93.166995] other info that might help us debug this:
[   93.173123]  Possible unsafe locking scenario:
[   93.173123] 
[   93.179771]        CPU0
[   93.181941]        ----
[   93.184727]   lock(&p->pi_lock);
[   93.188471]   lock(&p->pi_lock);
[   93.192588] 
[   93.192588]  *** DEADLOCK ***
[   93.192588] 
[   93.198248]  May be due to missing lock nesting notation
[   93.198248] 
[   93.205640] 3 locks held by swapper/8/0:
[   93.210208]  #0: ffffb17f40674e98 ((&timer.timer)){+.-.}-{0:0}, at: call_timer_fn+0x80/0x260
[   93.216945]  #1: ffff9227c0998e30 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x56/0x580
[   93.225435]  #2: ffff92285bff79d8 (&rq->__lock){-.-.}-{2:2}, at: try_to_wake_up+0x1ab/0x580
[   93.234238] 
[   93.234238] stack backtrace:
[   93.238342] CPU: 8 PID: 0 Comm: swapper/8 Not tainted 6.9.0-rc6+ #65
[   93.245220] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[   93.254093] Call Trace:
[   93.256901]  <IRQ>
[   93.258420]  dump_stack_lvl+0x77/0xb0
[   93.261825]  __lock_acquire+0x765/0x12b0
[   93.289798]  lock_acquire+0xca/0x2d0
[   93.293381]  ? get_wchan+0x33/0x80
[   93.297140]  ? lock_is_held_type+0xac/0x120
[   93.301057]  _raw_spin_lock_irq+0x48/0x90
[   93.307264]  ? get_wchan+0x33/0x80
[   93.310410]  get_wchan+0x33/0x80
[   93.314484]  __update_stats_enqueue_sleeper+0x156/0x390
[   93.318493]  enqueue_entity+0x34c/0x3e0
[   93.322788]  enqueue_task_fair+0xa3/0x350
[   93.326960]  activate_task+0x4c/0xe0
[   93.330226]  ttwu_do_activate+0x5d/0x1f0
[   93.347525]  try_to_wake_up+0x1da/0x580
[   93.352071]  ? __pfx_process_timeout+0x10/0x10
[   93.357023]  ? __pfx_process_timeout+0x10/0x10
[   93.361356]  call_timer_fn+0xae/0x260
[   93.365165]  __run_timer_base.part.35+0x26d/0x2c0
[   93.371324]  ? ktime_get+0x6b/0x130
[   93.375678]  ? ktime_get+0x8b/0x130
[   93.379055]  ? native_apic_msr_write+0x30/0x40
[   93.383911]  run_timer_softirq+0x51/0x90
[   93.397918]  __do_softirq+0xb6/0x3ec
[   93.402236]  irq_exit_rcu+0xba/0xe0
[   93.406044]  sysvec_apic_timer_interrupt+0x6a/0x80
[   93.410164]  </IRQ>
[   93.411967]  <TASK>
[   93.413257]  asm_sysvec_apic_timer_interrupt+0x1a/0x20
[   93.418952] RIP: 0010:pv_native_safe_halt+0xf/0x20
[   93.423460] Code: 22 d7 c3 cc cc cc cc 0f 1f 40 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa eb 07 0f 00 2d 55 af 26 00 fb f4 <c3> cc cc cc cc 66 90 66 2e 0f 1f 84 00 00 00 00 00 90 90 90 90 90
[   93.459197] RSP: 0018:ffffb17f40117e60 EFLAGS: 00000246
[   93.465006] RAX: 0000000000004000 RBX: 0000000000000001 RCX: ffff92285be00000
[   93.471498] RDX: 00000000001f37e8 RSI: ffffffffafd61b00 RDI: ffff92286a432c64
[   93.479505] RBP: ffff92286a432c64 R08: ffff92286a432c00 R09: 0000000000000001
[   93.503897] R10: 0000000000000001 R11: ffff92285bfe6258 R12: ffff92286646a400
[   93.512211] R13: ffffffffafd61b00 R14: 0000000000000001 R15: 0000000000000000
[   93.518061]  acpi_safe_halt+0x14/0x20
[   93.522244]  acpi_idle_enter+0x7f/0xd0
[   93.526335]  cpuidle_enter_state+0x93/0x570
[   93.530482]  cpuidle_enter+0x2d/0x40
[   93.533615]  do_idle+0x213/0x270
[   93.545854]  cpu_startup_entry+0x29/0x30
[   93.549904]  start_secondary+0x123/0x140
[   93.553957]  common_startup_64+0x13e/0x141
[   93.558172]  </TASK>