From: David Ahern <daahern@cisco.com>
To: Christoph Bartoschek <bartoschek@gmx.de>
Cc: linux-perf-users@vger.kernel.org
Subject: Re: Profiling a program's runtime
Date: Fri, 04 Feb 2011 17:56:20 -0700 [thread overview]
Message-ID: <4D4CA034.2010204@cisco.com> (raw)
In-Reply-To: <201102042051.21617.bartoschek@gmx.de>
[-- Attachment #1: Type: text/plain, Size: 1608 bytes --]
On 02/04/11 12:51, Christoph Bartoschek wrote:
> Am Freitag 04 Februar 2011 schrieb David Ahern:
>
>> You can determine time blocked on read (and other system calls) by
>> acquiring all context switches:
>>
>> perf record -e cs -c 1 -a
>>
>> From there you'll want to generate a time history output. To use
>> unmodified perf code use the -D option to dump raw samples (perf report
>> -D). You can find the process of interest and the kernel timestamp
>> between schedule out events -- and the sched out event before your
>> process. Together you can piece together the time you blocked on read.
>>
>> Alternatively, there are add-on patches which dump the timehistory in a
>> pretty print format:
>>
>> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00049.html
>> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00047.html
>> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00048.html
>>
>>
>> That output can be manipulated much easier to determine time on the
>> processor and time between schedule-in events.
>>
>> Not the complete picture of what I think you are looking for -- but a
>> way to get the time blocked on syscall stats via perf.
>
> Looks quite complicated to get such a profile. However I have to check it,
> when I'm back at work.
Can be - depends on the insights you seek. It's been invaluable data for
the product I work on. Attached is a couple of snippets from a local
timehist-analysis tool (workflow is 'perf record', dump timehistory, run
timehist-analysis to time sort the samples, etc).
David
>
> Thanks
> Christoph
[-- Attachment #2: example-timehist-analysis --]
[-- Type: text/plain, Size: 2998 bytes --]
System view of processes:
: ------------------ | ------------------ :
: cpu 0 | cpu 1 :
---------------: ------------------ | ------------------ :
Time of Day : process[pid] run | process[pid] run : Stack Trace
----------------------------------------------------------------------------
10:24:17.875423: myproc3[3888] 214 | : schedule_timeout
...
10:24:17.883073: | yz[5552] 48 : work_resched ...
10:24:17.883084: | yz[5562] 11 : futex_wait ...
10:24:17.883103: | yz[5552] 18 : work_resched ...
10:24:17.883113: | yz[5560] 9 : futex_wait ...
10:24:17.883151: | yz[5552] 38 : work_resched ...
10:24:17.883175: | yz[5562] 23 : futex_wait ...
10:24:17.883196: | yz[5560] 21 : futex_wait ...
10:24:17.883211: | yz[5552] 14 : schedule_timeout ...
10:24:17.889569: swapper[0] 14145 | : cpu_idle ...
10:24:17.889692: myproc1[3853] 123 | : schedule_timeout ...
10:24:17.889781: myproc2[5577] 88 | : schedule_timeout ...
10:24:17.889835: abc[4245] 54 | : schedule_timeout ...
...
In-depth view of a single process:
: cpu 0 | cpu 1 :
: ---------------------------- | --------------------------- :
: run betwn | run betwn :
Time of Day : process[tid] time time | process[tid] time time :
-----------------------------------------------------------------------------------------------
...
10:24:17.890170: myproc[3888] 334 14412 | : __skb_recv_datagram ...
10:24:17.898361: | myproc[3888] 94 8097 : work_resched ...
10:24:17.898806: | myproc[3888] 56 388 : __skb_recv_datagram ...
10:24:17.905296: myproc[3888] 111 6379 | : __skb_recv_datagram ...
10:24:17.915303: myproc[3888] 139 9868 | : __skb_recv_datagram ...
10:24:17.916041: myproc[3888] 14 724 | : __skb_recv_datagram ...
10:24:17.919939: myproc[3888] 16 3881 | : __skb_recv_datagram ...
10:24:17.920047: myproc[3888] 15 93 | : __skb_recv_datagram ...
...
run time is how long the thread ran once scheduled
betwn time is how long the thread went between schedulings
Stack depths snipped to one-level for this example (with schedule_timeout excluded); perf captures the complete stack and you can drop symbols to bring clarity to where a process blocks, for how long, etc.
next prev parent reply other threads:[~2011-02-05 1:05 UTC|newest]
Thread overview: 12+ messages / expand[flat|nested] mbox.gz Atom feed top
2011-02-04 14:38 Profiling a program's runtime Christoph Bartoschek
2011-02-04 17:16 ` Frederic Weisbecker
2011-02-04 17:41 ` Christoph Bartoschek
2011-02-04 17:47 ` Frederic Weisbecker
2011-02-04 18:10 ` David Ahern
2011-02-04 18:33 ` Maucci, Cyrille
2011-02-04 19:48 ` Christoph Bartoschek
2011-02-04 19:57 ` Maucci, Cyrille
2011-02-07 20:38 ` Arnaldo Carvalho de Melo
2011-02-04 19:51 ` Christoph Bartoschek
2011-02-05 0:56 ` David Ahern [this message]
2011-02-04 19:24 ` Christoph Bartoschek
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=4D4CA034.2010204@cisco.com \
--to=daahern@cisco.com \
--cc=bartoschek@gmx.de \
--cc=linux-perf-users@vger.kernel.org \
/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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.