[libmill] Re: Profiling limbill

  • From: Martin Sustrik <sustrik@xxxxxxxxxx>
  • To: libmill@xxxxxxxxxxxxx
  • Date: Fri, 31 Jul 2015 21:36:32 +0200

I suppose the profilers get confused by the seemingly trashed stack. I am not sure we can do anything about that.

Martin

On 2015-07-31 21:18, Nir Soffer wrote:

Hi all,

I tried to profile tutorial/step6 using gprof, but it seems that I get
partial output.

I tried also google profiler (
http://gperftools.googlecode.com/git/doc/cpuprofile.html)
but I get an empty profile :-)

I tried this:

./configure --enable-debug --disable-shared CFLAGS=-pg LDFLAGS=-pg
make clean
make
tutorial/step6

In another shell I run a script simulating 1000 concurrent clients 20 times.

(This used to abort when poll() is interrupted, fixed in
https://github.com/sustrik/libmill/commit/a8972e3c354db6a9a4c62081855125290cad53fe
)

I get gmon.out file, but when I view it I get this output:

$ gprof -b tutorial/step6 gmon.out
Flat profile:

Each sample counts as 0.01 seconds.
no time accumulated

% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
0.00 0.00 0.00 17 0.00 0.00 mill_fdwait
0.00 0.00 0.00 16 0.00 0.00 iplocal
0.00 0.00 0.00 11 0.00 0.00 mill_trace_
0.00 0.00 0.00 9 0.00 0.00 main
0.00 0.00 0.00 8 0.00 0.00 mill_choose_wait
0.00 0.00 0.00 6 0.00 0.00 mill_ipany
0.00 0.00 0.00 5 0.00 0.00 gotrace
0.00 0.00 0.00 4 0.00 0.00 mill_chclose
0.00 0.00 0.00 3 0.00 0.00 mill_choose_val
0.00 0.00 0.00 3 0.00 0.00 mill_chs
0.00 0.00 0.00 3 0.00 0.00 mill_ipport
0.00 0.00 0.00 3 0.00 0.00 mill_register_cr
0.00 0.00 0.00 2 0.00 0.00 mill_ipliteral
0.00 0.00 0.00 1 0.00 0.00 _init
0.00 0.00 0.00 1 0.00 0.00 mill_chmake
0.00 0.00 0.00 1 0.00 0.00 mill_getchan
0.00 0.00 0.00 1 0.00 0.00 mill_ipv4_literal
0.00 0.00 0.00 1 0.00 0.00 mill_ipv6_literal


Call graph


granularity: each sample hit covers 2 byte(s) no time propagated

index % time self children called name
[1] 0.0 0.00 0.00 8+2 <cycle 1 as a whole> [1]
0.00 0.00 9 main <cycle 1> [5]
0.00 0.00 1 mill_chmake <cycle 1> [15]
-----------------------------------------------
0.00 0.00 1/17 statistics [72]
0.00 0.00 1/17 mill_chmake <cycle 1> [15]
0.00 0.00 2/17 _init [83]
0.00 0.00 2/17 mill_unregister_cr [62]
0.00 0.00 2/17 goredump [26]
0.00 0.00 3/17 dialogue [23]
0.00 0.00 6/17 main <cycle 1> [5]
[2] 0.0 0.00 0.00 17 mill_fdwait [2]
0.00 0.00 10/16 iplocal [3]
0.00 0.00 2/3 mill_chs [11]
-----------------------------------------------
0.00 0.00 1/16 statistics [72]
0.00 0.00 1/16 dialogue [23]
0.00 0.00 2/16 _init [83]
0.00 0.00 2/16 main <cycle 1> [5]
0.00 0.00 10/16 mill_fdwait [2]
[3] 0.0 0.00 0.00 16 iplocal [3]
-----------------------------------------------
0.00 0.00 1/11 mill_chmake <cycle 1> [15]
0.00 0.00 1/11 mill_ipv4_literal [17]
0.00 0.00 1/11 mill_ipv6_literal [18]
0.00 0.00 1/11 mill_ipliteral [14]
0.00 0.00 2/11 mill_ipport [12]
0.00 0.00 5/11 main <cycle 1> [5]
[4] 0.0 0.00 0.00 11 mill_trace_ [4]
0.00 0.00 1/5 gotrace [8]
-----------------------------------------------
1 mill_chmake <cycle 1> [15]
0.00 0.00 1/8 __gmon_start__ [87]
0.00 0.00 1/8 mill_getchan [16]
0.00 0.00 3/8 mill_resume [53]
0.00 0.00 3/8 goredump [26]
[5] 0.0 0.00 0.00 9 main <cycle 1> [5]
0.00 0.00 6/17 mill_fdwait [2]
0.00 0.00 5/11 mill_trace_ [4]
0.00 0.00 4/5 gotrace [8]
0.00 0.00 3/3 mill_register_cr [13]
0.00 0.00 2/16 iplocal [3]
0.00 0.00 1/2 mill_ipliteral [14]
0.00 0.00 1/3 mill_ipport [12]
0.00 0.00 1/8 mill_choose_wait [6]
1 mill_chmake <cycle 1> [15]
-----------------------------------------------
0.00 0.00 1/8 _init [83]
0.00 0.00 1/8 main <cycle 1> [5]
0.00 0.00 1/8 mill_chdup [30]
0.00 0.00 1/8 mill_chclose [9]
0.00 0.00 2/8 mill_chr [37]
0.00 0.00 2/8 goredump [26]
[6] 0.0 0.00 0.00 8 mill_choose_wait [6]
-----------------------------------------------
0.00 0.00 1/6 mill_ipv4_literal [17]
0.00 0.00 1/6 mill_ipv6_literal [18]
0.00 0.00 2/6 mill_ipliteral [14]
0.00 0.00 2/6 mill_ipport [12]
[7] 0.0 0.00 0.00 6 mill_ipany [7]
-----------------------------------------------
0.00 0.00 1/5 mill_trace_ [4]
0.00 0.00 4/5 main <cycle 1> [5]
[8] 0.0 0.00 0.00 5 gotrace [8]
-----------------------------------------------
0.00 0.00 1/4 mill_chmake <cycle 1> [15]
0.00 0.00 3/4 mill_resume [53]
[9] 0.0 0.00 0.00 4 mill_chclose [9]
0.00 0.00 1/8 mill_choose_wait [6]
-----------------------------------------------
0.00 0.00 1/3 mill_go_prologue [43]
0.00 0.00 2/3 mill_chr [37]
[10] 0.0 0.00 0.00 3 mill_choose_val [10]
0.00 0.00 1/3 mill_chs [11]
-----------------------------------------------
0.00 0.00 1/3 mill_choose_val [10]
0.00 0.00 2/3 mill_fdwait [2]
[11] 0.0 0.00 0.00 3 mill_chs [11]
-----------------------------------------------
0.00 0.00 1/3 _init [83]
0.00 0.00 1/3 dialogue [23]
0.00 0.00 1/3 main <cycle 1> [5]
[12] 0.0 0.00 0.00 3 mill_ipport [12]
0.00 0.00 2/11 mill_trace_ [4]
0.00 0.00 2/6 mill_ipany [7]
-----------------------------------------------
0.00 0.00 3/3 main <cycle 1> [5]
[13] 0.0 0.00 0.00 3 mill_register_cr [13]
-----------------------------------------------
0.00 0.00 1/2 _init [83]
0.00 0.00 1/2 main <cycle 1> [5]
[14] 0.0 0.00 0.00 2 mill_ipliteral [14]
0.00 0.00 2/6 mill_ipany [7]
0.00 0.00 1/11 mill_trace_ [4]
-----------------------------------------------
1 main <cycle 1> [5]
[15] 0.0 0.00 0.00 1 mill_chmake <cycle 1> [15]
0.00 0.00 1/4 mill_chclose [9]
0.00 0.00 1/17 mill_fdwait [2]
0.00 0.00 1/11 mill_trace_ [4]
1 main <cycle 1> [5]
-----------------------------------------------
0.00 0.00 1/1 statistics [72]
[16] 0.0 0.00 0.00 1 mill_getchan [16]
0.00 0.00 1/8 main <cycle 1> [5]
-----------------------------------------------
0.00 0.00 1/1 __gmon_start__ [87]
[17] 0.0 0.00 0.00 1 mill_ipv4_literal [17]
0.00 0.00 1/6 mill_ipany [7]
0.00 0.00 1/11 mill_trace_ [4]
-----------------------------------------------
0.00 0.00 1/1 statistics [72]
[18] 0.0 0.00 0.00 1 mill_ipv6_literal [18]
0.00 0.00 1/11 mill_trace_ [4]
0.00 0.00 1/6 mill_ipany [7]
-----------------------------------------------
0.00 0.00 1/1 statistics [72]
[83] 0.0 0.00 0.00 1 _init [83]
0.00 0.00 2/17 mill_fdwait [2]
0.00 0.00 2/16 iplocal [3]
0.00 0.00 1/2 mill_ipliteral [14]
0.00 0.00 1/8 mill_choose_wait [6]
0.00 0.00 1/3 mill_ipport [12]
-----------------------------------------------


Index by function name

[83] _init [6] mill_choose_wait [17]
mill_ipv4_literal (ip.c)
[8] gotrace [11] mill_chs [18]
mill_ipv6_literal (ip.c)
[3] iplocal [2] mill_fdwait [13]
mill_register_cr
[5] main [16] mill_getchan [4] mill_trace_
[9] mill_chclose [7] mill_ipany (ip.c) [1] <cycle 1>
[15] mill_chmake [14] mill_ipliteral (ip.c)
[10] mill_choose_val [12] mill_ipport

Nir


Other related posts: