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
