Changeset 179972 in webkit

Timestamp:

Feb 11, 2015 3:57:31 PM (9 years ago)

Author:

Chris Dumez

Message:

[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 Sam Weinig.

Source/WebCore:

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

Source/WebKit2:

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.

Location:

trunk/Source

Files:

• WebCore/ChangeLog (modified) (1 diff)
• WebCore/WebCore.exp.in (modified) (1 diff)
• WebCore/page/DiagnosticLoggingKeys.cpp (modified) (4 diffs)
• WebCore/page/DiagnosticLoggingKeys.h (modified) (3 diffs)
• WebKit2/ChangeLog (modified) (1 diff)
• WebKit2/NetworkProcess/NetworkProcess.cpp (modified) (1 diff)
• WebKit2/NetworkProcess/NetworkProcess.h (modified) (2 diffs)
• WebKit2/NetworkProcess/NetworkResourceLoader.cpp (modified) (1 diff)
• WebKit2/NetworkProcess/cache/NetworkCache.cpp (modified) (4 diffs)
• WebKit2/NetworkProcess/cache/NetworkCache.h (modified) (1 diff)
• WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h (modified) (1 diff)
• WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm (modified) (4 diffs)
• WebKit2/UIProcess/Network/NetworkProcessProxy.cpp (modified) (1 diff)
• WebKit2/UIProcess/Network/NetworkProcessProxy.h (modified) (1 diff)
• WebKit2/UIProcess/Network/NetworkProcessProxy.messages.in (modified) (1 diff)
• WebKit2/UIProcess/WebPageProxy.h (modified) (2 diffs)

trunk/Source/WebCore/ChangeLog

@@ +1 @@
+2015-02-11  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 Sam Weinig.
+
+        Add a few more diagnostic logging keys for the network cache efficacy
+        logging.
+
 2015-02-11  Sam Weinig  <sam@webkit.org>
 

trunk/Source/WebCore/WebCore.exp.in

@@ -946 +946 @@
 __ZN7WebCore21CrossThreadCopierBaseILb0ELb0ENS_19IDBDatabaseMetadataEE4copyERKS1_
 __ZN7WebCore21DiagnosticLoggingKeys10webViewKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys12retrievalKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys15networkCacheKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys25noLongerInCacheFailureKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys26unhandledRequestFailureKeyEv
+__ZN7WebCore21DiagnosticLoggingKeys29unusableCachedEntryFailureKeyEv
 __ZN7WebCore21DiagnosticLoggingKeys7userKeyEv
 __ZN7WebCore21DiagnosticLoggingKeys9zoomedKeyEv

trunk/Source/WebCore/page/DiagnosticLoggingKeys.cpp

@@ -104 +104 @@
 }
 
+String DiagnosticLoggingKeys::networkCacheKey()
+{
+    return ASCIILiteral("networkCache");
+}
+
 String DiagnosticLoggingKeys::networkKey()
 {
@@ -134 +139 @@
 }
 
+String DiagnosticLoggingKeys::noLongerInCacheFailureKey()
+{
+    return ASCIILiteral("noLongerInCacheFailure");
+}
+
 String DiagnosticLoggingKeys::otherKey()
 {
@@ -299 +309 @@
 }
 
+String DiagnosticLoggingKeys::retrievalKey()
+{
+    return ASCIILiteral("retrieval");
+}
+
 String DiagnosticLoggingKeys::revalidatingKey()
 {
@@ -334 +349 @@
 }
 
+String DiagnosticLoggingKeys::unhandledRequestFailureKey()
+{
+    return ASCIILiteral("unhandledRequestFailure");
+}
+
+String DiagnosticLoggingKeys::unusableCachedEntryFailureKey()
+{
+    return ASCIILiteral("unusableCachedEntryFailure");
+}
+
 String DiagnosticLoggingKeys::unusedKey()
 {

trunk/Source/WebCore/page/DiagnosticLoggingKeys.h

@@ -64 +64 @@
     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();
@@ -91 +93 @@
     static String resourceRequestKey();
     static String resourceResponseKey();
+    WEBCORE_EXPORT static String retrievalKey();
     static String revalidatingKey();
     static String sameLoadKey();
@@ -97 +100 @@
     static String styleSheetKey();
     static String svgDocumentKey();
+    WEBCORE_EXPORT static String unhandledRequestFailureKey();
+    WEBCORE_EXPORT static String unusableCachedEntryFailureKey();
     static String unusedKey();
     static String unusedReasonCredentialSettingsKey();

trunk/Source/WebKit2/ChangeLog

@@ +1 @@
+2015-02-11  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 Sam Weinig.
+
+        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-11  Tim Horton  <timothy_horton@apple.com>
 

trunk/Source/WebKit2/NetworkProcess/NetworkProcess.cpp

@@ -302 +302 @@
 }
 
+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()
 {

trunk/Source/WebKit2/NetworkProcess/NetworkProcess.h

@@ -34 +34 @@
 #include "MessageReceiverMap.h"
 #include "NetworkResourceLoadScheduler.h"
+#include <WebCore/DiagnosticLoggingResultType.h>
 #include <WebCore/SessionID.h>
 #include <memory>
@@ -75 +76 @@
     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:

trunk/Source/WebKit2/NetworkProcess/NetworkResourceLoader.cpp

@@ -142 +142 @@
 
     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.

trunk/Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp

@@ -219 +219 @@
 }
 
-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());
@@ -228 +228 @@
     if (!canRetrieve(originalRequest)) {
         if (m_statistics)
-            m_statistics->recordNotUsingCacheForRequest(storageKey, originalRequest);
+            m_statistics->recordNotUsingCacheForRequest(webPageID, storageKey, originalRequest);
 
         completionHandler(nullptr);
@@ -237 +237 @@
     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);
@@ -250 +250 @@
         bool success = !!decodedEntry;
         if (m_statistics)
-            m_statistics->recordRetrievedCachedEntry(storageKey, originalRequest, success);
+            m_statistics->recordRetrievedCachedEntry(webPageID, storageKey, originalRequest, success);
 
 #if !LOG_DISABLED

trunk/Source/WebKit2/NetworkProcess/cache/NetworkCache.h

@@ -65 +65 @@
     };
     // 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 {

trunk/Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h

@@ -45 +45 @@
     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:

trunk/Source/WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm

@@ -32 +32 @@
 #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>
@@ -166 +169 @@
 }
 
-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);
@@ -179 +182 @@
 }
 
-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);
@@ -192 +195 @@
 }
 
-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());
+    }
 }
 

trunk/Source/WebKit2/UIProcess/Network/NetworkProcessProxy.cpp

@@ -231 +231 @@
 }
 
+void NetworkProcessProxy::logDiagnosticMessage(uint64_t pageID, const String& message, const String& description)
+{
+    WebPageProxy* page = WebProcessProxy::webPage(pageID);
+    // FIXME: We do this null-check because by the time the decision to log is made, the page may be gone. We should refactor to avoid this,
+    // but for now we simply drop the message in the rare case this happens.
+    if (!page)
+        return;
+
+    page->logDiagnosticMessage(message, description);
+}
+
+void NetworkProcessProxy::logDiagnosticMessageWithResult(uint64_t pageID, const String& message, const String& description, uint32_t result)
+{
+    WebPageProxy* page = WebProcessProxy::webPage(pageID);
+    // FIXME: We do this null-check because by the time the decision to log is made, the page may be gone. We should refactor to avoid this,
+    // but for now we simply drop the message in the rare case this happens.
+    if (!page)
+        return;
+
+    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);
+    // FIXME: We do this null-check because by the time the decision to log is made, the page may be gone. We should refactor to avoid this,
+    // but for now we simply drop the message in the rare case this happens.
+    if (!page)
+        return;
+
+    page->logDiagnosticMessageWithValue(message, description, value);
+}
+
 } // namespace WebKit
 

trunk/Source/WebKit2/UIProcess/Network/NetworkProcessProxy.h

@@ -92 +92 @@
     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

trunk/Source/WebKit2/UIProcess/Network/NetworkProcessProxy.messages.in

@@ -29 +29 @@
 
     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)
 }
 

trunk/Source/WebKit2/UIProcess/WebPageProxy.h

@@ -989 +989 @@
     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&);
@@ -1238 +1243 @@
     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();