1518030 - Allow logs to be mirrored into Profiler Markers

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement, P3)

Description

[Randell Jesup [:jesup] (needinfo me)]

When debugging, it would be very useful to be able to see log messages from Gecko in the context of the profiler UI (and the ability to correlate profile stacks and execution with when the log message occurred).

This implements a simple version by adding a "profilermarkers" keyword for the MOZ_LOG envvar that mirrors log messages to makers.

It depends on TextMarker support

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: add keyword to mirror LOG messages into ProfilerMarkers

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Note: I'll probably end up adding a specific marker object for Log messages, since I think we may want to do some processing in perf-html, and so we'll want to know it's a log.  It's not needed to start using this, but I'm open to doing it now and a matching tweak to perf-html.io

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

Attachment: move Logging markers from TextMarkes to LogMarkers

Comment 4

[Honza Bambas (:mayhemer)]

Isn't there already a way to to show logs from time spans in cleopatra? I remember that used to work..

Comment 5

[Nathan Froyd [:froydnj]]

Comment on attachment 9034613 [details] [diff] [review]
add keyword to mirror LOG messages into ProfilerMarkers

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

Let's experiment with this and see how far we can get.

Comment 6

[Markus Stange [:mstange]]

Comment on attachment 9034613 [details] [diff] [review]
add keyword to mirror LOG messages into ProfilerMarkers

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

I don't like the NS_ConvertASCIItoUTF16 call in here but it gets removed in the next patch, so that's fine.

Comment 7

[Markus Stange [:mstange]]

Comment on attachment 9035124 [details] [diff] [review]
move Logging markers from TextMarkes to LogMarkers

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

::: tools/profiler/public/ProfilerMarkerPayload.h
@@ +411,5 @@
> +  DECL_STREAM_PAYLOAD
> +
> + private:
> +  // Avoid an extra alloc
> +  char mModule[32]; // longest known LazyLogModule name is ~24

Please use an nsAutoCStringN for this. Then you won't need the assert, you won't need to write the word "strncpy", and it still saves you the alloc.

@@ +412,5 @@
> +
> + private:
> +  // Avoid an extra alloc
> +  char mModule[32]; // longest known LazyLogModule name is ~24
> +  const mozilla::UniquePtr<char> mText;

And an nsCString for this.

Comment 8

[Markus Stange [:mstange]]

(In reply to Honza Bambas (:mayhemer) from comment #4)

Isn't there already a way to to show logs from time spans in cleopatra? I remember that used to work..

Not any more. The Gecko profiler used to hook printf_stderr, and the initial version of perf.html had a Log tab for that, but the printf_stderr hooking got removed in bug 1346132 comment 2.

Comment 9

[Markus Stange [:mstange]]

However, that comment brings up a good point:

(In reply to Nicholas Nethercote [:njn] from comment #2)

Also, it prevents us from using MOZ_LOG in the profiler, which is something I
want. Because if any code that locks gPSMutex also calls MOZ_LOG, that then
calls printf_stderr(), which calls profiler_log(), which locks gPSMutex,
which deadlocks.

Randell, have you thought about this problem?

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

Attachment: move Logging markers from TextMarkes to LogMarkers

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

PR to enable tooltips for LogMarkers is https://github.com/devtools-html/perf.html/pull/1630

Comment 12

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Markus Stange [:mstange] from comment #9)

However, that comment brings up a good point:

(In reply to Nicholas Nethercote [:njn] from comment #2)

Also, it prevents us from using MOZ_LOG in the profiler, which is something I
want. Because if any code that locks gPSMutex also calls MOZ_LOG, that then
calls printf_stderr(), which calls profiler_log(), which locks gPSMutex,
which deadlocks.

Randell, have you thought about this problem?

Markers don't grab a mutex - they call RacyRegisteredThread::AddPendingMarker(), which just adds to a list used by one thread, with no locking.

Comment 13

[Markus Stange [:mstange]]

Great.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aa43ce6e3442
add keyword to mirror LOG messages into Profiler LogMarkers r=mstange,froyd

Comment 15

[Daniel Varga [:dvarga]]

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

Comment 16

[Florian Quèze [:florian]]

Hey Randell, do you remember if there was a reason to not enable this behavior by default and rely only the the profiler_thread_is_being_profiled_for_markers()` check? If so, does this reason still apply?

If it was because we were concerned about the overhead of adding profiler markers, I think Gerald's fixes over the last few years have dramatically reduce it.

Maybe we could instead put a keyword to enable capturing stacks in these markers?

Comment 17

[Julien Wajsberg [:julienw]]

(In reply to Florian Quèze [:florian] from comment #16)

Hey Randell, do you remember if there was a reason to not enable this behavior by default and rely only the the profiler_thread_is_being_profiled_for_markers()` check? If so, does this reason still apply?

If it was because we were concerned about the overhead of adding profiler markers, I think Gerald's fixes over the last few years have dramatically reduce it

I actually filed bug 1705019 some time ago for this.

Maybe we could instead put a keyword to enable capturing stacks in these markers?

good idea! Would you please file a separate bug?

Comment 18

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Julien Wajsberg [:julienw] from comment #17)

Maybe we could instead put a keyword to enable capturing stacks in these markers?

good idea! Would you please file a separate bug?

Florian, maybe you missed to file that bug? Could you please have a look?

Comment 19

[Florian Quèze [:florian]]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #18)

(In reply to Julien Wajsberg [:julienw] from comment #17)

Maybe we could instead put a keyword to enable capturing stacks in these markers?

good idea! Would you please file a separate bug?

Florian, maybe you missed to file that bug? Could you please have a look?

I took care of it in bug 1705019, no need for a separate bug.