Changeset 232759 in webkit


Ignore:
Timestamp:
Jun 12, 2018 10:53:02 AM (6 years ago)
Author:
Antti Koivisto
Message:

Add performance logging for slow cache retrieves
​https://bugs.webkit.org/show_bug.cgi?id=186520
<rdar://problem/41002070>

Reviewed by Chris Dumez.

We sometimes see slow cache retrieves in logs. Add some more logging to better analyze these cases.

This patch adds timings to all cache storage retrieve operations and passes them up to the client.
We then log the timings on NetworkResourceLoader levels if needed. Items logged include

  • total retrieve time
  • dispatch delay and number of resources dispatched before this one
  • record I/O time
  • blob I/O time
  • whether cache shrink was in progress
  • whether cache synchronization was in progress
  • cancellation
  • NetworkProcess/NetworkResourceLoader.cpp:

(WebKit::NetworkResourceLoader::retrieveCacheEntry):
(WebKit::NetworkResourceLoader::logSlowCacheRetrieveIfNeeded):

Log if the retrieve took more than 1s.

  • NetworkProcess/NetworkResourceLoader.h:
  • NetworkProcess/cache/CacheStorageEngineCaches.cpp:

(WebKit::CacheStorage::Caches::readRecord):

  • NetworkProcess/cache/NetworkCache.cpp:

(WebKit::NetworkCache::Cache::retrieve):
(WebKit::NetworkCache::Cache::completeRetrieve):
(WebKit::NetworkCache::Cache::retrieveData):

  • NetworkProcess/cache/NetworkCache.h:
  • NetworkProcess/cache/NetworkCacheSpeculativeLoadManager.cpp:

(WebKit::NetworkCache::SpeculativeLoadManager::retrieveEntryFromStorage):
(WebKit::NetworkCache::SpeculativeLoadManager::retrieveSubresourcesEntry):

SpeculativeLoadManager does not records specific timings yet but at least we do log when they occur.

  • NetworkProcess/cache/NetworkCacheStorage.cpp:

(WebKit::NetworkCache::Storage::ReadOperation::cancel):
(WebKit::NetworkCache::Storage::ReadOperation::finish):

Record timing info in ReadOperations.

(WebKit::NetworkCache::Storage::dispatchReadOperation):
(WebKit::NetworkCache::retrieveFromMemory):
(WebKit::NetworkCache::Storage::retrieve):

  • NetworkProcess/cache/NetworkCacheStorage.h:
Location:
trunk/Source/WebKit
Files:
9 edited

Legend:

Unmodified
Added
Removed

  • trunk/Source/WebKit/ChangeLog

    r232744 r232759  
     12018-06-12  Antti Koivisto  <antti@apple.com>
     2
     3        Add performance logging for slow cache retrieves
     4        https://bugs.webkit.org/show_bug.cgi?id=186520
     5        <rdar://problem/41002070>
     6
     7        Reviewed by Chris Dumez.
     8
     9        We sometimes see slow cache retrieves in logs. Add some more logging to better analyze these cases.
     10
     11        This patch adds timings to all cache storage retrieve operations and passes them up to the client.
     12        We then log the timings on NetworkResourceLoader levels if needed. Items logged include
     13
     14        - total retrieve time
     15        - dispatch delay and number of resources dispatched before this one
     16        - record I/O time
     17        - blob I/O time
     18        - whether cache shrink was in progress
     19        - whether cache synchronization was in progress
     20        - cancellation
     21
     22        * NetworkProcess/NetworkResourceLoader.cpp:
     23        (WebKit::NetworkResourceLoader::retrieveCacheEntry):
     24        (WebKit::NetworkResourceLoader::logSlowCacheRetrieveIfNeeded):
     25
     26        Log if the retrieve took more than 1s.
     27
     28        * NetworkProcess/NetworkResourceLoader.h:
     29        * NetworkProcess/cache/CacheStorageEngineCaches.cpp:
     30        (WebKit::CacheStorage::Caches::readRecord):
     31        * NetworkProcess/cache/NetworkCache.cpp:
     32        (WebKit::NetworkCache::Cache::retrieve):
     33        (WebKit::NetworkCache::Cache::completeRetrieve):
     34        (WebKit::NetworkCache::Cache::retrieveData):
     35        * NetworkProcess/cache/NetworkCache.h:
     36        * NetworkProcess/cache/NetworkCacheSpeculativeLoadManager.cpp:
     37        (WebKit::NetworkCache::SpeculativeLoadManager::retrieveEntryFromStorage):
     38        (WebKit::NetworkCache::SpeculativeLoadManager::retrieveSubresourcesEntry):
     39
     40        SpeculativeLoadManager does not records specific timings yet but at least we do log when they occur.
     41
     42        * NetworkProcess/cache/NetworkCacheStorage.cpp:
     43        (WebKit::NetworkCache::Storage::ReadOperation::cancel):
     44        (WebKit::NetworkCache::Storage::ReadOperation::finish):
     45
     46        Record timing info in ReadOperations.
     47
     48        (WebKit::NetworkCache::Storage::dispatchReadOperation):
     49        (WebKit::NetworkCache::retrieveFromMemory):
     50        (WebKit::NetworkCache::Storage::retrieve):
     51        * NetworkProcess/cache/NetworkCacheStorage.h:
     52
    1532018-06-11  Carlos Garcia Campos  <cgarcia@igalia.com>
    254

  • trunk/Source/WebKit/NetworkProcess/NetworkResourceLoader.cpp

    r232217 r232759  
    216216
    217217    RefPtr<NetworkResourceLoader> loader(this);
    218     m_cache->retrieve(request, { m_parameters.webPageID, m_parameters.webFrameID }, [this, loader = WTFMove(loader), request = ResourceRequest { request }](auto entry) mutable {
    219 #if RELEASE_LOG_DISABLED
    220         UNUSED_PARAM(this);
    221 #endif
     218    m_cache->retrieve(request, { m_parameters.webPageID, m_parameters.webFrameID }, [this, loader = WTFMove(loader), request = ResourceRequest { request }](auto entry, auto info) mutable {
    222219        if (loader->hasOneRef()) {
    223220            // The loader has been aborted and is only held alive by this lambda.
    224221            return;
    225222        }
     223
     224        loader->logSlowCacheRetrieveIfNeeded(info);
     225
    226226        if (!entry) {
    227227            RELEASE_LOG_IF_ALLOWED("retrieveCacheEntry: Resource not in cache (pageID = %" PRIu64 ", frameID = %" PRIu64 ", resourceID = %" PRIu64 ", isMainResource = %d, isSynchronous = %d)", m_parameters.webPageID, m_parameters.webFrameID, m_parameters.identifier, isMainResource(), isSynchronous());
    … …  
    10821082}
    10831083
     1084void NetworkResourceLoader::logSlowCacheRetrieveIfNeeded(const NetworkCache::Cache::RetrieveInfo& info)
     1085{
     1086#if RELEASE_LOG_DISABLED
     1087    UNUSED_PARAM(info);
     1088#else
     1089    if (!isAlwaysOnLoggingAllowed())
     1090        return;
     1091    auto duration = info.completionTime - info.startTime;
     1092    if (duration < 1_s)
     1093        return;
     1094    RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Took %.0fms, priority %d", duration.milliseconds(), info.priority);
     1095    if (info.wasSpeculativeLoad)
     1096        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Was speculative load");
     1097    if (!info.storageTimings.startTime)
     1098        return;
     1099    RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Storage retrieve time %.0fms", (info.storageTimings.completionTime - info.storageTimings.startTime).milliseconds());
     1100    if (info.storageTimings.dispatchTime) {
     1101        auto time = (info.storageTimings.dispatchTime - info.storageTimings.startTime).milliseconds();
     1102        auto count = info.storageTimings.dispatchCountAtDispatch - info.storageTimings.dispatchCountAtStart;
     1103        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Dispatch delay %.0fms, dispatched %lu resources first", time, count);
     1104    }
     1105    if (info.storageTimings.recordIOStartTime)
     1106        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Record I/O time %.0fms", (info.storageTimings.recordIOEndTime - info.storageTimings.recordIOStartTime).milliseconds());
     1107    if (info.storageTimings.blobIOStartTime)
     1108        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Blob I/O time %.0fms", (info.storageTimings.blobIOEndTime - info.storageTimings.blobIOStartTime).milliseconds());
     1109    if (info.storageTimings.synchronizationInProgressAtDispatch)
     1110        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Synchronization was in progress");
     1111    if (info.storageTimings.shrinkInProgressAtDispatch)
     1112        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Shrink was in progress");
     1113    if (info.storageTimings.wasCanceled)
     1114        RELEASE_LOG_IF_ALLOWED("logSlowCacheRetrieveIfNeeded: Retrieve was canceled");
     1115#endif
     1116}
     1117
    10841118} // namespace WebKit

  • trunk/Source/WebKit/NetworkProcess/NetworkResourceLoader.h

    r232121 r232759  
    178178    void enqueueSecurityPolicyViolationEvent(WebCore::SecurityPolicyViolationEvent::Init&&) final;
    179179
     180    void logSlowCacheRetrieveIfNeeded(const NetworkCache::Cache::RetrieveInfo&);
     181
    180182    const NetworkResourceLoadParameters m_parameters;
    181183

  • trunk/Source/WebKit/NetworkProcess/cache/CacheStorageEngineCaches.cpp

    r229914 r232759  
    509509    }
    510510
    511     m_storage->retrieve(key, 4, [protectedStorage = makeRef(*m_storage), callback = WTFMove(callback)](std::unique_ptr<Storage::Record> storage) mutable {
     511    m_storage->retrieve(key, 4, [protectedStorage = makeRef(*m_storage), callback = WTFMove(callback)](std::unique_ptr<Storage::Record> storage, const Storage::Timings&) mutable {
    512512        if (!storage) {
    513513            callback(makeUnexpected(Error::ReadDisk));

  • trunk/Source/WebKit/NetworkProcess/cache/NetworkCache.cpp

    r232447 r232759  
    310310}
    311311
    312 void Cache::retrieve(const WebCore::ResourceRequest& request, const GlobalFrameID& frameID, Function<void (std::unique_ptr<Entry>)>&& completionHandler)
     312void Cache::retrieve(const WebCore::ResourceRequest& request, const GlobalFrameID& frameID, RetrieveCompletionHandler&& completionHandler)
    313313{
    314314    ASSERT(request.url().protocolIsInHTTPFamily());
    … …  
    320320
    321321    Key storageKey = makeCacheKey(request);
     322    auto priority = static_cast<unsigned>(request.priority());
     323
     324    RetrieveInfo info;
     325    info.startTime = MonotonicTime::now();
     326    info.priority = priority;
    322327
    323328#if ENABLE(NETWORK_CACHE_SPECULATIVE_REVALIDATION)
    … …  
    332337            m_statistics->recordNotUsingCacheForRequest(frameID.first, storageKey, request, retrieveDecision);
    333338
    334         completionHandler(nullptr);
     339        completeRetrieve(WTFMove(completionHandler), nullptr, info);
    335340        return;
    336341    }
    … …  
    338343#if ENABLE(NETWORK_CACHE_SPECULATIVE_REVALIDATION)
    339344    if (canUseSpeculativeRevalidation && m_speculativeLoadManager->canRetrieve(storageKey, request, frameID)) {
    340         m_speculativeLoadManager->retrieve(storageKey, [request, completionHandler = WTFMove(completionHandler)](std::unique_ptr<Entry> entry) {
     345        m_speculativeLoadManager->retrieve(storageKey, [request, completionHandler = WTFMove(completionHandler), info = WTFMove(info)](std::unique_ptr<Entry> entry) mutable {
     346            info.wasSpeculativeLoad = true;
    341347            if (entry && WebCore::verifyVaryingRequestHeaders(entry->varyingRequestHeaders(), request))
    342                 completionHandler(WTFMove(entry));
     348                completeRetrieve(WTFMove(completionHandler), WTFMove(entry), info);
    343349            else
    344                 completionHandler(nullptr);
     350                completeRetrieve(WTFMove(completionHandler), nullptr, info);
    345351        });
    346352        return;
    … …  
    348354#endif
    349355
    350     auto startTime = WallTime::now();
    351     auto priority = static_cast<unsigned>(request.priority());
    352 
    353     m_storage->retrieve(storageKey, priority, [this, protectedThis = makeRef(*this), request, completionHandler = WTFMove(completionHandler), startTime, storageKey, frameID](auto record) {
     356    m_storage->retrieve(storageKey, priority, [this, protectedThis = makeRef(*this), request, completionHandler = WTFMove(completionHandler), info = WTFMove(info), storageKey, frameID](auto record, auto timings) mutable {
     357        info.storageTimings = timings;
     358
    354359        if (!record) {
    355360            LOG(NetworkCache, "(NetworkProcess) not found in storage");
    … …  
    358363                m_statistics->recordRetrievalFailure(frameID.first, storageKey, request);
    359364
    360             completionHandler(nullptr);
     365            completeRetrieve(WTFMove(completionHandler), nullptr, info);
    361366            return false;
    362367        }
    … …  
    378383
    379384#if !LOG_DISABLED
    380         auto elapsed = WallTime::now() - startTime;
     385        auto elapsed = MonotonicTime::now() - info.startTime;
    381386        LOG(NetworkCache, "(NetworkProcess) retrieve complete useDecision=%d priority=%d time=%" PRIi64 "ms", static_cast<int>(useDecision), static_cast<int>(request.priority()), elapsed.millisecondsAs<int64_t>());
    382 #else
    383         UNUSED_PARAM(startTime);
    384 #endif
    385         completionHandler(WTFMove(entry));
     387#endif
     388        completeRetrieve(WTFMove(completionHandler), WTFMove(entry), info);
    386389
    387390        if (m_statistics)
    … …  
    391394}
    392395
     396void Cache::completeRetrieve(RetrieveCompletionHandler&& handler, std::unique_ptr<Entry> entry, RetrieveInfo& info)
     397{
     398    info.completionTime = MonotonicTime::now();
     399    handler(WTFMove(entry), info);
     400}
    393401   
    394402std::unique_ptr<Entry> Cache::makeEntry(const WebCore::ResourceRequest& request, const WebCore::ResourceResponse& response, RefPtr<WebCore::SharedBuffer>&& responseData)
    … …  
    622630{
    623631    Key key { dataKey, m_storage->salt() };
    624     m_storage->retrieve(key, 4, [completionHandler = WTFMove(completionHandler)] (auto record) {
     632    m_storage->retrieve(key, 4, [completionHandler = WTFMove(completionHandler)] (auto record, auto) {
    625633        if (!record || !record->body.size()) {
    626634            completionHandler(nullptr, 0);

  • trunk/Source/WebKit/NetworkProcess/cache/NetworkCache.h

    r231484 r232759  
    103103
    104104    // Completion handler may get called back synchronously on failure.
    105     void retrieve(const WebCore::ResourceRequest&, const GlobalFrameID&, Function<void (std::unique_ptr<Entry>)>&&);
     105    struct RetrieveInfo {
     106        MonotonicTime startTime;
     107        MonotonicTime completionTime;
     108        unsigned priority;
     109        Storage::Timings storageTimings;
     110        bool wasSpeculativeLoad { false };
     111
     112        WTF_MAKE_FAST_ALLOCATED;
     113    };
     114    using RetrieveCompletionHandler = Function<void (std::unique_ptr<Entry>, const RetrieveInfo&)>;
     115    void retrieve(const WebCore::ResourceRequest&, const GlobalFrameID&, RetrieveCompletionHandler&&);
    106116    std::unique_ptr<Entry> store(const WebCore::ResourceRequest&, const WebCore::ResourceResponse&, RefPtr<WebCore::SharedBuffer>&&, Function<void (MappedBody&)>&&);
    107117    std::unique_ptr<Entry> storeRedirect(const WebCore::ResourceRequest&, const WebCore::ResourceResponse&, const WebCore::ResourceRequest& redirectRequest);
    … …  
    141151    Key makeCacheKey(const WebCore::ResourceRequest&);
    142152
     153    static void completeRetrieve(RetrieveCompletionHandler&&, std::unique_ptr<Entry>, RetrieveInfo&);
     154
    143155    String dumpFilePath() const;
    144156    void deleteDumpFile();

  • trunk/Source/WebKit/NetworkProcess/cache/NetworkCacheSpeculativeLoadManager.cpp

    r230944 r232759  
    417417void SpeculativeLoadManager::retrieveEntryFromStorage(const SubresourceInfo& info, RetrieveCompletionHandler&& completionHandler)
    418418{
    419     m_storage.retrieve(info.key(), static_cast<unsigned>(info.priority()), [completionHandler = WTFMove(completionHandler)](auto record) {
     419    m_storage.retrieve(info.key(), static_cast<unsigned>(info.priority()), [completionHandler = WTFMove(completionHandler)](auto record, auto timings) {
    420420        if (!record) {
    421421            completionHandler(nullptr);
    … …  
    572572    ASSERT(storageKey.type() == "Resource");
    573573    auto subresourcesStorageKey = makeSubresourcesKey(storageKey, m_storage.salt());
    574     m_storage.retrieve(subresourcesStorageKey, static_cast<unsigned>(ResourceLoadPriority::Medium), [completionHandler = WTFMove(completionHandler)](auto record) {
     574    m_storage.retrieve(subresourcesStorageKey, static_cast<unsigned>(ResourceLoadPriority::Medium), [completionHandler = WTFMove(completionHandler)](auto record, auto timings) {
    575575        if (!record) {
    576576            completionHandler(nullptr);

  • trunk/Source/WebKit/NetworkProcess/cache/NetworkCacheStorage.cpp

    r231708 r232759  
    7272    std::atomic<unsigned> activeCount { 0 };
    7373    bool isCanceled { false };
     74    Timings timings;
    7475};
    7576
    … …  
    8081    if (isCanceled)
    8182        return;
     83    timings.completionTime = MonotonicTime::now();
     84    timings.wasCanceled = true;
    8285    isCanceled = true;
    83     completionHandler(nullptr);
     86    completionHandler(nullptr, timings);
    8487}
    8588
    … …  
    9699            resultRecord = nullptr;
    97100    }
    98     return completionHandler(WTFMove(resultRecord));
     101    timings.completionTime = MonotonicTime::now();
     102    return completionHandler(WTFMove(resultRecord), timings);
    99103}
    100104
    … …  
    645649    m_activeReadOperations.add(WTFMove(readOperationPtr));
    646650
     651    readOperation.timings.dispatchTime = MonotonicTime::now();
     652    readOperation.timings.synchronizationInProgressAtDispatch = m_synchronizationInProgress;
     653    readOperation.timings.shrinkInProgressAtDispatch = m_shrinkInProgress;
     654    readOperation.timings.dispatchCountAtDispatch = m_readOperationDispatchCount;
     655
     656    ++m_readOperationDispatchCount;
     657
    647658    // Avoid randomness during testing.
    648659    if (m_mode != Mode::Testing) {
    … …  
    661672            ++readOperation.activeCount;
    662673
     674        readOperation.timings.recordIOStartTime = MonotonicTime::now();
     675
    663676        auto channel = IOChannel::open(recordPath, IOChannel::Type::Read);
    664677        channel->read(0, std::numeric_limits<size_t>::max(), &ioQueue(), [this, &readOperation](const Data& fileData, int error) {
     678            readOperation.timings.recordIOEndTime = MonotonicTime::now();
    665679            if (!error)
    666680                readRecord(readOperation, fileData);
    … …  
    670684        if (shouldGetBodyBlob) {
    671685            // Read the blob in parallel with the record read.
     686            readOperation.timings.blobIOStartTime = MonotonicTime::now();
     687
    672688            auto blobPath = blobPathForKey(readOperation.key);
    673689            readOperation.resultBodyBlob = m_blobStorage.get(blobPath);
     690
     691            readOperation.timings.blobIOEndTime = MonotonicTime::now();
     692
    674693            finishReadOperation(readOperation);
    675694        }
    … …  
    748767            LOG(NetworkCacheStorage, "(NetworkProcess) found write operation in progress");
    749768            RunLoop::main().dispatch([record = operation->record, completionHandler = WTFMove(completionHandler)] {
    750                 completionHandler(std::make_unique<Storage::Record>(record));
     769                completionHandler(std::make_unique<Storage::Record>(record), { });
    751770            });
    752771            return true;
    … …  
    840859
    841860    if (!m_capacity) {
    842         completionHandler(nullptr);
     861        completionHandler(nullptr, { });
    843862        return;
    844863    }
    845864
    846865    if (!mayContain(key)) {
    847         completionHandler(nullptr);
     866        completionHandler(nullptr, { });
    848867        return;
    849868    }
    … …  
    855874
    856875    auto readOperation = std::make_unique<ReadOperation>(*this, key, WTFMove(completionHandler));
     876
     877    readOperation->timings.startTime = MonotonicTime::now();
     878    readOperation->timings.dispatchCountAtStart = m_readOperationDispatchCount;
     879
    857880    m_pendingReadOperationsByPriority[priority].prepend(WTFMove(readOperation));
    858881    dispatchPendingReadOperations();

  • trunk/Source/WebKit/NetworkProcess/cache/NetworkCacheStorage.h

    r231484 r232759  
    3535#include <wtf/Function.h>
    3636#include <wtf/HashSet.h>
     37#include <wtf/MonotonicTime.h>
    3738#include <wtf/Optional.h>
    3839#include <wtf/WallTime.h>
    … …  
    5152
    5253    struct Record {
    53         WTF_MAKE_FAST_ALLOCATED;
    54     public:
    5554        Key key;
    5655        WallTime timeStamp;
    … …  
    5857        Data body;
    5958        std::optional<SHA1::Digest> bodyHash;
    60     };
     59
     60        WTF_MAKE_FAST_ALLOCATED;
     61    };
     62
     63    struct Timings {
     64        MonotonicTime startTime;
     65        MonotonicTime dispatchTime;
     66        MonotonicTime recordIOStartTime;
     67        MonotonicTime recordIOEndTime;
     68        MonotonicTime blobIOStartTime;
     69        MonotonicTime blobIOEndTime;
     70        MonotonicTime completionTime;
     71        size_t dispatchCountAtStart { 0 };
     72        size_t dispatchCountAtDispatch { 0 };
     73        bool synchronizationInProgressAtDispatch { false };
     74        bool shrinkInProgressAtDispatch { false };
     75        bool wasCanceled { false };
     76
     77        WTF_MAKE_FAST_ALLOCATED;
     78    };
     79
    6180    // This may call completion handler synchronously on failure.
    62     typedef Function<bool (std::unique_ptr<Record>)> RetrieveCompletionHandler;
     81    using RetrieveCompletionHandler = Function<bool (std::unique_ptr<Record>, const Timings&)>;
    6382    void retrieve(const Key&, unsigned priority, RetrieveCompletionHandler&&);
    6483
    65     typedef Function<void (const Data& mappedBody)> MappedBodyHandler;
     84    using MappedBodyHandler = Function<void (const Data& mappedBody)>;
    6685    void store(const Record&, MappedBodyHandler&&, CompletionHandler<void()>&& = { });
    6786
    … …  
    164183    bool m_synchronizationInProgress { false };
    165184    bool m_shrinkInProgress { false };
     185    size_t m_readOperationDispatchCount { 0 };
    166186
    167187    Vector<Key::HashType> m_recordFilterHashesAddedDuringSynchronization;
Note: See TracChangeset for help on using the changeset viewer.