Perf: event wakeup discards sched_waking events

[Mathieu Desnoyers]

----- On Jan 10, 2019, at 9:25 AM, Mathieu Desnoyers mathieu.desnoyers@xxxxxxxxxxxx wrote:

> ----- On Jan 10, 2019, at 9:11 AM, Mathieu Desnoyers
> mathieu.desnoyers@xxxxxxxxxxxx wrote:
> 
>> ----- On Jan 10, 2019, at 8:44 AM, Mathieu Desnoyers
>> mathieu.desnoyers@xxxxxxxxxxxx wrote:
>> 
>>> ----- On Jan 10, 2019, at 8:08 AM, rostedt rostedt@xxxxxxxxxxx wrote:
>>> 
>>>> On Wed, 9 Jan 2019 20:38:51 -0500 (EST)
>>>> Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxxxx> 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