Why calls to functions in libclntsh.so often come from *ROOT* in the Call Graph section?

[blackwater]

The question is about HP Caliper (HP-UX Itanium Version A.4.3.2) on HP-UX 11.31.

I have a test C++ program that depends on libclntsh.so (Oracle client 11.2.0.3) and my own simple shared library (libmy_lib.so).
I call functions from libclntsh.so and from libmy_lib.so.
Then I run HP Caliper and get a scgprof report.

In the Call Graph section I see correct call stack for calls to functions in my own simple shared library.
And incorrect call stack for calls to functions in libclntsh.so.
Calls to functions in libclntsh.so often come from *ROOT*?
Why they come from ROOT?
When I attach to the test program process with HP wdb I see a correct backtrace for them.

This is an example for the function kpufch() from libclntsh.so:
In HP wdb:

Breakpoint 2, kpufch () at kpuf.c:2079
2079    in kpuf.c
#0  kpufch () at kpuf.c:2079
#1  0xc000000006873b80:0 in OCIStmtFetch () at oci8.c:1342
#2  0x4000000000004490:0 in threadfunc () at test_oci.cpp:187
#3  0x40000000000031d0:0 in main () at test_oci.cpp:312

 In HP Caliper:

Call Graph
------------------------------------------------------------------------
                 % Func Hits                             
       % Total     Under Parent   Called/Total     %         Parents
Index  Hits In   In Func          Called+Self     Call   Name     Index
       or Under    In Children    Called/Total    Total      Children
------------------------------------------------------------------------
[1]     100.0      0.00                -                 *ROOT* [1]
                      28.44            1                     libclntsh.so.11.1::$cold_ttcrbur [2]
                      15.71            1                     libclntsh.so.11.1::$cold_ttcdrv [6]
                      11.46            1                     test_oci::threadfunc(void*) [10]
                       9.97            1                     libclntsh.so.11.1::$cold_upirtrc [12]
                       9.96            1                     libclntsh.so.11.1::$cold_kpufch0 [14]
                       4.42            1                     *Call Stubs*
                       4.15            1                     libclntsh.so.11.1::$cold_kpuhhalp [25]
                       3.76            1                     libclntsh.so.11.1::kpufch [26]

------------------------------------------------------------------------
                     100.00            1                     *ROOT* [1]
[26]      3.8     10.64                -                 libclntsh.so.11.1::kpufch [26]
                      82.49          303/427        71       libclntsh.so.11.1::kpufch0 [24]
                       6.88          371/1809       21       libclntsh.so.11.1::$cold_kpummTLSGET1 [64]

This is an example for the function my_sub_function() from libmy_lib.so:
In HP wdb:

Breakpoint 1, my_sub_function () at my_lib.cpp:7
7         int res = time(0);
Current language:  auto; currently c++
(gdb) bt
#0  my_sub_function () at my_lib.cpp:7
#1  0xc0000000001e2800:0 in my_function_in_another_dll () at my_lib.cpp:16
#2  0x4000000000004430:0 in threadfunc () at test_oci.cpp:181
#3  0x40000000000031d0:0 in main () at test_oci.cpp:312

In HP Caliper:

------------------------------------------------------------------------
                     100.00           82/82        100       test_oci::threadfunc(void*) [10]
[98]      0.6      5.97               82                 libmy_lib.so::my_function_in_another_dll [98]
                      94.03           78/78        100       libmy_lib.so::my_sub_function [103]

I will upload a caliper report and my test program.
I build it with aCC in this way:

aCC -AA +O2 +Onoinline +z -c +DD64 my_lib.cpp
ld -h my_sub_function -b -o libmy_lib.so my_lib.o
aCC -AA +DD64 +O2 -I/u01/app/oracle/product/11.2.0/cl11203/rdbms/public -L/u01/app/oracle/product/11.2.0/cl11203/lib -L. test_oci.cpp -lclntsh -lmy_lib -o test_oci

By the way I see that there are lots of functions in the Call Graph section of the attached report that this call stack directly from *ROOT*. I chose kpufch () only as an example:

Call Graph
------------------------------------------------------------------------
                 % Func Hits                             
       % Total     Under Parent   Called/Total     %         Parents
Index  Hits In   In Func          Called+Self     Call   Name     Index
       or Under    In Children    Called/Total    Total      Children
------------------------------------------------------------------------
[1]     100.0      0.00                -                 *ROOT* [1]
                      28.44            1                     libclntsh.so.11.1::$cold_ttcrbur [2]
                      15.71            1                     libclntsh.so.11.1::$cold_ttcdrv [6]
                      11.46            1                     test_oci::threadfunc(void*) [10]
                       9.97            1                     libclntsh.so.11.1::$cold_upirtrc [12]
                       9.96            1                     libclntsh.so.11.1::$cold_kpufch0 [14]

P.S. This thread has been moved from HP-UX > General to HP-UX > languages - HP Forums Moderator

[Dennis Handly]

>Why they come from ROOT?

Have you looked at the Caliper documents?  I assumed it was something like gprof's <spontaneous>.

Or possibly indirect calls?

Have you tried gprof to see if it has the same problem?

>ld -h my_sub_function -b -o libmy_lib.so my_lib.o

It is illegal to link aC++ load modules directly with ld.  You should be using aCC -b:

aCC -b -Wl,-h,my_sub_function -o libmy_lib.so my_lib.o

FYI:  I don't see any kudos assigned to any of your topics from either the EBC forum or the older ITRC.

Please take of them.  (Thanks)

[blackwater]

Dennis,

> Have you looked at the Caliper documents?  I assumed it was something like gprof's <spontaneous>.

This is that I see in gprof: "If the identity of the callers of a function cannot be determined, a dummy caller-line is printed which has`<spontaneous>'as the "caller's name" and all other fields blank"

But this is actually my question. Why in my library libmy_lib.so functions can be determined and in Oracle cannot?

> Or possibly indirect calls?

This is how assembler code looks for OCIStmtFetch() that calls kpufch(). Do you see an indirect call to kpufch()?

(gdb) disassemble
Dump of assembler code for function OCIStmtFetch:
;;; DOC Line Information: [Line, Column Start, Column End] [Line, Column] [Line]
;;; File: oci8.c
;;; Line: 1341
0xc000000006873b40:0 <OCIStmtFetch>:
          alloc            r38=ar.pfs,0,8,6,0                                MMI
0xc000000006873b40:1 <OCIStmtFetch+0x1>:              mov              r37=gp
0xc000000006873b40:2 <OCIStmtFetch+0x2>:              mov              r39=rp
;;; Line: 1342
0xc000000006873b50:0 <OCIStmtFetch+0x10>:
          mov              r40=r32                                           MMI,
0xc000000006873b50:1 <OCIStmtFetch+0x11>:             mov              r41=r33
0xc000000006873b50:2 <OCIStmtFetch+0x12>:
          mov              r42=r34;;
0xc000000006873b60:0 <OCIStmtFetch+0x20>:
          mov              r43=r35                                           MMI
0xc000000006873b60:1 <OCIStmtFetch+0x21>:             mov              r44=0
0xc000000006873b60:2 <OCIStmtFetch+0x22>:             mov              r45=r36
0xc000000006873b70:0 <OCIStmtFetch+0x30>:
          nop.m            0x0                                               MMB,
0xc000000006873b70:1 <OCIStmtFetch+0x31>:             nop.m            0x0
0xc000000006873b70:2 <OCIStmtFetch+0x32>:
          br.call.sptk.many rp=0xc0000000066fed60;;
0xc000000006873b80:0 <OCIStmtFetch+0x40>:
          mov              gp=r37                                            MI,I
0xc000000006873b80:1 <OCIStmtFetch+0x41>:             mov              rp=r39;;
0xc000000006873b80:2 <OCIStmtFetch+0x42>:
          mov.i            ar.pfs=r38
0xc000000006873b90:0 <OCIStmtFetch+0x50>:
          nop.m            0x0                                               MMB,
0xc000000006873b90:1 <OCIStmtFetch+0x51>:             nop.m            0x0
0xc000000006873b90:2 <OCIStmtFetch+0x52>:             br.ret.sptk.many rp;;
End of assembler dump.
(gdb) x/i $pc
0xc000000006873b80:0 <OCIStmtFetch+0x40>:
          mov              gp=r37                                            MI,I

> It is illegal to link aC++ load modules directly with ld.  You should be using aCC -b:

OK,  changed it. However there is no problem with libmy_lib.so. It is just a test library to see how function calls to a shared library are seen by HP Calper. As I see HP Caliper correctly prints call stacks for calls to my_sub_function()

[Dennis Handly]

>Why in my library libmy_lib.so functions can be determined and in Oracle cannot?

I would check the Caliper documentation to see what it says about *ROOT*.  I thought it's because libclntsh.so is stripped?

>Do you see an indirect call to kpufch()?

No, just a call to an import stub.

>there is no problem with libmy_lib.so.

Using ld directly is a bad habit to get into.

[blackwater]

Dennis,

> I would check the Caliper documentation to see what it says about *ROOT*.
I have looked for *ROOT* and found it only in examples in Caliper documentation.
And one place was about acuracy in cgprof section but unfortunately it seems to be irrelevant to my question.

> I thought it's because libclntsh.so is stripped?
nm shows that there are symbols:

bash-3.2$ ldd ./test_oci | grep libclntsh
        libclntsh.so.11.1 =>    /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.11.1
bash-3.2$ nm /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.11.1 | grep -E -e "\bkpufch\b|\bOCIStmtFetch\b"
40000000011d7b40 T OCIStmtFetch
4000000001514840 T kpufch

On the contrary libmy_lib.so is stripped:

bash-3.2$ nm ./libmy_lib.so
nm: ./libmy_lib.so: no symbols

Yet in a caliper scgprof report (caliper scgprof -e 10 -o test_oci.pid.21_11.txt `ps -u $USER | awk '$4~/test_oci/ {print $1}'`)
I see that libmy_lib.so::my_sub_function has still a correct call stack
(I mean test_oci::threadfunc calls libmy_lib.so::my_function_in_another_dll and libmy_lib.so::my_function_in_another_dll calls libmy_lib.so::my_sub_function):

------------------------------------------------------------------------
                     100.00           19/19        100       test_oci::threadfunc(void*) [11]
[148]     0.2     14.29               19                 libmy_lib.so::my_function_in_another_dll [148]
                      85.71           17/17        100       libmy_lib.so::my_sub_function [156]

 While kpufch comes right from *ROOT*:

------------------------------------------------------------------------
                     100.00            1                     *ROOT* [1]
[26]      3.3     13.48                -                 libclntsh.so.11.1::kpufch [26]
                      79.26           89/125        71       libclntsh.so.11.1::kpufch0 [25]
                       7.26           96/470        20       libclntsh.so.11.1::$cold_kpummTLSGET1 [64]

Although HP wdb show me that libclntsh.so.11.1::kpufch is only called from OCIStmtFetch().
I created a simple .gdbinit:

  set pagination off
  file ./test_oci
  shell ps -u $USER | awk '$4~/test_oci/ {print "attach "$1}' > attach_to_a_out
  source attach_to_a_out
  b kpufch
  commands
  bt
  c
  end
  set logging file test_oci.gdb.txt
  set logging on
  c

It shows that calls to libclntsh.so.11.1::kpufch() come only from OCIStmtFetch() and have this backtrace:

Breakpoint 1, kpufch () at kpuf.c:2079
2079	in kpuf.c
#0  kpufch () at kpuf.c:2079
#1  0xc000000006873b80:0 in OCIStmtFetch () at oci8.c:1342
#2  0x4000000000004490:0 in threadfunc(void*)+0x570 ()
#3  0x40000000000031d0:0 in main+0x980 ()

Why HP Caliper (Version A.4.3.2) doesn't see that kpufch() is called from OCIStmtFetch(), not from *ROOT* while HP wdb do see correctl the call stack?

[blackwater]

> Using ld directly is a bad habit to get into.

OK. This is how I build libmy_lib.so now:

aCC -g -AA +O2 +Onoinline +z -b +DD64 my_lib.cpp -o libmy_lib.so
aCC -AA +DD64 +O2 -I/u01/app/oracle/product/11.2.0/cl11203/rdbms/public -L/u01/app/oracle/product/11.2.0/cl11203/lib -L. test_oci.cpp -lclntsh -lmy_lib -o test_oci
strip test_oci
strip libmy_lib.so

[Dennis Handly]

>I have looked for *ROOT* and found it only in examples in Caliper documentation.
>And one place was about accuracy in cgprof section but unfortunately it seems to be irrelevant to my question.

I guess I found that too:

... and time allocated to the *ROOT* entry  descendants.

But I do see in /opt/caliper/doc/text/cgprof.help:

   An entry called *ROOT* reflects 100 percent of the time for your executable, which represents the time from:
     o All the functions with no parents
     o Out-of-context modules
     o Stub code

The source also mentions cases where inline functions call other functions.

>Why Caliper doesn't see that kpufch is called from OCIStmtFetch, not from *ROOT* while HP wdb do see correctly the call stack?

Probably because Caliper samples and wdb doesn't and is too dumb to mess up?

>This is how I build libmy_lib.so now:
>aCC -g -AA +O2 +Onoinline +z -b +DD64 my_lib.cpp -o libmy_lib.so

I typically put my -c or -b first, so I immediately know what the driver is doing.

[blackwater]

>   An entry called *ROOT* reflects 100 percent of the time for your executable, which represents the time from:
>     o All the functions with no parents
>     o Out-of-context modules
>     o Stub code
>   The source also mentions cases where inline functions call other functions.

This phrase "Out-of-context modules"  is mentioned only once in whe whole Caliper 5.2 User guide. I mean there is no explanation what it means. Is it relevant to my situation?
"All the functions with no parents". If that means a top function for a main thread or a POSIX thread then kpufch() is obviously not of this type.
By the way I will upload HP wdb disasemble for libclntsh::kpufch().


>>Why Caliper doesn't see that kpufch is called from OCIStmtFetch, not from *ROOT* while HP wdb do see correctly the call stack?
>Probably because Caliper samples and wdb doesn't and is too dumb to mess up?

Still don't understand. libclntsh::kpufch() is called more often than libmy_lib.so::my_sub_function():
Function Summary
---------------------------------------------------------------------------------------------------------
   0.45    77.22               14   0.00              0      0.00  libclntsh.so.11.1::kpufch         kpuf.c
   0.19    88.34                6   0.00             17      0.11  libmy_lib.so::my_sub_function     

Despite this call graph for libmy_lib.so::my_sub_function() is correct but call graph for libclntsh::kpufch() is not:
------------------------------------------------------------------------
                     100.00            1                     *ROOT* [1]
[26]      3.3     13.48                -                 libclntsh.so.11.1::kpufch [26]
                      79.26           89/125        71       libclntsh.so.11.1::kpufch0 [25]
                       7.26           96/470        20       libclntsh.so.11.1::$cold_kpummTLSGET1 [64]

------------------------------------------------------------------------
                     100.00           19/19        100       test_oci::threadfunc(void*) [11]
[148]     0.2     14.29               19                 libmy_lib.so::my_function_in_another_dll [148]
                      85.71           17/17        100       libmy_lib.so::my_sub_function [156]

Moreover I see that lots of functions from libclntsh are called from *ROOT*
Call Graph
------------------------------------------------------------------------
                 % Func Hits                             
       % Total     Under Parent   Called/Total     %         Parents
Index  Hits In   In Func          Called+Self     Call   Name     Index
       or Under    In Children    Called/Total    Total      Children
------------------------------------------------------------------------
[1]     100.0      0.00                -                 *ROOT* [1]
                      28.11            1                     libclntsh.so.11.1::$cold_ttcrbur [3]
                      17.28            1                     libclntsh.so.11.1::$cold_ttcdrv [4]
                      10.78            1                     test_oci::threadfunc(void*) [11]
                       9.95            1                     libclntsh.so.11.1::$cold_upirtrc [13]
                       9.21            1                     libclntsh.so.11.1::$cold_kpufch0 [15]
                       4.45            1                     libclntsh.so.11.1::$cold_kpuhhalp [22]
                       4.34            1                     *Call Stubs*
                       3.34            1                     libclntsh.so.11.1::kpufch [26]

Finally that is interesting is that call graph for function calls inside libclnsh.so are correctlty seen by HP Caliper.

This is an example for libclntsh.so.11.1::kpufch0:

------------------------------------------------------------------------
                      28.80           36/125        29       libclntsh.so.11.1::$cold_kpufch0 [15]
                      71.20           89/125        71       libclntsh.so.11.1::kpufch [26]
[25]      3.7     12.11              125                 libclntsh.so.11.1::kpufch0 [25]
                      73.44           38/55         69       libclntsh.so.11.1::kpurcsc [23]
                      12.30           39/39        100       libclntsh.so.11.1::kpufrfs [110]
                       1.41           98/240        41       libclntsh.so.11.1::kpummgg [173]
                       0.74           35/2302        2       libc.so.1::memset [43]

[blackwater]

Installed HP Caliper 5.5 and run

caliper scgprof -e 10 -o test_oci.55.2.txt `ps -u $USER | awk '$4~/test_oci/ {print $1}'`

for my test.

Still the same picture.

Calls to libclntsh.so.11.1::kpufch come from *ROOT*

------------------------------------------------------------------------
                     100.00            1                     *ROOT* [1]
[26]      3.7      6.41                -                 libclntsh.so.11.1::kpufch [26]
                      85.07           70/93         75       libclntsh.so.11.1::kpufch0 [24]
                       8.51           76/316        24       libclntsh.so.11.1::$cold_kpummTLSGET1 [62]
------------------------------------------------------------------------

Yet HP Caliper correctly finds callers for functions deep inside libclntsh.so.11.1. This is an example for libclntsh.so.11.1::kpufch0:

------------------------------------------------------------------------
                      24.73           23/93         25       libclntsh.so.11.1::$cold_kpufch0 [15]
                      75.27           70/93         75       libclntsh.so.11.1::kpufch [26]
[24]      4.2     20.43               93                 libclntsh.so.11.1::kpufch0 [24]
                      70.54           20/32         63       libclntsh.so.11.1::kpurcsc [20]
                       7.65           16/16        100       libclntsh.so.11.1::kpufrfs [134]
                       0.96           28/1488        2       libc.so.1::memset [38]
                       0.42           62/167        37       libclntsh.so.11.1::kpummgg [203]
------------------------------------------------------------------------

Why does kpufch0 have correct callers and kpufch doesn't?

I will upload HP wdb disassemble for kpufch0

[blackwater]

Forgot to mention:

bash-3.2$ aCC --version
aCC: HP C/aC++ B3910B A.06.15 [May 16 2007]

[Dennis Handly]

>I mean there is no explanation what it means. Is it relevant to my situation?

It may be related to the inlining case I mentioned?  You can experiment with this be removing the Minimal Line Table by:

1) Make a copy of libclntsh

2) Make the copy writable

3) strip -l the copy

4)  Use LD_LIBRARY_PATH to point to the copy and rerun caliper.  (Make sure it is using the copy.)

Then see if *ROOT* goes away?

>I will upload HP wdb disassemble for libclntsh::kpufch().

I think the caller is more interesting.  And you haven't dumped the $cold_ part.

It could be that Caliper doesn't handle hot/cold code correctly?

And the disassembly shows that rp is saved at kpufch+0x42.

>libclntsh::kpufch() is called more often than libmy_lib.so::my_sub_function():

The issue is where the sample is taken and how much work Caliper does to unwind.  wdb is dumb and uses the industrial strength libunwind to unwind and that must get it right.  Caliper may take some shortcuts for speed.

>Moreover I see that lots of functions from libclntsh are called from *ROOT*

That has lots of $cold_ sections.

>Still the same picture.

Ideally if they couldn't fix it, they could explain it better.  :-)

>kpufch0.txt 87 KB

Shows it has a $cold_ section.

>test_oci.55.2.txt 177 KB

The Function Details show only samples in $cold_kpufch.  At least to the 1% cutoff.

>aCC: HP C/aC++ B3910B A.06.15 [May 16 2007]

This is pretty old.

[blackwater]

> It could be that Caliper doesn't handle hot/cold code correctly?
> That has lots of $cold_ sections.
> Shows it has a $cold_ section.

Sorry, does $cold_ section have any special meaning?

The call graph section has both $cold_kpufch0 and kpufch and they both according to Caliper are called from *ROOT*? Does $cold prefix have any specail meaning on IA64?

9.29 1 libclntsh.so.11.1::$cold_kpufch0 [15]
3.74 1 libclntsh.so.11.1::kpufch [26]

[Dennis Handly]

>does $cold_ section have any special meaning?

Functions compiled with PBO are split into hot and cold sections, the latter are in $cold_.

>Does $cold prefix have any special meaning on IA64?

Yes, for HP-UX's compiler toolchain.

[blackwater]

> It may be related to the inlining case I mentioned?  You can experiment with this be removing the Minimal Line Table by:

> 1) Make a copy of libclntsh
> 2) Make the copy writable
> 3) strip -l the copy
> 4)  Use LD_LIBRARY_PATH to point to the copy and rerun caliper.  (Make sure it is using the copy.)

> Then see if *ROOT* goes away?

It didn't help. I copied and stripped libclntsh.so.11.1 and ran HP caliper.
This is output:

ls -l /home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/libclnt*
lrwxr-xr-x   1 has_test   users           19 Nov 22 15:28 /home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/libclntsh.so -> ./libclntsh.so.11.1
-rwxr-xr-x   1 has_test   users      100883568 Nov 22 15:31 /home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/libclntsh.so.11.1

ls -l /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.10.1 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.11.1 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh_nopthread.so /u01/app/oracle/product/11.2.0/cl11203/lib/libclntst11.a
lrwxr-xr-x   1 oracle     oinstall        60 Sep 26 16:55 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so -> /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.11.1
lrwxr-xr-x   1 oracle     oinstall        12 Sep 26 16:54 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.10.1 -> libclntsh.so
-rwxr-xr-x   1 oracle     oinstall   120559312 Sep 26 16:53 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh.so.11.1
-rwxr-xr-x   1 oracle     oinstall   120559312 Sep 26 16:54 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntsh_nopthread.so
-rw-r--r--   1 oracle     oinstall         0 Oct 21  2011 /u01/app/oracle/product/11.2.0/cl11203/lib/libclntst11.a

pldd 4770
4770:   /home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/test_oci
/home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/test_oci
/usr/lib/hpux64/dld.so
/home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/libclntsh.so.11.1
/home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/libmy_lib.so
/usr/lib/hpux64/libstd_v2.so.1
/usr/lib/hpux64/libCsup.so.1
/usr/lib/hpux64/libm.so.1
/usr/lib/hpux64/libunwind.so.1
/usr/lib/hpux64/libc.so.1
/usr/lib/hpux64/libdl.so.1
/home/has_test/PERF_HAS_TESTS/HPUX/11.31/ia64/sk/test.oci.acc.1th.libclntsh/libnnz11.so
/usr/lib/hpux64/librt.so.1
/usr/lib/hpux64/libpthread.so.1
/usr/lib/hpux64/libnsl.so.1
/usr/lib/hpux64/libdiskown.so
/usr/lib/hpux64/libuca.so.1
/usr/lib/hpux64/libxti.so.1
/usr/lib/hpux64/libnss_files.so.1
/usr/lib/hpux64/libnss_dns.so.1


I will upload a caliper report. This is just a part of it

------------------------------------------------------------------------
                     100.00            1                     *ROOT* [1]
[26]      3.8      9.49                -                 libclntsh.so.11.1::kpufch [26]
                      83.01          323/465        69       libclntsh.so.11.1::kpufch0 [22]
                       7.50          344/1746       20       libclntsh.so.11.1::$cold_kpummTLSGET1 [56]
------------------------------------------------------------------------

[Dennis Handly]

>It didn't help. I copied and stripped libclntsh.so.11.1 and ran HP caliper.

Then is isn't the inlining problem.

It appeared you ran caliper on an existing process, 4770.  That will also have *ROOT* for functions that have a sample but no matching one for their caller.

[blackwater]

> It appeared you ran caliper on an existing process, 4770. That will also have *ROOT* for functions that have a sample but no matching one for their caller.

That is true. I run caliper for a already running process. But why is it a problem?
caliper scgprof -e 10 -o $1 `ps -u $USER | awk '$4~/test_oci/ {print $1}'`

[blackwater]

>   And you haven't dumped the $cold_ part.

Dump of assembler code for function OCIStmtFetch:
Dump of assembler code for function kpufch:
Dump of assembler code for function $cold_kpufch:

I have uploaded disassemle.txt.

[Dennis Handly]

>But why is it a problem?

Because for those functions, they won't have a parent.  The call counts don't match up because sampling started after the function was called.

But I would expect SOME of the calls to show up with non-*ROOT* if called again.

[blackwater]

> Ideally if they couldn't fix it, they could explain it better. :-)
Could you clarify, please. Do you mean Oracle or HP Caliper team?

[blackwater]

>Because for those functions, they won't have a parent.  The call counts don't match up because sampling started after the function was called.

> But I would expect SOME of the calls to show up with non-*ROOT* if called again.

So you mean that both functions still have to have normal call stack, not from  *ROOT*?

Is a problem of HP Caliper or libclntsh.so?

By the way, one question is not clear to me.

I have breakpoint on $cold_kpufch but it is never hit. Yet HP caliper shows that it is called quite often:

(gdb) info breakpoints
Num Type           Disp Enb Address    What
1   breakpoint     keep y   0x9fffffffbbbd88d0 in kpufch at kpuf.c:2079
        breakpoint already hit 88 times
4   breakpoint     keep n   0x9fffffffbb46abd0 <$cold_kpufch>

Do you know why?

[Dennis Handly]

>Do you mean Oracle or HP Caliper team?

You said you installed a new Caliper, so that team.

[blackwater]

>>> Ideally if they couldn't fix it, they could explain it better. :-)

>>Could you clarify, please. Do you mean Oracle or HP Caliper team?

>You said you installed a new Caliper, so that team.

So, is anything else necessary from me to reproduce the problem on your side?

Or I just have to wait for an answer from HP Caliper team about this problem.

[Dennis Handly]

>is anything else necessary from me to reproduce the problem on your side?

Well, I know of a gedanken experiment to try but I don't know if it will have any success.

If you don't have a simple test case from scratch, it may be very hard to figure out.

Unless you just want to document why there is *ROOT* there.

>I just have to wait for an answer from HP Caliper team about this problem.

Unless you have a support contract to contact the HPSC, I'm not sure you'll get an answer.

Also, why do you care about what happens inside libclntsh.so?

The caliper data indicates the PBO instrumentation input isn't enough to cover the paths you're finding.

[Dennis Handly]

>So you mean that both functions still have to have normal call stack, not from  *ROOT*?

Except timewise, there was no caller to the functions active when you attached.

>Is a problem of HP Caliper or libclntsh.so?

Well, not libclntsh.so, since it runs correctly.  :-)  (I don't think it is compiled with foreign devil tools.)

The "problem" in Caliper could be it doesn't document what *ROOT* means and any limitations.

>I have breakpoint on $cold_kpufch but it is never hit. Yet HP caliper shows that it is called quite often:

This is NOT a function but a label.  It is the start of "cold" blocks of code in kpufch.  If the PBO instrumentation is done correctly you should never (or hardly ever :-) get hits in $cold_ code.

So Caliper could treat cold code in several ways:

1) Maintain the fiction that cold code doesn't exist and map all samples to $cold_foo to foo.

     This may "fix" your problem.  And is probably simpler.

2) Keep them separate in the reports but combine the two for parent info, if that would eliminate *ROOT*.

     This would keep useful info in that cold code appearing in samples may indicate poor PBO input.

[blackwater]

> Well, I know of a gedanken experiment to try but I don't know if it will have any success.

> If you don't have a simple test case from scratch, it may be very hard to figure out.

Sorry, didn't make it clear. In my fist message I attached source.zip. It contains test_oci.cpp, my_lib.cpp and build_all.sh.  build_all.sh builds a simple test program test_oci.

I run the test program in this way:

./test_oci scott/tiger@db 0 1000000 1 0

So when test_oci is running I get a caliper report

caliper scgprof -e 10 -o test_oci.caliper.txt `ps -u $USER | awk '$4~/test_oci/ {print $1}'`

I will upload SQL table that is necessary for the test_oci.

> Unless you have a support contract to contact the HPSC, I'm not sure you'll get an answer.

I will ask about that.

> Also, why do you care about what happens inside libclntsh.so?

I thought that it would give to me a more correct caliper report.

I mean that my real program works a lot with Oracle database through OCI.

Since calls to functions in libclntsh.so are sometimes disconnected like in this situation:

main () -> threadfunc() -> OCIStmtFetch() -> kpufch()

Then I think I get Call Graph section which is not very accurate.

Let me give you an example.

In test_oci.pid.2.txt there is a "Function Summary ". This is just a few lines from it:

Function Summary
---------------------------------------------------------------------------------------------------------
% Total  Cumulat                    Secs                    Msecs                                    
   IP      % of              IP      in            Call      per                                     
Samples    Total          Samples   Func          Count      Call  Function                          File
---------------------------------------------------------------------------------------------------------

   0.85    65.32               98   0.03            378      0.08  libclntsh.so.11.1::$cold_kpufch   kpuf.c
   0.40    77.19               46   0.01              0      0.00  libclntsh.so.11.1::kpufch         kpuf.c

 And in Call Graph section:

------------------------------------------------------------------------
                     100.00            1                     *ROOT* [1]
[26]      3.8     10.64                -                 libclntsh.so.11.1::kpufch [26]
                      82.49          303/427        71       libclntsh.so.11.1::kpufch0 [24]
                       6.88          371/1809       21       libclntsh.so.11.1::$cold_kpummTLSGET1 [64]
------------------------------------------------------------------------

------------------------------------------------------------------------
                     100.00          321/321       100       test_oci::threadfunc(void*) [10]
[38]      1.9      1.87              321                 libclntsh.so.11.1::OCIStmtFetch [38]
                      98.13          378/378       100       libclntsh.so.11.1::$cold_kpufch [43]
------------------------------------------------------------------------

 Am I right that a more correct libclntsh.so.11.1::OCIStmtFetch might look like this (roughly):

------------------------------------------------------------------------
                     100.00          321/321       100       test_oci::threadfunc(void*) [10]
[38]      5.0      1.87              321                 libclntsh.so.11.1::OCIStmtFetch [38]

                                                                               libclntsh.so.11.1::kpufch [26]
                      98.13          378/378       100       libclntsh.so.11.1::$cold_kpufch [43]

                                                                              
------------------------------------------------------------------------

Am I right that there must be two items under OCIStmtFetch() and increased  % Total Hits?

I mean both libclntsh.so.11.1::kpufch and libclntsh.so.11.1::$cold_kpufch.

This is actually the main reason why I ask about this problem.