Fix remaining bad uses of logDiagnosticMessageWithValue()
[WebKit-https.git] / Source / WebKit2 / 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 #if ENABLE(NETWORK_CACHE)
29 #include "NetworkCacheStatistics.h"
30
31 #include "Logging.h"
32 #include "NetworkCache.h"
33 #include "NetworkCacheFileSystem.h"
34 #include "NetworkProcess.h"
35 #include <WebCore/DiagnosticLoggingKeys.h>
36 #include <WebCore/DiagnosticLoggingResultType.h>
37 #include <WebCore/ResourceRequest.h>
38 #include <WebCore/SQLiteDatabaseTracker.h>
39 #include <WebCore/SQLiteStatement.h>
40 #include <WebCore/SQLiteTransaction.h>
41 #include <wtf/RunLoop.h>
42
43 namespace WebKit {
44 namespace NetworkCache {
45
46 static const char* StatisticsDatabaseName = "WebKitCacheStatistics.db";
47 static const std::chrono::milliseconds mininumWriteInterval = std::chrono::milliseconds(10000);
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(const String& cachePath)
77 {
78     ASSERT(RunLoop::isMain());
79
80     String databasePath = WebCore::pathByAppendingComponent(cachePath, StatisticsDatabaseName);
81     return std::make_unique<Statistics>(databasePath);
82 }
83
84 Statistics::Statistics(const String& databasePath)
85     : m_serialBackgroundIOQueue(WorkQueue::create("com.apple.WebKit.Cache.Statistics.Background", WorkQueue::Type::Serial, WorkQueue::QOS::Background))
86     , m_writeTimer(*this, &Statistics::writeTimerFired)
87 {
88     initialize(databasePath);
89 }
90
91 void Statistics::initialize(const String& databasePath)
92 {
93     ASSERT(RunLoop::isMain());
94
95     auto startTime = std::chrono::system_clock::now();
96
97     serialBackgroundIOQueue().dispatch([this, databasePath = databasePath.isolatedCopy(), networkCachePath = singleton().recordsPath().isolatedCopy(), startTime] {
98         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
99
100         if (!WebCore::makeAllDirectories(WebCore::directoryName(databasePath)))
101             return;
102
103         LOG(NetworkCache, "(NetworkProcess) Opening network cache statistics database at %s...", databasePath.utf8().data());
104         m_database.open(databasePath);
105         m_database.disableThreadingChecks();
106         if (!m_database.isOpen()) {
107             LOG_ERROR("Network cache statistics: Failed to open / create the network cache statistics database");
108             return;
109         }
110
111         executeSQLCommand(m_database, ASCIILiteral("CREATE TABLE IF NOT EXISTS AlreadyRequested (hash TEXT PRIMARY KEY)"));
112         executeSQLCommand(m_database, ASCIILiteral("CREATE TABLE IF NOT EXISTS UncachedReason (hash TEXT PRIMARY KEY, reason INTEGER)"));
113
114         WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT count(*) FROM AlreadyRequested"));
115         if (statement.prepareAndStep() != SQLITE_ROW) {
116             LOG_ERROR("Network cache statistics: Failed to count the number of rows in AlreadyRequested table");
117             return;
118         }
119
120         m_approximateEntryCount = statement.getColumnInt(0);
121
122 #if !LOG_DISABLED
123         auto elapsedMS = static_cast<int64_t>(std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - startTime).count());
124 #endif
125         LOG(NetworkCache, "(NetworkProcess) Network cache statistics database load complete, entries=%lu time=%" PRIi64 "ms", static_cast<size_t>(m_approximateEntryCount), elapsedMS);
126
127         if (!m_approximateEntryCount) {
128             bootstrapFromNetworkCache(networkCachePath);
129 #if !LOG_DISABLED
130             elapsedMS = static_cast<int64_t>(std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - startTime).count());
131 #endif
132             LOG(NetworkCache, "(NetworkProcess) Network cache statistics database bootstrapping complete, entries=%lu time=%" PRIi64 "ms", static_cast<size_t>(m_approximateEntryCount), elapsedMS);
133         }
134     });
135 }
136
137 void Statistics::bootstrapFromNetworkCache(const String& networkCachePath)
138 {
139     ASSERT(!RunLoop::isMain());
140
141     LOG(NetworkCache, "(NetworkProcess) Bootstrapping the network cache statistics database from the network cache...");
142
143     HashSet<String> hashes;
144     traverseRecordsFiles(networkCachePath, ASCIILiteral("Resource"), [&hashes](const String& fileName, const String& hashString, const String& type, bool isBodyBlob, const String& recordDirectoryPath) {
145         if (isBodyBlob)
146             return;
147
148         Key::HashType hash;
149         if (!Key::stringToHash(hashString, hash))
150             return;
151
152         hashes.add(hashString);
153     });
154
155     WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
156     WebCore::SQLiteTransaction writeTransaction(m_database);
157     writeTransaction.begin();
158
159     addHashesToDatabase(hashes);
160
161     writeTransaction.commit();
162 }
163
164 void Statistics::shrinkIfNeeded()
165 {
166     ASSERT(RunLoop::isMain());
167     const size_t maxEntries = 100000;
168
169     if (m_approximateEntryCount < maxEntries)
170         return;
171
172     LOG(NetworkCache, "(NetworkProcess) shrinking statistics cache m_approximateEntryCount=%lu, maxEntries=%lu", static_cast<size_t>(m_approximateEntryCount), maxEntries);
173
174     clear();
175
176     serialBackgroundIOQueue().dispatch([this, networkCachePath = singleton().recordsPath().isolatedCopy()] {
177         bootstrapFromNetworkCache(networkCachePath);
178         LOG(NetworkCache, "(NetworkProcess) statistics cache shrink completed m_approximateEntryCount=%lu", static_cast<size_t>(m_approximateEntryCount));
179     });
180 }
181
182 void Statistics::recordRetrievalRequest(uint64_t webPageID)
183 {
184     NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalRequestKey(), WebCore::ShouldSample::Yes);
185 }
186
187 void Statistics::recordNotCachingResponse(const Key& key, StoreDecision storeDecision)
188 {
189     ASSERT(storeDecision != StoreDecision::Yes);
190
191     m_storeDecisionsToAdd.set(key.hashAsString(), storeDecision);
192     if (!m_writeTimer.isActive())
193         m_writeTimer.startOneShot(mininumWriteInterval);
194 }
195
196 static String retrieveDecisionToDiagnosticKey(RetrieveDecision retrieveDecision)
197 {
198     switch (retrieveDecision) {
199     case RetrieveDecision::NoDueToHTTPMethod:
200         return WebCore::DiagnosticLoggingKeys::unsupportedHTTPMethodKey();
201     case RetrieveDecision::NoDueToConditionalRequest:
202         return WebCore::DiagnosticLoggingKeys::isConditionalRequestKey();
203     case RetrieveDecision::NoDueToReloadIgnoringCache:
204         return WebCore::DiagnosticLoggingKeys::isReloadIgnoringCacheDataKey();
205     case RetrieveDecision::NoDueToStreamingMedia:
206         return WebCore::DiagnosticLoggingKeys::streamingMedia();
207     case RetrieveDecision::Yes:
208         ASSERT_NOT_REACHED();
209         break;
210     }
211     return emptyString();
212 }
213
214 void Statistics::recordNotUsingCacheForRequest(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request, RetrieveDecision retrieveDecision)
215 {
216     ASSERT(retrieveDecision != RetrieveDecision::Yes);
217
218     auto hash = key.hashAsString();
219     queryWasEverRequested(hash, NeedUncachedReason::No, [this, hash, requestURL = request.url(), webPageID, retrieveDecision](bool wasEverRequested, const std::optional<StoreDecision>&) {
220         if (wasEverRequested) {
221             String diagnosticKey = retrieveDecisionToDiagnosticKey(retrieveDecision);
222             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());
223             NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheUnusedReasonKey(), diagnosticKey, WebCore::ShouldSample::Yes);
224         } else {
225             NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheUnusedReasonKey(), WebCore::DiagnosticLoggingKeys::neverSeenBeforeKey(), WebCore::ShouldSample::Yes);
226             markAsRequested(hash);
227         }
228     });
229 }
230
231 static String storeDecisionToDiagnosticKey(StoreDecision storeDecision)
232 {
233     switch (storeDecision) {
234     case StoreDecision::NoDueToProtocol:
235         return WebCore::DiagnosticLoggingKeys::notHTTPFamilyKey();
236     case StoreDecision::NoDueToHTTPMethod:
237         return WebCore::DiagnosticLoggingKeys::unsupportedHTTPMethodKey();
238     case StoreDecision::NoDueToAttachmentResponse:
239         return WebCore::DiagnosticLoggingKeys::isAttachmentKey();
240     case StoreDecision::NoDueToNoStoreResponse:
241     case StoreDecision::NoDueToNoStoreRequest:
242         return WebCore::DiagnosticLoggingKeys::cacheControlNoStoreKey();
243     case StoreDecision::NoDueToHTTPStatusCode:
244         return WebCore::DiagnosticLoggingKeys::uncacheableStatusCodeKey();
245     case StoreDecision::NoDueToUnlikelyToReuse:
246         return WebCore::DiagnosticLoggingKeys::unlikelyToReuseKey();
247     case StoreDecision::NoDueToStreamingMedia:
248         return WebCore::DiagnosticLoggingKeys::streamingMedia();
249     case StoreDecision::Yes:
250         // It was stored but could not be retrieved so it must have been pruned from the cache.
251         return WebCore::DiagnosticLoggingKeys::noLongerInCacheKey();
252     }
253     return String();
254 }
255
256 void Statistics::recordRetrievalFailure(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request)
257 {
258     auto hash = key.hashAsString();
259     queryWasEverRequested(hash, NeedUncachedReason::Yes, [this, hash, requestURL = request.url(), webPageID](bool wasPreviouslyRequested, const std::optional<StoreDecision>& storeDecision) {
260         if (wasPreviouslyRequested) {
261             String diagnosticKey = storeDecisionToDiagnosticKey(storeDecision.value());
262             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());
263             NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheFailureReasonKey(), diagnosticKey, WebCore::ShouldSample::Yes);
264         } else {
265             NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheFailureReasonKey(), WebCore::DiagnosticLoggingKeys::neverSeenBeforeKey(), WebCore::ShouldSample::Yes);
266             markAsRequested(hash);
267         }
268     });
269 }
270
271 static String cachedEntryReuseFailureToDiagnosticKey(UseDecision decision)
272 {
273     switch (decision) {
274     case UseDecision::NoDueToVaryingHeaderMismatch:
275         return WebCore::DiagnosticLoggingKeys::varyingHeaderMismatchKey();
276     case UseDecision::NoDueToMissingValidatorFields:
277         return WebCore::DiagnosticLoggingKeys::missingValidatorFieldsKey();
278     case UseDecision::NoDueToDecodeFailure:
279     case UseDecision::NoDueToExpiredRedirect:
280         return WebCore::DiagnosticLoggingKeys::otherKey();
281     case UseDecision::Use:
282     case UseDecision::Validate:
283         ASSERT_NOT_REACHED();
284         break;
285     }
286     return emptyString();
287 }
288
289 void Statistics::recordRetrievedCachedEntry(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request, UseDecision decision)
290 {
291     WebCore::URL requestURL = request.url();
292     if (decision == UseDecision::Use) {
293         LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s is in the cache and is used", webPageID, requestURL.string().ascii().data());
294         NetworkProcess::singleton().logDiagnosticMessageWithResult(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingResultPass, WebCore::ShouldSample::Yes);
295         return;
296     }
297
298     if (decision == UseDecision::Validate) {
299         LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s is in the cache but needs revalidation", webPageID, requestURL.string().ascii().data());
300         NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::needsRevalidationKey(), WebCore::ShouldSample::Yes);
301         return;
302     }
303
304     String diagnosticKey = cachedEntryReuseFailureToDiagnosticKey(decision);
305     LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s is in the cache but wasn't used, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
306     NetworkProcess::singleton().logDiagnosticMessage(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheReuseFailureKey(), diagnosticKey, WebCore::ShouldSample::Yes);
307 }
308
309 void Statistics::recordRevalidationSuccess(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request)
310 {
311     WebCore::URL requestURL = request.url();
312     LOG(NetworkCache, "(NetworkProcess) webPageID %" PRIu64 ": %s was successfully revalidated", webPageID, requestURL.string().ascii().data());
313
314     NetworkProcess::singleton().logDiagnosticMessageWithResult(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::revalidatingKey(), WebCore::DiagnosticLoggingResultPass, WebCore::ShouldSample::Yes);
315 }
316
317 void Statistics::markAsRequested(const String& hash)
318 {
319     ASSERT(RunLoop::isMain());
320
321     m_hashesToAdd.add(hash);
322     if (!m_writeTimer.isActive())
323         m_writeTimer.startOneShot(mininumWriteInterval);
324 }
325
326 void Statistics::writeTimerFired()
327 {
328     ASSERT(RunLoop::isMain());
329
330     serialBackgroundIOQueue().dispatch([this, hashesToAdd = WTFMove(m_hashesToAdd), storeDecisionsToAdd = WTFMove(m_storeDecisionsToAdd)] {
331         if (!m_database.isOpen())
332             return;
333
334         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
335         WebCore::SQLiteTransaction writeTransaction(m_database);
336         writeTransaction.begin();
337
338         addHashesToDatabase(hashesToAdd);
339         addStoreDecisionsToDatabase(storeDecisionsToAdd);
340
341         writeTransaction.commit();
342     });
343
344     shrinkIfNeeded();
345 }
346
347 void Statistics::queryWasEverRequested(const String& hash, NeedUncachedReason needUncachedReason, RequestedCompletionHandler&& completionHandler)
348 {
349     ASSERT(RunLoop::isMain());
350
351     // Query pending writes first.
352     bool wasAlreadyRequested = m_hashesToAdd.contains(hash);
353     if (wasAlreadyRequested && needUncachedReason == NeedUncachedReason::No) {
354         completionHandler(true, std::nullopt);
355         return;
356     }
357     if (needUncachedReason == NeedUncachedReason::Yes && m_storeDecisionsToAdd.contains(hash)) {
358         completionHandler(true, m_storeDecisionsToAdd.get(hash));
359         return;
360     }
361
362     // Query the database.
363     auto everRequestedQuery = std::make_unique<EverRequestedQuery>(EverRequestedQuery { hash, needUncachedReason == NeedUncachedReason::Yes, WTFMove(completionHandler) });
364     auto& query = *everRequestedQuery;
365     m_activeQueries.add(WTFMove(everRequestedQuery));
366     serialBackgroundIOQueue().dispatch([this, wasAlreadyRequested, &query] () mutable {
367         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
368         std::optional<StoreDecision> storeDecision;
369         if (m_database.isOpen()) {
370             if (!wasAlreadyRequested) {
371                 WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT hash FROM AlreadyRequested WHERE hash=?"));
372                 if (statement.prepare() == SQLITE_OK) {
373                     statement.bindText(1, query.hash);
374                     wasAlreadyRequested = (statement.step() == SQLITE_ROW);
375                 }
376             }
377             if (wasAlreadyRequested && query.needUncachedReason) {
378                 WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT reason FROM UncachedReason WHERE hash=?"));
379                 storeDecision = StoreDecision::Yes;
380                 if (statement.prepare() == SQLITE_OK) {
381                     statement.bindText(1, query.hash);
382                     if (statement.step() == SQLITE_ROW)
383                         storeDecision = static_cast<StoreDecision>(statement.getColumnInt(0));
384                 }
385             }
386         }
387         RunLoop::main().dispatch([this, &query, wasAlreadyRequested, storeDecision] {
388             query.completionHandler(wasAlreadyRequested, storeDecision);
389             m_activeQueries.remove(&query);
390         });
391     });
392 }
393
394 void Statistics::clear()
395 {
396     ASSERT(RunLoop::isMain());
397
398     serialBackgroundIOQueue().dispatch([this] {
399         if (m_database.isOpen()) {
400             WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
401             WebCore::SQLiteTransaction deleteTransaction(m_database);
402             deleteTransaction.begin();
403             executeSQLCommand(m_database, ASCIILiteral("DELETE FROM AlreadyRequested"));
404             executeSQLCommand(m_database, ASCIILiteral("DELETE FROM UncachedReason"));
405             deleteTransaction.commit();
406             m_approximateEntryCount = 0;
407         }
408     });
409 }
410
411 void Statistics::addHashesToDatabase(const HashSet<String>& hashes)
412 {
413     ASSERT(!RunLoop::isMain());
414     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
415     ASSERT(m_database.isOpen());
416
417     WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT OR IGNORE INTO AlreadyRequested (hash) VALUES (?)"));
418     if (statement.prepare() != SQLITE_OK)
419         return;
420
421     for (auto& hash : hashes) {
422         statement.bindText(1, hash);
423         if (executeSQLStatement(statement))
424             ++m_approximateEntryCount;
425         statement.reset();
426     }
427 }
428
429 void Statistics::addStoreDecisionsToDatabase(const HashMap<String, NetworkCache::StoreDecision>& storeDecisions)
430 {
431     ASSERT(!RunLoop::isMain());
432     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
433     ASSERT(m_database.isOpen());
434
435     WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT OR REPLACE INTO UncachedReason (hash, reason) VALUES (?, ?)"));
436     if (statement.prepare() != SQLITE_OK)
437         return;
438
439     for (auto& pair : storeDecisions) {
440         statement.bindText(1, pair.key);
441         statement.bindInt(2, static_cast<int>(pair.value));
442         executeSQLStatement(statement);
443         statement.reset();
444     }
445 }
446
447 }
448 }
449
450 #endif // ENABLE(NETWORK_CACHE)