[Bug runtime/15669] New: syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[Bug runtime/15669] New: syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[agentzh at gmail dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=15669

            Bug ID: 15669
           Summary: syscall probe handlers are called exactly twice for
                    every syscall on Amazon Linux
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: agentzh at gmail dot com

For every syscall on Amazon Linux (kernel 3.2.39-6.88.amzn1.x86_64 ), the
syscall.* probe handlers are always called exactly twice.

From the dmesg output, it seems that Amazon Linux is running by Xen:

    $ dmesg|grep Xen
    [    0.000000]  Xen: 0000000000000000 - 00000000000a0000 (usable)
    [    0.000000]  Xen: 00000000000a0000 - 0000000000100000 (reserved)
    [    0.000000]  Xen: 0000000000100000 - 0000000446400000 (usable)
    [    0.000000] Booting paravirtualized kernel on Xen
    [    0.000000] Xen version: 3.4.3.amazon (preserve-AD)
    [    0.000000] Xen: using vcpuop timer interface
    [    0.000000] installing Xen timer for CPU 0
    [    0.044854] installing Xen timer for CPU 1
    [    0.068736] PCI: setting up Xen PCI frontend stub
    [    0.324525] Initialising Xen virtual ethernet driver.

utrace is enabled in the kernel:

    $ grep CONFIG_UTRACE /boot/config-`uname -r`
    CONFIG_UTRACE=y

systemtap is using a recent git master (commit 56098c7902 ).

Some more information about the system:

    $ cat /etc/issue
    Amazon Linux AMI release 2013.03
    Kernel \r on an \m

Any suggestions on tracking this issue further. Sorry if this is not the right
place to report an issue related to a kernel maintained by Amazon.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/15669] syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[agentzh at gmail dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=15669

--- Comment #1 from agentzh <agentzh at gmail dot com> ---
Created attachment 7090
  --> http://sourceware.org/bugzilla/attachment.cgi?id=7090&action=edit
The output of stap-report on Amazon Linux

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/15669] syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[agentzh at gmail dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=15669

--- Comment #2 from agentzh <agentzh at gmail dot com> ---
Some test cases in systemtap's existing test suite can demonstrate this bug.
For example, the systemtap.base/at_var.exp is failing due to duplicate syscall
probe handler runs:

  Running ./systemtap.base/at_var.exp ...
  Executing on host: gcc ./systemtap.base/at_var.c  -O2 -g  -lm   -o at_var   
(timeout = 300)                                   
  spawn -ignore SIGHUP gcc ./systemtap.base/at_var.c -O2 -g -lm -o at_var^M
  executing: stap ./systemtap.base/at_var.stp -c ./at_var
  FAIL: at_var
  line 11: expected "user_int(&$foo->bar): 40"
  Got "$utimes$$: {.tv_sec=1, .tv_usec=2}"     
      "$utimes[1]$$: {.tv_sec=3, .tv_usec=4}"
      "@var("utimes")$$: {.tv_sec=1, .tv_usec=2}"
      "@var("utimes")[1]$$: {.tv_sec=3, .tv_usec=4}"
      "user_int(&$foo->bar): 40"     
      "user_int(&@var("foo")->bar): 40"     
      "&@cast($foo->bar, "struct foo")->bar: 42"
      "&@cast(@var("foo")->bar, "struct foo")->bar: 42"
      "$foo->bar == @entry($foo->bar): true"
      "@var("foo")->bar == @entry(@var("foo")->bar): true"
  testcase ./systemtap.base/at_var.exp completed in 8 seconds

Also, also for cast-user:

  Running ./systemtap.base/cast-user.exp ...
  Executing on host: gcc ./systemtap.base/cast-user.c  -g  -lm   -o
/home/ec2-user/git/systemtap2/testsuite/cast-user.exe    (timeout = 300)
  spawn -ignore SIGHUP gcc ./systemtap.base/cast-user.c -g -lm -o
/home/ec2-user/git/systemtap2/testsuite/cast-user.exe^M
  PASS: cast-user compile
  executing: stap ./systemtap.base/cast-user.stp
/home/ec2-user/git/systemtap2/testsuite/cast-user.exe -c
/home/ec2-user/git/systemtap2/testsuite/cast-user.exe
  FAIL: cast-user
  line 5: expected ""
  Got "binary sa_family OK"
      "binary sa_data OK"
      "header sa_family OK"
      "header sa_data OK"
  testcase ./systemtap.base/cast-user.exp completed in 4 seconds

We can see that the outputs in the syscall probe handlers are duplicated for
exactly once.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/15669] syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[fche at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=15669

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |WAITING
                 CC|                            |fche at redhat dot com

--- Comment #3 from Frank Ch. Eigler <fche at redhat dot com> ---
This could happen if for some reason the tapset is partially duplicated in the
install tree.  See "stap --vp 3 ..." to see which stp files are processed.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/15669] syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[jistone at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=15669

Josh Stone <jistone at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jistone at redhat dot com

--- Comment #4 from Josh Stone <jistone at redhat dot com> ---
(In reply to Frank Ch. Eigler from comment #3)
> This could happen if for some reason the tapset is partially duplicated in
> the install tree.

This can especially happen if you install on top of a prior release.  The file
syscalls.stp used to be in tapset/, then release-2.0 moved it to tapset/linux/.
 So if you have the old file, it won't be overwritten, but duplicated.

There are also runtime files that were relocated the same way.  Please make
sure that you try with a completely clean install.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/15669] syscall probe handlers are called exactly twice for every syscall on Amazon Linux

[agentzh at gmail dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=15669

agentzh <agentzh at gmail dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|WAITING                     |RESOLVED
         Resolution|---                         |FIXED

--- Comment #5 from agentzh <agentzh at gmail dot com> ---
it is indeed the issue of loading duplicate tapset files in the installation
directory. stap -vvv confirms that. I've already tested a clean installation of
systemtap in Amazon Linux on EC2. the related tests are all passing now! :D

Thank you for your help!

-- 
You are receiving this mail because:
You are the assignee for the bug.