Re: itrace: An interrupts tracing tool

From: Steven Rostedt
Date: Mon Sep 22 2014 - 08:18:21 EST

On Mon, 22 Sep 2014 11:35:43 +0800
duzhiping <duzhiping.du@xxxxxxxxxx> wrote:

> Many functions depends on interrupts in Linux system, when the interrupts occur an error, it may cause fatal problem.
>
> Then, we should record their trace when interrupts in and out. The recorded information could help us analyze interrupts errors.
>
> Itrace is such an interrupts trace tool we have developed, it provides config interface and trace information through "procfs".
>
> Do you think it has the value to upstream?
>

You mean like:

# trace-cmd record -p function_graph -l do_IRQ -e irq_handler_entry sleep 10
# trace-cmd report
trace-cmd-3165 [002] 53.201912: funcgraph_entry: | do_IRQ() {
trace-cmd-3165 [002] 53.201920: irq_handler_entry: irq=21 name=uhci_hcd:usb4
trace-cmd-3165 [002] 53.201924: irq_handler_entry: irq=21 name=eth0
trace-cmd-3165 [002] 53.201927: funcgraph_exit: + 12.738 us | }
<idle>-0 [003] 53.202140: funcgraph_entry: | do_IRQ() {
<idle>-0 [003] 53.202146: irq_handler_entry: irq=21 name=uhci_hcd:usb4
<idle>-0 [003] 53.202148: irq_handler_entry: irq=21 name=eth0
<idle>-0 [003] 53.202151: funcgraph_exit: + 10.172 us | }
<idle>-0 [000] 58.679619: funcgraph_entry: | do_IRQ() {
<idle>-0 [000] 58.679625: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [000] 58.679630: funcgraph_exit: 8.040 us | }
<idle>-0 [001] 58.680176: funcgraph_entry: | do_IRQ() {
<idle>-0 [001] 58.680178: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [001] 58.680181: funcgraph_exit: 4.160 us | }
<idle>-0 [002] 58.680633: funcgraph_entry: | do_IRQ() {
<idle>-0 [002] 58.680635: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [002] 58.680637: funcgraph_exit: 3.489 us | }
<idle>-0 [003] 58.680913: funcgraph_entry: | do_IRQ() {
<idle>-0 [003] 58.680915: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [003] 58.680917: funcgraph_exit: 3.368 us | }
kworker/u8:1-40 [000] 58.681191: funcgraph_entry: | do_IRQ() {
kworker/u8:1-40 [000] 58.681192: irq_handler_entry: irq=14 name=ata_piix
kworker/u8:1-40 [000] 58.681196: funcgraph_exit: 4.551 us | }
<idle>-0 [001] 58.681415: funcgraph_entry: | do_IRQ() {
<idle>-0 [001] 58.681417: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [001] 58.681420: funcgraph_exit: 3.991 us | }
<idle>-0 [002] 58.681632: funcgraph_entry: | do_IRQ() {
<idle>-0 [002] 58.681633: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [002] 58.681635: funcgraph_exit: 2.183 us | }


Or just use the irq events only?

# trace-cmd record -e irq_handler_entry -e irq_handler_exit sleep 10
# trace-cmd report
<idle>-0 [003] 198.853342: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [003] 198.853344: irq_handler_exit: irq=14 ret=handled
<idle>-0 [000] 198.862038: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [000] 198.862040: irq_handler_exit: irq=14 ret=handled
<idle>-0 [001] 198.862227: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [001] 198.862228: irq_handler_exit: irq=14 ret=handled
<idle>-0 [002] 198.870423: irq_handler_entry: irq=14 name=ata_piix
<idle>-0 [002] 198.870424: irq_handler_exit: irq=14 ret=handled


It's a bit cleaner, but the function_graph gives the times nicely. But
I do plan on updating trace-cmd to give times between different events.

-- Steve
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/