New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 714382 link

Starred by 2 users

Issue metadata

Status: WontFix
Owner: ----
Closed: Apr 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 2
Type: Bug



Sign in to add a comment

Linked pages open slowly unless in incognito

Reported by clinton....@gmail.com, Apr 22 2017

Issue description

UserAgent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36

Example URL:
Any linked article from cbc.ca/news

Steps to reproduce the problem:
1. Go to www.cbc.ca/news
2. Click one of the article links
3. Wait...

What is the expected behavior?
The linked page should open quickly.  It does open quickly (normally) if I use incognito mode.

What went wrong?
The page takes too long to open

Did this work before? N/A 

Chrome version: 57.0.2987.133  Channel: n/a
OS Version: 10.0
Flash Version: I've set "Block sites from running Flash"

The articles on that site also give me this problem: https://bugs.chromium.org/p/chromium/issues/detail?id=704410
 
Labels: Needs-Milestone

Comment 2 by eroman@chromium.org, Apr 25 2017

Labels: Needs-Feedback
If it is loading quickly in Incognito mode but slowly in your regular profile, then it points to some configuration unique to that profile.

This is a non-exhaustive list, but some things to try turning off one at a time in your profile until you find what was causing the slow-down:

 * Disable chrome extensions (chrome://extensions) - my prime suspect would be an extension causing the slow-down.
 * Clear your cache (menu -> more tools -> clear browsing data)
 * Clear your cookies

What do you see while it is loading? (what does the load status at bottom of screen show).
Hi, thanks,

I have no extensions.

I just tried clearing the cache (for the last week - is that enough?), then the cookies.  Neither made any improvement unfortunately.

It says "Waiting for www.cbc.ca..." during most of the wait.  There are some other messages before that but they go by too quickly to read.
Project Member

Comment 4 by sheriffbot@chromium.org, Apr 25 2017

Cc: eroman@chromium.org
Labels: -Needs-Feedback
Thank you for providing more feedback. Adding requester "eroman@chromium.org" to the cc list and removing "Needs-Feedback" label.

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

Comment 5 by eroman@chromium.org, Apr 25 2017

Can you follow the instructions here:
  https://dev.chromium.org/for-testers/providing-network-details

And attach 2 separate logs to this bug:

  (1) A log captured while loading the site in an incognito window (it loads quickly)

  (2) A log captured while loading the site in non-incognito (it loads slowly).

Cheers.

Comment 6 by eroman@chromium.org, Apr 25 2017

Labels: Needs-Feedback
Hi, I'm attaching the logs.  I used chrome://net-export instead because that's what the net-internals page said to do.  Thanks.
chrome-net-export-log-incognito.json
6.9 MB View Download
chrome-net-export-log-normal.json
4.5 MB View Download
Project Member

Comment 8 by sheriffbot@chromium.org, Apr 25 2017

Labels: -Needs-Feedback
Thank you for providing more feedback. Adding requester "eroman@chromium.org" to the cc list and removing "Needs-Feedback" label.

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

Comment 9 by eroman@chromium.org, Apr 25 2017

Cc: rdsmith@chromium.org mmenke@chromium.org
Thanks for the logs!

In comparing those logs, an interesting difference is looking at the load for:
   http://www.cbc.ca/i/news/v10/css/storypage-print.css

Loading a CSS subresource would block the page from completing its load.
 * In the incognito version it loads in 1 second
 * In the non-incognito mode it still hasn't loaded after 32 seconds

It blocks for 12 seconds on the ResourceScheduler, and then stalls waiting to read the headers (but never gets them).

The main differences I see between those two requests is:
 * The incognito one opened a new socket, whereas the failed version re-used a socket
 * The incognito version has a smaller cookie payload (1K vs more than 3K)
 * The non-incognito version adds an If-Modified-Since to load from cache.

There are other requests to that site which do re-use sockets (and succeed), so I am not convinced that is the root problem.

@clinton: While in regular mode (not incognito) an you try deleting all your cookies for that page? (click on the 'i' in the left of the URL box, then click cookies, then Ctrl-a to select all, then remove) and see if the article loads differently afterwards.

Summoning @mmenke and @rdsmith for other ideas.
Curiously, a small number of requests to http://www.cbc.ca/ in that log took almost exactly 12 seconds between sending the request and getting headers back from the server.  Only a number of events from other requests occur during one of those.  It looks like nothing happened from about t=53095 to t=61908, but some of the 12-second stalls are from t=63615 to t=75762, and there are a bunch of events between those, so not at all clear if there's a stall.

Otherwise, nothing too interesting, though the socket we never receive a response on got the previous response only a couple milliseconds before we reused it for another request, so it is presumably alive.  Capturing was stopped 20 seconds after the request started, so it was not in the middle of another 12-second stall.
So the ResourceScheduler block is blocking (in both traces) on the completion of all render blocking requests initiated before the <body> tag is parsed--the difference is just whether there are any outstanding requests at the point where we hit the <body> tag.  So what that means is that the storypage-print.css event is blocking on main frame parsing, which is probably blocked on some other resource load.  

I went looking for what that load might be in the slow case, and the only one I could come up with was event 63795 (http://www.cbc.ca/cmlink/7.3959) which completes at t=61901, where the RS unblocks the story page load @ t=61906.  

63795 is taking all its time between HTTP_STREAM_PARSER_READ_HEADERS and HTTP_TRANSACTION_READ_RESPONSE_HEADERS, which I believe means that it's blocked on a network read.  In other words, it seems to be blocked because of a slow server.  That fits with the rest of the storypage.css load, as well as fitting with what you get if you compare the timeline views--to my inexperienced eye, there are *many* fewer bytes being received per second in the non-incognito mode than in the incognito mode.

One question is that I don't believe any extension interference would show up in this way--I think that that would show up in DELEGATE_INFO delegate_blocked_by line, like the ResourceScheduler.  But I'd value one of you checking that belief.

So the question becomes what could the difference between these two cases be that results in the server behaving so differently?  

I'd endorse Eric's "delete all cookies for the page" experiment.  I'm also interested if we have some mechanism (command line flag?  Subtle use of authentication?) to disable socket re-use; I could easily imagine code paths on the server being very different for initial and re-used sockets.

Per my earlier comment, there are a bunch of slow requests - 63795, 63850, 64317, and 64228 all hang for 12 seconds, waiting for headers from the network (In addition to the request that never completes).  The first two hang at around the same time, and then the second two hang around the same time (And both start just a bit before the first two complete).
Do you agree with my basic conclusion that those stalls sorta have to be server driven, or do you see a way that something on the client side might be (proximate) cause?
The other possibility is that there's an IO thread hang - very few network events happen during the first stall, which could fit that hypothesis.  It looks like more things happen during the second stall, though.

So I think that the possibilities are the IO thread is hung, or the server is being slow in responding to these requests, for some unknown reason.
Hello everyone thanks for helping me out.
@eroman I deleted all the cookies for the page as you requested, and it seems to be working normally now.  (I couldn't get the "select all" to work though - is there a trick to it?)
The problem is solved for me, for now.  Thanks!
Status: WontFix (was: Unconfirmed)
> Hello everyone thanks for helping me out.
> @eroman I deleted all the cookies for the page as you requested, and it seems > to be working normally now.

Great!

I should have had you save the cookies first, since now we can't figure out what exactly about your cookie jar was breaking things...

I am guessing some value in your cookies was tickling a server-side bug.

> (I couldn't get the "select all" to work though - is there a trick to it?)

Ah, so apparently select-all doesn't work on Windows Chrome :(
On Mac Chrome you can select them all with command-A.

> The problem is solved for me, for now.  Thanks!

Cool, will close this bug then.

Sign in to add a comment