Oh, and, for what it's worth, this has been happening for roughly a month.

If I understand how to read Sample files, the long pole is "5829 -[NSConcreteHashTable rehashAround:] " which is happening when as a result of CreateClassifiedAttributedString. This makes me suspect either omnibox ui generally or a Mac ui framework problem. 

One way to read it is that hashProbe is taking a long time. Another is some code higher up the chain has begun making a lot more calls (in a loop, say) such that whenever Instruments samples the stack looks like we're stuck waiting for hashProbe to finish.

sdy@, did you also upgrade to 10.13 about a month ago?

shrike@ (re. #3): I'm pretty sure that I've been running High Sierra for longer, but I'm not sure if this started with a macOS update or with a Chrome update, so I'm suspecting Chrome.

I agree that it's also possible/likely that it's being called repeatedly. Is there any debugging information I could collect from the omnibox world?

> Is there any debugging information I could collect from the omnibox world?
After a startup on which you witness the hang, go to about:histograms and paste all the Omnibox ones here.  That might tell if it's an omnibox logic issue, a UI paint issue, or something else.  thanks!

Here are *all* of them.

Deleted: histograms.txt 794 KB

histograms.txt 794 KB View Download

The longest entry in those histograms is Omnibox.CharTypedToRepaintLatency, which a longest latency of 150ms.  That histogram captures a lot of the core omnibox logic (description below).  If you're seeing a long lag than that, it's not likely any part of the omnibox system.

Omnibox.CharTypedToRepaintLatency description:
    Records the time taken between a keystroke being typed in the omnibox and
    the text being painted. If there are multiple keystrokes before a paint,
    logs the time since the earliest one.

    This duration is composed of three parts:

    a) the time spent processing the initial input event

    b) the time spent for the repaint task to be scheduled on the message loop

    c) the time spent painting the Omnibox

    d) (on views platforms) the time until the pixels are actually composited

    There's a number of breakdown metrics to help diagnose a regression. First,
    Omnibox.CharTypedToRepaintLatency.ToPaint measures the combined time of (a)
    and (b). Omnibox.QueryTime2 is a good proxy for just (a). And there's also
    Omnibox.PaintTime that corresponds to (c). We don't have a direct metric for
    (d), but if neither Omnibox.CharTypedToRepaintLatency.ToPaint nor
    Omnibox.PaintTime regressed, then the regression must be in (d).

    It's also possible to get insight into (b) via the UMA Task Profiler
    dashboard by looking at "average queue time" of the task
    DisplayScheduler::ScheduleBeginFrameDeadline.

    Note: The semantics of this metric on views platforms changed in M62, as
    previously time (d) was not included in the metric.

This looks really concerning. Unfortunately, there's insufficient information to figure out exactly what's going on. sdy, can you try to launch Chrome w/ instruments [sampling tool, high precision], and try to repro? Alternatively, launch Chrome w/ tracing enabled? See https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/recording-tracing-runs and "--trace-startup".

My first instinct is that this is a Omnibox Cocoa bug [which no one owns]...but looking more closely at the sample, this seems like it could also be a bug in sync. I'm really curious to know how often "OmniboxPopupModel::OnResultChanged" is called.

re:
> I'm really curious to know how often "OmniboxPopupModel::OnResultChanged" is called.
You might be interested in bug 712268.

OK, done. Both attached. I don't see OnResultChanged, but I do see AutocompleteController::UpdateResult called 488 times in the trace, which each call taking ~10ms. Thoughts?

erikchen@: The Instruments trace looked basically like the sample output in the original report to me, am I looking at it right?

Deleted: startup_hang.json 13.0 MB

startup_hang.json 13.0 MB View Download

Deleted: startup_hang.trace.zip 9.6 MB

startup_hang.trace.zip 9.6 MB Download

Deleted: Screen Shot 2017-10-18 at 10.50.54 AM.png 121 KB

	Screen Shot 2017-10-18 at 10.50.54 AM.png 121 KB View Download

Deleted: Screen Shot 2017-10-18 at 10.51.08 AM.png 46.0 KB

	Screen Shot 2017-10-18 at 10.51.08 AM.png 46.0 KB View Download

Weeeird. Okay. If anyone wants to follow along, grab the symbols for 64.0.3242.0, Instruments Beta 9.1, and load the trace in c#12. 

Observation 1: sdy@ is running OOP HP. I bet if you turn it off [#memlog in about:flags], this will improve to an extent. Can you try that and report back on results? [OOP HP mostly exacerbates existing problems]. 

Observation 2: There are *a lot* of OnePassword errors in the console. Try turning that off and see if it helps? There are 9k error messages over a span of 2 seconds [~1 error message every 100us], that look like:
"""
2017-10-18 10:47:02.717584-0400 OnePasswordNativeMessageHost[15641:196830] 683005 [EXT_NMH:(Secondary Thread 0x60400007fc40):<OnePasswordNativeMessageHost: 0x60c00001f490>] E terminate: | Terminating
2017-10-18 10:47:02.717690-0400 OnePasswordNativeMessageHost[15641:196830] 683005 [EXT_NMH:(Secondary Thread 0x60400007fc40):<OPNMMessage: 0x600000205b40>] E initWithMessage:length: | failed, reported length: 0
2017-10-18 10:47:02.717877-0400 OnePasswordNativeMessageHost[15641:196830] 683005 [EXT_NMH:(Secondary Thread 0x60400007fc40):<OPNMHostAppDelegate: 0x60000003f120>] E applicationDidFinishLaunching: | Failed to construct message for received data of size: 0
"""

Observation 3: There appear to be something horribly wrong with the autocomplete cells. My guess is that for some reason, there are a lot of classifications in https://cs.chromium.org/chromium/src/chrome/browser/ui/cocoa/omnibox/omnibox_popup_cell.mm?type=cs&l=321, resulting in a horrifying number of attributes added to the string.
 
Observation 4: 488 times is too many for AutocompleteController::UpdateResult. paging mpearson@.

Note that of the ~18s of sampled time in the Chrome process, 10s involves a stack that has "autocomplete" in it. That's pretty amazing.

> Observation 4: 488 times is too many for AutocompleteController::UpdateResult.
> paging mpearson@.
CC jdonnelly.  Luckily I'm not on omnibox bug triage this week. :-)

*super* interesting. Fresh runs attached with the HP and 1Password extension turned off, the delay feels pretty similar, unfortunately.

Deleted: chrome_startup_hang_run_2.json.zip 2.9 MB

chrome_startup_hang_run_2.json.zip 2.9 MB Download

Deleted: chrome_startup_hang_run_2.trace.zip 7.4 MB

chrome_startup_hang_run_2.trace.zip 7.4 MB Download

Hm. In the new trace, the main thread still has hundreds of back-to-back invocations of AutocompleteController::UpdateResult, each of which takes 25ms. 

This seems like a fairly serious, deterministically reproducible issue [on at least one machine]. Assigning to jdonnelly, and making it a RB-S.

There are also a ton of appearances of OnTemplateURLServiceChanged in the json version of the trace. The autocomplete SearchProvider listens for this event and can call UpdateResult in response (as in the stack trace in sdy's original report).

erikchen: can you confirm whether many or most of the stacks in the trace include OnTemplateURLServiceChanged and syncer::SharedChangeProcessor::StartAssociation like the one in the original report? Or point me at some instructions for loading the trace? (I've never used Instruments (this is part of XCode?) and I don't know how to get the build symbols.)

Yes, everything starts with syncer::SharedChangeProcessor::StartAssociation.

Deleted: Screen Shot 2017-10-19 at 10.02.12 AM.png 183 KB

	Screen Shot 2017-10-19 at 10.02.12 AM.png 183 KB View Download

Thanks. Does anyone know someone from the Sync team we can loop in, then?

vasilii: as OWNER of components/search_engines, do you have any insight into why we might see a large number of repeated invocations of TemplateURLService::MergeDataAndStartSyncing on Mac?

TemplateURLService::MergeDataAndStartSyncing is called by the Sync code and should happen only one per profile. Are you sure it's happening?

Adding zea@ from the Sync team.

I agree with vasilii, TemplateURLService::MergeDataAndStartSyncing should only ever called once per startup (unless you sign out and sign back in) - per profile. If MergeDataAndStartSyncing is getting invoked multiple times for the same profile, something would be seriously wrong.

How many template URLs do you have? chrome://sync-internals should have the information, it calls them "Search Engines". MergeDataAndStartSyncing is going to loop through all of your "sync" template urls and all of your "local" template urls, and compare those two sets, and try to make them the same. They should typically be near identical (except for on first time syncing, which isn't your case).

It doesn't seem like MergeDataAndStartSyncing should need to trigger these observation methods, it shouldn't really be changing anything. But at the same time, these observation methods shouldn't be so expensive.

From the trace, we see that non-stop, back-to-back invocations of AutocompleteController::UpdateResult [each lasting ~15.8ms] for ~6 seconds. From the instrumentations run [which samples every 100us, over several seconds], we see that every invocation of AutocompleteController::UpdateResult has the exact same stack trace. This leaves two possibilities:

1) TemplateURLService::MergeDataAndStartSyncing is being called once per invocation of AutocompleteController::UpdateResult.
2) There is a tight loop somewhere between TemplateURLService::MergeDataAndStartSyncing and AutocompleteController::UpdateResult that causes the latter to be called hundreds of times in a row.

I do not know enough about the code paths to know if (1) or (2) is the root cause. Given that this repros on Canary for sdy over more than 1 version, it should be easy to add some temporary logging that will answer this question.

MergeDataAndStartSyncing will loop over every single template URL you have. 6/.0158=378. My guess is (2), and they have ~400 template URLs.

Looking at the stack in comment #18, we're calling TemplateURLService::Update() from MergeDataAndStartSyncing which only happens when the synced template URL's last modified time is bigger than the local's [1]. Could it be that we're storing these two times with slightly different precision?

[1] https://cs.chromium.org/chromium/src/components/search_engines/template_url_service.cc?l=1031

Alternatively, if your local template URL storage (where that is, I don't actually know) is failing to persist changes to disk, but your sync storage is still working, that could explain this as well.

Throwing some logging before the if clause I linked to to print out the times, everything matches on my Linux machine, and does not enter the "if" or the "else if". Everything no-ops.

As an aside, given that TemplateURLService::MergeDataAndStartSyncing runs a tight loop, can we queue up a call to TemplateURLService::NotifyObservers that we invoke once, after the sync is finished, rather than calling O(N) times?

Seems pretty reasonable to me, looks like XxxNoNotify() methods already exist to facilitate that. Make sure you get the Remove/Add calls inside of MergeInSyncTemplateURL as well.

> Seems pretty reasonable to me, looks like XxxNoNotify() methods already exist to facilitate that. Make sure you get the Remove/Add calls inside of MergeInSyncTemplateURL as well.

Please clarify. Who is going to make this change? 

There are other questions here too; for example, SearchProvider only does anything in response to template URL service changes if there's an incomplete query.  What is the incomplete query here?

Oh, I didn't have anyone in particular in mind! Seems simple enough, I don't mind doing it. But we also need to get to the bottom of the timestamp issue.

Peter, I think the user has a habit of typing into the omnibox as the first thing they do, right as sync's ~9 second delayed initialization triggers. From the initial report:

> About ~30% of the time I launch Chrome on my personal profile at home, Chrome hangs for around seven seconds as I'm tying in the omnibox. I'm not sure if it's the typing that triggers the hang, or if the hang just happens a second or two into launch.

Correct, the browser only hangs if I start typing in the omnibox immediately.

sdy, can you add a log statement right before the "if" check I linked to? Something like:

LOG(ERROR) << "sync last mod " << sync_turl->last_modified().ToInternalValue() << " local last mod " << local_turl->last_modified().ToInternalValue();

Would also be good to get the sizes of local_data_map and sync_data_map.

We may want to consider modifying SearchProvider so it doesn't update matches if nothing has really changed.  This might require more granular TemplateURLService notifications (which is something we've wanted off and on anyway).

That said, if MergeDataAndStartSyncing is firing repeated notifications instead of one batch one, that's clearly wrong and will be the big win here, so I'm all for fixing that.

Sky, is there any progress on this bug?

https://chromium-review.googlesource.com/c/chromium/src/+/745521 has been posted, waiting for a review.

It'd be nice if we could figure out why the timestamps were not matching for sdy@, but the more I think about it, the more I suspect there's just some problem writing to disk that's not really a logical problem in Chrome.

sdy@ - it'd be convenient if you could check to see if you synced your personal account on another device, does this problem repro? If it doesn't, it lends credence to simply a persistence issue. If it does actually repro, then there's another problem we need to investigate.

Sure. I just made a fresh profile on another device, signed in, and waited for it to sync. There *is* a startup hang, but it's somewhat shorter (~3 seconds) than at home. If it'd be helpful to grab a particular kind of trace, let me know.

(P.S. erikchen@: I pinged 1Password about the extension spam :). It looks like it also slows down shutdown significantly.)

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

commit ab7ec09197e84de11f893d4f0f4e94322ac35ede
Author: Sky Malice <skym@chromium.org>
Date: Thu Nov 16 19:24:57 2017

Batch notify calls from TemplateURLService during sync operations.

Expanded the existing model of calling NoNotify methods, and changed
some sync only methods to return a bool representing whether a change
was made to the local data or not. RemoveNoNotify does not currently
expose if a change was actually made, so we assume that one was, fixing
this was out of scope. This allowed the sync methods (apply and merge)
to track if any changes were made, and invoke a single NotifyObservers
after all local changes had been applied.

As made evident by the unit tests, there's some complexity around
changing the default search engine that may still result in more than
one notification call.

Bug:  775049 
Change-Id: Ie0b3080a60852f6cc09704feb4de8f850386353b
Reviewed-on: https://chromium-review.googlesource.com/745521
Reviewed-by: Vasilii Sukhanov <vasilii@chromium.org>
Commit-Queue: Sky Malice <skym@chromium.org>
Cr-Commit-Position: refs/heads/master@{#517148}
[modify] https://crrev.com/ab7ec09197e84de11f893d4f0f4e94322ac35ede/chrome/browser/search_engines/template_url_service_sync_unittest.cc
[modify] https://crrev.com/ab7ec09197e84de11f893d4f0f4e94322ac35ede/components/search_engines/template_url_service.cc
[modify] https://crrev.com/ab7ec09197e84de11f893d4f0f4e94322ac35ede/components/search_engines/template_url_service.h

It's concerning that this somewhat repros on other devices, confusing that the delay is smaller, maybe because of the machine's strength? Is it okay if I look at your server side template urls data to try to repro this myself? This makes me think that my write off of your problems being file system related may be incorrect. Also, what platform was your home device, Mac or something else?

Your symptoms should be fixed by the CL I just landed, lowering priority and removing RBS.

> It's concerning that this somewhat repros on other devices, confusing that the delay is smaller, maybe because of the machine's strength?

Unfortunately the machines have the same specs :).

Is it okay if I look at your server side template urls data to try to repro this myself?

Yes, go ahead!

> This makes me think that my write off of your problems being file system related may be incorrect. Also, what platform was your home device, Mac or something else?

Yep — Mac, running 10.13.1.

> Your symptoms should be fixed by the CL I just landed, lowering priority and removing RBS.

Sweet. I'll let you know if I see the symptoms again.

I went to investigate this today, and realized, I never asked which account you were having this problem with. Was it your @chromium.org or a different one?

Oh, somehow I assumed I leaked it in one of the things I uploaded :). Sent it to you by email.

I seem to be able to repro locally, it seems sync's copy has more significant digits.

sync: 13152922509182432 local: 13152922509000000

Looking at server side data for syd@'s account, I see lots of template urls that have many significant digits of timestamp.

It would seem that during merge, the sync data looks marginally newer (bigger time value) than the local data. This triggers an update, which modifies the in memory version to be the same now, but then we save we call Time::ToTimeT() which seems to truncate.

Clearly we should not be calling update here, and we need to stop that somehow. It seems like the sync copies should use the same precision as the local copies do, but achieving this seems tricky. Should the local copies actively lower precision upon local change? That would keep the sync copy in sync, but would also be a violation of abstraction, our storage mechanism is leaking. Self healing during merge seems awkward. It may be more simple to just lower precision on all sides before comparing last_modified (or any timestamp that's being serialized with ToTimeT).

Changing the format we save the local data in seems too tricky, since everyone already has lots of data saved that we must be backwards compatible with.

Looks like there are three timestamp fields inside TemplateURLData, 
* date_created
* last_modified
* last_visited

They're set to ~now in four places
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_data.cc?rcl=f9c5b01ec56d4ce4ab794bc0e505b8f0d7e6556e&l=17
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_data.cc?rcl=f9c5b01ec56d4ce4ab794bc0e505b8f0d7e6556e&l=18
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_service.cc?rcl=fb178abd808e39b65a0d86c2b999546b16d9c556&l=2008
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_service.cc?rcl=fb178abd808e39b65a0d86c2b999546b16d9c556&l=1679

We could wrap these four places with a time_t round trip, though it would feel bad. The latter could could have this encapsulated inside the service's |clock_|, but requiring a Clock to be passed into TemplateURLData() seems a bit onerous.

I'm worried that the RemoveAutoGeneratedX() methods are going to be subtly missing values if you used a template url's creation time to create the time ranges, though I don't think that's going to cause problems for the current single caller. last_visited seems to be completely unused, as far as I can tell. The only actual problems are coming from:
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_service.cc?rcl=10de2b1dfda392d47caa4778fdb2df1640a34479&l=1042
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_service.cc?rcl=10de2b1dfda392d47caa4778fdb2df1640a34479&l=1051
* https://cs.chromium.org/chromium/src/components/search_engines/template_url_service.cc?rcl=10de2b1dfda392d47caa4778fdb2df1640a34479&l=2117

I'm tempted to just lower the precision of these comparisons and leave things messy, since I don't see a great way to make things better.

We had the same bug for the password manager. We solved it by migrating the database and storing ToInternalValue().

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

commit 9243479dad5a742a40d46439ee5c2f4a799e581b
Author: Sky Malice <skym@chromium.org>
Date: Wed Dec 06 02:37:51 2017

Increase precision on keywords db timestamps.

On disk timestamps were using second resolution, while in memory and
sync representations were using microsecond. This meant that by round
tripping data to disk, the actual values would chance slightly. There
were several places that compared timestamps, and these difference did
no fix themselves, but rather resulted in repeated churn. The database
columns were already 64 bit integers, so this change doesn't even
modify the schema, just changes the format of data stored.

Bug:  775049 
Change-Id: I03886d249c4b9195f20b897d309da6063db4bf6f
Reviewed-on: https://chromium-review.googlesource.com/806646
Commit-Queue: Sky Malice <skym@chromium.org>
Reviewed-by: Peter Kasting <pkasting@chromium.org>
Cr-Commit-Position: refs/heads/master@{#521965}
[modify] https://crrev.com/9243479dad5a742a40d46439ee5c2f4a799e581b/components/search_engines/keyword_table.cc
[modify] https://crrev.com/9243479dad5a742a40d46439ee5c2f4a799e581b/components/search_engines/keyword_table.h
[add] https://crrev.com/9243479dad5a742a40d46439ee5c2f4a799e581b/components/test/data/web_database/version_76.sql
[modify] https://crrev.com/9243479dad5a742a40d46439ee5c2f4a799e581b/components/webdata/common/BUILD.gn
[modify] https://crrev.com/9243479dad5a742a40d46439ee5c2f4a799e581b/components/webdata/common/web_database.cc
[modify] https://crrev.com/9243479dad5a742a40d46439ee5c2f4a799e581b/components/webdata/common/web_database_migration_unittest.cc

skym, thank you for following up! This seems like a big win. :)

+1, thank you! The actual cause is weirdly satisfying.