1512690 - Improve Message Manager Logging

Status: RESOLVED FIXED

(Core :: IPC, enhancement)

Description

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

While investigating Message Manager, I wrote and adapted some code to log the full contents of MM messages. After talking to people it seems like there is interest in me landing this so it can be used in the future.

Comment 1

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

Comment 2

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Add a mechanism to omit logging specified Message Manager topics

Comment 3

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

:kmag - You seem to be someone who knows a lot about Message Manager - would you be willing to review this? (Or suggest someone for me to pass it to?) Aside from the perf concern below, the OSX build error below, and cleaning up the #include order in MMPrinter.cpp, I think it's good to go.

FWIW, I tried to make MMPrinter:Print an inline function; but this caused a 'requires dynamic R_X86_64_PC32 reloc against' error: https://paste.rs/IUl.cpp  Removing 'inline' made it go away...



Haik, Alex: On OSX I get a a screwy build error: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5537ae6857a69b831b55a7de63bb49c9128ca69e&selectedJob=215979333 about error: reference to 'Point/Rect/Size' is ambiguous
Have you seen this before? Do you know what #include magic I need to do to make this go away?



jmaher: I get one regression on this patch to add some heavy logging that is disabled by default. Do you think this is a concerning enough regression to do something about?  I could restrict it to Debug builds; but then I'd lose the ability to add logging on Nightly which would really help me out...
https://treeherder.mozilla.org/perf.html#/compare?originalProject=mozilla-central&newProject=try&newRevision=2ab8531e708846dcf21e685028182013149659de&framework=1&showOnlyComparable=1&showOnlyImportant=1&selectedTimeRange=172800

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

I am curious why this is showing up on linux and windows, not macosx?  Is there a way to enable this behind an environment variable or preference?

Comment 5

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #4)
> I am curious why this is showing up on linux and windows, not macosx?  Is
> there a way to enable this behind an environment variable or preference?

OSX is broken right now, we don't have results for it =)

It is currently gated on a check of MOZ_LOG_TEST (which I believe boils down to a slightly-more-complictaed env var check) - although this check does occur inside a function call rather than inline. I will try moving the check outside of the function call and see if that reduces the overhead.

Comment 6

[Haik Aftandilian [:haik]]

(In reply to Tom Ritter [:tjr] from comment #3)
> Haik, Alex: On OSX I get a a screwy build error:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=5537ae6857a69b831b55a7de63bb49c9128ca69e&selectedJob=2
> 15979333 about error: reference to 'Point/Rect/Size' is ambiguous
> Have you seen this before? Do you know what #include magic I need to do to
> make this go away?

Hey Tom, removing the "#include "nsLocalFile.h" from dom/ipc/MMPrinter.cpp fixed the build issue for me.

Comment 7

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Looks like a macro-based approach solves the performance problems!

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ab80454e3526b7fdceadbc7fe7126a9b003cf5f4
https://treeherder.mozilla.org/perf.html#/compare?originalProject=mozilla-central&newProject=try&newRevision=ab80454e3526b7fdceadbc7fe7126a9b003cf5f4&framework=1&showOnlyComparable=1&selectedTimeRange=172800

And haik; thanks for that, sorry I didn't try it myself.

Comment 8

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

Comment 9

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Add a mechanism to omit logging specified Message Manager topics

Okay; these patches are up to date and good to review.

If there's a better approach to str_replace I'd be happy to switch over to it; but unsure what API to use...

Comment 10

[Kris Maglione [:kmag]]

Comment on attachment 9030023 [details] [diff] [review]
Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

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

I expect that this logging will be useful to have, but the stringifier needs some work.

::: dom/ipc/MMPrinter.cpp
@@ +31,5 @@
> +
> +namespace mozilla {
> +namespace dom {
> +
> +static LazyLogModule gMMLog("MessageManagerLog");

No "Log" in log module names, please.

@@ +37,5 @@
> +#define MMPRINT_LOG(x) MOZ_LOG(gMMLog, LogLevel::Verbose, x)
> +
> +// https://stackoverflow.com/a/779960
> +// You must free the result if result is non-NULL.
> +char* str_replace(char* orig, const char* rep, const char* with) {

Please use nsCString::ReplaceSubstring for this.

@@ +89,5 @@
> +  if (!JS_Enumerate(aCx, object, &ids)) {
> +    return;
> +  }
> +
> +  for (size_t i = 0, n = ids.length(); i < n; i++) {

`ids.length()` is an inlined member variable getter. No need to store its result. It's cheap enough on its own.

And, for that matter, this can probably just be a range iterator.

@@ +93,5 @@
> +  for (size_t i = 0, n = ids.length(); i < n; i++) {
> +    // Retrieve Property name.
> +    nsAutoJSString propName;
> +    if (!propName.init(aCx, ids[i])) {
> +      continue;

Maybe print something about OOM here rather than silently continuing?

@@ +99,5 @@
> +    MMPRINT_LOG(("%*s'%s' : ", aRecursionCounter * 4, "",
> +                 NS_ConvertUTF16toUTF8(propName).get()));
> +
> +    // Retrieve Property value.
> +    JS::RootedValue propertyValue(aCx);

This (and generally all other JS::Rooted* declarations) should be hoisted outside of the loop. Setup and tear-down of Rooted containers is not super cheap.

@@ +149,5 @@
> +  }
> +
> +  if (aValue.isObject()) {
> +    MMPRINT_LOG(("%*s{", aRecursionCounter * 4, ""));
> +    MMPrinter::PrintObject(aCx, aValue, aRecursionCounter + 1);

Am I missing somewhere where we handle infinite recursion from cyclic values?

Honestly, this makes me kind of uneasy. It would probably make more sense to just use the same stringifier as uneval()...

@@ +160,5 @@
> +    return true;
> +  }
> +
> +  if (aValue.isSymbol()) {
> +    MMPRINT_LOG(("%*s[Symbol Type]", aRecursionCounter * 4, ""));

You'll probably want to stringify this in some manner or other...

@@ +169,5 @@
> +    MMPRINT_LOG(("%*s[Primitive Type]", aRecursionCounter * 4, ""));
> +    return true;
> +  }
> +
> +  if (aValue.isGCThing()) {

This should never happen for structured clone data if the above return false.

@@ +174,5 @@
> +    MMPRINT_LOG(("%*s[GCThing]", aRecursionCounter * 4, ""));
> +    return true;
> +  }
> +
> +  if (aValue.isMagic()) {

This should never happen at all for structured clone data. Probably just drop these two `if`s and add an assertion that this is never reached.

@@ +189,5 @@
> +/* static */
> +bool MMPrinter::PrintImpl(char const* aLocation,
> +                          nsTString<char16_t> const& aMsg,
> +                          ClonedMessageData const& aData) {
> +  NS_LossyConvertUTF16toASCII asciiMsg(aMsg);

Why ASCII?

@@ +208,5 @@
> +  xpc::SandboxOptions options;
> +
> +  JS::RootedValue v(cx);
> +  nsresult rv2 =
> +      CreateSandboxObject(cx, &v, nsXPConnect::SystemPrincipal(), options);

This is super expensive. Probably better off using privileged or unprivileged junk scope.

::: dom/ipc/MMPrinter.h
@@ +11,5 @@
> +namespace dom {
> +
> +class MMPrinter {
> + public:
> +  static bool Print(char const* aLocation, nsTString<char16_t> const& aMsg,

This should be defined in the class definition so the log check can be inlined. This code is hot enough for it to matter. Though I suppose with LTO it'll probably be inlined either way.

Comment 11

[Kris Maglione [:kmag]]

Comment on attachment 9030324 [details] [diff] [review]
Bug 1512690 - Add a mechanism to omit logging specified Message Manager topics

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

::: dom/ipc/MMPrinter.cpp
@@ +198,5 @@
> +  *  - The full topic name must be specified. MOZ_LOG_MESSAGEMANAGER_SKIP="foo"
> +  *    (or "foo*") will _not_ match topic 'foobar'
> +  *  - Multiple topics can be specified, they can be deliniated by anything, or
> +  *    nothing at all (see below).
> +  *  - Topic names that are a substring of specified topic names _will_ be matched

Maybe just be a bit clear that if the topic appears anywhere as a substring of the filter, it will be skipped, with a couple of examples of single and multiple-topic strings and what they match?

This description is way harder to parse than the code is...

@@ +206,5 @@
> +  *     Will  match the topics 'foobar', 'foo', 'bar', and 'ten' (even though you may not
> +  *     have intended to match the latter three) and it will not match the topics
> +  *     'extensionresult' or 'Foo'.
> +  */
> +  char* mmSkipLog = PR_GetEnv("MOZ_LOG_MESSAGEMANAGER_SKIP");

Maybe `static const char mmSkipLog = PR_GetEnv(...)` so we don't have to fetch the environment variable again for every message? I generally wouldn't expect it to change at runtime, or for us to need to honor those changes if it does...

Comment 12

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

Comment 13

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Add a mechanism to omit logging specified Message Manager topics

Carrying forward r+ from Comment 11

Comment 14

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Thanks for the super-prompt review!


(In reply to Kris Maglione [:kmag] from comment #10)
> @@ +149,5 @@
> > +  }
> > +
> > +  if (aValue.isObject()) {
> > +    MMPRINT_LOG(("%*s{", aRecursionCounter * 4, ""));
> > +    MMPrinter::PrintObject(aCx, aValue, aRecursionCounter + 1);
> 
> Am I missing somewhere where we handle infinite recursion from cyclic values?
> 
> Honestly, this makes me kind of uneasy. It would probably make more sense to
> just use the same stringifier as uneval()...

I did not know about that. I replaced almost the whole thing with a call to the uneval wrapper!


> @@ +189,5 @@
> > +/* static */
> > +bool MMPrinter::PrintImpl(char const* aLocation,
> > +                          nsTString<char16_t> const& aMsg,
> > +                          ClonedMessageData const& aData) {
> > +  NS_LossyConvertUTF16toASCII asciiMsg(aMsg);
> 
> Why ASCII?

Didn't know any better. Fixed this (I think.)


> @@ +208,5 @@
> > +  xpc::SandboxOptions options;
> > +
> > +  JS::RootedValue v(cx);
> > +  nsresult rv2 =
> > +      CreateSandboxObject(cx, &v, nsXPConnect::SystemPrincipal(), options);
> 
> This is super expensive. Probably better off using privileged or
> unprivileged junk scope.

Unprivileged seems to work!


> ::: dom/ipc/MMPrinter.h
> @@ +11,5 @@
> > +namespace dom {
> > +
> > +class MMPrinter {
> > + public:
> > +  static bool Print(char const* aLocation, nsTString<char16_t> const& aMsg,
> 
> This should be defined in the class definition so the log check can be
> inlined. This code is hot enough for it to matter. Though I suppose with LTO
> it'll probably be inlined either way.

I'm not sure what you mean by this. I think you mean that if I moved the entire Print() function into the .h file it would be eligible for inlining from the compiler and thus could be faster?

I don't think I can do that because I have the gMMLog global variable?  

I definetly want to avoid calling into the function to evaluate the Log Test; but that's why I have the MMPRINTER_PRINT macro that is used in all the callsites; so the MOZ_LOG_TEST is present in those functions.

Is that sufficient?  Or should I do something else?


(In reply to Kris Maglione [:kmag] from comment #11)
> @@ +206,5 @@
> > +  *     Will  match the topics 'foobar', 'foo', 'bar', and 'ten' (even though you may not
> > +  *     have intended to match the latter three) and it will not match the topics
> > +  *     'extensionresult' or 'Foo'.
> > +  */
> > +  char* mmSkipLog = PR_GetEnv("MOZ_LOG_MESSAGEMANAGER_SKIP");
> 
> Maybe `static const char mmSkipLog = PR_GetEnv(...)` so we don't have to
> fetch the environment variable again for every message? I generally wouldn't
> expect it to change at runtime, or for us to need to honor those changes if
> it does...

Actually; my use case for this logging is explicitly to incrementally update this env var while the browser is running so I (and others) can keep our normal workflows while slowly generating less logs and (hopefully) generating a better, more interesting edge-case-signal to noise.  So I left it evaluating each call...

Comment 15

[Kris Maglione [:kmag]]

(In reply to Tom Ritter [:tjr] from comment #14)
> > ::: dom/ipc/MMPrinter.h
> > @@ +11,5 @@
> > > +namespace dom {
> > > +
> > > +class MMPrinter {
> > > + public:
> > > +  static bool Print(char const* aLocation, nsTString<char16_t> const& aMsg,
> > 
> > This should be defined in the class definition so the log check can be
> > inlined. This code is hot enough for it to matter. Though I suppose with LTO
> > it'll probably be inlined either way.
> 
> I'm not sure what you mean by this. I think you mean that if I moved the
> entire Print() function into the .h file it would be eligible for inlining
> from the compiler and thus could be faster?
> 
> I don't think I can do that because I have the gMMLog global variable?  
> 
> I definetly want to avoid calling into the function to evaluate the Log
> Test; but that's why I have the MMPRINTER_PRINT macro that is used in all
> the callsites; so the MOZ_LOG_TEST is present in those functions.
> 
> Is that sufficient?  Or should I do something else?

Typically we'd do something like:

    class MMPrinter {
      LazyLogModule sLog;
    }
    ...
    LazyLogModule MMPrinter::sLog("MessageManager");

So the inlined functions can access sLog.

In general, I'll always prefer an inlined function to a macro when feasible.

> Actually; my use case for this logging is explicitly to incrementally update
> this env var while the browser is running so I (and others) can keep our
> normal workflows while slowly generating less logs and (hopefully)
> generating a better, more interesting edge-case-signal to noise.  So I left
> it evaluating each call...

Hm. OK... I'd tend to want to expose something like that as a proper API, but I suppose as long as the overhead is low enough...

Comment 16

[Kris Maglione [:kmag]]

Comment on attachment 9030509 [details] [diff] [review]
Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

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

r=me with changes.

::: dom/ipc/MMPrinter.cpp
@@ +40,5 @@
> +/* static */
> +void MMPrinter::Print(char const* aLocation,
> +                          nsTString<char16_t> const& aMsg,
> +                          ClonedMessageData const& aData) {
> +  auto charMsg = NS_ConvertUTF16toUTF8(aMsg);

Nit: NS_ConvertUTF16toUTF8 charMsg(aMsg); Or just inline the whole thing as NS_ConvertUTF16toUTF8(aMsg).get().

@@ +55,5 @@
> +
> +  AutoJSAPI jsapi;
> +  jsapi.Init();
> +  JSContext* cx = jsapi.cx();
> +  JSAutoRealm ar(cx, xpc::UnprivilegedJunkScope());

Nit: You can skip the JSAutoRealm if you just do `MOZ_ALWAYS_TRUE(jsapi.Init(xpc::UnprivilegedJunkScope()))`

@@ +65,5 @@
> +  JS::RootedValue scdContent(cx);
> +  data.Read(cx, &scdContent, rv);
> +  if (NS_WARN_IF(rv.Failed())) {
> +    rv.SuppressException();
> +    JS_ClearPendingException(cx);

This shouldn't be necessary. Any JS exception should be set on the ErrorResult, not the JSContext.

@@ +69,5 @@
> +    JS_ClearPendingException(cx);
> +    return;
> +  }
> +
> +  JSString* unevalObj = JS_ValueToSource(cx, scdContent);

This should probably be a RootedString.

@@ +71,5 @@
> +  }
> +
> +  JSString* unevalObj = JS_ValueToSource(cx, scdContent);
> +  nsAutoString autoObj;
> +  AssignJSFlatString(autoObj, JS_ASSERT_STRING_IS_FLAT(unevalObj));

nsAutoJSString srcString;
  if (!srcString.init(cx, autoObj))
    return;

::: dom/ipc/MMPrinter.h
@@ +13,5 @@
> +extern LazyLogModule gMMLog;
> +
> +#define MMPRINTER_PRINT(aLocation, aMsg, aData) \
> +  if (MOZ_UNLIKELY(MOZ_LOG_TEST(gMMLog, LogLevel::Debug))) { \
> +    MMPrinter::Print(aLocation, aMsg, aData); \

This needs to be clang-formatted...

But I'd rather it just be an inlined function defined in MMPrinter that checks the log flags and calls an internal print function.

@@ +22,5 @@
> +  static void Print(char const* aLocation, nsTString<char16_t> const& aMsg,
> +                        ClonedMessageData const& aData);
> +
> + private:
> +  

Nit: Trailing space.

Comment 17

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

Comment 18

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Add a mechanism to omit logging specified Message Manager topics

Carrying forward r+ from Comment 11

Comment 19

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

(In reply to Kris Maglione [:kmag] from comment #16)
> r=me with changes.

Thanks; I flagged you one more time just to make sure I refactored it the right way; but I addressed all these comments.

Comment 20

[Kris Maglione [:kmag]]

Comment on attachment 9030542 [details] [diff] [review]
Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

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

::: dom/ipc/MMPrinter.h
@@ +11,5 @@
> +namespace dom {
> +
> +class MMPrinter {
> + public:
> +  static LazyLogModule sMMLog;

Nit: I'd probably make this private.

@@ +12,5 @@
> +
> +class MMPrinter {
> + public:
> +  static LazyLogModule sMMLog;
> +  static inline void Print(char const* aLocation,

Nit: `inline` is implied.

@@ +13,5 @@
> +class MMPrinter {
> + public:
> +  static LazyLogModule sMMLog;
> +  static inline void Print(char const* aLocation,
> +                           nsTString<char16_t> const& aMsg,

Nit: `const nsAString&` (also in PrintImpl, obviously).

Comment 21

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Introduce a MesageManager log topic for MM topics and data

Carrying forward R+ from Comment 20

Comment 22

[Tom Ritter [:tjr] (OOTO until 4/30 at least)]

Attachment: Bug 1512690 - Add a mechanism to omit logging specified Message Manager topics

Carrying forward r+ from Comment 11

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/841be5946814
Introduce a MesageManager log topic for MM topics and data r=tjr
https://hg.mozilla.org/integration/mozilla-inbound/rev/9f90cb82af56
Add a mechanism to omit logging specified Message Manager topics r=tjr

Comment 24

[Cristina Coroiu [:ccoroiu]]

https://hg.mozilla.org/mozilla-central/rev/841be5946814
https://hg.mozilla.org/mozilla-central/rev/9f90cb82af56