linux-kernel - Re: Pin-pointing the root of unusual application latencies

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <46A4DAE5.4010302@free.fr>
Date:	Mon, 23 Jul 2007 18:44:21 +0200
From:	John Sigler <linux.kernel@...e.fr>
To:	Ingo Molnar <mingo@...e.hu>
CC:	linux-rt-users@...r.kernel.org,
	oprofile-list@...ts.sourceforge.net, linux-kernel@...r.kernel.org
Subject: Re: Pin-pointing the root of unusual application latencies

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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/