Messages in this thread | | | Date | Mon, 22 Sep 2014 08:18:14 -0400 | From | Steven Rostedt <> | Subject | Re: itrace: An interrupts tracing tool |
| |
On Mon, 22 Sep 2014 11:35:43 +0800 duzhiping <duzhiping.du@huawei.com> 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
| |