Bug 141269 – [WK2] Add logging to validate the network cache efficacy (Part 1)

• Component: Page Loading
• Status: RESOLVED FIXED

[Chris Dumez]

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>

[Chris Dumez]

Created attachment 246063 [details]
WIP patch

Still needs another pass but uploading already in case Antti has some early feedback on the overall approach.

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246076 [details]
WIP Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246082 [details]
WIP Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

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.

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246090 [details]
WIP Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246123 [details]
WIP Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246131 [details]
WIP Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246139 [details]
Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246141 [details]
Patch

[WebKit Commit Bot]

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.

[Antti Koivisto]

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.

[Chris Dumez]

Created attachment 246184 [details]
Patch

[Chris Dumez]

Now using SQLite as backend.

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246189 [details]
Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246197 [details]
Patch

[WebKit Commit Bot]

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.

[Antti Koivisto]

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.

[Chris Dumez]

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.

[Chris Dumez]

Created attachment 246220 [details]
Patch

[WebKit Commit Bot]

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.

[Chris Dumez]

Created attachment 246221 [details]
Patch

[Chris Dumez]

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

[WebKit Commit Bot]

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.

[Chris Dumez]

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.

[WebKit Commit Bot]

Comment on attachment 246221 [details]
Patch

Clearing flags on attachment: 246221

Committed r179804: <http://trac.webkit.org/changeset/179804>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.