LTTng core kernel instrumentation

Instrumentation of IRQ related events : irq_entry, irq_exit and irq_next_handler.

It allows tracers to perform latency analysis on those various types of interrupts and to detect interrupts with max/min/avg duration. It helps detecting driver or hardware problems which cause an ISR to take ages to execute. It has been shown to be the case with bogus hardware causing an mmio read to take a few milliseconds.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

irq_entry and irq_exit not declared static because they appear in x86 arch code.

The idea behind logging irq/softirq/tasklet/(and eventually syscall) entry and exit events is to be able to recreate the kernel execution state at a given point in time. Knowing which execution context is responsible for a given trace event is _very_ valuable in trace data analysis.

The IRQ instrumentation instruments the IRQ handler entry and exit. Jason instrumented the irq notifier chain calls (irq_handler_entry/exit). His approach provides information about which handler is being called, but does not map correctly to the fact that _multiple_ handlers are being called from within the same interrupt handler. From an interrupt latency analysis POV, this is incorrect.

Quoted 24 lines · Mathieu Desnoyers

Instrumentation of IRQ related events : irq_entry, irq_exit and irq_next_handler.

It allows tracers to perform latency analysis on those various types of interrupts and to detect interrupts with max/min/avg duration. It helps detecting driver or hardware problems which cause an ISR to take ages to execute. It has been shown to be the case with bogus hardware causing an mmio read to take a few milliseconds.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

irq_entry and irq_exit not declared static because they appear in x86 arch code.

The idea behind logging irq/softirq/tasklet/(and eventually syscall) entry and exit events is to be able to recreate the kernel execution state at a given point in time. Knowing which execution context is responsible for a given trace event is _very_ valuable in trace data analysis.

Quoted 7 lines

The IRQ instrumentation instruments the IRQ handler entry and exit. Jason instrumented the irq notifier chain calls (irq_handler_entry/exit). His approach provides information about which handler is being called, but does not map correctly to the fact that _multiple_ handlers are being called from within the same interrupt handler. From an interrupt latency analysis POV, this is incorrect.

Since we are passing back the irq number, and we can not be interrupted by the same irq, I think it should be pretty clear we are in the same handler. That said, the extra entry/exit tracepoints could make the sequence of events simpler to decipher, which is important. The code looks good, and provides at least as much information as the patch that I proposed. So i'll be happy either way :)

Quoted 33 lines · Jason Baron

Quoted 24 lines · Mathieu Desnoyers

Instrumentation of IRQ related events : irq_entry, irq_exit and irq_next_handler.

It allows tracers to perform latency analysis on those various types of interrupts and to detect interrupts with max/min/avg duration. It helps detecting driver or hardware problems which cause an ISR to take ages to execute. It has been shown to be the case with bogus hardware causing an mmio read to take a few milliseconds.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

irq_entry and irq_exit not declared static because they appear in x86 arch code.

The idea behind logging irq/softirq/tasklet/(and eventually syscall) entry and exit events is to be able to recreate the kernel execution state at a given point in time. Knowing which execution context is responsible for a given trace event is _very_ valuable in trace data analysis.

Quoted 7 lines

The IRQ instrumentation instruments the IRQ handler entry and exit. Jason instrumented the irq notifier chain calls (irq_handler_entry/exit). His approach provides information about which handler is being called, but does not map correctly to the fact that _multiple_ handlers are being called from within the same interrupt handler. From an interrupt latency analysis POV, this is incorrect.

Quoted 7 lines

Since we are passing back the irq number, and we can not be interrupted by the same irq, I think it should be pretty clear we are in the same handler. That said, the extra entry/exit tracepoints could make the sequence of events simpler to decipher, which is important. The code looks good, and provides at least as much information as the patch that I proposed. So i'll be happy either way :)

We already have your patch merged up in the tracing tree and it gives entry+exit tracepoints.

Ingo

Quoted 46 lines · Ingo Molnar

Quoted 33 lines · Jason Baron

Quoted 24 lines · Mathieu Desnoyers

Instrumentation of IRQ related events : irq_entry, irq_exit and irq_next_handler.

It allows tracers to perform latency analysis on those various types of interrupts and to detect interrupts with max/min/avg duration. It helps detecting driver or hardware problems which cause an ISR to take ages to execute. It has been shown to be the case with bogus hardware causing an mmio read to take a few milliseconds.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

irq_entry and irq_exit not declared static because they appear in x86 arch code.

The idea behind logging irq/softirq/tasklet/(and eventually syscall) entry and exit events is to be able to recreate the kernel execution state at a given point in time. Knowing which execution context is responsible for a given trace event is _very_ valuable in trace data analysis.

Quoted 7 lines

The IRQ instrumentation instruments the IRQ handler entry and exit. Jason instrumented the irq notifier chain calls (irq_handler_entry/exit). His approach provides information about which handler is being called, but does not map correctly to the fact that _multiple_ handlers are being called from within the same interrupt handler. From an interrupt latency analysis POV, this is incorrect.

Quoted 7 lines

Since we are passing back the irq number, and we can not be interrupted by the same irq, I think it should be pretty clear we are in the same handler. That said, the extra entry/exit tracepoints could make the sequence of events simpler to decipher, which is important. The code looks good, and provides at least as much information as the patch that I proposed. So i'll be happy either way :)

We already have your patch merged up in the tracing tree and it gives entry+exit tracepoints.

Quoted 1 line

Ingo

maybe i wasn't clear. Entry and exit as I proposed and as in the tracing tree are for entry and exit into each handler per irq. Mathieu is proposing an entry/exit tracepoint per irq, and a 3rd tracepoint to tell us which handler is being called and its return code. hope this is clear.

Quoted 47 lines · Jason Baron

Quoted 46 lines · Ingo Molnar

Quoted 33 lines · Jason Baron

Quoted 24 lines · Mathieu Desnoyers

Instrumentation of IRQ related events : irq_entry, irq_exit and irq_next_handler.

It allows tracers to perform latency analysis on those various types of interrupts and to detect interrupts with max/min/avg duration. It helps detecting driver or hardware problems which cause an ISR to take ages to execute. It has been shown to be the case with bogus hardware causing an mmio read to take a few milliseconds.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

irq_entry and irq_exit not declared static because they appear in x86 arch code.

The idea behind logging irq/softirq/tasklet/(and eventually syscall) entry and exit events is to be able to recreate the kernel execution state at a given point in time. Knowing which execution context is responsible for a given trace event is _very_ valuable in trace data analysis.

Quoted 7 lines

The IRQ instrumentation instruments the IRQ handler entry and exit. Jason instrumented the irq notifier chain calls (irq_handler_entry/exit). His approach provides information about which handler is being called, but does not map correctly to the fact that _multiple_ handlers are being called from within the same interrupt handler. From an interrupt latency analysis POV, this is incorrect.

Quoted 7 lines

Since we are passing back the irq number, and we can not be interrupted by the same irq, I think it should be pretty clear we are in the same handler. That said, the extra entry/exit tracepoints could make the sequence of events simpler to decipher, which is important. The code looks good, and provides at least as much information as the patch that I proposed. So i'll be happy either way :)

We already have your patch merged up in the tracing tree and it gives entry+exit tracepoints.

Quoted 7 lines

Quoted 1 line

Ingo

maybe i wasn't clear. Entry and exit as I proposed and as in the tracing tree are for entry and exit into each handler per irq. Mathieu is proposing an entry/exit tracepoint per irq, and a 3rd tracepoint to tell us which handler is being called and its return code. hope this is clear.

Ok, i misunderstood that.

Mathieu's is slightly more compact, but yours is more logical.

I believe your pre/post IRQ handler callback is the right model - it decouples device IRQ handling from any notion of 'IRQ'.

For example, we could correctly express "handler got executed by an IRQ thread" via it - while via Mathieu's scheme it does not really map to that.

So if then i think there should be a third tracepoint in addition to your two existing tracepoints: a 'raw vector' type of tracepoint. It's added both to do_IRQ() entry point, but also to the various common SMP IPI entry points: reschedule, TLB flush and local timer IRQ tick.

The best information there to pass to the probe is the raw vector number, and the ptregs structure.

Hm?

Ingo

If we want to do this logically, without thinking about tracer performance impact, we could/should do :

trace_irq_entry(irqno, pt_regs)

  for_each_handler() {
    trace_irq_handler_entry(action)
    action->handler()
    trace_irq_handler_exit(ret)

}
trace_irq_exit(retval)

Quoted 10 lines · Mathieu Desnoyers

If we want to do this logically, without thinking about tracer performance impact, we could/should do :

trace_irq_entry(irqno, pt_regs)

  for_each_handler() {
    trace_irq_handler_entry(action)
    action->handler()
    trace_irq_handler_exit(ret)

}
trace_irq_exit(retval)

Not really.

Quoted 14 lines · Ingo Molnar

Quoted 10 lines · Mathieu Desnoyers

If we want to do this logically, without thinking about tracer performance impact, we could/should do :

trace_irq_entry(irqno, pt_regs)

  for_each_handler() {
    trace_irq_handler_entry(action)
    action->handler()
    trace_irq_handler_exit(ret)

}
trace_irq_exit(retval)

Quoted 1 line

Not really.

Put differently: we seem to agree on handler invocation entry/exit events (and those are handled by Jason's patch already), and that's good.

I dont think we need two events for physical IRQ events though. One is enough: entry event. What meaning does 'retval' have in your pseudo-code above? None typically.

This is actually a very good example of what Christoph Hellwig, Peter Zijlstra and myself have been trying to warn you about the TRACE_EVENT macro : it exports the tracepoints to userspace, and thus makes them a userspace-visible API, when those tracepoints should be tied to the kernel code and nothing else. An adaptation layer should provide the abstractions that makes the information presented to the user more "logical".

Quoted 8 lines · Mathieu Desnoyers

This is actually a very good example of what Christoph Hellwig, Peter Zijlstra and myself have been trying to warn you about the TRACE_EVENT macro : it exports the tracepoints to userspace, and thus makes them a userspace-visible API, when those tracepoints should be tied to the kernel code and nothing else. An adaptation layer should provide the abstractions that makes the information presented to the user more "logical".

Let me correct you here. TRACE_EVENT does ***NOT*** export anything to userspace. There is no code what so ever in TRACE_EVENT that does so.

Now, ftrace does export information using TRACE_EVENT to userspace. But that is the way ftrace wants to handle it. There's nothing needed to export to userspace. What is exported, is exported ***BECAUSE*** it can change. I'll only try to keep the format that is exported the same. But nothing should rely on what the format represents staying the same.

If someone adds a TRACE_EVENT, you can uses it to record you data, anyway you like. Ftrace will use it to show how to read the binary data, which is only needed if you want to do that. It uses the print format to print to the console in case of failure. Or to the trace file, which by the way can also change without notice.

Quoted 11 lines · * Steven Rostedt ([email protected]) wrote:

Quoted 8 lines · Mathieu Desnoyers

This is actually a very good example of what Christoph Hellwig, Peter Zijlstra and myself have been trying to warn you about the TRACE_EVENT macro : it exports the tracepoints to userspace, and thus makes them a userspace-visible API, when those tracepoints should be tied to the kernel code and nothing else. An adaptation layer should provide the abstractions that makes the information presented to the user more "logical".

Quoted 3 lines

Let me correct you here. TRACE_EVENT does ***NOT*** export anything to userspace. There is no code what so ever in TRACE_EVENT that does so.

Except the comment on top of TRACE_EVENT() in tracepoint.h maybe ?

 *      *
 *      * Fast binary tracing: define the trace record via
 *      * TP_STRUCT__entry(). You can think about it like a
 *      * regular C structure local variable definition.
 *      *
 *      * This is how the trace record is structured and will
 *      * be saved into the ring buffer. These are the fields
 *      * that will be exposed to user-space in
 *      * /debug/tracing/events/<*>/format.

You don't need to have code within the infrastructure to actually export stuff to userspace. Stating in the API that you some information will be presented to userspace counts.

Quoted 7 lines

Now, ftrace does export information using TRACE_EVENT to userspace. But that is the way ftrace wants to handle it. There's nothing needed to export to userspace. What is exported, is exported ***BECAUSE*** it can change. I'll only try to keep the format that is exported the same. But nothing should rely on what the format represents staying the same.

Quoted 5 lines

If someone adds a TRACE_EVENT, you can uses it to record you data, anyway you like. Ftrace will use it to show how to read the binary data, which is only needed if you want to do that. It uses the print format to print to the console in case of failure. Or to the trace file, which by the way can also change without notice.

Hrm, so you are planning to add, in
include/trace/sched_event_types.h, things like :

TRACE_EVENT(sched_kthread_stop,

        TP_PROTO(struct task_struct *t),

        TP_ARGS(t),

        TP_STRUCT__entry(
                __array(        char,   comm,   TASK_COMM_LEN   )
                __field(        pid_t,  pid                     )
        ),

        TP_fast_assign(
                memcpy(__entry->comm, t->comm, TASK_COMM_LEN);
                __entry->pid    = t->pid;
        ),

        TP_printk("task %s:%d", __entry->comm, __entry->pid)

);

Actually specifying that the TP_STRUCT__entry, TP_fast_assign and TP_printk are specific to ftrace and should not be considered as a stable API, am I correct ?

Then only when ftrace is built in the kernel do we have kernel/trace/events.c including the holy include/trace/trace_events.h, which includes all the trace_events headers, and then including kernel/trace/trace_events_stage_{1,2,3}.h to override the TRACE_EVENT macro and create the callbacks for each TRACE_EVENT statements.

Then big problem with this is that, whether you like it or not, you *are* adding an API to the tracepoints, but just validating the types when ftrace is being built. If you want to add an API to the tracepoints, then the type verification should be done _even when ftrace is disabled_.

Therefore, the TRACE_EVENT in tracepoint.h should map to macros that would verify the argument types.

I think it's ok to specify that the arguments of a given TRACE_EVENT may change without notice. We have to say it explicitly in the TRACE_EVENT header though.

And while we talk about this, I also wonder why we won't simply embed the result of the TP_fast_assign and TP_printk in the tracepoint unlikely branch ? This would skip a function call in the tracing fast path, and would save the overhead of a whole function call when tracing is active. But that implies more bounds between tracepoints and data output, but given you are already declaring this in the same API, I don't see the problem anymore.

About the struct ftrace_raw_##name created in stage 1, I think the padding at the end of the structure is a complete waste of space. You should probably have a look at the ltt-type-serializer.[ch] in LTTng.

I am still unsure that the approach you take with TRACE_EVENT, which I would call "automatically generating code using header and macro tricks", is in the end easier to review than the simple C callback approach I have taken in LTTng, adding the "glue" in the DEFINE_MARKER_TP() macros to connect a specific C callback to the actual tracepoint.

The good thing about your approach is that everyting about a trace event can be declared within the same macro. In LTTng, I have to create probe modules and write stuff like :

void probe_irq_softirq_exit(struct softirq_action *h,

        struct softirq_action *softirq_vec);

DEFINE_MARKER_TP(kernel, softirq_exit, irq_softirq_exit,

        probe_irq_softirq_exit, "softirq_id #1u%lu");

void probe_irq_softirq_exit(struct softirq_action *h,
struct softirq_action *softirq_vec)

{
        struct marker *marker;
        unsigned char data;

        data = ((unsigned long)h - (unsigned long)softirq_vec) / sizeof(*h);

        marker = &GET_MARKER(kernel, softirq_exit);
        ltt_specialized_trace(marker, marker->single.probe_private,
                &data, sizeof(data), sizeof(data));
}

by hand, and then the kernel softirq_exit event is shown in debugfs/ltt/markers/kernel/softirq_exit/. But I don't see the big win you get by doing it in TRACE_EVENT, especially if it is not type-verified when ftrace is disabled, compared to adding those callbacks in standard kernel modules, which is a coding-style we have been used to for years.

I haven't seen much automatically generated code around in the kernel tree, maybe there is a good reason ? I can't wait to see the first kernel JIT based on ftrace. ;-)

Mathieu

Signature · 2 lines

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Quoted 28 lines · Mathieu Desnoyers

Quoted 11 lines · * Steven Rostedt ([email protected]) wrote:

Quoted 8 lines · Mathieu Desnoyers

This is actually a very good example of what Christoph Hellwig, Peter Zijlstra and myself have been trying to warn you about the TRACE_EVENT macro : it exports the tracepoints to userspace, and thus makes them a userspace-visible API, when those tracepoints should be tied to the kernel code and nothing else. An adaptation layer should provide the abstractions that makes the information presented to the user more "logical".

Quoted 3 lines

Let me correct you here. TRACE_EVENT does ***NOT*** export anything to userspace. There is no code what so ever in TRACE_EVENT that does so.

Except the comment on top of TRACE_EVENT() in tracepoint.h maybe ?

 *      *
 *      * Fast binary tracing: define the trace record via
 *      * TP_STRUCT__entry(). You can think about it like a
 *      * regular C structure local variable definition.
 *      *
 *      * This is how the trace record is structured and will
 *      * be saved into the ring buffer. These are the fields
 *      * that will be exposed to user-space in
 *      * /debug/tracing/events/<*>/format.

Quoted 3 lines

You don't need to have code within the infrastructure to actually export stuff to userspace. Stating in the API that you some information will be presented to userspace counts.

That is done by ftrace not TRACE_EVENT.

Quoted 35 lines

Quoted 7 lines

Now, ftrace does export information using TRACE_EVENT to userspace. But that is the way ftrace wants to handle it. There's nothing needed to export to userspace. What is exported, is exported ***BECAUSE*** it can change. I'll only try to keep the format that is exported the same. But nothing should rely on what the format represents staying the same.

Quoted 5 lines

If someone adds a TRACE_EVENT, you can uses it to record you data, anyway you like. Ftrace will use it to show how to read the binary data, which is only needed if you want to do that. It uses the print format to print to the console in case of failure. Or to the trace file, which by the way can also change without notice.

Hrm, so you are planning to add, in
include/trace/sched_event_types.h, things like :

TRACE_EVENT(sched_kthread_stop,

        TP_PROTO(struct task_struct *t),

        TP_ARGS(t),

        TP_STRUCT__entry(
                __array(        char,   comm,   TASK_COMM_LEN   )
                __field(        pid_t,  pid                     )
        ),

        TP_fast_assign(
                memcpy(__entry->comm, t->comm, TASK_COMM_LEN);
                __entry->pid    = t->pid;
        ),

        TP_printk("task %s:%d", __entry->comm, __entry->pid)

);

Quoted 3 lines

Actually specifying that the TP_STRUCT__entry, TP_fast_assign and TP_printk are specific to ftrace and should not be considered as a stable API, am I correct ?

No they are not specific to ftrace. I said they are used by ftrace. They can be modified at will by the maintainer. The macros makes the updates automatic for ftrace.

Quoted 6 lines

Then only when ftrace is built in the kernel do we have kernel/trace/events.c including the holy include/trace/trace_events.h, which includes all the trace_events headers, and then including kernel/trace/trace_events_stage_{1,2,3}.h to override the TRACE_EVENT macro and create the callbacks for each TRACE_EVENT statements.

Currently ftrace is the only user of the include/trace/trace_events.h Others are welcome to do what they wish.

Quoted 1 line

Quoted 5 lines

Then big problem with this is that, whether you like it or not, you *are* adding an API to the tracepoints, but just validating the types when ftrace is being built. If you want to add an API to the tracepoints, then the type verification should be done _even when ftrace is disabled_.

It's an internal API not a user space one. Internal APIs are fine, and can change whenever we want.

Quoted 3 lines

Therefore, the TRACE_EVENT in tracepoint.h should map to macros that would verify the argument types.

We could do that too.

Quoted 4 lines

I think it's ok to specify that the arguments of a given TRACE_EVENT may change without notice. We have to say it explicitly in the TRACE_EVENT header though.

Sure, I totally agree.

Quoted 8 lines

And while we talk about this, I also wonder why we won't simply embed the result of the TP_fast_assign and TP_printk in the tracepoint unlikely branch ? This would skip a function call in the tracing fast path, and would save the overhead of a whole function call when tracing is active. But that implies more bounds between tracepoints and data output, but given you are already declaring this in the same API, I don't see the problem anymore.

I'm not exactly what you mean here? You mean to add it at the location in the code? If that is the case, I disagree. Since we don't want to clutter code with trace point data. It is nice to keep it out in separate headers.

This is what we also think about #ifdefs, it is better to have static inlines in headers that to clutter the code with them.

Quoted 4 lines

About the struct ftrace_raw_##name created in stage 1, I think the padding at the end of the structure is a complete waste of space. You should probably have a look at the ltt-type-serializer.[ch] in LTTng.

I don't know what padding you are talking about.

Quoted 32 lines

I am still unsure that the approach you take with TRACE_EVENT, which I would call "automatically generating code using header and macro tricks", is in the end easier to review than the simple C callback approach I have taken in LTTng, adding the "glue" in the DEFINE_MARKER_TP() macros to connect a specific C callback to the actual tracepoint.

The good thing about your approach is that everyting about a trace event can be declared within the same macro. In LTTng, I have to create probe modules and write stuff like :

void probe_irq_softirq_exit(struct softirq_action *h,

        struct softirq_action *softirq_vec);

DEFINE_MARKER_TP(kernel, softirq_exit, irq_softirq_exit,

        probe_irq_softirq_exit, "softirq_id #1u%lu");

void probe_irq_softirq_exit(struct softirq_action *h,
struct softirq_action *softirq_vec)

{
        struct marker *marker;
        unsigned char data;

        data = ((unsigned long)h - (unsigned long)softirq_vec) / sizeof(*h);

        marker = &GET_MARKER(kernel, softirq_exit);
        ltt_specialized_trace(marker, marker->single.probe_private,
                &data, sizeof(data), sizeof(data));
}

Quoted 6 lines

by hand, and then the kernel softirq_exit event is shown in debugfs/ltt/markers/kernel/softirq_exit/. But I don't see the big win you get by doing it in TRACE_EVENT, especially if it is not type-verified when ftrace is disabled, compared to adding those callbacks in standard kernel modules, which is a coding-style we have been used to for years.

Well, I originally had it like you did above. But I found that if I did that, the number of events would be greatly limited. Once I added this infrastructure, a bunch of events were able to be made quickly.

As for the type checking, that should be easy to add. Don't need ftrace to do it.

-- Steve

Quoted 11 lines

I haven't seen much automatically generated code around in the kernel tree, maybe there is a good reason ? I can't wait to see the first kernel JIT based on ftrace. ;-)

Mathieu

Signature · 2 lines

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

This third type of tracepoint for IRQs you are talking about is actually what I had in LTTng. I decided to add the irq_next_handler and to add a action field to irq_entry to include the irq handler information needed by Jason.

If we want to do this logically, without thinking about tracer performance impact, we could/should do :

trace_irq_entry(irqno, pt_regs)

  for_each_handler() {
    trace_irq_handler_entry(action)
    action->handler()
    trace_irq_handler_exit(ret)

}
trace_irq_exit(retval)

And add the irq_entry/irq_exit events to the arch-specific reschedule, tlb flush, local timer irq, as I have in my lttng tree already.

But given the trace_irq_handler_entry/trace_irq_handler_exit events could be combined, given we can record action and ret in the irq_entry/exit events, I decided to remove 2 tracepoints (out of 4) from the single-handler fast path by adding this information to the irq entry/exit events, and decided to combine the irq_handler entry/exit into a single next_handler event, which records the previous ret value and the next action to execute.

On an interrupt-driven workload, it will have a significant impact. (2 events vs 4).

If we add interrupt threads to the kernel, then we can switch to the following scheme :

* instrumentation of the real interrupt handler :

trace_irq_entry(irqno, pt_regs)

trace_irq_exit(ret)

* instrumentation of the irq threads :

trace_irq_thread_entry()

trace_irq_thread_exit()

I don't see why we should mind trying to make the tracepoints "logical", especially if it hurts performance considerably. Doing these implementation-specific versions of irq tracepoints would provide the best performance we can get when tracing. It's up to the tracers to specialize their analysis based on the underlying IRQ mechanism (non-threaded vs threaded).

Quoted 28 lines · Mathieu Desnoyers

This third type of tracepoint for IRQs you are talking about is actually what I had in LTTng. I decided to add the irq_next_handler and to add a action field to irq_entry to include the irq handler information needed by Jason.

If we want to do this logically, without thinking about tracer performance impact, we could/should do :

trace_irq_entry(irqno, pt_regs)

  for_each_handler() {
    trace_irq_handler_entry(action)
    action->handler()
    trace_irq_handler_exit(ret)

}
trace_irq_exit(retval)

And add the irq_entry/irq_exit events to the arch-specific reschedule, tlb flush, local timer irq, as I have in my lttng tree already.

But given the trace_irq_handler_entry/trace_irq_handler_exit events could be combined, given we can record action and ret in the irq_entry/exit events, I decided to remove 2 tracepoints (out of 4) from the single-handler fast path by adding this information to the irq entry/exit events, and decided to combine the irq_handler entry/exit into a single next_handler event, which records the previous ret value and the next action to execute.

Quoted 2 lines

On an interrupt-driven workload, it will have a significant impact. (2 events vs 4).

I thought tracepoints while not active are very low overhead.

If you only want to use 2 of the 4, would that be just as fast?

Quoted 14 lines

If we add interrupt threads to the kernel, then we can switch to the following scheme :

* instrumentation of the real interrupt handler :

trace_irq_entry(irqno, pt_regs)

trace_irq_exit(ret)

* instrumentation of the irq threads :

trace_irq_thread_entry()

Quoted 8 lines

trace_irq_thread_exit()

I don't see why we should mind trying to make the tracepoints "logical", especially if it hurts performance considerably. Doing these implementation-specific versions of irq tracepoints would provide the best performance we can get when tracing. It's up to the tracers to specialize their analysis based on the underlying IRQ mechanism (non-threaded vs threaded).

Perhaps we want to make them logical so that other things might hook into these trace points besides a tracer. I do not agree that the code should be modified just to make the trace points faster. The trace points are just hooks into code, and should have no effect when disabled. Once the code starts to change due to better placement of tracepoints for tracers, that's when those trace points should be NACKed.

-- Steve

Quoted 47 lines · Jason Baron

Quoted 46 lines · Ingo Molnar

Quoted 33 lines · Jason Baron

Quoted 24 lines · Mathieu Desnoyers

Instrumentation of IRQ related events : irq_entry, irq_exit and irq_next_handler.

It allows tracers to perform latency analysis on those various types of interrupts and to detect interrupts with max/min/avg duration. It helps detecting driver or hardware problems which cause an ISR to take ages to execute. It has been shown to be the case with bogus hardware causing an mmio read to take a few milliseconds.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

irq_entry and irq_exit not declared static because they appear in x86 arch code.

The idea behind logging irq/softirq/tasklet/(and eventually syscall) entry and exit events is to be able to recreate the kernel execution state at a given point in time. Knowing which execution context is responsible for a given trace event is _very_ valuable in trace data analysis.

Quoted 7 lines

The IRQ instrumentation instruments the IRQ handler entry and exit. Jason instrumented the irq notifier chain calls (irq_handler_entry/exit). His approach provides information about which handler is being called, but does not map correctly to the fact that _multiple_ handlers are being called from within the same interrupt handler. From an interrupt latency analysis POV, this is incorrect.

Quoted 7 lines

Since we are passing back the irq number, and we can not be interrupted by the same irq, I think it should be pretty clear we are in the same handler. That said, the extra entry/exit tracepoints could make the sequence of events simpler to decipher, which is important. The code looks good, and provides at least as much information as the patch that I proposed. So i'll be happy either way :)

We already have your patch merged up in the tracing tree and it gives entry+exit tracepoints.

Quoted 7 lines

Quoted 1 line

Ingo

maybe i wasn't clear. Entry and exit as I proposed and as in the tracing tree are for entry and exit into each handler per irq. Mathieu is proposing an entry/exit tracepoint per irq, and a 3rd tracepoint to tell us which handler is being called and its return code. hope this is clear.

Ok, i misunderstood that.

Mathieu's is slightly more compact, but yours is more logical.

I believe your pre/post IRQ handler callback is the right model - it decouples device IRQ handling from any notion of 'IRQ'.

For example, we could correctly express "handler got executed by an IRQ thread" via it - while via Mathieu's scheme it does not really map to that.

So if then i think there should be a third tracepoint in addition to your two existing tracepoints: a 'raw vector' type of tracepoint. It's added both to do_IRQ() entry point, but also to the various common SMP IPI entry points: reschedule, TLB flush and local timer IRQ tick.

The best information there to pass to the probe is the raw vector number, and the ptregs structure.

Hm?

kernel/irq/handle.c +13 -3

+static irqreturn_t __handle_irq_next_handler(unsigned int irq,
+	struct irqaction **action, irqreturn_t *retval, unsigned int *status)
+{
+	irqreturn_t ret;
+
+	ret = (*action)->handler(irq, (*action)->dev_id);
+	if (ret == IRQ_HANDLED)
+		*status |= (*action)->flags;
+	*retval |= ret;
+	*action = (*action)->next;
+	return ret;
+}
+
 static irqreturn_t _handle_IRQ_event(unsigned int irq, struct irqaction *action)
 {
 	irqreturn_t ret, retval = IRQ_NONE;

@@ -324,13 +345,12 @@ static irqreturn_t _handle_IRQ_event(uns
 	if (!(action->flags & IRQF_DISABLED))
 		local_irq_enable_in_hardirq();
 
-	do {
-		ret = action->handler(irq, action->dev_id);
-		if (ret == IRQ_HANDLED)

* lockdep: we want to handle all irq_desc locks as a single lock-class:
*/
struct lock_class_key irq_desc_lock_class;

kernel/irq/handle.c +13 -3

@@ -316,6 +324,19 @@ irqreturn_t no_action(int cpl, void *dev
 	return IRQ_NONE;
 }
 
+static irqreturn_t __handle_irq_next_handler(unsigned int irq,
+	struct irqaction **action, irqreturn_t *retval, unsigned int *status)
+{
+	irqreturn_t ret;
+
+	ret = (*action)->handler(irq, (*action)->dev_id);
+	if (ret == IRQ_HANDLED)
+		*status |= (*action)->flags;
+	*retval |= ret;
+	*action = (*action)->next;
+	return ret;
+}
+
 static irqreturn_t _handle_IRQ_event(unsigned int irq, struct irqaction *action)
 {
 	irqreturn_t ret, retval = IRQ_NONE;

@@ -324,13 +345,12 @@ static irqreturn_t _handle_IRQ_event(uns
 	if (!(action->flags & IRQF_DISABLED))
 		local_irq_enable_in_hardirq();
 
-	do {
-		ret = action->handler(irq, action->dev_id);
-		if (ret == IRQ_HANDLED)

-----Original Message-----
From: [email protected] [mailto:[email protected]] On Behalf Of Ingo Molnar
Sent: Tuesday, March 24, 2009 1:56 PM
To: Mathieu Desnoyers
Cc: [email protected]; [email protected]; [email protected]; Frederic Weisbecker; Jason Baron; Peter Zijlstra; Thomas Gleixner; Russell King; Masami Hiramatsu; Frank Ch. Eigler; Hideo AOKI; Takashi Nishiie; Steven Rostedt; Eduard - Gabriel Munteanu
Subject: Re: [patch 3/9] LTTng instrumentation tasklets

Quoted 1 line · Mathieu Desnoyers

tasklet entry and exit events.

kernel/softirq.c static struct softirq_action softirq_vec · line 59

Quoted 4 lines

kernel/softirq.c +4 -0

+DEFINE_TRACE(irq_tasklet_high_entry);
+DEFINE_TRACE(irq_tasklet_high_exit);
+DEFINE_TRACE(irq_tasklet_low_entry);
+DEFINE_TRACE(irq_tasklet_low_exit);

Dunno - tasklets are a legacy mechanism, not sure we want to instrument them.

Quick question. I understand this is unrelated to this patch. So I apologize in advance.
Ingo - you mentioned "tasklets are a legacy mechanism". Is there a plan to phase them out ? Let me draw a small picture as to what's bothering me.

With the SR-IOV support if there are 'N' virtual functions then there will be 'N' driver instances(actually N+1, 1 for the PF). If that driver drains the responses in the interrupt context then all such VF-instances could virtually block everyone else(because SR-IOV guys might also have MSI-X enabled).
So now all such drivers should alter their Rx path.Driver's can queue tasklets and can also get the performance they want.

Any suggestions?

-----Original Message-----
From: Peter Zijlstra [mailto:[email protected]]
Sent: Wednesday, March 25, 2009 10:18 AM
To: Loke,Chetan
Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Subject: RE: [patch 3/9] LTTng instrumentation tasklets

Quoted 7 lines · On Wed, 2009-03-25 at 06:52 -0700, [email protected] wrote:

Quick question. I understand this is unrelated to this patch. So I apologize in advance.
Ingo - you mentioned "tasklets are a legacy mechanism". Is there a plan to phase them out ? Let me draw a small picture as to what's bothering me.

With the SR-IOV support if there are 'N' virtual functions

then there

Quoted 3 lines

will be 'N' driver instances(actually N+1, 1 for the PF). If that driver drains the responses in the interrupt context then all such VF-instances could virtually block everyone else(because

SR-IOV guys

Quoted 2 lines

might also have MSI-X enabled).
So now all such drivers should alter their Rx path.Driver's

can queue

Quoted 3 lines

tasklets and can also get the performance they want.

Any suggestions?

Threaded interrupts?

Quoted 32 lines

-----Original Message-----
From: Peter Zijlstra [mailto:[email protected]]
Sent: Wednesday, March 25, 2009 10:18 AM
To: Loke,Chetan
Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Subject: RE: [patch 3/9] LTTng instrumentation tasklets

Quoted 7 lines · On Wed, 2009-03-25 at 06:52 -0700, [email protected] wrote:

Quick question. I understand this is unrelated to this patch. So I apologize in advance.
Ingo - you mentioned "tasklets are a legacy mechanism". Is there a plan to phase them out ? Let me draw a small picture as to what's bothering me.

With the SR-IOV support if there are 'N' virtual functions

then there

Quoted 3 lines

will be 'N' driver instances(actually N+1, 1 for the PF). If that driver drains the responses in the interrupt context then all such VF-instances could virtually block everyone else(because

SR-IOV guys

Quoted 2 lines

might also have MSI-X enabled).
So now all such drivers should alter their Rx path.Driver's

can queue

Quoted 6 lines

Quoted 3 lines

tasklets and can also get the performance they want.

Any suggestions?

Threaded interrupts?

If we truly need to address performance and scalability for the SCSI-subsystem then we need something lightweight.

Compared to Jason's patch, this patch also instruments softirq raise event.

Instrument timer activity (timer set, expired, current time updates) to keep information about the "real time" flow within the kernel. It can be used by a trace analysis tool to synchronize information coming from various sources, e.g. to merge traces with system logs.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

Note : do_setitimer instrumentation could potentially be done with a more generic system call instrumentation.

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/timer.h |   24 ++++++++++++++++++++++++
 kernel/itimer.c       |    8 ++++++++
 kernel/timer.c        |   12 +++++++++++-
 3 files changed, 43 insertions(+), 1 deletion(-)

Index: linux-2.6-lttng/include/trace/timer.h
===================================================================

include/trace/timer.h new file +14 -0

@@ -0,0 +1,24 @@
+#ifndef _TRACE_TIMER_H
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+
+DECLARE_TRACE(timer_itimer_expired,
+	TPPROTO(struct signal_struct *sig),
+		TPARGS(sig));
+DECLARE_TRACE(timer_itimer_set,
+	TPPROTO(int which, struct itimerval *value),
+		TPARGS(which, value));
+DECLARE_TRACE(timer_set,
+	TPPROTO(struct timer_list *timer),
+		TPARGS(timer));

the init methods are missing from your patch entirely - and the rest is partially incomplete as well.

Instrumentation of the del_timer() variants is missing. For a complete lifetime analysis of timers this cannot be left out.

Quoted 3 lines · Ingo Molnar

the init methods are missing from your patch entirely - and the rest is partially incomplete as well.

Quoted 2 lines

Instrumentation of the del_timer() variants is missing. For a complete lifetime analysis of timers this cannot be left out.

Look at the debugobjects hooks. They cover the complete timer life time already.

Piggypacking tracepoints on those would simplify maintenance and reduce the number of extra lines in the code.

Quoted 7 lines · Thomas Gleixner

Quoted 5 lines · Ingo Molnar

the init methods are missing from your patch entirely - and the rest is partially incomplete as well.

Instrumentation of the del_timer() variants is missing. For a complete lifetime analysis of timers this cannot be left out.

Quoted 5 lines

Look at the debugobjects hooks. They cover the complete timer life time already.

Piggypacking tracepoints on those would simplify maintenance and reduce the number of extra lines in the code.

makes sense. They dont cover itimers nor hrtimers though.

Instrument the core kernel : module load/free and printk events. It helps the tracer to keep track of module related events and to export valuable printk information into the traces.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC Frederic Weisbecker <[email protected]>

CC Andrew Morton <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/kernel.h |   19 +++++++++++++++++++
 kernel/module.c        |    8 ++++++++
 kernel/printk.c        |    7 +++++++
 3 files changed, 34 insertions(+)

Index: linux-2.6-lttng/kernel/printk.c
===================================================================

kernel/printk.c +6 -0

@@ -32,6 +32,7 @@
 #include <linux/security.h>
 #include <linux/bootmem.h>
 #include <linux/syscalls.h>
+#include <trace/kernel.h>
 
 #include <asm/uaccess.h>
 

@@ -59,6 +60,7 @@ int console_printk[4] = {
 	MINIMUM_CONSOLE_LOGLEVEL,	/* minimum_console_loglevel */
 	DEFAULT_CONSOLE_LOGLEVEL,	/* default_console_loglevel */
 };
+EXPORT_SYMBOL_GPL(console_printk);
 
 /*
  * Low level drivers may need that to know if they can schedule in

@@ -128,6 +130,9 @@ EXPORT_SYMBOL(console_set_on_cmdline);
 /* Flag: console code may call schedule() */
 static int console_may_schedule;
 
+DEFINE_TRACE(kernel_printk);
+DEFINE_TRACE(kernel_vprintk);
+
 #ifdef CONFIG_PRINTK
 
 static char __log_buf[__LOG_BUF_LEN];

@@ -560,6 +565,7 @@ asmlinkage int printk(const char *fmt, .
 	int r;
 
 	va_start(args, fmt);
+	trace_kernel_printk(_RET_IP_);
 	r = vprintk(fmt, args);
 	va_end(args);
 

Index: linux-2.6-lttng/kernel/module.c
===================================================================

kernel/module.c +1 -0

@@ -51,6 +51,7 @@
 #include <linux/tracepoint.h>
 #include <linux/ftrace.h>
 #include <linux/async.h>
+#include <trace/kernel.h>
 
 #if 0
 #define DEBUGP printk

(Rusty Cc:-ed - for the module.c tracepoints below)

I believe that to have a complete picture of module usage, module refcount get/put events should be included as well, beyond the basic load/free events.

These both have performance impact (a module get/put in a fastpath hurts scalability), and are informative in terms of establishing the module dependency graph.

Quoted 2 lines · On Wednesday 25 March 2009 05:03:13 Ingo Molnar wrote:

(Rusty Cc:-ed - for the module.c tracepoints below)

Thanks, tho they look fine and non-intrusive to me.

Quoted 7 lines

I believe that to have a complete picture of module usage, module refcount get/put events should be included as well, beyond the basic load/free events.

These both have performance impact (a module get/put in a fastpath hurts scalability), and are informative in terms of establishing the module dependency graph.

A module_get()/put() should not hurt scalability at all! I went to great and horrible lengths to ensure that was the case since the rewrite in 2.4.

But a module dependency graph et. al. would be kind of cool.

(Rusty Cc:-ed - for the module.c tracepoints below)

Quoted 71 lines · Mathieu Desnoyers

Instrument the core kernel : module load/free and printk events. It helps the tracer to keep track of module related events and to export valuable printk information into the traces.

Those tracepoints are used by LTTng.

About the performance impact of tracepoints (which is comparable to markers), even without immediate values optimizations, tests done by Hideo Aoki on ia64 show no regression. His test case was using hackbench on a kernel where scheduler instrumentation (about 5 events in code scheduler code) was added. See the "Tracepoints" patch header for performance result detail.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC Frederic Weisbecker <[email protected]>

CC Andrew Morton <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/kernel.h |   19 +++++++++++++++++++
 kernel/module.c        |    8 ++++++++
 kernel/printk.c        |    7 +++++++
 3 files changed, 34 insertions(+)

Index: linux-2.6-lttng/kernel/printk.c
===================================================================

kernel/printk.c +6 -0

@@ -32,6 +32,7 @@
 #include <linux/security.h>
 #include <linux/bootmem.h>
 #include <linux/syscalls.h>
+#include <trace/kernel.h>
 
 #include <asm/uaccess.h>
 

@@ -59,6 +60,7 @@ int console_printk[4] = {
 	MINIMUM_CONSOLE_LOGLEVEL,	/* minimum_console_loglevel */
 	DEFAULT_CONSOLE_LOGLEVEL,	/* default_console_loglevel */
 };
+EXPORT_SYMBOL_GPL(console_printk);
 
 /*
  * Low level drivers may need that to know if they can schedule in

@@ -128,6 +130,9 @@ EXPORT_SYMBOL(console_set_on_cmdline);
 /* Flag: console code may call schedule() */
 static int console_may_schedule;
 
+DEFINE_TRACE(kernel_printk);
+DEFINE_TRACE(kernel_vprintk);
+
 #ifdef CONFIG_PRINTK
 
 static char __log_buf[__LOG_BUF_LEN];

@@ -560,6 +565,7 @@ asmlinkage int printk(const char *fmt, .
 	int r;
 
 	va_start(args, fmt);
+	trace_kernel_printk(_RET_IP_);
 	r = vprintk(fmt, args);
 	va_end(args);
 

@@ -667,6 +673,7 @@ asmlinkage int vprintk(const char *fmt, 
 	printed_len += vscnprintf(printk_buf + printed_len,
 				  sizeof(printk_buf) - printed_len, fmt, args);
 

kernel/printk.c asmlinkage int vprintk(const char *fmt, · line 676

Quoted 1 line

kernel/printk.c +1 -0

+	trace_kernel_vprintk(_RET_IP_, printk_buf, printed_len);

So here we pass in the formatted output. What sense does it make to have the above printk tracepoint? Little i think.

Also, i'm not entirely convinced about the wiseness of instrumenting an essential debug facility like printk(). Lets keep this one at the tail portion of the patch-queue, ok?

Quoted 13 lines

Index: linux-2.6-lttng/kernel/module.c
===================================================================

kernel/module.c +1 -0

@@ -51,6 +51,7 @@
 #include <linux/tracepoint.h>
 #include <linux/ftrace.h>
 #include <linux/async.h>
+#include <trace/kernel.h>
 
 #if 0
 #define DEBUGP printk

kernel/module.c static BLOCKING_NOTIFIER_HEAD(module_not · line 83

Quoted 5 lines

kernel/module.c +2 -0

@@ -78,6 +79,9 @@ static BLOCKING_NOTIFIER_HEAD(module_not
 /* Bounds of module allocation, for speeding __module_text_address */
 static unsigned long module_addr_min = -1UL, module_addr_max = 0;
 
+DEFINE_TRACE(kernel_module_load);
+DEFINE_TRACE(kernel_module_free);

I believe that to have a complete picture of module usage, module refcount get/put events should be included as well, beyond the basic load/free events.

These both have performance impact (a module get/put in a fastpath hurts scalability), and are informative in terms of establishing the module dependency graph.

Another thing that is iteresting and which is not covered here are module request events and usermode helper callouts. These too have instrumentation and performance analysis uses.

Plus, here too it would be desired to put in default probes as well, via TRACE_EVENT().

Thanks,

Ingo