[Bug runtime/10427] New: Multiple tracepoint OKs!

[Bug runtime/10427] New: Multiple tracepoint OKs!

[mjw at redhat dot com]

On a rawhide install (2.6.31-0.81.rc3.git4.fc12.x86_64) the
testsuite/systemtap.base/tracepoints.stp sometimes produces multiple triggers of
the following probe:

probe all_tracepoints!, begin {
    println("tracepoints OK")
    exit()
}

But only with clean caches.

$ rm -rf ~/.systemtap && stap -v testsuite/systemtap.base/tracepoints.stp

Pass 1: parsed user script and 58 library script(s) in 90usr/10sys/110real ms.
Pass 2: analyzed script: 60 probe(s), 2 function(s), 0 embed(s), 1 global(s) in
6600usr/8570sys/14727real ms.
Pass 3: translated to C into
"/tmp/stapTj3U43/stap_6a431ab5b96059ed64495d90c1c45405_20000.c" in
10usr/0sys/11real ms.
Pass 4: compiled C into "stap_6a431ab5b96059ed64495d90c1c45405_20000.ko" in
4530usr/1600sys/6163real ms.
Pass 5: starting run.
tracepoints OK
tracepoints OK
tracepoints OK
Pass 5: run completed in 30usr/60sys/124real ms.

With the cache in place, it never seems to trigger multiple times afterwards. It
also doesn't trigger multiple times ever on fedora 11 (2.6.29.6-213.fc11.x86_64).

-- 
           Summary: Multiple tracepoint OKs!
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: mjw at redhat dot com
                CC: jistone at redhat dot com


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

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

[Bug runtime/10427] Multiple tracepoint OKs!

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-07-22 12:47 -------
Actually, I just saw this also happen while using the cache. So that isn't the
differentiator. In fact with the same module from the cache it seems to give
different results from time to time:

[mark@rawhide64 testsuite]$ stap -v
~/src/systemtap/testsuite/systemtap.base/tracepoints.stp
Pass 1: parsed user script and 58 library script(s) in 130usr/50sys/500real ms.
Pass 2: analyzed script: 60 probe(s), 2 function(s), 0 embed(s), 1 global(s) in
340usr/600sys/1527real ms.
Pass 3: using cached
/home/mark/.systemtap/cache/6a/stap_6a431ab5b96059ed64495d90c1c45405_20000.c
Pass 4: using cached
/home/mark/.systemtap/cache/6a/stap_6a431ab5b96059ed64495d90c1c45405_20000.ko
Pass 5: starting run.
tracepoints OK
tracepoints OK
tracepoints OK
tracepoints OK
Pass 5: run completed in 10usr/60sys/103real ms.
[mark@rawhide64 testsuite]$ stap -v
~/src/systemtap/testsuite/systemtap.base/tracepoints.stp
Pass 1: parsed user script and 58 library script(s) in 100usr/20sys/119real ms.
Pass 2: analyzed script: 60 probe(s), 2 function(s), 0 embed(s), 1 global(s) in
370usr/540sys/1095real ms.
Pass 3: using cached
/home/mark/.systemtap/cache/6a/stap_6a431ab5b96059ed64495d90c1c45405_20000.c
Pass 4: using cached
/home/mark/.systemtap/cache/6a/stap_6a431ab5b96059ed64495d90c1c45405_20000.ko
Pass 5: starting run.
tracepoints OK
Pass 5: run completed in 10usr/80sys/119real ms.

-- 


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

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

[Bug runtime/10427] Multiple tracepoint OKs!

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-07-22 12:56 -------
O, I think I see what happens. Probably while we are doing the probe, printing
the message and calling exit() some other tracepoint is hit, hits is already >
100 and so the probe gets triggered again. So this is probably just a testsuite
bug. Although a slightly confusing one.

-- 


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

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

[Bug runtime/10427] Multiple tracepoint OKs!

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-07-22 13:01 -------
commit d51df7d73716deb8fc99877a37a3043a70cf613e
Author: Mark Wielaard <mjw@redhat.com>
Date:   Wed Jul 22 14:59:54 2009 +0200

    PR10427 Multiple tracepoints OK!
    
    * testsuite/systemtap.base/tracepoints.stp: Only print once, when enough hit
      or at the begin probe.


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


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

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

[Bug runtime/10427] Multiple tracepoint OKs!

[jistone at redhat dot com]

------- Additional Comments From jistone at redhat dot com  2009-07-22 18:04 -------
(In reply to comment #2)
> O, I think I see what happens. Probably while we are doing the probe, printing
> the message and calling exit() some other tracepoint is hit, hits is already >
> 100 and so the probe gets triggered again. So this is probably just a testsuite
> bug. Although a slightly confusing one.

Yeah, there's an exit race condition.  The probe flow looks something like this:

1. If session_state != RUNNING, skip the probe
2. Lock the hits global
3. Increment hits
4. If hits >= 100, call exit() (which sets session_state = STOPPING)
5. Unlock hits

So 2-5 are atomic, but there is a chance that other cpus could have gotten past
#1 before exit() is called.

Reversing #1 and #2 would solve the race for this particular script, but
generally probe handlers may not have any mutual locks.  That's why we don't
make any guarantees that exit() will force any in-flight probes to skip.

Your fix looks fine.

-- 


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

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