Bug 141269 - [WK2] Add logging to validate the network cache efficacy (Part 1)
Summary: [WK2] Add logging to validate the network cache efficacy (Part 1)
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Page Loading (show other bugs)
Version: 528+ (Nightly build)
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Chris Dumez
URL:
Keywords: InRadar
Depends on:
Blocks: 141345
  Show dependency treegraph
 
Reported: 2015-02-04 15:38 PST by Chris Dumez
Modified: 2015-02-08 14:06 PST (History)
3 users (show)

See Also:


Attachments
WIP patch (12.39 KB, patch)
2015-02-04 15:49 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
WIP Patch (25.21 KB, patch)
2015-02-04 20:12 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
WIP Patch (28.58 KB, patch)
2015-02-04 22:26 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
WIP Patch (28.34 KB, patch)
2015-02-04 22:31 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
WIP Patch (28.42 KB, patch)
2015-02-04 22:51 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
WIP Patch (28.69 KB, patch)
2015-02-05 12:57 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
WIP Patch (33.33 KB, patch)
2015-02-05 14:46 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (36.19 KB, patch)
2015-02-05 16:59 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (36.23 KB, patch)
2015-02-05 17:16 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (39.88 KB, patch)
2015-02-06 15:57 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (39.57 KB, patch)
2015-02-06 16:41 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (39.69 KB, patch)
2015-02-06 19:10 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (38.10 KB, patch)
2015-02-07 15:32 PST, Chris Dumez
no flags Details | Formatted Diff | Diff
Patch (38.15 KB, patch)
2015-02-07 15:35 PST, Chris Dumez
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Chris Dumez 2015-02-04 15:38:28 PST
Add logging to measure the network cache efficacy.

This is part 1, containing the console logging code inside the NetworkCache.
The diagnostic logging wiring will be added in a follow-up patch.

Radar: <rdar://problem/19632080>
Comment 1 Chris Dumez 2015-02-04 15:49:52 PST
Created attachment 246063 [details]
WIP patch

Still needs another pass but uploading already in case Antti has some early feedback on the overall approach.
Comment 2 WebKit Commit Bot 2015-02-04 15:52:25 PST
Attachment 246063 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStorage.h:144:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:256:  Place brace on its own line for function definitions.  [whitespace/braces] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStorageCocoa.mm:142:  Weird number of spaces at line-start.  Are you using a 4-space indent?  [whitespace/indent] [3]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStorageCocoa.mm:167:  Place brace on its own line for function definitions.  [whitespace/braces] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStorageCocoa.mm:470:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 5 in 4 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 3 Chris Dumez 2015-02-04 20:12:17 PST
Created attachment 246076 [details]
WIP Patch
Comment 4 WebKit Commit Bot 2015-02-04 20:13:44 PST
Attachment 246076 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:30:  You should not add a blank line before implementation file's own header.  [build/include_order] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:93:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:42:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 4 in 8 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 5 Chris Dumez 2015-02-04 22:26:37 PST
Created attachment 246082 [details]
WIP Patch
Comment 6 WebKit Commit Bot 2015-02-04 22:28:06 PST
Attachment 246082 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:30:  You should not add a blank line before implementation file's own header.  [build/include_order] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:109:  Extra space before last semicolon. If this should be an empty statement, use { } instead.  [whitespace/semicolon] [5]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:165:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:42:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 5 in 8 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 7 Chris Dumez 2015-02-04 22:31:27 PST
Created attachment 246083 [details]
WIP Patch

Ok, this latest patch takes into consideration Antti's feedback from IRC, except the setting to make this logging conditional at run time (I'll add that tomorrow and double check everything).
In the mean time, please let me know if you have other comments.
Comment 8 WebKit Commit Bot 2015-02-04 22:32:59 PST
Attachment 246083 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:30:  You should not add a blank line before implementation file's own header.  [build/include_order] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:109:  Extra space before last semicolon. If this should be an empty statement, use { } instead.  [whitespace/semicolon] [5]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:165:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:42:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 5 in 8 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 9 Chris Dumez 2015-02-04 22:51:46 PST
Created attachment 246090 [details]
WIP Patch
Comment 10 WebKit Commit Bot 2015-02-04 22:53:12 PST
Attachment 246090 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:30:  You should not add a blank line before implementation file's own header.  [build/include_order] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:110:  Extra space before last semicolon. If this should be an empty statement, use { } instead.  [whitespace/semicolon] [5]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:166:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:42:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 5 in 8 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 11 Chris Dumez 2015-02-05 12:57:38 PST
Created attachment 246123 [details]
WIP Patch
Comment 12 WebKit Commit Bot 2015-02-05 13:08:26 PST
Attachment 246123 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:30:  You should not add a blank line before implementation file's own header.  [build/include_order] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:110:  Extra space before last semicolon. If this should be an empty statement, use { } instead.  [whitespace/semicolon] [5]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:167:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:42:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:54:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 6 in 8 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 13 Chris Dumez 2015-02-05 14:46:36 PST
Created attachment 246131 [details]
WIP Patch
Comment 14 WebKit Commit Bot 2015-02-05 14:48:33 PST
Attachment 246131 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:30:  You should not add a blank line before implementation file's own header.  [build/include_order] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:110:  Extra space before last semicolon. If this should be an empty statement, use { } instead.  [whitespace/semicolon] [5]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorageCocoa.mm:167:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:42:  Extra space before ( in function call  [whitespace/parens] [4]
ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheStatsStorage.h:54:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 6 in 12 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 15 Chris Dumez 2015-02-05 16:59:19 PST
Created attachment 246139 [details]
Patch
Comment 16 WebKit Commit Bot 2015-02-05 17:01:35 PST
Attachment 246139 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 13 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 17 Chris Dumez 2015-02-05 17:16:44 PST
Created attachment 246141 [details]
Patch
Comment 18 WebKit Commit Bot 2015-02-05 17:19:57 PST
Attachment 246141 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 13 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 19 Antti Koivisto 2015-02-06 08:11:39 PST
Comment on attachment 246141 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=246141&action=review

r+ since there will be subsequent patches. I'm still bit confused by some aspects here.

> Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:58
> +        m_statisticsStorage = NetworkCacheStatistics::open(cachePath);

m_statisticsStorage -> m_statistics

> Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:231
> +    WebCore::URL requestURL = originalRequest.url();
> +    NetworkCacheKey storageKey = makeCacheKey(originalRequest);
>      if (!canRetrieve(originalRequest)) {
> +        if (isEfficacyLoggingEnabled()) {
> +            m_statisticsStorage->wasPreviouslySeen(storageKey, [this, storageKey, requestURL](bool wasPreviouslySeen) {

You are capturing 'this' just so you can call back to m_statisticsStorage, not a very nice pattern. 

Generally I would prefer encapsulating more of this to NetworkCacheStatistics:

if (m_statistics)
   m_statistics->recordNotUsingCacheForRequest(originalRequest);

and move the equivalent code there. I'd like NetworkCache to be about HTTP semantics.

> Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:234
> +                if (wasPreviouslySeen) {
> +                    LOG(NetworkCache, "(NetworkProcess) %s was previously seen but wasn't cacheable", requestURL.string().ascii().data());
> +                    // FIXME: Do diagnostic logging.

The log message here is not really correct. Cacheability is a property of the response, not request. Here we filter out some request that we know can't be handled by the cache.

> Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:257
> +            if (isEfficacyLoggingEnabled()) {
> +                m_statisticsStorage->wasPreviouslySeen(storageKey, [this, storageKey, requestURL](bool wasPreviouslySeen) {
> +                    if (wasPreviouslySeen) {
> +                        LOG(NetworkCache, "(NetworkProcess) %s was previously cached but is no longer in the cache", requestURL.string().ascii().data());
> +                        // FIXME: Do diagnostic logging.
> +                    } else
> +                        m_statisticsStorage->markAsSeen(storageKey);
> +                });
> +            }

Similarly this would be 

if (m_statistics)
   m_statistics->recordRetrieveFailed(originalRequest);

I'm confused what markAsSeen() indicates. It probably needs a more descriptive name. Is it "did we ever try to request this resource"? If so shouldn't you also set it when the retrieve succeeds?

> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h:39
> +    typedef std::function<void (bool wasPreviouslySeen)> CompletionHandler;

This could use a less generic name than "CompletionHandler"

> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h:43
> +    void wasPreviouslySeen(const NetworkCacheKey&, const CompletionHandler&) const;

queryPreviouslySeen?

> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm:104
> +            // Create empty file in cache statistics folder.
> +            String statisticsPartitionPath = partitionPath;
> +            statisticsPartitionPath.replace(cachePath, cacheStatisticsPath);
> +            createEmptyFile(WebCore::pathByAppendingComponent(statisticsPartitionPath, fileName));

This is a rather funky way of storing information. Something bit more traditional (like SQLite) might be appropriate for statistics collection.
Comment 20 Chris Dumez 2015-02-06 15:57:47 PST
Created attachment 246184 [details]
Patch
Comment 21 Chris Dumez 2015-02-06 15:58:48 PST
Now using SQLite as backend.
Comment 22 WebKit Commit Bot 2015-02-06 15:59:28 PST
Attachment 246184 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 15 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 23 Chris Dumez 2015-02-06 16:41:51 PST
Created attachment 246189 [details]
Patch
Comment 24 WebKit Commit Bot 2015-02-06 16:47:27 PST
Attachment 246189 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 15 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 25 Chris Dumez 2015-02-06 19:10:09 PST
Created attachment 246197 [details]
Patch
Comment 26 WebKit Commit Bot 2015-02-06 19:12:33 PST
Attachment 246197 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 15 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 27 Antti Koivisto 2015-02-07 06:04:34 PST
Comment on attachment 246197 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=246197&action=review

> Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:256
>          auto decodedEntry = decodeStorageEntry(*entry, originalRequest);
>          bool success = !!decodedEntry;
> +        if (m_statistics) {
> +            if (success)
> +                m_statistics->recordUsingCachedEntry(storageKey, originalRequest);
> +            else
> +                m_statistics->recordNotUsingCachedEntry(storageKey, originalRequest);
> +        }

This could perhaps be a single function with a success argument.

We should add the reason we failed to use the entry at some point.

> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h:71
> +    BloomFilter<20> m_everRequestedFilter;

Was there some indication that this large filter is actually needed? The simple queries done here might be pretty well-optimized in SQLite and lookups happen in a low-priority dispatch queue so shouldn't affect normal cache operation.

> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm:306
> +bool NetworkCacheStatistics::addHashToDatabase(NetworkCacheKey::HashType hash)
> +{
> +    ASSERT(!RunLoop::isMain());
> +    ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
> +    ASSERT(m_database.isOpen());
> +
> +    WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT INTO AlreadyRequested (hash) VALUES (?)"));
> +    if (statement.prepare() != WebCore::SQLResultOk)
> +        return false;
> +
> +    statement.bindInt64(1, hash);

Note that bug 141356 makes NetworkCacheKey::HashType an MD5 digest so this needs some adjustment, perhaps switching to key.hashAsString().

Similarly key.hash() -> key.shortHash() if you need 32bits.
Comment 28 Chris Dumez 2015-02-07 11:02:37 PST
Comment on attachment 246197 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=246197&action=review

>> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h:71
>> +    BloomFilter<20> m_everRequestedFilter;
> 
> Was there some indication that this large filter is actually needed? The simple queries done here might be pretty well-optimized in SQLite and lookups happen in a low-priority dispatch queue so shouldn't affect normal cache operation.

Without the bloom filter, we'll get ~2x the amount of disk I/O for each resource request. That said, this is a simple DB query on an indexed column, in a background thread. Since this is merely used for logging, we don't really need to worry about latency. I'll test locally without the bloom filter and see how it goes. Worse case scenario, we can always reintroduce the bloom filter if it causes regressions.

>> Source/WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm:306
>> +    statement.bindInt64(1, hash);
> 
> Note that bug 141356 makes NetworkCacheKey::HashType an MD5 digest so this needs some adjustment, perhaps switching to key.hashAsString().
> 
> Similarly key.hash() -> key.shortHash() if you need 32bits.

Ok, I'll adjust accordingly, assuming you land your change before me.
Comment 29 Chris Dumez 2015-02-07 15:32:19 PST
Created attachment 246220 [details]
Patch
Comment 30 WebKit Commit Bot 2015-02-07 15:33:45 PST
Attachment 246220 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 15 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 31 Chris Dumez 2015-02-07 15:35:23 PST
Created attachment 246221 [details]
Patch
Comment 32 Chris Dumez 2015-02-07 15:36:06 PST
It'd be great if you could have one last look Antti. I made the following changes:
- Removed the bloom filter for now
- Store new MD5 hashes as Strings in the database
Comment 33 WebKit Commit Bot 2015-02-07 15:36:32 PST
Attachment 246221 [details] did not pass style-queue:


ERROR: Source/WebKit2/NetworkProcess/cache/NetworkCacheFileSystemPosix.h:56:  Extra space before ( in function call  [whitespace/parens] [4]
Total errors found: 1 in 15 files


If any of these errors are false positives, please file a bug against check-webkit-style.
Comment 34 Chris Dumez 2015-02-07 15:49:53 PST
Comment on attachment 246197 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=246197&action=review

>> Source/WebKit2/NetworkProcess/cache/NetworkCache.cpp:256
>> +        }
> 
> This could perhaps be a single function with a success argument.
> 
> We should add the reason we failed to use the entry at some point.

Oh, and I made this change too.
Comment 35 WebKit Commit Bot 2015-02-08 14:06:11 PST
Comment on attachment 246221 [details]
Patch

Clearing flags on attachment: 246221

Committed r179804: <http://trac.webkit.org/changeset/179804>
Comment 36 WebKit Commit Bot 2015-02-08 14:06:19 PST
All reviewed patches have been landed.  Closing bug.