741652 - Make JS_{Start,Stop}Profiling work with perf on Linux

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Justin Lebar (not reading bugmail)]

This should be pretty straightforward -- just call |perf record -g $pid|, then kill it in JS_StopProfiling.

Comment 1

[Justin Lebar (not reading bugmail)]

Sigh, the version of perf I have fails when you do --pid $pid:

http://help.lockergnome.com/linux/GIT-PULL-perf-core-fixes--ftopict533063.html

Comment 2

[Justin Lebar (not reading bugmail)]

Attachment: Patch v1

This seems to work, except my system's version of |perf| is horked -- it returns "failed to mmap with 22" when I do |perf record --pid| on a multi-threaded program.

I guess this will have to wait until I get a better kernel, unless someone else can test.

Comment 3

[Justin Lebar (not reading bugmail)]

FWIW the newsgroups I read said that --tid should work.  So I could profile just one thread.  |perf record --tid| runs without error, but then perf report crashes with a bus error.  I don't know if that's my bug or perf's, but since I really want --pid anyway, I don't care too much.

Comment 4

[Justin Lebar (not reading bugmail)]

Wow, the latest version of perf was ridiculously easy to build and install.

Clone the kernel, cd tools/perf, do [ make, install the package it asks for ], make install.  It even installs it into $HOME/bin.

Comment 5

[Justin Lebar (not reading bugmail)]

Comment on attachment 611856 [details] [diff] [review]
Patch v1

And with the new version of perf, this works great.

It might also work with the older version of perf -- the main quality of the new version seems to be that it displays better error messages, so you know what sysctl to frob.

Randomly picking a JS person for review; please forward it along if I chose poorly.

Comment 6

[Andrew McCreight [:mccr8]]

sfink may be a better choice, as he's done various profile-related things.

Comment 7

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

Comment on attachment 611856 [details] [diff] [review]
Patch v1

Review of attachment 611856 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/jsdbgapi.cpp
@@ +1115,5 @@
>  #endif
> +#ifdef __linux__
> +    if (!js_StartPerf())
> +        ok = JS_FALSE;
> +#endif

I'm not sure if I want this to be unconditional. The other profilers are controlled by non-default configure flags, so something will only happen if you really want it. This one will fire up a new process and nuke a local file whenever you're running on Linux. (Obviously, nothing at all will happen unless somebody calls JS_StartProfiling(), but it seems like the activation requirements of all of these should be comparable. Right now you can safely put these calls into test suites or whatever.)

Maybe put this behind an environment variable? The others probably ought to do the same, then, but I wouldn't bother with that for now.

@@ +1595,5 @@
> +#include <sys/wait.h>
> +#include <unistd.h>
> +#include <signal.h>
> +
> +bool perfInitialized = false;

Make this static too

@@ +1606,5 @@
> +     * later on, so we want it to be clean when we start out.
> +     */
> +    if (!perfInitialized) {
> +        perfInitialized = true;
> +        unlink("perf.data");

It makes me nervous that this is nuking any perf.data I might have lying around. What about passing in -o mozperf.data or something? Does that make it significantly more annoying to process these?

@@ +1617,5 @@
> +        /* perf record --append --call-graph --pid $mainPID */
> +        char mainPidStr[16];
> +        snprintf(mainPidStr, sizeof(mainPidStr), "%d", mainPid);
> +        execlp("perf", "perf", "record", "--append",
> +               "--call-graph", "--pid", mainPidStr, (char*) NULL);

Hm.... it would be nice to allow different command-line arguments (-e, -F, maybe omit --call-graph when it's annoying...) But I'm not sure of an easy way to do that. Reading an environment variable and splitting it on spaces or something would work, but it'd be messy. Never mind for now; I suppose I can always make a ~/bin/perf shell script.

@@ +1626,5 @@
> +    }
> +    else if (childPid > 0) {
> +        /* Give perf a chance to warm up. */
> +        usleep(500 * 1000);
> +        perfPid = childPid;

This doesn't behave very well if someone starts profiling twice. Maybe check perfPid at the beginning and return false if it's already set? Then you could merge childPid and perfPid.

Comment 8

[Justin Lebar (not reading bugmail)]

Thanks for the review, Steve!

Using an environment variable to control this sounds great to me.  (I didn't want to use a configure variable, since I didn't want to force a recompile.)

FWIW, I think you can effectively ignore --call-graph with the right perf report invocation.  I'm happy to read in flags from the environment variable -- that should be easy enough.

Comment 9

[Justin Lebar (not reading bugmail)]

Attachment: Patch v2

Comment 10

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

Comment on attachment 612222 [details] [diff] [review]
Patch v2

Review of attachment 612222 [details] [diff] [review]:
-----------------------------------------------------------------

I'm a little worried about the zombie issue, but I'll let you decide whatever you want there.

::: js/src/jsdbgapi.cpp
@@ +1682,5 @@
> +    }
> +    else if (childPid > 0) {
> +        /* Give perf a chance to warm up. */
> +        usleep(500 * 1000);
> +        perfPid = childPid;

Ignoring the fact that this is all horribly thread unsafe (which is fine), wouldn't it be better to reorder these two, just to shrink the race window a bit?

@@ +1699,5 @@
> +        return true;
> +    }
> +
> +    kill(perfPid, SIGINT);
> +    waitpid(perfPid, NULL, WNOHANG);

This makes me nervous. It seems like it would be very easy to accumulate zombies. You do a kill, then do a waitpid (before the killed process exits), and because of the WNOHANG you return immediately and have a zombie.

Why WNOHANG? I know zero is a little dangerous because it could cause a hang, but it still seems better.

It would be a little safer if you checked the return value of kill() and only did waitpid if it succeeded. (I'm worried about ESRCH.)

Comment 11

[Justin Lebar (not reading bugmail)]

> Why WNOHANG? I know zero is a little dangerous because it could cause a hang, but it still seems 
> better.
>
> It would be a little safer if you checked the return value of kill() and only did waitpid if it 
> succeeded. (I'm worried about ESRCH.)

Sounds good to me!  I think that would accomplish what I was trying to do, which is not completely fall over if perf dies before we kill() it.

Comment 12

[Justin Lebar (not reading bugmail)]

So I tried wait(perfPid, NULL, 0) (only if kill() returns 0), and I quickly encountered a hang in waitpid().  The perf process I'm waiting on is still alive, despite the SIGINT.

Upon investigation, I think this is a bug in perf.  perf is hitting some error case here ("Couldn't generate buildids." -- I have no idea what that means) and trying to exit.  But it then tries to do something with these buildids in the exit handler and ends up hung in mmap64() (?!).

I'll file a bug on the perf issue.  But...perhaps we shouldn't assume that the process will die when we ask.  (SIGKILL is wrong too -- perf needs to gracefully shut down, otherwise it corrupts its data file.)

Do you think we should simply get rid of the waitpid call, or put a sleep in?  Neither of those is particularly appealing to me...

Comment 13

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

Ugh. It's fairly common (though ugly) to SIGINT and/or SIGTERM, wait a little while, then SIGKILL. But if that corrupts the data file, that kinda sucks. How does that work in the hanging case, though? Is there any way of getting a valid data file out when it hangs?

I would vote against eliminating the waitpid with no other change.

What are the other alternatives? You could use sigaction(SIGCHLD, SA_NOCLDWAIT) to avoid zombies. But then you'd be changing child handling behavior globally across the process, which doesn't seem very safe.

Perhaps it would be best to daemonize the perf process? (Double-fork so it gets reparented to init, close all shared file descriptors, setsid(), whatever else is needed.) Then you could drop the waitpid. Actually, come to think of it, it'd be better to leave the file descriptors alone and maybe skip the setsid, since you probably want perf to die with the browser. So maybe just double-fork and eliminate the waitpid?

Comment 14

[Justin Lebar (not reading bugmail)]

> So maybe just double-fork and eliminate the waitpid?

Would I insert a sleep in place of the waitpid?  Otherwise, if the kill() doesn't happen immediately, we'll continue profiling for a bit afterwards.  I don't know how important this is -- I guess it depends on how small of a thing you're trying to profile.

(Of course, sleep only affects the current thread, so the profile will pick up other threads.  I saw this happen to me, with the safebrowsing thread.  I'm not sure there's much we can do about this, though.  We *could* ask jemalloc to lock everything, which would likely halt all threads pretty quickly...)

Comment 15

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

(In reply to Justin Lebar [:jlebar] from comment #14)
> > So maybe just double-fork and eliminate the waitpid?
> 
> Would I insert a sleep in place of the waitpid?  Otherwise, if the kill()
> doesn't happen immediately, we'll continue profiling for a bit afterwards. 
> I don't know how important this is -- I guess it depends on how small of a
> thing you're trying to profile.

Oh, I see what you mean. Ugh.

Ok, forget about the double-fork, especially since I just realized that it makes it a pain to do the kill() because you'd need to invent some mechanism for communicating the grandchild pid back to the main process. (Have the child send it via a pipe? Store it in a known file path? Yuck.)

This is feeling too complicated for a corner case we don't really care that much about. But going further down the rabbit hole anyway...

I see option 1 something like:

  kill(SIGINT);
  if (waitpid(WNOHANG) == -1):
    sleep(0.25);
    if (waitpid(WNOHANG) == -1):
      sleep(3);
      kill(SIGKILL);
      waitpid(0)

or option 2 something like:

  <readable,writable> = pipe();
  if fork() == 0:
    close(readable);
    exec("perf");
  close(writable);
  .
  .
  .
  kill(SIGINT);
  select(readable, 3 seconds);
  if (timeout):
    kill(SIGKILL);
  waitpid(0)

> (Of course, sleep only affects the current thread, so the profile will pick
> up other threads.  I saw this happen to me, with the safebrowsing thread. 
> I'm not sure there's much we can do about this, though.  We *could* ask
> jemalloc to lock everything, which would likely halt all threads pretty
> quickly...)

Comment 16

[Justin Lebar (not reading bugmail)]

> This is feeling too complicated for a corner case we don't really care that much about.

Well, what's the simple case which is 95% correct?  It's not double-fork.  Is it |kill(); wait(WNOHANG);| ?

>   <readable,writable> = pipe();
>   if fork() == 0:
>     close(readable);
>     exec("perf");
>   close(writable);

How is this supposed to work?  I'm definitely not an expert here, but: When we exec, it kills all our fd's, right?  So after exec, readable and writeable is dead in the child, and writeable is dead in the parent.  Then we select, and that doesn't fail immediately?

Comment 17

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

(In reply to Justin Lebar [:jlebar] from comment #16)
> > This is feeling too complicated for a corner case we don't really care that much about.
> 
> Well, what's the simple case which is 95% correct?  It's not double-fork. 
> Is it |kill(); wait(WNOHANG);| ?

I don't know if this hits 95% or not. If you try it, and in practice it seems like the kill() response happens before the waitpid(WNOHANG), then I'm fine with it.

If not, then perhaps you could additionally waitpid on the previous pid (if any) when starting up profiling for a 2nd time. Heck, if you're normally going to be calling JS_StartProfiling only once per run, you could even do a SIGKILL on the previous pid to kill it with fire. (Note that the kill won't fail even if the process exited in the meantime, because it's still a zombie until a successful waitpid.) But I suppose you don't want that given that you're using the append option? Oh, wait, you unlink.

> >   <readable,writable> = pipe();
> >   if fork() == 0:
> >     close(readable);
> >     exec("perf");
> >   close(writable);
> 
> How is this supposed to work?  I'm definitely not an expert here, but: When
> we exec, it kills all our fd's, right?

No. By default, *all* fds are preserved during both fork and exec. There is an FD_CLOEXEC flag that will autoclose fds during an exec if set, but the default is to inherit everything.

> So after exec, readable and
> writeable is dead in the child, and writeable is dead in the parent.  Then
> we select, and that doesn't fail immediately?

I originally wrote this up expecting a SIGPIPE when the child died and the parent tried to read, and was trying to use that. But I tried it, and it returned a successful read of zero bytes. Still, the select() I gave should work either way.

Not that I expect it helps, but here's a Perl equivalent:

perl -le '$^F = 10; pipe(R,W); $pid = fork() or do { close(R); exec("sleep 10"); }; close(W); sleep(1); kill(2, $pid); $s = ""; vec($s, fileno(R), 1) = 1; select($s, $s, $s, 3); waitpid($pid, 0)'

the sleep(1) is a placeholder for "do some work". Ignore the $^F bizarreness; it's to suppress perl's default behavior of setting FD_CLOEXEC on nearly everything.

Comment 18

[Justin Lebar (not reading bugmail)]

> If not, then perhaps you could additionally waitpid on the previous pid (if any) when starting up 
> profiling for a 2nd time.

But then, do I kill it and potentially corrupt my data file?  :-/

> Heck, if you're normally going to be calling JS_StartProfiling only once 
> per run, you could even do a SIGKILL on the previous pid to kill it with fire. (Note that the kill 
> won't fail even if the process exited in the meantime, because it's still a zombie until a 
> successful waitpid.) But I suppose you don't want that given that you're using the append option? 

Right.

> Oh, wait, you unlink.

Only once per run of the browser, so we can have multiple JS_StartProfiling()s aggregated into one perf data file.

This is would all be so much simpler if perf didn't have bugs!  :)

I'll see if I can get option 1 or 2 to work.

Comment 19

[Justin Lebar (not reading bugmail)]

I got the pipe option working.  But when I hit this perf bug, the browser is still unusable -- we pause for seconds at a time waiting for perf to complete, every time we CC.

And then when we do kill it, it corrupts its data file, so there's really no point in going on.

It looks like perf only hangs when I collect exotic measurements like branch or cache misses.  CPU profiling works fine.

I'm kind of tempted to go back to the world where we just hang.  Then it's obvious to the developer that there's a problem -- that's a lot better than, for example, disabling perf after we send one SIGKILL.

What do you think?

Comment 20

[Justin Lebar (not reading bugmail)]

Attachment: Patch v3 (select() on pipe)

Comment 21

[Justin Lebar (not reading bugmail)]

Comment on attachment 614523 [details] [diff] [review]
Patch v3 (select() on pipe)

er, ignore the JS_{Start,Stop}Profiling calls this adds to the CC.

Comment 22

[Justin Lebar (not reading bugmail)]

Attachment: Patch option 2, v1

This is just patch v2 with your review comments.  It will hang if perf hangs.

Comment 23

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

Comment on attachment 614526 [details] [diff] [review]
Patch option 2, v1

Review of attachment 614526 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/jsdbgapi.cpp
@@ +1713,5 @@
> +    /*
> +     * If kill() failed, assume it failed because perf died early and continue
> +     * on as though perf had been successfully killed.
> +     */
> +    perfPid = 0;

Sorry to drag you through the mud on this one, but the comment is incorrect. If perf died earlier, there will still be a zombie process holding its pid, and it would still be nice to reap that zombie. (I think the kill would actually succeed in that case, so you'd do a waitpid that would complete successfully immediately, and everything would be good.)

I think I led you astray with the ESRCH comment -- I was wrong, you shouldn't skip the waitpid entirely if kill() fails. (Anyway, you'd only get an ESRCH if you had a logic error or multithreading problem setting perfPid.)

r+ if you add a waitpid(WNOHANG) in the case that kill() returns an error. Looks fine otherwise.

Comment 24

[Justin Lebar (not reading bugmail)]

> Sorry to drag you through the mud on this one

No, I appreciate it!

I'm away from my Linux box for the week, but I'll revisit this once I'm back.

Comment 25

[Justin Lebar (not reading bugmail)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/79af6cb5647c

Comment 26

[Benoit Girard (:BenWa)]

Have you had a chance to try the Gecko Profiler? Its already controlled from JS just not this API. It should already work under all Tier 1 platform. We could achieve a similar results everywhere plus once we solve bug 736299 we should have a solution to peak into JS code.

Maybe it would be a good candidate to implement JS_Profiling under Tier 1 platforms.

Comment 27

[Justin Lebar (not reading bugmail)]

No, I haven't tried the built-in gecko profiler.  There's something about the tools you're familiar with...  Tempt me not with a shiny thing!  I am a dog, and I am old.

(In all seriousness, I doubt the gecko profiler handles stacks which go through the kernel with aplomb.  Also, perf can profile a wide variety of performance counters, although most of them hang on my system, so perhaps that's not so useful.)

Comment 28

[(no longer active)]

https://hg.mozilla.org/mozilla-central/rev/79af6cb5647c

Comment 29

[Justin Lebar (not reading bugmail)]

Oops, I didn't get rid of the comment from comment 23.  I'll kill it once the tree reopens.

Comment 30

[Ryan VanderMeulen [:RyanVM]]

Follow-up:
http://hg.mozilla.org/mozilla-central/rev/799566d5b2c1