Consider disabling Gecko logging on Fennec

RESOLVED FIXED in Firefox 49

Status

()

Firefox for Android
General
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: froydnj, Unassigned)

Tracking

(Blocks: 1 bug)

unspecified
Firefox 49
All
Android
Points:
---

Firefox Tracking Flags

(firefox49 fixed)

Details

(Whiteboard: [MemShrink:P2])

Attachments

(4 attachments, 2 obsolete attachments)

(Reporter)

Description

2 years ago
Over in bug 1215247 comment 43, Richard said:

> > Speaking as someone who has put a significant amount of effort into removing
> > code, shrinking data structures, and the like...there's not very much left
> > to remove without starting to gut platform features.
> 
> To an extent, I'm proposing gutting platform features. (Or, more moderately, > splitting the monolithic Gecko to allow us to ship much less.)
> 
> That is to say: if it doesn't contribute to acquiring or retaining Firefox 
> users, I would like it to be removed from the Gecko that we ship, with the 
> ultimate goal of getting libxul and omni.ja down to 2013/2014 levels.

In that vein, I'd like to propose the idea of completely disabling logging on Fennec, with the intent of thereby removing the static format strings that logging requires, along with the code to do the actual logging.  A five-line patch resulting in ~800K of space savings on libxul is nothing to sneeze at[1].

Historical background: we used to control whether logging was enabled with a configure-time switch.  But debugging problems with networking or media (those are the two biggest logging consumers, AFAICT from looking at logging strings in libxul) in the field proved tedious (e.g. get sufficient motivated bug reporters to provide logs), and it was also unhelpful for developers who wanted to log in release-ish builds to compile their own binaries.  So we enabled logging always and everywhere.  We've also moved to make logging more convenient, by moving our logging framework into Gecko proper rather than NSPR, and to make logs toggleable at runtime through about:config prefs.

Logging was also enabled inconsistently previously: some people only enabled logging when we passed --enable-logging, others enabled logging always, still others enabled logging only under compile-time #defines.  We don't have those problems anymore.

My hypothesis is that this unconditional logging is useful for desktop Firefox in the wild, but it's not that useful for Fennec in the wild, due to the difficulty of retrieving logs from the device and the difficulty in setting logging up.  Assuming that's true, all that code and data devoted to logging isn't helping us in acquiring or retaining Firefox users on Android, and we should disable it.

Broad net of people CC'd to attempt to solicit thoughts.  ni? to Maire and Patrick as I think this would affect their teams the most and I'm curious whether the logging has been useful for diagnosing problems on Android, or just on desktop Firefox.

[1] Measurements indicate that the strings themselves take up ~360K, and the code to do the logging takes up ~440K (!).
Flags: needinfo?(mreavy)
Flags: needinfo?(mcmanus)
we have definitely resolved fennec specific issues via nspr-style logs. And for necko in general these are the best source of information for solving problems.

that being said, fennec specific network problems are fairly unusual - though not unheard of.. and we usually do first try and repro on dekstop (perhaps with a slightly different profile) as a matter of developer productivity.

what I am less sure of is whether we could have had the reporters download different builds.. I suspect that because, as you say, getting the logs from mobile is kind of a pita you're dealing with a sophisticated user anyhow who probably can add the "get a new build" issue to the list of things that have to be done. So this change wouldn't freak me out.
Flags: needinfo?(mcmanus)
For release builds, this makes a lot of sense to me.

CCing snorp and kats; I'm not sure how much mobile platform relies on Gecko logs in release in the wild.
Summary: consider disabling logging on Fennec → Consider disabling Gecko logging on Fennec
We definitely rely on logcat output when it's available in crash reports. Some of the useful information there is from Android, and some from Gecko. That said, we don't really use NSPR logging (and it's not on by default to be useful for crash reports), so if you wanted to kill the logging code there it wouldn't be bad.
What percentage of fennec devs use debug builds? For desktop it's incredibly low.

I don't know if you have a distinction of non-debug vs release, but I'd suggest leaving logging enabled on all builds except the "main" releases (ie opt builds that are not aurora/nightly/trunk), it's probably useful on beta as well.
(Reporter)

Comment 5

2 years ago
(In reply to Eric Rahm [:erahm] from comment #4)
> I don't know if you have a distinction of non-debug vs release, but I'd
> suggest leaving logging enabled on all builds except the "main" releases (ie
> opt builds that are not aurora/nightly/trunk), it's probably useful on beta
> as well.

I was thinking about making it #ifdef RELEASE_BUILD, so logging would be enabled on trunk/nightly/aurora and disabled on beta/release (I think that's how the #define works; if not, consider this proposal a #define that does so).  We could leave logging enabled on beta too, if folks thought it would be useful.
(In reply to James Willcox (:snorp) (jwillcox@mozilla.com) from comment #3)
> We definitely rely on logcat output when it's available in crash reports.
> Some of the useful information there is from Android, and some from Gecko.
> That said, we don't really use NSPR logging (and it's not on by default to
> be useful for crash reports), so if you wanted to kill the logging code
> there it wouldn't be bad.

+1. We don't get a lot of value from NSPR logging in release (Beta or Final).
(In reply to Richard Newman [:rnewman] from comment #2)
> CCing snorp and kats; I'm not sure how much mobile platform relies on Gecko
> logs in release in the wild.

I don't rely on it very much, and if it's helpful to axe it then I have no issue with that. Usually when I need logging I just roll a try build for a user to run and get it that way.

(In reply to Nathan Froyd [:froydnj] from comment #5)
> I was thinking about making it #ifdef RELEASE_BUILD, so logging would be
> enabled on trunk/nightly/aurora and disabled on beta/release (I think that's
> how the #define works; if not, consider this proposal a #define that does
> so).

Yup, that's the right #ifdef. https://wiki.mozilla.org/Platform/Channel-specific_build_defines
As a first step, I'd be most comfortable turning this off for Release and Beta opt builds and keeping it on for Nightly and Dev Edition and debug builds.

If bloat in Nightly and Dev Edition matters, let me know, and I can actively track how often we use it for Nightly and Dev Edition going forward. Sound reasonable?
Flags: needinfo?(mreavy)
See Also: → bug 1263338
(Reporter)

Comment 9

2 years ago
Created attachment 8740115 [details] [diff] [review]
disable logging on Android release builds

This patch is straightforward, but a bit longer than the promised five lines
due to comments and the disabling of MOZ_LOG_TEST.

One thing I'm not sure about is if, with this patch, Android builds will fail
when beta merges because we'll suddenly have lots of LazyLogModule variables
that don't look used at all.  I need to experiment a little.  If that does turn
out to be a problem, we might have to s/LazyLogModule/MOZ_DEFINE_LOG_MODULE/g
or something similar.
Attachment #8740115 - Flags: review?(erahm)
Whiteboard: [MemShrink]
Comment on attachment 8740115 [details] [diff] [review]
disable logging on Android release builds

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

I think this approach is fine. I have some qualms about |MOZ_LOGGING_ENABLED|, so lets discuss that before landing.

::: xpcom/base/Logging.h
@@ +21,5 @@
>  // work progresses more functionality will be swapped out in favor of
>  // mozilla logging implementations.
>  
> +// We normally have logging enabled everywhere, but measurements showed that
> +// having logging enabled on Android is quite expensive (hundreds of kilobytes

Maybe remove "quite expensive" and just say that having logging enabled increased the binary size by X%.

@@ +22,5 @@
>  // mozilla logging implementations.
>  
> +// We normally have logging enabled everywhere, but measurements showed that
> +// having logging enabled on Android is quite expensive (hundreds of kilobytes
> +// for both the data and all the logging calls).  Because logging is

Perhaps "Because retrieving logs from a mobile device"

@@ +29,5 @@
> +// devices, we've chosen to leave logging enabled on desktop, but disabled on
> +// Android.  Given that logging can still be useful for development purposes,
> +// however, we leave logging enabled on Android developer builds.
> +#if !defined(ANDROID) || !defined(RELEASE_BUILD)
> +#define MOZ_LOGGING_ENABLED 1

I don't love that we're exposing a new logging macro, I spent a lot of time ridding us of |#ifdef PR_LOGGING| and I'm a little worried people might start using this.

@@ +197,5 @@
>  // parenthesized form to a varargs form. For example:
>  //   ("%s", "a message") => "%s", "a message"
>  #define MOZ_LOG_EXPAND_ARGS(...) __VA_ARGS__
>  
> +#if MOZ_LOGGING_ENABLED

So we could just move that whole #define MOZ_LOGGING_ENABLED down to here and remove the macro.

@@ +221,3 @@
>  
>  #undef PR_LOG
>  #undef PR_LOG_TEST

...or we could #undef it here.
Attachment #8740115 - Flags: review?(erahm) → feedback+
(In reply to Nathan Froyd [:froydnj] from comment #9)
> One thing I'm not sure about is if, with this patch, Android builds will fail
> when beta merges because we'll suddenly have lots of LazyLogModule variables
> that don't look used at all.  I need to experiment a little.  If that does
> turn
> out to be a problem, we might have to s/LazyLogModule/MOZ_DEFINE_LOG_MODULE/g
> or something similar.

FWIW I'd probably r- that, or at least there would be a lengthy discussion.
> One thing I'm not sure about is if, with this patch, Android builds will fail
> when beta merges because we'll suddenly have lots of LazyLogModule variables
> that don't look used at all.  I need to experiment a little.

Can you just force-remove them and do a try push?
Flags: needinfo?(nfroyd)
Whiteboard: [MemShrink] → [MemShrink:P2]
(Reporter)

Comment 13

2 years ago
(In reply to Nicholas Nethercote [:njn] from comment #12)
> > One thing I'm not sure about is if, with this patch, Android builds will fail
> > when beta merges because we'll suddenly have lots of LazyLogModule variables
> > that don't look used at all.  I need to experiment a little.
> 
> Can you just force-remove them and do a try push?

I thought I wrote a reply to this, but apparently not.

Building with --enable-warnings-as-errors runs into problems because we have variables defined that are only used in LOG statements.  And when those LOG statements are removed, we then have unused variable errors.
Flags: needinfo?(nfroyd)
(In reply to Nathan Froyd [:froydnj] from comment #13)
> (In reply to Nicholas Nethercote [:njn] from comment #12)
> > > One thing I'm not sure about is if, with this patch, Android builds will fail
> > > when beta merges because we'll suddenly have lots of LazyLogModule variables
> > > that don't look used at all.  I need to experiment a little.
> > 
> > Can you just force-remove them and do a try push?
> 
> I thought I wrote a reply to this, but apparently not.
> 
> Building with --enable-warnings-as-errors runs into problems because we have
> variables defined that are only used in LOG statements.  And when those LOG
> statements are removed, we then have unused variable errors.

How many? Arguably they're doing it wrong, ideally log specific messages are built up within a MOZ_LOG_TEST block.
(Reporter)

Comment 15

2 years ago
(In reply to Eric Rahm [:erahm] from comment #14)
> (In reply to Nathan Froyd [:froydnj] from comment #13)
> > Building with --enable-warnings-as-errors runs into problems because we have
> > variables defined that are only used in LOG statements.  And when those LOG
> > statements are removed, we then have unused variable errors.
> 
> How many? Arguably they're doing it wrong, ideally log specific messages are
> built up within a MOZ_LOG_TEST block.

I didn't try to start fixing them up yet, but I ran into code like:

http://dxr.mozilla.org/mozilla-central/source/netwerk/dns/nsHostResolver.cpp#447 (unused variable)
http://dxr.mozilla.org/mozilla-central/source/widget/ContentCache.cpp#21 (unused function, only called from MOZ_LOG invocations)

Neither of those strike me as particularly unusual
I'm not sure if there's a good solution here. Perhaps some trickery where mozilla::log_test always returns false, and then do something clever where |MOZ_LOG| deletes the first vararg (the format string)? So then you at least get rid of the strings.
(Reporter)

Comment 17

2 years ago
Created attachment 8749352 [details] [diff] [review]
part 1 - use temporary variables in CacheIndex logging

Using temporary variables here makes the code a bit clearer by not
repeating the readUint32 call.  A temporary variable also avoids the
compiler complaining about not using the result of readUint32 (which is
a MOZ_MUST_USE function) for the upcoming logging disabling patch.
Attachment #8749352 - Flags: review?(michal.novotny)
(Reporter)

Comment 18

2 years ago
Created attachment 8749353 [details] [diff] [review]
part 2 - remove temporary variable in nsPresContext's constructor

In the upcoming patch to disable logging, we're going to conditionally
turn MOZ_LOG_TEST into a constant false.  But for this instance of
MOZ_LOG_TEST in nsPresContext, turning it into a constant means that
|log| becomes unused.  Since |log| isn't used after this point, let's
move the |gfxPlatform::GetLog| call into the MOZ_LOG_TEST call, removing
the temporary variable, and making the compiler happy.
Attachment #8749353 - Flags: review?(dholbert)
(Reporter)

Comment 19

2 years ago
Created attachment 8749354 [details] [diff] [review]
part 3 - remove GetUserMediaLog function from MediaEngineWebRTC.cpp

GetUserMediaLog is a holdover from when when used PRLogModule and needed
to avoid a static constructor.  Now we have LazyLogModule, which doesn't
invoke static constructors, and so we can use that directly, rather than
indirecting through GetUserMediaLog.  This change also helps avoid an
unused function warning when logging is disabled.
Attachment #8749354 - Flags: review?(rjesup)
(Reporter)

Comment 20

2 years ago
Created attachment 8749356 [details] [diff] [review]
part 4 - disable logging on Android release builds, v2

This new patch addresses the feedback from the previous version and includes a
workaround for MOZ_LOG's arguments falling afoul of the compiler's warnings
when logging is disabled.

The only thing I didn't change was talking about x% of binary size for
disabling logging; I think "hundreds of kilobytes" is more likely to be an
accurate description down the road than "x% of binary size".  But I also like
my bikesheds to be painted a particular shade of blue.
Attachment #8749356 - Flags: review?(erahm)
(Reporter)

Updated

2 years ago
Attachment #8740115 - Attachment is obsolete: true
Attachment #8749353 - Flags: review?(dholbert) → review+
Attachment #8749352 - Flags: review?(michal.novotny) → review+
(Reporter)

Comment 21

2 years ago
FWIW, I verified that this approach with void-casting arguments does just as well as the previous approach of making the MOZ_LOG statement go away entirely.  libxul.so file size goes down ~900K with the patches applied and passes an --enable-warnings-as-errors build.
Comment on attachment 8749356 [details] [diff] [review]
part 4 - disable logging on Android release builds, v2

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

::: xpcom/base/Logging.h
@@ +30,5 @@
> +// desktop machines tend to be less space/bandwidth-constrained than Android
> +// devices, we've chosen to leave logging enabled on desktop, but disabled on
> +// Android.  Given that logging can still be useful for development purposes,
> +// however, we leave logging enabled on Android developer builds.
> +#if !defined(ANDROID) || !defined(RELEASE_BUILD)

Sorry I forgot about this last time, B2G has android defined right? I wonder if they'd care if we disabled this. Not a big deal I guess, as it's no longer tier 1 but it might be nice to leave the decision to them.

@@ +231,5 @@
> +//
> +// making |v| an unused variable and thus triggering compiler warnings.
> +#define MOZ_LOG_IGNORE_EXPRESSION(x) (void)(x);
> +
> +#define MOZ_LOG(_module,_level,_args) \

I like this solution! Just one caveat:

Shouldn't this be if (MOZ_LOG_TEST(_module, _level)) {
 ...
}

Otherwise it seems like we'll be possibly evaluating functions that aren't intended to be evaluated if logging is disabled.

For example:

> MOZ_LOG(gLogModule, LogLevel::Verbose, "%d %s",
>     CalculateSomethingExpensive(),
>     PromiseFlatCString(...).get());

would become:

> (void)(gLogModule);
> (void)(LogLevel::Verbose);
> (void)(CalculateSomethingExpensive());
> (void)(PromiseFlatCString(...).get());
Attachment #8749356 - Flags: review?(erahm) → feedback+
(Reporter)

Comment 23

2 years ago
Created attachment 8749408 [details] [diff] [review]
part 4 - disable logging on Android release builds, v3

Letting MOZ_LOG rely on the null definition of MOZ_LOG_TEST is much nicer, and
also avoids any issues that might crop up around variables suddenly become
unused when we merge to beta.

I think I'll keep the previous patches, though, since I think they are strict
improvements on their own.

I have no comment on the B2G-specificness.  I doubt they care strongly about
logging at this point.
Attachment #8749408 - Flags: review?(erahm)
(Reporter)

Updated

2 years ago
Attachment #8749356 - Attachment is obsolete: true
Comment on attachment 8749408 [details] [diff] [review]
part 4 - disable logging on Android release builds, v3

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

Well this turned out much simpler. r=me

::: xpcom/base/Logging.h
@@ +14,5 @@
>  
>  #include "mozilla/Assertions.h"
>  #include "mozilla/Atomics.h"
>  #include "mozilla/Likely.h"
> +#include "mozilla/MacroForEach.h"

min: You can remove this.
Attachment #8749408 - Flags: review?(erahm) → review+
> libxul.so file size goes down ~900K with the patches applied and
> passes an --enable-warnings-as-errors build.

\o/

Updated

2 years ago
Attachment #8749354 - Flags: review?(rjesup) → review+

Comment 27

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/2017c1063280
https://hg.mozilla.org/mozilla-central/rev/27ce66a25abe
https://hg.mozilla.org/mozilla-central/rev/8d27734170d9
https://hg.mozilla.org/mozilla-central/rev/5a110cddee4d
Status: NEW → RESOLVED
Last Resolved: 2 years ago
status-firefox49: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 49
You need to log in before you can comment on or make changes to this bug.