This may be a regression, but I'm not sure. TE, would you mind trying to bisect?

Actually, this seems to *not* happen with 65.0.3325.162.

sdy@ Thanks for the issue.

Tested this issue on Mac OS 10.13.3 on the reported version 67.0.3368.1 and the latest Canary 67.0.3370.0 and Stable 65.0.3325.162 by following the below steps.

1. Launched Chrome and launched Activity monitor.
2. Observed CPU tab of the Chrome browser process on Activity monitor and it shows ~5-8%.
3. Closed the tabs on Chrome and can see the CPU usage ~5%.
4. On quitting Chrome, cannot see Chrome in the Activity Monitor list.
Attached is the screen cast for reference.

This issue is intermittent as sometimes can observe the CPU usage is ~8-11% when the tabs are closed.

Request you to please check and confirm if anything is missed from our end in triaging the issue.

Thanks..

Deleted: 821532.mp4 1.7 MB

	821532.mp4 1.7 MB View Download

In step 3, close all Chrome windows but *don't* quit Chrome. The ~5% idle CPU usage may be another bug, but you should still see a spike when you're moving the mouse.

Hey sdy@: Can you reproduce it with all extensions disabled? I tried to reproduce it on macOS 10.12.6, but I can't repro it. (Please see the attached screencast).

Maybe this issue is a macOS 10.13.x-specific issue?

Deleted: screencast.mov 3.5 MB

	screencast.mov 3.5 MB View Download

> The ~5% idle CPU usage may be another bug ...

fyi: I reported  issue 821940 .

Hmm, interesting. It works for me on 10.13.3 with extensions disabled. See attachment.

Deleted: crbug_821532_demo.mp4 784 KB

	crbug_821532_demo.mp4 784 KB View Download

May be  issue 821940  is the same root cause for this issue?

It's possible? +fsamuel@.

sdy@ Thanks for the update.

Tested this issue on Mac OS 10.13.3 on the latest Canary 67.0.3371.0 and equivalent Dev version.

Able to reproduce the issue on Canary, but the issue is not observed on the equivalent Dev build.
On Canary can observe the CPU usage upto 11% while moving the mouse and no tabs are open. On equivalent Dev version, can see the CPU usage ~0.4%.
Attached are the screen casts for reference.

fsamuel@ As per comment #8, request you to please check if this issue is related to  issue 821940 .

We won't be able to provide bisect as this issue is reproducible only on Canary but not on Dev build, hence removing Needs-Bisect label.
Marking this as Untriaged for further updates from Dev.

Adding ReleaseBlock-Stable as this is a recent regression. Please feel free to remove if it is not applicable.

Thanks..

Deleted: 821532-Canary.mp4 1.5 MB

	821532-Canary.mp4 1.5 MB View Download

Deleted: 821532-M67-Dev.mp4 1.3 MB

	821532-M67-Dev.mp4 1.3 MB View Download

You are probably looking for a change made after 531199 (known good), but no later than 531200 (first known bad).
CHANGELOG URL:
The script might not always return single CL as suspect as some perf builds might get missing due to failure.
  https://chromium.googlesource.com/chromium/src/+log/f6031ae8d9b1bebcc3735c51a7384c94265db2bc..56f31113259c561a93b5b47f5dc9d6575bc6bab6

The bisect seems to point to 56f31113259c561a93b5b47f5dc9d6575bc6bab6. michaelpg@, can you think of a way this change (or something that this change flipped on) would result in mouse activity being tracked in the background?

It doesn't make a lot of sense. If there are no Chrome windows open, the stuff in window_activity_watcher.cc shouldn't be running at all.

If someone can build Chrome on Mac, you could check by adding logging to MaybeLogWindowMetricsUkmEntry(). I don't have the ability to build for Mac though.

michaelpg@: Sorry for the delay. I just re-bisected to your change :/. I did figure out that it only repros if I close the window with cmd+w, *not* if I close it by clicking the window or tab close button with the mouse


What kind of logging would be helpful? I tried some one basic line. If I and then close the window with the mouse, I get this:

    [27800:775:0330/141134.671406:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)
    [27800:775:0330/141138.292111:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)
    [27800:775:0330/141141.169622:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)
    [27800:775:0330/141141.190467:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)

While if I use the keyboard I get this:

    [27964:775:0330/141219.904912:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)
    [27964:775:0330/141220.197200:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)
    [27964:775:0330/141221.961155:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(true)
    [27964:775:0330/141221.978505:ERROR:window_activity_watcher.cc(133)] Hit MaybeLogWindowMetricsUkmEntry(false)

Happy to collect more.

So if you close the only open window, and then move your mouse around, do you see on the order of 4 lines logged? Or on the order of dozens (to account for the CPU usage)?

I'm having trouble seeing how this change could impact CPU usage without the code actually doing anything. Perhaps there's something odd about how BrowserList works on Mac that's causing a bunch of spurious function calls....?

Elly, could you do some preliminary investigation for me, since I don't have a Mac development machine? If you can repro the CPU usage issue, it would be helpful to see if this code is indeed triggering and how often the function runs.

Sure:

I can reproduce this on trunk, as of bc77a6b6 (i.e. this morning). I added some logging to MaybeLogWindowMetricsUkmEntry() and it is *not* repeatedly called, so I don't think that function is at fault.

I'm trying to get a sample of what's going on, but so far without success - Activity Monitor is refusing to sample for some reason.

Two things:

1) This only happens when Chrome is the active app, even if there are no open windows; if Chrome is inactive, I can't repro it, which makes sampling it with Activity Monitor challenging :)

2) I got a sample successfully using sample(1), with the sample starting *only* after closing the last window. Here's an interesting fragment:

    + !                           :       30 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:]  (in AppKit) + 914  [0x7fff288dd5e2]
    + !                           :       | 30 _DPSEventHandledByCarbon  (in AppKit) + 145  [0x7fff2850be39]
    + !                           :       |   30 SendEventToEventTarget  (in HIToolbox) + 39  [0x7fff29e82f21]
    + !                           :       |     29 SendEventToEventTargetInternal(OpaqueEventRef*, OpaqueEventTargetRef*, HandlerCallRec*)  (in HIToolbox) + 374  [0x7fff29e6dc4d]
    + !                           :       |     + 29 DispatchEventToHandlers(EventTargetRec*, OpaqueEventRef*, HandlerCallRec*)  (in HIToolbox) + 2616  [0x7fff29e6ed37]
    + !                           :       |     +   28 ToolboxEventDispatcherHandler(OpaqueEventHandlerCallRef*, OpaqueEventRef*, void*)  (in HIToolbox) + 1822  [0x7fff29ea9b4f]
    + !                           :       |     +   ! 28 FindWindowAndPartFromMouseEvent  (in HIToolbox) + 112  [0x7fff29eab396]
    + !                           :       |     +   !   28 FindWindow  (in HIToolbox) + 38  [0x7fff29eab415]
    + !                           :       |     +   !     28 FindWindowOfClass  (in HIToolbox) + 56  [0x7fff29eab45b]
    + !                           :       |     +   !       23 FindWindowCommon(Point, OpaqueWindowPtr**, short*)  (in HIToolbox) + 46  [0x7fff29eab523]
    + !                           :       |     +   !       : 23 MBarHit  (in HIToolbox) + 44  [0x7fff29eab5a1]
    + !                           :       |     +   !       :   23 _MBarHit(MenuData*, Point, unsigned char, unsigned char*, MenuData**)  (in HIToolbox) + 106  [0x7fff2a005a3b]
    + !                           :       |     +   !       :     23 _HIPresentationInstanceFindAtLocation  (in HIToolbox) + 116  [0x7fff29eab902]
    + !                           :       |     +   !       :       23 MenuBarInstance::ForEachMenuBarDo(void (MenuBarInstance*) block_pointer)  (in HIToolbox) + 47  [0x7fff29e76e63]
    + !                           :       |     +   !       :         23 ___HIPresentationInstanceFindAtLocation_block_invoke  (in HIToolbox) + 50  [0x7fff29eab96d]
    + !                           :       |     +   !       :           23 MenuBarInstance::ContainsPoint(CGPoint, unsigned int*)  (in HIToolbox) + 168  [0x7fff29eaba2a]
    + !                           :       |     +   !       :             23 MenuBarInstance::ForEachWindowDo(unsigned char, bool (OpaqueWindowPtr*, unsigned int) block_pointer)  (in HIToolbox) + 253  [0x7fff29e778e9]
    + !                           :       |     +   !       :               20 invocation function for block in MenuBarInstance::ForEachBoundsDo(bool (CGRect, unsigned int) block_pointer)  (in HIToolbox) + 51  [0x7fff29eaba9c]

There's another interesting thing too:

    +         ! : | 50 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE1_PERFORM_FUNCTION__  (in CoreFoundation) + 41  [0x7fff2abc0ae9]
    +         ! : |   50 __CFMachPortPerform  (in CoreFoundation) + 310  [0x7fff2abc0c36]
    +         ! : |     50 MessageHandler(__CFMachPort*, void*, long, void*)  (in HIToolbox) + 51  [0x7fff29e9f970]
    +         ! : |       24 PullEventsFromWindowServerOnConnection(unsigned int, unsigned char, __CFMachPortBoost*)  (in HIToolbox) + 45  [0x7fff29e9f9cf]
    +         ! : |       + 24 SLEventCreateNextEvent  (in SkyLight) + 44  [0x7fff4d37ce74]
    +         ! : |       +   24 SLSGetNextEventRecordInternal  (in SkyLight) + 81  [0x7fff4d30447d]
    +         ! : |       +     13 CGSSnarfAndDispatchDatagrams  (in SkyLight) + 168  [0x7fff4d27254d]

A more detailed sample via Instruments reveals that:

1) We still receive events when active but with no windows, which makes sense because we need to drive the menu bars still
2) We receive these events even when the mouse is nowhere near the menu bars
3) There are four busy threads:

* The main thread is hitting [NSApplication updateWindows] fairly often, called into via [BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
* The _NSEventThread is hitting the second trace fragment pasted above - it's receiving mach messages and calling into PullEventsFromWindowServerOnConnection()
* A thread is calling into safe_browsing::V4Store::ApplyUpdate(), which might have been some async request completing - unclear
* A thread is doing some "mojo stuff" - I see net::SocketPosix::OnFileCanReadWithoutBlocking() and mojo::edk::ChannelPosix::OnFileCanReadWithoutBlocking() and such

So, I'm not sure there is any particular single cause here, but there are a couple of promising avenues.

Shot in the dark: could this related to the warnings I've been seeing that look like this:

> 2018-04-17 16:28:24.354 Chromium[38015:3717022] *** Owner supplied to -[NSTrackingArea initWithRect:options:owner:userInfo:] referenced a deallocating object. Tracking area behavior is undefined. Break on NSTrackingAreaDeallocatingOwnerError to debug.

? Maybe a tracking area is being leaked.

Thanks, Elly.

It's still weird that this was twice bisected to my change. It should be simple to rule out completely though: would you please verify that the issues still repros when TabActivityWatcher/WindowActivityWatcher are completely disabled?

1. Run Chrome with --force-enable-metrics-reporting --disable-features=TabMetricsLogging
2. Verify the issue still reproduces
3. Confirm the feature is disabled:
   - Open a few tabs and windows and switch between them
   - Visit chrome://ukm and verify that logs are present, but no TabMetrics or WindowMetrics entries

Thanks!

#20: I followed your steps and observed that at (2) the issue still reproduces and at (3) there are no such metrics entries, so we can consider your feature fully ruled out.

I will continue investigating this over the next few days.

M67 Stable promotion is coming soon. Your bug is labelled as Stable ReleaseBlock, pls make sure to land the fix and request a merge into the release branch ASAP. Thank you.

We should address this, but it doesn't need to block stable. Also, the original CL landed in 66.

s/original CL/CL that seems to have triggered this/

*** UI Mass Triage ***

Able to reproduce the issue on Mac with chrome Dev #72.0.3610.2, canary #72.0.3617.0 as per steps mentioned in the comment #0

Kicking this into Available since it's unlikely we will work on this soon.