Closed Bug 1074952 Opened 10 years ago Closed 10 years ago

Consolidate graphics error/warning logging story

Categories

(Core :: Graphics, defect)

x86
All
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla36

People

(Reporter: milan, Assigned: milan)

References

Details

Attachments

(7 files, 18 obsolete files)

7.54 KB, patch
milan
: review+
Details | Diff | Splinter Review
2.18 KB, patch
bas.schouten
: review+
Details | Diff | Splinter Review
13.50 KB, patch
bas.schouten
: review+
Details | Diff | Splinter Review
3.44 KB, patch
bas.schouten
: review+
Details | Diff | Splinter Review
1.13 KB, patch
milan
: review+
Details | Diff | Splinter Review
8.07 KB, patch
milan
: review+
Details | Diff | Splinter Review
3.71 KB, patch
milan
: review+
Details | Diff | Splinter Review
From the recent work week:
gfxCriticalError - in both release and debug, logged into a circular buffer and into the crash log - always keep the first one, but otherwise keep the last N (driven by gfx.logging.length preference) messages.

gfxWarning - in both release and debug, logged into a circular buffer.  Keep the last N (driven by gfx.logging.length preference) messages.

gfxDebug - in debug only.

gfx.logging.level preference set to 1 gives us the above behaviour.  Set to 2, it stops all gfxDebug messages.  Set to 3, it stops all gfxWarning messages as well.  The default is 1.
Comment on attachment 8497597 [details] [diff] [review]
Initial patch, a potential way to expose the Moz2D values to prefs.

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

r+'ed this patch in bug 1069620.
Attachment #8497597 - Flags: feedback?(bas)
(In reply to Milan Sreckovic [:milan] from comment #0)
> gfx.logging.level preference set to 1 gives us the above behaviour.  Set to
> 2, it stops all gfxDebug messages.  Set to 3, it stops all gfxWarning
> messages as well.  The default is 1.

Drive-by comment: to my mind it seems counter-intuitive that a higher value for gfx.logging.level should result in less logging. I'd expect "higher" logging levels to record/report more stuff, not less...
(In reply to Jonathan Kew (:jfkthame) from comment #3)
> (In reply to Milan Sreckovic [:milan] from comment #0)
> > gfx.logging.level preference set to 1 gives us the above behaviour.  Set to
> > 2, it stops all gfxDebug messages.  Set to 3, it stops all gfxWarning
> > messages as well.  The default is 1.
> 
> Drive-by comment: to my mind it seems counter-intuitive that a higher value
> for gfx.logging.level should result in less logging. I'd expect "higher"
> logging levels to record/report more stuff, not less...

That's a valid point.  This behaviour is inherited from prlog that is used under the covers (see definition of PR_LOG_TEST in prlog.h), where the approach is "you need to be this tall to get on this ride (log)".
(In reply to Milan Sreckovic [:milan] from comment #4)
> (In reply to Jonathan Kew (:jfkthame) from comment #3)
> > (In reply to Milan Sreckovic [:milan] from comment #0)
> > > gfx.logging.level preference set to 1 gives us the above behaviour.  Set to
> > > 2, it stops all gfxDebug messages.  Set to 3, it stops all gfxWarning
> > > messages as well.  The default is 1.
> > 
> > Drive-by comment: to my mind it seems counter-intuitive that a higher value
> > for gfx.logging.level should result in less logging. I'd expect "higher"
> > logging levels to record/report more stuff, not less...
> 
> That's a valid point.  This behaviour is inherited from prlog that is used
> under the covers (see definition of PR_LOG_TEST in prlog.h), where the
> approach is "you need to be this tall to get on this ride (log)".

I'll take some of this back.  We have our levels as "1 is debug, 3 is critical", but prlog goes the other way "1 is always logged, 2 is critical, 4 is debug", so I'll look at changing our side in the subsequent patches to match.  "Larger number means more messages" does make sense.
(In reply to Milan Sreckovic [:milan] from comment #0)

> gfxDebug - in debug only.

I think the use of "debug" is not really great here. I think this is really "verbose" logging more than "debug" logging. There's also the problem of knowing whether that means "is only enabled for debug builds" or not. I realize PR_LOG is similar but if we're going to come up with something new why not use terminology that's a little more reflective of what the logging is actually doing.
We expect (what we currently call) gfxDebug to be compiled out in the release build, and only doing something in the #ifdef DEBUG - we want to use it often enough not to worry about increasing the size of the release build.  gfxDebugLog or gfxLogDebug or gfxTraceDebug or something like that is an option?  I'm not sure how "new" we want things to be, it was more to be consistent, but I'm sure we'll take any suggestions on what would make things more understandable and easier to maintain.  So:

1. Something that is #ifdef DEBUG only, gets compiled out in the release builds and that is just for tracing the code.  

2. Something that is run time governed by a pref, available in both debug and release builds, and constitutes a warning that things are not quite normal, but it isn't necessarily a sign of a bug in our code.  For example, failing to get back a large canvas.  Off by default in non-debug build, on by default in debug build.  Actually, perhaps on by default in the nightly.

3. Something that is telling us that we have a bug in our code.  Critical error, logged into the crash report as well.  On by default.  Will probably crash soon, but it depends.  Basically, the way we'd use an assert in the debug build.

What would be the good names?
The story is evolving so let me record some thoughts.

First, the simple stuff - naming: gfxDebug - maybe use gfxLog instead. Basically, gfxWarning is for something mildly disturbing, and gfxLog is just for making a lot of noise when you're debugging something in particular (which is where gfxDebug probably came from before.)

Second, some kind of filtering when it comes to logging. Sometimes you want to see all the logging, but sometimes you just want to see apz or tiling or layers or whatever.  So, combine what we'd have with logging, with what comes from prlog (so, this would be limited to those platforms alone to start), and use gfxLog("gfx-whatever") << ... syntax instead. One of the overall gfx.logging.level options would be "show me all logs", but one, just below it, would be "show me only the logs enabled by prlog (again, that would only work for the platforms where prlog does anything.)
Assignee: nobody → milan
For the non-main thread logging - one option is to save them and pick them up if/when we crash, the other is to keep sending them across.  Probably the later.
Attachment #8511233 - Attachment description: Part 2. gfxWarning() should be available in both debug and release builds. (WIP) → Part 2. gfxWarning() should be available in both debug and release builds.
Attachment #8511233 - Flags: review?(bas) → review+
Note that the CrashReporter currently rejects the not-default-process-and-not-main-thread scenario, but the other combinations should be OK.  Certainly the non-e10s OMTC scenario is covered.
Attachment #8512984 - Flags: review?(nical.bugzilla)
Attachment #8512984 - Flags: review?(nical.bugzilla) → review+
Comment on attachment 8511236 [details] [diff] [review]
Part 3. Redo the const values and optimize for the case where we run time don't log messages.

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

::: gfx/2d/Logging.h
@@ +93,5 @@
>  
>    // Used to choose the level of logging we get.  The higher the number,
> +  // the more logging we get.  Value of zero will give you no logging,
> +  // 1 will give you everything, 2 just errors, 3 adds warnings and
> +  // 5 adds logging/debug (so, 1 behaves the same as 5.)  The missing value

Drive-by observation: "1" giving you everything while "2" only gives you errors seems to contradict "the higher the number, the more logging we get".
Comment on attachment 8515114 [details] [diff] [review]
Part 6. Fully qualify the appropriate logs in the logging macros. r=botond

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

::: gfx/2d/Logging.h
@@ +367,5 @@
>  typedef Log<LOG_WARNING> WarningLog;
>  typedef Log<LOG_CRITICAL, CriticalLogger> CriticalLog;
>  
>  #ifdef GFX_LOG_DEBUG
> +#define gfxDebug gfx::DebugLog

Is there any harm in going the whole hog and qualifying them with mozilla::gfx::?
Attachment #8515114 - Flags: review?(botond) → review+
Is this duplicating machinery elsewhere, such as in bug 881389 or its dependents?
It's more that completing bug 881389 may give us a unified way to implement one function in here, the one that actually delivers the logs to the user (BasicLogger::OutputMessage in Logging.h, which is today a combination of printf, printf_stderr, PR_LogPrint and OutputDebugStringA.) Most of the work here is one level higher, for us to consistently use the logging capabilities...
Update the docs and fully quality with mozilla::gfx:: instead of just gfx:: based on the feedback.
Attachment #8515114 - Attachment is obsolete: true
Attachment #8517671 - Flags: review+
Attachment #8517671 - Attachment is patch: true
Attachment #8517666 - Attachment description: Add logging support for a couple of common Moz2d enums and use them. → Part 7. Add logging support for a couple of common Moz2d enums and use them.
Comment on attachment 8511236 [details] [diff] [review]
Part 3. Redo the const values and optimize for the case where we run time don't log messages.

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

::: gfx/2d/Logging.h
@@ +360,4 @@
>    }
>  
>    std::stringstream mMessage;
> +  int mOptions;

I'm wondering out loud whether LogIt should be separate bool field instead of a bitflag. Both to avoid the bitwise-AND when checking it and to make it impossible for people to shove it into their LogOptions.
Attachment #8511236 - Flags: review?(bas) → review+
Attachment #8512836 - Flags: review?(bas)
Made enough changes that I won't carry the r+.
Attachment #8511236 - Attachment is obsolete: true
Attachment #8520942 - Flags: review?(bas)
Attachment #8512984 - Attachment is obsolete: true
The code that uses these enums belongs to a different bug.
Attachment #8517666 - Attachment is obsolete: true
Attachment #8520948 - Flags: review?(bas)
Comment on attachment 8520943 [details] [diff] [review]
Part 4. For the critical log, save the first, then circular buffer the rest into the crash annotations.

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

::: gfx/thebes/gfxPlatform.cpp
@@ +174,5 @@
> +  uint32_t mMaxCapacity;
> +  int32_t mIndex;
> +};
> +
> +nsCString CrashStatsLogForwarder::kCrashCriticalKey("GraphicsCriticalError");

This shows up as a leak, so I'll change it to const char* instead.
Don't use the static for the key. Nicer code, and no worries about leaking statics.
Attachment #8520943 - Attachment is obsolete: true
Attachment #8520943 - Flags: review?(bas)
Attachment #8522435 - Flags: review?(bas)
Comment on attachment 8522435 [details] [diff] [review]
Part 4. For the critical log, save the first, then circular buffer the rest into the crash annotations. r=bschouten

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

::: gfx/thebes/gfxPlatform.cpp
@@ +176,5 @@
> +  int32_t mIndex;
> +};
> +
> +CrashStatsLogForwarder::CrashStatsLogForwarder(const char* aKey)
> +: mBuffer()

nit: whitespace

@@ +190,5 @@
> +  mBuffer.reserve(static_cast<size_t>(aCapacity));
> +}
> +
> +bool
> +CrashStatsLogForwarder::UpdateStringsVector(const std::string& aString)

personally I'd prefer just adding using namespace std and dropping all the std::

@@ +605,5 @@
>      mozilla::gl::GLContextProviderEGL::Shutdown();
>  #endif
>  
> +    // This is a bit iffy - we're assuming that we were the ones that set the
> +    // log forwarder in the Factory, so that it's our responsibility to 

Yeah, I thought about this, and I considered storing mLogForwarder on the gfxPlatform class. But I felt that was sort of needless.
Attachment #8522435 - Flags: review?(bas) → review+
Attachment #8520942 - Flags: review?(bas) → review+
Attachment #8520948 - Flags: review?(bas) → review+
Hi Milan, part 6 failed to apply:

1 out of 2 hunks FAILED -- saving rejects to file gfx/layers/d3d11/TextureD3D11.cpp.rej
patch failed, unable to continue (try -v)
patch failed, rejects left in working dir
errors during apply, please fix and refresh 1074952.6.p4

could you take a look ?
Flags: needinfo?(milan)
Hmm, applies cleanly for me - did you take it from the try run, or from the bug?  Because the bug has an up to date Part 6, and the try run has a merge conflict.  I'll check against inbound, in case it's different there, I was checking against central.
Flags: needinfo?(milan) → needinfo?(cbook)
OK, I see, it doesn't apply cleanly on inbound.
This should merge cleanly on inbound.
Attachment #8524132 - Attachment is obsolete: true
Flags: needinfo?(cbook)
Attachment #8524655 - Flags: review+
Any follow up enhancement and changes in bug 1101685.
You need to log in before you can comment on or make changes to this bug.