- Revision
- 219144
- Author
- bfulg...@apple.com
- Date
- 2017-07-05 12:05:24 -0700 (Wed, 05 Jul 2017)
Log Message
[WK2] Prevent ResourceLoadStatistics from triggering a cascade of read/write events
https://bugs.webkit.org/show_bug.cgi?id=174062\
<rdar://problem/33086744>
Reviewed by Chris Dumez.
Source/WebCore:
Treat DISPATCH_VNODE_DELETE, DISPATCH_VNODE_RENAME, and DISPATCH_VNODE_REVOKE as equivalent
"file is unavailable" events, and act as though the file was deleted. Don't listen for
DISPATCH_VNODE_EXTEND, since we always get a DISPATCH_VNODE_WRITE as well, and we only
want to read once.
Finally, add some logging to support future investigations.
* platform/FileMonitor.h:
(WebCore::FileMonitor::platformMonitor): Expose dispatch_source_t for logging purposes.
* platform/cocoa/FileMonitorCocoa.mm:
(WebCore::FileMonitor::startMonitoring): Add logging.
(WebCore::FileMonitor::stopMonitoring): Ditto.
Source/WebKit2:
ResourceLoadStatistics was triggering periods of high CPU use due to a cascade of read/write
operations:
(1) The 'makeRefPtr' call in FileMonitor::startMonitoring was capturing 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. This problem was addressed in
the short term by stopping the file monitor in WebResourceLoadStatisticsStore::stopMonitoringStatisticsStorage,
rather than relying on the destructor to shut things down. This will be improved in a
subsequent patch.
(2) 'syncWithExistingStatisticsStorageIfNeeded' was creating a FileMonitor during the write operation,
which exacerbated the chain of read/writes already present due to the self-reference described above.
(3) 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.
We also shouldn't allow the ResourceLoadStatistics worker thread to consume high CPU resources. Run it
as utility QoS, avoiding using the CPU when other work is going on.
Drive-by fix: The closure in setWritePersistentStoreCallback() should stop monitoring before writing
data, and should start monitoring after the write completes.
* UIProcess/WebResourceLoadStatisticsStore.cpp:
(WebKit::WebResourceLoadStatisticsStore::WebResourceLoadStatisticsStore): Run our worker queue
as a utility-level process.
(WebKit::WebResourceLoadStatisticsStore::registerSharedResourceLoadObserver): Stop checking for
updates before writing, and begin checking again once the write is complete.
(WebKit::WebResourceLoadStatisticsStore::statisticsFileModificationTime): Added.
(WebKit::WebResourceLoadStatisticsStore::readDataFromDiskIfNeeded): Avoid reading the file if it
was last modified on (or before) the time we last read the file.
(WebKit::WebResourceLoadStatisticsStore::refreshFromDisk): Ditto.
(WebKit::WebResourceLoadStatisticsStore::stopMonitoringStatisticsStorage): Explicitly stop file
monitoring so that the active file modification handler will terminate.
(WebKit::WebResourceLoadStatisticsStore::syncWithExistingStatisticsStorageIfNeeded): Do not begin
monitoring the file after syncing, since this is only used as part of an ongoing write operation.
Modified Paths
Diff
Modified: trunk/Source/WebCore/ChangeLog (219143 => 219144)
--- trunk/Source/WebCore/ChangeLog 2017-07-05 18:40:18 UTC (rev 219143)
+++ trunk/Source/WebCore/ChangeLog 2017-07-05 19:05:24 UTC (rev 219144)
@@ -1,3 +1,24 @@
+2017-07-05 Brent Fulgham <bfulg...@apple.com>
+
+ [WK2] Prevent ResourceLoadStatistics from triggering a cascade of read/write events
+ https://bugs.webkit.org/show_bug.cgi?id=174062\
+ <rdar://problem/33086744>
+
+ Reviewed by Chris Dumez.
+
+ Treat DISPATCH_VNODE_DELETE, DISPATCH_VNODE_RENAME, and DISPATCH_VNODE_REVOKE as equivalent
+ "file is unavailable" events, and act as though the file was deleted. Don't listen for
+ DISPATCH_VNODE_EXTEND, since we always get a DISPATCH_VNODE_WRITE as well, and we only
+ want to read once.
+
+ Finally, add some logging to support future investigations.
+
+ * platform/FileMonitor.h:
+ (WebCore::FileMonitor::platformMonitor): Expose dispatch_source_t for logging purposes.
+ * platform/cocoa/FileMonitorCocoa.mm:
+ (WebCore::FileMonitor::startMonitoring): Add logging.
+ (WebCore::FileMonitor::stopMonitoring): Ditto.
+
2017-07-05 Jonathan Bedard <jbed...@apple.com>
Add WebKitPrivateFrameworkStubs for iOS 11
Modified: trunk/Source/WebCore/platform/cocoa/FileMonitorCocoa.mm (219143 => 219144)
--- trunk/Source/WebCore/platform/cocoa/FileMonitorCocoa.mm 2017-07-05 18:40:18 UTC (rev 219143)
+++ trunk/Source/WebCore/platform/cocoa/FileMonitorCocoa.mm 2017-07-05 19:05:24 UTC (rev 219144)
@@ -33,8 +33,9 @@
namespace WebCore {
-constexpr unsigned monitorMask = DISPATCH_VNODE_DELETE | DISPATCH_VNODE_WRITE | DISPATCH_VNODE_EXTEND | DISPATCH_VNODE_RENAME | DISPATCH_VNODE_REVOKE;
-
+constexpr unsigned monitorMask = DISPATCH_VNODE_DELETE | DISPATCH_VNODE_WRITE | DISPATCH_VNODE_RENAME | DISPATCH_VNODE_REVOKE;
+constexpr unsigned fileUnavailableMask = DISPATCH_VNODE_DELETE | DISPATCH_VNODE_RENAME | DISPATCH_VNODE_REVOKE;
+
void FileMonitor::startMonitoring()
{
if (m_platformMonitor)
@@ -53,7 +54,9 @@
}
m_platformMonitor = adoptDispatch(dispatch_source_create(DISPATCH_SOURCE_TYPE_VNODE, handle, monitorMask, m_handlerQueue->dispatchQueue()));
-
+
+ LOG(ResourceLoadStatistics, "Creating monitor %p", m_platformMonitor.get());
+
dispatch_source_set_event_handler(m_platformMonitor.get(), [this, protectedThis = makeRefPtr(this), fileMonitor = m_platformMonitor.get()] () mutable {
// If this is getting called after the monitor was cancelled, just drop the notification.
if (dispatch_source_testcancel(fileMonitor))
@@ -60,11 +63,14 @@
return;
unsigned flag = dispatch_source_get_data(fileMonitor);
- if (flag & DISPATCH_VNODE_DELETE) {
+ LOG(ResourceLoadStatistics, "File event %#X for monitor %p", flag, fileMonitor);
+ if (flag & fileUnavailableMask) {
m_modificationHandler(FileChangeType::Removal);
dispatch_source_cancel(fileMonitor);
- } else
+ } else {
+ ASSERT(flag & DISPATCH_VNODE_WRITE);
m_modificationHandler(FileChangeType::Modification);
+ }
});
dispatch_source_set_cancel_handler(m_platformMonitor.get(), [fileMonitor = m_platformMonitor.get()] {
@@ -79,7 +85,9 @@
{
if (!m_platformMonitor)
return;
-
+
+ LOG(ResourceLoadStatistics, "Stopping monitor %p", m_platformMonitor.get());
+
dispatch_source_cancel(m_platformMonitor.get());
m_platformMonitor = nullptr;
}
Modified: trunk/Source/WebKit2/ChangeLog (219143 => 219144)
--- trunk/Source/WebKit2/ChangeLog 2017-07-05 18:40:18 UTC (rev 219143)
+++ trunk/Source/WebKit2/ChangeLog 2017-07-05 19:05:24 UTC (rev 219144)
@@ -1,3 +1,48 @@
+2017-07-05 Brent Fulgham <bfulg...@apple.com>
+
+ [WK2] Prevent ResourceLoadStatistics from triggering a cascade of read/write events
+ https://bugs.webkit.org/show_bug.cgi?id=174062\
+ <rdar://problem/33086744>
+
+ Reviewed by Chris Dumez.
+
+ ResourceLoadStatistics was triggering periods of high CPU use due to a cascade of read/write
+ operations:
+ (1) The 'makeRefPtr' call in FileMonitor::startMonitoring was capturing 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. This problem was addressed in
+ the short term by stopping the file monitor in WebResourceLoadStatisticsStore::stopMonitoringStatisticsStorage,
+ rather than relying on the destructor to shut things down. This will be improved in a
+ subsequent patch.
+ (2) 'syncWithExistingStatisticsStorageIfNeeded' was creating a FileMonitor during the write operation,
+ which exacerbated the chain of read/writes already present due to the self-reference described above.
+ (3) 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.
+
+ We also shouldn't allow the ResourceLoadStatistics worker thread to consume high CPU resources. Run it
+ as utility QoS, avoiding using the CPU when other work is going on.
+
+ Drive-by fix: The closure in setWritePersistentStoreCallback() should stop monitoring before writing
+ data, and should start monitoring after the write completes.
+
+ * UIProcess/WebResourceLoadStatisticsStore.cpp:
+ (WebKit::WebResourceLoadStatisticsStore::WebResourceLoadStatisticsStore): Run our worker queue
+ as a utility-level process.
+ (WebKit::WebResourceLoadStatisticsStore::registerSharedResourceLoadObserver): Stop checking for
+ updates before writing, and begin checking again once the write is complete.
+ (WebKit::WebResourceLoadStatisticsStore::statisticsFileModificationTime): Added.
+ (WebKit::WebResourceLoadStatisticsStore::readDataFromDiskIfNeeded): Avoid reading the file if it
+ was last modified on (or before) the time we last read the file.
+ (WebKit::WebResourceLoadStatisticsStore::refreshFromDisk): Ditto.
+ (WebKit::WebResourceLoadStatisticsStore::stopMonitoringStatisticsStorage): Explicitly stop file
+ monitoring so that the active file modification handler will terminate.
+ (WebKit::WebResourceLoadStatisticsStore::syncWithExistingStatisticsStorageIfNeeded): Do not begin
+ monitoring the file after syncing, since this is only used as part of an ongoing write operation.
+
2017-07-05 Jonathan Bedard <jbed...@apple.com>
Add WebKitPrivateFrameworkStubs for iOS 11
Modified: trunk/Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp (219143 => 219144)
--- trunk/Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp 2017-07-05 18:40:18 UTC (rev 219143)
+++ trunk/Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.cpp 2017-07-05 19:05:24 UTC (rev 219144)
@@ -43,6 +43,7 @@
#include <wtf/NeverDestroyed.h>
#include <wtf/RunLoop.h>
#include <wtf/Seconds.h>
+#include <wtf/WallTime.h>
#include <wtf/threads/BinarySemaphore.h>
#if PLATFORM(COCOA)
@@ -93,7 +94,7 @@
WebResourceLoadStatisticsStore::WebResourceLoadStatisticsStore(const String& resourceLoadStatisticsDirectory)
: m_resourceLoadStatisticsStore(ResourceLoadStatisticsStore::create())
- , m_statisticsQueue(WorkQueue::create("WebResourceLoadStatisticsStore Process Data Queue"))
+ , m_statisticsQueue(WorkQueue::create("WebResourceLoadStatisticsStore Process Data Queue", WorkQueue::Type::Serial, WorkQueue::QOS::Utility))
, m_statisticsStoragePath(resourceLoadStatisticsDirectory)
, m_telemetryOneShotTimer(RunLoop::main(), this, &WebResourceLoadStatisticsStore::telemetryTimerFired)
, m_telemetryRepeatedTimer(RunLoop::main(), this, &WebResourceLoadStatisticsStore::telemetryTimerFired)
@@ -219,7 +220,9 @@
});
m_resourceLoadStatisticsStore->setWritePersistentStoreCallback([this, protectedThis = makeRef(*this)] {
m_statisticsQueue->dispatch([this, protectedThis = protectedThis.copyRef()] {
+ stopMonitoringStatisticsStorage();
writeStoreToDisk();
+ startMonitoringStatisticsStorage();
});
});
m_resourceLoadStatisticsStore->setGrandfatherExistingWebsiteDataCallback([this, protectedThis = makeRef(*this)] {
@@ -262,6 +265,21 @@
});
}
+WallTime WebResourceLoadStatisticsStore::statisticsFileModificationTime(const String& path) const
+{
+ ASSERT(!RunLoop::isMain());
+ time_t modificationTime;
+ if (!getFileModificationTime(path, modificationTime))
+ return { };
+
+ return WallTime::fromRawSeconds(modificationTime);
+}
+
+bool WebResourceLoadStatisticsStore::hasStatisticsFileChangedSinceLastSync(const String& path)
+{
+ return statisticsFileModificationTime(path) > m_lastStatisticsFileSyncTime;
+}
+
void WebResourceLoadStatisticsStore::readDataFromDiskIfNeeded()
{
if (!m_resourceLoadStatisticsEnabled)
@@ -268,7 +286,20 @@
return;
m_statisticsQueue->dispatch([this, protectedThis = makeRef(*this)] {
- auto decoder = createDecoderFromDisk(ASCIILiteral("full_browsing_session"));
+ String resourceLog = persistentStoragePath(ASCIILiteral("full_browsing_session"));
+ if (resourceLog.isEmpty() || !fileExists(resourceLog)) {
+ grandfatherExistingWebsiteData();
+ return;
+ }
+
+ if (!hasStatisticsFileChangedSinceLastSync(resourceLog)) {
+ // No need to grandfather in this case.
+ return;
+ }
+
+ WallTime readTime = WallTime::now();
+
+ auto decoder = createDecoderFromDisk(resourceLog);
if (!decoder) {
grandfatherExistingWebsiteData();
return;
@@ -277,6 +308,8 @@
coreStore().clearInMemory();
coreStore().readDataFromDecoder(*decoder);
+ m_lastStatisticsFileSyncTime = readTime;
+
if (coreStore().isEmpty())
grandfatherExistingWebsiteData();
});
@@ -285,11 +318,25 @@
void WebResourceLoadStatisticsStore::refreshFromDisk()
{
ASSERT(!RunLoop::isMain());
- auto decoder = createDecoderFromDisk(ASCIILiteral("full_browsing_session"));
+
+ String resourceLog = persistentStoragePath(ASCIILiteral("full_browsing_session"));
+ if (resourceLog.isEmpty())
+ return;
+
+ // We sometimes see file changed events from before our load completed (we start
+ // reading at the first change event, but we might receive a series of events related
+ // to the same file operation). Catch this case to avoid reading overly often.
+ if (!hasStatisticsFileChangedSinceLastSync(resourceLog))
+ return;
+
+ WallTime readTime = WallTime::now();
+
+ auto decoder = createDecoderFromDisk(resourceLog);
if (!decoder)
return;
coreStore().readDataFromDecoder(*decoder);
+ m_lastStatisticsFileSyncTime = readTime;
}
void WebResourceLoadStatisticsStore::processWillOpenConnection(WebProcessProxy&, IPC::Connection& connection)
@@ -328,7 +375,11 @@
syncWithExistingStatisticsStorageIfNeeded();
auto encoder = coreStore().createEncoderFromData();
- writeEncoderToDisk(*encoder.get(), "full_browsing_session");
+
+ String resourceLog = persistentStoragePath(ASCIILiteral("full_browsing_session"));
+ writeEncoderToDisk(*encoder.get(), resourceLog);
+
+ m_lastStatisticsFileSyncTime = WallTime::now();
}
static PlatformFileHandle openAndLockFile(const String& path, FileOpenMode mode)
@@ -356,7 +407,7 @@
closeFile(handle);
}
-void WebResourceLoadStatisticsStore::writeEncoderToDisk(KeyedEncoder& encoder, const String& label) const
+void WebResourceLoadStatisticsStore::writeEncoderToDisk(KeyedEncoder& encoder, const String& path) const
{
ASSERT(!RunLoop::isMain());
@@ -364,16 +415,12 @@
if (!rawData)
return;
- String resourceLog = persistentStoragePath(label);
- if (resourceLog.isEmpty())
- return;
-
if (!m_statisticsStoragePath.isEmpty()) {
makeAllDirectories(m_statisticsStoragePath);
platformExcludeFromBackup();
}
- auto handle = openAndLockFile(resourceLog, OpenForWrite);
+ auto handle = openAndLockFile(path, OpenForWrite);
if (handle == invalidPlatformFileHandle)
return;
@@ -432,6 +479,12 @@
void WebResourceLoadStatisticsStore::stopMonitoringStatisticsStorage()
{
ASSERT(!RunLoop::isMain());
+ if (!m_statisticsStorageMonitor)
+ return;
+
+ // FIXME(174166): The FileMonitor captures itself, incrementing its refcount. Manually stopping the monitor shuts down the lambda holding the extra
+ // reference, so the object will be cleaned up properly.
+ m_statisticsStorageMonitor->stopMonitoring();
m_statisticsStorageMonitor = nullptr;
}
@@ -440,10 +493,12 @@
ASSERT(!RunLoop::isMain());
if (m_statisticsStorageMonitor)
return;
-
+
+ String resourceLog = persistentStoragePath(ASCIILiteral("full_browsing_session"));
+ if (resourceLog.isEmpty() || !fileExists(resourceLog))
+ return;
+
refreshFromDisk();
-
- startMonitoringStatisticsStorage();
}
@@ -454,14 +509,10 @@
}
#endif
-std::unique_ptr<KeyedDecoder> WebResourceLoadStatisticsStore::createDecoderFromDisk(const String& label) const
+std::unique_ptr<KeyedDecoder> WebResourceLoadStatisticsStore::createDecoderFromDisk(const String& path) const
{
ASSERT(!RunLoop::isMain());
- String resourceLog = persistentStoragePath(label);
- if (resourceLog.isEmpty())
- return nullptr;
-
- auto handle = openAndLockFile(resourceLog, OpenForRead);
+ auto handle = openAndLockFile(path, OpenForRead);
if (handle == invalidPlatformFileHandle)
return nullptr;
Modified: trunk/Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.h (219143 => 219144)
--- trunk/Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.h 2017-07-05 18:40:18 UTC (rev 219143)
+++ trunk/Source/WebKit2/UIProcess/WebResourceLoadStatisticsStore.h 2017-07-05 19:05:24 UTC (rev 219144)
@@ -40,6 +40,7 @@
#endif
namespace WTF {
+class WallTime;
class WorkQueue;
}
@@ -121,8 +122,9 @@
void grandfatherExistingWebsiteData();
void writeStoreToDisk();
- void writeEncoderToDisk(WebCore::KeyedEncoder&, const String& label) const;
- std::unique_ptr<WebCore::KeyedDecoder> createDecoderFromDisk(const String& label) const;
+ void writeEncoderToDisk(WebCore::KeyedEncoder&, const String& path) const;
+ std::unique_ptr<WebCore::KeyedDecoder> createDecoderFromDisk(const String& path) const;
+ WallTime statisticsFileModificationTime(const String& label) const;
void platformExcludeFromBackup() const;
void deleteStoreFromDisk();
void clearInMemoryData();
@@ -130,6 +132,7 @@
void refreshFromDisk();
void telemetryTimerFired();
void submitTelemetry();
+ bool hasStatisticsFileChangedSinceLastSync(const String& path);
#if PLATFORM(COCOA)
void registerUserDefaultsIfNeeded();
@@ -144,6 +147,7 @@
Ref<WTF::WorkQueue> m_statisticsQueue;
RefPtr<WebCore::FileMonitor> m_statisticsStorageMonitor;
String m_statisticsStoragePath;
+ WTF::WallTime m_lastStatisticsFileSyncTime;
bool m_resourceLoadStatisticsEnabled { false };
RunLoop::Timer<WebResourceLoadStatisticsStore> m_telemetryOneShotTimer;
RunLoop::Timer<WebResourceLoadStatisticsStore> m_telemetryRepeatedTimer;
