Bug 705590. Measure system font fallback times. r=jrmuizel
authorJohn Daggett <jdaggett@mozilla.com>
Wed, 30 Nov 2011 10:55:11 +0900
changeset 82619 a36ee10d4f5da17faa57585a611d6b2b24366482
parent 82618 47500d6cbffd73121223dd637ddb29d244b8fb11
child 82620 3c716afd37a7c4a9e0efcb297cbb8d7cff93c872
push id519
push userakeybl@mozilla.com
push dateWed, 01 Feb 2012 00:38:35 +0000
treeherdermozilla-beta@788ea1ef610b [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjrmuizel
bugs705590
milestone11.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 705590. Measure system font fallback times. r=jrmuizel
gfx/thebes/gfxPlatformFontList.cpp
toolkit/components/telemetry/TelemetryHistograms.h
--- a/gfx/thebes/gfxPlatformFontList.cpp
+++ b/gfx/thebes/gfxPlatformFontList.cpp
@@ -73,16 +73,17 @@
 #include "gfxTextRunWordCache.h"
 
 #include "nsUnicharUtils.h"
 #include "nsUnicodeRange.h"
 #include "gfxUnicodeProperties.h"
 
 #include "mozilla/Preferences.h"
 #include "mozilla/Telemetry.h"
+#include "mozilla/TimeStamp.h"
 
 using namespace mozilla;
 
 // font info loader constants
 static const PRUint32 kDelayBeforeLoadingCmaps = 8 * 1000; // 8secs
 static const PRUint32 kIntervalBetweenLoadingCmaps = 150; // 150ms
 static const PRUint32 kNumFontsPerSlice = 10; // read in info 10 fonts at a time
 
@@ -401,47 +402,61 @@ gfxPlatformFontList::FindFontForChar(con
             gfxFontStyle normalStyle;
             fontEntry = FindFontForFamily(mReplacementCharFallbackFamily, &normalStyle, needsBold);
         }
 
         if (fontEntry && fontEntry->TestCharacterMap(aCh))
             return fontEntry;
     }
 
+    static bool first = true;
+    TimeStamp start = TimeStamp::Now();
+
     FontSearch data(aCh, aPrevFont);
 
     // iterate over all font families to find a font that support the character
     mFontFamilies.Enumerate(gfxPlatformFontList::FindFontForCharProc, &data);
 
+    TimeDuration elapsed = TimeStamp::Now() - start;
+
 #ifdef PR_LOGGING
     PRLogModuleInfo *log = gfxPlatform::GetLog(eGfxLog_textrun);
 
     if (NS_UNLIKELY(log)) {
         PRUint32 charRange = gfxFontUtils::CharRangeBit(aCh);
         PRUint32 unicodeRange = FindCharUnicodeRange(aCh);
         PRUint32 hbscript = gfxUnicodeProperties::GetScriptCode(aCh);
         PR_LOG(log, PR_LOG_DEBUG,\
                ("(textrun-systemfallback) char: u+%6.6x "
-                "char-range: %d unicode-range: %d script: %d match: [%s] count: %d\n",
+                "char-range: %d unicode-range: %d script: %d match: [%s]"
+                " count: %d time: %dus\n",
                 aCh,
                 charRange, unicodeRange, hbscript,
                 (data.mBestMatch ?
                  NS_ConvertUTF16toUTF8(data.mBestMatch->Name()).get() :
                  "<none>"),
-                data.mCount));
+                data.mCount,
+                PRInt32(elapsed.ToMicroseconds())));
     }
 #endif
 
     // no match? add to set of non-matching codepoints
     if (!data.mBestMatch) {
         mCodepointsWithNoFonts.set(aCh);
     } else if (aCh == 0xFFFD) {
         mReplacementCharFallbackFamily = data.mBestMatch->FamilyName();
     }
 
+    PRInt32 intElapsed = PRInt32(first ? elapsed.ToMilliseconds() :
+                                         elapsed.ToMicroseconds());
+    Telemetry::Accumulate((first ? Telemetry::SYSTEM_FONT_FALLBACK_FIRST :
+                                   Telemetry::SYSTEM_FONT_FALLBACK),
+                          intElapsed);
+    first = false;
+
     return data.mBestMatch;
 }
 
 PLDHashOperator PR_CALLBACK 
 gfxPlatformFontList::FindFontForCharProc(nsStringHashKey::KeyType aKey, nsRefPtr<gfxFontFamily>& aFamilyEntry,
      void *userArg)
 {
     FontSearch *data = static_cast<FontSearch*>(userArg);
--- a/toolkit/components/telemetry/TelemetryHistograms.h
+++ b/toolkit/components/telemetry/TelemetryHistograms.h
@@ -107,16 +107,20 @@ HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST
 HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_COUNT, 1, 10000, 10, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList Font Family Count")
 HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_GDI_TABLE, 0, 1, 2, BOOLEAN, "gfxDWriteFontList::DelayedInitFontList GDI Table Access")
 HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_COLLECT, 1, 30000, 10, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList GetSystemFontCollection (ms)")
 HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_ITERATE, 1, 30000, 10, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList iterate over families (ms)")
 HISTOGRAM(GDI_INITFONTLIST_TOTAL, 1, 30000, 10, EXPONENTIAL, "gfxGDIFontList::InitFontList Total (ms)")
 #elif defined(XP_MACOSX)
 HISTOGRAM(MAC_INITFONTLIST_TOTAL, 1, 30000, 10, EXPONENTIAL, "gfxMacPlatformFontList::InitFontList Total (ms)")
 #endif
+
+HISTOGRAM(SYSTEM_FONT_FALLBACK, 1, 100000, 50, EXPONENTIAL, "System font fallback (us)")
+HISTOGRAM(SYSTEM_FONT_FALLBACK_FIRST, 1, 40000, 20, EXPONENTIAL, "System font fallback, first call (ms)")
+
 HISTOGRAM(SHUTDOWN_OK, 0, 1, 2, BOOLEAN, "Did the browser start after a successful shutdown")
 
 HISTOGRAM(IMAGE_DECODE_LATENCY, 50,  5000000, 100, EXPONENTIAL, "Time spent decoding an image chunk (us)")
 HISTOGRAM(IMAGE_DECODE_TIME,    50, 50000000, 100, EXPONENTIAL, "Time spent decoding an image (us)")
 HISTOGRAM(IMAGE_DECODE_ON_DRAW_LATENCY,  50, 50000000, 100, EXPONENTIAL, "Time from starting a decode to it showing up on the screen (us)")
 HISTOGRAM(IMAGE_DECODE_CHUNKS, 1,  500, 50, EXPONENTIAL, "Number of chunks per decode attempt")
 HISTOGRAM(IMAGE_DECODE_COUNT, 1,  500, 50, EXPONENTIAL, "Decode count")
 HISTOGRAM(IMAGE_DECODE_SPEED_JPEG, 500, 50000000,  50, EXPONENTIAL, "JPEG image decode speed (Kbytes/sec)")