Bug 668133 - Add telemetry probes for font enumeration, r=jtd
authorMichael Wu <mwu@mozilla.com>
Tue, 26 Jul 2011 23:42:53 -0700
changeset 74430 6eca6c29e2c044628640c2f978ef27d53d65461c
parent 74427 685b3762558c91d19580dc295e54c43a7138f911
child 74431 4d170faf61228cd902a53c6ba5719a70fef91639
push id67
push userclegnitto@mozilla.com
push dateFri, 04 Nov 2011 22:39:41 +0000
treeherdermozilla-release@04778346a3b0 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjtd
bugs668133
milestone8.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 668133 - Add telemetry probes for font enumeration, r=jtd
gfx/thebes/gfxDWriteFontList.cpp
gfx/thebes/gfxGDIFontList.cpp
gfx/thebes/gfxMacPlatformFontList.mm
gfx/thebes/gfxPlatformFontList.cpp
toolkit/components/telemetry/TelemetryHistograms.h
--- a/gfx/thebes/gfxDWriteFontList.cpp
+++ b/gfx/thebes/gfxDWriteFontList.cpp
@@ -40,39 +40,36 @@
 
 #include "gfxDWriteFontList.h"
 #include "gfxDWriteFonts.h"
 #include "nsUnicharUtils.h"
 #include "nsILocaleService.h"
 #include "nsServiceManagerUtils.h"
 #include "nsCharSeparatedTokenizer.h"
 #include "mozilla/Preferences.h"
+#include "mozilla/Telemetry.h"
 
 #include "gfxGDIFontList.h"
 
 #include "nsIWindowsRegKey.h"
 
 using namespace mozilla;
 
-#ifdef PR_LOGGING
-
 #define LOG_FONTLIST(args) PR_LOG(gfxPlatform::GetLog(eGfxLog_fontlist), \
                                PR_LOG_DEBUG, args)
 #define LOG_FONTLIST_ENABLED() PR_LOG_TEST( \
                                    gfxPlatform::GetLog(eGfxLog_fontlist), \
                                    PR_LOG_DEBUG)
 
 #define LOG_FONTINIT(args) PR_LOG(gfxPlatform::GetLog(eGfxLog_fontinit), \
                                PR_LOG_DEBUG, args)
 #define LOG_FONTINIT_ENABLED() PR_LOG_TEST( \
                                    gfxPlatform::GetLog(eGfxLog_fontinit), \
                                    PR_LOG_DEBUG)
 
-#endif // PR_LOGGING
-
 // font info loader constants
 
 // avoid doing this during startup even on slow machines but try to start
 // it soon enough so that system fallback doesn't happen first
 static const PRUint32 kDelayBeforeLoadingFonts = 120 * 1000; // 2 minutes after init
 static const PRUint32 kIntervalBetweenLoadingFonts = 2000;   // every 2 seconds until complete
 
 static __inline void
@@ -668,122 +665,113 @@ static void LogRegistryEvent(const wchar
 
 nsresult
 gfxDWriteFontList::InitFontList()
 {
     LOGREGISTRY(L"InitFontList start");
 
     mInitialized = PR_FALSE;
 
-#ifdef PR_LOGGING
     LARGE_INTEGER frequency;        // ticks per second
     LARGE_INTEGER t1, t2, t3;           // ticks
     double elapsedTime, upTime;
     char nowTime[256], nowDate[256];
 
     if (LOG_FONTINIT_ENABLED()) {    
         GetTimeFormat(LOCALE_INVARIANT, TIME_FORCE24HOURFORMAT, 
                       NULL, NULL, nowTime, 256);
         GetDateFormat(LOCALE_INVARIANT, NULL, NULL, NULL, nowDate, 256);
-        upTime = (double) GetTickCount();
-        QueryPerformanceFrequency(&frequency);
-        QueryPerformanceCounter(&t1);
     }
-#endif
+    upTime = (double) GetTickCount();
+    QueryPerformanceFrequency(&frequency);
+    QueryPerformanceCounter(&t1);
 
     HRESULT hr;
     gfxFontCache *fc = gfxFontCache::GetCache();
     if (fc) {
         fc->AgeAllGenerations();
     }
 
     mGDIFontTableAccess = Preferences::GetBool("gfx.font_rendering.directwrite.use_gdi_table_loading", PR_FALSE);
 
     gfxPlatformFontList::InitFontList();
 
     mFontSubstitutes.Clear();
     mNonExistingFonts.Clear();
 
-#ifdef PR_LOGGING
-    if (LOG_FONTINIT_ENABLED()) {
-        QueryPerformanceCounter(&t2);
-    }
-#endif
+    QueryPerformanceCounter(&t2);
 
     hr = gfxWindowsPlatform::GetPlatform()->GetDWriteFactory()->
         GetGdiInterop(getter_AddRefs(mGDIInterop));
     if (FAILED(hr)) {
         return NS_ERROR_FAILURE;
     }
 
     LOGREGISTRY(L"InitFontList end");
 
-#ifdef PR_LOGGING
+    QueryPerformanceCounter(&t3);
+
     if (LOG_FONTINIT_ENABLED()) {
-        QueryPerformanceCounter(&t3);
-
         // determine dwrite version
         nsAutoString dwriteVers;
         gfxWindowsPlatform::GetDLLVersion(L"dwrite.dll", dwriteVers);
         LOG_FONTINIT(("InitFontList\n"));
         LOG_FONTINIT(("Start: %s %s\n", nowDate, nowTime));
         LOG_FONTINIT(("Uptime: %9.3f s\n", upTime/1000));
         LOG_FONTINIT(("dwrite version: %s\n", 
                       NS_ConvertUTF16toUTF8(dwriteVers).get()));
-        elapsedTime = (t3.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
-        LOG_FONTINIT(("Total time in InitFontList:    %9.3f ms\n", elapsedTime));
-        elapsedTime = (t2.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
-        LOG_FONTINIT((" --- gfxPlatformFontList init: %9.3f ms\n", elapsedTime));
-        elapsedTime = (t3.QuadPart - t2.QuadPart) * 1000.0 / frequency.QuadPart;
-        LOG_FONTINIT((" --- GdiInterop object:        %9.3f ms\n", elapsedTime));
     }
-#endif
+
+    elapsedTime = (t3.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_INITFONTLIST_TOTAL, elapsedTime);
+    LOG_FONTINIT(("Total time in InitFontList:    %9.3f ms\n", elapsedTime));
+    elapsedTime = (t2.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_INITFONTLIST_INIT, elapsedTime);
+    LOG_FONTINIT((" --- gfxPlatformFontList init: %9.3f ms\n", elapsedTime));
+    elapsedTime = (t3.QuadPart - t2.QuadPart) * 1000.0 / frequency.QuadPart;
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_INITFONTLIST_GDI, elapsedTime);
+    LOG_FONTINIT((" --- GdiInterop object:        %9.3f ms\n", elapsedTime));
 
     return NS_OK;
 }
 
 nsresult
 gfxDWriteFontList::DelayedInitFontList()
 {
     LOGREGISTRY(L"DelayedInitFontList start");
 
-#ifdef PR_LOGGING
     LARGE_INTEGER frequency;        // ticks per second
     LARGE_INTEGER t1, t2, t3;           // ticks
     double elapsedTime, upTime;
     char nowTime[256], nowDate[256];
 
     if (LOG_FONTINIT_ENABLED()) {    
         GetTimeFormat(LOCALE_INVARIANT, TIME_FORCE24HOURFORMAT, 
                       NULL, NULL, nowTime, 256);
         GetDateFormat(LOCALE_INVARIANT, NULL, NULL, NULL, nowDate, 256);
-        upTime = (double) GetTickCount();
-        QueryPerformanceFrequency(&frequency);
-        QueryPerformanceCounter(&t1);
     }
-#endif
+
+    upTime = (double) GetTickCount();
+    QueryPerformanceFrequency(&frequency);
+    QueryPerformanceCounter(&t1);
 
     HRESULT hr;
 
     LOGREGISTRY(L"calling GetSystemFontCollection");
     nsRefPtr<IDWriteFontCollection> systemFonts;
     hr = gfxWindowsPlatform::GetPlatform()->GetDWriteFactory()->
         GetSystemFontCollection(getter_AddRefs(systemFonts));
     NS_ASSERTION(SUCCEEDED(hr), "GetSystemFontCollection failed!");
     LOGREGISTRY(L"GetSystemFontCollection done");
 
     if (FAILED(hr)) {
         return NS_ERROR_FAILURE;
     }
 
-#ifdef PR_LOGGING
-    if (LOG_FONTINIT_ENABLED()) {
-        QueryPerformanceCounter(&t2);
-    }
-#endif
+    QueryPerformanceCounter(&t2);
 
     for (UINT32 i = 0; i < systemFonts->GetFontFamilyCount(); i++) {
         nsRefPtr<IDWriteFontFamily> family;
         systemFonts->GetFontFamily(i, getter_AddRefs(family));
 
         nsRefPtr<IDWriteLocalizedStrings> names;
         hr = family->GetFamilyNames(getter_AddRefs(names));
         if (FAILED(hr)) {
@@ -960,39 +948,46 @@ gfxDWriteFontList::DelayedInitFontList()
     mForceGDIClassicMaxFontSize =
         Preferences::GetInt("gfx.font_rendering.cleartype_params.force_gdi_classic_max_size",
                             mForceGDIClassicMaxFontSize);
 
     StartLoader(kDelayBeforeLoadingFonts, kIntervalBetweenLoadingFonts);
 
     LOGREGISTRY(L"DelayedInitFontList end");
 
-#ifdef PR_LOGGING
+    QueryPerformanceCounter(&t3);
+
     if (LOG_FONTINIT_ENABLED()) {
-        QueryPerformanceCounter(&t3);
-
         // determine dwrite version
         nsAutoString dwriteVers;
         gfxWindowsPlatform::GetDLLVersion(L"dwrite.dll", dwriteVers);
         LOG_FONTINIT(("DelayedInitFontList\n"));
         LOG_FONTINIT(("Start: %s %s\n", nowDate, nowTime));
         LOG_FONTINIT(("Uptime: %9.3f s\n", upTime/1000));
         LOG_FONTINIT(("dwrite version: %s\n", 
                       NS_ConvertUTF16toUTF8(dwriteVers).get()));
-        elapsedTime = (t3.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
-        LOG_FONTINIT((
-          "Total time in DelayedInitFontList:    %9.3f ms (families: %d, %s)\n",
-          elapsedTime, systemFonts->GetFontFamilyCount(),
-          (mGDIFontTableAccess ? "gdi table access" : "dwrite table access")));
-        elapsedTime = (t2.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
-        LOG_FONTINIT((" --- GetSystemFontCollection:  %9.3f ms\n", elapsedTime));
-        elapsedTime = (t3.QuadPart - t2.QuadPart) * 1000.0 / frequency.QuadPart;
-        LOG_FONTINIT((" --- iterate over families:    %9.3f ms\n", elapsedTime));
     }
-#endif
+
+    elapsedTime = (t3.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_DELAYEDINITFONTLIST_TOTAL, elapsedTime);
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_DELAYEDINITFONTLIST_COUNT,
+                          systemFonts->GetFontFamilyCount());
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_DELAYEDINITFONTLIST_GDI_TABLE, mGDIFontTableAccess);
+    LOG_FONTINIT((
+       "Total time in DelayedInitFontList:    %9.3f ms (families: %d, %s)\n",
+       elapsedTime, systemFonts->GetFontFamilyCount(),
+       (mGDIFontTableAccess ? "gdi table access" : "dwrite table access")));
+
+    elapsedTime = (t2.QuadPart - t1.QuadPart) * 1000.0 / frequency.QuadPart;
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_DELAYEDINITFONTLIST_COLLECT, elapsedTime);
+    LOG_FONTINIT((" --- GetSystemFontCollection:  %9.3f ms\n", elapsedTime));
+
+    elapsedTime = (t3.QuadPart - t2.QuadPart) * 1000.0 / frequency.QuadPart;
+    Telemetry::Accumulate(Telemetry::DWRITEFONT_DELAYEDINITFONTLIST_ITERATE, elapsedTime);
+    LOG_FONTINIT((" --- iterate over families:    %9.3f ms\n", elapsedTime));
 
     return NS_OK;
 }
 
 static void
 RemoveCharsetFromFontSubstitute(nsAString &aName)
 {
     PRInt32 comma = aName.FindChar(PRUnichar(','));
--- a/gfx/thebes/gfxGDIFontList.cpp
+++ b/gfx/thebes/gfxGDIFontList.cpp
@@ -55,18 +55,22 @@
 #include "nsUnicharUtils.h"
 
 #include "nsDirectoryServiceUtils.h"
 #include "nsDirectoryServiceDefs.h"
 #include "nsAppDirectoryServiceDefs.h"
 #include "nsISimpleEnumerator.h"
 #include "nsIWindowsRegKey.h"
 
+#include "mozilla/Telemetry.h"
+
 #include <usp10.h>
 
+using namespace mozilla;
+
 #define ROUND(x) floor((x) + 0.5)
 
 
 #ifndef CLEARTYPE_QUALITY
 #define CLEARTYPE_QUALITY 5
 #endif
 
 #ifdef PR_LOGGING
@@ -643,16 +647,17 @@ gfxGDIFontList::GetFontSubstitutes()
         }
     }
     return NS_OK;
 }
 
 nsresult
 gfxGDIFontList::InitFontList()
 {
+    Telemetry::AutoTimer<Telemetry::GDI_INITFONTLIST_TOTAL> timer;
     gfxFontCache *fc = gfxFontCache::GetCache();
     if (fc)
         fc->AgeAllGenerations();
 
     // reset font lists
     gfxPlatformFontList::InitFontList();
     
     mFontSubstitutes.Clear();
--- a/gfx/thebes/gfxMacPlatformFontList.mm
+++ b/gfx/thebes/gfxMacPlatformFontList.mm
@@ -54,19 +54,23 @@
 
 #include "nsServiceManagerUtils.h"
 #include "nsTArray.h"
 
 #include "nsDirectoryServiceUtils.h"
 #include "nsDirectoryServiceDefs.h"
 #include "nsISimpleEnumerator.h"
 
+#include "mozilla/Telemetry.h"
+
 #include <unistd.h>
 #include <time.h>
 
+using namespace mozilla;
+
 class nsAutoreleasePool {
 public:
     nsAutoreleasePool()
     {
         mLocalPool = [[NSAutoreleasePool alloc] init];
     }
     ~nsAutoreleasePool()
     {
@@ -712,16 +716,18 @@ gfxMacPlatformFontList::InitFontList()
     nsAutoreleasePool localPool;
 
     ATSGeneration currentGeneration = ::ATSGetGeneration();
 
     // need to ignore notifications after adding each font
     if (mATSGeneration == currentGeneration)
         return NS_OK;
 
+    Telemetry::AutoTimer<Telemetry::MAC_INITFONTLIST_TOTAL> timer;
+
     mATSGeneration = currentGeneration;
 #ifdef PR_LOGGING
     LOG_FONTLIST(("(fontlist) updating to generation: %d", mATSGeneration));
 #endif
 
     // reset font lists
     gfxPlatformFontList::InitFontList();
     
--- a/gfx/thebes/gfxPlatformFontList.cpp
+++ b/gfx/thebes/gfxPlatformFontList.cpp
@@ -72,16 +72,17 @@
 #include "gfxPlatformFontList.h"
 #include "gfxTextRunWordCache.h"
 
 #include "nsUnicharUtils.h"
 #include "nsUnicodeRange.h"
 #include "gfxUnicodeProperties.h"
 
 #include "mozilla/Preferences.h"
+#include "mozilla/Telemetry.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
 
@@ -194,16 +195,17 @@ gfxPlatformFontList::GenerateFontListKey
     ToLowerCase(aResult);
 }
 
 void 
 gfxPlatformFontList::InitOtherFamilyNames()
 {
     mOtherFamilyNamesInitialized = PR_TRUE;
 
+    Telemetry::AutoTimer<Telemetry::FONTLIST_INITOTHERFAMILYNAMES> timer;
     // iterate over all font families and read in other family names
     mFontFamilies.Enumerate(gfxPlatformFontList::InitOtherFamilyNamesProc, this);
 }
                                                          
 PLDHashOperator PR_CALLBACK
 gfxPlatformFontList::InitOtherFamilyNamesProc(nsStringHashKey::KeyType aKey,
                                               nsRefPtr<gfxFontFamily>& aFamilyEntry,
                                               void* userArg)
@@ -214,16 +216,17 @@ gfxPlatformFontList::InitOtherFamilyName
 }
 
 void
 gfxPlatformFontList::InitFaceNameLists()
 {
     mFaceNamesInitialized = PR_TRUE;
 
     // iterate over all font families and read in other family names
+    Telemetry::AutoTimer<Telemetry::FONTLIST_INITFACENAMELISTS> timer;
     mFontFamilies.Enumerate(gfxPlatformFontList::InitFaceNameListsProc, this);
 }
 
 PLDHashOperator PR_CALLBACK
 gfxPlatformFontList::InitFaceNameListsProc(nsStringHashKey::KeyType aKey,
                                            nsRefPtr<gfxFontFamily>& aFamilyEntry,
                                            void* userArg)
 {
--- a/toolkit/components/telemetry/TelemetryHistograms.h
+++ b/toolkit/components/telemetry/TelemetryHistograms.h
@@ -61,16 +61,31 @@ HISTOGRAM(EARLY_GLUESTARTUP_READ_OPS, 1,
 HISTOGRAM(EARLY_GLUESTARTUP_READ_TRANSFER, 1, 50 * 1024, 12, EXPONENTIAL, "ProcessIoCounters.ReadTransferCount before glue startup (KB)")
 HISTOGRAM(GLUESTARTUP_READ_OPS, 1, 100, 12, LINEAR, "ProcessIoCounters.ReadOperationCount after glue startup")
 HISTOGRAM(GLUESTARTUP_READ_TRANSFER, 1, 50 * 1024, 12, EXPONENTIAL, "ProcessIoCounters.ReadTransferCount after glue startup (KB)")
 #elif defined(XP_UNIX)
 HISTOGRAM(EARLY_GLUESTARTUP_HARD_FAULTS, 1, 100, 12, LINEAR, "Hard faults count before glue startup")
 HISTOGRAM(GLUESTARTUP_HARD_FAULTS, 1, 500, 12, EXPONENTIAL, "Hard faults count after glue startup")
 HISTOGRAM(PAGE_FAULTS_HARD, 8, 64 * 1024, 13, EXPONENTIAL, "Hard page faults (since last telemetry ping)")
 #endif
+HISTOGRAM(FONTLIST_INITOTHERFAMILYNAMES, 1, 30000, 50, EXPONENTIAL, "Time(ms) spent on reading other family names from all fonts")
+HISTOGRAM(FONTLIST_INITFACENAMELISTS, 1, 30000, 50, EXPONENTIAL, "Time(ms) spent on reading family names from all fonts")
+#if defined(XP_WIN)
+HISTOGRAM(DWRITEFONT_INITFONTLIST_TOTAL, 1, 30000, 10, EXPONENTIAL, "gfxDWriteFontList::InitFontList Total (ms)")
+HISTOGRAM(DWRITEFONT_INITFONTLIST_INIT, 1, 30000, 10, EXPONENTIAL, "gfxDWriteFontList::InitFontList init (ms)")
+HISTOGRAM(DWRITEFONT_INITFONTLIST_GDI, 1, 30000, 10, EXPONENTIAL, "gfxDWriteFontList::InitFontList GdiInterop object (ms)")
+HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_TOTAL, 1, 30000, 10, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList Total (ms)")
+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(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)")
 
 /**
  * Networking telemetry
  */
 HISTOGRAM(TOTAL_CONTENT_PAGE_LOAD_TIME, 100, 10000, 100, EXPONENTIAL, "HTTP: Total page load time (ms)")