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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).