61bef1e11c3cf8375f73925b723b916fb31eb37e
[WebKit-https.git] / Source / WebKit / NetworkProcess / cache / NetworkCacheStatistics.cpp
1 /*
2  * Copyright (C) 2015 Apple Inc. All rights reserved.
3  *
4  * Redistribution and use in source and binary forms, with or without
5  * modification, are permitted provided that the following conditions
6  * are met:
7  * 1. Redistributions of source code must retain the above copyright
8  *    notice, this list of conditions and the following disclaimer.
9  * 2. Redistributions in binary form must reproduce the above copyright
10  *    notice, this list of conditions and the following disclaimer in the
11  *    documentation and/or other materials provided with the distribution.
12  *
13  * THIS SOFTWARE IS PROVIDED BY APPLE INC. AND ITS CONTRIBUTORS ``AS IS''
14  * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
15  * THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
16  * PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL APPLE INC. OR ITS CONTRIBUTORS
17  * BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
18  * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
19  * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
20  * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
21  * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
22  * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF
23  * THE POSSIBILITY OF SUCH DAMAGE.
24  */
25
26 #include "config.h"
27
28 #include "NetworkCacheStatistics.h"
29
30 #include "Logging.h"
31 #include "NetworkCache.h"
32 #include "NetworkCacheFileSystem.h"
33 #include "NetworkProcess.h"
34 #include <WebCore/DiagnosticLoggingKeys.h>
35 #include <WebCore/DiagnosticLoggingResultType.h>
36 #include <WebCore/ResourceRequest.h>
37 #include <WebCore/SQLiteDatabaseTracker.h>
38 #include <WebCore/SQLiteStatement.h>
39 #include <WebCore/SQLiteTransaction.h>
40 #include <wtf/RunLoop.h>
41 #include <wtf/Seconds.h>
42
43 namespace WebKit {
44 namespace NetworkCache {
45
46 static const char* StatisticsDatabaseName = "WebKitCacheStatistics.db";
47 static const Seconds mininumWriteInterval { 10_s };
48
49 static bool executeSQLCommand(WebCore::SQLiteDatabase& database, const String& sql)
50 {
51     ASSERT(!RunLoop::isMain());
52     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
53     ASSERT(database.isOpen());
54
55     bool result = database.executeCommand(sql);
56     if (!result)
57         LOG_ERROR("Network cache statistics: failed to execute statement \"%s\" error \"%s\"", sql.utf8().data(), database.lastErrorMsg());
58
59     return result;
60 }
61
62 static bool executeSQLStatement(WebCore::SQLiteStatement& statement)
63 {
64     ASSERT(!RunLoop::isMain());
65     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
66     ASSERT(statement.database().isOpen());
67
68     if (statement.step() != SQLITE_DONE) {
69         LOG_ERROR("Network cache statistics: failed to execute statement \"%s\" error \"%s\"", statement.query().utf8().data(), statement.database().lastErrorMsg());
70         return false;
71     }
72
73     return true;
74 }
75
76 std::unique_ptr<Statistics> Statistics::open(Cache& cache, const String& cachePath)
77 {
78     ASSERT(RunLoop::isMain());
79
80     String databasePath = FileSystem::pathByAppendingComponent(cachePath, StatisticsDatabaseName);
81     return std::make_unique<Statistics>(cache, databasePath);
82 }
83
84 Statistics::Statistics(Cache& cache, const String& databasePath)
85     : m_cache(cache)
86     , m_serialBackgroundIOQueue(WorkQueue::create("com.apple.WebKit.Cache.Statistics.Background", WorkQueue::Type::Serial, WorkQueue::QOS::Background))
87     , m_writeTimer(*this, &Statistics::writeTimerFired)
88 {
89     initialize(databasePath);
90 }
91
92 void Statistics::initialize(const String& databasePath)
93 {
94     ASSERT(RunLoop::isMain());
95
96     auto startTime = WallTime::now();
97
98     serialBackgroundIOQueue().dispatch([this, databasePath = databasePath.isolatedCopy(), networkCachePath = m_cache.recordsPath(), startTime] {
99         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
100
101         if (!FileSystem::makeAllDirectories(FileSystem::directoryName(databasePath)))
102             return;
103
104         LOG(NetworkCache, "(NetworkProcess) Opening network cache statistics database at %s...", databasePath.utf8().data());
105         m_database.open(databasePath);
106         m_database.disableThreadingChecks();
107         if (!m_database.isOpen()) {
108             LOG_ERROR("Network cache statistics: Failed to open / create the network cache statistics database");
109             return;
110         }
111
112         executeSQLCommand(m_database, "CREATE TABLE IF NOT EXISTS AlreadyRequested (hash TEXT PRIMARY KEY)"_s);
113         executeSQLCommand(m_database, "CREATE TABLE IF NOT EXISTS UncachedReason (hash TEXT PRIMARY KEY, reason INTEGER)"_s);
114
115         WebCore::SQLiteStatement statement(m_database, "SELECT count(*) FROM AlreadyRequested"_s);
116         if (statement.prepareAndStep() != SQLITE_ROW) {
117             LOG_ERROR("Network cache statistics: Failed to count the number of rows in AlreadyRequested table");
118             return;
119         }
120
121         m_approximateEntryCount = statement.getColumnInt(0);
122
123 #if !LOG_DISABLED
124         auto elapsed = WallTime::now() - startTime;
125 #else
126         UNUSED_PARAM(startTime);
127 #endif
128         LOG(NetworkCache, "(NetworkProcess) Network cache statistics database load complete, entries=%lu time=%" PRIi64 "ms", static_cast<size_t>(m_approximateEntryCount), elapsed.millisecondsAs<int64_t>());
129
130         if (!m_approximateEntryCount) {
131             bootstrapFromNetworkCache(networkCachePath);
132 #if !LOG_DISABLED
133             elapsed = WallTime::now() - startTime;
134 #else
135             UNUSED_PARAM(startTime);
136 #endif
137             LOG(NetworkCache, "(NetworkProcess) Network cache statistics database bootstrapping complete, entries=%lu time=%" PRIi64 "ms", static_cast<size_t>(m_approximateEntryCount), elapsed.millisecondsAs<int64_t>());
138         }
139     });
140 }
141
142 void Statistics::bootstrapFromNetworkCache(const String& networkCachePath)
143 {
144     ASSERT(!RunLoop::isMain());
145
146     LOG(NetworkCache, "(NetworkProcess) Bootstrapping the network cache statistics database from the network cache...");
147
148     HashSet<String> hashes;
149     traverseRecordsFiles(networkCachePath, "Resource"_s, [&hashes](const String& fileName, const String& hashString, const String& type, bool isBodyBlob, const String& recordDirectoryPath) {
150         if (isBodyBlob)
151             return;
152
153         Key::HashType hash;
154         if (!Key::stringToHash(hashString, hash))
155             return;
156
157         hashes.add(hashString);
158     });
159
160     WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
161     WebCore::SQLiteTransaction writeTransaction(m_database);
162     writeTransaction.begin();
163
164     addHashesToDatabase(hashes);
165
166     writeTransaction.commit();
167 }
168
169 void Statistics::shrinkIfNeeded()
170 {
171     ASSERT(RunLoop::isMain());
172     const size_t maxEntries = 100000;
173
174     if (m_approximateEntryCount < maxEntries)
175         return;
176
177     LOG(NetworkCache, "(NetworkProcess) shrinking statistics cache m_approximateEntryCount=%lu, maxEntries=%lu", static_cast<size_t>(m_approximateEntryCount), maxEntries);
178
179     clear();
180
181     serialBackgroundIOQueue().dispatch([this, networkCachePath = m_cache.recordsPath()] {
182         bootstrapFromNetworkCache(networkCachePath);
183         LOG(NetworkCache, "(NetworkProcess) statistics cache shrink completed m_approximateEntryCount=%lu", static_cast<size_t>(m_approximateEntryCount));
184     });
185 }
186
187 void Statistics::recordRetrievalRequest(uint64_t webPageID)
188 {
189     m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalRequestKey(), WebCore::ShouldSample::Yes);
190 }
191
192 void Statistics::recordNotCachingResponse(const Key& key, StoreDecision storeDecision)
193 {
194     ASSERT(storeDecision != StoreDecision::Yes);
195
196     m_storeDecisionsToAdd.set(key.hashAsString(), storeDecision);
197     if (!m_writeTimer.isActive())
198         m_writeTimer.startOneShot(mininumWriteInterval);
199 }
200
201 static String retrieveDecisionToDiagnosticKey(RetrieveDecision retrieveDecision)
202 {
203     switch (retrieveDecision) {
204     case RetrieveDecision::NoDueToHTTPMethod:
205         return WebCore::DiagnosticLoggingKeys::unsupportedHTTPMethodKey();
206     case RetrieveDecision::NoDueToConditionalRequest:
207         return WebCore::DiagnosticLoggingKeys::isConditionalRequestKey();
208     case RetrieveDecision::NoDueToReloadIgnoringCache:
209         return WebCore::DiagnosticLoggingKeys::isReloadIgnoringCacheDataKey();
210     case RetrieveDecision::NoDueToStreamingMedia:
211         return WebCore::DiagnosticLoggingKeys::streamingMedia();
212     case RetrieveDecision::Yes:
213         ASSERT_NOT_REACHED();
214         break;
215     }
216     return emptyString();
217 }
218
219 void Statistics::recordNotUsingCacheForRequest(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request, RetrieveDecision retrieveDecision)
220 {
221     ASSERT(retrieveDecision != RetrieveDecision::Yes);
222
223     auto hash = key.hashAsString();
224     queryWasEverRequested(hash, NeedUncachedReason::No, [this, hash, requestURL = request.url(), webPageID, retrieveDecision](bool wasEverRequested, const Optional<StoreDecision>&) {
225         if (wasEverRequested) {
226             String diagnosticKey = retrieveDecisionToDiagnosticKey(retrieveDecision);
227             LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s was previously requested but we are not using the cache, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
228             m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheUnusedReasonKey(), diagnosticKey, WebCore::ShouldSample::Yes);
229         } else {
230             m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheUnusedReasonKey(), WebCore::DiagnosticLoggingKeys::neverSeenBeforeKey(), WebCore::ShouldSample::Yes);
231             markAsRequested(hash);
232         }
233     });
234 }
235
236 static String storeDecisionToDiagnosticKey(StoreDecision storeDecision)
237 {
238     switch (storeDecision) {
239     case StoreDecision::NoDueToProtocol:
240         return WebCore::DiagnosticLoggingKeys::notHTTPFamilyKey();
241     case StoreDecision::NoDueToHTTPMethod:
242         return WebCore::DiagnosticLoggingKeys::unsupportedHTTPMethodKey();
243     case StoreDecision::NoDueToAttachmentResponse:
244         return WebCore::DiagnosticLoggingKeys::isAttachmentKey();
245     case StoreDecision::NoDueToNoStoreResponse:
246     case StoreDecision::NoDueToNoStoreRequest:
247         return WebCore::DiagnosticLoggingKeys::cacheControlNoStoreKey();
248     case StoreDecision::NoDueToHTTPStatusCode:
249         return WebCore::DiagnosticLoggingKeys::uncacheableStatusCodeKey();
250     case StoreDecision::NoDueToUnlikelyToReuse:
251         return WebCore::DiagnosticLoggingKeys::unlikelyToReuseKey();
252     case StoreDecision::NoDueToStreamingMedia:
253         return WebCore::DiagnosticLoggingKeys::streamingMedia();
254     case StoreDecision::Yes:
255         // It was stored but could not be retrieved so it must have been pruned from the cache.
256         return WebCore::DiagnosticLoggingKeys::noLongerInCacheKey();
257     }
258     return String();
259 }
260
261 void Statistics::recordRetrievalFailure(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request)
262 {
263     auto hash = key.hashAsString();
264     queryWasEverRequested(hash, NeedUncachedReason::Yes, [this, hash, requestURL = request.url(), webPageID](bool wasPreviouslyRequested, const Optional<StoreDecision>& storeDecision) {
265         if (wasPreviouslyRequested) {
266             String diagnosticKey = storeDecisionToDiagnosticKey(storeDecision.value());
267             LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s was previously request but is not in the cache, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
268             m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheFailureReasonKey(), diagnosticKey, WebCore::ShouldSample::Yes);
269         } else {
270             m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheFailureReasonKey(), WebCore::DiagnosticLoggingKeys::neverSeenBeforeKey(), WebCore::ShouldSample::Yes);
271             markAsRequested(hash);
272         }
273     });
274 }
275
276 static String cachedEntryReuseFailureToDiagnosticKey(UseDecision decision)
277 {
278     switch (decision) {
279     case UseDecision::NoDueToVaryingHeaderMismatch:
280         return WebCore::DiagnosticLoggingKeys::varyingHeaderMismatchKey();
281     case UseDecision::NoDueToMissingValidatorFields:
282         return WebCore::DiagnosticLoggingKeys::missingValidatorFieldsKey();
283     case UseDecision::NoDueToDecodeFailure:
284     case UseDecision::NoDueToExpiredRedirect:
285     case UseDecision::Use:
286     case UseDecision::Validate:
287         ASSERT_NOT_REACHED();
288         break;
289     }
290     return emptyString();
291 }
292
293 void Statistics::recordRetrievedCachedEntry(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request, UseDecision decision)
294 {
295     URL requestURL = request.url();
296     if (decision == UseDecision::Use) {
297         LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s is in the cache and is used", webPageID, requestURL.string().ascii().data());
298         m_cache.networkProcess().logDiagnosticMessageWithResult(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingResultPass, WebCore::ShouldSample::Yes);
299         return;
300     }
301
302     if (decision == UseDecision::Validate) {
303         LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s is in the cache but needs revalidation", webPageID, requestURL.string().ascii().data());
304         m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::needsRevalidationKey(), WebCore::ShouldSample::Yes);
305         return;
306     }
307
308     String diagnosticKey = cachedEntryReuseFailureToDiagnosticKey(decision);
309     LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s is in the cache but wasn't used, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
310     m_cache.networkProcess().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheReuseFailureKey(), diagnosticKey, WebCore::ShouldSample::Yes);
311 }
312
313 void Statistics::recordRevalidationSuccess(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request)
314 {
315     URL requestURL = request.url();
316     LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s was successfully revalidated", webPageID, requestURL.string().ascii().data());
317
318     m_cache.networkProcess().logDiagnosticMessageWithResult(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::revalidatingKey(), WebCore::DiagnosticLoggingResultPass, WebCore::ShouldSample::Yes);
319 }
320
321 void Statistics::markAsRequested(const String& hash)
322 {
323     ASSERT(RunLoop::isMain());
324
325     m_hashesToAdd.add(hash);
326     if (!m_writeTimer.isActive())
327         m_writeTimer.startOneShot(mininumWriteInterval);
328 }
329
330 void Statistics::writeTimerFired()
331 {
332     ASSERT(RunLoop::isMain());
333
334     serialBackgroundIOQueue().dispatch([this, hashesToAdd = WTFMove(m_hashesToAdd), storeDecisionsToAdd = WTFMove(m_storeDecisionsToAdd)] {
335         if (!m_database.isOpen())
336             return;
337
338         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
339         WebCore::SQLiteTransaction writeTransaction(m_database);
340         writeTransaction.begin();
341
342         addHashesToDatabase(hashesToAdd);
343         addStoreDecisionsToDatabase(storeDecisionsToAdd);
344
345         writeTransaction.commit();
346     });
347
348     shrinkIfNeeded();
349 }
350
351 void Statistics::queryWasEverRequested(const String& hash, NeedUncachedReason needUncachedReason, RequestedCompletionHandler&& completionHandler)
352 {
353     ASSERT(RunLoop::isMain());
354
355     // Query pending writes first.
356     bool wasAlreadyRequested = m_hashesToAdd.contains(hash);
357     if (wasAlreadyRequested && needUncachedReason == NeedUncachedReason::No) {
358         completionHandler(true, WTF::nullopt);
359         return;
360     }
361     if (needUncachedReason == NeedUncachedReason::Yes && m_storeDecisionsToAdd.contains(hash)) {
362         completionHandler(true, m_storeDecisionsToAdd.get(hash));
363         return;
364     }
365
366     // Query the database.
367     auto everRequestedQuery = std::make_unique<EverRequestedQuery>(EverRequestedQuery { hash, needUncachedReason == NeedUncachedReason::Yes, WTFMove(completionHandler) });
368     auto& query = *everRequestedQuery;
369     m_activeQueries.add(WTFMove(everRequestedQuery));
370     serialBackgroundIOQueue().dispatch([this, wasAlreadyRequested, &query] () mutable {
371         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
372         Optional<StoreDecision> storeDecision;
373         if (m_database.isOpen()) {
374             if (!wasAlreadyRequested) {
375                 WebCore::SQLiteStatement statement(m_database, "SELECT hash FROM AlreadyRequested WHERE hash=?"_s);
376                 if (statement.prepare() == SQLITE_OK) {
377                     statement.bindText(1, query.hash);
378                     wasAlreadyRequested = (statement.step() == SQLITE_ROW);
379                 }
380             }
381             if (wasAlreadyRequested && query.needUncachedReason) {
382                 WebCore::SQLiteStatement statement(m_database, "SELECT reason FROM UncachedReason WHERE hash=?"_s);
383                 storeDecision = StoreDecision::Yes;
384                 if (statement.prepare() == SQLITE_OK) {
385                     statement.bindText(1, query.hash);
386                     if (statement.step() == SQLITE_ROW)
387                         storeDecision = static_cast<StoreDecision>(statement.getColumnInt(0));
388                 }
389             }
390         }
391         RunLoop::main().dispatch([this, &query, wasAlreadyRequested, storeDecision] {
392             query.completionHandler(wasAlreadyRequested, storeDecision);
393             m_activeQueries.remove(&query);
394         });
395     });
396 }
397
398 void Statistics::clear()
399 {
400     ASSERT(RunLoop::isMain());
401
402     serialBackgroundIOQueue().dispatch([this] {
403         if (m_database.isOpen()) {
404             WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
405             WebCore::SQLiteTransaction deleteTransaction(m_database);
406             deleteTransaction.begin();
407             executeSQLCommand(m_database, "DELETE FROM AlreadyRequested"_s);
408             executeSQLCommand(m_database, "DELETE FROM UncachedReason"_s);
409             deleteTransaction.commit();
410             m_approximateEntryCount = 0;
411         }
412     });
413 }
414
415 void Statistics::addHashesToDatabase(const HashSet<String>& hashes)
416 {
417     ASSERT(!RunLoop::isMain());
418     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
419     ASSERT(m_database.isOpen());
420
421     WebCore::SQLiteStatement statement(m_database, "INSERT OR IGNORE INTO AlreadyRequested (hash) VALUES (?)"_s);
422     if (statement.prepare() != SQLITE_OK)
423         return;
424
425     for (auto& hash : hashes) {
426         statement.bindText(1, hash);
427         if (executeSQLStatement(statement))
428             ++m_approximateEntryCount;
429         statement.reset();
430     }
431 }
432
433 void Statistics::addStoreDecisionsToDatabase(const HashMap<String, NetworkCache::StoreDecision>& storeDecisions)
434 {
435     ASSERT(!RunLoop::isMain());
436     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
437     ASSERT(m_database.isOpen());
438
439     WebCore::SQLiteStatement statement(m_database, "INSERT OR REPLACE INTO UncachedReason (hash, reason) VALUES (?, ?)"_s);
440     if (statement.prepare() != SQLITE_OK)
441         return;
442
443     for (auto& pair : storeDecisions) {
444         statement.bindText(1, pair.key);
445         statement.bindInt(2, static_cast<int>(pair.value));
446         executeSQLStatement(statement);
447         statement.reset();
448     }
449 }
450
451 }
452 }