Profiling a program's runtime

Profiling a program's runtime

[Christoph Bartoschek]

Hi,

I would like to get a callgraph for the whole time a program runs. Is this 
possible with perf?

Most profilers I know only show me where the cputime is spent. But I would 
like to know how the wall time is used and in which functions. It's hard for 
me to explain what I mean, therefore I try it with an example.

I have a program that consists basically of three functions:

func_calc() is a computationally intensive function.
func_netw() is a function that reads requests from the network.
func_disk() is a function that writes data to the filesystem.

One execution of the program might last 10 seconds. 5 seconds of the time 
the programms waits for network requests in a call to read(). 3 seconds are 
spent for calculations in func_calc() and 2 seconds pass while the programm 
blocks on the write() requests in func_disk().

Overall the profiler should tell me that 50% of runtime are used by 
func_netw(), 30% are used by func_calc() and 20% are used by func_disk().

Most of the time I want to ignore the time the program spents to wait for 
the scheduler.

How can such a profile be generated with perf?

Christoph

Re: Profiling a program's runtime

[Frederic Weisbecker]

On Fri, Feb 04, 2011 at 03:38:53PM +0100, Christoph Bartoschek wrote:
> Hi,
> 
> I would like to get a callgraph for the whole time a program runs. Is this 
> possible with perf?
> 
> Most profilers I know only show me where the cputime is spent. But I would 
> like to know how the wall time is used and in which functions. It's hard for 
> me to explain what I mean, therefore I try it with an example.
> 
> I have a program that consists basically of three functions:
> 
> func_calc() is a computationally intensive function.
> func_netw() is a function that reads requests from the network.
> func_disk() is a function that writes data to the filesystem.
> 
> One execution of the program might last 10 seconds. 5 seconds of the time 
> the programms waits for network requests in a call to read(). 3 seconds are 
> spent for calculations in func_calc() and 2 seconds pass while the programm 
> blocks on the write() requests in func_disk().
> 
> Overall the profiler should tell me that 50% of runtime are used by 
> func_netw(), 30% are used by func_calc() and 20% are used by func_disk().
> 
> Most of the time I want to ignore the time the program spents to wait for 
> the scheduler.
> 
> How can such a profile be generated with perf?

If I understood you well, you make a difference between:

- profiling only the code executed by your task
- profiling any code executed while your task was existing,
which includes what happens on other CPUs and other tasks that
may share the same CPU? Everything in fact?

So for the case, you just launch:

	perf record -g my_task

For the second case, use -a for system wide profiling while
your task exists:

	./perf record -a -g my_task

Hope that helps.

Re: Profiling a program's runtime

[Christoph Bartoschek]

Frederic Weisbecker wrote:

> 
> If I understood you well, you make a difference between:
> 
> - profiling only the code executed by your task
> - profiling any code executed while your task was existing,
> which includes what happens on other CPUs and other tasks that
> may share the same CPU? Everything in fact?
> 
> So for the case, you just launch:
> 
> perf record -g my_task
> 
> For the second case, use -a for system wide profiling while
> your task exists:
> 
> ./perf record -a -g my_task

I am not interessted in code that is executed in other processes while my 
task exists. 

I want that not only the CPU time is counted that my task uses, but also the 
time my task waits.

For example, if my task waits for network packets in a read() then the time  
should be added to the read() function. Other profilers I know would not 
count the time when the process is blocked.

Christoph

Re: Profiling a program's runtime

[Frederic Weisbecker]

On Fri, Feb 04, 2011 at 06:41:57PM +0100, Christoph Bartoschek wrote:
> Frederic Weisbecker wrote:
> 
> > 
> > If I understood you well, you make a difference between:
> > 
> > - profiling only the code executed by your task
> > - profiling any code executed while your task was existing,
> > which includes what happens on other CPUs and other tasks that
> > may share the same CPU? Everything in fact?
> > 
> > So for the case, you just launch:
> > 
> > perf record -g my_task
> > 
> > For the second case, use -a for system wide profiling while
> > your task exists:
> > 
> > ./perf record -a -g my_task
> 
> I am not interessted in code that is executed in other processes while my 
> task exists. 
> 
> I want that not only the CPU time is counted that my task uses, but also the 
> time my task waits.

The time your task waits, other tasks executes :-/  (including idle in the scheme)
 
> For example, if my task waits for network packets in a read() then the time  
> should be added to the read() function. Other profilers I know would not 
> count the time when the process is blocked.

What do you mean by adding time to read?

I'm very confused with what you want.

Re: Profiling a program's runtime

[David Ahern]

On 02/04/11 10:47, Frederic Weisbecker wrote:

>> I want that not only the CPU time is counted that my task uses, but also the 
>> time my task waits.
> 
> The time your task waits, other tasks executes :-/  (including idle in the scheme)
>  
>> For example, if my task waits for network packets in a read() then the time  
>> should be added to the read() function. Other profilers I know would not 
>> count the time when the process is blocked.

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.

David

RE: Profiling a program's runtime

[Maucci, Cyrille]

I'd think that what he's looking for is a bit what caliper cstack would provide.


So something like showing 'running' (consuming CPU) and 'blocked' (I/O, passive wait, etc...)...


Function Summary 
-------------------------------------------------------------------------------------------------------
% Total  Cumulat                          Sample         Sample                                    
   IP      % of              IP            Hits           Hits                                     
Samples    Total          Samples        Running        Blocked  Function                          File
-------------------------------------------------------------------------------------------------------
  42.11    42.11             1456           1456              0  libc.so.1::__lseek_sys            
  38.09    80.19             1317            592            725  libc.so.1::_read_sys              
   9.43    89.62              326            326              0  libc.so.1::memset                 
   1.59    91.21               55             55              0  libc.so.1::_write_sys             
Etc...

On the flat summary side


And something presented like this in the call graph part


Call Graph
--------------------------------------------------------------------
       --% Total Hits In / Under--    % Func Hits    
       Run +     Run       Block        Under Parent     Parents
Index  Block     Hits      Hits       In Func        Name     Index
       Hits      Only      Only         In Children      Children
--------------------------------------------------------------------
[1]    100.0      78.0      22.0        0.00         *ROOT* [1]
                                           79.47         dld.so::main_opd_entry [5]
                                           20.04         *unknown_0x600000000e0a7608* [52]
                                            0.20         DDENV::main [4]
                                            0.09         DDENV::Bffo_BILLproc [25]
                                            0.06         DDENV::bffe_Root [46]
                                            0.03         *unknown_0x6000000008f9c6e8* [364]
                                            0.03         DDENV::bfen_EXECproc [2]
                                            0.03         DDENV::F1_RootObject [63]
                                            0.03         *unknown_0x134* [451]
                                            0.03         *unknown_0xc0000000000087a0* [456]
--------------------------------------------------------------------
                                           99.97         DDENV::main [4]
                                            0.03         *ROOT* [1]
[2]     99.8      77.8      22.0        0.00         DDENV::bfen_EXECproc [2]
                                          100.00         DDENV::bfen_INPUTproc [3]

Etc...




Sorry, I'm new to this list and have never used perf before but am planning to do so verysoon.
Did anyone answer his initial question "I would like to get a callgraph for the whole time a program runs. Is this possible with perf?"?


Thanks
++Cyrille


-----Original Message-----
From: linux-perf-users-owner@vger.kernel.org [mailto:linux-perf-users-owner@vger.kernel.org] On Behalf Of David Ahern
Sent: Friday, February 04, 2011 7:10 PM
To: Frederic Weisbecker; Christoph Bartoschek
Cc: linux-perf-users@vger.kernel.org; Arnaldo Carvalho de Melo
Subject: Re: Profiling a program's runtime



On 02/04/11 10:47, Frederic Weisbecker wrote:

>> I want that not only the CPU time is counted that my task uses, but 
>> also the time my task waits.
> 
> The time your task waits, other tasks executes :-/  (including idle in 
> the scheme)
>  
>> For example, if my task waits for network packets in a read() then 
>> the time should be added to the read() function. Other profilers I 
>> know would not count the time when the process is blocked.

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.

David
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in the body of a message to majordomo@vger.kernel.org More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Profiling a program's runtime

[Christoph Bartoschek]

Frederic Weisbecker wrote:

>> For example, if my task waits for network packets in a read() then the
>> time should be added to the read() function. Other profilers I know would
>> not count the time when the process is blocked.
> 
> What do you mean by adding time to read?
> 
> I'm very confused with what you want.

Take for example the following program:

#include <unistd.h>

int compute(int start) {
   for (int i = 0; i < 10000000; ++i) {
      start += i;
   }
   return start;
}

int main(int argc, char **) {
   int ret = 0;
   for (int i = 0; i != 5; ++i) {
      sleep(argc == 1 ? 0 : 1);
      ret += compute(argc);
   }
   return ret;
}

Here is what I get by default:

ponto@homer:~/software/perf> g++ small.C -Wall -W -pedantic
ponto@homer:~/software/perf> time ./a.out 

real    0m0.113s
user    0m0.111s
sys     0m0.001s
ponto@homer:~/software/perf> time perf record -f ./a.out 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.016 MB perf.data (~691 samples) ]

real    0m5.147s
user    0m0.012s
sys     0m0.008s
ponto@homer:~/software/perf> perf report | cat
[kernel.kallsyms] with build id 361b85a57658c9ebfa686878cc821250aaff28e2 not 
found, continuing without symbols
# Samples: 335743554
#
# Overhead  Command      Shared Object  Symbol
# ........  .......  .................  ......
#
    98.20%    a.out  a.out              [.] compute(int)
     1.51%    a.out  [kernel.kallsyms]  [k] page_remove_rmap
     0.25%    a.out  [kernel.kallsyms]  [k] page_fault
     0.03%    a.out  [kernel.kallsyms]  [k] _raw_spin_lock_irq
     0.00%    a.out  [kernel.kallsyms]  [k] intel_pmu_enable_all
     0.00%    a.out  [kernel.kallsyms]  [k] 0xffffffff810123cc

The report is clearly wrong. The program was only 2% in the compute function 
and 98% in the sleep() function.

Christoph

Re: Profiling a program's runtime

[Christoph Bartoschek]

Am Freitag 04 Februar 2011 schrieb Maucci, Cyrille:
> I'd think that what he's looking for is a bit what caliper cstack would
> provide.

This looks interessting. However caliper seems to only be available for 
Itanium based systems. We only have x86_64 systems.

Christoph

Re: Profiling a program's runtime

[Christoph Bartoschek]

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.

Thanks
Christoph

RE: Profiling a program's runtime

[Maucci, Cyrille]

Hi Christoph,

Yep. I was not promoting caliper here.
I was just referring to it so that we may get an idea of what he'd like to see in 'perf' reports.

++Cyrille 

-----Original Message-----
From: Christoph Bartoschek [mailto:bartoschek@gmx.de] 
Sent: Friday, February 04, 2011 8:48 PM
To: Maucci, Cyrille
Cc: linux-perf-users@vger.kernel.org
Subject: Re: Profiling a program's runtime

Am Freitag 04 Februar 2011 schrieb Maucci, Cyrille:
> I'd think that what he's looking for is a bit what caliper cstack 
> would provide.

This looks interessting. However caliper seems to only be available for Itanium based systems. We only have x86_64 systems.

Christoph

Re: Profiling a program's runtime

[David Ahern]

[-- 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.

Re: Profiling a program's runtime

[Arnaldo Carvalho de Melo]

Em Fri, Feb 04, 2011 at 07:57:00PM +0000, Maucci, Cyrille escreveu:
> Yep. I was not promoting caliper here.
> I was just referring to it so that we may get an idea of what he'd like to see in 'perf' reports.

Right, useful pointers, thanks, barring patents, I think we can get that
with perf at some point.

Catering to I/O bound workloads is something that is in the radar, has
been experimented with and should resume development soon, please take a
look at the 'trace' description at:

http://lwn.net/Articles/415728/

The discussion also has lots of useful suggestions and insights.

It is an area that badly needs help to get the perf infrastructure to
the next level, beyong the current state of good (excellent?) CPU bound
profiling.

- Arnaldo