Bug #2551

jstack may deal in stale ustack helper frames

Added by Rich Lowe about 2 years ago. Updated about 2 years ago.

Status:Resolved Start date:2012-03-28
Priority:High Due date:
Assignee:Rich Lowe % Done:

100%

Category:DTrace Spent time: -
Target version:-
Difficulty:Medium Tags:

Description

While debugging a couple of issues in the dtrace test suite I've happened upon a bug where ustack helper data may be passed to consumers despite being stale.

This tends to manifest itself as helper frames in inappropriate stacks (completely).

A bit of D such as:

syscall:::entry { 
    @[jstack()] = count(); 
} 

tick-5s { 
    exit(0); 
}

Will produce output like this:

...
              libc.so.1`syscall+0x5
              libc.so.1`thr_sigsetmask+0x1c2
              libc.so.1`sigprocmask+0x52
              sshd`collect_children+0x2a
              sshd`server_loop2+0x195
              sshd`do_authenticated2+0xc
              sshd`do_authenticated+0x31
              sshd`main+0x14c4
                [ /usr/lib/python2.6/threading.py:256 (wait) ]
              sshd`_start+0x83
              126
...

Which is clearly bogus.

What's happening is that the string buffer used for helper annotations is not cleared in the DTrace buffer, such that subsequent stack invocations, if they are as deep as, or deeper than, a prior annotated stack, will acquire the annotations erroneously.

In this case the actual stack that should have the annotations is

              libc.so.1`__pollsys+0x7
              libc.so.1`pselect+0x1bf
              libc.so.1`select+0x8e
              time.so`floatsleep+0xd8
              time.so`time_sleep+0x4a
              libpython2.6.so.1.0`PyCFunction_Call+0x19d
              libpython2.6.so.1.0`call_function+0x3e6
              libpython2.6.so.1.0`PyEval_EvalFrameEx+0x2cdb
                [ /usr/lib/python2.6/threading.py:256 (wait) ]
              libpython2.6.so.1.0`PyEval_EvalCodeEx+0x8cb
              libpython2.6.so.1.0`fast_function+0x174
              libpython2.6.so.1.0`call_function+0xe4
              libpython2.6.so.1.0`PyEval_EvalFrameEx+0x2cdb
                [ /usr/lib/python2.6/Queue.py:177 (get) ]
...

Note that the (wait) annotation is in the 8th frame in both cases, this pattern repeats throughout the entire output.

You can narrow it in time by aggregating on timestamp as well as jstack(), which happens to cause an ordering in time which shows that the bogus entries always postdate a valid stack with helped frames at matching depths.

We need to clear any string space in the DTrace buffer if we process a jstack() or ustack() action and we have string space but no helpers.

History

Updated by Rich Lowe about 2 years ago

  • Subject changed from jstack may deal in stale ustack helpers to jstack may deal in stale ustack helper frames

Updated by Rich Lowe about 2 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 0 to 100
  • Tags deleted (needs-triage)

Resolved in r13666 ab986bc53f59

Also available in: Atom PDF