As in 637640 a trace is requested for analysis.

i will post trace and timeline when it happen for me again but the issue is really mostly noticeable on heavy content websites specially if the site and web sites that uses flash player. you can even notice the slowdown while some heavy page loading  other tabs slow down to crawl like if chrome is running on one process.

An about:net-internals log would also be great (Instructions https://sites.google.com/a/chromium.org/dev/for-testers/providing-network-details).  Don't think this is an issue there, but best to double-check.

On the other bug, I mentioned another regression in PageLoad.PaintTiming.NavigationToFirstContentfulPaint that happened before the big regression.  Breaking up the metric by version, I'm less sure of that now - we released a couple instrumented versions in that period which may have been confusing the numbers I was looking at, and if there is a regression, it would be on the order of 2%, which could well just be noise, or some issue outside of Chrome, so probably not useful to try to divine anything there.

Also, could you please look at CPU usage in task manager, when this next happens to you?  It occurs to me that this may be related to the July 9th perf regression, which looks to be due to something causing the IO thread to become unresponsive (Would most likely be either CPU or disk use on that thread).

Attached both the trace & net-internals dump.

For the trace I could only record about 5s-10s of the page load, anything more was either giving a "Inflated gzip data too long to fit into a string" error or causing the chrome tab to run out of RAM. Hopefully it should still be fine.

Deleted: net-internals-log.json 7.3 MB

net-internals-log.json 7.3 MB View Download

Deleted: trace_Mon_Aug_29_2016_20.27.54.json.gz 7.2 MB

trace_Mon_Aug_29_2016_20.27.54.json.gz 7.2 MB Download

Oh, and as for the CPU usage, it jumps from around 1-2% usage > 12-15%.

Which tab was slow? Wowhead?

Yup.

eae@ can you look at this really long layout task?

Seems to be a a bunch of FontProxy.. is something thrashing?

On the network side of things, early in the log, the uMatrix extension is slowing requests down by 100-200 milliseconds, and uBlock origin is slowing them down by 200 to 500 milliseconds.  Later in the log, the extensions seem more reasonable, though still have a fairly significant impact.

The network stack seems kinda hosed to me - We see a huge number of requests at 3 seconds in, but some of them we don't service until 80 seconds in to the log, because there are so many requests in front of them (There are 1,500 network requests in that log, all made at nearly the same time!)

Could you disable those two extensions and collect another network log?

Attached new log with all extensions disabled. (Didn't notice that you only said to disable only uBlock/uMatrix)

This seems to have resolved the speed issue, going from 1m30s > 6s page load, even after turning everything back on. Will have to wait a few hours for the slowdown to appear again to see if it was due to uBlock/uMatrix.

Deleted: net-internals-log (1).json 9.0 MB

net-internals-log (1).json 9.0 MB View Download

[+rdsmith]  Thanks for that log!  Fine that you disabled all extensions.  It looks to me like 3 things are happening:

1)  Those extensions are very slow.
2)  Those extensions are making the disk cache slow (All responses are served out of the cache in both logs, but the cache is much faster in the second log).  It may be that the Chrome extension code is using significant CPU time on the IO thread, blocking the cache.  Or the extensions could be doing a lot of disk I/O.
3)  The ResourceScheduler slows requests entering the network stack.  This combines with issues 1 and  2  to make things really, really slow.

Of those issues, we're working on 3).  I'm wondering if there was some recent regression causing 1) and/or 2).

dtapuska:  I'm tentatively removing the Blink labels - I'm thinking this issue lies solely on the IO thread.  Feel free to add them back if you think it's appropriate.

mmenke@ It does appear the IO thread is slow as that would explain the really long layout times because it looks like they are doing blocking IPC.

Yea, you're right.  The IO thread is very busy, though the main renderer thread looks similarly busy.  I'm hoping this is a duplicate of issue 627999 (Sorry, access restricted) - a perf regression on July 9th in which a busy IO thread has been implicated.  We haven't made much progress on it, as of yet.  I'll keep the bugs separate, for now, just in case.

It looks like the IOThread is busy with basically three types of tasks:  Calls to ScheduledResourceRequest::Start, calls to ResourceLoader::StartRequest(), calls to ExtensionHostMsg_RequestForIOThread.

The ScheduledResourceRequest::Start and ResourceLoader::StartRequest calls are probably basically doing the same thing, just for requests that are delayed and those that aren't.  I'm not sure about the extension events, but they could very well be doing the same thing.

The renderer is mostly doing layout, and sending sync IPCs - so the renderer being busy is probably mostly a product of the IO thread being busy.  I think those sync IPCs are just tracing information, so not a concern in production code, and this can be treated as solely an IOThread issue.

I'm going to try to reproduce tomorrow, installing a bunch of extensions.

ok weird disabling adguard seems fixed the slowdowns so i can conform its Extensions related , btw i noticed 2 days ago that eagleget downloader Extensions causing some slow downs so i delete it and it go better but slow downs kept happening until i disabled Adguard i used it for like 4 hours without any weird slowdowns or lags. i might try to install back eagleget and see if its just adblockers related  ( cause it happened for me on Ublock origin too) .

+redevlin FYI for potential extension code hammering the IO thread.

Assuming this is the regression I've been looking into, the range is most likely 54.0.2791 to 54.0.2792.0 (https://chromium.googlesource.com/chromium/src/+log/54.0.2791.0..54.0.2792.0?pretty=fuller&n=10000).  None of the extensions changes in that range really stick out at me.

Just a quick update:  I think I've been able to replicate this on Canary.  At least the same test URL (http://www.wowhead.com/guides/legion/artifact-weapons, which uses an absurd number of resources) takes ~5 seconds after fresh relaunch, loading mostly from cache, just before the relaunch, it was taking ~30 seconds, also loading mostly from cache.  IOThread looked to be busy with a similar set of events as in the provided trace, though none of them seemed to be taking quite so insanely log.  I'm using uMatrix and uBlock origin extensions, with uMatrix set to allow scripts and XHRs, in addition to the default stuff.

Haven't had a chance to dig deeper, and haven't yet reproed in a debug build.

i did more testing yesterday by installing back eagleget Extensions again and ublock origin and lag and slowdowns came back so i removed ublock origin and kept eagleget and there were no noticeable lag and slow downs as when there was ublock. so it could be just related to Ad blockers ? 

I assume it's related to extensions that use the WebRequest API (Which ad blockers do - no idea if eagleget does).

I'm less convinced that I've managed to reproduce this than I was before.

dakutree, yahyoh1991:  Do you guys have HDDs or SSDs?

HDD...and i dont think its related much to HDD , because i kept monitoring what's happening with the CPU and HDD  when the slowdowns happens no excessive high disk access or high cpu spikes.

I'm on an SSD.

There's no rush on this, but if one (Or both) of you wouldn't mind, could you enable whatever extensions are causing the problems for you, and once the issue has appeared about, open up "about:profiler" click save, and then load a couple more pages that experience the issue (Don't need to keep about:profiler open), open up "about:profiler" again, and save it again, then upload both?

In my local repro attempts, I'm seeing a lot of time spent in URLRequest::ChromeNetworkDelegate::OnBeforeURLRequest 3, which points at one specific part of the extensions code.  Want to see if things look similar for you guys as well.

[+robwu]:  This regression is starting to look like it may have been caused by your CL:  https://codereview.chromium.org/2121873002, though I'm not at all confident of that.  We saw a regression the day you landed that CL, and assuming that the issue reported here is the same regression (It may not be), this repro also looks extension-related, and my attempts to repro this (Which may or may not have been successful - not sure), point to ChromeExtensionsNetworkDelegateImpl::OnBeforeURLRequest, which you CL affected.

So there's a certainly lot of uncertainty there.  Can your CL be easily reverted?  May be simplest to revert it for a couple revisions, and see if things record and the reporters can still repro the issue.  If the issue isn't fixed, can just reland it.

The patch fixes a rare CHECK crash on Windows. You can safely revert it for
a few releases.

Thanks!  I've CQed the revert.  I'll keep an eye on our metrics, and dakutree and yahyoh1991 can weigh in on whether it fixed the issue they're running into as well, once it land.

See also  issue 643025 

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

commit e579d519620e6583ddc304f22c4c3c71dabbbe20
Author: mmenke <mmenke@chromium.org>
Date: Thu Sep 01 22:41:14 2016

Revert of Fix WebRequest's EventListener::operator< (patchset #3 id:40001 of https://codereview.chromium.org/2121873002/ )

Reason for revert:
This may have caused a perf regression.  Reverting to verify.  If it did not, I'll reland next week.

BUG= 641958 , 643025 

Original issue's description:
> Fix WebRequest's EventListener::operator<
>
> std::set's count() method is expected to return 0 or 1. But due
> to the fact that EventListener::operator< conditionally ignored
> |embedder_process_id|, the count method could return more than 1
> (e.g. 2) in release builds on Windows (VC++), and fail an assertion.
>
> This assertion failure shows that the assumption about the uniqueness
> of EventListeners (while ignoring the |embedder_process_id| value) does
> not hold, i.e. there may be more than one non-webview EventListeners
> with the same |extension_id| and |sub_event_name|, but different
> |embedder_process_id|.
>
> To fix this, this patch removes the conditional exclusion of
> |embedder_process_id| from operator< and looks up |embedder_process_id|
> before searching through the set.
>
> BUG=589735
> TEST=./unit_tests --gtest_filter=ExtensionWebRequestTest.AddAndRemoveListeners
>
> Committed: https://crrev.com/c89943b168ef2ccc51f3ec0720e552f36ec31351
> Cr-Commit-Position: refs/heads/master@{#404456}

TBR=rockot@chromium.org,rob@robwu.nl
# Not skipping CQ checks because original CL landed more than 1 days ago.
BUG=589735

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

[modify] https://crrev.com/e579d519620e6583ddc304f22c4c3c71dabbbe20/chrome/browser/extensions/api/web_request/web_request_api_unittest.cc
[modify] https://crrev.com/e579d519620e6583ddc304f22c4c3c71dabbbe20/extensions/browser/api/web_request/web_request_api.cc
[modify] https://crrev.com/e579d519620e6583ddc304f22c4c3c71dabbbe20/extensions/browser/api/web_request/web_request_api.h

the fix should be in today canary ?

Yea, it should (hopefully) be fixed in 55.0.2847.0, which went out earlier today.

its seems fixed, all fast without any slowdowns after +4 hours of heavy use 

The patch should eventually be restored. I don't have time to work on this in the next few weeks, but if it's still open I'll look into the root cause (see also  bug 643025 ).

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

commit a67f30a6b303582d930417197f4a351901c6898a
Author: Erik Chen <erikchen@chromium.org>
Date: Tue Sep 06 23:56:27 2016

[Merge to 2840] Revert of Fix WebRequest's EventListener::operator< (patchset #3 id:40001 of https://codereview.chromium.org/2121873002/ )

> Reason for revert:
> This may have caused a perf regression.  Reverting to verify.  If it did not, I'll reland next week.
>
> BUG= 641958 , 643025 
>
> Original issue's description:
> > Fix WebRequest's EventListener::operator<
> >
> > std::set's count() method is expected to return 0 or 1. But due
> > to the fact that EventListener::operator< conditionally ignored
> > |embedder_process_id|, the count method could return more than 1
> > (e.g. 2) in release builds on Windows (VC++), and fail an assertion.
> >
> > This assertion failure shows that the assumption about the uniqueness
> > of EventListeners (while ignoring the |embedder_process_id| value) does
> > not hold, i.e. there may be more than one non-webview EventListeners
> > with the same |extension_id| and |sub_event_name|, but different
> > |embedder_process_id|.
> >
> > To fix this, this patch removes the conditional exclusion of
> > |embedder_process_id| from operator< and looks up |embedder_process_id|
> > before searching through the set.
> >
> > BUG=589735
> > TEST=./unit_tests --gtest_filter=ExtensionWebRequestTest.AddAndRemoveListeners
> >
> > Committed: https://crrev.com/c89943b168ef2ccc51f3ec0720e552f36ec31351
> > Cr-Commit-Position: refs/heads/master@{#404456}
>
> TBR=rockot@chromium.org,rob@robwu.nl
> # Not skipping CQ checks because original CL landed more than 1 days ago.
> BUG=589735
>
> Review-Url: https://codereview.chromium.org/2299373002
> Cr-Commit-Position: refs/heads/master@{#416094}
> (cherry picked from commit e579d519620e6583ddc304f22c4c3c71dabbbe20)

Review URL: https://codereview.chromium.org/2317923002 .

Cr-Commit-Position: refs/branch-heads/2840@{#192}
Cr-Branched-From: 1ae106dbab4bddd85132d5b75c670794311f4c57-refs/heads/master@{#414607}

[modify] https://crrev.com/a67f30a6b303582d930417197f4a351901c6898a/chrome/browser/extensions/api/web_request/web_request_api_unittest.cc
[modify] https://crrev.com/a67f30a6b303582d930417197f4a351901c6898a/extensions/browser/api/web_request/web_request_api.cc
[modify] https://crrev.com/a67f30a6b303582d930417197f4a351901c6898a/extensions/browser/api/web_request/web_request_api.h

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

commit 7cdfec136b896222345c88f56e89a2d40d53e49c
Author: erikchen <erikchen@chromium.org>
Date: Thu Sep 08 21:14:46 2016

Fix semantics of ExtensionWebRequestEventRouter::EventListeners.

There are two types of EventListeners: those with web_view_instance_id and those
without. EventListeners with a web_view_instance_id need to always consider
embedder_process_id for equality comparisons. EventListeners without a
web_view_instance_id should sometimes ignore embedder_process_id (when being
removed) for equality comparisons.

The previous code had two major issues:
  1) EventListeners were stored in a std::set. std:set requires a stable sort
  operator. There is no way to create a stable sort operator that sometimes
  ignores embedder_process_id.

  Aside: std::set is almost never the right container to use from a performance
  perspective. In this case, the code frequently needs to iterate through the
  entire container away, so I've changed the container to be a std::vector (we
  expect the total number of elements to be small). If we find performance
  issues, we should switch to std::unordered_set.

  2) EventListeners need to be messaged asynchronously, but it's possible that
  the EventListener is no longer registered by the time the callback comes
  around. The previous code would make a copy of the EventListener, and then try
  to "find" the original copy in the callback. Once again, this requires clear
  semantics for equality.

The new code makes several changes:
  1) Create the class EventListener::ID. As its name implies, this uniquely
  identifies an EventListener.

  2) Disallow copy and assignment of EventListeners. The only use case is async
  identity checking, which should use EventListener::ID instead.

  3) This cleanup means EventListener::blocked_requests no longer has to be
  mutable. (A clear sign that something was wrong with the previous scheme).

The most important result is that it is no longer possible to have identity
confusion between EventListeners, as all comparisons use EventListener::ID. This
was the root cause of the leak from  Issue 643025 .

BUG= 643025 ,  641958 

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

[modify] https://crrev.com/7cdfec136b896222345c88f56e89a2d40d53e49c/chrome/browser/extensions/api/web_request/web_request_api_unittest.cc
[modify] https://crrev.com/7cdfec136b896222345c88f56e89a2d40d53e49c/extensions/browser/api/web_request/web_request_api.cc
[modify] https://crrev.com/7cdfec136b896222345c88f56e89a2d40d53e49c/extensions/browser/api/web_request/web_request_api.h

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

commit f5f0196947ef79ab06a121329945ed3141c9b095
Author: erikchen <erikchen@chromium.org>
Date: Thu Sep 15 18:27:36 2016

[Merge to 2840] Fix semantics of ExtensionWebRequestEventRouter::EventListeners.

> There are two types of EventListeners: those with web_view_instance_id and those
> without. EventListeners with a web_view_instance_id need to always consider
> embedder_process_id for equality comparisons. EventListeners without a
> web_view_instance_id should sometimes ignore embedder_process_id (when being
> removed) for equality comparisons.
>
> The previous code had two major issues:
>   1) EventListeners were stored in a std::set. std:set requires a stable sort
>   operator. There is no way to create a stable sort operator that sometimes
>   ignores embedder_process_id.
>
>   Aside: std::set is almost never the right container to use from a performance
>   perspective. In this case, the code frequently needs to iterate through the
>   entire container away, so I've changed the container to be a std::vector (we
>   expect the total number of elements to be small). If we find performance
>   issues, we should switch to std::unordered_set.
>
>   2) EventListeners need to be messaged asynchronously, but it's possible that
>   the EventListener is no longer registered by the time the callback comes
>   around. The previous code would make a copy of the EventListener, and then try
>   to "find" the original copy in the callback. Once again, this requires clear
>   semantics for equality.
>
> The new code makes several changes:
>   1) Create the class EventListener::ID. As its name implies, this uniquely
>   identifies an EventListener.
>
>   2) Disallow copy and assignment of EventListeners. The only use case is async
>   identity checking, which should use EventListener::ID instead.
>
>   3) This cleanup means EventListener::blocked_requests no longer has to be
>   mutable. (A clear sign that something was wrong with the previous scheme).
>
> The most important result is that it is no longer possible to have identity
> confusion between EventListeners, as all comparisons use EventListener::ID. This
> was the root cause of the leak from  Issue 643025 .
>
> BUG= 643025 ,  641958 
>
> Review-Url: https://codereview.chromium.org/2303113002
> Cr-Commit-Position: refs/heads/master@{#417398}
> (cherry picked from commit 7cdfec136b896222345c88f56e89a2d40d53e49c)

Review URL: https://codereview.chromium.org/2344993002 .

Cr-Commit-Position: refs/branch-heads/2840@{#379}
Cr-Branched-From: 1ae106dbab4bddd85132d5b75c670794311f4c57-refs/heads/master@{#414607}

[modify] https://crrev.com/f5f0196947ef79ab06a121329945ed3141c9b095/chrome/browser/extensions/api/web_request/web_request_api_unittest.cc
[modify] https://crrev.com/f5f0196947ef79ab06a121329945ed3141c9b095/extensions/browser/api/web_request/web_request_api.cc
[modify] https://crrev.com/f5f0196947ef79ab06a121329945ed3141c9b095/extensions/browser/api/web_request/web_request_api.h

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

commit a67f30a6b303582d930417197f4a351901c6898a
Author: Erik Chen <erikchen@chromium.org>
Date: Tue Sep 06 23:56:27 2016

[Merge to 2840] Revert of Fix WebRequest's EventListener::operator< (patchset #3 id:40001 of https://codereview.chromium.org/2121873002/ )

> Reason for revert:
> This may have caused a perf regression.  Reverting to verify.  If it did not, I'll reland next week.
>
> BUG= 641958 , 643025 
>
> Original issue's description:
> > Fix WebRequest's EventListener::operator<
> >
> > std::set's count() method is expected to return 0 or 1. But due
> > to the fact that EventListener::operator< conditionally ignored
> > |embedder_process_id|, the count method could return more than 1
> > (e.g. 2) in release builds on Windows (VC++), and fail an assertion.
> >
> > This assertion failure shows that the assumption about the uniqueness
> > of EventListeners (while ignoring the |embedder_process_id| value) does
> > not hold, i.e. there may be more than one non-webview EventListeners
> > with the same |extension_id| and |sub_event_name|, but different
> > |embedder_process_id|.
> >
> > To fix this, this patch removes the conditional exclusion of
> > |embedder_process_id| from operator< and looks up |embedder_process_id|
> > before searching through the set.
> >
> > BUG=589735
> > TEST=./unit_tests --gtest_filter=ExtensionWebRequestTest.AddAndRemoveListeners
> >
> > Committed: https://crrev.com/c89943b168ef2ccc51f3ec0720e552f36ec31351
> > Cr-Commit-Position: refs/heads/master@{#404456}
>
> TBR=rockot@chromium.org,rob@robwu.nl
> # Not skipping CQ checks because original CL landed more than 1 days ago.
> BUG=589735
>
> Review-Url: https://codereview.chromium.org/2299373002
> Cr-Commit-Position: refs/heads/master@{#416094}
> (cherry picked from commit e579d519620e6583ddc304f22c4c3c71dabbbe20)

Review URL: https://codereview.chromium.org/2317923002 .

Cr-Commit-Position: refs/branch-heads/2840@{#192}
Cr-Branched-From: 1ae106dbab4bddd85132d5b75c670794311f4c57-refs/heads/master@{#414607}

[modify] https://crrev.com/a67f30a6b303582d930417197f4a351901c6898a/chrome/browser/extensions/api/web_request/web_request_api_unittest.cc
[modify] https://crrev.com/a67f30a6b303582d930417197f4a351901c6898a/extensions/browser/api/web_request/web_request_api.cc
[modify] https://crrev.com/a67f30a6b303582d930417197f4a351901c6898a/extensions/browser/api/web_request/web_request_api.h

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

commit f5f0196947ef79ab06a121329945ed3141c9b095
Author: erikchen <erikchen@chromium.org>
Date: Thu Sep 15 18:27:36 2016

[Merge to 2840] Fix semantics of ExtensionWebRequestEventRouter::EventListeners.

> There are two types of EventListeners: those with web_view_instance_id and those
> without. EventListeners with a web_view_instance_id need to always consider
> embedder_process_id for equality comparisons. EventListeners without a
> web_view_instance_id should sometimes ignore embedder_process_id (when being
> removed) for equality comparisons.
>
> The previous code had two major issues:
>   1) EventListeners were stored in a std::set. std:set requires a stable sort
>   operator. There is no way to create a stable sort operator that sometimes
>   ignores embedder_process_id.
>
>   Aside: std::set is almost never the right container to use from a performance
>   perspective. In this case, the code frequently needs to iterate through the
>   entire container away, so I've changed the container to be a std::vector (we
>   expect the total number of elements to be small). If we find performance
>   issues, we should switch to std::unordered_set.
>
>   2) EventListeners need to be messaged asynchronously, but it's possible that
>   the EventListener is no longer registered by the time the callback comes
>   around. The previous code would make a copy of the EventListener, and then try
>   to "find" the original copy in the callback. Once again, this requires clear
>   semantics for equality.
>
> The new code makes several changes:
>   1) Create the class EventListener::ID. As its name implies, this uniquely
>   identifies an EventListener.
>
>   2) Disallow copy and assignment of EventListeners. The only use case is async
>   identity checking, which should use EventListener::ID instead.
>
>   3) This cleanup means EventListener::blocked_requests no longer has to be
>   mutable. (A clear sign that something was wrong with the previous scheme).
>
> The most important result is that it is no longer possible to have identity
> confusion between EventListeners, as all comparisons use EventListener::ID. This
> was the root cause of the leak from  Issue 643025 .
>
> BUG= 643025 ,  641958 
>
> Review-Url: https://codereview.chromium.org/2303113002
> Cr-Commit-Position: refs/heads/master@{#417398}
> (cherry picked from commit 7cdfec136b896222345c88f56e89a2d40d53e49c)

Review URL: https://codereview.chromium.org/2344993002 .

Cr-Commit-Position: refs/branch-heads/2840@{#379}
Cr-Branched-From: 1ae106dbab4bddd85132d5b75c670794311f4c57-refs/heads/master@{#414607}

[modify] https://crrev.com/f5f0196947ef79ab06a121329945ed3141c9b095/chrome/browser/extensions/api/web_request/web_request_api_unittest.cc
[modify] https://crrev.com/f5f0196947ef79ab06a121329945ed3141c9b095/extensions/browser/api/web_request/web_request_api.cc
[modify] https://crrev.com/f5f0196947ef79ab06a121329945ed3141c9b095/extensions/browser/api/web_request/web_request_api.h