403132 - DTrace function probes are double-counting invocations

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Myk Melez [:myk] [@mykmelez]]

The js_calltime.d DTrace script in the DTrace Toolkit reports twice as many invocations of functions as are actually taking place, and the following script shows twice as many function entries/exits:

dtrace -Z -n 'javascript*:::function-entry,javascript*:::function-return { @[probename, copyinstr(arg2)] = count(); } END { printa(" %-16s %-32s %@8d\n", @); }'

I confirmed the problem by adding a dump statement to a function and counting the number of times the message in the statement appeared on the console.  It appeared half as many times as DTrace says the function was invoked.

I noticed this on Mac OS X, but bgregg said on IRC that he thinks this isn't platform specific and that "the probe macros in jsinterp.c may need to be juggled (again)".

Comment 1

[Robert Sayre]

It's not a problem with the placement in jsinterp.c.

I checked this by calling printf whenever we called function-entry/function-exit. The probe is only getting called once, but showing up twice in dtrace.

Comment 2

[Robert Sayre]

Attachment: probes showing up twice

Comment 3

[Robert Sayre]

OK, that's just the *enabled macros. 

Comment 4

[Andrew Sutherland [:asuth] (he/him)]

Short story: It looks like there is a bug in the Apple linker involving its DTrace logic and -dead_strip.  If you rebuild libmozjs.dylib without "-Wl,-dead_strip", you should be golden.

Longer story:

I wrote a limited DOF parser (DTrace Object Format) and ran it against libmozjs.dylib.  As built by default (with -dead_strip), each probe offset or probe enable offset has twice as many entries as it 'should' show up.  (The offsets referenced by the dof_probe are sometimes duplicated outright, but may also be different.  However, I haven't 'pierced' that offset semantically, so the differing offsets may still be equivalent.)  'Should' in this case is compared against the baseline of linking without dead_strip...

There are two distinct code paths that detect the magic ___dtrace* symbols in the linker, depending on whether dead-strip is enabled.  I haven't learned enough about the linker logic to posit an actual cause with confidence, though I have suspicions that are probably wrong and so I won't mention them.


Possible solution:

A delightful Makefile hack that interposes a filter-out command to remove the dead_strip command, predicated on having dtrace probes enabled.  We could also fix Apple's linker or figure out how to structure things so as to not trigger the problem.  Those seem like more work, though.  We could also add a post-processing pass that corrects the resulting problems in the DOF, but that seems more evil than the Makefile solution.

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

Attachment: filter-out dead_strip argument to LD for OS X with DTrace enabled

The aforementioned 'possible solution'.  Since the -dead_strip comes from configure and the problem case is only when DTrace is involved, it doesn't make sense to do any global disabling of -dead_strip (at a configure level).  Having configure detect the -dead_strip problem seems wildly non-trivial, leaving some other centralization of logic in rules.mk as the most obvious candidate for a better solution.  But the Makefile.in in question already is explicitly aware of the DTrace stuff going on, so I'm going to argue this is a reasonable fix for now.

My DOF reader code (python) is here: http://hg.mozilla.org/users/bugmail_asutherland.org/dofread/

Comment 6

[(not currently active) Ted Mielczarek]

Ugh. Can we detect the bug in gcc by version number or something? I'd be much happier with a configure test.

Comment 7

[Andrew Sutherland [:asuth] (he/him)]

The configure test is easy.  For now, all versions of the linker (not gcc) that are capable of doing the DTrace magic should have the bug, which means OS X 10.5.*.  The issue is that I assume we don't want to turn off dead_strip for libraries that don't have DTrace probes, so the ideal configure solution would presumably also involve changes to rules.mk to only disable dead_strip when DTrace is involved.  This would likely entail refactoring much of the DTrace logic in js/src/Makefile.in into rules.mk.

Does that sound like a viable solution (configure detects the problem, have rules.mk moot the flag when appropriate), or did you have something else in mind?

Comment 8

[Robert Sayre]

Maybe we should skip -dead_strip when building with DTrace. That's not such a big deal. I want to add other probes, in libxul. Anyone know of an Apple bug on this?

Comment 9

[(not currently active) Ted Mielczarek]

That works for me.

Comment 10

[Robert Sayre]

Attachment: disable -dead_strip in configure

not sure if this is the right way to do it, but it seems to work

Comment 11

[(not currently active) Ted Mielczarek]

Comment on attachment 324264 [details] [diff] [review]
disable -dead_strip in configure

There's already an --enable-dtrace, maybe you missed it because it's AC_ARG_ENABLE (I have no idea why, probably some Sun guy's patch). Otherwise I basically approve of this patch.

Comment 12

[Robert Sayre]

turns out my first patch doesn't link libxul. I fixed that, and I'm using the test from above. as soon as I get my mbp to wake up, I'll have a final patch.

Comment 13

[(not currently active) Ted Mielczarek]

Comment on attachment 321461 [details] [diff] [review]
filter-out dead_strip argument to LD for OS X with DTrace enabled

Waiting on sayrer's patch.

Comment 14

[Robert Sayre]

Comment on attachment 301945 [details]
probes showing up twice

this is actually fine, it's in the object files that problem lies.

Comment 15

[Robert Sayre]

Attachment: final

Comment 16

[Brendan Gregg]

Thanks and great work for finding a fix!