[PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Zhen Lei]

[T58] BUG: sleeping function called from invalid context at kernel/kallsyms.c:305
[T58] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 58, name: kallsyms_test
[T58] preempt_count: 0, expected: 0
[T58] RCU nest depth: 0, expected: 0
[T58] no locks held by kallsyms_test/58.
[T58] irq event stamp: 18899904
[T58] hardirqs last enabled at (18899903): finish_task_switch.isra.0 (core.c:?)
[T58] hardirqs last disabled at (18899904): test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
[T58] softirqs last enabled at (18899886): __do_softirq (??:?)
[T58] softirqs last disabled at (18899879): ____do_softirq (irq.c:?)
[T58] CPU: 0 PID: 58 Comm: kallsyms_test Tainted: G T  6.1.0-next-20221215 #2
[T58] Hardware name: linux,dummy-virt (DT)
[T58] Call trace:
[T58] dump_backtrace (??:?)
[T58] show_stack (??:?)
[T58] dump_stack_lvl (??:?)
[T58] dump_stack (??:?)
[T58] __might_resched (??:?)
[T58] kallsyms_on_each_symbol (??:?)
[T58] test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
[T58] test_entry (kallsyms_selftest.c:?)
[T58] kthread (kthread.c:?)
[T58] ret_from_fork (??:?)
[T58] kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 5744310840 ns
[T58] kallsyms_selftest: kallsyms_on_each_match_symbol() traverse all: 1164580 ns
[T58] kallsyms_selftest: finish

Functions kallsyms_on_each_symbol() and kallsyms_on_each_match_symbol()
call the user-registered hook function for each symbol that meets the
requirements. Because it is uncertain how long that hook function will
execute, they call cond_resched() to avoid consuming CPU resources for a
long time. However, irqs need to be disabled during the performance test
to ensure the accuracy of test data. Because the performance test hook is
very clear, very simple function, let's do not call cond_resched() when
CONFIG_KALLSYMS_SELFTEST=y.

Fixes: 30f3bb09778d ("kallsyms: Add self-test facility")
Reported-by: Anders Roxell <anders.roxell@linaro.org>
Signed-off-by: Zhen Lei <thunder.leizhen@huawei.com>
---
 kernel/kallsyms.c | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/kernel/kallsyms.c b/kernel/kallsyms.c
index 83f499182c9aa31..a49e344a686517b 100644
--- a/kernel/kallsyms.c
+++ b/kernel/kallsyms.c
@@ -302,7 +302,8 @@ int kallsyms_on_each_symbol(int (*fn)(void *, const char *, struct module *,
 		ret = fn(data, namebuf, NULL, kallsyms_sym_address(i));
 		if (ret != 0)
 			return ret;
-		cond_resched();
+		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
+			cond_resched();
 	}
 	return 0;
 }
@@ -319,7 +320,8 @@ int kallsyms_on_each_match_symbol(int (*fn)(void *, unsigned long),
 
 	for (i = start; !ret && i <= end; i++) {
 		ret = fn(data, kallsyms_sym_address(get_symbol_seq(i)));
-		cond_resched();
+		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
+			cond_resched();
 	}
 
 	return ret;
-- 
2.25.1

Re: [PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Christophe Leroy]

Le 20/12/2022 à 07:39, Zhen Lei a écrit :
> [T58] BUG: sleeping function called from invalid context at kernel/kallsyms.c:305
> [T58] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 58, name: kallsyms_test
> [T58] preempt_count: 0, expected: 0
> [T58] RCU nest depth: 0, expected: 0
> [T58] no locks held by kallsyms_test/58.
> [T58] irq event stamp: 18899904
> [T58] hardirqs last enabled at (18899903): finish_task_switch.isra.0 (core.c:?)
> [T58] hardirqs last disabled at (18899904): test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
> [T58] softirqs last enabled at (18899886): __do_softirq (??:?)
> [T58] softirqs last disabled at (18899879): ____do_softirq (irq.c:?)
> [T58] CPU: 0 PID: 58 Comm: kallsyms_test Tainted: G T  6.1.0-next-20221215 #2
> [T58] Hardware name: linux,dummy-virt (DT)
> [T58] Call trace:
> [T58] dump_backtrace (??:?)
> [T58] show_stack (??:?)
> [T58] dump_stack_lvl (??:?)
> [T58] dump_stack (??:?)
> [T58] __might_resched (??:?)
> [T58] kallsyms_on_each_symbol (??:?)
> [T58] test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
> [T58] test_entry (kallsyms_selftest.c:?)
> [T58] kthread (kthread.c:?)
> [T58] ret_from_fork (??:?)
> [T58] kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 5744310840 ns
> [T58] kallsyms_selftest: kallsyms_on_each_match_symbol() traverse all: 1164580 ns
> [T58] kallsyms_selftest: finish
> 
> Functions kallsyms_on_each_symbol() and kallsyms_on_each_match_symbol()
> call the user-registered hook function for each symbol that meets the
> requirements. Because it is uncertain how long that hook function will
> execute, they call cond_resched() to avoid consuming CPU resources for a
> long time. However, irqs need to be disabled during the performance test
> to ensure the accuracy of test data. Because the performance test hook is
> very clear, very simple function, let's do not call cond_resched() when
> CONFIG_KALLSYMS_SELFTEST=y.

I don't think it is appropriate to change the behaviour of a core 
function based on whether a compile time option related to tests is 
selected or not, because you will change the behaviour for all users, 
not only for the tests.

If the problem is that IRQs are disabled, maybe the solution is

	if (!irqs_disabled())
		cond_resched();

Or try to disable the call to cond_resched() in a way or another during 
the run of selftests.

> 
> Fixes: 30f3bb09778d ("kallsyms: Add self-test facility")
> Reported-by: Anders Roxell <anders.roxell@linaro.org>
> Signed-off-by: Zhen Lei <thunder.leizhen@huawei.com>
> ---
>   kernel/kallsyms.c | 6 ++++--
>   1 file changed, 4 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/kallsyms.c b/kernel/kallsyms.c
> index 83f499182c9aa31..a49e344a686517b 100644
> --- a/kernel/kallsyms.c
> +++ b/kernel/kallsyms.c
> @@ -302,7 +302,8 @@ int kallsyms_on_each_symbol(int (*fn)(void *, const char *, struct module *,
>   		ret = fn(data, namebuf, NULL, kallsyms_sym_address(i));
>   		if (ret != 0)
>   			return ret;
> -		cond_resched();
> +		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
> +			cond_resched();
>   	}
>   	return 0;
>   }
> @@ -319,7 +320,8 @@ int kallsyms_on_each_match_symbol(int (*fn)(void *, unsigned long),
>   
>   	for (i = start; !ret && i <= end; i++) {
>   		ret = fn(data, kallsyms_sym_address(get_symbol_seq(i)));
> -		cond_resched();
> +		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
> +			cond_resched();
>   	}
>   
>   	return ret;

Re: [PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Petr Mladek]

On Tue 2022-12-20 08:15:40, Christophe Leroy wrote:
> 
> 
> Le 20/12/2022 à 07:39, Zhen Lei a écrit :
> > [T58] BUG: sleeping function called from invalid context at kernel/kallsyms.c:305
> > [T58] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 58, name: kallsyms_test
> > [T58] preempt_count: 0, expected: 0
> > [T58] RCU nest depth: 0, expected: 0
> > [T58] no locks held by kallsyms_test/58.
> > [T58] irq event stamp: 18899904
> > [T58] hardirqs last enabled at (18899903): finish_task_switch.isra.0 (core.c:?)
> > [T58] hardirqs last disabled at (18899904): test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
> > [T58] softirqs last enabled at (18899886): __do_softirq (??:?)
> > [T58] softirqs last disabled at (18899879): ____do_softirq (irq.c:?)
> > [T58] CPU: 0 PID: 58 Comm: kallsyms_test Tainted: G T  6.1.0-next-20221215 #2
> > [T58] Hardware name: linux,dummy-virt (DT)
> > [T58] Call trace:
> > [T58] dump_backtrace (??:?)
> > [T58] show_stack (??:?)
> > [T58] dump_stack_lvl (??:?)
> > [T58] dump_stack (??:?)
> > [T58] __might_resched (??:?)
> > [T58] kallsyms_on_each_symbol (??:?)
> > [T58] test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
> > [T58] test_entry (kallsyms_selftest.c:?)
> > [T58] kthread (kthread.c:?)
> > [T58] ret_from_fork (??:?)
> > [T58] kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 5744310840 ns
> > [T58] kallsyms_selftest: kallsyms_on_each_match_symbol() traverse all: 1164580 ns
> > [T58] kallsyms_selftest: finish
> > 
> > Functions kallsyms_on_each_symbol() and kallsyms_on_each_match_symbol()
> > call the user-registered hook function for each symbol that meets the
> > requirements. Because it is uncertain how long that hook function will
> > execute, they call cond_resched() to avoid consuming CPU resources for a
> > long time. However, irqs need to be disabled during the performance test
> > to ensure the accuracy of test data. Because the performance test hook is
> > very clear, very simple function, let's do not call cond_resched() when
> > CONFIG_KALLSYMS_SELFTEST=y.
> 
> I don't think it is appropriate to change the behaviour of a core 
> function based on whether a compile time option related to tests is 
> selected or not, because you will change the behaviour for all users, 
> not only for the tests.

I agree. This is very bad idea. It would change the behavior for
the entire system.

> If the problem is that IRQs are disabled, maybe the solution is
> 
> 	if (!irqs_disabled())
> 		cond_resched();
> 
> Or try to disable the call to cond_resched() in a way or another during 
> the run of selftests.

If I get it correctly, the problem is this code in kernel/kallsyms_selftest.c:

static int lookup_name(void *data, const char *name, struct module *mod, unsigned long addr)
{
[...]
	local_irq_save(flags);
	t0 = sched_clock();
	(void)kallsyms_lookup_name(name);
	t1 = sched_clock();
	local_irq_restore(flags);
[...]

and IRQs are disabled to measure the time spent in this function
without interruption and rescheduling.

I am sure that there are better ways how to measure the time.
Even the "time" command in userspace is able to show time how much CPU
time a command used.

I am not familiar with it. But task_cputime() in
kernel/sched/cputime.c looks promising. And there must be
the interface how the user space get this information.
Some is available via /proc/<PID>/... I am not sure
if there is a syscall.

Best Regards,
Petr

Re: [PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Leizhen (ThunderTown)]

On 2022/12/20 19:01, Petr Mladek wrote:
> On Tue 2022-12-20 08:15:40, Christophe Leroy wrote:
>>
>>
>> Le 20/12/2022 à 07:39, Zhen Lei a écrit :
>>> [T58] BUG: sleeping function called from invalid context at kernel/kallsyms.c:305
>>> [T58] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 58, name: kallsyms_test
>>> [T58] preempt_count: 0, expected: 0
>>> [T58] RCU nest depth: 0, expected: 0
>>> [T58] no locks held by kallsyms_test/58.
>>> [T58] irq event stamp: 18899904
>>> [T58] hardirqs last enabled at (18899903): finish_task_switch.isra.0 (core.c:?)
>>> [T58] hardirqs last disabled at (18899904): test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
>>> [T58] softirqs last enabled at (18899886): __do_softirq (??:?)
>>> [T58] softirqs last disabled at (18899879): ____do_softirq (irq.c:?)
>>> [T58] CPU: 0 PID: 58 Comm: kallsyms_test Tainted: G T  6.1.0-next-20221215 #2
>>> [T58] Hardware name: linux,dummy-virt (DT)
>>> [T58] Call trace:
>>> [T58] dump_backtrace (??:?)
>>> [T58] show_stack (??:?)
>>> [T58] dump_stack_lvl (??:?)
>>> [T58] dump_stack (??:?)
>>> [T58] __might_resched (??:?)
>>> [T58] kallsyms_on_each_symbol (??:?)
>>> [T58] test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
>>> [T58] test_entry (kallsyms_selftest.c:?)
>>> [T58] kthread (kthread.c:?)
>>> [T58] ret_from_fork (??:?)
>>> [T58] kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 5744310840 ns
>>> [T58] kallsyms_selftest: kallsyms_on_each_match_symbol() traverse all: 1164580 ns
>>> [T58] kallsyms_selftest: finish
>>>
>>> Functions kallsyms_on_each_symbol() and kallsyms_on_each_match_symbol()
>>> call the user-registered hook function for each symbol that meets the
>>> requirements. Because it is uncertain how long that hook function will
>>> execute, they call cond_resched() to avoid consuming CPU resources for a
>>> long time. However, irqs need to be disabled during the performance test
>>> to ensure the accuracy of test data. Because the performance test hook is
>>> very clear, very simple function, let's do not call cond_resched() when
>>> CONFIG_KALLSYMS_SELFTEST=y.
>>
>> I don't think it is appropriate to change the behaviour of a core 
>> function based on whether a compile time option related to tests is 
>> selected or not, because you will change the behaviour for all users, 
>> not only for the tests.
> 
> I agree. This is very bad idea. It would change the behavior for
> the entire system.

It just doesn't look so good, but it doesn't affect the entire system,
and the proposed changes below will.

> 
>> If the problem is that IRQs are disabled, maybe the solution is
>>
>> 	if (!irqs_disabled())
>> 		cond_resched();

If irqs is disabled by the upper layer, this error cannot be easily detected.

>>
>> Or try to disable the call to cond_resched() in a way or another during 
>> the run of selftests.
> 
> If I get it correctly, the problem is this code in kernel/kallsyms_selftest.c:

Yes, another method is to remove the interrupt protection.

> 
> static int lookup_name(void *data, const char *name, struct module *mod, unsigned long addr)
> {
> [...]
> 	local_irq_save(flags);
> 	t0 = sched_clock();
> 	(void)kallsyms_lookup_name(name);
> 	t1 = sched_clock();
> 	local_irq_restore(flags);
> [...]
> 
> and IRQs are disabled to measure the time spent in this function
> without interruption and rescheduling.
> 
> I am sure that there are better ways how to measure the time.
> Even the "time" command in userspace is able to show time how much CPU
> time a command used.

I've got an idea:

local_irq_save(flags);
//get the count and cputime of interrupts
t0 = sched_clock();
local_irq_restore(flags);

(void)kallsyms_lookup_name(name);

local_irq_save(flags);
t1 = sched_clock();
//get the count and cputime of interrupts
local_irq_restore(flags);

minus the cputime of local_irq_save(flags)/local_irq_restore(flags)

if count changed, minus the cputime of interrupts

> 
> I am not familiar with it. But task_cputime() in
> kernel/sched/cputime.c looks promising. And there must be
> the interface how the user space get this information.
> Some is available via /proc/<PID>/... I am not sure
> if there is a syscall.
> 
> Best Regards,
> Petr
> .
> 

-- 
Regards,
  Zhen Lei

Re: [PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Petr Mladek]

On Tue 2022-12-20 22:29:31, Leizhen (ThunderTown) wrote:
> On 2022/12/20 19:01, Petr Mladek wrote:
> > On Tue 2022-12-20 08:15:40, Christophe Leroy wrote:
> >>
> >>
> >> Le 20/12/2022 à 07:39, Zhen Lei a écrit :
> >>> [T58] BUG: sleeping function called from invalid context at kernel/kallsyms.c:305
> >>> [T58] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 58, name: kallsyms_test
> >>> [T58] preempt_count: 0, expected: 0
> >>> [T58] RCU nest depth: 0, expected: 0
> >>> [T58] no locks held by kallsyms_test/58.
> >>> [T58] irq event stamp: 18899904
> >>> [T58] hardirqs last enabled at (18899903): finish_task_switch.isra.0 (core.c:?)
> >>> [T58] hardirqs last disabled at (18899904): test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
> >>> [T58] softirqs last enabled at (18899886): __do_softirq (??:?)
> >>> [T58] softirqs last disabled at (18899879): ____do_softirq (irq.c:?)
> >>> [T58] CPU: 0 PID: 58 Comm: kallsyms_test Tainted: G T  6.1.0-next-20221215 #2
> >>> [T58] Hardware name: linux,dummy-virt (DT)
> >>> [T58] Call trace:
> >>> [T58] dump_backtrace (??:?)
> >>> [T58] show_stack (??:?)
> >>> [T58] dump_stack_lvl (??:?)
> >>> [T58] dump_stack (??:?)
> >>> [T58] __might_resched (??:?)
> >>> [T58] kallsyms_on_each_symbol (??:?)
> >>> [T58] test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
> >>> [T58] test_entry (kallsyms_selftest.c:?)
> >>> [T58] kthread (kthread.c:?)
> >>> [T58] ret_from_fork (??:?)
> >>> [T58] kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 5744310840 ns
> >>> [T58] kallsyms_selftest: kallsyms_on_each_match_symbol() traverse all: 1164580 ns
> >>> [T58] kallsyms_selftest: finish
> >>>
> >>> Functions kallsyms_on_each_symbol() and kallsyms_on_each_match_symbol()
> >>> call the user-registered hook function for each symbol that meets the
> >>> requirements. Because it is uncertain how long that hook function will
> >>> execute, they call cond_resched() to avoid consuming CPU resources for a
> >>> long time. However, irqs need to be disabled during the performance test
> >>> to ensure the accuracy of test data. Because the performance test hook is
> >>> very clear, very simple function, let's do not call cond_resched() when
> >>> CONFIG_KALLSYMS_SELFTEST=y.
> >>
> >> I don't think it is appropriate to change the behaviour of a core 
> >> function based on whether a compile time option related to tests is 
> >> selected or not, because you will change the behaviour for all users, 
> >> not only for the tests.
> > 
> > I agree. This is very bad idea. It would change the behavior for
> > the entire system.
> 
> It just doesn't look so good, but it doesn't affect the entire system,
> and the proposed changes below will.

I do not understand this. The proposed patch did:

--- a/kernel/kallsyms.c
+++ b/kernel/kallsyms.c
@@ -302,7 +302,8 @@ int kallsyms_on_each_symbol(int (*fn)(void *, const char *, struct module *,
 		ret = fn(data, namebuf, NULL, kallsyms_sym_address(i));
 		if (ret != 0)
 			return ret;
-		cond_resched();
+		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
+			cond_resched();
 	}
 	return 0;
 }
@@ -319,7 +320,8 @@ int kallsyms_on_each_match_symbol(int (*fn)(void *, unsigned long),
 
 	for (i = start; !ret && i <= end; i++) {
 		ret = fn(data, kallsyms_sym_address(get_symbol_seq(i)));
-		cond_resched();
+		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
+			cond_resched();
 	}
 
 	return ret;

It changes the behavior for any kallsyms_on_each_symbol()
and kallsyms_on_each_match_symbol() caller. And this _is_ the problem!

The cond_resched() is there for a reason. See the commit
f5bdb34bf0c9314548f2 ("livepatch: Avoid CPU hogging with
cond_resched").

If a function explicitely includes cond_resched() because it
delayed something by >1s that it must never be called with
interrupts enabled except when there is a good reason to
do so, e.g. for debugging. And measuring CPU time
in a selftest is not a good reason, definitely!

> > If I get it correctly, the problem is this code in kernel/kallsyms_selftest.c:
> 
> Yes, another method is to remove the interrupt protection.
> > 
> > static int lookup_name(void *data, const char *name, struct module *mod, unsigned long addr)
> > {
> > [...]
> > 	local_irq_save(flags);
> > 	t0 = sched_clock();
> > 	(void)kallsyms_lookup_name(name);
> > 	t1 = sched_clock();
> > 	local_irq_restore(flags);
> > [...]
> > 
> > and IRQs are disabled to measure the time spent in this function
> > without interruption and rescheduling.
> > 
> > I am sure that there are better ways how to measure the time.
> > Even the "time" command in userspace is able to show time how much CPU
> > time a command used.
> 
> I've got an idea:
> 
> local_irq_save(flags);
> //get the count and cputime of interrupts
> t0 = sched_clock();
> local_irq_restore(flags);
> 
> (void)kallsyms_lookup_name(name);
> 
> local_irq_save(flags);
> t1 = sched_clock();
> //get the count and cputime of interrupts
> local_irq_restore(flags);

Why do you need to disable IRQs around sched_clock(), please?
It works well in any context.

Is sched_clock() needed at all?
Honestly, I do not understand why you are using sched_clock() for
this.

> > I am not familiar with it. But task_cputime() in
> > kernel/sched/cputime.c looks promising. And there must be
> > the interface how the user space get this information.
> > Some is available via /proc/<PID>/... I am not sure
> > if there is a syscall.

Please, try to investigate the above hints.

Honestly, it looks like you do not know what you are doing.

I NACK this patch.

Best Regards,
Petr

Re: [PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Leizhen (ThunderTown)]

On 2022/12/20 23:43, Petr Mladek wrote:
> On Tue 2022-12-20 22:29:31, Leizhen (ThunderTown) wrote:
>> On 2022/12/20 19:01, Petr Mladek wrote:
>>> On Tue 2022-12-20 08:15:40, Christophe Leroy wrote:
>>>>
>>>>
>>>> Le 20/12/2022 à 07:39, Zhen Lei a écrit :
>>>>> [T58] BUG: sleeping function called from invalid context at kernel/kallsyms.c:305
>>>>> [T58] in_atomic(): 0, irqs_disabled(): 128, non_block: 0, pid: 58, name: kallsyms_test
>>>>> [T58] preempt_count: 0, expected: 0
>>>>> [T58] RCU nest depth: 0, expected: 0
>>>>> [T58] no locks held by kallsyms_test/58.
>>>>> [T58] irq event stamp: 18899904
>>>>> [T58] hardirqs last enabled at (18899903): finish_task_switch.isra.0 (core.c:?)
>>>>> [T58] hardirqs last disabled at (18899904): test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
>>>>> [T58] softirqs last enabled at (18899886): __do_softirq (??:?)
>>>>> [T58] softirqs last disabled at (18899879): ____do_softirq (irq.c:?)
>>>>> [T58] CPU: 0 PID: 58 Comm: kallsyms_test Tainted: G T  6.1.0-next-20221215 #2
>>>>> [T58] Hardware name: linux,dummy-virt (DT)
>>>>> [T58] Call trace:
>>>>> [T58] dump_backtrace (??:?)
>>>>> [T58] show_stack (??:?)
>>>>> [T58] dump_stack_lvl (??:?)
>>>>> [T58] dump_stack (??:?)
>>>>> [T58] __might_resched (??:?)
>>>>> [T58] kallsyms_on_each_symbol (??:?)
>>>>> [T58] test_perf_kallsyms_on_each_symbol (kallsyms_selftest.c:?)
>>>>> [T58] test_entry (kallsyms_selftest.c:?)
>>>>> [T58] kthread (kthread.c:?)
>>>>> [T58] ret_from_fork (??:?)
>>>>> [T58] kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 5744310840 ns
>>>>> [T58] kallsyms_selftest: kallsyms_on_each_match_symbol() traverse all: 1164580 ns
>>>>> [T58] kallsyms_selftest: finish
>>>>>
>>>>> Functions kallsyms_on_each_symbol() and kallsyms_on_each_match_symbol()
>>>>> call the user-registered hook function for each symbol that meets the
>>>>> requirements. Because it is uncertain how long that hook function will
>>>>> execute, they call cond_resched() to avoid consuming CPU resources for a
>>>>> long time. However, irqs need to be disabled during the performance test
>>>>> to ensure the accuracy of test data. Because the performance test hook is
>>>>> very clear, very simple function, let's do not call cond_resched() when
>>>>> CONFIG_KALLSYMS_SELFTEST=y.
>>>>
>>>> I don't think it is appropriate to change the behaviour of a core 
>>>> function based on whether a compile time option related to tests is 
>>>> selected or not, because you will change the behaviour for all users, 
>>>> not only for the tests.
>>>
>>> I agree. This is very bad idea. It would change the behavior for
>>> the entire system.
>>
>> It just doesn't look so good, but it doesn't affect the entire system,
>> and the proposed changes below will.

I mean "the proposed changes below":
	if (!irqs_disabled())
		cond_resched();

> 
> I do not understand this. The proposed patch did:
> 
> --- a/kernel/kallsyms.c
> +++ b/kernel/kallsyms.c
> @@ -302,7 +302,8 @@ int kallsyms_on_each_symbol(int (*fn)(void *, const char *, struct module *,
>  		ret = fn(data, namebuf, NULL, kallsyms_sym_address(i));
>  		if (ret != 0)
>  			return ret;
> -		cond_resched();
> +		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
> +			cond_resched();
>  	}
>  	return 0;
>  }
> @@ -319,7 +320,8 @@ int kallsyms_on_each_match_symbol(int (*fn)(void *, unsigned long),
>  
>  	for (i = start; !ret && i <= end; i++) {
>  		ret = fn(data, kallsyms_sym_address(get_symbol_seq(i)));
> -		cond_resched();
> +		if (!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST))
> +			cond_resched();
>  	}
>  
>  	return ret;
> 
> It changes the behavior for any kallsyms_on_each_symbol()
> and kallsyms_on_each_match_symbol() caller. And this _is_ the problem!

!IS_ENABLED(CONFIG_KALLSYMS_SELFTEST) ==> CONFIG_KALLSYMS_SELFTEST=n

So when CONFIG_KALLSYMS_SELFTEST=n, cond_resched() is called, the
original function has not changed.

And when CONFIG_KALLSYMS_SELFTEST=y, cond_resched() is not called.

kallsyms_selftest: kallsyms_on_each_symbol() traverse all: 18864181 ns

The duration for disabling interruption does not exceed 20 ms.
It's not a big problem for test. CONFIG_KALLSYMS_SELFTEST is set only
in the lab.

> 
> The cond_resched() is there for a reason. See the commit
> f5bdb34bf0c9314548f2 ("livepatch: Avoid CPU hogging with
> cond_resched").
> 
> If a function explicitely includes cond_resched() because it
> delayed something by >1s that it must never be called with
> interrupts enabled except when there is a good reason to
> do so, e.g. for debugging. And measuring CPU time
> in a selftest is not a good reason, definitely!

OK, thanks.

> 
>>> If I get it correctly, the problem is this code in kernel/kallsyms_selftest.c:
>>
>> Yes, another method is to remove the interrupt protection.
>>>
>>> static int lookup_name(void *data, const char *name, struct module *mod, unsigned long addr)
>>> {
>>> [...]
>>> 	local_irq_save(flags);
>>> 	t0 = sched_clock();
>>> 	(void)kallsyms_lookup_name(name);
>>> 	t1 = sched_clock();
>>> 	local_irq_restore(flags);
>>> [...]
>>>
>>> and IRQs are disabled to measure the time spent in this function
>>> without interruption and rescheduling.
>>>
>>> I am sure that there are better ways how to measure the time.
>>> Even the "time" command in userspace is able to show time how much CPU
>>> time a command used.
>>
>> I've got an idea:
>>
>> local_irq_save(flags);
>> //get the count and cputime of interrupts
>> t0 = sched_clock();
>> local_irq_restore(flags);
>>
>> (void)kallsyms_lookup_name(name);
>>
>> local_irq_save(flags);
>> t1 = sched_clock();
>> //get the count and cputime of interrupts
>> local_irq_restore(flags);
> 
> Why do you need to disable IRQs around sched_clock(), please?
> It works well in any context.

I need to calculate the difference accurately.

//get the count and cputime of interrupts
        <-------- (1) maybe interrupted
t0 = sched_clock();
(void)kallsyms_lookup_name(name);  <------- (2) maybe interrupted
t1 = sched_clock();
        <-------- (3) maybe interrupted
//get the count and cputime of interrupts

Interrupted at different points, resulting in inaccurate
calculation results. (1) and (3) also need to be considered.

> 
> Is sched_clock() needed at all?

Yes, because I'm counting the execution time of a single function, the
time is short.

> Honestly, I do not understand why you are using sched_clock() for
> this.

The unit of sched_clock() is nanosecond, high precision, no conversion required.

> 
>>> I am not familiar with it. But task_cputime() in
>>> kernel/sched/cputime.c looks promising. And there must be
>>> the interface how the user space get this information.
>>> Some is available via /proc/<PID>/... I am not sure
>>> if there is a syscall.
> 
> Please, try to investigate the above hints.

Yes, I will. Thanks.

> 
> Honestly, it looks like you do not know what you are doing.
> 
> I NACK this patch.
> 
> Best Regards,
> Petr
> .
> 

-- 
Regards,
  Zhen Lei

Re: [PATCH] kallsyms: Fix sleeping function called from invalid context when CONFIG_KALLSYMS_SELFTEST=y

[Leizhen (ThunderTown)]

On 2022/12/21 20:37, Leizhen (ThunderTown) wrote:
>>>> I am not familiar with it. But task_cputime() in
>>>> kernel/sched/cputime.c looks promising. And there must be
>>>> the interface how the user space get this information.
>>>> Some is available via /proc/<PID>/... I am not sure
>>>> if there is a syscall.
>> Please, try to investigate the above hints.
> Yes, I will. Thanks.

Function task_cputime() works well when CONFIG_VIRT_CPU_ACCOUNTING_GEN=y,
but not when CONFIG_TICK_CPU_ACCOUNTING=y. The latter seems to be based on
tick interrupt sampling, rather than recording timestamps during task switches.

> 

-- 
Regards,
  Zhen Lei