can not find symbol in mcount support (on ARM)

[iamwonseok]

can not find symbol in mcount support (on ARM)

[namhyung]

Thanks for reporting the problem. I'm not sure what's the problem and it works fine on my raspberry-pi 2 board. Could you please share your environment using uftrace info command (of course you need to run record command before info)?

Also I'd like to see your test result: please show me the output of ./runtest.py -vp -O2 076.

[iamwonseok]

Sure, I ran every command on my renesas r-car h2 board.

uftrace info log:

root@kesl:~# uftrace info
# system information
# ==================
# program version     : uftrace v0.6.1-19-g8dcb
# recorded on         : Thu Jan 26 05:32:55 2017
# cmdline             : uftrace record hello 
# cpu info            : ARMv7 Processor rev 2 (v7l)
# number of cpus      : 4 / 8 (online / possible)
# memory info         : 3.8 / 3.9 GB (free / total)
# system load         : 0.00 / 0.01 / 0.02 (1 / 5 / 15 min)
# kernel version      : Linux 3.10.31-ltsi
# hostname            : kesl
# distro              : "Ubuntu 14.04 LTS"
#
# process information
# ===================
# number of tasks     : 1
# task list           : 831
# exe image           : /root/hello
# build id            : a24cf79a1920c02aea3138757f45339c1b27c420
# exit status         : exited with code: 0
# cpu time            : 0.010 / 0.010 sec (sys / user)
# context switch      : 1 / 1 (voluntary / involuntary)
# max rss             : 1088 KB
# page fault          : 0 / 422 (major / minor)
# disk iops           : 0 / 0 (read / write)

./runtest.py -vp -O2 076:

root@kesl:~/uftrace/tests# ./runtest.py -vp -O2 076
Test case             pg
--------------------: O2
build command for library: gcc -o libabc_test_lib.so -fno-inline -fno-builtin -fno-omit-frame-pointer  -pg -O2  -shared -fPIC s-lib.c   
build command for executable: gcc -o t-lib s-libmain.c    -Wl,-rpath,$ORIGIN -L. -labc_test_lib
uftrace: /root/uftrace/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6ec765f
test command: ../uftrace --no-pager -L.. replay -d xxx -F lib_b@libabc_test
=========== expected =============
 lib_b() {
   lib_c();
 } /* lib_b */
=========== original =============
# DURATION    TID     FUNCTION

=========== result =============

076 lib_replay_F    : NG

[namhyung]

@iamwonseok sorry for late reply.

Hmm.. nothing seems wrong. I don't know why it could not find a symbol from the address. Could you please re-run uftrace record (after runtest.py above) and show me the output of sid-XXX.map file in the data directory? You will need to add --force option like below:

$ cd tests
$ ./runtest.py -pO2 076
076 lib_replay_F    : NG

$ uftrace record --force  t-lib
$ cat uftrace.data/*.map

[iamwonseok]

@namhyung It is fine. It was Lunar's New Year holiday season.

Anyway, I am attaching log as below:

root@kesl:~/uftrace/tests# ./runtest.py -pO2 076
Test case             pg
--------------------: O2
uftrace: /root/uftrace/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6f3b65f
076 lib_replay_F    : NG

root@kesl:~/uftrace/tests# uftrace record --force  t-lib
uftrace: /root/uftrace/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6ebc65f

root@kesl:~/uftrace/tests# cat uftrace.data/*.map
00008000-00009000 r-xp 00000000 b3:19 24520      /root/uftrace/tests/t-lib
00010000-00011000 r--p 00000000 b3:19 24520      /root/uftrace/tests/t-lib
00011000-00012000 rw-p 00001000 b3:19 24520      /root/uftrace/tests/t-lib
00012000-00033000 rw-p 00000000 00:00 0          [heap]
b6c4e000-b6c51000 rw-p 00000000 00:00 0 
b6c51000-b6c6a000 r-xp 00000000 b3:19 176842     /lib/arm-linux-gnueabihf/libgcc_s.so.1
b6c6a000-b6c71000 ---p 00019000 b3:19 176842     /lib/arm-linux-gnueabihf/libgcc_s.so.1
b6c71000-b6c72000 rw-p 00018000 b3:19 176842     /lib/arm-linux-gnueabihf/libgcc_s.so.1
b6c72000-b6cd5000 r-xp 00000000 b3:19 176850     /lib/arm-linux-gnueabihf/libm-2.19.so
b6cd5000-b6cdc000 ---p 00063000 b3:19 176850     /lib/arm-linux-gnueabihf/libm-2.19.so
b6cdc000-b6cdd000 r--p 00062000 b3:19 176850     /lib/arm-linux-gnueabihf/libm-2.19.so
b6cdd000-b6cde000 rw-p 00063000 b3:19 176850     /lib/arm-linux-gnueabihf/libm-2.19.so
b6cde000-b6cee000 r-xp 00000000 b3:19 176877     /lib/arm-linux-gnueabihf/libpthread-2.19.so
b6cee000-b6cf5000 ---p 00010000 b3:19 176877     /lib/arm-linux-gnueabihf/libpthread-2.19.so
b6cf5000-b6cf6000 r--p 0000f000 b3:19 176877     /lib/arm-linux-gnueabihf/libpthread-2.19.so
b6cf6000-b6cf7000 rw-p 00010000 b3:19 176877     /lib/arm-linux-gnueabihf/libpthread-2.19.so
b6cf7000-b6cf9000 rw-p 00000000 00:00 0 
b6cf9000-b6d91000 r-xp 00000000 b3:19 123292     /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
b6d91000-b6d98000 ---p 00098000 b3:19 123292     /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
b6d98000-b6d9c000 r--p 00097000 b3:19 123292     /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
b6d9c000-b6d9e000 rw-p 0009b000 b3:19 123292     /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
b6d9e000-b6da4000 rw-p 00000000 00:00 0 
b6da4000-b6da6000 r-xp 00000000 b3:19 176838     /lib/arm-linux-gnueabihf/libdl-2.19.so
b6da6000-b6dad000 ---p 00002000 b3:19 176838     /lib/arm-linux-gnueabihf/libdl-2.19.so
b6dad000-b6dae000 r--p 00001000 b3:19 176838     /lib/arm-linux-gnueabihf/libdl-2.19.so
b6dae000-b6daf000 rw-p 00002000 b3:19 176838     /lib/arm-linux-gnueabihf/libdl-2.19.so
b6daf000-b6db4000 r-xp 00000000 b3:19 176880     /lib/arm-linux-gnueabihf/librt-2.19.so
b6db4000-b6dbb000 ---p 00005000 b3:19 176880     /lib/arm-linux-gnueabihf/librt-2.19.so
b6dbb000-b6dbc000 r--p 00004000 b3:19 176880     /lib/arm-linux-gnueabihf/librt-2.19.so
b6dbc000-b6dbd000 rw-p 00005000 b3:19 176880     /lib/arm-linux-gnueabihf/librt-2.19.so
b6dbd000-b6dcb000 r-xp 00000000 b3:19 123236     /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
b6dcb000-b6dd3000 ---p 0000e000 b3:19 123236     /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
b6dd3000-b6dd4000 r--p 0000e000 b3:19 123236     /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
b6dd4000-b6dd5000 rw-p 0000f000 b3:19 123236     /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
b6dd5000-b6eaf000 r-xp 00000000 b3:19 176829     /lib/arm-linux-gnueabihf/libc-2.19.so
b6eaf000-b6eb6000 ---p 000da000 b3:19 176829     /lib/arm-linux-gnueabihf/libc-2.19.so
b6eb6000-b6eb8000 r--p 000d9000 b3:19 176829     /lib/arm-linux-gnueabihf/libc-2.19.so
b6eb8000-b6eb9000 rw-p 000db000 b3:19 176829     /lib/arm-linux-gnueabihf/libc-2.19.so
b6eb9000-b6ebc000 rw-p 00000000 00:00 0 
b6ebc000-b6ebd000 r-xp 00000000 b3:19 24519      /root/uftrace/tests/libabc_test_lib.so
b6ebd000-b6ec4000 ---p 00001000 b3:19 24519      /root/uftrace/tests/libabc_test_lib.so
b6ec4000-b6ec5000 r--p 00000000 b3:19 24519      /root/uftrace/tests/libabc_test_lib.so
b6ec5000-b6ec6000 rw-p 00001000 b3:19 24519      /root/uftrace/tests/libabc_test_lib.so
b6ec6000-b6ed3000 r-xp 00000000 b3:19 132187     /usr/local/lib/libmcount-fast.so
b6ed3000-b6edb000 ---p 0000d000 b3:19 132187     /usr/local/lib/libmcount-fast.so
b6edb000-b6edc000 r--p 0000d000 b3:19 132187     /usr/local/lib/libmcount-fast.so
b6edc000-b6edd000 rw-p 0000e000 b3:19 132187     /usr/local/lib/libmcount-fast.so
b6edd000-b6ee0000 rw-p 00000000 00:00 0 
b6ee0000-b6ef7000 r-xp 00000000 b3:19 176819     /lib/arm-linux-gnueabihf/ld-2.19.so
b6ef7000-b6ef8000 rw-p 00000000 00:00 0 
b6efa000-b6eff000 rw-p 00000000 00:00 0 
b6eff000-b6f00000 r--p 00017000 b3:19 176819     /lib/arm-linux-gnueabihf/ld-2.19.so
b6f00000-b6f01000 rw-p 00018000 b3:19 176819     /lib/arm-linux-gnueabihf/ld-2.19.so
bee9c000-beebd000 rwxp 00000000 00:00 0          [stack]
befc4000-befc5000 r-xp 00000000 00:00 0          [sigpage]
befc5000-befc6000 r--p 00000000 00:00 0          [vvar]
befc6000-befc7000 r-xp 00000000 00:00 0          [vdso]
ffff0000-ffff1000 r-xp 00000000 00:00 0          [vectors]
root@kesl:~/uftrace/tests# 

[namhyung]

Thanks.

So the address 0xb6ebc65f was in the code segment of /root/uftrace/tests/libabc_test_lib.so. Looks ok.

Could you please show the symbol table of the libabc_test_lib.so like below?

$ readelf -s libabc_test_lib.so | grep FUNC

[iamwonseok]

Here is the symbol table of libabc_test_lib.so:

root@kesl:~/uftrace/tests# readelf -s libabc_test_lib.so | grep FUNC
     3: 00000000     0 FUNC    GLOBAL DEFAULT  UND raise@GLIBC_2.4 (2)
     4: 00000000     0 FUNC    WEAK   DEFAULT  UND __cxa_finalize@GLIBC_2.4 (2)
     7: 00000000     0 FUNC    GLOBAL DEFAULT  UND getpid@GLIBC_2.4 (2)
     9: 00000000     0 FUNC    GLOBAL DEFAULT  UND __gnu_mcount_nc@GLIBC_2.8 (3)
    11: 00000655    20 FUNC    GLOBAL DEFAULT   11 lib_a
    16: 00000641    20 FUNC    GLOBAL DEFAULT   11 lib_b
    18: 000004b8     0 FUNC    GLOBAL DEFAULT    9 _init
    19: 00000625    26 FUNC    GLOBAL DEFAULT   11 lib_c
    21: 00000924     0 FUNC    GLOBAL DEFAULT   12 _fini
    25: 00000530     0 FUNC    LOCAL  DEFAULT   11 call_weak_fn
    35: 00000555     0 FUNC    LOCAL  DEFAULT   11 deregister_tm_clones
    38: 00000585     0 FUNC    LOCAL  DEFAULT   11 register_tm_clones
    42: 000005bd     0 FUNC    LOCAL  DEFAULT   11 __do_global_dtors_aux
    48: 000005fd     0 FUNC    LOCAL  DEFAULT   11 frame_dummy
    67: 000008fd    26 FUNC    LOCAL  DEFAULT   11 __aeabi_idivmod
    68: 00000919    12 FUNC    LOCAL  DEFAULT   11 __aeabi_ldiv0
    70: 00000669   660 FUNC    LOCAL  DEFAULT   11 __divsi3
    71: 00000919    12 FUNC    LOCAL  DEFAULT   11 __aeabi_idiv0
    75: 00000669     0 FUNC    LOCAL  DEFAULT   11 __aeabi_idiv
    79: 00000000     0 FUNC    GLOBAL DEFAULT  UND raise@@GLIBC_2.4
    80: 00000655    20 FUNC    GLOBAL DEFAULT   11 lib_a
    81: 00000625    26 FUNC    GLOBAL DEFAULT   11 lib_c
    82: 00000000     0 FUNC    WEAK   DEFAULT  UND __cxa_finalize@@GLIBC_2.4
    87: 00000924     0 FUNC    GLOBAL DEFAULT   12 _fini
    90: 00000000     0 FUNC    GLOBAL DEFAULT  UND getpid@@GLIBC_2.4
    91: 00000641    20 FUNC    GLOBAL DEFAULT   11 lib_b
    96: 00000000     0 FUNC    GLOBAL DEFAULT  UND __gnu_mcount_nc@@GLIBC_2.
    98: 000004b8     0 FUNC    GLOBAL DEFAULT    9 _init
root@kesl:~/uftrace/tests#

[namhyung]

Thanks. I think it's a problem of handling binaries built with thumb mode. I only tested arm mode, sorry.

I'll investigate the thumb code handling and let you know if there's a progress. Thanks!

[namhyung]

I pushed some debugging code into debug/56 branch. Could you please check it out and re-run the record command above with -v option?

[iamwonseok]

Sure. Here is the log on my machine.

root@kesl:~/uftrace-debug56/tests# ./runtest.py -pO2 076                                                                                                                                
Test case             pg
--------------------: O2
uftrace: /root/uftrace-debug56/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6f5565f
076 lib_replay_F    : NG

root@kesl:~/uftrace-debug56/tests# uftrace record -v --force t-lib
uftrace: removing uftrace.data.old directory
uftrace: creating 1 thread(s) for recording
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
mcount: map: 8000-9000 /root/uftrace-debug56/tests/t-lib
mcount: map: b6c5c000-b6c75000 /lib/arm-linux-gnueabihf/libgcc_s.so.1
mcount: map: b6c7d000-b6ce0000 /lib/arm-linux-gnueabihf/libm-2.19.so
mcount: map: b6ce9000-b6cf9000 /lib/arm-linux-gnueabihf/libpthread-2.19.so
mcount: map: b6d04000-b6d9c000 /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
mcount: map: b6daf000-b6db1000 /lib/arm-linux-gnueabihf/libdl-2.19.so
mcount: map: b6dba000-b6dbf000 /lib/arm-linux-gnueabihf/librt-2.19.so
mcount: map: b6dc8000-b6dd6000 /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
mcount: map: b6de0000-b6eba000 /lib/arm-linux-gnueabihf/libc-2.19.so
mcount: map: b6ec7000-b6ec8000 /root/uftrace-debug56/tests/libabc_test_lib.so
mcount: map: b6ed1000-b6ee1000 /usr/local/lib/libmcount.so
mcount: map: b6eed000-b6f04000 /lib/arm-linux-gnueabihf/ld-2.19.so
mcount: map: be843000-be864000 [stack]
mcount: map: beb51000-beb52000 [sigpage]
mcount: map: beb53000-beb54000 [vdso]
mcount: map: ffff0000-ffff1000 [vectors]
mcount: mcount setup done
uftrace: /root/uftrace-debug56/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6ec765f
mcount: shmem_finish: tid: 2546 seqnum = 0 curr = 0, nr_buf = 2 max_buf = 2
uftrace: child terminated with exit code: 1
uftrace: reading uftrace.data/task.txt file
symbol: loading symbols from t-lib
symbol: symtab found 4 symbols

[namhyung]

@iamwonseok Thank you for doing this!

Strangely, it seems not loading the symbol table from the library in find_symtabs(). I pushed one more commit to debug this onto the debug/56 branch. Could you please re-run it one more?

[iamwonseok]

As a result, the log messages from symbol: Add more debug messages and symbol: Debugging map symbol loading are the same. It seems that ./runtest.py -pO2 076 and uftrace record -v --force t-lib do not reach the function find_symtabs()
Anyway, I am attached the log from the newestdebug/56 branch.

root@kesl:~/uftrace-debug56-p1/tests# ./runtest.py -vp -O2 076
Test case             pg
--------------------: O2
build command for library: gcc -o libabc_test_lib.so -fno-inline -fno-builtin -fno-omit-frame-pointer  -pg -O2  -shared -fPIC s-lib.c   
build command for executable: gcc -o t-lib -fno-inline -fno-builtin -fno-omit-frame-pointer    s-libmain.c    -Wl,-rpath,$ORIGIN -L.  -labc_test_lib
uftrace: /root/uftrace-debug56-p1/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6f1965f
test command: ../uftrace --no-pager -L.. replay -d xxx -F lib_b@libabc_test
=========== expected =============
 lib_b() {
   lib_c();
 } /* lib_b */
=========== original =============
[0] 0xb6f19625: lib_c (26)
[1] 0xb6f19641: lib_b (20)
[2] 0xb6f19655: lib_a (20)
[3] 0xb6f19669: __divsi3 (660)
[4] 0xb6f198fd: __aeabi_idivmod (26)
[5] 0xb6f19919: __aeabi_idiv0 (12)
# DURATION    TID     FUNCTION

=========== result =============
[0] 0xb6f19625: lib_c (26)
[1] 0xb6f19641: lib_b (20)
[2] 0xb6f19655: lib_a (20)
[3] 0xb6f19669: __divsi3 (660)
[4] 0xb6f198fd: __aeabi_idivmod (26)
[5] 0xb6f19919: __aeabi_idiv0 (12)
076 lib_replay_F    : NG

root@kesl:~/uftrace-debug56-p1/tests# uftrace record -v --force t-lib
uftrace: removing uftrace.data.old directory
uftrace: creating 1 thread(s) for recording
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
mcount: map: 8000-9000 /root/uftrace-debug56-p1/tests/t-lib
mcount: map: b6d22000-b6d3b000 /lib/arm-linux-gnueabihf/libgcc_s.so.1
mcount: map: b6d43000-b6da6000 /lib/arm-linux-gnueabihf/libm-2.19.so
mcount: map: b6daf000-b6dbf000 /lib/arm-linux-gnueabihf/libpthread-2.19.so
mcount: map: b6dca000-b6e62000 /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
mcount: map: b6e75000-b6e77000 /lib/arm-linux-gnueabihf/libdl-2.19.so
mcount: map: b6e80000-b6e85000 /lib/arm-linux-gnueabihf/librt-2.19.so
mcount: map: b6e8e000-b6e9c000 /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
mcount: map: b6ea6000-b6f80000 /lib/arm-linux-gnueabihf/libc-2.19.so
mcount: map: b6f8d000-b6f8e000 /root/uftrace-debug56-p1/tests/libabc_test_lib.so
mcount: map: b6f97000-b6fa7000 /usr/local/lib/libmcount.so
mcount: map: b6fb3000-b6fca000 /lib/arm-linux-gnueabihf/ld-2.19.so
mcount: map: bec15000-bec36000 [stack]
mcount: map: bee44000-bee45000 [sigpage]
mcount: map: bee46000-bee47000 [vdso]
mcount: map: ffff0000-ffff1000 [vectors]
mcount: mcount setup done
uftrace: /root/uftrace-debug56-p1/arch/arm/mcount-support.c:263:mcount_arch_parent_location
 ERROR: cannot find symbol for b6f8d65f
mcount: shmem_finish: tid: 2879 seqnum = 0 curr = 0, nr_buf = 2 max_buf = 2
uftrace: child terminated with exit code: 1
uftrace: reading uftrace.data/task.txt file
symbol: loading symbols from t-lib
symbol: symtab found 4 symbols

[namhyung]

It seems that ./runtest.py -pO2 076 and uftrace record -v --force t-lib do not reach the function find_symtabs()

That's not possible since the error message comes from find_symtabs returning NULL. Now I think that it's a bug of is_kernel_address() to consider the address was from kernel. I pushed again a new code to verify it onto the debug/56 branch. It'd be nice if you could do it again, sorry..

[iamwonseok]

When I apply the patch, there is no cannot find symbol() error during ./runtest.py -pO2 076, but the result is still NG. Does it mean that results are different between real output and test case?

Here is the log message with '8834235 symbol: Fix kernel address check' patch.

root@kesl:~/uftrace-debug56-p2/tests# ./runtest.py -vp -O2 076
Test case             pg
--------------------: O2
build command for library: gcc -o libabc_test_lib.so -fno-inline -fno-builtin -fno-omit-frame-pointer  -pg -O2  -shared -fPIC s-lib.c   
build command for executable: gcc -o t-lib -fno-inline -fno-builtin -fno-omit-frame-pointer    s-libmain.c    -Wl,-rpath,$ORIGIN -L.  -labc_test_lib
[0] 0xb6f01625: lib_c (26)
[1] 0xb6f01641: lib_b (20)
[2] 0xb6f01655: lib_a (20)
[3] 0xb6f01669: __divsi3 (660)
[4] 0xb6f018fd: __aeabi_idivmod (26)
[5] 0xb6f01919: __aeabi_idiv0 (12)
test command: ../uftrace --no-pager -L.. replay -d xxx -F lib_b@libabc_test
=========== expected =============
 lib_b() {
   lib_c();
 } /* lib_b */
=========== original =============
[0] 0xb6f01625: lib_c (26)
[1] 0xb6f01641: lib_b (20)
[2] 0xb6f01655: lib_a (20)
[3] 0xb6f01669: __divsi3 (660)
[4] 0xb6f018fd: __aeabi_idivmod (26)
[5] 0xb6f01919: __aeabi_idiv0 (12)
# DURATION    TID     FUNCTION
            [ 2466] | lib_b() {
   5.400 us [ 2466] |   lib_c();
  16.500 us [ 2466] | } /* lib_b */

=========== result =============
[0] 0xb6f01625: lib_c (26)
[1] 0xb6f01641: lib_b (20)
[2] 0xb6f01655: lib_a (20)
[3] 0xb6f01669: __divsi3 (660)
[4] 0xb6f018fd: __aeabi_idivmod (26)
[5] 0xb6f01919: __aeabi_idiv0 (12)
 lib_b() {
   lib_c();
 } /* lib_b */
076 lib_replay_F    : NG

root@kesl:~/uftrace-debug56-p2/tests# uftrace record -v --force t-lib
uftrace: creating 1 thread(s) for recording
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
mcount: map: 8000-9000 /root/uftrace-debug56-p2/tests/t-lib
mcount: map: b6d24000-b6d3d000 /lib/arm-linux-gnueabihf/libgcc_s.so.1
mcount: map: b6d45000-b6da8000 /lib/arm-linux-gnueabihf/libm-2.19.so
mcount: map: b6db1000-b6dc1000 /lib/arm-linux-gnueabihf/libpthread-2.19.so
mcount: map: b6dcc000-b6e64000 /usr/lib/arm-linux-gnueabihf/libstdc++.so.6.0.19
mcount: map: b6e77000-b6e79000 /lib/arm-linux-gnueabihf/libdl-2.19.so
mcount: map: b6e82000-b6e87000 /lib/arm-linux-gnueabihf/librt-2.19.so
mcount: map: b6e90000-b6e9e000 /usr/lib/arm-linux-gnueabihf/libelf-0.158.so
mcount: map: b6ea8000-b6f82000 /lib/arm-linux-gnueabihf/libc-2.19.so
mcount: map: b6f8f000-b6f90000 /root/uftrace-debug56-p2/tests/libabc_test_lib.so
mcount: map: b6f99000-b6fa9000 /usr/local/lib/libmcount.so
mcount: map: b6fb5000-b6fcc000 /lib/arm-linux-gnueabihf/ld-2.19.so
mcount: map: be8ef000-be910000 [stack]
mcount: map: becea000-beceb000 [sigpage]
mcount: map: becec000-beced000 [vdso]
mcount: map: ffff0000-ffff1000 [vectors]
mcount: mcount setup done
symbol: couldn't find symbol from address: b6f8f65f
symbol: found a map: /root/uftrace-debug56-p2/tests/libabc_test_lib.so (0 symbols)
symbol: loading symbols from /root/uftrace-debug56-p2/tests/libabc_test_lib.so
symbol: symtab found 7 symbols
symbol: symtab has 6 symbols finally
[0] 0xb6f8f625: lib_c (26)
[1] 0xb6f8f641: lib_b (20)
[2] 0xb6f8f655: lib_a (20)
[3] 0xb6f8f669: __divsi3 (660)
[4] 0xb6f8f8fd: __aeabi_idivmod (26)
[5] 0xb6f8f919: __aeabi_idiv0 (12)
symbol: couldn't find symbol from address: b6f8f64b
symbol: found a map: /root/uftrace-debug56-p2/tests/libabc_test_lib.so (6 symbols)
symbol: couldn't find symbol from address: b6f8f62f
symbol: found a map: /root/uftrace-debug56-p2/tests/libabc_test_lib.so (6 symbols)
mcount: shmem_finish: tid: 2473 seqnum = 0 curr = 0, nr_buf = 2 max_buf = 2
uftrace: child terminated with exit code: 0
uftrace: reading uftrace.data/task.txt file
symbol: loading symbols from t-lib
symbol: symtab found 4 symbols

Well, I'd like to submit a patch, but I need to learn more how the uftace works. I'd be very happy if my feedback helps to improve this project. So, you do not need to sorry for asking.

[namhyung]

The test failed because of debug messages. Once you removed the first and second commit, it'll succeed I guess. But the real solution would be somewhat complicated since it should know the boundary between user and kernel address space.

On my raspberry PI machine, it was 2G-2G split so old code worked without problems. But on your machine, it's splitted as 3G-1G. So you need to figure out how the address space is organized and set a correct kernel base address before using symbol tables. In my third patch, it just assumed 3G-1G split so used 0xC0000000 but the real base address might be different depending on configurations.

I think it only affects 32-bit machines (so only ARM boards currently) since 64-bit address space is so huge and fixed. You need add it both in mcount_startup() and open_data_file() IMHO.

[namhyung]

@iamwonseok any progress on this?

[iamwonseok]

I am trying to figure out how the address space of linux is organized as you mentioned. I found a few ways to get how the kernel memory are splitted (VMSPLIT 3G-1G or 2G-2G) from user mode. One is using dmesg and the other is using /proc/kallsyms. As you know, getting a kernel start address, both of approaches need parsing the message.

By the way, I think the /proc/kallsyms is the better than dmesg, because dmesg can be lost kernel start address due to limited size of buffer and parsing overhead is smaller. The bug can be fixed using /proc/kallsyms IMHO.

How do you think about my opinion? If you agree with my opinion, I want to added some code (e.g. read, parse and get the kernel start address).

[namhyung]

I generally agree with you but reading /proc/kallsyms might fail since /proc/sys/kernel/kptr_restrict can hide actual address. I don't know how to find kernel start address from dmesg though.

As a fallback, you might check /proc/self/maps and guess the start address above "[stack]". The stack address is usually below the limit of address space with some random offset.

[iamwonseok]

I mean the kernel bootup log contains kernel memory layout information. If the information remains buffer of dmesg, we can get the kernel start address. I'm attaching my log with different PAGE_OFFSET. I think we can guess the kernel start address from lowmem or .text and those information is a default kernel log on ARM Architecture(32-bit and 64-bit). PATH: arch/arm(or arm64)/mm/init.c, function name: void __init mem_init(void)

case VMSPLIT_3G:

Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xe7800000 - 0xff000000   ( 376 MB)
    lowmem  : 0xc0000000 - 0xe7000000   ( 624 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0xc0008000 - 0xc081505c   (8245 kB)
      .init : 0xc0816000 - 0xc0896000   ( 512 kB)
      .data : 0xc0896000 - 0xc0908388   ( 457 kB)
       .bss : 0xc090b000 - 0xc0944de4   ( 232 kB)

case VMSPLIT_2G:

Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xc0800000 - 0xff000000   (1000 MB)
    lowmem  : 0x80000000 - 0xc0000000   (1024 MB)
    pkmap   : 0x7fe00000 - 0x80000000   (   2 MB)
    modules : 0x7f000000 - 0x7fe00000   (  14 MB)
      .text : 0x80008000 - 0x8081c06c   (8273 kB)
      .init : 0x8081d000 - 0x8089c000   ( 508 kB)
      .data : 0x8089c000 - 0x8090e388   ( 457 kB)
       .bss : 0x80911000 - 0x8094ade4   ( 232 kB)

However, this approach can be lost this information by queueing other messages to kernel log buffer. So I mentioned that /proc/kallsyms/ is better than dmesg.

Anyway, I checked out and understood how the kernel start address guesses from /proc/self/maps. I got the result as below through some tests on my machine with three VMSPLIT option such as 1G-3G, 2G-2G and 3G-1G. As a result, we can guess the kernel start address at 0xC000_0000 when the return value of stack is greater than 0xbxxx_xxxx. While the return value of stack is greater than 0x7xxx_xxxx or 0x4xxx_xxxx, we also guess the kernel start address at 0x8000_0000 or 0x4000_0000. How do you think about this kind of decision to get the kernel start address?

As your recommendation, I wrote simple test code for guessing the kernel start address and am attaching them as below:

#include <stdio.h>
#include <string.h>
#include <stdlib.h>

void get_kernel_start_addr(char *str)
{
    char *pch;
    unsigned int addr;

    pch = strtok (str,"-");
    addr = strtoul(pch, NULL, 16);

    if (addr < 0x40000000) {
        printf("PAGE_OFFSET is at 0x4000_0000\n");
    } else if (addr < 0x80000000) {
        printf("PAGE_OFFSET is at 0x8000_0000\n");
    } else {
        printf("PAGE_OFFSET is at 0xC000_0000\n");
    }   
}

int main(void)
{
    FILE *fp;
    char line[200];

    fp = popen("cat /proc/self/maps", "r");
    if (fp == NULL) {
        printf("we assume that PAGE_OFFSET is at 0xC000_0000 in this case\n");
    } else {
        while (fgets(line, sizeof(line), fp) != NULL) {
            if (strstr(line, "stack") != NULL) {
                get_kernel_start_addr(line);
                break;
            }   
        }   
        pclose(fp);
    }   
    return 0;
}

I think this approach is reasonable. If your opinion is the the same as me, could I write a patch for this bug?

[namhyung]

I think you'd be better checking "[stack" since some library might have "stack" in its name. Note that I omitted the closing bracket intentionally. Beside that, I'm ok with your approach.

But it seems there's another option for VMSPLIT. As far as I can see it from arch/arm/Kconfig file in the kernel source, it has 4 options like below (please see PAGE_OFFSET below):

choice
        prompt "Memory split"
        depends on MMU
        default VMSPLIT_3G

help
          Select the desired split between kernel and user memory.

          If you are not absolutely sure what you are doing, leave this
          option alone!

        config VMSPLIT_3G
                bool "3G/1G user/kernel split"
        config VMSPLIT_3G_OPT
                bool "3G/1G user/kernel split (for full 1G low memory)"
        config VMSPLIT_2G
                bool "2G/2G user/kernel split"
        config VMSPLIT_1G
                bool "1G/3G user/kernel split"
endchoice

config PAGE_OFFSET
        hex
        default PHYS_OFFSET if !MMU
        default 0x40000000 if VMSPLIT_1G
        default 0x80000000 if VMSPLIT_2G
        default 0xB0000000 if VMSPLIT_3G_OPT
        default 0xC0000000

[iamwonseok]

To fix the problem, we just need a setting proper kernel start address into KADDR_START when is_kernel_address() is called. The idea looks very simple. However, KADDR_START is defined as a macro and is_kernel_address() is defined static inline function. So, is_kernel_address() need to be modified, IMHO. I pushed work-in-progress version into debug/56 in my repository https://github.com/iamwonseok/uftrace. It can trace function for each configuration.

Could you please see the debug/56 in my repository and give me feedback, @namhyung ?

debug/56 in my repo: log on my machine for each VMSPLIT_*.

$ ./runtest.py -vp -O2 076
Test case             pg  
--------------------: O2
build command for library: gcc -o libabc_test_lib.so -fno-inline -fno-builtin -fno-omit-frame-pointer  -pg -O2  -shared -fPIC s-lib.c   
build command for executable: gcc -o t-lib -fno-inline -fno-builtin -fno-omit-frame-pointer    s-libmain.c    -Wl,-rpath,$ORIGIN -L.  -labc_test_lib
[0] 0x36f59625: lib_c (26)
[1] 0x36f59641: lib_b (20)
[2] 0x36f59655: lib_a (20)
[3] 0x36f59669: __divsi3 (660)
[4] 0x36f598fd: __aeabi_idivmod (26)
[5] 0x36f59919: __aeabi_idiv0 (12)
test command: ../uftrace --no-pager -L.. replay -d xxx -F lib_b@libabc_test
=========== expected =============
 lib_b() {
   lib_c();
 } /* lib_b */
=========== original =============
[0] 0x36f59625: lib_c (26)
[1] 0x36f59641: lib_b (20)
[2] 0x36f59655: lib_a (20)
[3] 0x36f59669: __divsi3 (660)
[4] 0x36f598fd: __aeabi_idivmod (26)
[5] 0x36f59919: __aeabi_idiv0 (12)
# DURATION    TID     FUNCTION
            [ 6477] | lib_b() {
  17.100 us [ 6477] |   lib_c();
  29.795 ms [ 6477] | } /* lib_b */

uftrace stopped tracing with remaining functions
================================================
task: 6480
[0] exit

task: 6482
[0] exit

task: 6484
[0] exit


=========== result =============
[0] 0x36f59625: lib_c (26)
[1] 0x36f59641: lib_b (20)
[2] 0x36f59655: lib_a (20)
[3] 0x36f59669: __divsi3 (660)
[4] 0x36f598fd: __aeabi_idivmod (26)
[5] 0x36f59919: __aeabi_idiv0 (12)
 lib_b() {
   lib_c();
 } /* lib_b */
uftrace stopped tracing with remaining functions
================================================
task: 6480
[0] exit
task: 6482
[0] exit
task: 6484
[0] exit
076 lib_replay_F    : NG

debug/56 in main repo: log on my machine for each VMSPLIT_*.

$ ./runtest.py -vp -O2 076                                                                                                                     
Test case             pg                                                                                                                     
--------------------: O2                                                                                                                     
build command for library: gcc -o libabc_test_lib.so -fno-inline -fno-builtin -fno-omit-frame-pointer  -pg -O2  -shared -fPIC s-lib.c        
build command for executable: gcc -o t-lib -fno-inline -fno-builtin -fno-omit-frame-pointer    s-libmain.c    -Wl,-rpath,$ORIGIN -L.  -labc_test_lib
test command: ../uftrace --no-pager -L.. replay -d xxx -F lib_b@libabc_test                                                                  
=========== expected =============
 lib_b() {            
   lib_c();
 } /* lib_b */
=========== original =============
# DURATION    TID     FUNCTION                                                                                                               

=========== result =============

076 lib_replay_F    : NG

[namhyung]

@iamwonseok thanks for doing that. It'd be easier for me if you could send a PR though.

It seems you call get_kaddr() everytime, but I think we can do it just once and use the value instead. Also you need to read map file in the data directory rather than current proc. Note that record and replay can be run on different machines.