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/1302865Reviewed-by: Alexei Svitkine <asvitkine@chromium.org>
Commit-Queue: Etienne Bergeron <etienneb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#603345}

ui/gfx/font_fallback_win.cc

@@ -19,7 +19,9 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_util.h"
+#include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
+#include "base/trace_event/trace_event.h"
 #include "base/win/registry.h"
 #include "ui/gfx/font.h"
 #include "ui/gfx/font_fallback.h"
@@ -77,6 +79,7 @@ void AppendFont(const std::string& name, int size, std::vector<Font>* fonts) {
 void QueryLinkedFontsFromRegistry(const Font& font,
                                   std::map<std::string, std::string>* font_map,
                                   std::vector<Font>* linked_fonts) {
+  std::string logging_str;
   const wchar_t* kSystemLink =
       L"Software\\Microsoft\\Windows NT\\CurrentVersion\\FontLink\\SystemLink";
 
@@ -91,11 +94,18 @@ void QueryLinkedFontsFromRegistry(const Font& font,
     return;
   }
 
+  base::StringAppendF(&logging_str, "Original font: %s\n",
+                      font.GetFontName().c_str());
+
   std::string filename;
   std::string font_name;
   for (size_t i = 0; i < values.size(); ++i) {
     internal::ParseFontLinkEntry(
         base::WideToUTF8(values[i]), &filename, &font_name);
+
+    base::StringAppendF(&logging_str, "fallback: '%s' '%s'\n",
+                        font_name.c_str(), filename.c_str());
+
     // If the font name is present, add that directly, otherwise add the
     // font names corresponding to the filename.
     if (!font_name.empty()) {
@@ -109,6 +119,13 @@ void QueryLinkedFontsFromRegistry(const Font& font,
   }
 
   key.Close();
+
+  for (const auto& resolved_font : *linked_fonts) {
+    base::StringAppendF(&logging_str, "resolved: '%s'\n",
+                        resolved_font.GetFontName().c_str());
+  }
+
+  TRACE_EVENT1("ui", "QueryLinkedFontsFromRegistry", "results", logging_str);
 }
 
 // CachedFontLinkSettings is a singleton cache of the Windows font settings
@@ -153,6 +170,9 @@ const std::vector<Font>* CachedFontLinkSettings::GetLinkedFonts(
   if (it != cached_linked_fonts_.end())
     return &it->second;
 
+  TRACE_EVENT1("ui", "CachedFontLinkSettings::GetLinkedFonts", "font_name",
+               font_name);
+
   SCOPED_UMA_HISTOGRAM_LONG_TIMER(
       "FontFallback.GetLinkedFonts.CacheMissTiming");
   std::vector<Font>* linked_fonts = &cached_linked_fonts_[font_name];