1004899 - Add stderr to profile output

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Benoit Girard (:BenWa)]

We're logging a lot of rich data right now like DisplayList/LayersDump but mapping between logcat and profiles is a nightmare.

My goal is to patch gecko so that profiles can receive profile information. Once that's done we can display the logs in cleopatra and annotate the timeline along with it.

Then in a follow up we can allow people to grep for their log output and write a custom visualizer.

Comment 1

[Benoit Girard (:BenWa)]

Attachment: Prototype

Comment 2

[Benoit Girard (:BenWa)]

Attachment: patch

Comment 3

[(no longer active)]

Comment on attachment 8416595 [details] [diff] [review]
patch

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

::: gfx/layers/composite/LayerManagerComposite.cpp
@@ +443,5 @@
>      NS_WARNING("Call on destroyed layer manager");
>      return;
>    }
>  
> +  if (true || gfxPrefs::LayersDump()) {

Please remove this hunk.

::: gfx/thebes/gfxASurface.cpp
@@ +894,5 @@
>           cStr += 140;
>         }
>       }
>  #endif
> +    fprintf_stderr(aFile, "%s", string.BeginReading());

This one too.

::: xpcom/glue/nsCRTGlue.cpp
@@ +275,5 @@
> +{
> +  if (profiler_is_active()) {
> +    char buf[2048];
> +    va_list argsCpy;
> +    va_copy(argsCpy, args);

No need to va_copy this.

@@ +280,5 @@
> +    int required = vsnprintf(buf, sizeof(buf), fmt, argsCpy);
> +    va_end(argsCpy);
> +    buf[sizeof(buf) - 1] = '\0';
> +
> +    if (required < 2048) {

|required| can be negative here, you need to handle that case too I think.

@@ +283,5 @@
> +
> +    if (required < 2048) {
> +      profiler_tracing("log", buf, TRACING_EVENT);
> +    } else {
> +      char* heapBuf = new char[required+1];

You forgot to free this.

@@ +285,5 @@
> +      profiler_tracing("log", buf, TRACING_EVENT);
> +    } else {
> +      char* heapBuf = new char[required+1];
> +      va_list argsCpy2;
> +      va_copy(argsCpy2, args);

No need to va_copy this.

@@ +292,5 @@
> +      // EVENT_BACKTRACE could be used to get a source
> +      // for all log events. This could be a runtime
> +      // flag later.
> +      profiler_tracing("log", heapBuf, TRACING_EVENT);
> +    }

So, why not use nsAutoCString and AppendPrintf instead of all of this?

@@ +313,4 @@
>    if (IsDebuggerPresent()) {
>      char buf[2048];
>      va_list argsCpy;
>      va_copy(argsCpy, args);

You don't need to va_copy this twice.  Just move this to the outer block, and pass argsCpy to both call sites.

Comment 4

[Benoit Girard (:BenWa)]

Ouuch, sorry. Thanks for the review!

Comment 5

[Benoit Girard (:BenWa)]

(In reply to :Ehsan Akhgari (lagging on bugmail, needinfo? me!) from comment #3)
> @@ +313,4 @@
> >    if (IsDebuggerPresent()) {
> >      char buf[2048];
> >      va_list argsCpy;
> >      va_copy(argsCpy, args);
> 
> You don't need to va_copy this twice.  Just move this to the outer block,
> and pass argsCpy to both call sites.

It's unlikely we will have both a debugger and a profiler attached. It means that we would be doing a single copy in every case.

Comment 6

[Benoit Girard (:BenWa)]

Attachment: patch v2

I tried what you suggested for the va_list but it crashes. I tried a few iterations but I think this is the minimal one. Calling vsnprintf modifies the va_list so it must be copied before using it.

Comment 7

[(no longer active)]

(In reply to comment #5)
> (In reply to :Ehsan Akhgari (lagging on bugmail, needinfo? me!) from comment
> #3)
> > @@ +313,4 @@
> > >    if (IsDebuggerPresent()) {
> > >      char buf[2048];
> > >      va_list argsCpy;
> > >      va_copy(argsCpy, args);
> > 
> > You don't need to va_copy this twice.  Just move this to the outer block,
> > and pass argsCpy to both call sites.
> 
> It's unlikely we will have both a debugger and a profiler attached. It means
> that we would be doing a single copy in every case.

Well, va_copy is only needed across function calls.  You should be able to va_copy once and pass it to multiple functions, what you're not allowed to do is to not va_copy and pass a va_list to another function.  (This is needed because va_list might be implemented as a relative offset to your stack frame.)

Comment 8

[Benoit Girard (:BenWa)]

va_arg changes the state of the va_list so it's statefull. To be safe I should probably go back to aggressive va_copy to be portable. It should be cheap I imagine?

Comment 9

[(no longer active)]

(In reply to Benoit Girard (:BenWa) from comment #8)
> va_arg changes the state of the va_list so it's statefull. To be safe I
> should probably go back to aggressive va_copy to be portable. It should be
> cheap I imagine?

Ah, yeah, va_arg does change the list...

Don't worry about the cost, I would expect this to be a bunch of pointer copies on most platforms.

Comment 10

[(no longer active)]

Comment on attachment 8416711 [details] [diff] [review]
patch v2

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

::: xpcom/glue/nsCRTGlue.cpp
@@ +288,5 @@
> +      profiler_tracing("log", buf, TRACING_EVENT);
> +    } else {
> +      char* heapBuf = new char[required+1];
> +    va_list argsCpy;
> +    va_copy(argsCpy, args);

Nit: indentation

Comment 11

[Benoit Girard (:BenWa)]

Attachment: Layers.dump parsing example

Comment 12

[Benoit Girard (:BenWa)]

Alright for this to work it can't be in nsCRTGlue.cpp since it gets linked in code where the profiler isn't available. Glandium tells me we have to move the code to mozglue to work around this.

Comment 13

[Benoit Girard (:BenWa)]

For future reference this was the test push that included this patch and failed:
https://tbpl.mozilla.org/?tree=Try&rev=f81ab48d8670

Comment 14

[Benoit Girard (:BenWa)]

Attachment: patch v3

Comment 15

[Benoit Girard (:BenWa)]

https://tbpl.mozilla.org/?tree=Try&rev=db94b22767d9

Comment 16

[(no longer active)]

Comment on attachment 8417574 [details] [diff] [review]
patch v3

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

Please file a follow-up on fixing the linkage issue properly.  r=me with that and the comment below.

::: tools/profiler/platform.cpp
@@ +436,5 @@
>  }
>  
> +#if defined(XP_WIN)
> +#define va_copy(dest, src) (dest = src)
> +#endif

You need to do something like this:

http://mxr.mozilla.org/mozilla-central/source/xpcom/glue/nsTextFormatter.cpp#40

Comment 17

[Benoit Girard (:BenWa)]

Depends on changes from bug 926922 because it has some profiler changes rolled into it that this uses. Going to wait for that to land.

Comment 18

[Benoit Girard (:BenWa)]

Attachment: patch v4

Comment 19

[Benoit Girard (:BenWa)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ddd5e6e4c6e3

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/ddd5e6e4c6e3