From: John Sigler <linux.kernel@free.fr>
To: Ingo Molnar <mingo@elte.hu>
Cc: linux-rt-users@vger.kernel.org,
oprofile-list@lists.sourceforge.net,
linux-kernel@vger.kernel.org
Subject: Re: Pin-pointing the root of unusual application latencies
Date: Mon, 23 Jul 2007 16:14:26 +0200 [thread overview]
Message-ID: <46A4B7C2.1070304@free.fr> (raw)
In-Reply-To: <20070723095357.GA886@elte.hu>
Ingo Molnar wrote:
> John Sigler wrote:
>
>> Here's a /proc/latency_trace dump. What is there to understand?
>>
>> # cat /proc/latency_trace
>> preemption latency trace v1.1.5 on 2.6.20.7-rt8
>> --------------------------------------------------------------------
>> latency: 26 us, #2/2, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
>> -----------------
>> | task: softirq-timer/0-4 (uid:0 nice:0 policy:1 rt_prio:50)
>> -----------------
>>
>> _------=> CPU#
>> / _-----=> irqs-off
>> | / _----=> need-resched
>> || / _---=> hardirq/softirq
>> ||| / _--=> preempt-depth
>> |||| /
>> ||||| delay
>> cmd pid ||||| time | caller
>> \ / ||||| \ | /
>> <...>-4 0D..1 26us : trace_stop_sched_switched
>> (__sched_text_start)
>
> could you try:
>
> http://redhat.com/~mingo/latency-tracing-patches/trace-it.c
>
> and run it like this:
>
> ./trace-it 1 > trace.txt
>
> does it produce lots of trace entries? If not then
> CONFIG_FUNCTION_TRACING is not enabled. Once you see lots of output in
> the file, the tracer is up and running and you can start tracing the
> latency in your app.
# ./trace-it 1 >/tmp/trace.txt
# wc /tmp/trace.txt
65555 393277 4096317 /tmp/trace.txt
preemption latency trace v1.1.5 on 2.6.20.7-rt8
--------------------------------------------------------------------
latency: 1020019 us, #65536/76272, 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
\ / ||||| \ | /
<...>-939 0D... 0us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 1us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 1us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 1us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 3us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 3us : read_tsc (get_monotonic_cycles)
[SNIP]
<...>-939 0D... 19763us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19763us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19763us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19764us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19764us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19764us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19765us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19765us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19765us : read_tsc (get_monotonic_cycles)
<...>-939 0D... 19765us : read_tsc (get_monotonic_cycles)
vim:ft=help
(I snipped ~65500 lines where only the number of "us" changes.)
Shouldn't there be other functions in the output?
Am I reading correctly that some read_tsc calls take 20 ms?
dmesg reports:
( trace-it-939 |#0): new 1020019 us user-latency.
> To track it down, use the method that trace-it.c uses to start/stop
> tracing, i.e. put the prctl(0,1); / prctl(0,0); calls into your app to
> start/stop tracing and the kernel will do the rest once you've set
> /proc/sys/kernel/preempt_max_latency back to 0: /proc/latency_trace will
> always contain the longest latency that your app triggered, of the
> critical path you programmed into it.
Here's what I came up with:
http://linux.kernel.free.fr/latency/check_dektec_input3.cxx
(I enable tracing only 1% of the time.)
The output looks very much like the one I got when I ran trace-it
preemption latency trace v1.1.5 on 2.6.20.7-rt8
--------------------------------------------------------------------
latency: 19996 us, #65536/65815, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
-----------------
| task: check_dektec_in-1151 (uid:0 nice:0 policy:2 rt_prio:80)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
<...>-1151 0D... 0us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 1us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 1us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 1us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 2us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 3us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 3us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 3us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 4us : read_tsc (get_monotonic_cycles)
[...]
<...>-1151 0D... 19764us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19764us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19765us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19765us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19765us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19766us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19766us : read_tsc (get_monotonic_cycles)
<...>-1151 0D... 19766us : read_tsc (get_monotonic_cycles)
Remarks:
1. Again, shouldn't there be other functions in the output?
2. How much overhead do the prctl calls incur? Is it possible that they
are somehow masking my problem? (I'll let the program run all night to
maximize the chances of capturing the anomalous latency.)
> also check the cyclictest source of how to do app-driven latency
> tracing.
Are you talking about this code:
http://git.kernel.org/?p=linux/kernel/git/tglx/rt-tests.git;a=blob_plain;f=cyclictest/cyclictest.c;hb=HEAD
I will study it.
Regards.
next prev parent reply other threads:[~2007-07-23 14:14 UTC|newest]
Thread overview: 19+ messages / expand[flat|nested] mbox.gz Atom feed top
[not found] <469600F7.3060603@free.fr>
2007-07-23 9:53 ` Pin-pointing the root of unusual application latencies Ingo Molnar
2007-07-23 14:14 ` John Sigler [this message]
2007-07-23 16:04 ` Ingo Molnar
2007-07-23 16:44 ` John Sigler
2007-07-24 8:31 ` John Sigler
2007-07-24 9:20 ` John Sigler
2007-07-25 13:04 ` John Sigler
2007-07-25 13:05 ` Ingo Molnar
2007-07-25 13:20 ` John Sigler
2007-07-25 13:38 ` Ingo Molnar
2007-07-25 14:05 ` John Sigler
2007-07-25 15:28 ` Karsten Wiese
2007-07-25 15:46 ` John Sigler
2007-07-25 16:31 ` Karsten Wiese
2007-07-25 17:09 ` Len Brown
2007-07-26 8:35 ` John Sigler
2007-07-26 10:45 ` John Sigler
2007-07-26 12:02 ` John Sigler
2007-07-26 15:16 ` John Sigler
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=46A4B7C2.1070304@free.fr \
--to=linux.kernel@free.fr \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-rt-users@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=oprofile-list@lists.sourceforge.net \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox