----- On Jan 10, 2019, at 9:25 AM, Mathieu Desnoyers [email protected] wrote:
> ----- On Jan 10, 2019, at 9:11 AM, Mathieu Desnoyers > [email protected] wrote: > >> ----- On Jan 10, 2019, at 8:44 AM, Mathieu Desnoyers >> [email protected] wrote: >> >>> ----- On Jan 10, 2019, at 8:08 AM, rostedt [email protected] wrote: >>> >>>> On Wed, 9 Jan 2019 20:38:51 -0500 (EST) >>>> Mathieu Desnoyers <[email protected]> wrote: >>>> >>>>> Hi Paul, >>>>> >>>>> I've had a user report that trace_sched_waking() appears to be >>>>> invoked while !rcu_is_watching() in some situation, so I started >>>>> digging into the scheduler idle code. >>>> >>>> I'm wondering if this isn't a bug. Do you have the backtrace for where >>>> trace_sched_waking() was called without rcu watching? >>> >>> I strongly suspect a bug as well. I'm awaiting a reproducer from the >>> user whom reported this issue so I can add a >>> WARN_ON_ONCE(!rcu_is_watching()) >>> in the scheduler code near trace_sched_waking() and gather a backtrace. >>> >>> It still has to be confirmed, but I suspect this have been triggered >>> within a HyperV guest. It may therefore be related to a virtualized >>> environment. >>> >>> I'll try to ask more specifically on which environment this was encountered. >> >> So it ends up it happens directly on hardware on a Linux laptop. Here is >> the stacktrace: >> >> vmlinux!try_to_wake_up >> vmlinux!default_wake_function >> vmlinux!pollwake >> vmlinux!__wake_up_common >> vmlinux!__wake_up_common_lock >> vmlinux!__wake_up >> vmlinux!perf_event_wakeup >> vmlinux!perf_pending_event >> vmlinux!irq_work_run_list >> vmlinux!irq_work_run >> vmlinux!smp_irq_work_iterrupt >> vmlinux!irq_work_interrupt >> vmlinux!finish_task_switch >> vmlinux!__schedule >> vmlinux!schedule_idle >> vmlinux!do_idle >> vmlinux!cpu_startup_entry >> vmlinux!start_secondary >> vmlinux!secondary_startup_64 >> >> Does it raise any red flag ? > > Based on this backtrace, I think I start to get a better understanding > of the situation. > > The initial problem reported to me was that ftrace was showing some > sched_waking > events in its trace that were missed by perf. > > I presumed this was because of the !rcu_is_watching() check, but I think I was > wrong. > > This backtrace seems to show that perf is itself triggering a sched_waking() > event. It there is probably a check that discards nested events within perf, > which would discard this from perf traces, but ftrace (and lttng) would trace > it just fine. Looking at: static void perf_pending_event(struct irq_work *entry) { struct perf_event *event = container_of(entry, struct perf_event, pending); int rctx; rctx = perf_swevent_get_recursion_context(); /* * If we 'fail' here, that's OK, it means recursion is already disabled * and we won't recurse 'further'. */ if (event->pending_disable) { event->pending_disable = 0; perf_event_disable_local(event); } if (event->pending_wakeup) { event->pending_wakeup = 0; perf_event_wakeup(event); } if (rctx >= 0) perf_swevent_put_recursion_context(rctx); } One side-effect of perf_event_wakeup() is to generate a sched_waking event. But I suspect it won't be traced by perf because it is invoked before putting the recursion context. Is there a reason why the wakeup is done before putting the recursion context ? Thanks, Mathieu -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com
