668133 - Add telemetry probes for font enumeration

Status: RESOLVED FIXED

(Core :: Graphics, defect)

Comment 1

[Michael Wu [:mwu]]

Attachment: Add font probes

This seems to work for dwrite, at least.

A couple things:
1. Do we need all these dwrite probes?
2. Are there other probes I should add?
3. I'm not sure what kind of min/max/buckets/etc I should be using for these probes. I just did 1-30000ms under the assumption that we're doing IO and the worse case might be pretty horrible.

Comment 2

[(dormant account)]

Comment on attachment 543015 [details] [diff] [review]
Add font probes

10 buckets should be enough. 
I made a RAII thing in bug 668355, might simplify code. I'm not sure that there is any benefit to explicit QueryPerformanceCounter(). mozilla/timestamp.h stuff might already do something similar, extreme precision isn't required here.

Comment 3

[Michael Wu [:mwu]]

(In reply to comment #2)
> 10 buckets should be enough. 
> I made a RAII thing in bug 668355, might simplify code. I'm not sure that
> there is any benefit to explicit QueryPerformanceCounter().
> mozilla/timestamp.h stuff might already do something similar, extreme
> precision isn't required here.

I'm not inclined to change the use of QPC unless jtd wants to since this is his timing code.

The RAII thing is nice - I can switch to it before landing if it lands first.

Comment 4

[John Daggett (:jtd)]

Michael, your patch is essentially *always* accumulating timing data.  With Telemetry is there a notion of collecting vs. not collecting?  Is histogram data preserved across runs?

I think a key weakness of this approach is that you're not distinguishing between cold/warm startup, those two cases will have very different timing profiles.

One other thing, are the description strings used in the HISTOGRAM() macro ever intended to be localized?

Comment 5

[(dormant account)]

(In reply to comment #4)
> Michael, your patch is essentially *always* accumulating timing data.  With
> Telemetry is there a notion of collecting vs. not collecting?  Is histogram
> data preserved across runs?

No.
I don't see much harm is always doing the timing.

> 
> I think a key weakness of this approach is that you're not distinguishing
> between cold/warm startup, those two cases will have very different timing
> profiles.

That's fine. We just need to see it on the serverside. We just need to see how often enumerations are slow(if they still are).

> 
> One other thing, are the description strings used in the HISTOGRAM() macro
> ever intended to be localized?

No. At the moment they are for documentation only, eventually they'll go on an official about:telemetry page, those aren't ever localized.

Comment 6

[John Daggett (:jtd)]

Comment on attachment 543015 [details] [diff] [review]
Add font probes

> @@ -65,7 +66,9 @@ using namespace mozilla;
>  #define LOG_FONTINIT_ENABLED() PR_LOG_TEST( \
>                                     gfxPlatform::GetLog(eGfxLog_fontinit), \
>                                     PR_LOG_DEBUG)
> -
> +#else
> +#define LOG_FONTINIT(args)
> +#define LOG_FONTINIT_ENABLED() 0
>  #endif // PR_LOGGING

This is redundant, the PR_LOG macros already reduce to this when not defined.

> -#ifdef PR_LOGGING
>                  if (LOG_FONTLIST_ENABLED()) {
>                      gfxFontEntry *fe = faces[i];
>                      LOG_FONTLIST(("(fontlist) moved (%s) to family (%s)"
> @@ -936,7 +929,6 @@ gfxDWriteFontList::DelayedInitFontList()
>                           (fe->IsItalic()) ? "italic" : "normal",
>                           fe->Weight(), fe->Stretch()));
>                  }
> -#endif

This code has nothing to do with font initialization timing, no need to
strip out the conditionals.

> +HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_GDI, 0, 1, 2, BOOLEAN, "gfxDWriteFontList::DelayedInitFontList GDI Access")

This should probably be _GDI_TABLE and GDI Table Access, otherwise the
"GDI" notion will be out of context.

> +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")
> +HISTOGRAM(DWRITEFONT_INITFONTLIST_TOTAL, 1, 30000, 50, EXPONENTIAL, "gfxDWriteFontList::InitFontList Total (ms)")
> +HISTOGRAM(DWRITEFONT_INITFONTLIST_INIT, 1, 30000, 50, EXPONENTIAL, "gfxDWriteFontList::InitFontList init (ms)")
> +HISTOGRAM(DWRITEFONT_INITFONTLIST_GDI, 1, 30000, 50, EXPONENTIAL, "gfxDWriteFontList::InitFontList GdiInterop object (ms)")
> +HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_TOTAL, 1, 30000, 50, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList Total (ms)")
> +HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_COUNT, 1, 10000, 50, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList Font Family Count")
> +HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_GDI, 0, 1, 2, BOOLEAN, "gfxDWriteFontList::DelayedInitFontList GDI Access")
> +HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_COLLECT, 1, 30000, 50, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList GetSystemFontCollection (ms)")
> +HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST_ITERATE, 1, 30000, 50, EXPONENTIAL, "gfxDWriteFontList::DelayedInitFontList iterate over families (ms)")

This patch only captures timing data in the DirectWrite case, seems to
me if we're going to do this we should do it in all instances of
InitFontList and generalize this a bit better.

Comment 7

[Michael Wu [:mwu]]

Attachment: Add font probes, v2

Review comments addressed and probes added for InitFontList in gfxGDIFontList.cpp and gfxMacPlatformFontList.mm .

Comment 8

[Michael Wu [:mwu]]

Attachment: Add font probes, v3

Comment 9

[John Daggett (:jtd)]

Comment on attachment 547003 [details] [diff] [review]
Add font probes, v3

Looks good.  It would nice to have a way to note that these timers are basically single sample results, there's not really a need for a histogram to capture these results since the InitFontList typically runs once during a browser run.

Comment 10

[Michael Wu [:mwu]]

http://hg.mozilla.org/integration/mozilla-inbound/rev/6eca6c29e2c0

Comment 11

[(no longer active)]

http://hg.mozilla.org/mozilla-central/rev/6eca6c29e2c0