Bug 678258. imglib: Record the time from starting a decode on draw and actually finishing it. r=jlebar
authorJeff Muizelaar <jmuizelaar@mozilla.com>
Wed, 10 Aug 2011 19:12:08 -0400
changeset 74276 3274828eccfb7eda8b46063e752f36110c4fd296
parent 74275 1d071e2fa07fdc856ef3471dc4c9e7c834f88efd
child 74277 4b4b359e77e48709bdd71a03cc6318b7d4fc232d
push id2
push userbsmedberg@mozilla.com
push dateFri, 19 Aug 2011 14:38:13 +0000
reviewersjlebar
bugs678258
milestone8.0a1
Bug 678258. imglib: Record the time from starting a decode on draw and actually finishing it. r=jlebar This ignores the distinction between async and sync decoding and instead focuses on the time it takes till the user sees the finished image.
modules/libpr0n/src/RasterImage.cpp
modules/libpr0n/src/RasterImage.h
toolkit/components/telemetry/TelemetryHistograms.h
--- a/modules/libpr0n/src/RasterImage.cpp
+++ b/modules/libpr0n/src/RasterImage.cpp
@@ -2492,16 +2492,20 @@ RasterImage::Draw(gfxContext *aContext,
   if (mFrameDecodeFlags != DECODE_FLAGS_DEFAULT) {
     if (!CanForciblyDiscard())
       return NS_ERROR_NOT_AVAILABLE;
     ForceDiscard();
 
     mFrameDecodeFlags = DECODE_FLAGS_DEFAULT;
   }
 
+  if (!mDecoded) {
+      mDrawStartTime = TimeStamp::Now();
+  }
+
   // If a synchronous draw is requested, flush anything that might be sitting around
   if (aFlags & FLAG_SYNC_DECODE) {
     nsresult rv = SyncDecode();
     NS_ENSURE_SUCCESS(rv, rv);
   }
 
   imgFrame *frame = GetCurrentDrawableImgFrame();
   if (!frame) {
@@ -2510,16 +2514,22 @@ RasterImage::Draw(gfxContext *aContext,
 
   nsIntRect framerect = frame->GetRect();
   nsIntMargin padding(framerect.x, framerect.y, 
                       mSize.width - framerect.XMost(),
                       mSize.height - framerect.YMost());
 
   frame->Draw(aContext, aFilter, aUserSpaceToImageSpace, aFill, padding, aSubimage);
 
+  if (mDecoded && !mDrawStartTime.IsNull()) {
+      TimeDuration drawLatency = TimeStamp::Now() - mDrawStartTime;
+      Telemetry::Accumulate(Telemetry::IMAGE_DECODE_ON_DRAW_LATENCY, PRInt32(drawLatency.ToMicroseconds()));
+      // clear the value of mDrawStartTime
+      mDrawStartTime = TimeStamp();
+  }
   return NS_OK;
 }
 
 //******************************************************************************
 /* [notxpcom] nsIFrame GetRootLayoutFrame() */
 nsIFrame*
 RasterImage::GetRootLayoutFrame()
 {
--- a/modules/libpr0n/src/RasterImage.h
+++ b/modules/libpr0n/src/RasterImage.h
@@ -528,16 +528,17 @@ private: // data
 
   // Decoding
   nsresult WantDecodedFrames();
   nsresult SyncDecode();
   nsresult InitDecoder(bool aDoSizeDecode);
   nsresult WriteToDecoder(const char *aBuffer, PRUint32 aCount);
   nsresult DecodeSomeData(PRUint32 aMaxBytes);
   PRBool   IsDecodeFinished();
+  TimeStamp mDrawStartTime;
 
   // Decoder shutdown
   enum eShutdownIntent {
     eShutdownIntent_Done        = 0,
     eShutdownIntent_Interrupted = 1,
     eShutdownIntent_Error       = 2,
     eShutdownIntent_AllCount    = 3
   };
--- a/toolkit/components/telemetry/TelemetryHistograms.h
+++ b/toolkit/components/telemetry/TelemetryHistograms.h
@@ -82,16 +82,17 @@ HISTOGRAM(DWRITEFONT_DELAYEDINITFONTLIST
 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)")
 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)")
 
 /**
  * Networking telemetry
  */
 HISTOGRAM(TOTAL_CONTENT_PAGE_LOAD_TIME, 100, 10000, 100, EXPONENTIAL, "HTTP: Total page load time (ms)")
 HISTOGRAM(HTTP_SUBITEM_OPEN_LATENCY_TIME, 1, 30000, 50, EXPONENTIAL, "HTTP subitem: Page start -> subitem open() (ms)")
 HISTOGRAM(HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME, 1, 30000, 50, EXPONENTIAL, "HTTP subitem: Page start -> first byte received for subitem reply (ms)")
 HISTOGRAM(HTTP_REQUEST_PER_PAGE, 1, 1000, 50, EXPONENTIAL, "HTTP: Requests per page (count)")