Enhance logging: Use "always on" macros

• Component: Web Template Framework
• Status: RESOLVED FIXED

[Keith Rollin]

Use the new "always on" macros in some strategic places. These places are identified by examining some currently "unsolvable" customer bug reports, as well as by some collective WebKit development experience.

[Radar WebKit Bug Importer]

<rdar://problem/24757730>

[Keith Rollin]

Created attachment 272379 [details]
Patch

[Chris Dumez]

Comment on attachment 272379 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=272379&action=review

> Source/WebCore/loader/ProgressTracker.cpp:123
>  void ProgressTracker::progressStarted(Frame& frame)

I worry these are going to be too noisy. Would it suffice to log frame load start and end in FrameLoader?

> Source/WebCore/platform/MemoryPressureHandler.cpp:183
> +void MemoryPressureHandler::ReliefLogger::diagnosticLog()

This seems to duplicate MemoryPressureHandler::ReliefLogger::platformLog() :(
Can we refactor this so we don't duplicate the code?

> Source/WebCore/platform/network/mac/ResourceHandleMac.mm:285
>  

If worry these may be too noisy.

> Source/WebCore/platform/network/mac/WebCoreResourceHandleAsDelegate.mm:246
>  

Would logging frame load complete suffice?

> Source/WebCore/platform/network/mac/WebCoreResourceHandleAsOperationQueueDelegate.mm:287
> +    LOG_ALWAYS("Handle %p delegate connectionDidFinishLoading:%p", m_handle, connection);

Ditto.

> Source/WebKit2/NetworkProcess/cocoa/NetworkDataTaskCocoa.mm:243
>  {

These seems very low-level. Also, I don't believe this code is actually being run anywhere at the moment.

> Source/WebKit2/Platform/IPC/Connection.cpp:905
> +    reportResourceUsage();

We log on EVERY IPC message? This seems like a lot.

> Source/WebKit2/Platform/IPC/Connection.cpp:984
> +    if (elapsed < kFiveSeconds)

Oh, I see now that you technically only log every 5 seconds even though you'll call this method a lot more often. Honestly, we have so many IPC messages that having a repeating timer with an interval of 5 seconds would likely do the same thing more cheaply.
Also, this seems like a lot of things to log every 5 seconds? no?

> Source/WebKit2/Platform/IPC/Connection.cpp:996
> +    double utime = usage.ru_utime.tv_sec + usage.ru_utime.tv_usec / 1000000.0;

1000000.0 should be a constant with a readable name.

> Source/WebKit2/Platform/IPC/Connection.h:362
> +    struct rusage m_usage = {{0, 0}, {0, 0}, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0};

do we really need the "struct " part?

[Keith Rollin]

Created attachment 272681 [details]
Patch

[Keith Rollin]

(In reply to comment #3)
> Comment on attachment 272379 [details]
> > Source/WebCore/loader/ProgressTracker.cpp:123
> >  void ProgressTracker::progressStarted(Frame& frame)
> 
> I worry these are going to be too noisy. Would it suffice to log frame load
> start and end in FrameLoader?

You and I subsequently had a long discussion about this, and you showed me some better places to insert these logging messages. I'll make those changes.

> > Source/WebCore/platform/MemoryPressureHandler.cpp:183
> > +void MemoryPressureHandler::ReliefLogger::diagnosticLog()
> 
> This seems to duplicate MemoryPressureHandler::ReliefLogger::platformLog() :(
> Can we refactor this so we don't duplicate the code?

I haven't been able to see how. The function is intertwined with logic and logging statements. I don't see how to pull out the common parts and isolate the different parts.

> > Source/WebKit2/Platform/IPC/Connection.cpp:984
> > +    if (elapsed < kFiveSeconds)
> 
> Oh, I see now that you technically only log every 5 seconds even though
> you'll call this method a lot more often. Honestly, we have so many IPC
> messages that having a repeating timer with an interval of 5 seconds would
> likely do the same thing more cheaply.
> Also, this seems like a lot of things to log every 5 seconds? no?

Regarding the usefulness and effectiveness of simply logging anything every 5 seconds, you, Gavin, and I talked about this, and have left this as a "it remains to be seen".

As for a timer, I used to do that, but Gavin pointed out that we don't want the process to wake up every five seconds if it would otherwise be idle. That might have a negative effect on a device's battery, so the current approach was taken.

> > Source/WebKit2/Platform/IPC/Connection.cpp:996
> > +    double utime = usage.ru_utime.tv_sec + usage.ru_utime.tv_usec / 1000000.0;
> 
> 1000000.0 should be a constant with a readable name.

Wilco.

> > Source/WebKit2/Platform/IPC/Connection.h:362
> > +    struct rusage m_usage = {{0, 0}, {0, 0}, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0};
> 
> do we really need the "struct " part?

This is a habit of mine for when I deal with plain Std C Lib type. I can remove it.

[Chris Dumez]

Comment on attachment 272681 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=272681&action=review

> Source/WebCore/platform/MemoryPressureHandler.cpp:193
> +        LOG_ALWAYS("Pressure relief: %s: -dirty %ld bytes (from %lu to %lu)", m_logString, (memoryDiff * -1), m_initialMemory, currentMemory);

If we called WTFLogAlways() instead of LOG_ALWAYS() (or in addition to) when s_loggingEnabled is true, then we could kill the platform-specific version.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:203
> +    LOG_ALWAYS("Starting resource load: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

It may be interesting to know if this is a main resource:
m_parameters.request.requester() == ResourceRequest::Requester::Main

Also, maybe this could clarify that it loads from the network, not the cache.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:276
> +    LOG_ALWAYS("Received page headers: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

Received resource response:

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:308
> +            LOG_ALWAYS("Asking permission to continue: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

I don't really think we're asking permission to continue but we are waiting for a message to keep going. The reason I believe is that depending on the response, the WebContent process may decide to convert the resource load into a download (e.g. if the MIME type cannot be displayed in the view).
This should probably say "Sending didReceiveResponse message to the WebContent process" or similar.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:310
> +                LOG_ALWAYS("Permission to continue denied: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

It is not really that the permission was denied but rather that we failed to send the didReceiveResponse IPC message to the WebContent process.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:323
> +        LOG_ALWAYS("Should continue: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

should continue what? I think the log message is not very clear on its own. I think we want something like:
Should wait for message from WebContent process before continuing resource load? yes / no.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:359
> +    LOG_ALWAYS("Finished loading: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

Why not log finishTime since we have it?

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:438
> +    LOG_ALWAYS("Continuing loading: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);

This only happens in case of redirect. This should probably says something like "Following redirect"

> Source/WebKit2/Platform/IPC/Connection.cpp:977
> +void Connection::reportResourceUsage()

This is still here? Can we at least split it into a different patch as I am worried about performance implications?

> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:174
> +    const char* url = resourceLoader->url().string().utf8().data();

Oh god, keeping a pointer to internal data of a temporary object :)
You want to use CString url = m_coreLoader->url().string().utf8();

> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:175
> +    LOG_ALWAYS("(WebProcess) WebLoaderStrategy::scheduleLoad, url '%s'/%p will be scheduled with the NetworkProcess with priority %d", url, url, static_cast<int>(resourceLoader->request().priority()));

Why is it useful to log the URL as a pointer?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:79
> +    const char* url = proposedRequest.url().string().utf8().data();

Same comment as above, this is wrong.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:80
> +    LOG_ALWAYS("(WebProcess) WebResourceLoader::willSendRequest to '%s'/%p", url, url);

Why is it useful to log the URL as a pointer?

Also, why are we logging URLs on WebContent process side but not Networking side?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:105
> +    const char* url = m_coreLoader->url().string().utf8().data();

Same comment as above, this is wrong.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:106
> +    LOG_ALWAYS("(WebProcess) WebResourceLoader::didReceiveResponse for '%s'/%p. Status %d.", url, url, response.httpStatusCode());

Why is it useful to log the URL as a pointer?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:139
> +    const char* url = m_coreLoader->url().string().utf8().data();

Same comment as above, this is wrong.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:140
> +    LOG_ALWAYS("(WebProcess) WebResourceLoader::didReceiveData of size %d for '%s'/%p", static_cast<int>(data.size()), url, url);

Why print the pointer?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:155
> +    const char* url = m_coreLoader->url().string().utf8().data();

Same comment as above, this is wrong.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:156
> +    LOG_ALWAYS("(WebProcess) WebResourceLoader::didFinishResourceLoad for '%s'/%p", url, url);

Why print the pointer?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:171
> +    const char* url = m_coreLoader->url().string().utf8().data();

Same comment as above, this is wrong.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:172
> +    LOG_ALWAYS("(WebProcess) WebResourceLoader::didFailResourceLoad for '%s'/%p", url, url);

Why print the pointer?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:188
> +    const char* url = m_coreLoader->url().string().utf8().data();

Same comment as above, this is wrong.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:189
> +    LOG_ALWAYS("(WebProcess) WebResourceLoader::didReceiveResource for '%s'/%p", url, url);

Why print the pointer?

[Chris Dumez]

Comment on attachment 272681 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=272681&action=review

>> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:174
>> +    const char* url = resourceLoader->url().string().utf8().data();
> 
> Oh god, keeping a pointer to internal data of a temporary object :)
> You want to use CString url = m_coreLoader->url().string().utf8();

Also I think we can just use latin1() since these are URLs.

[Chris Dumez]

Comment on attachment 272681 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=272681&action=review

This logging should probably be disabled for private / ephemeral sessions.

>>> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:174
>>> +    const char* url = resourceLoader->url().string().utf8().data();
>> 
>> Oh god, keeping a pointer to internal data of a temporary object :)
>> You want to use CString url = m_coreLoader->url().string().utf8();
> 
> Also I think we can just use latin1() since these are URLs.

Actually let's not log URLs at all.

[Keith Rollin]

(In reply to comment #6)
> Comment on attachment 272681 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=272681&action=review
> 
> > Source/WebCore/platform/MemoryPressureHandler.cpp:193
> > +        LOG_ALWAYS("Pressure relief: %s: -dirty %ld bytes (from %lu to %lu)", m_logString, (memoryDiff * -1), m_initialMemory, currentMemory);
> 
> If we called WTFLogAlways() instead of LOG_ALWAYS() (or in addition to) when
> s_loggingEnabled is true, then we could kill the platform-specific version.

OK.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:203
> > +    LOG_ALWAYS("Starting resource load: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> It may be interesting to know if this is a main resource:
> m_parameters.request.requester() == ResourceRequest::Requester::Main
> 
> Also, maybe this could clarify that it loads from the network, not the cache.

OK.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:276
> > +    LOG_ALWAYS("Received page headers: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> Received resource response:

OK.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:308
> > +            LOG_ALWAYS("Asking permission to continue: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> I don't really think we're asking permission to continue but we are waiting
> for a message to keep going. The reason I believe is that depending on the
> response, the WebContent process may decide to convert the resource load
> into a download (e.g. if the MIME type cannot be displayed in the view).
> This should probably say "Sending didReceiveResponse message to the
> WebContent process" or similar.

OK.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:310
> > +                LOG_ALWAYS("Permission to continue denied: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> It is not really that the permission was denied but rather that we failed to
> send the didReceiveResponse IPC message to the WebContent process.

OK

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:323
> > +        LOG_ALWAYS("Should continue: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> should continue what? I think the log message is not very clear on its own.
> I think we want something like:
> Should wait for message from WebContent process before continuing resource
> load? yes / no.

OK.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:359
> > +    LOG_ALWAYS("Finished loading: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> Why not log finishTime since we have it?

OK.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:438
> > +    LOG_ALWAYS("Continuing loading: pageID = %llu, frameID = %llu", m_parameters.webPageID, m_parameters.webFrameID);
> 
> This only happens in case of redirect. This should probably says something
> like "Following redirect"

OK.

> > Source/WebKit2/Platform/IPC/Connection.cpp:977
> > +void Connection::reportResourceUsage()
> 
> This is still here? Can we at least split it into a different patch as I am
> worried about performance implications?

OK.

> > Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:174
> > +    const char* url = resourceLoader->url().string().utf8().data();
> 
> Oh god, keeping a pointer to internal data of a temporary object :)
> You want to use CString url = m_coreLoader->url().string().utf8();

OK. I had simply copied that expression from when it was part of the subsequent logging statement, and didn't realize that a temporary was being created.

> > Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:175
> > +    LOG_ALWAYS("(WebProcess) WebLoaderStrategy::scheduleLoad, url '%s'/%p will be scheduled with the NetworkProcess with priority %d", url, url, static_cast<int>(resourceLoader->request().priority()));
> 
> Why is it useful to log the URL as a pointer?

Because we don't always log the string and we need something to thread together associated logging statements. (And, as we just discussed while I was typing this, we actually won't ever be logging the strings).

> Also I think we can just use latin1() since these are URLs.

I just made use of code that was previously there. I can change it to use latin1.

> Actually let's not log URLs at all.

With the "always on" logging no longer attempting to log urls ever, the previous debug-mode logging macros will be retained. Those will log urls, and those will be changed to call latin1.

[Keith Rollin]

Created attachment 273054 [details]
Patch

[Chris Dumez]

Comment on attachment 273054 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=273054&action=review

> Source/WebCore/loader/FrameLoader.cpp:143
> +#if LOG_ALWAYS_DISABLED

Why do we need this? LOG_ALWAYS() should already do nothing, no?

> Source/WebCore/loader/FrameLoader.cpp:1093
> +    FRAMELOADER_LOG_ALWAYS("Starting frame load, frame = %p, main = %d", &m_frame, static_cast<int>(m_frame.isMainFrame()));

I don't believe you need this static_cast.

> Source/WebCore/loader/FrameLoader.cpp:2274
> +            FRAMELOADER_LOG_ALWAYS("Committed frame load, frame = %p, main = %d", &m_frame, static_cast<int>(m_frame.isMainFrame()));

- I don't believe you need this static_cast.
- I would use "Finished frame load"
- You could also log the success state (see dl->mainDocumentError() handling below)

> Source/WebCore/loader/FrameLoader.h:299
> +    bool isLoggingAllowed() const;

Maybe we should rename to something less generic like isAlwaysOnLoggingAllowed() ?

> Source/WebCore/platform/MemoryPressureHandler.cpp:195
> +        MEMORYPRESSURE_LOG("Pressure relief: " STRING_SPECIFICATION ": (Unable to get dirty memory information for process)", m_logString);

We should probably use "Memory pressure relief:" as prefix here and below.

> Source/WebCore/platform/MemoryPressureHandler.h:93
>              , m_initialMemory(s_loggingEnabled ? platformMemoryUsage() : 0)

crazy thought, could we just set s_loggingEnabled to true when !LOG_ALWAYS_DISABLED and avoid all these #ifdefs?

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:49
> +#if LOG_ALWAYS_DISABLED

Why do we need this? LOG_ALWAYS() should already do nothing, no?

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:209
> +    NETWORKRESOURCELOADER_LOG_ALWAYS("Starting network resource load: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());

Since there can be several loads in a single frame, pageID/frameID does not uniquely identify a resource. You may want to add |this| pointer in there to identify specific resources.

You don't need to do this in this patch but we may want to log if it is a XHR as well (requester == XHR). Also maybe the request method (GET, POST, ...).

Also, it is interesting to know if the load is synchronous.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:282
> +    NETWORKRESOURCELOADER_LOG_ALWAYS("Received network resource response: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());

printing response.httpStatusCode() may be nice.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:316
> +                NETWORKRESOURCELOADER_LOG_ALWAYS("Failed to send the didReceiveResponse IPC message to the WebContent process: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());

Should this be a LOG ERROR?

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:365
> +    NETWORKRESOURCELOADER_LOG_ALWAYS("Finished loading network resource: pageID = %llu, frameID = %llu, isMainResource = %d, finishTime = %f", m_parameters.webPageID, m_parameters.webFrameID, isMainResource(), finishTime);

I think we want the unit for the finishTime.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:398
> +    NETWORKRESOURCELOADER_LOG_ALWAYS("Failed loading network resource: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());

May be nice to log if it is a cancellation, or a timeout. Those are common errors.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.h:101
> +    bool isMainResource() const { return m_parameters.request.requester() == WebCore::ResourceRequest::Requester::Main; }

Adding this utility function is nice but then you should update NetworkResourceLoader.cpp to use it in existing code as well.

> Source/WebKit2/Platform/IPC/Connection.cpp:37
> +#if LOG_ALWAYS_DISABLED

Why do we need this? LOG_ALWAYS() should already do nothing, no?

> Source/WebKit2/Platform/IPC/Connection.cpp:584
> +            CONNECTION_LOG_ALWAYS("Connection::waitForSyncReply: Connection no longer valid, id=%llu", syncRequestID);

Should this be a Log error?

> Source/WebKit2/Platform/IPC/Connection.cpp:595
> +    CONNECTION_LOG_ALWAYS("Connection::waitForSyncReply: Timed-out while waiting for reply, id=%llu", syncRequestID);

Should this be a LOG error?

> Source/WebKit2/Shared/ChildProcess.cpp:32
> +#if LOG_ALWAYS_DISABLED

Why do we need this? LOG_ALWAYS() should already do nothing, no?

> Source/WebKit2/Shared/ChildProcess.cpp:62
> +        CHILDPROCESS_LOG_ALWAYS("Exiting process early due to unacknowledged closed-connection");

Should this be a LOG Error?

> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:60
> +#if LOG_ALWAYS_DISABLED

Why do we need this? LOG_ALWAYS() should already do nothing, no?

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:85
> +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::willSendRequest to %p", &proposedRequest.url());

Would print |this| instead of the address of the URL.

Why the (WebProcess) prefix? Doesn't LOG_ALWAYS() already give us the info? If it does not, then other logging code should probably add such prefix too.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:109
> +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::didReceiveResponse for %p. Status %d.", &m_coreLoader->url(), response.httpStatusCode());

Would print |this| instead of the address of the URL.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:140
> +    LOG(Network, "(WebProcess) WebResourceLoader::didReceiveData of size %i for '%s'", (int)data.size(), m_coreLoader->url().string().latin1().data());

Please get rid of the C cast here too.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:141
> +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::didReceiveData of size %d for %p", static_cast<int>(data.size()), &m_coreLoader->url());

Would print |this| instead of the address of the URL.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:155
> +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::didFinishResourceLoad for %p", &m_coreLoader->url());

Would print |this| instead of the address of the URL.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:169
> +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::didFailResourceLoad for %p", &m_coreLoader->url());

Would print |this| instead of the address of the URL.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:184
> +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::didReceiveResource for %p", &m_coreLoader->url());

Would print |this| instead of the address of the URL.

[Keith Rollin]

(In reply to comment #11)
> > Source/WebCore/loader/FrameLoader.cpp:143
> > +#if LOG_ALWAYS_DISABLED
> 
> Why do we need this? LOG_ALWAYS() should already do nothing, no?

I had in mind the possibility that these macros might more complex than simple wrappers around LOG_ALWAYS. In that happened, we'd want local control over whether that complexity got included at the point where the macro was invoked or not. But since the macros are currently simple, I'll go ahead and remove the trappings around them.

> > Source/WebCore/loader/FrameLoader.cpp:1093
> > +    FRAMELOADER_LOG_ALWAYS("Starting frame load, frame = %p, main = %d", &m_frame, static_cast<int>(m_frame.isMainFrame()));
> 
> I don't believe you need this static_cast.

Yeah, I only recently satisfied myself on that. Even though I know from past experience that bools are promoted to ints in this context, I've never trusted that to happen. With all the problems that occur with mismatching formatting specifications with the corresponding values, I've gotten into the habit of explicitly casting those values. However, with compiler support of checking those values, I'm slowly "letting go" and letting the compiler help me there. I'll remove the static_casts.

> > Source/WebCore/loader/FrameLoader.cpp:2274
> > +            FRAMELOADER_LOG_ALWAYS("Committed frame load, frame = %p, main = %d", &m_frame, static_cast<int>(m_frame.isMainFrame()));
> 
> - I don't believe you need this static_cast.
> - I would use "Finished frame load"
> - You could also log the success state (see dl->mainDocumentError() handling
> below)

1 & 2) OK
3) I assumed that the logging of that error would occur elsewhere, either at the point where it happened or at a top level where it's ultimate handled. Should I confirm that rather than assuming?

> > Source/WebCore/loader/FrameLoader.h:299
> > +    bool isLoggingAllowed() const;
> 
> Maybe we should rename to something less generic like
> isAlwaysOnLoggingAllowed() ?

I don't have a problem with that.

> > Source/WebCore/platform/MemoryPressureHandler.cpp:195
> > +        MEMORYPRESSURE_LOG("Pressure relief: " STRING_SPECIFICATION ": (Unable to get dirty memory information for process)", m_logString);
> 
> We should probably use "Memory pressure relief:" as prefix here and below.

OK.

> > Source/WebCore/platform/MemoryPressureHandler.h:93
> >              , m_initialMemory(s_loggingEnabled ? platformMemoryUsage() : 0)
> 
> crazy thought, could we just set s_loggingEnabled to true when
> !LOG_ALWAYS_DISABLED and avoid all these #ifdefs?

It's so crazy that it just might work. But it doesn't. As you and I subsequently discussed offline, setting s_loggingEnabled to true doesn't work. Something comes along and sets it to False. You thought this might have something to do with a particular iOS Debug setting, but I was noticing this happen in my OS X testing, too. So I'm not sure why it's getting set to False, but it is. You and I then discussed perhaps adding some code to permanently pin it to True in ! LOG_ALWAYS_DISABLED mode, but at that point we're just re-introducing the #ifdefs we were trying to avoid.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:209
> > +    NETWORKRESOURCELOADER_LOG_ALWAYS("Starting network resource load: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());
> 
> Since there can be several loads in a single frame, pageID/frameID does not
> uniquely identify a resource. You may want to add |this| pointer in there to
> identify specific resources.

OK. 

> Also, it is interesting to know if the load is synchronous.

OK. 

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:282
> > +    NETWORKRESOURCELOADER_LOG_ALWAYS("Received network resource response: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());
> 
> printing response.httpStatusCode() may be nice.

Similar to mainDocumentError() above. Should I not assume that this is already logged or handled in some other way? If not, then perhaps we should create a new task that examines many aspects of WebKit and comprehensively handles the logging of errors.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:316
> > +                NETWORKRESOURCELOADER_LOG_ALWAYS("Failed to send the didReceiveResponse IPC message to the WebContent process: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());
> 
> Should this be a LOG ERROR?

Good idea.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:365
> > +    NETWORKRESOURCELOADER_LOG_ALWAYS("Finished loading network resource: pageID = %llu, frameID = %llu, isMainResource = %d, finishTime = %f", m_parameters.webPageID, m_parameters.webFrameID, isMainResource(), finishTime);
> 
> I think we want the unit for the finishTime.

What is it? This function is just passed a double. Should it be changed to some std::chrono type? I was told that that was our current standard.

Also, how is the value of finishTime different from the time of the logging statement?

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:398
> > +    NETWORKRESOURCELOADER_LOG_ALWAYS("Failed loading network resource: pageID = %llu, frameID = %llu, isMainResource = %d", m_parameters.webPageID, m_parameters.webFrameID, isMainResource());
> 
> May be nice to log if it is a cancellation, or a timeout. Those are common
> errors.

Same comment as above regarding the logging of errors. Great idea if it's not already being done, but might be nice to take a comprehensive approach rather than as an "as we notice the need" approach.

> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.h:101
> > +    bool isMainResource() const { return m_parameters.request.requester() == WebCore::ResourceRequest::Requester::Main; }
> 
> Adding this utility function is nice but then you should update
> NetworkResourceLoader.cpp to use it in existing code as well.

OK. I hadn't noticed that it was used elsewhere.

> > Source/WebKit2/Platform/IPC/Connection.cpp:584
> > +            CONNECTION_LOG_ALWAYS("Connection::waitForSyncReply: Connection no longer valid, id=%llu", syncRequestID);
> 
> Should this be a Log error?

I think they were, but that got lost in the latest refactoring. Thanks for catching that.

> > Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:85
> > +    WEBRESOURCELOADER_LOG_ALWAYS("(WebProcess) WebResourceLoader::willSendRequest to %p", &proposedRequest.url());
> 
> Would print |this| instead of the address of the URL.

I thought about that, but wasn't sure if it was the right move. Thanks for letting me know it's OK.

> Why the (WebProcess) prefix? Doesn't LOG_ALWAYS() already give us the info?
> If it does not, then other logging code should probably add such prefix too.

It's just left-over from the nearby logging code. It can be removed since the logging process is recorded. Also, after looking at the resulting logging, the "(WebProcess)" text kinda sticks out like a core thumb and should be removed for that reason alone.

> > Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:140
> > +    LOG(Network, "(WebProcess) WebResourceLoader::didReceiveData of size %i for '%s'", (int)data.size(), m_coreLoader->url().string().latin1().data());
> 
> Please get rid of the C cast here too.

I'll get rid of this and the subsequent static_cast and use the right formatting specifiers for the actual type.

[Keith Rollin]

(In reply to comment #12)
> 3) I assumed that the logging of that error would occur elsewhere, either at
> the point where it happened or at a top level where it's ultimate handled.
> Should I confirm that rather than assuming?

I'll go ahead and add logging of these error codes, but I'm also adding a new Bugzilla task to take a look at this comprehensively.

> > > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:365
> > > +    NETWORKRESOURCELOADER_LOG_ALWAYS("Finished loading network resource: pageID = %llu, frameID = %llu, isMainResource = %d, finishTime = %f", m_parameters.webPageID, m_parameters.webFrameID, isMainResource(), finishTime);
> > 
> > I think we want the unit for the finishTime.
> 
> What is it? This function is just passed a double. Should it be changed to
> some std::chrono type? I was told that that was our current standard.

didFinishLoading seems to be called with one of three inputs:

* Result of currentTime, which is basically gettimeofday(), or seconds in the UNIX epoch [2 instances]
* Result of monotonicallyIncreasingTime, which is a wrapper around currentTime [1 instance]
* Zero [15 instances]

[Keith Rollin]

Created attachment 273211 [details]
Patch

[Chris Dumez]

Comment on attachment 273211 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=273211&action=review

> Source/WebKit2/ChangeLog:10
> +        download activity.

I think this should be "resource load" rather than "resource download"

> Source/WebCore/loader/FrameLoader.cpp:2282
> +            FRAMELOADER_LOG_ALWAYS("Finished frame load, frame = %p, main = %d, isTimeout = %d, isCancellation = %d, errorCode = %d", &m_frame, m_frame.isMainFrame(), error.isTimeout(), error.isCancellation(), error.errorCode());

I would move the logging below with the error.isNull() check and split it in 2 log lines (1 for the error case, and 1 for the regular case) for clarity.
e.g. "Load finished without error" / "Load finished with error" + error logging

> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:203
> +    WEBLOADERSTRATEGY_LOG_ALWAYS("WebLoaderStrategy::scheduleLoad, pageID = %llu, frameID = %llu will be scheduled with the NetworkProcess with priority %d", loadParameters.webPageID, loadParameters.webFrameID, static_cast<int>(resourceLoader->request().priority()));

We have no way to map this to a specific WebResourceLoader logging happening later on. I think we should move this below and log the WebResourceLoader pointer to allow mapping.

> Source/WebKit2/WebProcess/Network/WebLoaderStrategy.cpp:207
>          // This load will never succeed so we will schedule it to fail asynchronously.

We should probably log this error.

> Source/WebKit2/WebProcess/Network/WebResourceLoader.cpp:81
> +    WEBRESOURCELOADER_LOG_ALWAYS("WebResourceLoader::willSendRequest to %p", this);

This message does not make much sense: "to %p". I think we should have something like: "WebResourceLoader = %p". Same comment for other logging in this file.

[Chris Dumez]

Note that your patch is not building on the EFL port as well:
https://webkit-queues.webkit.org/results/938282

[Keith Rollin]

Created attachment 273261 [details]
Patch

[Chris Dumez]

Comment on attachment 273261 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=273261&action=review

r=me with changes.

> Source/WebCore/loader/FrameLoader.cpp:2284
> +                FRAMELOADER_LOG_ALWAYS("Finished frame load without error, frame = %p, main = %d", &m_frame, m_frame.isMainFrame());

This should go in the else case :)

> Source/WebCore/loader/FrameLoader.cpp:2288
> +                FRAMELOADER_LOG_ALWAYS("Finished frame load with error, frame = %p, main = %d, isTimeout = %d, isCancellation = %d, errorCode = %d", &m_frame, m_frame.isMainFrame(), error.isTimeout(), error.isCancellation(), error.errorCode());

This should go in the if case.

> Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:325
> +    if (shouldContinueDidReceiveResponse)

Since you have an if / else now, I would break the ternary below and add the return statements to your if/else.

[Keith Rollin]

> Note that your patch is not building on the EFL port as well:

Crud.

(In reply to comment #18)
> Comment on attachment 273261 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=273261&action=review
> 
> r=me with changes.
> 
> > Source/WebCore/loader/FrameLoader.cpp:2284
> > +                FRAMELOADER_LOG_ALWAYS("Finished frame load without error, frame = %p, main = %d", &m_frame, m_frame.isMainFrame());
> 
> This should go in the else case :)
> 
> > Source/WebCore/loader/FrameLoader.cpp:2288
> > +                FRAMELOADER_LOG_ALWAYS("Finished frame load with error, frame = %p, main = %d, isTimeout = %d, isCancellation = %d, errorCode = %d", &m_frame, m_frame.isMainFrame(), error.isTimeout(), error.isCancellation(), error.errorCode());
> 
> This should go in the if case.
> 
> > Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp:325
> > +    if (shouldContinueDidReceiveResponse)
> 
> Since you have an if / else now, I would break the ternary below and add the
> return statements to your if/else.

Wilco.

[Keith Rollin]

Created attachment 273268 [details]
Patch

[WebKit Commit Bot]

Comment on attachment 273268 [details]
Patch

Clearing flags on attachment: 273268

Committed r197728: <http://trac.webkit.org/changeset/197728>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Csaba Osztrogonác]

(In reply to comment #21)
> Comment on attachment 273268 [details]
> Patch
> 
> Clearing flags on attachment: 273268
> 
> Committed r197728: <http://trac.webkit.org/changeset/197728>

It broke the build on many platforms:
- EFL Linux 64-bit Release WK2
   https://build.webkit.org/builders/EFL%20Linux%2064-bit%20Release%20WK2/builds/26929
- WinCairo 64-Bit Release
  https://build.webkit.org/builders/WinCairo%2064-Bit%20Release/builds/54692
- Apple Win Release (Build)
  https://build.webkit.org/builders/Apple%20Win%20Release%20%28Build%29/builds/76194

Please fix the builds ASAP.

[Csaba Osztrogonác]

Linux build fixes landed in
- http://trac.webkit.org/changeset/197750
- http://trac.webkit.org/changeset/197753

The Windows build is still broken. Please don't land 
patches with red EWS bubbles in the future! Thanks.