Re: Pin-pointing the root of unusual application latencies

[John Sigler]

Ingo Molnar wrote:

> add 'notrace' to the definition of read_tsc in arch/i386/kernel/tsc.c

OK.

> (or do echo 1 > /proc/sys/kernel/trace_use_raw_cycles
> if you are using recent enough -rt)

Is patch-2.6.20-rt8 recent enough?

# ./trace-it 1 >trace
# cat trace
preemption latency trace v1.1.5 on 2.6.20.7-rt8
--------------------------------------------------------------------
 latency: 1000034 us, #10083/10083, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
    -----------------
    | task: trace-it-939 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
trace-it-939   0D...    0us : user_trace_start (sys_prctl)
trace-it-939   0....    0us : rt_up (user_trace_start)
trace-it-939   0...1    1us : rt_mutex_unlock (rt_up)
trace-it-939   0D...    1us+< (0)
trace-it-939   0....    4us > sys_rt_sigprocmask (00000000 bfadff4c 
000000d8)
trace-it-939   0....    5us : sys_rt_sigprocmask (sysenter_past_esp)
trace-it-939   0....    5us : copy_from_user (sys_rt_sigprocmask)
trace-it-939   0....    5us : __copy_from_user_ll (copy_from_user)
trace-it-939   0....    5us : sigprocmask (sys_rt_sigprocmask)
trace-it-939   0....    5us : __lock_text_start (sigprocmask)
trace-it-939   0....    6us : recalc_sigpending (sigprocmask)
[...]
  <idle>-0     0DN.. 1000027us : __sched_text_start (cpu_idle)
  <idle>-0     0DN.1 1000027us : __sched_text_start (c0100f30 0 0)
  <idle>-0     0DN.1 1000027us : sched_clock (__sched_text_start)
  <idle>-0     0D..2 1000028us : __switch_to (__sched_text_start)
trace-it-939   0D..2 1000028us : __sched_text_start <<idle>-0> (20 -2)
trace-it-939   0D..1 1000029us : trace_stop_sched_switched 
(__sched_text_start)
trace-it-939   0.... 1000029us : hrtimer_cancel (do_nanosleep)
trace-it-939   0.... 1000030us : hrtimer_try_to_cancel (hrtimer_cancel)
trace-it-939   0D... 1000031us < (0)
trace-it-939   0.... 1000032us > sys_prctl (00000000 00000000 000000d8)
trace-it-939   0.... 1000032us : sys_prctl (sysenter_past_esp)
trace-it-939   0.... 1000032us : user_trace_stop (sys_prctl)
trace-it-939   0D... 1000033us : user_trace_stop (sys_prctl)

This looks better.

I will let my test program run overnight.

Regards.
-
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/