Same issue for us on https://www.wizbii.com/ Everything was working well on Chrome 66 and our site is at 100% CPU on Chrome 67

Able to reproduce issue on Mac with latest Chrome Stable i.e., 67.0.3396.62 only on Mac. Windows and Linux are working fine.

Working on bisect but so far can't find a bad build.


Note : The same works fine on M68 and M69.

Adding horo@ and ricea@ who have touched sync XHR more recently than I have.

I can reproduce this on Chrome 67.0.3396.62 on macOS but not on Windows.

My test site is: https://reillyeon.github.io/scraps/sync-xhr.html

 Issue 848181  has been merged into this issue.

Thank you reillyg@.

horo@ and ricea@, This is blocking M67 stable further roll out. Pls take a look ASAP. Thank you.

Hey all, we're starting to see some reports of this across consumer channels as well.

Community thread:
- https://productforums.google.com/forum/#!topic/chrome/qmxGjxqo0OA

Reddit thread:
- https://www.reddit.com/r/chrome/comments/8njj4d/huge_cpu_usage_in_chrome_67/

Listnr reports:
- https://listnr.corp.google.com/report/85475670187
- https://listnr.corp.google.com/report/85475673684
- https://listnr.corp.google.com/report/85475657838
- https://listnr.corp.google.com/report/85475654075
- https://listnr.corp.google.com/report/85475636345

Thanks!

Based on Manual Bisect I see that this issue is regressed between Chrome version 67.0.3396.56 and 67.0.3396.62. 

Change Log : https://chromium.googlesource.com/chromium/src/+log/67.0.3396.56..67.0.3396.62?pretty=fuller&n=10000


Suspecting CL : https://chromium.googlesource.com/chromium/src/+/e11497bc51059c4c1b2ebf0cd4537ef8e1d20972

Thank you  pbommana@

horo@/ricea@, The suspected CL merge was for - https://bugs.chromium.org/p/chromium/issues/detail?id=844268#c16.

Issue 848257 has been merged into this issue.

Making this the active bug since issue 848257 is restricted but nothing about this issue itself is confidential.

Useful debug info from issue 848257:

A sample shows that a thread is in a tight loop around this:

    2031 Thread_371557: TaskSchedulerServiceThread
    + 2031 thread_start  (in libsystem_pthread.dylib) + 13  [0x7fff76af2bf9]
    +   2031 _pthread_start  (in libsystem_pthread.dylib) + 377  [0x7fff76af350d]
    +     2031 _pthread_body  (in libsystem_pthread.dylib) + 340  [0x7fff76af3661]
    +       2031 base::(anonymous namespace)::ThreadFunc(void*)  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x20ffae7  []
    +         2031 base::Thread::ThreadMain()  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x2101bbb  [lock.h:26]
    +           2031 <name omitted>  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x20d0105  [run_loop.cc:136]
    +             1187 base::MessagePumpLibevent::Run(base::MessagePump::Delegate*)  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x20ab952  [message_pump_libevent.cc:248]
    +             ! 1149 event_base_loop  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x213667d  [event.c:514]
    +             ! : 878 kq_dispatch  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x2138c88  [kqueue.c:217]
    +             ! : | 864 event_warn  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x21372a6  [log.c:0]
    +             ! : | + 534 <name omitted>  (in Google Chrome Framework)  load address 0x10ba9a000 + 0x21371d5  [log.c:0]
    +             ! : | + ! 526 fprintf  (in libsystem_c.dylib) + 176  [0x7fff768673c9]
    +             ! : | + ! : 465 vfprintf_l  (in libsystem_c.dylib) + 54  [0x7fff7686e742]
    +             ! : | + ! : | 361 __xvprintf  (in libsystem_c.dylib) + 330  [0x7fff768972fd]
    +             ! : | + ! : | + 350 __sflush  (in libsystem_c.dylib) + 87  [0x7fff768663bd]
    +             ! : | + ! : | + ! 329 _swrite  (in libsystem_c.dylib) + 87  [0x7fff7686d796]
    +             ! : | + ! : | + ! : 325 __write_nocancel  (in libsystem_kernel.dylib) + 10,20,...  [0x7fff7692c2c2,0x7fff7692c2cc,...]

And a dtrace log shows that kevent is returning EINVAL, forcing this tight loop in libevent:

write_nocancel(0x2, "[warn] kevent: Invalid argument\n\0", 0x20)		 = 32 0
kevent(0xD, 0x7FB98C800600, 0x0)		 = 0 0
kevent(0xD, 0x7FB98C800600, 0x0)		 = -1 Err#22
write_nocancel(0x2, "[warn] kevent: Invalid argument\n\0", 0x20)		 = 32 0
kevent(0xD, 0x7FB98C800600, 0x0)		 = 0 0
kevent(0xD, 0x7FB98C800600, 0x0)		 = -1 Err#22
write_nocancel(0x2, "[warn] kevent: Invalid argument\n\0", 0x20)		 = 32 0
kevent(0xD, 0x7FB98C800600, 0x0)		 = 0 0
kevent(0xD, 0x7FB98C800600, 0x0)		 = -1 Err#22


==========

I took the testcase from the OP (thanks, btw!) and keyed it off a button click, to make it easier to work in the debugger (test case attached).

Before clicking the button to initiate the sync XHR, the thread always has a null delayed_work_time_ in the MessagePumpLibevent and takes this path: https://cs.chromium.org/chromium/src/base/message_loop/message_pump_libevent.cc?l=237&rcl=c65dbe40c4b7f9387d8b8634c53b7f366a49ccde

After clicking the button, we start computing a delayed work time of what looks pretty close to infinity:

frame #3: 0x000000011782a142 Google Chrome Framework`base::MessagePumpLibevent::Run(this=0x00007fb0f5203930, delegate=0x00007fb0f2d34910) at message_pump_libevent.cc:247 [opt]
   244 	        event_set(timer_event.get(), -1, 0, timer_callback, event_base_);
   245 	        event_base_set(event_base_, timer_event.get());
   246 	        event_add(timer_event.get(), &poll_tv);
-> 247 	        event_base_loop(event_base_, EVLOOP_ONCE);
   248 	        event_del(timer_event.get());
   249 	      } else {
   250 	        // It looks like delayed_work_time_ indicates a time in the past, so we
(lldb) p delay
(base::TimeDelta) $21 = (delta_ = 2147483625953241)

... which then gets translated into this timespec passed to kevent:

frame #1: 0x00000001178b7379 Google Chrome Framework`kq_dispatch(base=<unavailable>, arg=0x00007fb0f5203d00, tv=<unavailable>) at kqueue.c:212 [opt]
   209 			ts_p = &ts;
   210 		}
   211 	
-> 212 		res = kevent(kqop->kq, changes, kqop->nchanges,
   213 		    events, kqop->nevents, ts_p);
   214 		kqop->nchanges = 0;
   215 		if (res == -1) {
(lldb) p ts
(timespec) $20 = (tv_sec = 2147483625, tv_nsec = 953240000)

And that is indeed causing kevent to return EINVAL due to an invalid timeout. We probably need to handle an infinite timeout with a special case. As far as I can tell based on blame (https://chromium.googlesource.com/chromium/src/+blame/c65dbe40c4b7f9387d8b8634c53b7f366a49ccde/base/message_loop/message_pump_libevent.cc), this bug has always existed. We perhaps were just not encountering it before.

Deleted: bug-848210.html 363 bytes

bug-848210.html 363 bytes View Download

Fixing this in the MessagePump seems highly risky. The delayed work time is coming from here:

  * frame #0: 0x0000000111b17f7e Google Chrome Framework`base::internal::DelayedTaskManager::AddDelayedTask(base::internal::Task, base::OnceCallback<void (base::internal::Task)>) [inlined] base::internal::DelayedTaskManager::AddDelayedTaskNow(this=0x00007fa364c15948, task=Task @ 0x0000700017f76390, delay=(delta_ = 2147483647000000), post_task_now_callback=PostTaskNowCallback @ 0x0000700017f76550)>) at delayed_task_manager.cc:89 [opt]
    frame #1: 0x0000000111b17f7e Google Chrome Framework`base::internal::DelayedTaskManager::AddDelayedTask(this=0x00007fa364c15948, task=<unavailable>, post_task_now_callback=PostTaskNowCallback @ 0x0000700017f76758)>) at delayed_task_manager.cc:67 [opt]
    frame #2: 0x0000000111b1a41e Google Chrome Framework`base::internal::SchedulerSingleThreadTaskRunnerManager::SchedulerSingleThreadTaskRunner::PostDelayedTask(this=<unavailable>, from_here=<unavailable>, closure=<unavailable>, delay=<unavailable>)>, base::TimeDelta) at scheduler_single_thread_task_runner_manager.cc:301 [opt]
    frame #3: 0x0000000111b3211f Google Chrome Framework`base::Timer::PostNewScheduledTask(this=0x00007fa362e19a70, delay=(delta_ = 2147483647000000)) at timer.cc:203 [opt]
    frame #4: 0x0000000115a4ae34 Google Chrome Framework`content::SyncLoadContext::SyncLoadContext(network::ResourceRequest*, std::__1::unique_ptr<network::SharedURLLoaderFactoryInfo, std::__1::default_delete<network::SharedURLLoaderFactoryInfo> >, content::SyncLoadResponse*, base::WaitableEvent*, base::WaitableEvent*, double, mojo::InterfacePtrInfo<blink::mojom::BlobRegistry>, scoped_refptr<base::SingleThreadTaskRunner>) [inlined] void base::Timer::Start<content::SyncLoadContext>(this=0x00007fa362e19a70, posted_from=0x0000000116241167, delay=(delta_ = 2147483647000000), receiver=<unavailable>, method=<unavailable>)()) at timer.h:135 [opt]

Specifically, a base::OneShotTimer (which internally creates a delayed task) is constructed from the SyncLoadContext here: https://chromium.googlesource.com/chromium/src/+/67.0.3396.69/content/renderer/loader/sync_load_context.cc#68.

It doesn't really make sense to start a timeout timer for something that has effectively no timeout. Because we use INT_MAX (https://chromium.googlesource.com/chromium/src/+/67.0.3396.69/third_party/blink/renderer/platform/loader/fetch/resource_request.cc#39) for the default/infinite timeout, we hit this issue.

SyncLoadContext expects "no timeout" to be signaled with 0 while ResourceRequest uses INT_MAX.

It was https://chromium-review.googlesource.com/c/chromium/src/+/974989 which added the concept of timeouts to synchronous loads.

Was the bug in MessagePump already fixed on Canary?
I can reproduce this bug on Stable, but I can't reproduce on Canary.

We merged e11497bc51059c4c1b2ebf0cd4537ef8e1d20972 to Stable to fix the  bug 844268 .
The  bug 844268  is "Timeout reduced to 10-14 sec for xmlhttprequests".
But after this CL, OneShotTimer with INT_MAX timeout is used for the no-timeout case.

I created a CL http://crrev.com/c/1081768 which uses base::TimeDelta::Max() for the default timeout, and check it not to create OneShotTimer.
I think this can fix this 100% CPU usage bug.
But this CL is a bit complicated to merge to Stable.
SyncLoadContext::SignalHelper class was introduced in M68.

I think it is OK to revert e11497bc51059c4c1b2ebf0cd4537ef8e1d20972 on Stable.
But if possible we should use larger timeout value such as 1 day.
http://crrev.com/c/1081777

yhirano@
WDYT?

> govind@
Is it OK to land http://crrev.com/c/1081777 to branch-heads/3396?

M67 is already in stable, so which one of following is the safest option?

* Reverting e11497bc51059c4c1b2ebf0cd4537ef8e1d20972 from M67. If we do revert this change, are we ok to leave with  issue 844268  in M67?
* Merging http://crrev.com/c/1081777 to M67. If we decide to merge this change, is it possible to land it on trunk and test in canary or we will need to directly merge to M67? 

http://crrev.com/c/1081777 is almost same as reverting e11497bc51059c4c1b2ebf0cd4537ef8e1d20972.
I just changed the default timeout value from 10 sec to 1 day to mitigate the  issue 844268 .

The sync XHR related code has been largely changed from M67. So landing http://crrev.com/c/1081777 on trunk is almost meaningless.
I manually tested http://crrev.com/c/1081777 on branch-heads/3396 (M67) and verified that this bug was fixed.
So I want to directly merge to M67.

Thank you horo@.

Will it be fully safe to merge http://crrev.com/c/1081777 directly to M67 stable?

Yes.

Approving merge for http://crrev.com/c/1081777  to M67 branch 3396 based on comment #24 and per offline chat with horo@. Pls merge. Thank you.

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

commit 843d26289dfee145b3d16c059de4c2494bbb1ac1
Author: Tsuyoshi Horo <horo@chromium.org>
Date: Fri Jun 01 05:11:14 2018

Revert "[Merging to M67] Stop resetting 10 sec timeout in FetchParameters::MakeSynchronous()"

This reverts commit e11497bc51059c4c1b2ebf0cd4537ef8e1d20972.

The original CL was intended to fix the 10 second default timeout issue ( crbug.com/844268 ).
But this CL introduced 100% CPU usage issue by using OneShotTimer with INT_MAX ( crbug.com/848210 ).

So this CL reverts e11497bc51059c4c1b2ebf0cd4537ef8e1d20972, using a large timeout (1 day) to mitigate the timeout issue ( crbug.com/844268 ).

Bug:  848210 ,  844268 
Change-Id: Iccd4a7a9b416e11aca354c658d2e6c9bfc530db4
Reviewed-on: https://chromium-review.googlesource.com/1081777
Reviewed-by: Yutaka Hirano <yhirano@chromium.org>
Reviewed-by: Adam Rice <ricea@chromium.org>
Cr-Commit-Position: refs/branch-heads/3396@{#727}
Cr-Branched-From: 9ef2aa869bc7bc0c089e255d698cca6e47d6b038-refs/heads/master@{#550428}
[modify] https://crrev.com/843d26289dfee145b3d16c059de4c2494bbb1ac1/third_party/blink/renderer/platform/loader/fetch/fetch_parameters.cc

Issue 848276 has been merged into this issue.

Is there a plan to merge to http://crrev.com/c/1081777 to M68 as well? 

I don't think we need to merge to M68.

I can't reproduce the CPU 100% usage issue in M68.
I think the bug in MessagePump was fixed in M68.
I'm still bisecting to know what CL fixed the bug in MessagePump.

 Issue 848630  has been merged into this issue.

> govind@
I verified that the issue was fixed in 67.0.3396.71.

I still not full understand, but crrev.com/c/1059459 (r560052) which landed in 68.0.3435.0 has fixed the bug in MessagePump.

Before r560052, I can see the 100% CPU usage issue when I use OneShotTimer with INT_MAX in SyncLoadContext by applying crrev.com/c/1068893.
But after r560052, I can't see the 100% CPU usage issue.

crrev.com/c/1068893 (r561374) landed in 68.0.3439.0.
So we couldn't see this bug in M68.

But the CL (crrev.com/c/1068893) was merged to M67 (e11497bc51059c4c1b2ebf0cd4537ef8e1d20972).
So this bug was introduced only in M67.

Tested this issue on Mac 10.13.3 using chrome #67.0.3396.71  as per the steps mentioned in C#0.

Observed more than 95.5 CPU usage on reported version-67.0.3396.62 for the example.org tab in task manager after placing the content in devtools->Console.

Observed 0.1 cpu usage on chrome-67.0.3396.71 for the example.org tab in task manager after placing the content in devtools->Console.Seems issues got fixed as per C#30.Hence adding TE Verified labels after fix revert.

Please find the attached screencast of reported version & fixed version for reference.

Thanks..!

Deleted: 848210-Mac-Reported.mp4 2.8 MB

	848210-Mac-Reported.mp4 2.8 MB View Download

Deleted: 848210-Fixed version.mp4 1.9 MB

	848210-Fixed version.mp4 1.9 MB View Download

Fixed It:

HiddenChrome: Secret Settings & Tools (chrome://flags/)
https://chrome.google.com/webstore/detail/hiddenchrome-secret-setti/jhcdplpmjpchlfjfihdpimbakifjnnda?hl=en&

Maybe this might help: url: (chrome://flags/)

Simple Cache for HTTP (Enabled)
Throttle Expensive (Background Timers Enabled)
No-State Prefetch (Enabled No-State Prefetch)

Just a thought!

For those who end up here and think that they don't send any synchronous XHRs: Check your "beforeunload" handlers. Many tracking/external libraries trigger a synchronous XHR onbeforeunload to ensure it reaches the server before the window is closed.

I suspect https://chromium-review.googlesource.com/c/chromium/src/+/1059459 "fixes" the issue because of the repeating heartbeat_latency_timer_ in the ServiceThread. That timer will cause the MessagePump's delayed work time to always be less than the infinity timer created by the sync XHR. Without that change, if no other delayed work is queued, then the sync XHR's delayed work time is the only one used to calculate the pump's next delayed work time.

 Issue 848703  has been merged into this issue.

Note: affects extension pages (including background pages!) as well

https://github.com/Tampermonkey/tampermonkey/issues/552
https://chrome.google.com/webstore/detail/tampermonkey/dhdgffkkebhmkfjojejmpbldmpobfkfo

Thanks

Re: rsesek@ (comment 40)
Ah, that's sounds reasonable.
Then, we don't need to merge the CL to M68.

I'm still working on a proper fix: http://crrev.com/c/1081768

Just to make sure, nothing is pending for M67, correct?

Yes.
Nothing for M67 and M68,

I will http://crrev.com/c/1081768 for TOT(M69).

It's an extension. I've disabled all my extension, and the CPU usage went down. As soon as I re-enabled the cookie manager the CPU usage of Google Chrome Helper was again at 100%. So maybe there are also other extensions which cause this trouble since the latest Chrome update.

I had at least two extensions (VisualPing and Ghostery) that were causing 100% CPU. Disabling them "fixed" it.

In my OSX Chrome, the 100% CPU was caused by 
"User Agent Switcher, URL sniffer 0.9.3.9" extension. Disabling that myself for now.

Fixed by 843d26289dfee145b3d16c059de4c2494bbb1ac1 which landed in 67.0.3396.71.
https://chromium.googlesource.com/chromium/src/+log/67.0.3396.71

What's the timeframe before 67.0.3396.71 gets released into stable channel? So we can update our installs.

Had to switch back to firefox due to this issue on Macbook pro retina TB core I7 under Macos 10.13.5

 Issue 849275  has been merged into this issue.

When will this fix version gets released? my Macbook pro's fans sound really terrible.

Do we have a timeline for when 67.0.3396.71+ will be pushed out to the public? It's been several days since the bug was reported as patched on 67.0.3396.71, this bug's status is now set to "fixed", and yet Chrome's self-updater still does not have a new version available (I'm on 67.0.3396.62)? I even tried freshly re-downloading Chrome from https://www.google.com/chrome/, but it's still giving me 67.0.3396.62...

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

commit ea7d04675fd27256726991d4471c07b9ec8c1914
Author: Tsuyoshi Horo <horo@chromium.org>
Date: Tue Jun 05 10:26:16 2018

Use base::TimeDelta::Max() for the default value of ResourceRequest.TimeoutInterval() for no timeout

Bug:  848210 
Change-Id: I32a9207c0c5016f8d662fc5c0a5e7de1ef2c8d91
Reviewed-on: https://chromium-review.googlesource.com/1081768
Reviewed-by: Yutaka Hirano <yhirano@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Reviewed-by: Adam Rice <ricea@chromium.org>
Commit-Queue: Tsuyoshi Horo <horo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#564434}
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/content/renderer/loader/resource_dispatcher.cc
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/content/renderer/loader/resource_dispatcher.h
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/content/renderer/loader/sync_load_context.cc
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/content/renderer/loader/sync_load_context.h
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/content/renderer/loader/web_url_loader_impl_unittest.cc
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/third_party/blink/public/platform/web_url_request.h
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/third_party/blink/renderer/core/loader/document_threadable_loader.cc
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/third_party/blink/renderer/platform/exported/web_url_request.cc
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/third_party/blink/renderer/platform/loader/fetch/resource_request.cc
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/third_party/blink/renderer/platform/loader/fetch/resource_request.h
[modify] https://crrev.com/ea7d04675fd27256726991d4471c07b9ec8c1914/third_party/blink/renderer/platform/loader/fetch/resource_request_test.cc

 Issue 849623  has been merged into this issue.

We're planning on releasing an M67 update with the fix later this week.

 Issue 849818  has been merged into this issue.

Tested this issue on Mac 10.13.4 using chrome #67.0.3396.79  as per the steps mentioned in C#0.

Observed 0.1 cpu usage on chrome-67.0.3396.79 for the example.org tab in task manager after placing the content in devtools->Console.Please confirm on the fix as per C#56.

Please find the attached screencast for reference.

Thanks..!

> jmukthavaram@
Sorry, I don't understand well.
Are you saying that 0.1 cpu usage is a problem?
Didn't you see the 0.1 cpu usage before executing the code?

The 0.1% cpu usage is an expected behavior.

I verified that the bug (100% CPU usage) was fixed using Chrome 67.0.3396.79 Mac.

67.0.3396.79 is now available: https://chromereleases.googleblog.com/2018/06/stable-channel-update-for-desktop.html

Issue 850208 has been merged into this issue.

Requesting postmortem for this bug. Please see go/chrome-postmortems for the process to follow.

Filed an  issue 850450  for the MessagePump bug.

 Issue 849120  has been merged into this issue.

 Issue 880499  has been merged into this issue.