It's currently nigh impossible to get these pr_debug()s to print something. Being guarded by initcall_debug means one has to enable tons of other debug output during boot, and the system_state condition further means it's impossible to get them when loading modules later.
Also, the compiler can't know that these global conditions do not change, so there are W=2 warnings kernel/async.c:125:9: warning: ‘calltime’ may be used uninitialized in this function [-Wmaybe-uninitialized] kernel/async.c:300:9: warning: ‘starttime’ may be used uninitialized in this function [-Wmaybe-uninitialized] Make it possible, for a DYNAMIC_DEBUG kernel, to get these to print their messages by booting with appropriate 'dyndbg="file async.c +p"' command line argument. For a non-DYNAMIC_DEBUG kernel, pr_debug() compiles to nothing. This does cost doing an unconditional ktime_get() for the starttime value, but the corresponding ktime_get for the end time can be elided by factoring it into a function which only gets called if the printk() arguments end up being evaluated. Signed-off-by: Rasmus Villemoes <li...@rasmusvillemoes.dk> --- Andrew, this one is of course on top of https://lore.kernel.org/lkml/20210226124355.2503524-1-li...@rasmusvillemoes.dk/ which you already applied. kernel/async.c | 48 ++++++++++++++++++++---------------------------- 1 file changed, 20 insertions(+), 28 deletions(-) diff --git a/kernel/async.c b/kernel/async.c index 45a867b8644a..4b5971142922 100644 --- a/kernel/async.c +++ b/kernel/async.c @@ -78,6 +78,12 @@ static DECLARE_WAIT_QUEUE_HEAD(async_done); static atomic_t entry_count; +static long long microseconds_since(ktime_t start) +{ + ktime_t now = ktime_get(); + return ktime_to_ns(ktime_sub(now, start)) >> 10; +} + static async_cookie_t lowest_in_progress(struct async_domain *domain) { struct async_entry *first = NULL; @@ -111,24 +117,18 @@ static void async_run_entry_fn(struct work_struct *work) struct async_entry *entry = container_of(work, struct async_entry, work); unsigned long flags; - ktime_t calltime, delta, rettime; + ktime_t calltime; /* 1) run (and print duration) */ - if (initcall_debug && system_state < SYSTEM_RUNNING) { - pr_debug("calling %lli_%pS @ %i\n", - (long long)entry->cookie, - entry->func, task_pid_nr(current)); - calltime = ktime_get(); - } + pr_debug("calling %lli_%pS @ %i\n", (long long)entry->cookie, + entry->func, task_pid_nr(current)); + calltime = ktime_get(); + entry->func(entry->data, entry->cookie); - if (initcall_debug && system_state < SYSTEM_RUNNING) { - rettime = ktime_get(); - delta = ktime_sub(rettime, calltime); - pr_debug("initcall %lli_%pS returned after %lld usecs\n", - (long long)entry->cookie, - entry->func, - (long long)ktime_to_ns(delta) >> 10); - } + + pr_debug("initcall %lli_%pS returned after %lld usecs\n", + (long long)entry->cookie, entry->func, + microseconds_since(calltime)); /* 2) remove self from the pending queues */ spin_lock_irqsave(&async_lock, flags); @@ -287,23 +287,15 @@ EXPORT_SYMBOL_GPL(async_synchronize_full_domain); */ void async_synchronize_cookie_domain(async_cookie_t cookie, struct async_domain *domain) { - ktime_t starttime, delta, endtime; + ktime_t starttime; - if (initcall_debug && system_state < SYSTEM_RUNNING) { - pr_debug("async_waiting @ %i\n", task_pid_nr(current)); - starttime = ktime_get(); - } + pr_debug("async_waiting @ %i\n", task_pid_nr(current)); + starttime = ktime_get(); wait_event(async_done, lowest_in_progress(domain) >= cookie); - if (initcall_debug && system_state < SYSTEM_RUNNING) { - endtime = ktime_get(); - delta = ktime_sub(endtime, starttime); - - pr_debug("async_continuing @ %i after %lli usec\n", - task_pid_nr(current), - (long long)ktime_to_ns(delta) >> 10); - } + pr_debug("async_continuing @ %i after %lli usec\n", task_pid_nr(current), + microseconds_since(starttime)); } EXPORT_SYMBOL_GPL(async_synchronize_cookie_domain); -- 2.29.2
