Track performance of toBlob and its complete timeout delay

third_party/WebKit/Source/core/html/canvas/CanvasAsyncBlobCreator.cpp

Index: third_party/WebKit/Source/core/html/canvas/CanvasAsyncBlobCreator.cpp
diff --git a/third_party/WebKit/Source/core/html/canvas/CanvasAsyncBlobCreator.cpp b/third_party/WebKit/Source/core/html/canvas/CanvasAsyncBlobCreator.cpp
index 772783189e1b5113dc1d8f0539af13b393546f3c..150304386265dfef5a3430338bb1b3a6f0f4dc16 100644
--- a/third_party/WebKit/Source/core/html/canvas/CanvasAsyncBlobCreator.cpp
+++ b/third_party/WebKit/Source/core/html/canvas/CanvasAsyncBlobCreator.cpp
@@ -5,6 +5,7 @@
 #include "core/html/canvas/CanvasAsyncBlobCreator.h"
 
 #include "core/fileapi/Blob.h"
+#include "platform/Histogram.h"
 #include "platform/ThreadSafeFunctional.h"
 #include "platform/graphics/ImageBuffer.h"
 #include "platform/image-encoders/JPEGImageEncoder.h"
@@ -79,16 +80,17 @@ CanvasAsyncBlobCreator::MimeType convertMimeTypeStringToEnum(const String& mimeT
 
 } // anonymous namespace
 
-CanvasAsyncBlobCreator* CanvasAsyncBlobCreator::create(DOMUint8ClampedArray* unpremultipliedRGBAImageData, const String& mimeType, const IntSize& size, BlobCallback* callback)
+CanvasAsyncBlobCreator* CanvasAsyncBlobCreator::create(DOMUint8ClampedArray* unpremultipliedRGBAImageData, const String& mimeType, const IntSize& size, BlobCallback* callback, double startTime)
 {
-    return new CanvasAsyncBlobCreator(unpremultipliedRGBAImageData, convertMimeTypeStringToEnum(mimeType), size, callback);
+    return new CanvasAsyncBlobCreator(unpremultipliedRGBAImageData, convertMimeTypeStringToEnum(mimeType), size, callback, startTime);
 }
 
-CanvasAsyncBlobCreator::CanvasAsyncBlobCreator(DOMUint8ClampedArray* data, MimeType mimeType, const IntSize& size, BlobCallback* callback)
+CanvasAsyncBlobCreator::CanvasAsyncBlobCreator(DOMUint8ClampedArray* data, MimeType mimeType, const IntSize& size, BlobCallback* callback, double startTime)
     : m_data(data)
     , m_size(size)
     , m_mimeType(mimeType)
     , m_callback(callback)
+    , m_startTime(startTime)
 {
     ASSERT(m_data->length() == (unsigned) (size.height() * size.width() * 4));
     m_encodedImage = wrapUnique(new Vector<unsigned char>());
@@ -136,12 +138,15 @@ void CanvasAsyncBlobCreator::scheduleAsyncBlobCreation(bool canUseIdlePeriodSche
 
 void CanvasAsyncBlobCreator::scheduleInitiateJpegEncoding(const double& quality)
 {
+    m_scheduleInitiateStartTime = WTF::monotonicallyIncreasingTime();
     Platform::current()->mainThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::initiateJpegEncoding, this, quality));
 }
 
 void CanvasAsyncBlobCreator::initiateJpegEncoding(const double& quality, double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGInitiateEncodingCounter, ("Blink.Canvas.ToBlob.InitiateEncodingDelay.JPEG", 0, 10000000, 50));
+    toBlobJPEGInitiateEncodingCounter.count((WTF::monotonicallyIncreasingTime() - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
@@ -158,12 +163,15 @@ void CanvasAsyncBlobCreator::initiateJpegEncoding(const double& quality, double
 
 void CanvasAsyncBlobCreator::scheduleInitiatePngEncoding()
 {
+    m_scheduleInitiateStartTime = WTF::monotonicallyIncreasingTime();
     Platform::current()->mainThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::initiatePngEncoding, this));
 }
 
 void CanvasAsyncBlobCreator::initiatePngEncoding(double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGInitiateEncodingCounter, ("Blink.Canvas.ToBlob.InitiateEncodingDelay.PNG", 0, 10000000, 50));
+    toBlobPNGInitiateEncodingCounter.count((WTF::monotonicallyIncreasingTime() - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
@@ -185,10 +193,12 @@ void CanvasAsyncBlobCreator::idleEncodeRowsPng(double deadlineSeconds)
         return;
     }
 
+    double startTime = WTF::monotonicallyIncreasingTime();

[xlai (Olivia), 2016/06/24 14:56:09]

put this back.

     unsigned char* inputPixels = m_data->data() + m_pixelRowStride * m_numRowsCompleted;
     for (int y = m_numRowsCompleted; y < m_size.height(); ++y) {
         if (isDeadlineNearOrPassed(deadlineSeconds)) {
             m_numRowsCompleted = y;
+            m_elapsedTime += (WTF::monotonicallyIncreasingTime() - startTime);

[xlai (Olivia), 2016/06/24 14:56:09]

Put this back.

             Platform::current()->currentThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleEncodeRowsPng, this));
             return;
         }
@@ -199,6 +209,8 @@ void CanvasAsyncBlobCreator::idleEncodeRowsPng(double deadlineSeconds)
     PNGImageEncoder::finalizePng(m_pngEncoderState.get());
 
     m_idleTaskStatus = IdleTaskCompleted;
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGIdleEncodeCounter, ("Blink.Canvas.ToBlob.IdleEncodeDuration.PNG", 0, 10000000, 50));
+    toBlobPNGIdleEncodeCounter.count(m_elapsedTime * 1000000.0);

[xlai (Olivia), 2016/06/23 17:07:37]

I think there is a logic flaw. Think of the scenario when in the last
idleEncodeRowsPng() call, the encoding finishes the last few rows of encoding
without hitting the deadline in that particular idle period, so the above
addition to m_elapsedTime at Line 201 is not executed. Then in here, the
recording will miss out the time spent in the last idleEncodeRowsPng() call.

[xidachen, 2016/06/24 11:17:52]

Good catch, the new patch should have that fixed.

 
     if (isDeadlineNearOrPassed(deadlineSeconds)) {
         Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::createBlobAndInvokeCallback, this));
@@ -214,9 +226,12 @@ void CanvasAsyncBlobCreator::idleEncodeRowsJpeg(double deadlineSeconds)
         return;
     }
 
+    double startTime = WTF::monotonicallyIncreasingTime();
     m_numRowsCompleted = JPEGImageEncoder::progressiveEncodeRowsJpegHelper(m_jpegEncoderState.get(), m_data->data(), m_numRowsCompleted, SlackBeforeDeadline, deadlineSeconds);
     if (m_numRowsCompleted == m_size.height()) {
         m_idleTaskStatus = IdleTaskCompleted;
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGIdleEncodeCounter, ("Blink.Canvas.ToBlob.IdleEncodeDuration.JPEG", 0, 10000000, 50));
+        toBlobJPEGIdleEncodeCounter.count(m_elapsedTime * 1000000.0);
         if (isDeadlineNearOrPassed(deadlineSeconds)) {
             Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::createBlobAndInvokeCallback, this));
         } else {
@@ -226,6 +241,7 @@ void CanvasAsyncBlobCreator::idleEncodeRowsJpeg(double deadlineSeconds)
         m_idleTaskStatus = IdleTaskFailed;
         this->createNullAndInvokeCallback();
     } else {
+        m_elapsedTime += (WTF::monotonicallyIncreasingTime() - startTime);

[xlai (Olivia), 2016/06/23 17:07:37]

There is also a logic flaw here similar to the PNG one but the solution may be
different. The function JPEGImageEncoder::progressiveEncodeRowsJpegHelper() will
stop when it uses up the deadlineSeconds passed into it. If it manages to
complete all encoding, you'll never hit the Line 244 and so your m_elapsedTime
does not record the time spent in encoding. My suggestion for this one would be
to move Line 244 to the position between Line 230 and Line 231. In that way, you
accumulate m_elapsedTime regardless of failed, complete, in-progress status.

[xidachen, 2016/06/24 11:17:52]

Done.

         Platform::current()->currentThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleEncodeRowsJpeg, this));
     }
 }
@@ -263,6 +279,20 @@ void CanvasAsyncBlobCreator::encodeRowsJpegOnMainThread()
 void CanvasAsyncBlobCreator::createBlobAndInvokeCallback()
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(EnumerationHistogram, toBlobIdleTaskStatus, ("Blink.Canvas.ToBlob.IdleTaskStatus", IdleTaskNotSupported));
+    toBlobIdleTaskStatus.count(m_idleTaskStatus);

[xlai (Olivia), 2016/06/23 17:07:37]

You miss out the case when m_idleTaskStatus==IdleTaskFailed because
createBlobAndInvokeCallback() is only executed when idle encoding succeeds.

[xidachen, 2016/06/24 11:17:52]

Done.

+
+    double elapsedTime = WTF::monotonicallyIncreasingTime() - m_startTime;
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGCounter, ("Blink.Canvas.ToBlobDuration.PNG", 0, 10000000, 50));
+        toBlobPNGCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGCounter, ("Blink.Canvas.ToBlobDuration.JPEG", 0, 10000000, 50));
+        toBlobJPEGCounter.count(elapsedTime * 1000000.0);
+    } else {
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobWEBPCounter, ("Blink.Canvas.ToBlobDuration.WEBP", 0, 10000000, 50));
+        toBlobWEBPCounter.count(elapsedTime * 1000000.0);
+    }
     Blob* resultBlob = Blob::create(m_encodedImage->data(), m_encodedImage->size(), convertMimeTypeEnumToString(m_mimeType));
     Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&BlobCallback::handleEvent, wrapPersistent(m_callback.get()), resultBlob));
     // Avoid unwanted retention, see dispose().
@@ -342,7 +372,6 @@ void CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent(double quality)
         ASSERT(m_idleTaskStatus == IdleTaskFailed || m_idleTaskStatus == IdleTaskCompleted);
         this->signalAlternativeCodePathFinishedForTesting();
     }
-
 }
 
 void CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent()