934719 - log load begin and end in presshell code

Status: RESOLVED FIXED

(Core :: Layout, defect)

Description

[John Daggett (:jtd)]

It's really useful to be able to log presshell begin/end loads along with timing info, especially with complicated pages that include lots of nested content.  When combined with other logging, it makes it easier to distinguish between what events occurred during the initial page load and which occurred after.

Comment 1

[John Daggett (:jtd)]

Attachment: patch, log when loads begin and end in presshell code

Adds logging of PresShell begin/end load.  Dumps out the URL spec of the document along with the time elapsed between the begin/end load calls.

To log this load info:

  NSPR_LOG_MODULES=presshell:5

Comment 2

[Cameron McCormack (:heycam)]

Comment on attachment 827065 [details] [diff] [review]
patch, log when loads begin and end in presshell code

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

r=me with comments addressed.

::: layout/base/nsPresShell.cpp
@@ +20,5 @@
>  
> +#ifdef MOZ_LOGGING
> +#define FORCE_PR_LOG /* Allow logging in the release build */
> +#endif
> +#include "prlog.h"

prlog.h is already included further down.

@@ +686,5 @@
>    mReflowCountMgr->SetPresShell(this);
>  #endif
>  #ifdef PR_LOGGING
> +  mLoadBegin = TimeStamp::Now();
> +  if (! gLog) {

Remove the space after "!".

@@ +687,5 @@
>  #endif
>  #ifdef PR_LOGGING
> +  mLoadBegin = TimeStamp::Now();
> +  if (! gLog) {
> +    gLog = PR_NewLogModule("presshell");

Why rename the log module from "PresShell" to "presshell"?  Although we don't have awesome consistency, it does seem pretty common for log modules to be named after their class, if logging something conceptually related to that class.  And the class is named "PresShell" here.  So I think it would be better to leave it as it is.

@@ +2401,5 @@
> +
> +#ifdef PR_LOGGING
> +  if (gLog && PR_LOG_TEST(gLog, PR_LOG_DEBUG)) {
> +    mLoadBegin = TimeStamp::Now();
> +    nsIURI *uri = mDocument->GetDocumentURI();

"*" next to type.

@@ +2404,5 @@
> +    mLoadBegin = TimeStamp::Now();
> +    nsIURI *uri = mDocument->GetDocumentURI();
> +    nsAutoCString spec;
> +    if (uri)
> +      uri->GetSpec(spec);

Braces around if body.

@@ +2405,5 @@
> +    nsIURI *uri = mDocument->GetDocumentURI();
> +    nsAutoCString spec;
> +    if (uri)
> +      uri->GetSpec(spec);
> +    PR_LOG(gLog, PR_LOG_DEBUG,\

Remove the backslash.

@@ +2425,5 @@
> +#ifdef PR_LOGGING
> +  // log load
> +  if (gLog && PR_LOG_TEST(gLog, PR_LOG_DEBUG)) {
> +    TimeDuration loadTime = TimeStamp::Now() - mLoadBegin;
> +    nsIURI *uri = mDocument->GetDocumentURI();

"*" next to type.

@@ +2428,5 @@
> +    TimeDuration loadTime = TimeStamp::Now() - mLoadBegin;
> +    nsIURI *uri = mDocument->GetDocumentURI();
> +    nsAutoCString spec;
> +    if (uri)
> +      uri->GetSpec(spec);

Braces around if body.

@@ +2429,5 @@
> +    nsIURI *uri = mDocument->GetDocumentURI();
> +    nsAutoCString spec;
> +    if (uri)
> +      uri->GetSpec(spec);
> +    PR_LOG(gLog, PR_LOG_DEBUG,\

Remove backslash.

::: layout/base/nsPresShell.h
@@ +755,5 @@
>  
>    // The `performance.now()` value when we last started to process reflows.
>    DOMHighResTimeStamp       mLastReflowStart;
>  
> +  mozilla::TimeStamp        mLoadBegin;  // used to time loads

Make this #ifdef PR_LOGGING.

Comment 3

[John Daggett (:jtd)]

(In reply to Cameron McCormack (:heycam) from comment #2)
> >    // The `performance.now()` value when we last started to process reflows.
> >    DOMHighResTimeStamp       mLastReflowStart;
> >  
> > +  mozilla::TimeStamp        mLoadBegin;  // used to time loads
> 
> Make this #ifdef PR_LOGGING.

This one wouldn't make sense because PR_LOGGING can be enabled/disabled per source
file and that would produce differences in the structure of PresShell.

Comment 4

[John Daggett (:jtd)]

Pushed to trunk with review changes
https://hg.mozilla.org/integration/mozilla-inbound/rev/734992e111a2

Comment 5

[Cameron McCormack (:heycam)]

(In reply to John Daggett (:jtd) from comment #3)
> This one wouldn't make sense because PR_LOGGING can be enabled/disabled per
> source file and that would produce differences in the structure of PresShell.

Oh right, fair enough.

Comment 6

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/734992e111a2