[WK2] We should not even try the network cache for non-HTTP protocol requests
[WebKit-https.git] / Source / WebKit2 / NetworkProcess / cache / NetworkCacheStatisticsCocoa.mm
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 "NetworkCacheFileSystemPosix.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() != WebCore::SQLResultDone) {
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::unique_ptr<Statistics>(new Statistics(databasePath));
82 }
83
84 Statistics::Statistics(const String& databasePath)
85     : m_backgroundIOQueue(adoptDispatch(dispatch_queue_create("com.apple.WebKit.Cache.Statistics.Background", DISPATCH_QUEUE_SERIAL)))
86     , m_writeTimer(*this, &Statistics::writeTimerFired)
87 {
88     dispatch_set_target_queue(m_backgroundIOQueue.get(), dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_BACKGROUND, 0));
89
90     initialize(databasePath);
91 }
92
93 void Statistics::initialize(const String& databasePath)
94 {
95     ASSERT(RunLoop::isMain());
96
97     auto startTime = std::chrono::system_clock::now();
98
99     StringCapture databasePathCapture(databasePath);
100     StringCapture networkCachePathCapture(singleton().storagePath());
101     dispatch_async(m_backgroundIOQueue.get(), [this, databasePathCapture, networkCachePathCapture, startTime] {
102         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
103
104         String databasePath = databasePathCapture.string();
105         if (!WebCore::makeAllDirectories(WebCore::directoryName(databasePath)))
106             return;
107
108         LOG(NetworkCache, "(NetworkProcess) Opening network cache statistics database at %s...", databasePath.utf8().data());
109         m_database.open(databasePath);
110         m_database.disableThreadingChecks();
111         if (!m_database.isOpen()) {
112             LOG_ERROR("Network cache statistics: Failed to open / create the network cache statistics database");
113             return;
114         }
115
116         executeSQLCommand(m_database, ASCIILiteral("CREATE TABLE IF NOT EXISTS AlreadyRequested (hash TEXT PRIMARY KEY)"));
117         executeSQLCommand(m_database, ASCIILiteral("CREATE TABLE IF NOT EXISTS UncachedReason (hash TEXT PRIMARY KEY, reason INTEGER)"));
118
119         WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT count(*) FROM AlreadyRequested"));
120         if (statement.prepareAndStep() != WebCore::SQLResultRow) {
121             LOG_ERROR("Network cache statistics: Failed to count the number of rows in AlreadyRequested table");
122             return;
123         }
124
125         m_approximateEntryCount = statement.getColumnInt(0);
126
127 #if !LOG_DISABLED
128         auto elapsedMS = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - startTime).count();
129 #endif
130         LOG(NetworkCache, "(NetworkProcess) Network cache statistics database load complete, entries=%lu time=%lldms", static_cast<size_t>(m_approximateEntryCount), elapsedMS);
131
132         if (!m_approximateEntryCount) {
133             bootstrapFromNetworkCache(networkCachePathCapture.string());
134 #if !LOG_DISABLED
135             elapsedMS = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - startTime).count();
136 #endif
137             LOG(NetworkCache, "(NetworkProcess) Network cache statistics database bootstrapping complete, entries=%lu time=%lldms", static_cast<size_t>(m_approximateEntryCount), elapsedMS);
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     Vector<StringCapture> hashes;
149     traverseCacheFiles(networkCachePath, [&hashes](const String& hash, const String&) {
150         hashes.append(hash);
151     });
152
153     WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
154     WebCore::SQLiteTransaction writeTransaction(m_database);
155     writeTransaction.begin();
156
157     addHashesToDatabase(hashes);
158
159     writeTransaction.commit();
160 }
161
162 void Statistics::shrinkIfNeeded()
163 {
164     ASSERT(RunLoop::isMain());
165     const size_t maxEntries = 100000;
166
167     if (m_approximateEntryCount < maxEntries)
168         return;
169
170     LOG(NetworkCache, "(NetworkProcess) shrinking statistics cache m_approximateEntryCount=%lu, maxEntries=%lu", static_cast<size_t>(m_approximateEntryCount), maxEntries);
171
172     clear();
173
174     StringCapture networkCachePathCapture(singleton().storagePath());
175     dispatch_async(m_backgroundIOQueue.get(), [this, networkCachePathCapture] {
176         bootstrapFromNetworkCache(networkCachePathCapture.string());
177         LOG(NetworkCache, "(NetworkProcess) statistics cache shrink completed m_approximateEntryCount=%lu", static_cast<size_t>(m_approximateEntryCount));
178     });
179 }
180
181 void Statistics::recordNotCachingResponse(const Key& key, StoreDecision storeDecision)
182 {
183     ASSERT(storeDecision != StoreDecision::Yes);
184
185     m_storeDecisionsToAdd.set(key.hashAsString(), storeDecision);
186     if (!m_writeTimer.isActive())
187         m_writeTimer.startOneShot(mininumWriteInterval);
188 }
189
190 static String retrieveDecisionToDiagnosticKey(RetrieveDecision retrieveDecision)
191 {
192     switch (retrieveDecision) {
193     case RetrieveDecision::NoDueToHTTPMethod:
194         return WebCore::DiagnosticLoggingKeys::unsupportedHTTPMethodKey();
195     case RetrieveDecision::NoDueToConditionalRequest:
196         return WebCore::DiagnosticLoggingKeys::isConditionalRequestKey();
197     case RetrieveDecision::NoDueToReloadIgnoringCache:
198         return WebCore::DiagnosticLoggingKeys::isReloadIgnoringCacheDataKey();
199     case RetrieveDecision::Yes:
200         ASSERT_NOT_REACHED();
201         break;
202     }
203     return emptyString();
204 }
205
206 void Statistics::recordNotUsingCacheForRequest(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request, RetrieveDecision retrieveDecision)
207 {
208     ASSERT(retrieveDecision != RetrieveDecision::Yes);
209
210     String hash = key.hashAsString();
211     WebCore::URL requestURL = request.url();
212     queryWasEverRequested(hash, NeedUncachedReason::No, [this, hash, requestURL, webPageID, retrieveDecision](bool wasEverRequested, const Optional<StoreDecision>&) {
213         if (wasEverRequested) {
214             String diagnosticKey = retrieveDecisionToDiagnosticKey(retrieveDecision);
215             LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s was previously requested but we are not using the cache, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
216             NetworkProcess::singleton().logDiagnosticMessageWithValue(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::unusedKey(), diagnosticKey, WebCore::ShouldSample::Yes);
217         } else
218             markAsRequested(hash);
219     });
220 }
221
222 static String storeDecisionToDiagnosticKey(StoreDecision storeDecision)
223 {
224     switch (storeDecision) {
225     case StoreDecision::NoDueToProtocol:
226         return WebCore::DiagnosticLoggingKeys::notHTTPFamilyKey();
227     case StoreDecision::NoDueToHTTPMethod:
228         return WebCore::DiagnosticLoggingKeys::unsupportedHTTPMethodKey();
229     case StoreDecision::NoDueToAttachmentResponse:
230         return WebCore::DiagnosticLoggingKeys::isAttachmentKey();
231     case StoreDecision::NoDueToNoStoreResponse:
232         return WebCore::DiagnosticLoggingKeys::cacheControlNoStoreKey();
233     case StoreDecision::NoDueToHTTPStatusCode:
234         return WebCore::DiagnosticLoggingKeys::uncacheableStatusCodeKey();
235     case StoreDecision::Yes:
236         // It was stored but could not be retrieved so it must have been pruned from the cache.
237         return WebCore::DiagnosticLoggingKeys::noLongerInCacheKey();
238     }
239     return String();
240 }
241
242 void Statistics::recordRetrievalFailure(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request)
243 {
244     String hash = key.hashAsString();
245     WebCore::URL requestURL = request.url();
246     queryWasEverRequested(hash, NeedUncachedReason::Yes, [this, hash, requestURL, webPageID](bool wasPreviouslyRequested, const Optional<StoreDecision>& storeDecision) {
247         if (wasPreviouslyRequested) {
248             String diagnosticKey = storeDecisionToDiagnosticKey(storeDecision.value());
249             LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s was previously request but is not in the cache, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
250             NetworkProcess::singleton().logDiagnosticMessageWithValue(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::notInCacheKey(), diagnosticKey, WebCore::ShouldSample::Yes);
251         } else
252             markAsRequested(hash);
253     });
254 }
255
256 static String cachedEntryReuseFailureToDiagnosticKey(CachedEntryReuseFailure failure)
257 {
258     switch (failure) {
259     case CachedEntryReuseFailure::VaryingHeaderMismatch:
260         return WebCore::DiagnosticLoggingKeys::varyingHeaderMismatchKey();
261     case CachedEntryReuseFailure::MissingValidatorFields:
262         return WebCore::DiagnosticLoggingKeys::missingValidatorFieldsKey();
263     case CachedEntryReuseFailure::Other:
264         return WebCore::DiagnosticLoggingKeys::otherKey();
265     case CachedEntryReuseFailure::None:
266         ASSERT_NOT_REACHED();
267         break;
268     }
269     return emptyString();
270 }
271
272 void Statistics::recordRetrievedCachedEntry(uint64_t webPageID, const Key& key, const WebCore::ResourceRequest& request, CachedEntryReuseFailure failure)
273 {
274     WebCore::URL requestURL = request.url();
275     if (failure == CachedEntryReuseFailure::None) {
276         LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s is in the cache and is used", webPageID, requestURL.string().ascii().data());
277         NetworkProcess::singleton().logDiagnosticMessageWithResult(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::retrievalKey(), WebCore::DiagnosticLoggingResultPass, WebCore::ShouldSample::Yes);
278         return;
279     }
280
281     String diagnosticKey = cachedEntryReuseFailureToDiagnosticKey(failure);
282     LOG(NetworkCache, "(NetworkProcess) webPageID %llu: %s is in the cache but wasn't used, reason: %s", webPageID, requestURL.string().ascii().data(), diagnosticKey.utf8().data());
283     NetworkProcess::singleton().logDiagnosticMessageWithValue(webPageID, WebCore::DiagnosticLoggingKeys::networkCacheKey(), WebCore::DiagnosticLoggingKeys::unusableCachedEntryKey(), diagnosticKey, WebCore::ShouldSample::Yes);
284 }
285
286 void Statistics::markAsRequested(const String& hash)
287 {
288     ASSERT(RunLoop::isMain());
289
290     m_hashesToAdd.add(hash);
291     if (!m_writeTimer.isActive())
292         m_writeTimer.startOneShot(mininumWriteInterval);
293 }
294
295 void Statistics::writeTimerFired()
296 {
297     ASSERT(RunLoop::isMain());
298
299     Vector<StringCapture> hashesToAdd;
300     copyToVector(m_hashesToAdd, hashesToAdd);
301     m_hashesToAdd.clear();
302
303     Vector<std::pair<StringCapture, StoreDecision>> storeDecisionsToAdd;
304     copyToVector(m_storeDecisionsToAdd, storeDecisionsToAdd);
305     m_storeDecisionsToAdd.clear();
306
307     shrinkIfNeeded();
308
309     dispatch_async(m_backgroundIOQueue.get(), [this, hashesToAdd, storeDecisionsToAdd] {
310         if (!m_database.isOpen())
311             return;
312
313         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
314         WebCore::SQLiteTransaction writeTransaction(m_database);
315         writeTransaction.begin();
316
317         addHashesToDatabase(hashesToAdd);
318         addStoreDecisionsToDatabase(storeDecisionsToAdd);
319
320         writeTransaction.commit();
321     });
322 }
323
324 void Statistics::queryWasEverRequested(const String& hash, NeedUncachedReason needUncachedReason, const RequestedCompletionHandler& completionHandler)
325 {
326     ASSERT(RunLoop::isMain());
327
328     // Query pending writes first.
329     bool wasAlreadyRequested = m_hashesToAdd.contains(hash);
330     if (wasAlreadyRequested && needUncachedReason == NeedUncachedReason::No) {
331         completionHandler(true, Nullopt);
332         return;
333     }
334     if (needUncachedReason == NeedUncachedReason::Yes && m_storeDecisionsToAdd.contains(hash)) {
335         completionHandler(true, m_storeDecisionsToAdd.get(hash));
336         return;
337     }
338
339     // Query the database.
340     auto everRequestedQuery = std::make_unique<EverRequestedQuery>(EverRequestedQuery { hash, needUncachedReason == NeedUncachedReason::Yes, completionHandler });
341     auto& query = *everRequestedQuery;
342     m_activeQueries.add(WTF::move(everRequestedQuery));
343     dispatch_async(m_backgroundIOQueue.get(), [this, wasAlreadyRequested, &query] () mutable {
344         WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
345         Optional<StoreDecision> storeDecision;
346         if (m_database.isOpen()) {
347             if (!wasAlreadyRequested) {
348                 WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT hash FROM AlreadyRequested WHERE hash=?"));
349                 if (statement.prepare() == WebCore::SQLResultOk) {
350                     statement.bindText(1, query.hash);
351                     wasAlreadyRequested = (statement.step() == WebCore::SQLResultRow);
352                 }
353             }
354             if (wasAlreadyRequested && query.needUncachedReason) {
355                 WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT reason FROM UncachedReason WHERE hash=?"));
356                 storeDecision = StoreDecision::Yes;
357                 if (statement.prepare() == WebCore::SQLResultOk) {
358                     statement.bindText(1, query.hash);
359                     if (statement.step() == WebCore::SQLResultRow)
360                         storeDecision = static_cast<StoreDecision>(statement.getColumnInt(0));
361                 }
362             }
363         }
364         dispatch_async(dispatch_get_main_queue(), [this, &query, wasAlreadyRequested, storeDecision] {
365             query.completionHandler(wasAlreadyRequested, storeDecision);
366             m_activeQueries.remove(&query);
367         });
368     });
369 }
370
371 void Statistics::clear()
372 {
373     ASSERT(RunLoop::isMain());
374
375     dispatch_async(m_backgroundIOQueue.get(), [this] {
376         if (m_database.isOpen()) {
377             WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
378             WebCore::SQLiteTransaction deleteTransaction(m_database);
379             deleteTransaction.begin();
380             executeSQLCommand(m_database, ASCIILiteral("DELETE FROM AlreadyRequested"));
381             executeSQLCommand(m_database, ASCIILiteral("DELETE FROM UncachedReason"));
382             deleteTransaction.commit();
383             m_approximateEntryCount = 0;
384         }
385     });
386 }
387
388 void Statistics::addHashesToDatabase(const Vector<StringCapture>& hashes)
389 {
390     ASSERT(!RunLoop::isMain());
391     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
392     ASSERT(m_database.isOpen());
393
394     WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT OR IGNORE INTO AlreadyRequested (hash) VALUES (?)"));
395     if (statement.prepare() != WebCore::SQLResultOk)
396         return;
397
398     for (auto& hash : hashes) {
399         statement.bindText(1, hash.string());
400         if (executeSQLStatement(statement))
401             ++m_approximateEntryCount;
402         statement.reset();
403     }
404 }
405
406 void Statistics::addStoreDecisionsToDatabase(const Vector<std::pair<StringCapture, StoreDecision>>& storeDecisions)
407 {
408     ASSERT(!RunLoop::isMain());
409     ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
410     ASSERT(m_database.isOpen());
411
412     WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT OR REPLACE INTO UncachedReason (hash, reason) VALUES (?, ?)"));
413     if (statement.prepare() != WebCore::SQLResultOk)
414         return;
415
416     for (auto& pair : storeDecisions) {
417         statement.bindText(1, pair.first.string());
418         statement.bindInt(2, static_cast<int>(pair.second));
419         executeSQLStatement(statement);
420         statement.reset();
421     }
422 }
423
424 }
425 }
426
427 #endif // ENABLE(NETWORK_CACHE)