Re: [PATCH] tracing/function-graph-tracer: adjustments of the trace informations

[Frédéric Weisbecker]

2008/11/28 Ingo Molnar <mingo@xxxxxxx>:
>
> another detail: it would be nice to annotate IRQ entries some more.
>
> right now if a syscall is interrupted by a hardware interrupt, it looks
> like this:
>
>  0)               |              skb_dequeue() {
>  0)      0.365 us |                _spin_lock_irqsave();
>  0)      0.422 us |                _spin_unlock_irqrestore();
>  0)      1.912 us |              }
>  0)               |              memcpy_toiovec() {
>  0)               |                copy_to_user() {
>  0)               |                  smp_apic_timer_interrupt() {
>  0)      0.450 us |                    native_apic_mem_write();
>  0)               |                    irq_enter() {
>  0)      0.410 us |                      idle_cpu();
>  0)      1.167 us |                    }
>  0)               |                    hrtimer_interrupt() {
>
> the natural nesting is nice, but easy to miss. It would be nice to have
> something like:
>
>  0)               |              skb_dequeue() {
>  0)      0.365 us |                _spin_lock_irqsave();
>  0)      0.422 us |                _spin_unlock_irqrestore();
>  0)      1.912 us |              }
>  0)               |              memcpy_toiovec() {
>  0)               |                copy_to_user() {
>  0)             =====>               smp_apic_timer_interrupt() {
>  0)      0.450 us |                    native_apic_mem_write();
>  0)               |                    irq_enter() {
>  0)      0.410 us |                      idle_cpu();
>  0)      1.167 us |                    }
>  0)               |                    hrtimer_interrupt() {
>
> and perhaps something like this at the end of the irq frame:
>
>  0)      0.408 us |                          _local_bh_enable();
>  0) +   13.139 us |                        }
>  0) +   13.887 us |                      }
>  0)      0.406 us |                      idle_cpu();
>  0) +   15.373 us |                    }
>  0) +   74.564 us |                  }
>  0)               |                  _cond_resched() {
>  0)               |                    need_resched() {
>  0)      0.423 us |                      constant_test_bit();
>  0)      1.164 us |                    }
>  0)      1.915 us <===               } /* IRQ 1 end */
>  0) +   78.396 us |                }
>  0) +   79.123 us |              }
>  0)      0.387 us |              skb_pull();
>  0)               |              kfree_skb() {
>
> ?


I tried to figure out a way to signal a hardirq in a trace, I like
this arrow but It
breaks the indentation.
I would suggest:

  0)               |              skb_dequeue() {
  0)      0.365 us |                _spin_lock_irqsave();
  0)      0.422 us |                _spin_unlock_irqrestore();
  0)      1.912 us |              }
  0)               |              memcpy_toiovec() {
  0)               |                copy_to_user() {
             =====>
  0)               |               smp_apic_timer_interrupt() {
  0)      0.450 us |                    native_apic_mem_write();
  0)               |                    irq_enter() {
  0)      0.410 us |                      idle_cpu();
  0)      1.167 us |                    }
  0)               |                    hrtimer_interrupt() {

Your idea solves a part of one of the features I wanted to add: why
not using a single character column to print
the current context: workqueue, syscall, kernel thread, tasklet, hardirq .....
--
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/