I think this is because app-prod.js is always taking streamer path.
When we use streamer, it has no logic for producing code cache.(it just record time stamp)
This seems right, but at second time, it should go to path for producing cache.
But it takes stream path again.
This is the problem.

Attaching trace file for first launch

Deleted: trace_youtubeTV_firstLaunch.json.gz 16.1 MB

trace_youtubeTV_firstLaunch.json.gz 16.1 MB Download

Attaching trace file after several launch

Deleted: trace_youtubeTV_afterSeveralLaunch.json.gz 13.1 MB

trace_youtubeTV_afterSeveralLaunch.json.gz 13.1 MB Download

Tested the issue on Windows 10 using chrome reported version #54.0.2840.71 and latest canary #56.0.2907.0.

Attached a screen cast for your reference.

Following are the steps followed to reproduce the issue.
------------
1. Accessed youtube.com/tv page several time.
2.Opened dev tools and checked the console
3. Observed an error at console as app-prod.js-717.

Reporter@ - Could you please verify the screen cast and let us know if it is the issue.

Thanks..!!

Deleted: 660264.mp4 4.0 MB

	660264.mp4 4.0 MB View Download

Thank you for your screen cast.
I think that error have nothing to do with this issue.
The problem is compiling app-prod.js every time when we access youtube.com/tv.

I started looking into this, but not much progress yet.

I'm seeing the same thing as byeongha.cho@, though: app-prod.js gets compiled every time, despite hitting the Chrome cache.

We should be generating a code cache as all the requirements for it are fulfilled, but we seem to never actually call the code that would generate it. From what I'm seeing, isResourceHotForCaching in V8ScriptRunner.cpp - which is used to decide whether to build a code cache - always returns false.

From what I'm seeing, CachedMetadataHandler::setCachedMetadata doesn't seem to work.


I'm seeing this:

- V8ScriptRunner wants to write the 'timestamp' for determining whether a resource is 'hot', and calls V8ScriptRunner::setCacheTimestamp. 

- This calls the app-prod.js' blink::Resource's CachedMetadataHandler::clear.. and then setCachedMetadata.

- The blink::Resource calls sendToPlatform, which calls Platform::current()->cacheMetadata(...)

- This ends up in the browser process, in RenderMessageFilter::OnCacheableMetadataAvailable, which calls cache->WriteMetadata.

- This ends up in HttpCache::MetadataWriter, which calls Write, received an OnIOComplete(-400 [ERR_CACHE_MISS]) callback which, I take it, aborts the transaction.

- This ERR_CACHE_MISS originates in HttpCache::Transaction::BeginCacheRead, in the check that does RequiresValidation() != VALIDATION_NONE.

- RequiresValidation calls vary_data.MatchesRequest, which fails and causes it to return the value it returns. This compares the MD5 sum of the stored entry with the one it expects from the request. In the case of the write caused by setCachedMetadata, these look like md5 sums (as in: random-ish bytes) and do indeed differ.


As a caller to Resource::setCachedMetadata, I've never seen those hashsums, and don't really understand where they are coming from. It doesn't look like information I should have supplied.

From a 'high-level' perspective, all this happens while the main resource (app-prod.js) is successfully read from the cache, so I don't think this is truly a cache miss.

jkarlin: I need some help with this. Can you please take a look?

Not sure if you're the right person, but you're probably a lot closer than I am, as this is several layers away from things I actually understand. :)


Additional info:
- Please behold the saga in #13.
- This is easy to reproduce (per #0 + #11):
  - Start a browser with --user-data-dir=$(mktemp -d)
  - Go to www.youtube.com/tv. Reload twice (or more)
- There was a change in the validation logic in crrev.com/2398613002, which might have something to do with this.
- severity: This can be a very noticeable regression in startup performance (for websites that cache well).

Yes, crrev.com/2398613002 could certainly cause this. It now checks VARY headers before using a cache entry. The metadata writer makes bogus request headers which the response VARY doesn't match, and the write fails. I'll fix that.

The CL landed in M56+ though, so perhaps there is a different issue that the OP saw in M54?

#16, M54 vs M56+: Good point. I overlooked that.

We've had occasional reports about code caching not working as it should, so I was quite excited to finally have a case to cleanly reproduce this. If your change is recent (M56-ish), than this indeed suggests that there's something else going on. :(

My preference would be if I could wait for your fix, though, since - at least in this case - the vary_data.MatchesRequest thing shadows whatever other problem we may have on our side. Could you re-assign the bug to me once your fix is in?

Status update: The fix for the cache part of this has been up for a few days at https://codereview.chromium.org/2539323003/, just waiting for a review.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19

commit dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19
Author: jkarlin <jkarlin@chromium.org>
Date: Thu Dec 08 21:31:00 2016

[HttpCacheTransaction] Ignore vary check for WriteMetadata requests

BUG=660264

Review-Url: https://codereview.chromium.org/2539323003
Cr-Commit-Position: refs/heads/master@{#437349}

[modify] https://crrev.com/dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19/net/base/load_flags_list.h
[modify] https://crrev.com/dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19/net/http/http_cache.cc
[modify] https://crrev.com/dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19/net/http/http_cache_transaction.cc
[modify] https://crrev.com/dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19/net/http/http_cache_unittest.cc

Requesting to merge into M56 after the CL has baked.

Your change meets the bar and is auto-approved for M56 (branch: 2924)

This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Your change has been approved for M56. Please ensure to verify the fix and merge ASAP so that we could take it for next Beta Release.

It looks like there might be a perf regression due to this CL so I'm holding off on merging for now.

Just wanted to confirm that
- writing meta-data works as expected on tip-of-tree,
- code caching app-prod.js doesn't.

So there's still a problem on my end that needs fixing.

[Some notes-to-self, as I'll be signing off for holidays later today and need to dump some info so I can pick this up again when I'll be back:]

What I'm observing:
- Per #19 + #25, I can see the code cache for app-prod.js being generated and written. So #13 is no longer an issue.
- When we re-load, ScriptStreamer::startStreaming is called for app-prod.js.
- This accepts and starts streaming. Since streaming prevents the code cache from being read, we won't use the code cache we produced in a previous run.


How I'm interpreting it:
ScriptStreamer::startStreaming is meant to decline streaming if we have a cache hit (since code caching is typically better than streaming, as it avoids compilation entirely). It doesn't do this here, which I think is the problem that byeongha.cho@ has been observing in M54.

When we wrote that logic, the assumption was that a Resource from cache would be loaded "instantaneously", so !resource->isLoaded() would imply that there was no cache hit. This interpretation is apparently wrong; there is no such guarantee.

So the fix would be to rework ScriptStreamer::startStreamingInternal to... do something different. Not sure yet what.

This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Dear vogelheim, it was great analysis!!

I was keep investigating on aspect of streamer problem. 
And I think we can fix it with checking timestamp.
Because timestamp means that it was compiled once before.

If we check timestamp on prepareDataOnMainThread() of ScriptStreamer.cpp, 
we can supress streamer and it takes code cache path.

And in my humble opinion, it doesn't have inconsistency problem.
Because, as I know, timestamp is stored as meta data on cache entry 
and timestamp's lifecycle is same with cached resource ifself.

But I just look at this module from several month ago,
So I want to know how do you think about this solution :)

volgelheim@, I was wrong in our conversation. The metadata *is* available at the time that the response headers are returned to blink.

The perf regression has been addressed in issue 673317. Merging to beta today.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/c2ead440385e2cdea4e03f582704b871876579fa

commit c2ead440385e2cdea4e03f582704b871876579fa
Author: Josh Karlin <jkarlin@chromium.org>
Date: Thu Dec 22 15:41:22 2016

[HttpCacheTransaction] Ignore vary check for WriteMetadata requests

BUG=660264

Review-Url: https://codereview.chromium.org/2539323003
Cr-Commit-Position: refs/heads/master@{#437349}
(cherry picked from commit dddb82a088ea0a9fe1e50e954a3e9dd6cb7f5a19)

Review-Url: https://codereview.chromium.org/2594333003 .
Cr-Commit-Position: refs/branch-heads/2924@{#597}
Cr-Branched-From: 3a87aecc31cd1ffe751dd72c04e5a96a1fc8108a-refs/heads/master@{#433059}

[modify] https://crrev.com/c2ead440385e2cdea4e03f582704b871876579fa/net/base/load_flags_list.h
[modify] https://crrev.com/c2ead440385e2cdea4e03f582704b871876579fa/net/http/http_cache.cc
[modify] https://crrev.com/c2ead440385e2cdea4e03f582704b871876579fa/net/http/http_cache_transaction.cc
[modify] https://crrev.com/c2ead440385e2cdea4e03f582704b871876579fa/net/http/http_cache_unittest.cc

Alright, that part is fixed. Assigning to vogelheim@ for the remaining issues.

[Back from vacation; some more notes:]

Some notes from offline discussion w/ jkarlin, & follow-on to #26 + #30:
- The browser process "always" knows that metadata is available.
- The way the browser + blink processes currently communicate is that first the 'main' cache data is transmitted, and only at the end the metadata is also sent. blink::Resource will receive the metadata in one chunk at the end, and before that point in time has no indication that any metadata will be present.


@byeongha.cho, #29: I think conceptually that's exactly the right thing. It's just that at the point in time when startStreaming happens, we're not guaranteed to even know there's metadata (that is, the timestamp or actual code cache data). So I think in practice we'll have to do a bit more work, and first need to change how/when the browser process transmits the info to the renderer process.