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]