Clang X-ray dynamic tracing support #88

namhyung · 2017-04-21T02:42:36Z

Clang/LLVM 4.0 provides a dynamic tracing feature called X-ray. It's similar to gcc -mfentry -mnop-mcount but it also supports the exit path (like -finstrument-functions). In the end, it's more powerful and safe, but generates more bloated code - and it seems that the xray library is linked statically to the executable.

I pushed the code into review/xray-support-v1 branch. Anyone can play with the clang 4, please test! The usage is same as the dynamic patch (-P option):

$ clang -fxray-instrument -fxray-instruction-threshold=1 -o abc-xray  tests/s-abc.c

$ uftrace -P main abc-xray
# DURATION    TID     FUNCTION
            [11093] | main() {
   1.659 us [11093] |   getpid();
   5.963 us [11093] | } /* main */

The text was updated successfully, but these errors were encountered:

Taeung · 2017-04-21T08:20:19Z

Hi @namhyung 😄

I tested this new feature with uftrace built by gcc-5.4.0.
This feature works fine when testing Clang X-ray dynamic tracing as you tested.
(excluding the warning messages "warning: ignoring return value .." I told you on recent code review)

However,
I found segmentation fault with uftrace built by gcc-7.0.1.
Isn't it needed to care gcc-7.0.1 just yet ?

I tested on the below environment.

$ cd git/uftrace

$ git status | head -1
On branch review/xray-support-v1

$ gcc -dumpversion
7.0.1

$ sudo make clean && sudo make install

$ clang --version
clang version 4.0.0-svn297204-1~exp1 (branches/release_40)
Target: x86_64-unknown-linux-gnu
Thread model: posix
InstalledDir: /usr/bin

And I tested Clang X-ray dynamic tracing like below.

$ clang -fxray-instrument -fxray-instruction-threshold=1 -o abc-xray tests/s-abc.c

$ objdump -d abc-xray
...
0000000000423100 <main>:
  423100:       eb 09                   jmp    42310b <main+0xb>
  423102:       66 0f 1f 84 00 00 02    nopw   0x200(%rax,%rax,1)
  423109:       00 00 
  42310b:       55                      push   %rbp
  42310c:       48 89 e5                mov    %rsp,%rbp
  42310f:       48 83 ec 20             sub    $0x20,%rsp
  423113:       c7 45 fc 00 00 00 00    movl   $0x0,-0x4(%rbp)
  42311a:       89 7d f8                mov    %edi,-0x8(%rbp)
  42311d:       48 89 75 f0             mov    %rsi,-0x10(%rbp)
  423121:       c7 45 ec 00 00 00 00    movl   $0x0,-0x14(%rbp)
  423128:       83 7d f8 01             cmpl   $0x1,-0x8(%rbp)
  42312c:       0f 8e 10 00 00 00       jle    423142 <main+0x42>
  423132:       48 8b 45 f0             mov    -0x10(%rbp),%rax
  423136:       48 8b 78 08             mov    0x8(%rax),%rdi
  42313a:       e8 71 e9 fd ff          callq  401ab0 <atoi@plt>
  42313f:       89 45 ec                mov    %eax,-0x14(%rbp)
  423142:       e8 39 00 00 00          callq  423180 <a>
  423147:       b9 01 00 00 00          mov    $0x1,%ecx
  42314c:       31 d2                   xor    %edx,%edx
  42314e:       03 45 ec                add    -0x14(%rbp),%eax
  423151:       89 45 ec                mov    %eax,-0x14(%rbp)
  423154:       83 7d ec 00             cmpl   $0x0,-0x14(%rbp)
  423158:       0f 45 ca                cmovne %edx,%ecx
  42315b:       89 c8                   mov    %ecx,%eax
  42315d:       48 83 c4 20             add    $0x20,%rsp
  423161:       5d                      pop    %rbp
  423162:       c3                      retq   
  423163:       2e 66 0f 1f 84 00 00    nopw   %cs:0x200(%rax,%rax,1)
  42316a:       02 00 00 
  42316d:       0f 1f 00                nopl   (%rax)
  423170:       df a0 42 00 00 00       fbld   0x42(%rax)
  423176:       00 00                   add    %al,(%rax)
  423178:       0f 1f 84 00 00 00 00    nopl   0x0(%rax,%rax,1)
  42317f:       00 
...

$ uftrace -P main abc-xray 
WARN: invalid task file
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION

So I checked it by gdb with core file like below.
gdb tell me that seg fault occurs at libmcount/plthook.c:429

$ gdb abc-xray core
...
Reading symbols from abc-xray...(no debugging symbols found)...done.
[New LWP 14972]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `abc-xray'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f8b01a57022 in plthook_entry (ret_addr=0x7ffc712b17f8, child_idx=53, 
    module_id=140235009253736, regs=0x7ffc712b17b8)
    at /home/taeung/git/uftrace/libmcount/plthook.c:429
429		struct ftrace_trigger tr = {
(gdb) bt
#0  0x00007f8b01a57022 in plthook_entry (ret_addr=0x7ffc712b17f8, child_idx=53, 
    module_id=140235009253736, regs=0x7ffc712b17b8)
    at /home/taeung/git/uftrace/libmcount/plthook.c:429
#1  0x00007f8b01a61cfa in plt_hooker () from /usr/local/lib/libmcount.so
#2  0x0000000000401e89 in _start ()

The same problem occurs when testing just dynamic tracing with uftrace built by gcc-7.0.1.
The result from core file is same.

$ gcc -o t-abc -pg -mfentry -mnop-mcount tests/s-abc.c 

$ uftrace -P main t-abc
WARN: invalid task file
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION

namhyung · 2017-04-21T14:40:28Z

Thank you very much for testing this. I have two questions:

Does it crash dynamic tracing only? Or normal tracing is also broken?
Is it a problem of PLT hook code? IOW, --no-libcall is ok?

Taeung · 2017-04-23T00:52:16Z

It seems about just gcc 7..

I tested with uftrace built by gcc 7 like below.

Yes, normal tracing is also broken.

$ uftrace abc
WARN: invalid task file
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION

Okey but dynamic tracing is not ok.

case A) normal tracing [OK]

uftrace --no-libcall abc
# DURATION    TID     FUNCTION
            [ 4037] | main() {
            [ 4037] |   a() {
            [ 4037] |     b() {
   0.633 us [ 4037] |       c();
   1.960 us [ 4037] |     } /* b */
   2.197 us [ 4037] |   } /* a */
   2.582 us [ 4037] | } /* main */

case B) dynamic tracing [NG]

$ uftrace --no-libcall -P main abc.dyn
WARN: invalid task file
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION

Sorry, it seems better to make this problem new issue about gcc 7.
Because this problem is about not only xray / dynamic tracing but also normal tracing..

Taeung · 2017-04-23T01:38:34Z

And @namhyung I found the warning message about warning: ignoring return value
, when building uftrace by gcc 5.4.1.
So I commented here 😄

namhyung · 2017-04-25T07:01:06Z

Pushed review/xray-support-v2.

namhyung · 2017-04-26T01:39:06Z

Forgot to fix the warnings, pushed review/xray-support-v3 again. Thanks!

Taeung · 2017-04-26T05:25:53Z

Hi @namhyung ,

uftrace built by gcc 5 or gcc 6 work fine on xray-test you mentioned.

However, I found the similar segfault (at libmcount/mcount.c:714) on xray-test, again.
(The code is contained in e87574b)

gcc : 7.0.1
clang : 4.2.1
git-branch : review/xray-support-v3

xray-test environment

$ git pull upstream review/xray-support-v3
From https://github.com/namhyung/uftrace
 * branch            review/xray-support-v3 -> FETCH_HEAD
Already up-to-date.

$ git status | head -1
On branch review/xray-support-v3

$ gcc -dumpversion
7.0.1

$ sudo make clean && sudo make install

$ date && ll uftrace /usr/local/lib/libmcount*
Wed Apr 26 13:54:54 KST 2017
-rwxr-xr-x 1 root root  489048 2017-04-26 13:55:41 /usr/local/lib/libmcount-fast-single.so*
-rwxr-xr-x 1 root root  490424 2017-04-26 13:55:41 /usr/local/lib/libmcount-fast.so*
-rwxr-xr-x 1 root root    8192 2017-04-26 13:55:41 /usr/local/lib/libmcount-nop.so*
-rwxr-xr-x 1 root root  500416 2017-04-26 13:55:41 /usr/local/lib/libmcount-single.so*
-rwxr-xr-x 1 root root  501448 2017-04-26 13:55:41 /usr/local/lib/libmcount.so*
-rwxr-xr-x 1 root root 1314744 2017-04-26 13:55:33 uftrace*

Build target program abc-xray built by clang 4

$ clang -dumpversion
4.2.1

$ clang -fxray-instrument -fxray-instruction-threshold=1 -o abc-xray tests/s-abc.c

Segmentation fault on xray-test

$ uftrace -P main abc-xray 
child terminated by signal: 11: Segmentation fault
# DURATION    TID     FUNCTION

If checking it with gdb and core file, you can see the segfault at libmcount/mcount.c:714

$ gdb abc-xray core
...
Reading symbols from abc-xray...(no debugging symbols found)...done.
[New LWP 4986]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `abc-xray'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007fdf15b48802 in xray_entry (parent=140721932945512, child=4337925, 
    regs=0x7ffc60d34830) at /home/taeung/git/uftrace/libmcount/mcount.c:714
714		struct ftrace_trigger tr = {

namhyung · 2017-04-26T05:52:34Z

Thanks a lot for testing! Could you please test below again?

diff --git a/arch/x86_64/xray.S b/arch/x86_64/xray.S
index de58da3..261e54b 100644
--- a/arch/x86_64/xray.S
+++ b/arch/x86_64/xray.S
@@ -7,44 +7,41 @@
 .type __xray_entry, @function
 __xray_entry:
        .cfi_startproc
-       sub $56, %rsp
-       .cfi_adjust_cfa_offset 56
+       sub $48, %rsp
+       .cfi_adjust_cfa_offset 48
 
-       movq %rdi, 48(%rsp)
+       movq %rdi, 40(%rsp)
        .cfi_offset rdi, -24
-       movq %rsi, 40(%rsp)
+       movq %rsi, 32(%rsp)
        .cfi_offset rsi, -32
-       movq %rdx, 32(%rsp)
+       movq %rdx, 24(%rsp)
        .cfi_offset rdx, -40
-       movq %rcx, 24(%rsp)
+       movq %rcx, 16(%rsp)
        .cfi_offset rcx, -48
-       movq %r8, 16(%rsp)
+       movq %r8, 8(%rsp)
        .cfi_offset r8, -56
-       movq %r9, 8(%rsp)
+       movq %r9, 0(%rsp)
        .cfi_offset r9, -64
-       movq %rax, 0(%rsp)
-       .cfi_offset rax, -72
 
        /* child ip */
-       movq 56(%rsp), %rsi
+       movq 48(%rsp), %rsi
        /* parent ip */
-       lea 64(%rsp), %rdi
+       lea 56(%rsp), %rdi
 
        /* mcount_args */
-       lea 8(%rsp), %rdx
+       movq %rsp, %rdx
 
        call xray_entry
 
-       movq 0(%rsp), %rax
-       movq 8(%rsp), %r9
-       movq 16(%rsp), %r8
-       movq 24(%rsp), %rcx
-       movq 32(%rsp), %rdx
-       movq 40(%rsp), %rsi
-       movq 48(%rsp), %rdi
-
-       add $56, %rsp
-       .cfi_adjust_cfa_offset -56
+       movq 0(%rsp), %r9
+       movq 8(%rsp), %r8
+       movq 16(%rsp), %rcx
+       movq 24(%rsp), %rdx
+       movq 32(%rsp), %rsi
+       movq 40(%rsp), %rdi
+
+       add $48, %rsp
+       .cfi_adjust_cfa_offset -48
 
        retq
        .cfi_endproc

Taeung · 2017-04-26T05:55:29Z

Okey, I'll tell you the result of your patch ! 😄

Taeung · 2017-04-26T06:29:21Z

Fine ! the segfault is gone, @namhyung

Taeung · 2017-04-26T06:33:52Z

But I found the similar segfault on original dynamic tracing.
So I added new issue !

namhyung · 2017-04-26T06:37:04Z

Yep, I think there's a problem too. Even -mfentry (not dynamic) option will crash due to the same problem IMHO.

namhyung · 2017-04-26T08:07:06Z

Pushed review/xray-support-v4 with the fix and a testcase.

Taeung · 2017-04-26T09:33:40Z

@namhyung I checked new test case of 90f95a16

I thought the case that testers use old clang (e.g. clang 3.8 that can't support xray).
Sure, this test script can show BI (Build failed).

But how about using sys.stderr or Popen() to tell tester correct build error messages such as:

Case 1) Using sys.stderr when building test cases:

diff --git a/tests/runtest.py b/tests/runtest.py
index f8e0522..13a3d85 100755
--- a/tests/runtest.py
+++ b/tests/runtest.py
@@ -59,7 +59,7 @@ class TestBase:
 
         self.pr_debug("build command: %s" % build_cmd)
         try:
-            if sp.call(build_cmd.split(), stdout=sp.PIPE, stderr=sp.PIPE) != 0:
+            if sp.call(build_cmd.split(), stdout=sp.PIPE, stderr=sys.stderr) != 0:
                 return TestBase.TEST_BUILD_FAIL
             return TestBase.TEST_SUCCESS
         except:

Then, we can see build error like below without -v option:

$ ./runtest.py xray
Test case                 pg             finstrument-fu
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'
140 dynamic_xray        : BI BI BI BI BI BI BI BI BI BI

Or,

Case 2) Using Popen() instead of subprocess.call() to show build error message:

diff --git a/tests/runtest.py b/tests/runtest.py
index f8e0522..e1645ac 100755
--- a/tests/runtest.py
+++ b/tests/runtest.py
@@ -59,7 +59,10 @@ class TestBase:
 
         self.pr_debug("build command: %s" % build_cmd)
         try:
-            if sp.call(build_cmd.split(), stdout=sp.PIPE, stderr=sp.PIPE) != 0:
+            p = sp.Popen(build_cmd.split(), stdout=sp.PIPE, stderr=sp.PIPE)
+            sp.stdout, sp.stderr = p.communicate()
+            if p.returncode != 0:
+                self.pr_debug(sp.stderr)
                 return TestBase.TEST_BUILD_FAIL
             return TestBase.TEST_SUCCESS
         except:

Then, we can see the error message only with -v option

./runtest.py -v xray
Test case                 pg             finstrument-fu
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os
build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

build command: clang -o t-abc -fno-inline -fno-builtin -fno-omit-frame-pointer  -fxray-instrument -fxray-instruction-threshold=1  s-abc.c   
clang: error: unknown argument: '-fxray-instrument'
clang: error: unknown argument: '-fxray-instruction-threshold=1'

140 dynamic_xray        : BI BI BI BI BI BI BI BI BI BI

What do you think about this change ?

namhyung · 2017-04-27T00:17:38Z

I like the option 2. Can I add it as a separate commit with your sign-off?

Taeung · 2017-04-27T00:25:18Z

Sure, you can do that 😄

namhyung · 2017-04-27T00:43:41Z

Merged: 04991ed

honggyukim · 2017-04-27T03:59:54Z

I didn't catch up x-ray support for a while but thanks very much for this work!

namhyung added the review label Apr 21, 2017

namhyung closed this as completed Apr 27, 2017

Taeung mentioned this issue May 1, 2017

doc: Add examples for X-ray dynamic tracing to live and record man pages #94

Merged

jeonghwanin mentioned this issue Aug 30, 2023

Error Building uftrace on Raspberry Pi 4B Board : Bad Instructions in aarch64 #1818

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Clang X-ray dynamic tracing support #88

Clang X-ray dynamic tracing support #88

namhyung commented Apr 21, 2017

Taeung commented Apr 21, 2017

namhyung commented Apr 21, 2017

Taeung commented Apr 23, 2017

Taeung commented Apr 23, 2017

namhyung commented Apr 25, 2017

namhyung commented Apr 26, 2017

Taeung commented Apr 26, 2017 •

edited

Loading

namhyung commented Apr 26, 2017

Taeung commented Apr 26, 2017

Taeung commented Apr 26, 2017

Taeung commented Apr 26, 2017

namhyung commented Apr 26, 2017

namhyung commented Apr 26, 2017

Taeung commented Apr 26, 2017

namhyung commented Apr 27, 2017

Taeung commented Apr 27, 2017

namhyung commented Apr 27, 2017

honggyukim commented Apr 27, 2017

Clang X-ray dynamic tracing support #88

Clang X-ray dynamic tracing support #88

Comments

namhyung commented Apr 21, 2017

Taeung commented Apr 21, 2017

namhyung commented Apr 21, 2017

Taeung commented Apr 23, 2017

Taeung commented Apr 23, 2017

namhyung commented Apr 25, 2017

namhyung commented Apr 26, 2017

Taeung commented Apr 26, 2017 • edited Loading

namhyung commented Apr 26, 2017

Taeung commented Apr 26, 2017

Taeung commented Apr 26, 2017

Taeung commented Apr 26, 2017

namhyung commented Apr 26, 2017

namhyung commented Apr 26, 2017

Taeung commented Apr 26, 2017

namhyung commented Apr 27, 2017

Taeung commented Apr 27, 2017

namhyung commented Apr 27, 2017

honggyukim commented Apr 27, 2017

Taeung commented Apr 26, 2017 •

edited

Loading