Potential jank detected on Omnibox (char to repaint) |
|||||||||||||||||||||
Issue descriptionSlow-reports is shipped back to our server with a chrome trace when some jank is detected on the chrome main thread. We instrumented the metric 'Omnibox.CharTypedToRepaintLatency.ToPaint' to collect a slow-reports traces when the char to repaint is above the threshold 50 ms. Examples: 01ea2b2c223b21ea b1844230e4cc4514 301cf5d53d61b54e 25b2292938ce3dad 584b064941dc7409 7f7db42fb1e588e3
,
Jul 27
Looking to the code void AutocompleteController::Start https://cs.chromium.org/chromium/src/components/omnibox/browser/autocomplete_controller.cc?l=286 There is a loop over autocomplete providers, which also provide us UMA metrics for their execution time. Followed by a call to UpdateResult(false, true); Assuming the graph from #c2, we can estimate that Providers time is proportional to UpdateResults. The current slow-reports trigger is about 50 ms. Omnibox.QueryTime2.1 25% users have > 20 ms Omnibox.QueryTime2.2 7% users have > 20 ms Omnibox.QueryTime2.3 4% users have > 20 ms Omnibox.QueryTime2.4 2% users have > 20 ms Omnibox.QueryTime2.5 1% users have > 20 ms There will be at least 1% users with jank for every characters typed.
,
Jul 27
The provider "Omnibox.ProviderTime2.HistoryQuick" tell us that 1% of the user will get results above 20 ms. This metric don't tell us how many of these queries are the first character. I expect that percentage to be higher on first character based on "Omnibox.QueryTime2.1".
,
Jul 27
,
Jul 27
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/32d2c24ca385879d751364aeebcdffde65a4ea2d commit 32d2c24ca385879d751364aeebcdffde65a4ea2d Author: Etienne Bergeron <etienneb@chromium.org> Date: Fri Jul 27 21:17:29 2018 Add a navigation category to slow-reports Adding the navigation category to get better trace for omnibox debugging. R=oysteine@chromium.org Bug: 868419 Change-Id: I08842d4f8de7845f63a8add5ef2f10ab460b1ce5 Reviewed-on: https://chromium-review.googlesource.com/1153457 Reviewed-by: oysteine <oysteine@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#578799} [modify] https://crrev.com/32d2c24ca385879d751364aeebcdffde65a4ea2d/content/browser/tracing/background_tracing_config_impl.cc [modify] https://crrev.com/32d2c24ca385879d751364aeebcdffde65a4ea2d/content/browser/tracing/background_tracing_config_impl.h [modify] https://crrev.com/32d2c24ca385879d751364aeebcdffde65a4ea2d/content/browser/tracing/background_tracing_config_unittest.cc [modify] https://crrev.com/32d2c24ca385879d751364aeebcdffde65a4ea2d/content/browser/tracing/background_tracing_manager_impl.cc
,
Jul 28
For the record, we carefully control the amount of memory HistoryQuick provider uses, trying to limit its size without impacting quality. I don't think it can be further shrunk without harm. So, yes, almost everyone with a large history will experience jank on their first keystroke in the omnibox. :-( This is partially because the first keystroke matches so many URLs from history and partially because the later keystrokes, in addition to searching fewer items, can use the cached results from earlier keystrokes. The first keystroke has no cached results to leverage.
,
Jul 30
Just an idea, for the first keystroke, that can be pre-computed? There is about 26 entries. I still want to get traces with a repro of this specific case. For now, I can't tell yet how frequent they are, and how this is impacting our users.
,
Jul 30
> Just an idea, for the first keystroke, that can be pre-computed? Maybe, but at least not easily. Maybe you can help me think through this. My main concern is that the cache would have to be re-computed upon any page visit, which means caching just makes computing top-list omnibox list happen more often, more likely causing jank while browsing the web. Or, maybe with some heuristics, we can do a fast and approximate update upon each page visit and cache that for a single keystroke. However, we would want to do a full / exact scoring as users type more. This might mean we, for example, do the exact computation on the second keystroke, not the first. This might just push the jank to be a little later. (Or maybe this will work, as the later keystroke have fewer page URLs to rank, which means even with exact scoring it may go faster.)
,
Jul 30
On a short term, I want to evaluate the frequency and the impact of these janks. We can observe them in uploaded slow-reports, but we can't tell the reach and how negatively they affect our users. I see two dimensions: memory footprint and the jank caused on the UI thread. For the memory footprint, what we want to optimize is the usefulness of memory used. Does having more entries in memory will improve the omnibox suggestions. For the jank, we are currently adding metrics to help estimating the impact of the jank.
,
Jul 30
thanks etienneb@. Let me know when you have guidance about this. I've been thinking more about the proposal in comment #10/11. I think it might be workable. It would be nice to have a good estimate of its priority, which hopefully you can give us.
,
Aug 1
Assigning to etienneb@ to remove from omnibox triage queue.
,
Aug 1
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/e1b21dc79f36dc4c7ddcb9ce606b94751eedeeca commit e1b21dc79f36dc4c7ddcb9ce606b94751eedeeca Author: Etienne Bergeron <etienneb@chromium.org> Date: Wed Aug 01 20:14:23 2018 Add memory metric to trace event to investigate omnibox performance Adding estimated memory usage to the quick history provider. it is suspected to be slow and cause jank on UI thread when memory usage is high. These metrics will be received with slow-reports and will help to investigate some jank on UI thread. R=mpearson@chromium.org Bug: 868419 Change-Id: I344f84ec00f318fdb9db63c5b464b119a9d5e3eb Reviewed-on: https://chromium-review.googlesource.com/1156847 Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Reviewed-by: Mark Pearson <mpearson@chromium.org> Cr-Commit-Position: refs/heads/master@{#579919} [modify] https://crrev.com/e1b21dc79f36dc4c7ddcb9ce606b94751eedeeca/components/omnibox/browser/history_quick_provider.cc [modify] https://crrev.com/e1b21dc79f36dc4c7ddcb9ce606b94751eedeeca/components/omnibox/browser/in_memory_url_index.cc [modify] https://crrev.com/e1b21dc79f36dc4c7ddcb9ce606b94751eedeeca/components/omnibox/browser/in_memory_url_index.h
,
Aug 1
For what it's worth, the root problem may be that we are simply letting the history grow unbounded right now, and indirectly the HistoryQuickProvider is becoming bloated and slowing down. If a user's history has grown to 1 million entries I'd argue we've failed at helping that user meaningfully organize their data, no matter how they got into that state. For example, we know of some webgames that cause a history entry to be created with every single interaction (ie, every keystroke or click). These users end up with GB of history data, and eventually manually and regularly flush their history database just to keep Chrome running. As a general policy, I think we need to start thinking about having some form of caps in memory/CPU usage of any component/feature, extending out to at least the 99th percentile. Right now I suspect we have so many independent 1% problems that a significant portion of users is affected (gut feeling, actively trying to prove or disprove this).
,
Aug 14
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/7a9ec8c0fcbcd78697c48a395519412ff7ea1a89 commit 7a9ec8c0fcbcd78697c48a395519412ff7ea1a89 Author: Etienne Bergeron <etienneb@chromium.org> Date: Tue Aug 14 17:58:56 2018 Revert "Add memory metric to trace event to investigate omnibox performance" This reverts commit e1b21dc79f36dc4c7ddcb9ce606b94751eedeeca. Reason for revert: 1) No longer needed 2) Slowing down omnibox Original change's description: > Add memory metric to trace event to investigate omnibox performance > > Adding estimated memory usage to the quick history provider. > it is suspected to be slow and cause jank on UI thread when memory usage > is high. > > These metrics will be received with slow-reports and will help to > investigate some jank on UI thread. > > R=​mpearson@chromium.org > > Bug: 868419 > Change-Id: I344f84ec00f318fdb9db63c5b464b119a9d5e3eb > Reviewed-on: https://chromium-review.googlesource.com/1156847 > Commit-Queue: Etienne Bergeron <etienneb@chromium.org> > Reviewed-by: Mark Pearson <mpearson@chromium.org> > Cr-Commit-Position: refs/heads/master@{#579919} TBR=mpearson@chromium.org,etienneb@chromium.org # Not skipping CQ checks because original CL landed > 1 day ago. Bug: 868419 Change-Id: I96785874209368579844e9c55052bc53de12a5a8 Reviewed-on: https://chromium-review.googlesource.com/1174692 Reviewed-by: Mark Pearson <mpearson@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#582973} [modify] https://crrev.com/7a9ec8c0fcbcd78697c48a395519412ff7ea1a89/components/omnibox/browser/history_quick_provider.cc [modify] https://crrev.com/7a9ec8c0fcbcd78697c48a395519412ff7ea1a89/components/omnibox/browser/in_memory_url_index.cc [modify] https://crrev.com/7a9ec8c0fcbcd78697c48a395519412ff7ea1a89/components/omnibox/browser/in_memory_url_index.h
,
Aug 31
It seems there is multiple root cause for that bug. I will update the bug with these cases. The most common one is related to localisaion. -> ui::ResourceBundle::GetLocalizedString(int) https://cs.chromium.org/chromium/src/components/omnibox/browser/search_provider.cc?l=290 I will add a trace event to be able to dissociate slow-reports related to that case. I briefly looked to the bug, and it's spinning into base::IsStringASCII. That may sounds like a corrupt string. I didn't find the root cause yet.
,
Aug 31
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/f51931d17a8ae15edf1559ca74a06e21b3d3a689 commit f51931d17a8ae15edf1559ca74a06e21b3d3a689 Author: Etienne Bergeron <etienneb@chromium.org> Date: Fri Aug 31 18:56:40 2018 Add a trace event on omnibox potential source of jank This CL is adding a trace event around a potential jank point. The purpose of that trace point is to help differenciate slow-reports related to that potential bug and other sources of jank. This code will be removed soon. Feel free to revert the CL on any performance or stability issue. R=mpearson@chromium.org Bug: 868419 Change-Id: I4ed4e86d89d3eb4a5308fb5941b962b5c10e6da4 Reviewed-on: https://chromium-review.googlesource.com/1199924 Reviewed-by: Mark Pearson <mpearson@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#588102} [modify] https://crrev.com/f51931d17a8ae15edf1559ca74a06e21b3d3a689/components/omnibox/browser/search_provider.cc
,
Sep 7
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/a1fb72cf2b0ec35d1922fd47a453536cf53d0757 commit a1fb72cf2b0ec35d1922fd47a453536cf53d0757 Author: Etienne Bergeron <etienneb@chromium.org> Date: Fri Sep 07 21:06:47 2018 Add a metric to track omnibox warmup Some omnibox janks are related to singleton not yet initialized. We believe there can be lot of code running under the hood on the first key stroke. We observed font cache initialisation, localisation loading, etc... The intend of this metrics is to be able to compare popupation for the first key stroke and for the normal use of omnibox. R=mpearson@chromium.org Bug: 868419 Change-Id: I191fd6ee564aa584b633b66a2f90fc7752b64633 Reviewed-on: https://chromium-review.googlesource.com/1210167 Reviewed-by: Mark Pearson <mpearson@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#589640} [modify] https://crrev.com/a1fb72cf2b0ec35d1922fd47a453536cf53d0757/components/omnibox/browser/autocomplete_controller.cc [modify] https://crrev.com/a1fb72cf2b0ec35d1922fd47a453536cf53d0757/components/omnibox/browser/autocomplete_controller.h [modify] https://crrev.com/a1fb72cf2b0ec35d1922fd47a453536cf53d0757/tools/metrics/histograms/histograms.xml
,
Sep 11
,
Sep 13
From this slow-reports: 2301bec357826df1 Time is spent in this stackframe 0xa4a6b - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa4a14 - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa48e4 - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa476c - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa467f - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa3c45 - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa3233 - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xa3132 - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0xf68cd - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] SkScalerContext_DW::getBoundingBox(SkGlyph *,DWRITE_RENDERING_MODE,DWRITE_TEXTURE_TYPE,tagRECT *) SkScalerContext_DW::generateMetrics(SkGlyph *) SkScalerContext::getMetrics(SkGlyph *) SkGlyphCache::allocateNewGlyph(SkPackedGlyphID,SkGlyphCache::MetricsType) SkGlyphCache::getGlyphIDMetrics(unsigned short) sk_getMetrics_glyph_next SkPaint::getTextWidths(void const *,unsigned __int64,float * const,SkRect * const) gfx::`anonymous namespace\'::GetGlyphWidthAndExtents gfx::`anonymous namespace\'::GetGlyphHorizontalAdvance hb_font_get_glyph_h_advances_default hb_ot_shape hb_shape_plan_execute hb_shape_full hb_shape gfx::RenderTextHarfBuzz::ShapeRunsWithFont(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> > *) gfx::RenderTextHarfBuzz::ShapeRuns(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> >) gfx::RenderTextHarfBuzz::ItemizeAndShapeText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunList *) gfx::RenderTextHarfBuzz::EnsureLayoutRunList() gfx::RenderTextHarfBuzz::EnsureLayout() gfx::RenderTextHarfBuzz::GetStringSizeF() gfx::RenderTextHarfBuzz::GetStringSize() OmniboxTextView::CalculatePreferredSize() OmniboxTextView::ReapplyStyling() OmniboxTextView::SetText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,std::vector<AutocompleteMatch::ACMatchClassification,std::allocator<AutocompleteMatch::ACMatchClassification> > const &,bool) OmniboxResultView::Invalidate() OmniboxResultView::SetMatch(AutocompleteMatch const &) OmniboxPopupContentsView::UpdatePopupAppearance() OmniboxPopupModel::OnResultChanged() OmniboxEditModel::OnCurrentMatchChanged() OmniboxController::OnResultChanged(bool) AutocompleteController::UpdateResult(bool,bool) AutocompleteController::Start(AutocompleteInput const &) OmniboxEditModel::StartAutocomplete(bool,bool) OmniboxEditModel::UpdateInput(bool,bool) OmniboxEditModel::OnAfterPossibleChange(OmniboxView::StateChanges const &,bool) OmniboxViewViews::OnAfterPossibleChange(bool) views::Textfield::DoInsertChar(wchar_t) OmniboxViewViews::DoInsertChar(wchar_t) views::Textfield::InsertChar(ui::KeyEvent const &) ui::InputMethodWinBase::OnChar(HWND__ *,unsigned int,unsigned __int64,__int64,tagMSG const &,int *) ui::InputMethodWinBase::ProcessUnhandledKeyEvent(ui::KeyEvent *,std::vector<tagMSG,std::allocator<tagMSG> > const *) ui::InputMethodWinBase::DispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchEvent(ui::EventTarget *,ui::Event *) ui::EventDispatcherDelegate::DispatchEvent(ui::EventTarget *,ui::Event *) ui::EventProcessor::OnEventFromSource(ui::Event *) ui::EventSource::SendEventToSinkFromRewriter(ui::Event *,ui::EventRewriter const *) ui::EventSource::SendEventToSink(ui::Event *) views::DesktopWindowTreeHostWin::HandleKeyEvent(ui::KeyEvent *) views::HWNDMessageHandler::OnKeyEvent(unsigned int,unsigned __int64,__int64) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) UserCallWinProcCheckWow(_ACTIVATION_CONTEXT *,__int64 (*)(tagWND *,unsigned int,unsigned __int64,__int64),HWND__ *,_WM_VALUE,unsigned __int64,__int64,void *,int) DispatchMessageWorker base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh BaseThreadInitThunk RtlUserThreadStart
,
Sep 13
From this slow-reports: f5bbe06a596b3d64 There seems to be an interaction with the sampler profiler. This potential bug is tracked here: https://bugs.chromium.org/p/chromium/issues/detail?id=882982
,
Sep 13
From this slow-reports: 3ca27823e9a6e02c "0x68d9d - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0x68763 - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0x66dfb - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] 0x4368b - DWrite.dll [166B4D93A07F464D0B5A5B3DBA06E7921] SkScalerContext_DW::generateAdvance(SkGlyph *) SkScalerContext_DW::generateMetrics(SkGlyph *) SkScalerContext::getMetrics(SkGlyph *) SkGlyphCache::allocateNewGlyph(SkPackedGlyphID,SkGlyphCache::MetricsType) SkGlyphCache::getGlyphIDMetrics(unsigned short) sk_getMetrics_glyph_next SkPaint::getTextWidths(void const *,unsigned __int64,float * const,SkRect * const) gfx::`anonymous namespace\'::GetGlyphWidthAndExtents gfx::`anonymous namespace\'::GetGlyphHorizontalAdvance hb_font_get_glyph_h_advances_default hb_ot_shape hb_shape_plan_execute hb_shape_full hb_shape gfx::RenderTextHarfBuzz::ShapeRunsWithFont(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> > *) gfx::RenderTextHarfBuzz::ShapeRuns(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> >) gfx::RenderTextHarfBuzz::ItemizeAndShapeText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunList *) gfx::RenderTextHarfBuzz::EnsureLayoutRunList() gfx::RenderTextHarfBuzz::EnsureLayout() gfx::RenderTextHarfBuzz::GetStringSizeF() gfx::RenderTextHarfBuzz::GetStringSize() OmniboxTextView::CalculatePreferredSize() OmniboxTextView::ReapplyStyling() OmniboxTextView::SetText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,std::vector<AutocompleteMatch::ACMatchClassification,std::allocator<AutocompleteMatch::ACMatchClassification> > const &,bool) OmniboxResultView::Invalidate() OmniboxResultView::SetMatch(AutocompleteMatch const &) OmniboxPopupContentsView::UpdatePopupAppearance() OmniboxPopupModel::OnResultChanged() OmniboxEditModel::OnCurrentMatchChanged() OmniboxController::OnResultChanged(bool) AutocompleteController::UpdateResult(bool,bool) AutocompleteController::Start(AutocompleteInput const &) OmniboxEditModel::StartAutocomplete(bool,bool) OmniboxEditModel::UpdateInput(bool,bool) OmniboxEditModel::OnAfterPossibleChange(OmniboxView::StateChanges const &,bool) OmniboxViewViews::OnAfterPossibleChange(bool) views::Textfield::DoInsertChar(wchar_t) OmniboxViewViews::DoInsertChar(wchar_t) views::Textfield::InsertChar(ui::KeyEvent const &) ui::InputMethodWinBase::OnChar(HWND__ *,unsigned int,unsigned __int64,__int64,tagMSG const &,int *) ui::InputMethodWinBase::ProcessUnhandledKeyEvent(ui::KeyEvent *,std::vector<tagMSG,std::allocator<tagMSG> > const *) ui::InputMethodWinBase::DispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchEvent(ui::EventTarget *,ui::Event *) ui::EventDispatcherDelegate::DispatchEvent(ui::EventTarget *,ui::Event *) ui::EventProcessor::OnEventFromSource(ui::Event *) ui::EventSource::SendEventToSinkFromRewriter(ui::Event *,ui::EventRewriter const *) ui::EventSource::SendEventToSink(ui::Event *) views::DesktopWindowTreeHostWin::HandleKeyEvent(ui::KeyEvent *) views::HWNDMessageHandler::OnKeyEvent(unsigned int,unsigned __int64,__int64) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) UserCallWinProcCheckWow(_ACTIVATION_CONTEXT *,__int64 (*)(tagWND *,unsigned int,unsigned __int64,__int64),HWND__ *,_WM_VALUE,unsigned __int64,__int64,void *,int) DispatchMessageWorker base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh BaseThreadInitThunk RtlUserThreadStart
,
Sep 19
By looking to the previous comment, omnibox is calling: OmniboxTextView::CalculatePreferredSize which is using gfx and ends up into RenderTextHarfBuzz::ShapeRunsWithFont https://cs.chromium.org/chromium/src/ui/gfx/render_text_harfbuzz.cc?l=1885 // ShapeRunWithFont can be extremely slow, so use cached results if possible. // Only do this on the UI thread, to avoid synchronization overhead (and // because almost all calls are on the UI thread. Also avoid caching long // strings, to avoid blowing up the cache size.
,
Sep 21
The previous sample (80d408f046e4e503) has 3 omnibox query of more than 5 seconds each. That trace shows a user with the Virtual Keyboard (windows 10 RS4). See attachment. We were also observing slow stackframes related to the virtual keyboard.
,
Sep 24
We are starting to receive enough slow-reports with stackframe to prioritize fixes. This stackframe is the most common one received for omnibox. Which is pointing to font preloading. memcpy DWriteFontTypeface::onGetTableData(unsigned int,unsigned __int64,unsigned __int64,void *) gfx::`anonymous namespace'::GetFontTable hb_face_reference_table _hb_ot_layout_create(hb_face_t *) hb_ot_shaper_face_data_ensure hb_shape_plan_create2 hb_shape_plan_create_cached2 hb_shape_full hb_shape gfx::RenderTextHarfBuzz::ShapeRunsWithFont(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> > *) gfx::RenderTextHarfBuzz::ShapeRuns(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> >) gfx::RenderTextHarfBuzz::ItemizeAndShapeText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunList *) gfx::RenderTextHarfBuzz::EnsureLayoutRunList() gfx::RenderTextHarfBuzz::EnsureLayout() gfx::RenderTextHarfBuzz::GetStringSizeF() gfx::RenderTextHarfBuzz::GetStringSize() OmniboxTextView::CalculatePreferredSize() OmniboxTextView::ReapplyStyling() OmniboxTextView::SetText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,std::vector<AutocompleteMatch::ACMatchClassification,std::allocator<AutocompleteMatch::ACMatchClassification> > const &,bool) OmniboxResultView::Invalidate() OmniboxResultView::SetMatch(AutocompleteMatch const &) OmniboxPopupContentsView::UpdatePopupAppearance() OmniboxPopupModel::OnResultChanged() OmniboxEditModel::OnCurrentMatchChanged() OmniboxController::OnResultChanged(bool) AutocompleteController::UpdateResult(bool,bool) AutocompleteController::Start(AutocompleteInput const &) OmniboxEditModel::StartAutocomplete(bool,bool) OmniboxEditModel::UpdateInput(bool,bool) OmniboxEditModel::OnAfterPossibleChange(OmniboxView::StateChanges const &,bool) OmniboxViewViews::OnAfterPossibleChange(bool) views::Textfield::DoInsertChar(wchar_t) OmniboxViewViews::DoInsertChar(wchar_t) views::Textfield::InsertChar(ui::KeyEvent const &) ui::InputMethodWinBase::OnChar(HWND__ *,unsigned int,unsigned __int64,__int64,tagMSG const &,int *) ui::InputMethodWinBase::ProcessUnhandledKeyEvent(ui::KeyEvent *,std::vector<tagMSG,std::allocator<tagMSG> > const *) ui::InputMethodWinBase::DispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchEvent(ui::EventTarget *,ui::Event *) ui::EventDispatcherDelegate::DispatchEvent(ui::EventTarget *,ui::Event *) ui::EventProcessor::OnEventFromSource(ui::Event *) ui::EventSource::SendEventToSinkFromRewriter(ui::Event *,ui::EventRewriter const *) ui::EventSource::SendEventToSink(ui::Event *) views::DesktopWindowTreeHostWin::HandleKeyEvent(ui::KeyEvent *) views::HWNDMessageHandler::OnKeyEvent(unsigned int,unsigned __int64,__int64) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) user32.dll user32.dll base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh kernel32.dll
,
Sep 24
More frequent stackframes: memcpy DWriteFontTypeface::onGetTableData(unsigned int,unsigned __int64,unsigned __int64,void *) gfx::`anonymous namespace'::GetFontTable hb_face_reference_table _hb_ot_layout_create(hb_face_t *) hb_ot_shaper_face_data_ensure hb_shape_plan_create2 hb_shape_plan_create_cached2 hb_shape_full hb_shape gfx::RenderTextHarfBuzz::ShapeRunsWithFont(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> > *) gfx::RenderTextHarfBuzz::ShapeRuns(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> >) gfx::RenderTextHarfBuzz::ItemizeAndShapeText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunList *) gfx::RenderTextHarfBuzz::EnsureLayoutRunList() gfx::RenderTextHarfBuzz::EnsureLayout() gfx::RenderTextHarfBuzz::GetStringSizeF() gfx::RenderTextHarfBuzz::GetStringSize() OmniboxTextView::CalculatePreferredSize() OmniboxTextView::ReapplyStyling() OmniboxTextView::SetText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,std::vector<AutocompleteMatch::ACMatchClassification,std::allocator<AutocompleteMatch::ACMatchClassification> > const &,bool) OmniboxResultView::Invalidate() OmniboxResultView::SetMatch(AutocompleteMatch const &) OmniboxPopupContentsView::UpdatePopupAppearance() OmniboxPopupModel::OnResultChanged() OmniboxEditModel::OnCurrentMatchChanged() OmniboxController::OnResultChanged(bool) AutocompleteController::UpdateResult(bool,bool) AutocompleteController::Start(AutocompleteInput const &) OmniboxEditModel::StartAutocomplete(bool,bool) OmniboxEditModel::UpdateInput(bool,bool) OmniboxEditModel::OnAfterPossibleChange(OmniboxView::StateChanges const &,bool) OmniboxViewViews::OnAfterPossibleChange(bool) views::Textfield::DoInsertChar(wchar_t) OmniboxViewViews::DoInsertChar(wchar_t) views::Textfield::InsertChar(ui::KeyEvent const &) ui::InputMethodWinBase::OnChar(HWND__ *,unsigned int,unsigned __int64,__int64,tagMSG const &,int *) ui::InputMethodWinBase::ProcessUnhandledKeyEvent(ui::KeyEvent *,std::vector<tagMSG,std::allocator<tagMSG> > const *) ui::InputMethodWinBase::DispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchEvent(ui::EventTarget *,ui::Event *) ui::EventDispatcherDelegate::DispatchEvent(ui::EventTarget *,ui::Event *) ui::EventProcessor::OnEventFromSource(ui::Event *) ui::EventSource::SendEventToSinkFromRewriter(ui::Event *,ui::EventRewriter const *) ui::EventSource::SendEventToSink(ui::Event *) views::DesktopWindowTreeHostWin::HandleKeyEvent(ui::KeyEvent *) views::HWNDMessageHandler::OnKeyEvent(unsigned int,unsigned __int64,__int64) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) user32.dll user32.dll base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh kernel32.dll ntdll.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll SkScalerContext_DW::generateAdvance(SkGlyph *) SkScalerContext_DW::generateMetrics(SkGlyph *) SkScalerContext::getMetrics(SkGlyph *) SkGlyphCache::allocateNewGlyph(SkPackedGlyphID,SkGlyphCache::MetricsType) SkGlyphCache::getGlyphIDMetrics(unsigned short) sk_getMetrics_glyph_next SkPaint::getTextWidths(void const *,unsigned __int64,float * const,SkRect * const) gfx::`anonymous namespace'::GetGlyphWidthAndExtents gfx::`anonymous namespace'::GetGlyphHorizontalAdvance hb_font_get_glyph_h_advances_default hb_ot_shape hb_shape_plan_execute hb_shape_full hb_shape gfx::RenderTextHarfBuzz::ShapeRunsWithFont(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> > *) gfx::RenderTextHarfBuzz::ShapeRuns(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> >) gfx::RenderTextHarfBuzz::ItemizeAndShapeText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunList *) gfx::RenderTextHarfBuzz::EnsureLayoutRunList() gfx::RenderTextHarfBuzz::EnsureLayout() gfx::RenderTextHarfBuzz::GetStringSizeF() gfx::RenderTextHarfBuzz::GetStringSize() OmniboxTextView::CalculatePreferredSize() OmniboxTextView::ReapplyStyling() OmniboxTextView::SetText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,std::vector<AutocompleteMatch::ACMatchClassification,std::allocator<AutocompleteMatch::ACMatchClassification> > const &,bool) OmniboxResultView::Invalidate() OmniboxResultView::SetMatch(AutocompleteMatch const &) OmniboxPopupContentsView::UpdatePopupAppearance() OmniboxPopupModel::OnResultChanged() OmniboxEditModel::OnCurrentMatchChanged() OmniboxController::OnResultChanged(bool) AutocompleteController::UpdateResult(bool,bool) AutocompleteController::Start(AutocompleteInput const &) OmniboxEditModel::StartAutocomplete(bool,bool) OmniboxEditModel::UpdateInput(bool,bool) OmniboxEditModel::OnAfterPossibleChange(OmniboxView::StateChanges const &,bool) OmniboxViewViews::OnAfterPossibleChange(bool) views::Textfield::DoInsertChar(wchar_t) OmniboxViewViews::DoInsertChar(wchar_t) views::Textfield::InsertChar(ui::KeyEvent const &) ui::InputMethodWinBase::OnChar(HWND__ *,unsigned int,unsigned __int64,__int64,tagMSG const &,int *) ui::InputMethodWinBase::ProcessUnhandledKeyEvent(ui::KeyEvent *,std::vector<tagMSG,std::allocator<tagMSG> > const *) ui::InputMethodWinBase::DispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchEvent(ui::EventTarget *,ui::Event *) ui::EventDispatcherDelegate::DispatchEvent(ui::EventTarget *,ui::Event *) ui::EventProcessor::OnEventFromSource(ui::Event *) ui::EventSource::SendEventToSinkFromRewriter(ui::Event *,ui::EventRewriter const *) ui::EventSource::SendEventToSink(ui::Event *) views::DesktopWindowTreeHostWin::HandleKeyEvent(ui::KeyEvent *) views::HWNDMessageHandler::OnKeyEvent(unsigned int,unsigned __int64,__int64) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) user32.dll user32.dll base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh dwrite.dll dwrite.dll dwrite.dll dwrite.dll SkScalerContext_DW::generateAdvance(SkGlyph *) SkScalerContext_DW::generateMetrics(SkGlyph *) SkScalerContext::getMetrics(SkGlyph *) SkGlyphCache::allocateNewGlyph(SkPackedGlyphID,SkGlyphCache::MetricsType) SkGlyphCache::getGlyphIDMetrics(unsigned short) sk_getMetrics_glyph_next SkPaint::getTextWidths(void const *,unsigned __int64,float * const,SkRect * const) gfx::`anonymous namespace'::GetGlyphWidthAndExtents gfx::`anonymous namespace'::GetGlyphHorizontalAdvance hb_font_get_glyph_h_advances_default hb_ot_shape hb_shape_plan_execute hb_shape_full hb_shape gfx::RenderTextHarfBuzz::ShapeRunsWithFont(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> > *) gfx::RenderTextHarfBuzz::ShapeRuns(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunHarfBuzz::FontParams const &,std::vector<gfx::internal::TextRunHarfBuzz *,std::allocator<gfx::internal::TextRunHarfBuzz *> >) gfx::RenderTextHarfBuzz::ItemizeAndShapeText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::internal::TextRunList *) gfx::RenderTextHarfBuzz::EnsureLayoutRunList() gfx::RenderTextHarfBuzz::EnsureLayout() gfx::RenderTextHarfBuzz::GetStringSizeF() gfx::RenderTextHarfBuzz::GetStringSize() OmniboxTextView::CalculatePreferredSize() OmniboxTextView::ReapplyStyling() OmniboxTextView::SetText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,std::vector<AutocompleteMatch::ACMatchClassification,std::allocator<AutocompleteMatch::ACMatchClassification> > const &,bool) OmniboxResultView::Invalidate() OmniboxResultView::SetMatch(AutocompleteMatch const &) OmniboxPopupContentsView::UpdatePopupAppearance() OmniboxPopupModel::OnResultChanged() OmniboxEditModel::OnCurrentMatchChanged() OmniboxController::OnResultChanged(bool) AutocompleteController::UpdateResult(bool,bool) AutocompleteController::Start(AutocompleteInput const &) OmniboxEditModel::StartAutocomplete(bool,bool) OmniboxEditModel::UpdateInput(bool,bool) OmniboxEditModel::OnAfterPossibleChange(OmniboxView::StateChanges const &,bool) OmniboxViewViews::OnAfterPossibleChange(bool) views::Textfield::DoInsertChar(wchar_t) OmniboxViewViews::DoInsertChar(wchar_t) views::Textfield::InsertChar(ui::KeyEvent const &) ui::InputMethodWinBase::OnChar(HWND__ *,unsigned int,unsigned __int64,__int64,tagMSG const &,int *) ui::InputMethodWinBase::ProcessUnhandledKeyEvent(ui::KeyEvent *,std::vector<tagMSG,std::allocator<tagMSG> > const *) ui::InputMethodWinBase::DispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchKeyEvent(ui::KeyEvent *) aura::WindowEventDispatcher::PreDispatchEvent(ui::EventTarget *,ui::Event *) ui::EventDispatcherDelegate::DispatchEvent(ui::EventTarget *,ui::Event *) ui::EventProcessor::OnEventFromSource(ui::Event *) ui::EventSource::SendEventToSinkFromRewriter(ui::Event *,ui::EventRewriter const *) ui::EventSource::SendEventToSink(ui::Event *) views::DesktopWindowTreeHostWin::HandleKeyEvent(ui::KeyEvent *) views::HWNDMessageHandler::OnKeyEvent(unsigned int,unsigned __int64,__int64) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) user32.dll user32.dll base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh kernel32.dll
,
Sep 26
,
Oct 5
,
Oct 11
I'm moving away the slow fonts loading to a separate bug: https://bugs.chromium.org/p/chromium/issues/detail?id=894459 I'll continue to update this one with other slow-cases.
,
Today
(18 hours ago)
|
|||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||
Comment 1 by etienneb@chromium.org
, Jul 2712.8 KB
12.8 KB View Download
11.6 KB
11.6 KB View Download