Allow logs to be mirrored into Profiler Markers

RESOLVED FIXED in Firefox 66

Status

()

enhancement
P3
normal
RESOLVED FIXED
7 months ago
3 months ago

People

(Reporter: jesup, Assigned: jesup)

Tracking

(Blocks 1 bug)

58 Branch
mozilla66
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox66 fixed)

Details

(Whiteboard: [qf-])

Attachments

(2 attachments, 1 obsolete attachment)

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
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

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

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.
Attachment #9034613 - Flags: review?(nfroyd) → review+
Priority: -- → P3
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.
Attachment #9034613 - Flags: review?(mstange) → review+
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.
Attachment #9035124 - Flags: review?(mstange) → review-

(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.

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?

Attachment #9035124 - Attachment is obsolete: true

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

Attachment #9036505 - Flags: review?(mstange) → review+

(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.

Great.

Pushed by rjesup@wgate.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aa43ce6e3442
add keyword to mirror LOG messages into Profiler LogMarkers r=mstange,froyd
Whiteboard: [qf] → [qf-]
Status: NEW → RESOLVED
Closed: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla66
You need to log in before you can comment on or make changes to this bug.