[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <c5a04eaa-2b8d-647a-7c70-9262e6147394@huawei.com>
Date: Tue, 20 Dec 2022 22:29:31 +0800
From: "Leizhen (ThunderTown)" <thunder.leizhen@...wei.com>
To: Petr Mladek <pmladek@...e.com>,
Christophe Leroy <christophe.leroy@...roup.eu>
CC: "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
Luis Chamberlain <mcgrof@...nel.org>,
"linux-modules@...r.kernel.org" <linux-modules@...r.kernel.org>,
Anders Roxell <anders.roxell@...aro.org>
Subject: Re: [PATCH] kallsyms: Fix sleeping function called from invalid
context when CONFIG_KALLSYMS_SELFTEST=y
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
Powered by blists - more mailing lists