[WK2] Add logging to validate the network cache efficacy (Part 2)
authorcdumez@apple.com <cdumez@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 11 Feb 2015 02:31:49 +0000 (02:31 +0000)
committercdumez@apple.com <cdumez@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 11 Feb 2015 02:31:49 +0000 (02:31 +0000)
https://bugs.webkit.org/show_bug.cgi?id=141345
Source/WebCore:

Reviewed by Antti Koivisto.

Add a few more diagnostic logging keys for the network cache efficacy
logging.

Source/WebKit2:

<rdar://problem/19632080>

Reviewed by Antti Koivisto.

Add diagnostic logging messages to validate the network cache efficacy.
The following 4 messages are added:
- networkCache / retrieval / success
- networkCache / retrieval / unhandledRequestFailure
- networkCache / retrieval / noLongerInCacheFailure
- networkCache / retrieval / unusableCachedEntryFailure

The messages are sent via IPC from the NetworkProcess to the UIProcess,
where the WebPageProxy code already handles diagnostic messages sent by
the WebProcess.

git-svn-id: http://svn.webkit.org/repository/webkit/trunk@179910 268f45cc-cd09-0410-ab3c-d52691b4dbfc

17 files changed:
Source/WebCore/ChangeLog
Source/WebCore/WebCore.exp.in
Source/WebCore/page/DiagnosticLoggingKeys.cpp
Source/WebCore/page/DiagnosticLoggingKeys.h
Source/WebCore/platform/sql/SQLiteDatabaseTracker.h
Source/WebKit2/ChangeLog
Source/WebKit2/NetworkProcess/NetworkProcess.cpp
Source/WebKit2/NetworkProcess/NetworkProcess.h
Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp
Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp
Source/WebKit2/NetworkProcess/cache/NetworkCache.h
Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h
Source/WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm
Source/WebKit2/UIProcess/Network/NetworkProcessProxy.cpp
Source/WebKit2/UIProcess/Network/NetworkProcessProxy.h
Source/WebKit2/UIProcess/Network/NetworkProcessProxy.messages.in
Source/WebKit2/UIProcess/WebPageProxy.h

index 2ef8491..c1076e6 100644 (file)
@@ -1,3 +1,13 @@
+2015-02-10  Chris Dumez  <cdumez@apple.com>
+
+        [WK2] Add logging to validate the network cache efficacy (Part 2)
+        https://bugs.webkit.org/show_bug.cgi?id=141345
+
+        Reviewed by Antti Koivisto.
+
+        Add a few more diagnostic logging keys for the network cache efficacy
+        logging.
+
 2015-02-10  Commit Queue  <commit-queue@webkit.org>
 
         Unreviewed, rolling out r179896.
index c003730..e30d5f2 100644 (file)
@@ -945,6 +945,11 @@ __ZN7WebCore21BlobDataFileReferenceD2Ev
 __ZN7WebCore21CrossThreadCopierBaseILb0ELb0EN3WTF6StringEE4copyERKS2_
 __ZN7WebCore21CrossThreadCopierBaseILb0ELb0ENS_19IDBDatabaseMetadataEE4copyERKS1_
 __ZN7WebCore21DiagnosticLoggingKeys10webViewKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys12retrievalKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys15networkCacheKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys25noLongerInCacheFailureKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys26unhandledRequestFailureKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys29unusableCachedEntryFailureKeyEv
 __ZN7WebCore21DiagnosticLoggingKeys7userKeyEv
 __ZN7WebCore21DiagnosticLoggingKeys9zoomedKeyEv
 __ZN7WebCore21DisplayRefreshMonitor46handleDisplayRefreshedNotificationOnMainThreadEPv
index 4645f72..39ff5d8 100644 (file)
@@ -103,6 +103,11 @@ String DiagnosticLoggingKeys::navigationKey()
     return ASCIILiteral("navigation");
 }
 
+String DiagnosticLoggingKeys::networkCacheKey()
+{
+    return ASCIILiteral("networkCache");
+}
+
 String DiagnosticLoggingKeys::networkKey()
 {
     return ASCIILiteral("network");
@@ -133,6 +138,11 @@ String DiagnosticLoggingKeys::noDocumentLoaderKey()
     return ASCIILiteral("noDocumentLoader");
 }
 
+String DiagnosticLoggingKeys::noLongerInCacheFailureKey()
+{
+    return ASCIILiteral("noLongerInCacheFailure");
+}
+
 String DiagnosticLoggingKeys::otherKey()
 {
     return ASCIILiteral("other");
@@ -298,6 +308,11 @@ String DiagnosticLoggingKeys::resourceResponseKey()
     return ASCIILiteral("resourceResponse");
 }
 
+String DiagnosticLoggingKeys::retrievalKey()
+{
+    return ASCIILiteral("retrieval");
+}
+
 String DiagnosticLoggingKeys::revalidatingKey()
 {
     return ASCIILiteral("revalidating");
@@ -333,6 +348,16 @@ String DiagnosticLoggingKeys::svgDocumentKey()
     return ASCIILiteral("svgDocument");
 }
 
+String DiagnosticLoggingKeys::unhandledRequestFailureKey()
+{
+    return ASCIILiteral("unhandledRequestFailure");
+}
+
+String DiagnosticLoggingKeys::unusableCachedEntryFailureKey()
+{
+    return ASCIILiteral("unusableCachedEntryFailure");
+}
+
 String DiagnosticLoggingKeys::unusedKey()
 {
     return ASCIILiteral("unused");
index 92b2d3e..f9ca21d 100644 (file)
@@ -63,10 +63,12 @@ public:
     static String mediaLoadingFailedKey();
     static String mustRevalidateIsExpiredKey();
     static String navigationKey();
+    WEBCORE_EXPORT static String networkCacheKey();
     static String networkKey();
     static String noCacheKey();
     static String noCurrentHistoryItemKey();
     static String noDocumentLoaderKey();
+    WEBCORE_EXPORT static String noLongerInCacheFailureKey();
     static String noStoreKey();
     static String notInMemoryCacheKey();
     static String otherKey();
@@ -90,12 +92,15 @@ public:
     static String resourceKey();
     static String resourceRequestKey();
     static String resourceResponseKey();
+    WEBCORE_EXPORT static String retrievalKey();
     static String revalidatingKey();
     static String sameLoadKey();
     static String scriptKey();
     static String sourceKey();
     static String styleSheetKey();
     static String svgDocumentKey();
+    WEBCORE_EXPORT static String unhandledRequestFailureKey();
+    WEBCORE_EXPORT static String unusableCachedEntryFailureKey();
     static String unusedKey();
     static String unusedReasonCredentialSettingsKey();
     static String unusedReasonErrorKey();
index 1e4392f..45b01c6 100644 (file)
@@ -38,7 +38,7 @@ WEBCORE_EXPORT void incrementTransactionInProgressCount();
 WEBCORE_EXPORT void setClient(SQLiteDatabaseTrackerClient*);
 
 #if !ASSERT_DISABLED
-bool hasTransactionInProgress();
+WEBCORE_EXPORT bool hasTransactionInProgress();
 #endif
 
 };
index c9026f6..a0246a4 100644 (file)
@@ -1,3 +1,22 @@
+2015-02-10  Chris Dumez  <cdumez@apple.com>
+
+        [WK2] Add logging to validate the network cache efficacy (Part 2)
+        https://bugs.webkit.org/show_bug.cgi?id=141345
+        <rdar://problem/19632080>
+
+        Reviewed by Antti Koivisto.
+
+        Add diagnostic logging messages to validate the network cache efficacy.
+        The following 4 messages are added:
+        - networkCache / retrieval / success
+        - networkCache / retrieval / unhandledRequestFailure
+        - networkCache / retrieval / noLongerInCacheFailure
+        - networkCache / retrieval / unusableCachedEntryFailure
+
+        The messages are sent via IPC from the NetworkProcess to the UIProcess,
+        where the WebPageProxy code already handles diagnostic messages sent by
+        the WebProcess.
+
 2015-02-10  Conrad Shultz  <conrad_shultz@apple.com>
 
         Clients need the ability to hook into immediate action lifecycle
index 69a6383..2c90b02 100644 (file)
@@ -301,6 +301,21 @@ void NetworkProcess::getNetworkProcessStatistics(uint64_t callbackID)
     parentProcessConnection()->send(Messages::WebProcessPool::DidGetStatistics(data, callbackID), 0);
 }
 
+void NetworkProcess::logDiagnosticMessage(uint64_t webPageID, const String& message, const String& description)
+{
+    parentProcessConnection()->send(Messages::NetworkProcessProxy::LogDiagnosticMessage(webPageID, message, description), 0);
+}
+
+void NetworkProcess::logDiagnosticMessageWithResult(uint64_t webPageID, const String& message, const String& description, WebCore::DiagnosticLoggingResultType result)
+{
+    parentProcessConnection()->send(Messages::NetworkProcessProxy::LogDiagnosticMessageWithResult(webPageID, message, description, result), 0);
+}
+
+void NetworkProcess::logDiagnosticMessageWithValue(uint64_t webPageID, const String& message, const String& description, const String& value)
+{
+    parentProcessConnection()->send(Messages::NetworkProcessProxy::LogDiagnosticMessageWithValue(webPageID, message, description, value), 0);
+}
+
 void NetworkProcess::terminate()
 {
     platformTerminate();
index ad1e291..c9db647 100644 (file)
@@ -33,6 +33,7 @@
 #include "DownloadManager.h"
 #include "MessageReceiverMap.h"
 #include "NetworkResourceLoadScheduler.h"
+#include <WebCore/DiagnosticLoggingResultType.h>
 #include <WebCore/SessionID.h>
 #include <memory>
 #include <wtf/Forward.h>
@@ -75,6 +76,11 @@ public:
     DownloadManager& downloadManager();
     bool canHandleHTTPSServerTrustEvaluation() const { return m_canHandleHTTPSServerTrustEvaluation; }
 
+    // Diagnostic messages logging.
+    void logDiagnosticMessage(uint64_t webPageID, const String& message, const String& description);
+    void logDiagnosticMessageWithResult(uint64_t webPageID, const String& message, const String& description, WebCore::DiagnosticLoggingResultType);
+    void logDiagnosticMessageWithValue(uint64_t webPageID, const String& message, const String& description, const String& value);
+
 private:
     NetworkProcess();
     ~NetworkProcess();
index 01ac936..a3d0c86 100644 (file)
@@ -141,7 +141,7 @@ void NetworkResourceLoader::start()
     }
 
     RefPtr<NetworkResourceLoader> loader(this);
-    NetworkCache::singleton().retrieve(originalRequest(), [loader](std::unique_ptr<NetworkCache::Entry> entry) {
+    NetworkCache::singleton().retrieve(originalRequest(), m_parameters.webPageID, [loader](std::unique_ptr<NetworkCache::Entry> entry) {
         if (loader->hasOneRef()) {
             // The loader has been aborted and is only held alive by this lambda.
             return;
index d4770aa..33b1656 100644 (file)
@@ -218,7 +218,7 @@ static NetworkCacheKey makeCacheKey(const WebCore::ResourceRequest& request)
     return NetworkCacheKey(request.httpMethod(), partition, request.url().string());
 }
 
-void NetworkCache::retrieve(const WebCore::ResourceRequest& originalRequest, std::function<void (std::unique_ptr<Entry>)> completionHandler)
+void NetworkCache::retrieve(const WebCore::ResourceRequest& originalRequest, uint64_t webPageID, std::function<void (std::unique_ptr<Entry>)> completionHandler)
 {
     ASSERT(isEnabled());
 
@@ -227,7 +227,7 @@ void NetworkCache::retrieve(const WebCore::ResourceRequest& originalRequest, std
     NetworkCacheKey storageKey = makeCacheKey(originalRequest);
     if (!canRetrieve(originalRequest)) {
         if (m_statistics)
-            m_statistics->recordNotUsingCacheForRequest(storageKey, originalRequest);
+            m_statistics->recordNotUsingCacheForRequest(webPageID, storageKey, originalRequest);
 
         completionHandler(nullptr);
         return;
@@ -236,12 +236,12 @@ void NetworkCache::retrieve(const WebCore::ResourceRequest& originalRequest, std
     auto startTime = std::chrono::system_clock::now();
     unsigned priority = originalRequest.priority();
 
-    m_storage->retrieve(storageKey, priority, [this, originalRequest, completionHandler, startTime, storageKey](std::unique_ptr<NetworkCacheStorage::Entry> entry) {
+    m_storage->retrieve(storageKey, priority, [this, originalRequest, completionHandler, startTime, storageKey, webPageID](std::unique_ptr<NetworkCacheStorage::Entry> entry) {
         if (!entry) {
             LOG(NetworkCache, "(NetworkProcess) not found in storage");
 
             if (m_statistics)
-                m_statistics->recordRetrievalFailure(storageKey, originalRequest);
+                m_statistics->recordRetrievalFailure(webPageID, storageKey, originalRequest);
 
             completionHandler(nullptr);
             return false;
@@ -249,7 +249,7 @@ void NetworkCache::retrieve(const WebCore::ResourceRequest& originalRequest, std
         auto decodedEntry = decodeStorageEntry(*entry, originalRequest);
         bool success = !!decodedEntry;
         if (m_statistics)
-            m_statistics->recordRetrievedCachedEntry(storageKey, originalRequest, success);
+            m_statistics->recordRetrievedCachedEntry(webPageID, storageKey, originalRequest, success);
 
 #if !LOG_DISABLED
         auto elapsedMS = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - startTime).count();
index 40e43fc..4af3187 100644 (file)
@@ -64,7 +64,7 @@ public:
         bool needsRevalidation;
     };
     // Completion handler may get called back synchronously on failure.
-    void retrieve(const WebCore::ResourceRequest&, std::function<void (std::unique_ptr<Entry>)>);
+    void retrieve(const WebCore::ResourceRequest&, uint64_t webPageID, std::function<void (std::unique_ptr<Entry>)>);
 
     struct MappedBody {
 #if ENABLE(SHAREABLE_RESOURCE)
index bb52387..65cfd6c 100644 (file)
@@ -44,9 +44,9 @@ public:
 
     void clear();
 
-    void recordNotUsingCacheForRequest(const NetworkCacheKey&, const WebCore::ResourceRequest&);
-    void recordRetrievalFailure(const NetworkCacheKey&, const WebCore::ResourceRequest&);
-    void recordRetrievedCachedEntry(const NetworkCacheKey&, const WebCore::ResourceRequest&, bool success);
+    void recordNotUsingCacheForRequest(uint64_t webPageID, const NetworkCacheKey&, const WebCore::ResourceRequest&);
+    void recordRetrievalFailure(uint64_t webPageID, const NetworkCacheKey&, const WebCore::ResourceRequest&);
+    void recordRetrievedCachedEntry(uint64_t webPageID, const NetworkCacheKey&, const WebCore::ResourceRequest&, bool success);
 
 private:
     explicit NetworkCacheStatistics(const String& databasePath);
index 1227946..c13fd0e 100644 (file)
@@ -31,6 +31,9 @@
 #include "Logging.h"
 #include "NetworkCache.h"
 #include "NetworkCacheFileSystemPosix.h"
+#include "NetworkProcess.h"
+#include <WebCore/DiagnosticLoggingKeys.h>
+#include <WebCore/DiagnosticLoggingResultType.h>
 #include <WebCore/ResourceRequest.h>
 #include <WebCore/SQLiteDatabaseTracker.h>
 #include <WebCore/SQLiteStatement.h>
@@ -165,40 +168,42 @@ void NetworkCacheStatistics::shrinkIfNeeded()
     });
 }
 
-void NetworkCacheStatistics::recordNotUsingCacheForRequest(const NetworkCacheKey& key, const WebCore::ResourceRequest& request)
+void NetworkCacheStatistics::recordNotUsingCacheForRequest(uint64_t webPageID, const NetworkCacheKey& key, const WebCore::ResourceRequest& request)
 {
     String hash = key.hashAsString();
     WebCore::URL requestURL = request.url();
-    queryWasEverRequested(hash, [this, hash, requestURL](bool wasEverRequested) {
+    queryWasEverRequested(hash, [this, hash, requestURL, webPageID](bool wasEverRequested) {
         if (wasEverRequested) {
-            LOG(NetworkCache, "(NetworkProcess) %s was previously requested but is not handled by the cache", requestURL.string().ascii().data());
-            // FIXME: Do diagnostic logging.
+            LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s was previously requested but is not handled by the cache", webPageID, requestURL.string().ascii().data());
+            NetworkProcess::singleton().logDiagnosticMessageWithValue(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingKeys::unhandledRequestFailureKey());
         } else
             markAsRequested(hash);
     });
 }
 
-void NetworkCacheStatistics::recordRetrievalFailure(const NetworkCacheKey& key, const WebCore::ResourceRequest& request)
+void NetworkCacheStatistics::recordRetrievalFailure(uint64_t webPageID, const NetworkCacheKey& key, const WebCore::ResourceRequest& request)
 {
     String hash = key.hashAsString();
     WebCore::URL requestURL = request.url();
-    queryWasEverRequested(hash, [this, hash, requestURL](bool wasPreviouslyRequested) {
+    queryWasEverRequested(hash, [this, hash, requestURL, webPageID](bool wasPreviouslyRequested) {
         if (wasPreviouslyRequested) {
-            LOG(NetworkCache, "(NetworkProcess) %s was previously cached but is no longer in the cache", requestURL.string().ascii().data());
-            // FIXME: Do diagnostic logging.
+            LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s was previously cached but is no longer in the cache", webPageID, requestURL.string().ascii().data());
+            NetworkProcess::singleton().logDiagnosticMessageWithValue(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingKeys::noLongerInCacheFailureKey());
         } else
             markAsRequested(hash);
     });
 }
 
-void NetworkCacheStatistics::recordRetrievedCachedEntry(const NetworkCacheKey& key, const WebCore::ResourceRequest& request, bool success)
+void NetworkCacheStatistics::recordRetrievedCachedEntry(uint64_t webPageID, const NetworkCacheKey& key, const WebCore::ResourceRequest& request, bool success)
 {
     WebCore::URL requestURL = request.url();
-    if (success)
-        LOG(NetworkCache, "(NetworkProcess) %s is in the cache and is used", requestURL.string().ascii().data());
-    else
-        LOG(NetworkCache, "(NetworkProcess) %s is in the cache but wasn't used", requestURL.string().ascii().data());
-    // FIXME: Do diagnostic logging.
+    if (success) {
+        LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s is in the cache and is used", webPageID, requestURL.string().ascii().data());
+        NetworkProcess::singleton().logDiagnosticMessageWithResult(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingResultPass);
+    } else {
+        LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s is in the cache but wasn't used", webPageID, requestURL.string().ascii().data());
+        NetworkProcess::singleton().logDiagnosticMessageWithValue(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingKeys::unusableCachedEntryFailureKey());
+    }
 }
 
 void NetworkCacheStatistics::markAsRequested(const String& hash)
index d5f33fc..534e0d8 100644 (file)
@@ -230,6 +230,30 @@ void NetworkProcessProxy::didFinishLaunching(ProcessLauncher* launcher, IPC::Con
 #endif
 }
 
+void NetworkProcessProxy::logDiagnosticMessage(uint64_t pageID, const String& message, const String& description)
+{
+    WebPageProxy* page = WebProcessProxy::webPage(pageID);
+    MESSAGE_CHECK(page);
+
+    page->logDiagnosticMessage(message, description);
+}
+
+void NetworkProcessProxy::logDiagnosticMessageWithResult(uint64_t pageID, const String& message, const String& description, uint32_t result)
+{
+    WebPageProxy* page = WebProcessProxy::webPage(pageID);
+    MESSAGE_CHECK(page);
+
+    page->logDiagnosticMessageWithResult(message, description, result);
+}
+
+void NetworkProcessProxy::logDiagnosticMessageWithValue(uint64_t pageID, const String& message, const String& description, const String& value)
+{
+    WebPageProxy* page = WebProcessProxy::webPage(pageID);
+    MESSAGE_CHECK(page);
+
+    page->logDiagnosticMessageWithValue(message, description, value);
+}
+
 } // namespace WebKit
 
 #endif // ENABLE(NETWORK_PROCESS)
index cd996d1..3f89627 100644 (file)
@@ -91,6 +91,9 @@ private:
     void didCreateNetworkConnectionToWebProcess(const IPC::Attachment&);
     void didReceiveAuthenticationChallenge(uint64_t pageID, uint64_t frameID, const WebCore::AuthenticationChallenge&, uint64_t challengeID);
     void didDeleteWebsiteData(uint64_t callbackID);
+    void logDiagnosticMessage(uint64_t pageID, const String& message, const String& description);
+    void logDiagnosticMessageWithResult(uint64_t pageID, const String& message, const String& description, uint32_t result);
+    void logDiagnosticMessageWithValue(uint64_t pageID, const String& message, const String& description, const String& value);
 
     // ProcessLauncher::Client
     virtual void didFinishLaunching(ProcessLauncher*, IPC::Connection::Identifier) override;
index 93a37b4..e9d8cf6 100644 (file)
@@ -28,6 +28,11 @@ messages -> NetworkProcessProxy LegacyReceiver {
     DidReceiveAuthenticationChallenge(uint64_t pageID, uint64_t frameID, WebCore::AuthenticationChallenge challenge, uint64_t challengeID)
 
     DidDeleteWebsiteData(uint64_t callbackID)
+
+    # Diagnostic messages logging
+    LogDiagnosticMessage(uint64_t pageID, String message, String description)
+    LogDiagnosticMessageWithResult(uint64_t pageID, String message, String description, uint32_t result)
+    LogDiagnosticMessageWithValue(uint64_t pageID, String message, String description, String value)
 }
 
 #endif // ENABLE(NETWORK_PROCESS)
index 24d9e2f..c92ca89 100644 (file)
@@ -988,6 +988,11 @@ public:
 
     void setShouldDispatchFakeMouseMoveEvents(bool);
 
+    // Diagnostic messages logging.
+    void logDiagnosticMessage(const String& message, const String& description);
+    void logDiagnosticMessageWithResult(const String& message, const String& description, uint32_t result);
+    void logDiagnosticMessageWithValue(const String& message, const String& description, const String& value);
+
 private:
     WebPageProxy(PageClient&, WebProcessProxy&, uint64_t pageID, const WebPageConfiguration&);
     void platformInitialize();
@@ -1237,11 +1242,6 @@ private:
     void setCursor(const WebCore::Cursor&);
     void setCursorHiddenUntilMouseMoves(bool);
 
-    // Diagnostic messages logging.
-    void logDiagnosticMessage(const String& message, const String& description);
-    void logDiagnosticMessageWithResult(const String& message, const String& description, uint32_t result);
-    void logDiagnosticMessageWithValue(const String& message, const String& description, const String& value);
-
     void didReceiveEvent(uint32_t opaqueType, bool handled);
     void stopResponsivenessTimer();