588537 - Generate ETW events from js engine for xperf etc.

Status: RESOLVED FIXED

(Core :: JavaScript Engine, enhancement)

Description

[Steve Fink [:sfink] [:s:]]

Forked off of bug 584175.

Generate manifest-based ETW events for tracing various aspects of the JS engine: execution start/stop, compiles, GC events, object&string allocation/finalization, etc.

Warning: these events have security implications (consumers see URLs etc.) I think it should be ok because this is using its own channel, and the channel is marked as type "Analytic" so it should be restricted to Admin. But it will need review.

Comment 1

[Steve Fink [:sfink] [:s:]]

Attachment: Manifest describing ETW events to produce

This is my current manifest. It includes everything MS Research is interested in, plus the probes we had previously.

Comment 2

[Steve Fink [:sfink] [:s:]]

Attachment: Total hack to set WINVER so that the event symbols get defined

Setting WINVER globally to a higher value seemed to cause problems.

This setting should be ok even on older versions of Windows as long as the Windows 7 SDK is being used.

Obviously, this is not the right way to set this. I'm posting it for comment.

Comment 3

[Steve Fink [:sfink] [:s:]]

Attachment: Add the ETW support to the build

Another piece I need help with. This patch:

* Adds an --enable-ETW flag for compiling in the ETW event provider code on. ETW is relatively expensive even when disabled (unlike eg dtrace), so we definitely don't want it to default on in its current form. Arguably you could split off some cheap events and unconditionally enable them, but not for now.

* Builds jsprobes.cpp unconditionally. This really should have been part of bug 584175. But it only matters once you have a second user after dtrace.

* Adds calls to mc and rc to build ETWProvider.* artifacts. I just threw them in; there's probably a more principled way to go about it. I know little about Windows build stuff (or our build system, for that matter.)

Comment 4

[Steve Fink [:sfink] [:s:]]

Attachment: Inject probes all over the place

This patch defines a bunch of new probes (the stuff that will be used for announcing ETW events) with empty bodies, and then instruments lots of JS code to call them. The empty bodies ought to be easy to optimize away, so I didn't do any preprocessor games to make them invisible. (The arguments passed in are all simple, so I *think* that they should be free as well.)

I probably should have put this patch earlier in the series.

This is the patch that could probably use the most eyeballs.

Comment 5

[Steve Fink [:sfink] [:s:]]

Attachment: Implement the ETW event writers

Actually send out the events.

Note that even with the patch applied and --enable-ETW, this still won't send anything out. You have to enable the event provider before it'll do anything but slow down your program.

Comment 6

[Steve Fink [:sfink] [:s:]]

Attachment: Register the ETW provider

Last patch. Register the event provider.

Note that events will *still* not be sent out unless there's a consumer out there asking for them. I've been using logman, but xperf is the "right" tool for it.

I need help with this patch, too. I don't know where the right place is to put this code. I just stuck it in here to get some results out.

Comment 7

[Steve Fink [:sfink] [:s:]]

Background info:

  http://msdn.microsoft.com/en-us/magazine/cc163437.aspx
  http://msdn.microsoft.com/en-us/library/aa363668%28VS.85%29.aspx

Comment 8

[Steve Fink [:sfink] [:s:]]

Attachment: Add a couple of JS utility commands

This patch adds, badly, two commands that were useful in using the ETW functionality in production: customMark and forceGC. I stuck them onto Object, which is probably the worst of all places but it was what I could figure out quickly. It seems like they ought to be either on the global object, or perhaps customMark should be on some Probes object or something. Advice appreciated.

Comment 9

[Steve Fink [:sfink] [:s:]]

Attachment: ETW event manifest

Trivial update to remove paths from the manifest. It's not going to automatically work either way, so may as well prune out nonexistent paths.

Comment 10

[Steve Fink [:sfink] [:s:]]

Attachment: Part 2: add --enable-ETW option, along with build commands

This adds ETW (Event Tracing for Windows) to the build. This patch requires the manifest earlier in this bug. No actual calls to ETW happen at runtime yet; I wanted to separate out the build portion for review.

In particular, I'm unsure about the WINVER piece. At least 0x600 is necessary in order for this to compile, because the event functions won't be defined (from <evntprov.h>) without it. But there must have been some reason for the particular settings in there just above it.

Comment 11

[Steve Fink [:sfink] [:s:]]

Attachment: Part 3: insert probes throughout js tree

This is actually independent of ETW; any Probes:: implementation could make use of these.

Comment 12

[Steve Fink [:sfink] [:s:]]

Attachment: Part 1: ETW (Event Tracing for Windows) manifest

Re-uploading purely to change the title.

Comment 13

[Steve Fink [:sfink] [:s:]]

Attachment: Part 4: Implement ETW probe points

gal: Not sure if you're the right person to review this. Let me know if not.

Implement ETW (Event Tracing for Windows) probes.

Unfortunately, this mixes in a signature change to the probes (from returning
void to returning bool). I'm still not sure whether it's a good idea.

Also, this patch adds some more windows.h pollution removal (since this patch would otherwise break the compile of js/src/methodjit/PolyIC.cpp).

This also adds Probes::pauseProfilers and Probes::resumeProfilers to pause/resume whatever profilers happen to be compiled in. (They all still have their own idiosyncratic ways to start and stop; this is only for suspending and resuming.)

Comment 14

[Steve Fink [:sfink] [:s:]]

Attachment: Part 5: Register the ETW provider (turn the ETW probes on)

Comment 15

[Andreas Gal :gal]

Comment on attachment 473210 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

I think you want ted for this review.

Comment 16

[Andreas Gal :gal]

Comment on attachment 473240 [details] [diff] [review]
Part 1: ETW (Event Tracing for Windows) manifest

NPOTB. No approval needed.

Comment 17

[Andreas Gal :gal]

Comment on attachment 473241 [details] [diff] [review]
Part 4: Implement ETW probe points

NPOTB. No approval needed. I don't much like pauseProfilers/resumeProfilers but I have no better suggestion. Maybe Brendan does? The rest looks great.

Comment 18

[Andreas Gal :gal]

Comment on attachment 473243 [details] [diff] [review]
Part 5: Register the ETW provider (turn the ETW probes on)

Trivial change. No approval needed here, just land it on TM.

Comment 19

[Steve Fink [:sfink] [:s:]]

Comment on attachment 473213 [details] [diff] [review]
Part 3: insert probes throughout js tree

I missed the r? on this one. You've already seen this code.

Comment 20

[Benjamin Smedberg]

Comment on attachment 473210 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

Use $(RC) since it exists already.

And use mc.exe instead of mc, for pymake happiness.

In configure.in, please explain that ETW == Event Tracing for Windows.

r=me with those changes

Comment 21

[Steve Fink [:sfink] [:s:]]

Attachment: Part 2: add --enable-ETW option, along with build commands

Updated with review changes.

Sorry for bothering you again with a review request, but since you pointed me toward $(RC) it felt bad to be using a naked mc.exe in Makefile.in, so I added $(MC) alongside $(RC). That was enough of a change that I didn't want to assume r=bsmedberg carried over.

Comment 22

[Steve Fink [:sfink] [:s:]]

Comment on attachment 475648 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

Got the email wrong. See previous comment. Thanks!

Comment 23

[Benjamin Smedberg]

Comment on attachment 475648 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

I don't see any

AC_SUBST(MC) in configure.in
or MC = @MC@ in autoconf.mk.in

I think you need it, and put them next to the equivalent RC lines.

Comment 24

[Rain [:rain1] (inactive)]

A couple of drive-by comments about the build system patch:
1. It makes sense to error out if the SDK is too old in configure.in itself. Just ensure that MOZ_WINSDK_TARGETVER is >= 0x06010000.
2. We have historically avoided bumping up WINVER globally, to reduce the chance that a build doesn't work on an older version of Windows. To be as close to a default build as possible, can you only bump up WINVER in the files where you need access to the newer stuff?

Comment 25

[Steve Fink [:sfink] [:s:]]

(In reply to comment #24)
> A couple of drive-by comments about the build system patch:
> 1. It makes sense to error out if the SDK is too old in configure.in itself.
> Just ensure that MOZ_WINSDK_TARGETVER is >= 0x06010000.

Makes sense, thanks.

> 2. We have historically avoided bumping up WINVER globally, to reduce the
> chance that a build doesn't work on an older version of Windows. To be as close
> to a default build as possible, can you only bump up WINVER in the files where
> you need access to the newer stuff?

I saw breakage when I bumped it up at the toplevel configure.in, which is why I limited it to js/src/configure.in. I'm not sure what the best way is to set WINVER at a finer granularity:

Obviously, I could just set it directly in the relevant file, but then we'd end up downgrading WINVER once the Windows 2035 SDK is released. So I could conditionally set it in those files if it isn't already at least that high. But because the relevant code ends up in headers (intentionally, to minimize overhead by allowing inlining), it already infects 42 out of the 92 entries in .deps/. So the gain isn't all that much anyway. (It pollutes this much because jsobjinlines.h has a probe in the NewObject template.)

Comment 26

[Rain [:rain1] (inactive)]

(In reply to comment #25)
> I saw breakage when I bumped it up at the toplevel configure.in, which is why I
> limited it to js/src/configure.in. I'm not sure what the best way is to set
> WINVER at a finer granularity:
> 
> Obviously, I could just set it directly in the relevant file, but then we'd end
> up downgrading WINVER once the Windows 2035 SDK is released.

Sure, but we already do it in a bunch of places anyway, so anyone bumping it up globally would have to check for it anyway.

> conditionally set it in those files if it isn't already at least that high. But
> because the relevant code ends up in headers (intentionally, to minimize
> overhead by allowing inlining), it already infects 42 out of the 92 entries in
> .deps/. So the gain isn't all that much anyway. (It pollutes this much because
> jsobjinlines.h has a probe in the NewObject template.)

Hm, if the changes are so far-reaching then I guess it makes sense to have it in js's configure.in.

Comment 27

[Steve Fink [:sfink] [:s:]]

Attachment: Part 2: add --enable-ETW option, along with build commands

- Added $(MC) properly.

- Fixed some problems with what gets installed. (It turns out that tracerpt.exe, at least, needs the manifest around, even though other tools know how to use what gets registered via wevtutil.)

- Fail during configure if the SDK version is too old (or doesn't exist at all, as when running on non-Windows)

This version has passed try (unlike my last mangled $(MC) half implementation.)

Comment 28

[Steve Fink [:sfink] [:s:]]

Comment on attachment 480754 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

benjamin@ vs bsmedberg@. Where do I keep getting that from? If only bugzilla did completion on the requestee field...

Comment 29

[Steve Fink [:sfink] [:s:]]

Attachment: Part 3: insert probes throughout js tree

Some crash fixes (fp() vs hasfp(), ordering of finalizeObject probe).

But the main change is that the GC probes are rewritten for the compartments landing. The probes are probably a little off, and have some problems:

 - GCStart/GCEnd are not done per-compartment, so are given NULL for the compartment.

 - same for GCStartMarkPhase/GCEndMarkPhase

Perhaps it would be better to give the NULL compartment calls rt->defaultCompartment instead, or make them take a runtime parameter instead of a compartment parameter?

 - GCStartSweepPhase/GCEndSweepPhase use rt->defaultCompartment for the sweep of all the random bits and pieces, which extends over the entire runtime's sweep, and then a series of overlapped begin/end ranges for each of the individual compartments. So you can't sum their times, and other compartments' work happens within the time range of each compartment. The latter could be fixed by breaking the sweep phase into two parts, and giving begin/end probes for each of the parts. Similarly, the defaultCompartment sweep could be started and stopped repeatedly to avoid overlapping, but it would end up being a ton of probes. (Or you could add suspend/resume probes for each compartment, with the same problem.)

 - if you have a background sweeping thread, then GCEnd may fire before that thread is done. If I understand things correctly, that thread may not be checked for done-ness until needed, so there's no place on the main thread to tightly mark the end. I could fire the probe from the sweeping thread, but I doubt all probe handlers will be happy about being called from multiple threads; it seemed safer to avoid that for now. But barring that, I'd need to have the probe subsystem post events to a queue that gets checked by some main thread event loop, which seems a lot more invasive than probes ought to be.

For purposes like what MSR was using this for, none of this would have mattered; they would have seen the same pattern of events from different runs, and I think that's all they cared about. For performance analysis of garbage collection, something different may be needed.

Comment 30

[Steve Fink [:sfink] [:s:]]

Attachment: Part 4: Implement ETW probe points

Delete some unused code, fixes a compile problem where I had multiple FunctionName definitions, and (the reason for a re-review request) fixes a crash when computing the size of a dense array after it is created and before it is initialized. At that time, isDenseArray() will be true but getDenseArrayCapacity() is illegal.

Comment 31

[Steve Fink [:sfink] [:s:]]

Comment on attachment 467168 [details] [diff] [review]
Add a couple of JS utility commands

(Obsoleting patch): Forcing GC already exists, custom mark is done in the wrong place and I need something more general anyway. Doesn't need to be part of this bug.

Comment 32

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 480754 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

I'm going to steal this review from Ben.  I gave this an r-, but only because there's one big issue, everything else looks pretty good.

>@@ -7462,16 +7467,36 @@ MOZ_ARG_ENABLE_BOOL(vtune,
> dnl ========================================================
>+dnl ETW - Event Tracing for Windows
>+dnl ========================================================
>+MOZ_ARG_ENABLE_BOOL(ETW,
>+[  --enable-ETW            Enable ETW (Event Tracing for Windows) event reporting
>+                          (needs Windows 7+ SDK)],
>+    MOZ_ETW=1,
>+    MOZ_ETW= )
>+if test -n "$MOZ_ETW"; then
>+    AC_DEFINE(MOZ_ETW)
>+fi
>+
>+if test -n "$MOZ_ETW"; then
>+    if test -z "$MOZ_WINSDK_TARGETVER"; then
>+        AC_MSG_ERROR([--enable-ETW is only valid on Windows ($MOZ_WINSDK_TARGETVER)])
>+    elif test "$MOZ_WINSDK_TARGETVER" -lt "06000000"; then
>+        AC_MSG_ERROR([--enable-ETW requires Windows SDK version 0x600 or greater.])
>+    fi
>+fi

SDK version 6.0 is the Vista SDK, no?  The configure message and the version number need to match.  I'd condense the two checks to into:
>if test -z "$MOZ_WINSDK_TARGETVER" && test "$MOZ_WINSDK_TARGETVER" -lt "06000000"; then
>    AC_MSG_ERROR([--enable-ETW requires building for Windows with the Vista SDK or newer])
>fi

I also think we should drop support for pre-Vista SDKs after 2.0 branches, but that's neither here nor there.

>@@ -637,16 +643,21 @@ LDFLAGS += -F/System/Library/PrivateFram
>+ifdef MOZ_ETW
>+# This will get the ETW provider resources into the library mozjs.dll
>+LOBJS += ETWProvider.res
>+endif

Can you use RESFILE instead of LOBJS?  LOBJS is supposed to be internal to how we build our shared libraries and there are other patches floating around that make substantial changes to that that could break this.

>@@ -846,16 +857,32 @@ host_jsoplengen.$(OBJ_SUFFIX): jsopcode.
>+ifdef MOZ_ETW
>+$(CURDIR)/ETWProvider.h $(CURDIR)/ETWProvider.rc $(CURDIR)/ETWProvider.mof: ETWProvider.man
>+	$(MC) -um -mof $(topsrcdir)/ETWProvider.man

I don't think you should need the $(CURDIR) prefixes here.  Also, replace s/topsrcdir/srcdir/.  They might be the same in js/src, but anywhere else in the tree they'd be different.

>+$(CPPSRCS:%.cpp=%.$(OBJ_SUFFIX)): $(CURDIR)/ETWProvider.h

This shouldn't be necessary at all.  If ETWProvider.h is getting included in these files the dependencies should be getting handled automatically.  I r-d this because if that's not happening we should figure out why and fix it before landing this.

>+$(CURDIR)/ETWProvider.res: $(CURDIR)/ETWProvider.rc
>+	$(RC) -r -i "$(SDKDIR)Include" $(CURDIR)/ETWProvider.rc
>+
>+export:: $(CURDIR)/ETWProvider.res
>+
>+install:: $(CURDIR)/ETWProvider.mof ETWProvider.man
>+	$(SYSINSTALL) $^ $(DESTDIR)$(bindir)

Same with this other CURDIR stuff.

>@@ -4515,16 +4520,29 @@ MOZ_ARG_ENABLE_BOOL(vtune,
> dnl ========================================================
>+dnl ETW
>+dnl ========================================================
>+MOZ_ARG_ENABLE_BOOL(ETW,
>+[  --enable-ETW            Enable ETW (Event Tracing for Windows) event reporting
>+                          (needs Windows 7+ SDK)],
>+    MOZ_ETW=1,
>+    MOZ_ETW= )
>+if test -n "$MOZ_ETW"; then
>+    AC_DEFINE(MOZ_ETW)
>+    WINVER=600
>+fi

Shouldn't we use all the same logic from configure.in here so that the right stuff happens when building a standalone Spidermonkey?

Comment 33

[Steve Fink [:sfink] [:s:]]

(In reply to comment #32)
> Comment on attachment 480754 [details] [diff] [review]
> Part 2: add --enable-ETW option, along with build commands
> 
> I'm going to steal this review from Ben.  I gave this an r-, but only because
> there's one big issue, everything else looks pretty good.

Thanks for the detailed review! I'm only just now getting back to this.

> SDK version 6.0 is the Vista SDK, no?  The configure message and the version
> number need to match.  I'd condense the two checks to into:
> >if test -z "$MOZ_WINSDK_TARGETVER" && test "$MOZ_WINSDK_TARGETVER" -lt "06000000"; then
> >    AC_MSG_ERROR([--enable-ETW requires building for Windows with the Vista SDK or newer])
> >fi

Done, although I kept them separate because I've found the "you can't enable ETW on a non-Windows platform, you idiot!" message helpful.

> >@@ -637,16 +643,21 @@ LDFLAGS += -F/System/Library/PrivateFram
> >+ifdef MOZ_ETW
> >+# This will get the ETW provider resources into the library mozjs.dll
> >+LOBJS += ETWProvider.res
> >+endif
> 
> Can you use RESFILE instead of LOBJS?  LOBJS is supposed to be internal to how
> we build our shared libraries and there are other patches floating around that
> make substantial changes to that that could break this.\

Done. (What happens when you have more than one resource file?)

> >@@ -846,16 +857,32 @@ host_jsoplengen.$(OBJ_SUFFIX): jsopcode.
> >+ifdef MOZ_ETW
> >+$(CURDIR)/ETWProvider.h $(CURDIR)/ETWProvider.rc $(CURDIR)/ETWProvider.mof: ETWProvider.man
> >+	$(MC) -um -mof $(topsrcdir)/ETWProvider.man
> 
> I don't think you should need the $(CURDIR) prefixes here.  Also, replace
> s/topsrcdir/srcdir/.  They might be the same in js/src, but anywhere else in
> the tree they'd be different.

I cargo-culted the CURDIR stuff from other parts of the makefile, probably because of this comment:

# Use CURDIR to avoid finding a jsautooplen.h in the source tree (from
# a previous build?) via VPATH when we're building in a separate tree.

They're a little bit viral, though -- if I use $(CURDIR)/ETWProvider.h on the left hand side somewhere, I seem to need it in the

  foo.obj: $(CURDIR)/ETWProvider.h

line too (which I didn't remove. See below.) I can safely remove it from everything else independently, though, as long as I don't worry about source tree builds for them.

Under the assumption that we don't really care about source tree builds, I removed it from everywhere. (Or does that only break objdir builds following source tree builds? We care even less about those.) Some other things in that makefile still use $(CURDIR), though.

I removed topsrcdir entirely by switching to $^.

> >+$(CPPSRCS:%.cpp=%.$(OBJ_SUFFIX)): $(CURDIR)/ETWProvider.h
> 
> This shouldn't be necessary at all.  If ETWProvider.h is getting included in
> these files the dependencies should be getting handled automatically.  I r-d
> this because if that's not happening we should figure out why and fix it before
> landing this.

It does get included, but does not get handled automatically. This comment (for dtrace stuff) claims:

# We can't automatically generate dependencies on auto-generated headers;
# we have to list them explicitly.

I don't know when the dependency file generation happens, so I don't know what would be required to fix this. It sounds messy, though.

> >+$(CURDIR)/ETWProvider.res: $(CURDIR)/ETWProvider.rc
> >+	$(RC) -r -i "$(SDKDIR)Include" $(CURDIR)/ETWProvider.rc
> >+
> >+export:: $(CURDIR)/ETWProvider.res
> >+
> >+install:: $(CURDIR)/ETWProvider.mof ETWProvider.man
> >+	$(SYSINSTALL) $^ $(DESTDIR)$(bindir)
> 
> Same with this other CURDIR stuff.

Yes, I think all of these CURDIRs can go away.

> 
> >@@ -4515,16 +4520,29 @@ MOZ_ARG_ENABLE_BOOL(vtune,
> > dnl ========================================================
> >+dnl ETW
> >+dnl ========================================================
> >+MOZ_ARG_ENABLE_BOOL(ETW,
> >+[  --enable-ETW            Enable ETW (Event Tracing for Windows) event reporting
> >+                          (needs Windows 7+ SDK)],
> >+    MOZ_ETW=1,
> >+    MOZ_ETW= )
> >+if test -n "$MOZ_ETW"; then
> >+    AC_DEFINE(MOZ_ETW)
> >+    WINVER=600
> >+fi
> 
> Shouldn't we use all the same logic from configure.in here so that the right
> stuff happens when building a standalone Spidermonkey?

Yes. I merged them. The only difference is that js/src/configure.in sets WINVER=600 (which unfortunately appears to mess things up when done in the toplevel configure.)

Comment 34

[Steve Fink [:sfink] [:s:]]

Attachment: Part 2: add --enable-ETW option, along with build commands

Addressed review comments.

Comment 35

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Looks like the relevant bug for that weirdness is Bug 462272.

Unfortunately I've paged this all out of my brain; I'll try to get to reviewing it sometime this week.

Comment 36

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 500954 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

Looks good.  We can figure out the sillyness with autogenerated headers later.

Do we intend to ship with MOZ_ETW on?

Comment 37

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

This is probably known/expected, but parts 3 and 4 are bit-rotted (or at least if you try and apply 4 without the bit-rotted 3 applied, it fails).

Comment #1 mentions MS research; any chance they are working on tooling that can understand the traces so as to provide a profiler-style summary of the execution traces?  (I am assuming that Xperf itself cannot do this based on my previous experience with it, but I have not used the most recent Xperf releases.)

Comment 38

[Steve Fink [:sfink] [:s:]]

Attachment: Part 2: add --enable-ETW option, along with build commands

(In reply to comment #36)
> Comment on attachment 500954 [details] [diff] [review]
> Part 2: add --enable-ETW option, along with build commands
> 
> Looks good.  We can figure out the sillyness with autogenerated headers later.

Sorry, I still had one $(CURDIR) left in the INSTALLED_HEADERS sections, which breaks when I remove the other $(CURDIR)s. This patch *should* be a very minor update to the one you r+'ed, but my manual interdiffs were bigger than expected. I'll see what bugzilla's interdiff says.

> Do we intend to ship with MOZ_ETW on?

No, it enables stuff that's too expensive. I need to split it up into cheap and expensive things so we can leave on the cheap parts. Bug 603768. But I'll do that post-landing, which will be post-FF4.0.

Comment 39

[Steve Fink [:sfink] [:s:]]

Attachment: Part 3: insert probes throughout js tree

(In reply to comment #37)
> This is probably known/expected, but parts 3 and 4 are bit-rotted (or at least
> if you try and apply 4 without the bit-rotted 3 applied, it fails).

Yeah, I need to cancel the r? for now  (this is for post-FF4.0). But I maintain an up-to-date version locally; I'll post it in case you're interested in playing with it. (I haven't actually tried compiling or running it on Windows, though...)

> Comment #1 mentions MS research; any chance they are working on tooling that
> can understand the traces so as to provide a profiler-style summary of the
> execution traces?  (I am assuming that Xperf itself cannot do this based on my
> previous experience with it, but I have not used the most recent Xperf
> releases.)

The MSR people were converting the event stream to text and running a handbuilt parser over it, because they were just using it to validate reproducible test runs.

Xperf will eat the events, but it just displays them on a linear timeline as individual dots. (So your assumption is correct.)

Supposedly, there's an upcoming xperf that adds configurable graph output. What that means, and whether it'll be enough to truly make use of custom events like these, is an unknown since I know nearly nothing about what they intend.

I suspect we'll end up needing a tool of our own, preferably something that can take other forms of input -- for example, I'd really like to see systemtap data integrated with probes' output. You may have heard of systemtap? ;-) (For those reading along, see http://www.visophyte.org/blog/2010/04/08/a-systemtap-script-to-attribute-js-string-memory-costs-to-the-creating-js-functions/ and several others.)

I haven't seen anything that strikes me as ideally suited to use as a base. Maybe I should look at the LTT GUI again; it's been years...

Comment 40

[Steve Fink [:sfink] [:s:]]

Attachment: Part 4: Implement ETW probe points

Updating to latest tracemonkey, cancelling review request for now.

Comment 41

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

(In reply to comment #39)
> Yeah, I need to cancel the r? for now  (this is for post-FF4.0). But I maintain
> an up-to-date version locally; I'll post it in case you're interested in
> playing with it. (I haven't actually tried compiling or running it on Windows,
> though...)

Thank you for posting these!  I will give the patch a spin later today.

Since you are keeping it up-to-date locally, is there any way you could periodically publish it to a publicly available repo?  If you're using mercurial queues, for example, it should be pretty easy.  (hq qcommit; cd .hg/patches; hg push)

I ask because in February I am going to start doing automated performance runs of Thunderbird (with our under-development netbook UI). I was planning to just go with SystemTap on linux using my "causal chaining" probes (probe event loop entry/exit, event loop/higher level scheduling, and XPConnect C++->Java crossings, plus capture C++ and JS stacks at notable points including latencytap-based points of thresholded thread sleep durations)...

But these probes could make Windows another good platform to run on too.  I'll see what the perceived slowdown/logging deluge is.  As long as it stays within a factor of 4x I think it should be fine.  (And we really want to be running with xperf on windows anyways because we want to see how the virus checkers are impacting us.  I've heard some things that make me think MS' free anti-badness tool might be causing our main thread to join on our async db thread at points...)
 
> I haven't seen anything that strikes me as ideally suited to use as a base.
> Maybe I should look at the LTT GUI again; it's been years...

I recently finally put up one of the example causal chaining runs with its UI, if you want to take a look:
http://clicky.visophyte.org/examples/mozperfish/20101017/causal.html

Beware that it downloads a 3.4MiB JSON trace file and that it's designed for my 1920x1080 monitor in portrait mode, so it tends to look dumb in landscape or on smaller screens.  In a nutshell, you can change the graph features by clicking in the upper right, and if you click on things in the graph, details should pop up in the mini tab-box at the bottom.

The blog post (part 1) that more fully describes the visualization is here:
http://www.visophyte.org/blog/?p=586
And the blog post (part 2) that is talking about this specific example is here:
http://www.visophyte.org/blog/?p=599

I mention this not as a be-all-and-end-all, but I will probably keep moving forward with it.  The main change that is likely to happen is to move towards having a smaller overall visualization of a test run on the side that relates to a scrollable detailed event-overview which is the main body.  An example of a bugzilla UI built around this idea is here:
http://www.visophyte.org/blog/wp-content/uploads/2010/12/bugbuggoose-detail-cropped-example.png

The attractive bit about such a layout is that the new widgeting framework for Thunderbird allows us to just fetch a decimated overview to build the timeline visualization and then only fetch the more specific data elements asynchronously.  That way there should be no need to download huge trace files in one go, although it obviously will require a fair amount of preprocessing and potentially some collaboration by a server.  (Although we might be able to fake it by creating a mess of JSON files on disk.)

Comment 42

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

Comment on attachment 473240 [details] [diff] [review]
Part 1: ETW (Event Tracing for Windows) manifest

You have 'keywords="SampleKeyword"' everywhere.  You should take these out.

You also have '<string id="SampleProvider.SampleEvent.message" value="Sample message" />' at the bottom.

These result in a lot of wasted space in the translated XML output, which is already very dry reading :)

Comment 43

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

I just ran with this in Thunderbird and for general operation the overhead wasn't particularly noticeable.  Hooray for efficient userspace-ish logging!

Unfortunately things crash with the probes active when I try and use the JS-heavy faceted search implementation and my windows build machine isn't set up with a debugger right now.  In February I should be able to provide more productive feedback.

Going through the probe output, I think we may need to start telling some of them about the JSContext in use and/or the active frame pointer.  Specifically, I don't believe we can reconstruct an accurate call-graph just from these traces in the face of nested event loops and XPConnect code which calls out to JS in a conceptually different context from the stuff already on the stack.

For my pecobro tooling of yore (http://www.visophyte.org/blog/tag/pecobro/) which was built on our dtrace probes, I know I ended up feeding the JSContext into function-info/function-return in order to make things not explode.  (The dtrace probes were maintaining stack depth information using thread-locals, but still needed the JSContext or the calculated depth would go crazy.) I think that may have been naive about the potential for context reuse and dormant frame chains and what not which is why I suggest we might need to provide some data about the frame chain.  I'm not fully up on the implications right now because my systemtap probes just walk the JS stack on demand which is much more straightforward and pecobro was the last execution-trace-in-the-large stuff I did.  (My stuff built on chronicle-recorder was localized reconstructed execution tracing.)

In any event, this is super-fantastic-awesome and thank you so much for your work on this!  This is going to be all kinds of useful.

sfink: Do you have a suggestion on a better venue to discuss stuff related to this patch? mozilla.dev.tech.js-engine? mozilla.tools? someplace less inundated by spam? I feel like there is a lot of potential interesting discussion to be had that would just clutter this bug (further).

Comment 44

[Steve Fink [:sfink] [:s:]]

(In reply to comment #41)
> (In reply to comment #39)
> 
> Since you are keeping it up-to-date locally, is there any way you could
> periodically publish it to a publicly available repo?  If you're using
> mercurial queues, for example, it should be pretty easy.  (hq qcommit; cd
> .hg/patches; hg push)

I haven't tried sharing queues before, but ok, you can use http://people.mozilla.org/~sfink/src/ETW-patches/

It may be more up to date than you'd like because I do an automatic qcommit after every change to the queue (see 
http://blog.mozilla.com/sfink/2010/12/09/mercurial-mq-extension-extension/ ). I'm pushing once an hour.

> I ask because in February I am going to start doing automated performance runs
> of Thunderbird (with our under-development netbook UI). I was planning to just
> go with SystemTap on linux using my "causal chaining" probes (probe event loop
> entry/exit, event loop/higher level scheduling, and XPConnect C++->Java
> crossings, plus capture C++ and JS stacks at notable points including
> latencytap-based points of thresholded thread sleep durations)...

One of these patches isn't really ETW-specific, in that it adds supposedly-generic Probes::* calls to the JS engine code. Some of those calls already produce SystemTap events, and I intend to add the rest in. So you might get some use out of this on non-Windows, too.

> But these probes could make Windows another good platform to run on too.  I'll
> see what the perceived slowdown/logging deluge is.  As long as it stays within
> a factor of 4x I think it should be fine.  (And we really want to be running
> with xperf on windows anyways because we want to see how the virus checkers are
> impacting us.  I've heard some things that make me think MS' free anti-badness
> tool might be causing our main thread to join on our async db thread at
> points...)

I also intend to separate things out into high- and low-frequency events so I can enable the low-frequency ones by default.

> > I haven't seen anything that strikes me as ideally suited to use as a base.
> > Maybe I should look at the LTT GUI again; it's been years...
> 
> I recently finally put up one of the example causal chaining runs with its UI,
> if you want to take a look:
> http://clicky.visophyte.org/examples/mozperfish/20101017/causal.html
> 
> Beware that it downloads a 3.4MiB JSON trace file and that it's designed for my
> 1920x1080 monitor in portrait mode, so it tends to look dumb in landscape or on
> smaller screens.  In a nutshell, you can change the graph features by clicking
> in the upper right, and if you click on things in the graph, details should pop
> up in the mini tab-box at the bottom.

I played with it some. You know, I think there might be a danger to usefulness if people get too caught up in watching the force-directed graph float around and forget what they're trying to figure out! :-)

> I mention this not as a be-all-and-end-all, but I will probably keep moving
> forward with it.  The main change that is likely to happen is to move towards
> having a smaller overall visualization of a test run on the side that relates
> to a scrollable detailed event-overview which is the main body.  An example of
> a bugzilla UI built around this idea is here:
> http://www.visophyte.org/blog/wp-content/uploads/2010/12/bugbuggoose-detail-cropped-example.png

It seems promising, though I haven't really looked closely enough to figure out how I'd use it productively.

(In reply to comment #43)
> Going through the probe output, I think we may need to start telling some of
> them about the JSContext in use and/or the active frame pointer.  Specifically,
> I don't believe we can reconstruct an accurate call-graph just from these
> traces in the face of nested event loops and XPConnect code which calls out to
> JS in a conceptually different context from the stuff already on the stack.

You may be right. When doing something similar, I dumped out the thread ID, but that's really not good enough. However, the frame pointer is dangerous, because the JIT engines don't really like to maintain it (especially the tracer, which happily JITs across frames without entering them.) So at best, I could only provide the fp part of the time depending on your run mode, which obviously breaks state maintenance. (Especially since you can enter a function in one mode and exit it in another.)

We'll probably have to come up with a scheme using synchronization points of some sort that can be relied upon.

> sfink: Do you have a suggestion on a better venue to discuss stuff related to
> this patch? mozilla.dev.tech.js-engine? mozilla.tools? someplace less inundated
> by spam? I feel like there is a lot of potential interesting discussion to be
> had that would just clutter this bug (further).

I agree. The mozilla.dev.performance group might make sense, but it has the spam flood issue too.

Maybe mozilla.tools is the best place. I think it's subject to the antispam experiments, and the last post is over a month old so perhaps they're working.

Comment 45

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 505126 [details] [diff] [review]
Part 2: add --enable-ETW option, along with build commands

It doesn't look like much has changed since the last version I reviewed, so carrying forward the r+.

Comment 46

[Steve Fink [:sfink] [:s:]]

Attachment: Part 3: insert probes throughout js tree

Finally trying to land this for realz. Passes try.

Comment 47

[Steve Fink [:sfink] [:s:]]

Attachment: Part 4: Implement ETW probe points

Comment 48

[Steve Fink [:sfink] [:s:]]

Landed on mozilla-inbound, seems to have stuck:

http://hg.mozilla.org/integration/mozilla-inbound/rev/4d7f75359cc4
http://hg.mozilla.org/integration/mozilla-inbound/rev/ba032460632a
http://hg.mozilla.org/integration/mozilla-inbound/rev/d5e9f04a9f44
http://hg.mozilla.org/integration/mozilla-inbound/rev/3774d9ba0265
http://hg.mozilla.org/integration/mozilla-inbound/rev/5562d165fe2b
http://hg.mozilla.org/integration/mozilla-inbound/rev/15fb1d1eaf70

Comment 49

[Steve Fink [:sfink] [:s:]]

Filed followup bug 671035 to get rid of the windows.h pollution that this adds.

Comment 50

[(no longer active)]

http://hg.mozilla.org/mozilla-central/rev/ba032460632a
http://hg.mozilla.org/mozilla-central/rev/d5e9f04a9f44
http://hg.mozilla.org/mozilla-central/rev/3774d9ba0265
http://hg.mozilla.org/mozilla-central/rev/5562d165fe2b
http://hg.mozilla.org/mozilla-central/rev/15fb1d1eaf70

Comment 51

[(no longer active)]

Oh, and may I point out that this is really cool stuff?!  /me desperately waits for a blog post bringing this into other people's attention...

Comment 52

[Daniel Holbert [:dholbert]]

This bug's second-to-last cset (5562d165fe2b) seems to have broke the "Ns" nightly shark-enabled build:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1310638072.1310638738.11148.gz
OS X 10.6.2 mozilla-central shark on 2011/07/14 03:07:52
> js/src/jsprobes.cpp: In static member function 'static bool js::Probes::controlProfilers(JSContext*, bool)':
> js/src/jsprobes.cpp:74: error: 'js_StartShark' was not declared in this scope
> js/src/jsprobes.cpp:87: error: 'js_StopShark' was not declared in this scope

Comment 53

[Daniel Holbert [:dholbert]]

(not sure if comment 52 merits a backout or what, but I think we need either that or a bustage-fix on the sooner side.)

Comment 54

[Steve Fink [:sfink] [:s:]]

I'm doing the bustage fix in bug 671632.

Comment 55

[Ed Morley [:emorley]]

Random followup fix (doesn't appear to be attached):
http://hg.mozilla.org/mozilla-central/rev/9b82bc2b354e