Bug 174062 – [WK2] Prevent ResourceLoadStatistics from triggering a cascade of read/write events

• Status: RESOLVED
• Resolution: FIXED
• Component: WebKit2

[Brent Fulgham]

We shouldn't allow the worker thread to consume high CPU resources. This worker should function as a background process, avoiding using the CPU when other work is going on.

[Brent Fulgham]

Created attachment 314351 [details]
Patch

[Radar WebKit Bug Importer]

<rdar://problem/33090466>

[Brent Fulgham]

Upon further review, I notice the following:

1. WebResourceLoadStatisticsStore::syncWithExistingStatisticsStorageIfNeeded causes a new FileMonitor to be created. This is currently only called as part of processStatisticsAndDataRecords(), where writeStoreToDisk() is called after we turn off file monitoring as part of an update to the data file. So this seems like it may cause an extra chain of reads to be triggered, which is wasteful.

2. The other place it might be called is setWritePersistentStoreCallback(), which doesn't ever seem to be used. Still, this closure to always stop monitoring before the write, and begin monitoring again after the write.

[Brent Fulgham]

Created attachment 314356 [details]
Patch

[Brent Fulgham]

After testing a bit, we should run this thread as a Utility QOS, not a full Background thread.

[Brent Fulgham]

Created attachment 314542 [details]
Patch

[Chris Dumez]

Comment on attachment 314542 [details]
Patch

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

> Source/WebCore/platform/cocoa/FileMonitorCocoa.mm:66
>          if (flag & DISPATCH_VNODE_DELETE) {

Shouldn't be treat DISPATCH_VNODE_RENAME (and DISPATCH_VNODE_REVOKE) the same way as a delete as well? I think our behavior should be the same wether the db file is removed or moved out of the way.
Also, should we really listen for DISPATCH_VNODE_EXTEND since we already listen for DISPATCH_VNODE_WRITE?

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:273
> +        return WallTime();

return { };

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:290
> +        if (!fileExists(resourceLog)) {

Could be merged with the previous if case.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:297
> +            // No need to grandfather in this case

Missing period at the end.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:389
> +    m_statisticsFileLastReadTime = WallTime::now();

It is weird to update a member called named m_statisticsFileLastReadTime from a writeToDisk() function.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:513
> +    if (!fileExists(resourceLog))

Could be merged in previous if case.

[Chris Dumez]

Comment on attachment 314542 [details]
Patch

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

> Source/WebKit2/ChangeLog:9
> +        We shouldn't allow the ResourceLoadStatistics worker thread to consume high CPU resources. Run it

While changing the work queue priority is probably a good thing here, I doubt this is the only fix needed for the extremely high CPU usage. You are changing a lot of things in this patch, could you please clarify what fixes the CPU usage issue and why?

[Brent Fulgham]

Comment on attachment 314542 [details]
Patch

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

>> Source/WebKit2/ChangeLog:9
>> +        We shouldn't allow the ResourceLoadStatistics worker thread to consume high CPU resources. Run it
> 
> While changing the work queue priority is probably a good thing here, I doubt this is the only fix needed for the extremely high CPU usage. You are changing a lot of things in this patch, could you please clarify what fixes the CPU usage issue and why?

We don't have a lot of control over how much CPU is used while reading/writing the data file. So, I tried to address the issue by preventing the process from doing the expensive operation more often than necessary.

1. The 'makeRefPtr' call in FileMonitor::startMonitoring captured a reference to itself, preventing the FileMonitor from being destroyed. This caused the file modification handler to fire in response to our own write events, creating a ridiculous read/write cycle. I'm sure this was a huge part of the problem. This was addressed by stopping the file monitor in WebResourceLoadStatisticsStore::stopMonitoringStatisticsStorage, rather than relying on the destructor to shut things down. Perhaps there is a tidier way to do so.
2. The work queue priority was higher than it needs to be for this process, which might have contributed to the problem.
3. I found that 'syncWithExistingStatisticsStoageIfNeeded' was creating a FileMonitor during our write operation, which exacerbated the chain of read/writes already present due to the self-reference I described above.
4. Because VNODE dispatch sources are low level, they do not offer a means of filtering out operations triggered by the current process. To avoid this, I added code to track the file modification time, so that we don't bother reading a file that holds data that is older than the in-memory data, even though we receive a file modification dispatch. Writes seem to trigger a chain of notification events in rapid succession. Once' we've responded to the first of these events, we don't need to to further reads until the data on disk changes again.

These changes may not prevent CF from using 100% cpu when serializing a file, but at least we will no longer have to experience this CPU use for long periods of time, or as a cascade of read/write/read events.

[Brent Fulgham]

Comment on attachment 314542 [details]
Patch

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

>> Source/WebCore/platform/cocoa/FileMonitorCocoa.mm:66
>>          if (flag & DISPATCH_VNODE_DELETE) {
> 
> Shouldn't be treat DISPATCH_VNODE_RENAME (and DISPATCH_VNODE_REVOKE) the same way as a delete as well? I think our behavior should be the same wether the db file is removed or moved out of the way.
> Also, should we really listen for DISPATCH_VNODE_EXTEND since we already listen for DISPATCH_VNODE_WRITE?

DISPATCH_VNODE_RENAME and DISPATCH_VNODE_REVOKE do make sense as DELETE proxies. I'll change that.

I wasn't sure if we received DISPATCH_VNODE_EXTEND in the absence of DISPATCH_VNODE_WRITE; I suppose it makes sense to ignore EXTEND if we are listening for WRITE since they seem to occur in close proximity during writes that make the file larger.

>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:273
>> +        return WallTime();
> 
> return { };

Will fix.

>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:290
>> +        if (!fileExists(resourceLog)) {
> 
> Could be merged with the previous if case.

OK.

>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:297
>> +            // No need to grandfather in this case
> 
> Missing period at the end.

Will fix.

>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:389
>> +    m_statisticsFileLastReadTime = WallTime::now();
> 
> It is weird to update a member called named m_statisticsFileLastReadTime from a writeToDisk() function.

I can rename it to "m_statisticsFileLastModificationTime". This is meant to avoid reading a file that contains no new information.

>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:513
>> +    if (!fileExists(resourceLog))
> 
> Could be merged in previous if case.

OK.

[Chris Dumez]

Comment on attachment 314542 [details]
Patch

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

>>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:389
>>> +    m_statisticsFileLastReadTime = WallTime::now();
>> 
>> It is weird to update a member called named m_statisticsFileLastReadTime from a writeToDisk() function.
> 
> I can rename it to "m_statisticsFileLastModificationTime". This is meant to avoid reading a file that contains no new information.

Or m_lastStatisticsFileSyncTime?

[Brent Fulgham]

(In reply to Chris Dumez from comment #11)
> Comment on attachment 314542 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=314542&action=review
> 
> >>> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:389
> >>> +    m_statisticsFileLastReadTime = WallTime::now();
> >> 
> >> It is weird to update a member called named m_statisticsFileLastReadTime from a writeToDisk() function.
> > 
> > I can rename it to "m_statisticsFileLastModificationTime". This is meant to avoid reading a file that contains no new information.
> 
> Or m_lastStatisticsFileSyncTime?

Yes! I'll use that.

[Brent Fulgham]

Created attachment 314613 [details]
Patch

[Chris Dumez]

Comment on attachment 314613 [details]
Patch

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

r=me with changes.

> Source/WebCore/platform/FileMonitor.h:53
> +#if USE(COCOA_EVENT_LOOP)

I wish we did not have to add an extra #if in this class' API. Do we really need to expose this?

> Source/WebCore/platform/cocoa/FileMonitorCocoa.mm:70
>          } else

Can we please ASSERT(flag & DISPATCH_VNODE_WRITE); in the else case?

> Source/WebKit2/ChangeLog:11
> +        (1) The 'makeRefPtr' call in FileMonitor::startMonitoring was capturing a reference to itself, preventing

As discussed offline, we should consider using a WeakPtr instead of a RefPtr to address this issue in a follow-up.

> Source/WebKit2/ChangeLog:17
> +        (2) 'syncWithExistingStatisticsStoageIfNeeded' was creating a FileMonitor during the write operation,

typo: stoage.

> Source/WebKit2/ChangeLog:27
> +        as a utility process, avoiding using the CPU when other work is going on.

s/as a utility process/as utility QoS/

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:291
> +        if (fileModificationTime <= m_lastStatisticsFileSyncTime) {

Can we move move these 2 lines to a utility method?
bool WebResourceLoadStatisticsStore::hasStatisticFileChangedSinceLastSync(path)
{
    return statisticsFileModificationTime(path) > m_lastStatisticsFileSyncTime;
}

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:292
> +            // No need to grandfather in this case.n

typo, extra 'n'.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:325
> +    WallTime fileModificationTime = statisticsFileModificationTime(resourceLog);

Could use utility function.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:336
> +    auto monitor = m_statisticsStorageMonitor ? m_statisticsStorageMonitor->platformMonitor() : nullptr;

This means non-cocoa WK2 ports will no longer be able to enable logging at compile time. I don't think we should expose the underlying monitor.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:430
> +    auto monitor = m_statisticsStorageMonitor ? m_statisticsStorageMonitor->platformMonitor() : nullptr;

Ditto about build breakage for other ports.

> Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp:492
> +    // The FileMonitor captures itself, incrementing its refcount. Manually stopping the monitor shuts down the lambda holding the extra

Should probably be a FIXME comment.

[Brent Fulgham]

Committed r219144: <http://trac.webkit.org/changeset/219144>