WebFonts: measure network loading time

third_party/WebKit/Source/core/css/RemoteFontFaceSource.cpp

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "core/css/RemoteFontFaceSource.h"
 
 #include "core/css/CSSCustomFontData.h"
 #include "core/css/CSSFontFace.h"
 #include "core/css/CSSFontSelector.h"
 #include "core/dom/Document.h"
 #include "core/fetch/ResourceFetcher.h"
 #include "core/inspector/ConsoleMessage.h"
 #include "core/loader/FrameLoaderClient.h"
 #include "core/page/NetworkStateNotifier.h"
 #include "platform/Histogram.h"
 #include "platform/RuntimeEnabledFeatures.h"
 #include "platform/fonts/FontCache.h"
 #include "platform/fonts/FontDescription.h"
 #include "platform/fonts/SimpleFontData.h"
 #include "public/platform/WebEffectiveConnectionType.h"
 #include "wtf/CurrentTime.h"
 
 namespace blink {
 
 namespace {
 
+// Should not change following enum order to be used for metrics values.
+enum CacheHitMetrics {
+    Miss,
+    DiskHit,
+    DataUrl,
+    MemoryHit,
+    CacheHitEnumMax
+};
+
+CacheHitMetrics getMetricsValue(RemoteFontFaceSource::DataSource dataSource)
+{
+    switch (dataSource) {
+    case RemoteFontFaceSource::FromDataURL:
+        return DataUrl;
+    case RemoteFontFaceSource::FromMemoryCache:
+        return MemoryHit;
+    case RemoteFontFaceSource::FromDiskCache:
+        return DiskHit;
+    case RemoteFontFaceSource::FromNetwork:
+        return Miss;
+    case RemoteFontFaceSource::FromUnknown:
+        // Still loading implies coming from network.

[Kunihiko Sakamoto, 2016/09/06 18:04:53]

Having this logic in this conversion function feels a bit weird...
Can we just call NOTREACHED() here?

[Takashi Toyoshima, 2016/09/07 08:49:08]

Done.

+        return Miss;
+    default:
+        NOTREACHED();
+    }
+    return Miss;
+}
+
 bool isEffectiveConnectionTypeSlowFor(Document* document)
 {
     WebEffectiveConnectionType type = document->frame()->loader().client()->getEffectiveConnectionType();
 
     WebEffectiveConnectionType thresholdType = RuntimeEnabledFeatures::webFontsInterventionV2With2GEnabled()
         ? WebEffectiveConnectionType::Type2G
         : WebEffectiveConnectionType::TypeSlow2G;
 
     return WebEffectiveConnectionType::TypeOffline <= type && type <= thresholdType;
 }
 
 bool isConnectionTypeSlow()
 {
     return networkStateNotifier().connectionType() == WebConnectionTypeCellular2G;
 }
 
-bool shouldTriggerWebFontsIntervention(Document* document, FontDisplay display, bool isLoadedFromMemoryCache, bool isLoadedFromDataURL)
+bool shouldTriggerWebFontsIntervention(Document* document, FontDisplay display, RemoteFontFaceSource::DataSource dataSource)

[Kunihiko Sakamoto, 2016/09/06 18:04:53]

Maybe make this a private member function of RemoteFonTaceSource, so
m_dataSource can be accessed directly.

[Takashi Toyoshima, 2016/09/07 08:49:08]

Hum... I'm neutral on this, but I'd rather consider to have dataSource inside
FontLoadHistograms since this is a state used for metrics. I didn't do so
because dataSource is used outside the inner class, here. But probably I can
write it in a reasonable way.

[Kunihiko Sakamoto, 2016/09/07 16:25:42]

ok, sgtm.

 {
     if (RuntimeEnabledFeatures::webFontsInterventionTriggerEnabled())
         return true;
-    if (isLoadedFromMemoryCache || isLoadedFromDataURL)
+    if (dataSource == RemoteFontFaceSource::FromMemoryCache || dataSource == RemoteFontFaceSource::FromDataURL)
         return false;
 
     bool isV2Enabled = RuntimeEnabledFeatures::webFontsInterventionV2With2GEnabled() || RuntimeEnabledFeatures::webFontsInterventionV2WithSlow2GEnabled();
 
     bool networkIsSlow = isV2Enabled ? isEffectiveConnectionTypeSlowFor(document) : isConnectionTypeSlow();
 
     return networkIsSlow && display == FontDisplayAuto;
 }
 
 } // namespace
 
 RemoteFontFaceSource::RemoteFontFaceSource(FontResource* font, CSSFontSelector* fontSelector, FontDisplay display)
     : m_font(font)
     , m_fontSelector(fontSelector)
     , m_display(display)
     , m_period(display == FontDisplaySwap ? SwapPeriod : BlockPeriod)
     , m_isInterventionTriggered(false)
-    , m_isLoadedFromMemoryCache(font->isLoaded())
+    , m_dataSource(font->url().protocolIsData() ? FromDataURL : font->isLoaded() ? FromMemoryCache : FromUnknown)
 {
     ThreadState::current()->registerPreFinalizer(this);
     m_font->addClient(this);
 
-    if (shouldTriggerWebFontsIntervention(m_fontSelector->document(), display, m_isLoadedFromMemoryCache, m_font->url().protocolIsData())) {
-
+    if (shouldTriggerWebFontsIntervention(m_fontSelector->document(), display, m_dataSource)) {
         m_isInterventionTriggered = true;
         m_period = SwapPeriod;
         m_fontSelector->document()->addConsoleMessage(ConsoleMessage::create(OtherMessageSource, InfoMessageLevel, "Slow network is detected. Fallback font will be used while loading: " + m_font->url().elidedString()));
     }
 }
 
 RemoteFontFaceSource::~RemoteFontFaceSource()
 {
 }
 
@@ skipping 27 matching lines @@
     return m_font->isLoaded();
 }
 
 bool RemoteFontFaceSource::isValid() const
 {
     return !m_font->errorOccurred();
 }
 
 void RemoteFontFaceSource::notifyFinished(Resource*)
 {
-    m_histograms.recordRemoteFont(m_font.get(), m_isLoadedFromMemoryCache);
-    m_histograms.fontLoaded(m_isInterventionTriggered, !m_isLoadedFromMemoryCache && !m_font->url().protocolIsData() && !m_font->response().wasCached());
+    if (m_dataSource == FromUnknown)
+        m_dataSource = m_font->response().wasCached() ? FromDiskCache : FromNetwork;
+    m_histograms.recordRemoteFont(m_font.get(), m_dataSource);
+    m_histograms.fontLoaded(m_isInterventionTriggered, m_dataSource);
 
     m_font->ensureCustomFontData();
     // FIXME: Provide more useful message such as OTS rejection reason.
     // See crbug.com/97467
     if (m_font->getStatus() == Resource::DecodeError && m_fontSelector->document()) {
         m_fontSelector->document()->addConsoleMessage(ConsoleMessage::create(OtherMessageSource, WarningMessageLevel, "Failed to decode downloaded font: " + m_font->url().elidedString()));
         if (m_font->otsParsingMessage().length() > 1)
             m_fontSelector->document()->addConsoleMessage(ConsoleMessage::create(OtherMessageSource, WarningMessageLevel, "OTS parsing error: " + m_font->otsParsingMessage()));
     }
 
     pruneTable();
     if (m_face) {
         m_fontSelector->fontFaceInvalidated();
         m_face->fontLoaded(this);
     }
     // Should not do anything after this line since the m_face->fontLoaded()
     // above may trigger deleting this object.
 }
 
 void RemoteFontFaceSource::fontLoadShortLimitExceeded(FontResource*)
 {
     if (m_display == FontDisplayFallback)
         switchToSwapPeriod();
     else if (m_display == FontDisplayOptional)
         switchToFailurePeriod();
 }
 
 void RemoteFontFaceSource::fontLoadLongLimitExceeded(FontResource*)
 {

[Kunihiko Sakamoto, 2016/09/06 18:04:53]

How about having

if (m_dataSource == FromUnknown) m_dataSource = FromNetwork;

here? So you don't need to write the logic of "consider Unknown as FromNetwork"
in multiple places.

[Takashi Toyoshima, 2016/09/07 08:49:08]

Move it inside longLimigExceeded() to have the member inside the inner class.

     if (m_display == FontDisplayBlock || (!m_isInterventionTriggered && m_display == FontDisplayAuto))
         switchToSwapPeriod();
     else if (m_display == FontDisplayFallback)
         switchToFailurePeriod();
 
-    m_histograms.longLimitExceeded(m_isInterventionTriggered);
+    m_histograms.longLimitExceeded(m_isInterventionTriggered, m_dataSource);
 }
 
 void RemoteFontFaceSource::switchToSwapPeriod()
 {
     ASSERT(m_period == BlockPeriod);
     m_period = SwapPeriod;
 
     pruneTable();
     if (m_face) {
         m_fontSelector->fontFaceInvalidated();
@@ skipping 65 matching lines @@
     if (!m_loadStartTime)
         m_loadStartTime = currentTimeMS();
 }
 
 void RemoteFontFaceSource::FontLoadHistograms::fallbackFontPainted(DisplayPeriod period)
 {
     if (period == BlockPeriod && !m_blankPaintTime)
         m_blankPaintTime = currentTimeMS();
 }
 
-void RemoteFontFaceSource::FontLoadHistograms::fontLoaded(bool isInterventionTriggered, bool isLoadedFromNetwork)
+void RemoteFontFaceSource::FontLoadHistograms::fontLoaded(bool isInterventionTriggered, DataSource dataSource)
 {
     if (!m_isLongLimitExceeded)
-        recordInterventionResult(isInterventionTriggered, isLoadedFromNetwork);
+        recordInterventionResult(isInterventionTriggered, dataSource);
 }
 
-void RemoteFontFaceSource::FontLoadHistograms::longLimitExceeded(bool isInterventionTriggered)
+void RemoteFontFaceSource::FontLoadHistograms::longLimitExceeded(bool isInterventionTriggered, DataSource dataSource)
 {
     m_isLongLimitExceeded = true;
-    recordInterventionResult(isInterventionTriggered, true);
+    recordInterventionResult(isInterventionTriggered, dataSource);
 }
 
 void RemoteFontFaceSource::FontLoadHistograms::recordFallbackTime(const FontResource* font)
 {
     if (m_blankPaintTime <= 0)
         return;
     int duration = static_cast<int>(currentTimeMS() - m_blankPaintTime);
     DEFINE_STATIC_LOCAL(CustomCountHistogram, blankTextShownTimeHistogram, ("WebFont.BlankTextShownTime", 0, 10000, 50));
     blankTextShownTimeHistogram.count(duration);
     m_blankPaintTime = -1;
 }
 
-void RemoteFontFaceSource::FontLoadHistograms::recordRemoteFont(const FontResource* font, bool isLoadedFromMemoryCache)
+void RemoteFontFaceSource::FontLoadHistograms::recordRemoteFont(const FontResource* font, DataSource dataSource)
 {
     if (m_loadStartTime > 0 && font && !font->isLoading()) {
+        enum { Miss, DiskHit, DataUrl, MemoryHit, CacheHitEnumMax };
+        int cacheHitValue = getMetricsValue(dataSource);
+        DEFINE_STATIC_LOCAL(EnumerationHistogram, cacheHitHistogram, ("WebFont.CacheHit", CacheHitEnumMax));
+        cacheHitHistogram.count(cacheHitValue);

[Kunihiko Sakamoto, 2016/09/06 18:04:53]

Call getMetricsValue() here and remove cacheHitValue variable?

[Takashi Toyoshima, 2016/09/07 08:49:09]

Done.

+
         int duration = static_cast<int>(currentTimeMS() - m_loadStartTime);
-        recordLoadTimeHistogram(font, duration);
+        recordLoadTimeHistogram(font, duration, dataSource);
         m_loadStartTime = -1;
 
-        enum { Miss, DiskHit, DataUrl, MemoryHit, CacheHitEnumMax };
-        int histogramValue = font->url().protocolIsData() ? DataUrl
-            : isLoadedFromMemoryCache ? MemoryHit
-            : font->response().wasCached() ? DiskHit
-            : Miss;
-        DEFINE_STATIC_LOCAL(EnumerationHistogram, cacheHitHistogram, ("WebFont.CacheHit", CacheHitEnumMax));
-        cacheHitHistogram.count(histogramValue);
-
         enum { CORSFail, CORSSuccess, CORSEnumMax };
         int corsValue = font->isCORSFailed() ? CORSFail : CORSSuccess;
         DEFINE_STATIC_LOCAL(EnumerationHistogram, corsHistogram, ("WebFont.CORSSuccess", CORSEnumMax));
         corsHistogram.count(corsValue);
     }
 }
 
-void RemoteFontFaceSource::FontLoadHistograms::recordLoadTimeHistogram(const FontResource* font, int duration)
+void RemoteFontFaceSource::FontLoadHistograms::recordLoadTimeHistogram(const FontResource* font, int duration, DataSource dataSource)
 {
     if (font->errorOccurred()) {
         DEFINE_STATIC_LOCAL(CustomCountHistogram, loadErrorHistogram, ("WebFont.DownloadTime.LoadError", 0, 10000, 50));
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, missedCacheLoadErrorHistogram, ("WebFont.MissedCache.DownloadTime.LoadError", 0, 10000, 50));

[Takashi Toyoshima, 2016/09/07 08:49:08]

Also, I'd say there is another requirement to have another variant,
HitDiskCache. sakamoto-san, could you follow mail thread I forwarded?

[Kunihiko Sakamoto, 2016/09/07 16:25:42]

Yeah I'm following the thread, and I agree we need cache-hit variant. I have
some questions:

- Should we add separate histogram(s) for DiskCacheHit and MemoryCacheHit?
- Breakdown by font size is needed?
- Can we deprecate existing cache-unaware histogram in favor of new ones?

[Takashi Toyoshima, 2016/09/09 06:25:24]

Good point.
If data comes from memory cache or data URL, we can have data on constructor.
That means load time is always 0. So, I think we don't need separate one for
MemoryCacheHit.

- Breakdown by font size is needed?

Probably yes for disk cache. Our current result implies it may have a wide
distribution.


- Can we deprecate existing cache-unaware histogram in favor of new ones?

Agreed. At some point, when we understand cache hit rate and loadtime for each
correctly, we won't need this (we can calculate it indirectly)

         loadErrorHistogram.count(duration);
+        if (dataSource == FromNetwork)
+            missedCacheLoadErrorHistogram.count(duration);
         return;
     }
 
     unsigned size = font->encodedSize();
     if (size < 10 * 1024) {
         DEFINE_STATIC_LOCAL(CustomCountHistogram, under10kHistogram, ("WebFont.DownloadTime.0.Under10KB", 0, 10000, 50));
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, missedCacheUnder10kHistogram, ("WebFont.MissedCache.DownloadTime.0.Under10KB", 0, 10000, 50));
         under10kHistogram.count(duration);
+        if (dataSource == FromNetwork)
+            missedCacheUnder10kHistogram.count(duration);
         return;
     }
     if (size < 50 * 1024) {
         DEFINE_STATIC_LOCAL(CustomCountHistogram, under50kHistogram, ("WebFont.DownloadTime.1.10KBTo50KB", 0, 10000, 50));
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, missedCacheUnder50kHistogram, ("WebFont.MissedCache.DownloadTime.1.10KBTo50KB", 0, 10000, 50));
         under50kHistogram.count(duration);
+        if (dataSource == FromNetwork)
+            missedCacheUnder50kHistogram.count(duration);
         return;
     }
     if (size < 100 * 1024) {
         DEFINE_STATIC_LOCAL(CustomCountHistogram, under100kHistogram, ("WebFont.DownloadTime.2.50KBTo100KB", 0, 10000, 50));
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, missedCacheUnder100kHistogram, ("WebFont.MissedCache.DownloadTime.2.50KBTo100KB", 0, 10000, 50));
         under100kHistogram.count(duration);
+        if (dataSource == FromNetwork)
+            missedCacheUnder100kHistogram.count(duration);
         return;
     }
     if (size < 1024 * 1024) {
         DEFINE_STATIC_LOCAL(CustomCountHistogram, under1mbHistogram, ("WebFont.DownloadTime.3.100KBTo1MB", 0, 10000, 50));
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, missedCacheUnder1mbHistogram, ("WebFont.MissedCache.DownloadTime.3.100KBTo1MB", 0, 10000, 50));
         under1mbHistogram.count(duration);
+        if (dataSource == FromNetwork)
+            missedCacheUnder1mbHistogram.count(duration);
         return;
     }
     DEFINE_STATIC_LOCAL(CustomCountHistogram, over1mbHistogram, ("WebFont.DownloadTime.4.Over1MB", 0, 10000, 50));
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, missedCacheOver1mbHistogram, ("WebFont.MissedCache.DownloadTime.4.Over1MB", 0, 10000, 50));
     over1mbHistogram.count(duration);
+    if (dataSource == FromNetwork)
+        missedCacheOver1mbHistogram.count(duration);
 }
 
-void RemoteFontFaceSource::FontLoadHistograms::recordInterventionResult(bool isTriggered, bool isLoadedFromNetwork)
+void RemoteFontFaceSource::FontLoadHistograms::recordInterventionResult(bool isTriggered, DataSource dataSource)
 {
     // interventionResult takes 0-3 values.
     int interventionResult = 0;
     if (m_isLongLimitExceeded)
         interventionResult |= 1 << 0;
     if (isTriggered)
         interventionResult |= 1 << 1;
     const int boundary = 1 << 2;
 
     DEFINE_STATIC_LOCAL(EnumerationHistogram, interventionHistogram, ("WebFont.InterventionResult", boundary));
     DEFINE_STATIC_LOCAL(EnumerationHistogram, missedCacheInterventionHistogram, ("WebFont.InterventionResult.MissedCache", boundary));
     interventionHistogram.count(interventionResult);
-    if (isLoadedFromNetwork)
+    if (dataSource == FromNetwork || dataSource == FromUnknown)
         missedCacheInterventionHistogram.count(interventionResult);
 }
 
 } // namespace blink