From: Tarik T. <tta...@gm...> - 2013-10-09 18:40:34
|
Hi, I am trying to profile opensips using operf --pid command and although profiler starts the profiling result does not have any connection with opensips. Opensips is haevily used during profiling. Here is the oputput: root@kuca:/etc/opensips# opensipsctl start INFO: Starting OpenSIPS : INFO: started (pid: 7816) root@kuca:/etc/opensips# operf --pid 7816 operf: Profiler started operf: Press Ctl-c or 'kill -SIGINT 7836' to stop profiling ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * * The number of samples actually recorded is less than expected, but is probably still statistically valid. Decreasing the sampling rate is the best option if you want to avoid throttling. Profiling done. root@kuca:/etc/opensips# opreport Using /etc/opensips/oprofile_data/samples/ for samples directory. CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz (estimated) Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000 CPU_CLK_UNHALT...| samples| %| ------------------ 841 70.2003 xkbcomp CPU_CLK_UNHALT...| samples| %| ------------------ 341 40.5470 libc-2.11.3.so 208 24.7325 xkbcomp 179 21.2842 no-vmlinux 73 8.6801 libX11.so.6.3.0 28 3.3294 libxkbfile.so.1.0.2 9 1.0702 ld-2.11.3.so 2 0.2378 [vdso] (tgid:7847 range:0xb77a7000-0xb77a7fff) 1 0.1189 [vdso] (tgid:7842 range:0xb77a9000-0xb77a9fff) 252 21.0351 php5 CPU_CLK_UNHALT...| samples| %| ------------------ 69 27.3810 ld-2.11.3.so 59 23.4127 no-vmlinux 57 22.6190 php5 53 21.0317 libc-2.11.3.so 12 4.7619 libcrypto.so.0.9.8 1 0.3968 libpthread-2.11.3.so 1 0.3968 suhosin.so 105 8.7646 exim4 CPU_CLK_UNHALT...| samples| %| ------------------ 49 46.6667 no-vmlinux 33 31.4286 libc-2.11.3.so 13 12.3810 ld-2.11.3.so 9 8.5714 exim4 1 0.9524 libdb-4.8.so On the opposite side when using command operf --system-wide the result is meaningful concerning opensips. root@kuca:/etc/opensips# operf --system-wide operf: Profiler started operf: Press Ctl-c or 'kill -SIGINT 7872' to stop profiling ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * * The number of samples actually recorded is less than expected, but is probably still statistically valid. Decreasing the sampling rate is the best option if you want to avoid throttling. Profiling done. root@kuca:/etc/opensips# opreport Using /etc/opensips/oprofile_data/samples/ for samples directory. CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz (estimated) Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000 CPU_CLK_UNHALT...| samples| %| ------------------ 402977 63.5545 opensips CPU_CLK_UNHALT...| samples| %| ------------------ 128309 31.8403 no-vmlinux 97832 24.2773 libcrypto.so.0.9.8 86686 21.5114 opensips 32932 8.1722 libssl.so.0.9.8 19217 4.7688 libc-2.11.3.so 11017 2.7339 libmysqlclient.so.16.0.0 4486 1.1132 auth.so 4078 1.0120 tm.so 3374 0.8373 db_mysql.so 3305 0.8201 registrar.so 2543 0.6311 sl.so 2154 0.5345 usrloc.so 1723 0.4276 [vdso] (tgid:7821 range:0xb7747000-0xb7747fff) 1032 0.2561 maxfwd.so 931 0.2310 domain.so 741 0.1839 auth_db.so 638 0.1583 [vdso] (tgid:7822 range:0xb7747000-0xb7747fff) 574 0.1424 uri.so 564 0.1400 sipmsgops.so 442 0.1097 rr.so 393 0.0975 signaling.so 4 9.9e-04 [vdso] (tgid:7819 range:0xb7747000-0xb7747fff) 2 5.0e-04 [vdso] (tgid:7820 range:0xb7747000-0xb7747fff) 116097 18.3100 mysqld CPU_CLK_UNHALT...| samples| %| ------------------ 73294 63.1317 mysqld 26235 22.5975 no-vmlinux 9467 8.1544 libc-2.11.3.so 5482 4.7219 libpthread-2.11.3.so 1009 0.8691 [vdso] (tgid:1749 range:0xb6fb1000-0xb6fb1fff) 243 0.2093 libstdc++.so.6.0.13 213 0.1835 libgcc_s.so.1 154 0.1326 libm-2.11.3.so Can you help me in understanding what am I doing wrong? Thanks, Tarik p.s.: operf version is: root@kuca:/etc/opensips# operf --version operf: oprofile 0.9.8 compiled on Jan 14 2013 20:34:35 |
From: Maynard J. <may...@us...> - 2013-10-10 00:33:30
|
On 10/09/2013 01:40 PM, Tarik Tankovic wrote: > Hi, > > I am trying to profile opensips using operf --pid command and although > profiler starts the profiling result does not have any connection with > opensips. Opensips is haevily used during profiling. Here is the > oputput: Hi, Tarik, I've never seen any issues where 'operf --pid' actually profiles the wrong process! I just did a simple test using oprofile 0.9.8, and it worked fine. I don't have any theory at present why the correct process is not being profiled for you. Does this only happen with opensips (which, btw, I'm not familiar with)? That is, can you use 'operf --pid' successfully on some simple testcase? Our latest release -- 0.9.9 -- has a number of fixes relating to the "--pid" option. Please install that and let me know if you still have problems and if there's a way I can reproduce them. If I can't reproduce, I'll need to walk you through collection of debugging information. -Maynard > > root@kuca:/etc/opensips# opensipsctl start > > INFO: Starting OpenSIPS : > INFO: started (pid: 7816) > root@kuca:/etc/opensips# operf --pid 7816 > operf: Profiler started > operf: Press Ctl-c or 'kill -SIGINT 7836' to stop profiling > ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * * > The number of samples actually recorded is less than expected, but is > probably still statistically valid. Decreasing the sampling rate is the > best option if you want to avoid throttling. > > Profiling done. > root@kuca:/etc/opensips# opreport > Using /etc/opensips/oprofile_data/samples/ for samples directory. > CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a > unit mask of 0x00 (No unit mask) count 100000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 841 70.2003 xkbcomp > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 341 40.5470 libc-2.11.3.so > 208 24.7325 xkbcomp > 179 21.2842 no-vmlinux > 73 8.6801 libX11.so.6.3.0 > 28 3.3294 libxkbfile.so.1.0.2 > 9 1.0702 ld-2.11.3.so > 2 0.2378 [vdso] (tgid:7847 range:0xb77a7000-0xb77a7fff) > 1 0.1189 [vdso] (tgid:7842 range:0xb77a9000-0xb77a9fff) > 252 21.0351 php5 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 69 27.3810 ld-2.11.3.so > 59 23.4127 no-vmlinux > 57 22.6190 php5 > 53 21.0317 libc-2.11.3.so > 12 4.7619 libcrypto.so.0.9.8 > 1 0.3968 libpthread-2.11.3.so > 1 0.3968 suhosin.so > 105 8.7646 exim4 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 49 46.6667 no-vmlinux > 33 31.4286 libc-2.11.3.so > 13 12.3810 ld-2.11.3.so > 9 8.5714 exim4 > 1 0.9524 libdb-4.8.so > > On the opposite side when using command operf --system-wide the result > is meaningful concerning opensips. > > root@kuca:/etc/opensips# operf --system-wide > operf: Profiler started > operf: Press Ctl-c or 'kill -SIGINT 7872' to stop profiling > ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * * > The number of samples actually recorded is less than expected, but is > probably still statistically valid. Decreasing the sampling rate is the > best option if you want to avoid throttling. > > Profiling done. > root@kuca:/etc/opensips# opreport > Using /etc/opensips/oprofile_data/samples/ for samples directory. > CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a > unit mask of 0x00 (No unit mask) count 100000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 402977 63.5545 opensips > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 128309 31.8403 no-vmlinux > 97832 24.2773 libcrypto.so.0.9.8 > 86686 21.5114 opensips > 32932 8.1722 libssl.so.0.9.8 > 19217 4.7688 libc-2.11.3.so > 11017 2.7339 libmysqlclient.so.16.0.0 > 4486 1.1132 auth.so > 4078 1.0120 tm.so > 3374 0.8373 db_mysql.so > 3305 0.8201 registrar.so > 2543 0.6311 sl.so > 2154 0.5345 usrloc.so > 1723 0.4276 [vdso] (tgid:7821 range:0xb7747000-0xb7747fff) > 1032 0.2561 maxfwd.so > 931 0.2310 domain.so > 741 0.1839 auth_db.so > 638 0.1583 [vdso] (tgid:7822 range:0xb7747000-0xb7747fff) > 574 0.1424 uri.so > 564 0.1400 sipmsgops.so > 442 0.1097 rr.so > 393 0.0975 signaling.so > 4 9.9e-04 [vdso] (tgid:7819 range:0xb7747000-0xb7747fff) > 2 5.0e-04 [vdso] (tgid:7820 range:0xb7747000-0xb7747fff) > 116097 18.3100 mysqld > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 73294 63.1317 mysqld > 26235 22.5975 no-vmlinux > 9467 8.1544 libc-2.11.3.so > 5482 4.7219 libpthread-2.11.3.so > 1009 0.8691 [vdso] (tgid:1749 range:0xb6fb1000-0xb6fb1fff) > 243 0.2093 libstdc++.so.6.0.13 > 213 0.1835 libgcc_s.so.1 > 154 0.1326 libm-2.11.3.so > > Can you help me in understanding what am I doing wrong? > > Thanks, > > Tarik > > p.s.: operf version is: > > root@kuca:/etc/opensips# operf --version > operf: oprofile 0.9.8 compiled on Jan 14 2013 20:34:35 > > ------------------------------------------------------------------------------ > October Webinars: Code for Performance > Free Intel webinars can help you accelerate application performance. > Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most from > the latest Intel processors and coprocessors. See abstracts and register > > http://pubads.g.doubleclick.net/gampad/clk?id=60134071&iu=/4140/ostg.clktrk > _______________________________________________ > oprofile-list mailing list > opr...@li... > https://lists.sourceforge.net/lists/listinfo/oprofile-list > |
From: Maynard J. <may...@us...> - 2013-10-14 14:58:26
|
On 10/12/2013 03:38 PM, Tarik Tankovic wrote: > Dear Maynard, > > I 've installed the latest version of oprofile today and after that I > 've also realised where I was making a mistake. > > Actually, opensips is using more than one pid and for some reason the > third one is the one that is used. After I started with profiling pid > 12247 I 've got the result I was expecting: Tarik, Thanks for letting us know. Added oprofile-list back to cc so others can see solution. -Maynard > > root@kuca:/etc/opensips# pidof opensips > 12252 12251 12249 12248 12247 12246 12244 > root@kuca:/etc/opensips# operf --pid 12247 > operf: Press Ctl-c or 'kill -SIGINT 13402' to stop profiling > operf: Profiler started > ^C > Profiling done. > root@kuca:/etc/opensips# opreport > Using /etc/opensips/oprofile_data/samples/ for samples directory. > CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz (estimated) > Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a > unit mask of 0x00 (No unit mask) count 100000 > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 22975 83.4393 opensips > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 8638 37.5974 no-vmlinux > 7278 31.6779 opensips > 1699 7.3950 libc-2.11.3.so > 1657 7.2122 libmysqlclient.so.16.0.0 > 645 2.8074 auth.so > 534 2.3243 db_mysql.so > 531 2.3112 tm.so > 479 2.0849 registrar.so > 382 1.6627 usrloc.so > 329 1.4320 sl.so > 161 0.7008 [vdso] (tgid:12247 range:0xb77df000-0xb77dffff) > 134 0.5832 maxfwd.so > 119 0.5180 auth_db.so > 108 0.4701 domain.so > 95 0.4135 uri.so > 87 0.3787 sipmsgops.so > 59 0.2568 rr.so > 40 0.1741 signaling.so > 1557 5.6546 vmware-vmx > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 1557 100.000 no-vmlinux > 1198 4.3508 operf > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 1198 100.000 no-vmlinux > 811 2.9453 Xorg > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 811 100.000 no-vmlinux > 453 1.6452 unknown > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 453 100.000 no-vmlinux > 428 1.5544 xkbcomp > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 162 37.8505 libc-2.11.3.so > 114 26.6355 xkbcomp > 92 21.4953 no-vmlinux > 39 9.1121 libX11.so.6.3.0 > 11 2.5701 ld-2.11.3.so > 10 2.3364 libxkbfile.so.1.0.2 > 63 0.2288 sh > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 55 87.3016 no-vmlinux > 4 6.3492 libc-2.11.3.so > 3 4.7619 ld-2.11.3.so > 1 1.5873 dash > 50 0.1816 appLoader > CPU_CLK_UNHALT...| > samples| %| > ------------------ > 50 100.000 no-vmlinux > > I would probably get the same result with oprofile 0.9.8. > > Anyway, thank you for your support. > > Best regards, > > Tarik > > On 10/10/13, Tarik Tankovic <tta...@gm...> wrote: >> Thanks Maynard, >> >> I'll install the latest version of oprofile and then try again. >> >> Btw, opensips is an open SIP server on which I am conducting some >> performance tests and profiling is important for me for that very reason. >> >> Best regards, >> >> Tarik >> >> On Thursday, October 10, 2013, Maynard Johnson <may...@us...> wrote: >>> On 10/09/2013 01:40 PM, Tarik Tankovic wrote: >>>> Hi, >>>> >>>> I am trying to profile opensips using operf --pid command and although >>>> profiler starts the profiling result does not have any connection with >>>> opensips. Opensips is haevily used during profiling. Here is the >>>> oputput: >>> >>> Hi, Tarik, >>> I've never seen any issues where 'operf --pid' actually profiles the >> wrong process! I just did a simple test using oprofile 0.9.8, and it worked >> fine. I don't have any theory at present why the correct process is not >> being profiled for you. Does this only happen with opensips (which, btw, >> I'm not familiar with)? That is, can you use 'operf --pid' successfully on >> some simple testcase? Our latest release -- 0.9.9 -- has a number of fixes >> relating to the "--pid" option. Please install that and let me know if you >> still have problems and if there's a way I can reproduce them. If I can't >> reproduce, I'll need to walk you through collection of debugging >> information. >>> >>> -Maynard >>>> >>>> root@kuca:/etc/opensips# opensipsctl start >>>> >>>> INFO: Starting OpenSIPS : >>>> INFO: started (pid: 7816) >>>> root@kuca:/etc/opensips# operf --pid 7816 >>>> operf: Profiler started >>>> operf: Press Ctl-c or 'kill -SIGINT 7836' to stop profiling >>>> ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * >> * >>>> The number of samples actually recorded is less than expected, but is >>>> probably still statistically valid. Decreasing the sampling rate is the >>>> best option if you want to avoid throttling. >>>> >>>> Profiling done. >>>> root@kuca:/etc/opensips# opreport >>>> Using /etc/opensips/oprofile_data/samples/ for samples directory. >>>> CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz >> (estimated) >>>> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a >>>> unit mask of 0x00 (No unit mask) count 100000 >>>> CPU_CLK_UNHALT...| >>>> samples| %| >>>> ------------------ >>>> 841 70.2003 xkbcomp >>>> CPU_CLK_UNHALT...| >>>> samples| %| >>>> ------------------ >>>> 341 40.5470 libc-2.11.3.so >>>> 208 24.7325 xkbcomp >>>> 179 21.2842 no-vmlinux >>>> 73 8.6801 libX11.so.6.3.0 >>>> 28 3.3294 libxkbfile.so.1.0.2 >>>> 9 1.0702 ld-2.11.3.so >>>> 2 0.2378 [vdso] (tgid:7847 range:0xb77a7000-0xb77a7fff) >>>> 1 0.1189 [vdso] (tgid:7842 range:0xb77a9000-0xb77a9fff) >>>> 252 21.0351 php5 >>>> CPU_CLK_UNHALT...| >>>> samples| %| >>>> ------------------ >>>> 69 27.3810 ld-2.11.3.so >>>> 59 23.4127 no-vmlinux >>>> 57 22.6190 php5 >>>> 53 21.0317 libc-2.11.3.so >>>> 12 4.7619 libcrypto.so.0.9.8 >>>> 1 0.3968 libpthread-2.11.3.so >>>> 1 0.3968 suhosin.so >>>> 105 8.7646 exim4 >>>> CPU_CLK_UNHALT...| >>>> samples| %| >>>> ------------------ >>>> 49 46.6667 no-vmlinux >>>> 33 31.4286 libc-2.11.3.so >>>> 13 12.3810 ld-2.11.3.so >>>> 9 8.5714 exim4 >>>> 1 0.9524 libdb-4.8.so >>>> >>>> On the opposite side when using command operf --system-wide the result >>>> is meaningful concerning opensips. >>>> >>>> root@kuca:/etc/opensips# operf --system-wide >>>> operf: Profiler started >>>> operf: Press Ctl-c or 'kill -SIGINT 7872' to stop profiling >>>> ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * >> * >>>> The number of samples actually recorded is less than expected, but is >>>> probably still statistically valid. Decreasing the sampling rate is the >>>> best option if you want to avoid throttling. >>>> >>>> Profiling done. >>>> root@kuca:/etc/opensips# opreport >>>> Using /etc/opensips/oprofile_data/samples/ for samples directory. >>>> CPU: Intel Sandy Bridge microarchitecture, speed 3.101e+06 MHz >> (estimated) >>>> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a >>>> unit mask of 0x00 (No unit mask) count 100000 >>>> CPU_CLK_UNHALT...| >>>> samples| %| >>>> ------------------ >>>> 4> >> ------------------------------------------------------------------------------ >>>> October Webinars: Code for Performance >>>> Free Intel webinars can help you accelerate application performance. >>>> Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most >> from >>>> the latest Intel processors and coprocessors. See abstracts and register >>> >>>> >> http://pubads.g.doubleclick.net/gampad/clk?id=60134071&iu=/4140/ostg.clktrk >>>> _______________________________________________ >>>> oprofile-list mailing list >>>> opr...@li... >>>> https://lists.sourceforge.net/lists/listinfo/oprofile-list >>>> >>> >>> >> > |