[lttng-dev] Lacking instrumentation for threaded IRQs

[Julien Desfossez]

[...]

>>> For 2-
>>>
>>> * Instrument the kernel: Add tracepoints to the beginning and end of the
>>> irq_thread_fn function. Those events would indicate the context of a
>>> threaded IRQ so all events inside can be considered the results of an IRQ.
>>>
>>> * Instrument LTTng: Add a field to the lttng_statedump_interrupt
>>> tracepoint to add the thread handling this IRQ if available. That would
>>> give this thread a special state: instead of running, whatever happens
>>> there would be considered as the result of an IRQ. But only LTTng traces
>>> would benefit from this tracepoint, and only if there's a statedump (so
>>> not snapshot). It's sad... But would make a quick win for now.
>>>
>>>
>>> Here's a pad showing those possible options:
>>> https://hebdo.framapad.org/p/threadedirqlttnglinux8gjkh51yhfha
[...]

>> For #2, I am not exactly sure why we need special events for those
>> kernel threads, with the fix for #1, we know they are interrupt-related
>> threads, but they are not interrupts in the sense of "doing work while
>> the current task is interrupted". To me, everything this thread does is
>> related to the previous source of wakeup and I would imagine every chunk
>> of work it does is between an irq_thread_fn_entry/return block.
>> I am not against adding this information (or the statedump approach if
>> we are sure there is a 1 to 1 mapping), but I would like to understand
>> more precisely what this information would add to our understanding of
>> the trace.
>>
> We need to know that those threads are really interrupt thread for the
> dependency analysis. Look at the following sequence of events:
> 
> [12:02:17.779984311] (+0.000002224) dorsallaptop *sched_waking*: {
> cpu_id = 3 }, { comm = "irq/130-iwlwifi", tid = *639*, prio = -51,
> target_cpu = 3 }
> [12:02:17.779985668] (+0.000000565) dorsallaptop *do_IRQ_return*: {
> cpu_id = 3 }, { ip = 0xFFFFFFFF89A01C30, parent_ip = 0xFFFFFFFF89A0098F }
> [12:02:17.779986575] (+0.000000907) dorsallaptop *sched_switch*: {
> cpu_id = 3 }, { prev_comm = "swapper/3", prev_tid = 0, prev_prio = 20,
> prev_state = 0, next_comm = "irq/130-iwlwifi", next_tid = *639*,
> next_prio = -51 }
> [12:02:17.779998608] (+0.000011174) dorsallaptop net_if_receive_skb: {
> cpu_id = 3 }, { ... }
> [12:02:17.780019468] (+0.000020860) dorsallaptop sched_waking: { cpu_id
> = 3 }, { comm = "wget", tid = 2430, prio = 20, target_cpu = 0 }
> 
> If we do the critical path of the wget process, with the irq/130-iwlwifi
> thread considered a normal thread, we see it is woken up by an hardware
> interrupt, that we know if iwlwifi, but we don't know anything else
> about it, so the critical path ends up following the swapper process...
> Now if we consider the irq/130-iwlwifi thread as an interrupt-running
> process, we see that wget is actually woken up by the net_if_receive_skb
> event and we can follow this to the packet sent by another machine.
> Of course this can all be done at analysis time: if (ret = 2 and a
> wakeup inside the do_IRQ but outside the irq_handler) { assume the woken
> thread will be handling the interrupt } But it's the "assume" part that
> I don't like. With instrumentation, we can clarify this.

In this example, assuming we have the do_IRQ event, the critical path
seems clear to me:
- irq wakes up task 639
- task 639 runs, receives a packet and wakes up another task

So wget has been woken up by a thread that was itself woken up by an
interrupt, I don't see how swapper could end up in this chain if we have
the do_IRQ event.

I think the distinction with your explanation is that I see the
receive_skb as context around the wake up, but the source of wake up
(the transition in the dependency graph) is the wakeup occurring while
process 639 running, and that trace backs to the IRQ.

Julien