Jank caused by slow execution of RenderTextHarfBuzz::ShapeRuns |
||||||||||||
Issue descriptionShapeRuns is executed on the browser main thread and may be slow. In some cases, it can be minutes of janks caused by font loading. This bug was originally posted here (affecting omnibox): https://bugs.chromium.org/p/chromium/issues/detail?id=868419 This bug is an intend to document and dig into the specific case where fonts loading is the root cause of the jank.
,
Oct 11
From the following report: bb37581fca325dcf (attachment) We are seeing a jank caused by loading fallback fonts. The main thread is stalled 2 seconds on the following stackframe: ZwEnumerateValueKey LocalBaseRegEnumValue RegEnumValueW RegEnumValueWStub base::win::RegistryValueIterator::Read() gfx::`anonymous namespace\'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &) 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() This is the fallback fonts loading on windows. It seems to be enumerating fonts may be expensive. see https://cs.chromium.org/chromium/src/ui/gfx/render_text_harfbuzz.cc?l=1826 if (!preferred_fallback_family.empty()) { std::vector<Font> fallback_fonts = GetFallbackFonts(fallback_font); fallback_font_list.insert(fallback_font_list.end(), fallback_fonts.begin(), fallback_fonts.end()); }
,
Oct 11
From the following report: 345efb4d6fc93121 We are seeing a ~30 seconds jank caused by fonts loading. This is also related to loading fallback fonts. Stalled on the following stackframe: anonymous namespace\'::TrueTypeFontMetricsBuilder::GetBlackBox(unsigned short) `anonymous namespace\'::TrueTypeFontMetricsBuilder::GetGlyphMetrics(unsigned short) FontFaceRegionBuilder::Impl::WriteRegionInternal(MemoryWriter<PhysicalFontFaceRegion> &) FontFaceRegionBuilder::Impl::WriteRegion(MemoryWriter<PhysicalFontFaceRegion> &) FontFaceElement::AddToCacheImpl(FontLoaderManagers const &,CacheWriter &,void const * *,unsigned int *) CacheWriter::AddElement(FontLoaderManagers const &,IFontCacheElement &,unsigned int,unsigned int,void const * *,unsigned int *,bool *) ClientSideCacheContext::ClientLookup(IFontCacheElement &,unsigned int,unsigned int) ClientSideCacheContext::InitializeElementImpl(IFontCacheElement &,unsigned int,unsigned int) DWriteFontFace::DWriteFontFace(ClientSideCacheContext *,DWRITE_FONT_FACE_TYPE,DWRITE_FONT_SIMULATIONS,unsigned int,IDWriteFontFile * const *,unsigned int) DWriteFontFace::CreateFromKey(ClientSideCacheContext &,DWRITE_FONT_FACE_TYPE,DWRITE_FONT_SIMULATIONS,void const *,unsigned int,CountedPtr<AccessToken> const &,FontFaceCache *) DWriteFont::CreateFontFace(IDWriteFontFace * *) SkFontMgr_DirectWrite::onLegacyMakeTypeface(char const * const,SkFontStyle) <aliased> RefcountedBrowserContextKeyedServiceFactory::BuildServiceInstanceFor(base::SupportsUserData *) SkTypeface::MakeFromName(char const * const,SkFontStyle) gfx::PlatformFontWin::CreateHFontRefFromSkia(HFONT__ *,tagTEXTMETRICW const &) gfx::PlatformFontWin::CreateHFontRef(HFONT__ *) gfx::PlatformFontWin::InitWithFontNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::PlatformFont::CreateFromNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::Font::Font(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::`anonymous namespace\'::AppendFont gfx::`anonymous namespace\'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &) 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()
,
Oct 11
From this reports: 886b72740be30e9e The page loading time is high because browser process is spending ~30 seconds on fonts loading. Most of the time is spend in: FontFaceElement::AddToCacheImpl(FontLoaderManagers const &,CacheWriter &,void const * *,unsigned int *) CacheWriter::AddElement(FontLoaderManagers const &,IFontCacheElement &,unsigned int,unsigned int,void const * *,unsigned int *,bool *) ClientSideCacheContext::ClientLookup(IFontCacheElement &,unsigned int,unsigned int) ClientSideCacheContext::InitializeElementImpl(IFontCacheElement &,unsigned int,unsigned int) DWriteFontFace::DWriteFontFace(ClientSideCacheContext *,DWRITE_FONT_FACE_TYPE,DWRITE_FONT_SIMULATIONS,unsigned int,IDWriteFontFile * const *,unsigned int) DWriteFontFace::CreateFromKey(ClientSideCacheContext &,DWRITE_FONT_FACE_TYPE,DWRITE_FONT_SIMULATIONS,void const *,unsigned int,CountedPtr<AccessToken> const &,FontFaceCache *) DWriteFont::CreateFontFace(IDWriteFontFace * *) SkFontMgr_DirectWrite::onLegacyMakeTypeface(char const * const,SkFontStyle) <aliased> RefcountedBrowserContextKeyedServiceFactory::BuildServiceInstanceFor(base::SupportsUserData *) SkTypeface::MakeFromName(char const * const,SkFontStyle) gfx::PlatformFontWin::CreateHFontRefFromSkia(HFONT__ *,tagTEXTMETRICW const &) gfx::PlatformFontWin::CreateHFontRef(HFONT__ *) gfx::PlatformFontWin::InitWithFontNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::PlatformFont::CreateFromNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::Font::Font(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::`anonymous namespace\'::AppendFont gfx::`anonymous namespace\'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &) gfx::RenderTextHarfBuzz::ShapeRuns An important point to note, there are blocks of "sampling CPU events" that shows that we are reading multiple fonts, and each font is taking time.
,
Oct 11
From this report: 1228aa6c18dfc404 There is a 23 seconds fonts loading on a page load. This issue is not only affecting omnibox. It will affect startup time, page load, omnibox, etc..
,
Oct 11
,
Oct 11
,
Oct 11
This report: ab2ee9f3dead03a6 (12 seconds font loading) This is affecting : PageLoad.PaintTiming.NavigationToFirstContentfulPaint This is again a fallback fonts loading: gfx::PlatformFontWin::CreateHFontRefFromSkia(HFONT__ *,tagTEXTMETRICW const &) gfx::PlatformFontWin::CreateHFontRef(HFONT__ *) gfx::PlatformFontWin::InitWithFontNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::PlatformFont::CreateFromNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::Font::Font(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::`anonymous namespace\'::AppendFont gfx::`anonymous namespace\'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &)
,
Oct 11
+ ccameron@ since he is playing in this code. He may have some insights.
,
Oct 11
,
Oct 12
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/3638eaae091158d771e3ac8ce7d45c2ac925fb32 commit 3638eaae091158d771e3ac8ce7d45c2ac925fb32 Author: Etienne Bergeron <etienneb@chromium.org> Date: Fri Oct 12 14:33:56 2018 Add trace events to investigate pathological fonts loading This CL is adding trace events to look closer on some slow cases happening in the browser process. Traces will be collected via slow-reports and an investigation will be continued based on results of these events. R=fdoray@chromium.org, ccameron@chromium.org Bug: 894459 Change-Id: I2e3c37e9a42ceef9ca9aea5ec94a125db247aa77 Reviewed-on: https://chromium-review.googlesource.com/c/1277825 Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Reviewed-by: ccameron <ccameron@chromium.org> Reviewed-by: François Doray <fdoray@chromium.org> Cr-Commit-Position: refs/heads/master@{#599205} [modify] https://crrev.com/3638eaae091158d771e3ac8ce7d45c2ac925fb32/ui/gfx/render_text_harfbuzz.cc
,
Oct 12
I looked to the code and I think I've got what is happening. 1) gfx::RenderTextHarfBuzz::ShapeRuns That function is trying to split text to glyphs. There is a cache to hide the cost below (which may not be the right fix). The split is done with the primary font, or the fallback font. It it's not working, there is a call to get the fallbacks font (every installed fonts for a given family). Each font is tried until one is working. see : https://cs.chromium.org/chromium/src/ui/gfx/render_text_harfbuzz.cc?type=cs&q=ShapeRunsWithFont&g=0&l=1847 2) gfx::GetFallbackFonts(gfx::Font const &) GetFallbackFonts is enumerating fonts for a given family through registry key. The enumeration is cached by family to hide the expensive cost. https://cs.chromium.org/chromium/src/ui/gfx/font_fallback_win.cc?type=cs&g=0&l=325 Here again, the cache is only to hide the expensive cost. 3) gfx::`anonymous namespace\'::AppendFont gfx::`anonymous namespace\'::CachedFontLinkSettings::GetLinkedFonts AppendFont is adding the font to the list of known fonts. if (fonts->empty() || fonts->back().GetFontName() != name) fonts->push_back(Font(name, size)); The important point is that the Font constructor used is the Font(family, size) which is expensive on windows. This constructor will be called for every font of the family. 4) PlatformFontWin::PlatformFontWin(...) see: https://cs.chromium.org/chromium/src/ui/gfx/platform_font_win.cc?type=cs&sq=package:chromium&g=0&l=400 https://cs.chromium.org/chromium/src/ui/gfx/platform_font_win.cc?type=cs&sq=package:chromium&g=0&l=547 https://cs.chromium.org/chromium/src/ui/gfx/platform_font_win.cc?type=cs&sq=package:chromium&g=0&l=581 https://cs.chromium.org/chromium/src/ui/gfx/platform_font_win.cc?type=cs&sq=package:chromium&g=0&l=618 For each call to the constructor, this code will be executed: PlatformFontWin::HFontRef* PlatformFontWin::CreateHFontRefFromSkia(...) This code is really expensive since it's implies to load the font. To repro the slow path on windows, you need to search for an unicode string that can't be rendered with your primary font. You also need to have many fonts installed. I manage to fake the too many fonts installed by changing the fonts enumeration and adding multiple time the same fonts. I also suspect this can be slow on people with a slow computer and not too many fonts.
,
Oct 13
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/48cbd1dd19363a0f6c9108c7d35155d5cbfd70e2 commit 48cbd1dd19363a0f6c9108c7d35155d5cbfd70e2 Author: Etienne Bergeron <etienneb@chromium.org> Date: Sat Oct 13 02:39:59 2018 Remove useless fonts iterator This CL is a first step towards fixing performance issues with fonts. It's removing an useless fonts iterator. The iterator is only used to copy fonts from a vector to an other vector. R=fdoray@chromium.org Bug: 894459 Change-Id: Iadeeea61ad5f06dbd4b9ad2a9d440b7dba8742fd Reviewed-on: https://chromium-review.googlesource.com/c/1278849 Reviewed-by: Alexei Svitkine <asvitkine@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#599472} [modify] https://crrev.com/48cbd1dd19363a0f6c9108c7d35155d5cbfd70e2/ui/gfx/font_fallback_win.cc [modify] https://crrev.com/48cbd1dd19363a0f6c9108c7d35155d5cbfd70e2/ui/gfx/font_fallback_win.h [modify] https://crrev.com/48cbd1dd19363a0f6c9108c7d35155d5cbfd70e2/ui/gfx/font_fallback_win_unittest.cc
,
Oct 13
From this slow-report: afd792c5633e6c54 The main thread is blocked for ~42 seconds on ShapeRuns. The stalled task: LayerTreeHost::DoUpdateLayers Stackframe: dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll dwrite.dll SkFontMgr_DirectWrite::onLegacyMakeTypeface(char const * const,SkFontStyle) <aliased> RefcountedBrowserContextKeyedServiceFactory::BuildServiceInstanceFor(base::SupportsUserData *) SkTypeface::MakeFromName(char const * const,SkFontStyle) gfx::PlatformFontWin::CreateHFontRefFromSkia(HFONT__ *,tagTEXTMETRICW const &) gfx::PlatformFontWin::CreateHFontRef(HFONT__ *) gfx::PlatformFontWin::InitWithFontNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::PlatformFont::CreateFromNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::Font::Font(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::`anonymous namespace'::AppendFont gfx::`anonymous namespace'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &) 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::RenderText::Draw(gfx::Canvas *) views::Label::OnPaint(gfx::Canvas *) views::View::Paint(views::PaintInfo const &) views::View::RecursivePaintHelper(void ( views::View::*)(views::PaintInfo const &),views::PaintInfo const &) views::View::PaintChildren(views::PaintInfo const &) Tab::PaintChildren(views::PaintInfo const &) views::View::Paint(views::PaintInfo const &) TabStrip::PaintChildren(views::PaintInfo const &) views::View::Paint(views::PaintInfo const &) views::View::RecursivePaintHelper(void ( views::View::*)(views::PaintInfo const &),views::PaintInfo const &) views::View::PaintChildren(views::PaintInfo const &) TopContainerView::PaintChildren(views::PaintInfo const &) views::View::Paint(views::PaintInfo const &) views::View::RecursivePaintHelper(void ( views::View::*)(views::PaintInfo const &),views::PaintInfo const &) views::View::PaintChildren(views::PaintInfo const &) BrowserView::PaintChildren(views::PaintInfo const &) views::View::Paint(views::PaintInfo const &) views::View::RecursivePaintHelper(void ( views::View::*)(views::PaintInfo const &),views::PaintInfo const &) views::View::PaintChildren(views::PaintInfo const &) views::View::Paint(views::PaintInfo const &) views::View::RecursivePaintHelper(void ( views::View::*)(views::PaintInfo const &),views::PaintInfo const &) views::View::PaintChildren(views::PaintInfo const &) views::View::Paint(views::PaintInfo const &) views::View::PaintFromPaintRoot(ui::PaintContext const &) ui::Layer::PaintContentsToDisplayList(cc::ContentLayerClient::PaintingControlSetting) cc::PictureLayer::Update() cc::LayerTreeHost::DoUpdateLayers(cc::Layer *) cc::LayerTreeHost::UpdateLayers() cc::SingleThreadProxy::BeginMainFrame(viz::BeginFrameArgs const &) base::debug::TaskAnnotator::RunTask(char const *,base::PendingTask *) base::MessageLoop::RunTask(base::PendingTask *) base::MessageLoop::DoWork() 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
,
Oct 13
From this slow-report: e007ee60d708b095 There is a 41 seconds jank caused by this issue. This is affecting the "Startup.FirstWebContents.NonEmptyPaint2" metric. Stackframe: dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb SkFontMgr_DirectWrite::onLegacyMakeTypeface(char const * const,SkFontStyle) <aliased> RefcountedBrowserContextKeyedServiceFactory::BuildServiceInstanceFor(base::SupportsUserData *) SkTypeface::MakeFromName(char const * const,SkFontStyle) gfx::PlatformFontWin::CreateHFontRefFromSkia(HFONT__ *,tagTEXTMETRICW const &) gfx::PlatformFontWin::CreateHFontRef(HFONT__ *) gfx::PlatformFontWin::InitWithFontNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::PlatformFont::CreateFromNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::Font::Font(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::`anonymous namespace'::AppendFont gfx::`anonymous namespace'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &) 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() views::Label::GetTextSize() views::Label::CalculatePreferredSize() <aliased> views::View::GetMinimumSize() views::LabelButton::Layout() views::View::PreferredSizeChanged() views::Label::ResetLayout() views::LabelButton::LabelButton(views::ButtonListener *,std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,int) `anonymous namespace'::BookmarkButtonBase::BookmarkButtonBase BookmarkBarView::CreateBookmarkButton(bookmarks::BookmarkNode const *) BookmarkBarView::Layout() BookmarkBarView::BookmarkModelLoaded(bookmarks::BookmarkModel *,bool) bookmarks::BookmarkModel::DoneLoading(std::unique_ptr<bookmarks::BookmarkLoadDetails,std::default_delete<bookmarks::BookmarkLoadDetails> >) <aliased> base::internal::Invoker<base::internal::BindState<void (CreateChromeApplicationShortcutView::*)(std::unique_ptr<web_app::ShortcutInfo,std::default_delete<web_app::ShortcutInfo> >),base::WeakPtr<CreateChromeApplicationShortcutView> >,void (std::unique_ptr<web_app::ShortcutInfo,std::default_delete<web_app::ShortcutInfo> >)>::Run bookmarks::ModelLoader::OnFinishedLoad(std::unique_ptr<bookmarks::BookmarkLoadDetails,std::default_delete<bookmarks::BookmarkLoadDetails> >,base::OnceCallback<void >) base::internal::Invoker<base::internal::BindState<void (bookmarks::ModelLoader::*)(std::unique_ptr<bookmarks::BookmarkLoadDetails,std::default_delete<bookmarks::BookmarkLoadDetails> >, base::OnceCallback<void (std::unique_ptr<bookmarks::BookmarkLoadDetails,std::default_delete<bookmarks::BookmarkLoadDetails> >)>),scoped_refptr<bookmarks::ModelLoader>,std::unique_ptr<bookmarks::BookmarkLoadDetails,std::default_delete<bookmarks::BookmarkLoadDetails> >,base::OnceCallback<void (std::unique_ptr<bookmarks::BookmarkLoadDetails,std::default_delete<bookmarks::BookmarkLoadDetails> >)> >,void ()>::RunOnce base::debug::TaskAnnotator::RunTask(char const *,base::PendingTask *) base::MessageLoop::RunTask(base::PendingTask *) base::MessageLoop::DoWork() 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
,
Oct 13
From this slow-report: 886b72740be30e9e There is a 36 seconds jank on new tab page. Stackframe: 1 551 36.13 RenderTextHarfBuzz::ShapeRuns dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb dwrite.pdb SkFontMgr_DirectWrite::onLegacyMakeTypeface(char const * const,SkFontStyle) <aliased> RefcountedBrowserContextKeyedServiceFactory::BuildServiceInstanceFor(base::SupportsUserData *) SkTypeface::MakeFromName(char const * const,SkFontStyle) gfx::PlatformFontWin::CreateHFontRefFromSkia(HFONT__ *,tagTEXTMETRICW const &) gfx::PlatformFontWin::CreateHFontRef(HFONT__ *) gfx::PlatformFontWin::InitWithFontNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::PlatformFont::CreateFromNameAndSize(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::Font::Font(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,int) gfx::`anonymous namespace'::AppendFont gfx::`anonymous namespace'::CachedFontLinkSettings::GetLinkedFonts gfx::internal::LinkedFontsIterator::GetLinkedFonts() gfx::internal::LinkedFontsIterator::NextFont(gfx::Font *) gfx::GetFallbackFonts(gfx::Font const &) 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::Canvas::SizeStringFloat(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::FontList const &,float *,float *,int,int,gfx::Typesetter) gfx::Canvas::GetStringWidthF(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::FontList const &,gfx::Typesetter) gfx::ElideRectangleText(std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > const &,gfx::FontList const &,float,int,gfx::WordWrapBehavior,std::vector<std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> >,std::allocator<std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > > > *) message_center::InnerBoundedLabel::GetWrappedText(int,int) message_center::InnerBoundedLabel::GetSizeForWidthAndLines(int,int) message_center::BoundedLabel::GetHeightForWidth(int) views::BoxLayout::ViewWrapper::GetHeightForWidth(int) views::BoxLayout::MainAxisSizeForView(views::BoxLayout::ViewWrapper const &,int) views::BoxLayout::GetPreferredSizeForChildWidth(views::View const *,int) views::BoxLayout::GetPreferredHeightForWidth(views::View const *,int) message_center::NotificationView::GetHeightForWidth(int) views::FillLayout::GetPreferredHeightForWidth(views::View const *,int) message_center::MessagePopupCollection::GetNextEdge(message_center::MessagePopupCollection::PopupItem const &) message_center::MessagePopupCollection::IsNextEdgeOutsideWorkArea(message_center::MessagePopupCollection::PopupItem const &) message_center::MessagePopupCollection::AddPopup() message_center::MessagePopupCollection::TransitionToAnimation() message_center::MessagePopupCollection::Update() message_center::MessageCenterImpl::AddNotification(std::unique_ptr<message_center::Notification,std::default_delete<message_center::Notification> >) NotificationUIManagerImpl::Add(message_center::Notification const &,Profile *) NotificationPlatformBridgeMessageCenter::Display(NotificationHandler::Type,Profile *,message_center::Notification const &,std::unique_ptr<NotificationCommon::Metadata,std::default_delete<NotificationCommon::Metadata> >) NotificationDisplayServiceImpl::Display(NotificationHandler::Type,message_center::Notification const &,std::unique_ptr<NotificationCommon::Metadata,std::default_delete<NotificationCommon::Metadata> >) PlatformNotificationServiceImpl::DisplayPersistentNotification(content::BrowserContext *,std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &,GURL const &,GURL const &,blink::PlatformNotificationData const &,blink::NotificationResources const &) base::internal::Invoker<base::internal::BindState<void (content::PlatformNotificationService::*)(content::BrowserContext *, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > &, const GURL &, const GURL &, const blink::PlatformNotificationData &, const blink::NotificationResources &),base::internal::UnretainedWrapper<content::PlatformNotificationService>,content::BrowserContext *,std::basic_string<char,std::char_traits<char>,std::allocator<char> >,GURL,GURL,blink::PlatformNotificationData,blink::NotificationResources>,void ()>::RunOnce base::debug::TaskAnnotator::RunTask(char const *,base::PendingTask *) base::MessageLoop::RunTask(base::PendingTask *) base::MessageLoop::DoWork() 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
,
Oct 15
How come we don't have symbols for dwrite.dll? They should be available on Microsoft's symbol server.
,
Oct 15
We have symbol for dwrite, but there was an error in the pipeline to process these symbols. 1) sampling profiler was reporting the basename (got fixed 2 weeks ago) 2) the pdb name was reported lower case, crash server is case sensitive (got fixed last week) Thus recent traces should be symbolized correctly.
,
Oct 17
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/e3fac25689e1e47cd192425b6f461226fd45b1c2 commit e3fac25689e1e47cd192425b6f461226fd45b1c2 Author: Etienne Bergeron <etienneb@chromium.org> Date: Wed Oct 17 15:15:52 2018 Add a UMA timing metric for fallbacks fonts This CL is adding a metric to collect metric on the fallback fonts issue. Slow-reports show that many bad cases (99th percentile) of different heartbeat metrics are affected by: gfx::GetFallbackFonts(gfx::Font const &) 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() This UMA metric will help us to estimate the size of the population affected by this scenario. R=fdoray@chromium.org, holte@chromium.org, ccameron@chromium.org Bug: 894459 Change-Id: Ic0d1fac1f69a329bf11544f49e34c91635046331 Reviewed-on: https://chromium-review.googlesource.com/c/1281227 Reviewed-by: Steven Holte <holte@chromium.org> Reviewed-by: François Doray <fdoray@chromium.org> Reviewed-by: ccameron <ccameron@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#600393} [modify] https://crrev.com/e3fac25689e1e47cd192425b6f461226fd45b1c2/tools/metrics/histograms/histograms.xml [modify] https://crrev.com/e3fac25689e1e47cd192425b6f461226fd45b1c2/ui/gfx/render_text_harfbuzz.cc
,
Oct 22
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/58a6294a0ce9655c61498eb58fb77893807fe550 commit 58a6294a0ce9655c61498eb58fb77893807fe550 Author: Etienne Bergeron <etienneb@chromium.org> Date: Mon Oct 22 22:09:24 2018 Add UMA metrics for fallbacks fonts This CL is adding a metric to collect metric on the fallback fonts issue. Slow-reports show that many bad cases (99th percentile) of different heartbeat metrics are affected by: gfx::GetFallbackFonts(gfx::Font const &) Previous CL: https://chromium-review.googlesource.com/c/chromium/src/+/1281227/ The previous metrics show the problem for some users with latency above 1 minute. Unfortunately, it was hard to estimate the impact of the code since most of the subsequent calls will hit the cache. We are interrested in the initial call (not cached) since it's affecting startup time and omnibox first char typed to paint. The new metric will drive optimisation that will follow this CL. Bug: 894459 Change-Id: Iecfe02896cc08153cc630f6ba870036a408b4630 Reviewed-on: https://chromium-review.googlesource.com/c/1293272 Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Reviewed-by: Alexei Svitkine <asvitkine@chromium.org> Cr-Commit-Position: refs/heads/master@{#601746} [modify] https://crrev.com/58a6294a0ce9655c61498eb58fb77893807fe550/tools/metrics/histograms/histograms.xml [modify] https://crrev.com/58a6294a0ce9655c61498eb58fb77893807fe550/ui/gfx/font_fallback_win.cc
,
Oct 27
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/94502b658ba854da5423e7877780cf6e4c2a3c3b commit 94502b658ba854da5423e7877780cf6e4c2a3c3b Author: Etienne Bergeron <etienneb@chromium.org> Date: Sat Oct 27 19:45:47 2018 Add logging for fallback fonts This CL is the help understanding the jank caused in RenderTextHarfBuzz::ShapeRuns It seems that for some cases, getting the fallback fonts can be really slow. We know this can be related to the fonts, or to it's substitution. This CL is adding a trace event with the following information. The goal is to collect a few example from slow-reports and try to explain the high latencies. Title QueryLinkedFontsFromRegistry ... Args results "Original font: Segoe UI fallback: 'Tahoma' 'TAHOMA.TTF' fallback: 'Meiryo UI' 'MEIRYO.TTC' fallback: 'Meiryo UI' 'MEIRYO.TTC' fallback: 'MS UI Gothic' 'MSGOTHIC.TTC' fallback: 'Microsoft JhengHei UI' 'MSJH.TTC' fallback: 'Microsoft JhengHei UI' 'MSJH.TTC' fallback: 'Microsoft YaHei UI' 'MSYH.TTC' fallback: 'Microsoft YaHei UI' 'MSYH.TTC' fallback: 'Malgun Gothic' 'MALGUN.TTF' fallback: 'Malgun Gothic' 'MALGUN.TTF' fallback: 'PMingLiU' 'MINGLIU.TTC' fallback: 'SimSun' 'SIMSUN.TTC' fallback: 'Gulim' 'GULIM.TTC' fallback: 'Yu Gothic UI' 'YUGOTHM.TTC' fallback: 'Yu Gothic UI' 'YUGOTHM.TTC' fallback: 'Segoe UI Symbol' 'SEGUISYM.TTF' resolved: 'Tahoma' resolved: 'Arial' resolved: 'Arial' resolved: 'MS UI Gothic' resolved: 'Microsoft JhengHei UI' resolved: 'Microsoft YaHei UI' resolved: 'Malgun Gothic' resolved: 'Arial' resolved: 'SimSun' resolved: 'Arial' resolved: 'Yu Gothic UI' resolved: 'Segoe UI Symbol' " R=asvitkine@chromium.org Bug: 894459 Change-Id: I0c3f1b9e3404b4a84e331d8842cfbc1311d9f58b Reviewed-on: https://chromium-review.googlesource.com/c/1302865 Reviewed-by: Alexei Svitkine <asvitkine@chromium.org> Commit-Queue: Etienne Bergeron <etienneb@chromium.org> Cr-Commit-Position: refs/heads/master@{#603345} [modify] https://crrev.com/94502b658ba854da5423e7877780cf6e4c2a3c3b/ui/gfx/font_fallback_win.cc
,
Nov 1
From this slow-reports: ed96ea1a9a34e66c (11 seconds, font fallbacks) The time is spent in the DWrite cache. CacheReader::ValidateCheckSum(...) ClientSideCacheContext::FindInSharedCache(IElementKey const &,CachedElementData *) ClientSideCacheContext::FindElement(IElementKey const &,CachedElementData *) ElementTaskList::GetElementData(IBaseCacheContext *,IElementKey const &,CachedElementData *) ... gfx::PlatformFontWin::CreateHFontRefFromSkia ... gfx::GetFallbackFonts(gfx::Font const &) From this slow-reports: 2831116d5d9b77ba (10 seconds, font fallbacks) `anonymous namespace\'::TrueTypeFontMetricsBuilder::GetBlackBox(unsigned short) `anonymous namespace\'::TrueTypeFontMetricsBuilder::GetGlyphMetrics(unsigned short) FontFaceRegionBuilder::Impl::WriteRegionInternal(MemoryWriter<PhysicalFontFaceRegion> &) FontFaceRegionBuilder::Impl::WriteRegion(MemoryWriter<PhysicalFontFaceRegion> &) FontFaceElement::AddToCacheImpl(FontLoaderManagers const &,CacheWriter &,void const * *,unsigned int *) CacheWriter::AddElement(FontLoaderManagers const &,IFontCacheElement &,unsigned int,unsigned int,void const * *,unsigned int *,bool *) From this slow-reports: 2831116d5d9b77ba (8 seconds, font fallbacks) "`anonymous namespace\'::TrueTypeFontMetricsBuilder::GetBlackBox(unsigned short) `anonymous namespace\'::TrueTypeFontMetricsBuilder::GetGlyphMetrics(unsigned short) FontFaceRegionBuilder::Impl::WriteRegionInternal(MemoryWriter<PhysicalFontFaceRegion> &) FontFaceRegionBuilder::Impl::WriteRegion(MemoryWriter<PhysicalFontFaceRegion> &) FontFaceElement::AddToCacheImpl(FontLoaderManagers const &,CacheWriter &,void const * *,unsigned int *) CacheWriter::AddElement(FontLoaderManagers const &,IFontCacheElement &,unsigned int,unsigned int,void const * *,unsigned int *,bool *) It seems to me the cache can be really slow. I google it, and I've found this: https://support.microsoft.com/en-ca/help/2505438/slow-performance-in-applications-that-use-the-directwrite-api-on-a-com " This issue occurs because the DirectWrite API starts to read font information directly from the font files and caches them directly if the FontCache service takes too long to respond. "
,
Nov 1
I assume it's related since the function names are client-side-cache. https://support.microsoft.com/en-ca/help/2505438/slow-performance-in-applications-that-use-the-directwrite-api-on-a-com ClientSideCacheContext::ClientLookup(...) ClientSideCacheContext::InitializeElementImpl(...) which implies a client side cache, and seems to point to the cause of the problem.
,
Dec 7
Looking to : FontFallback.GetLinkedFonts.CacheMissTiming The 99th percentile is still at 5 seconds. example: 1e91eb993920b7af - 35 seconds jank The code is still in the cache: FontFaceElement::AddToCacheImpl(FontLoaderManagers const &,CacheWriter &,void const * *,unsigned int *) CacheWriter::AddElement(FontLoaderManagers const &,IFontCacheElement &,unsigned int,unsigned int,void const * *,unsigned int *,bool *) ClientSideCacheContext::ClientLookup(IFontCacheElement &,unsigned int,unsigned int) ClientSideCacheContext::InitializeElementImpl(IFontCacheElement &,unsigned int,unsigned int)
,
Today
(16 hours ago)
,
Today
(16 hours ago)
|
||||||||||||
►
Sign in to add a comment |
||||||||||||
Comment 1 by etienneb@chromium.org
, Oct 11