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 0ea4fc061382f39f833923a598e7dfea5998649b..cdc81547516277989a6c8e72775b59e01f11dd28 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,16 @@ void CanvasAsyncBlobCreator::scheduleAsyncBlobCreation(bool canUseIdlePeriodSche
 
 void CanvasAsyncBlobCreator::scheduleInitiateJpegEncoding(const double& quality)
 {
+    m_scheduleInitiateStartTime = WTF::monotonicallyIncreasingTime();
     Platform::current()->mainThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind<double>(&CanvasAsyncBlobCreator::initiateJpegEncoding, this, quality));
 }
 
 void CanvasAsyncBlobCreator::initiateJpegEncoding(const double& quality, double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    m_initiateStartTime = WTF::monotonicallyIncreasingTime();
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGInitiateEncodingCounter, ("Blink.Canvas.ToBlob.InitiateEncodingDelay.JPEG", 0, 10000000, 50));
+    toBlobJPEGInitiateEncodingCounter.count((m_initiateStartTime - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
@@ -158,12 +164,16 @@ void CanvasAsyncBlobCreator::initiateJpegEncoding(const double& quality, double
 
 void CanvasAsyncBlobCreator::scheduleInitiatePngEncoding()
 {
+    m_scheduleInitiateStartTime = WTF::monotonicallyIncreasingTime();
     Platform::current()->mainThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind<double>(&CanvasAsyncBlobCreator::initiatePngEncoding, this));
 }
 
 void CanvasAsyncBlobCreator::initiatePngEncoding(double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    m_initiateStartTime = WTF::monotonicallyIncreasingTime();
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGInitiateEncodingCounter, ("Blink.Canvas.ToBlob.InitiateEncodingDelay.PNG", 0, 10000000, 50));
+    toBlobPNGInitiateEncodingCounter.count((m_initiateStartTime - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
@@ -201,8 +211,11 @@ void CanvasAsyncBlobCreator::idleEncodeRowsPng(double deadlineSeconds)
     m_idleTaskStatus = IdleTaskCompleted;
 
     if (isDeadlineNearOrPassed(deadlineSeconds)) {
+        m_elapsedTime += (WTF::monotonicallyIncreasingTime() - m_initiateStartTime);

[Justin Novosad, 2016/06/22 14:38:57]

At each Idle slice, you are adding the time since start? This is not correct.

[xidachen, 2016/06/22 15:40:41]

The new patch should have that fixed.

         Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::createBlobAndInvokeCallback, this));
     } else {
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGIdleEncodeCounter, ("Blink.Canvas.ToBlob.IdleEncodeDuration.PNG", 0, 10000000, 50));
+        toBlobPNGIdleEncodeCounter.count(m_elapsedTime * 1000000.0);
         this->createBlobAndInvokeCallback();
     }
 }
@@ -218,8 +231,11 @@ void CanvasAsyncBlobCreator::idleEncodeRowsJpeg(double deadlineSeconds)
     if (m_numRowsCompleted == m_size.height()) {
         m_idleTaskStatus = IdleTaskCompleted;
         if (isDeadlineNearOrPassed(deadlineSeconds)) {
+            m_elapsedTime += (WTF::monotonicallyIncreasingTime() - m_initiateStartTime);

[Justin Novosad, 2016/06/22 14:38:57]

Not correct.

             Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::createBlobAndInvokeCallback, this));
         } else {
+            DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGIdleEncodeCounter, ("Blink.Canvas.ToBlob.IdleEncodeDuration.JPEG", 0, 10000000, 50));
+            toBlobJPEGIdleEncodeCounter.count(m_elapsedTime * 1000000.0);
             this->createBlobAndInvokeCallback();
         }
     } else if (m_numRowsCompleted == JPEGImageEncoder::ProgressiveEncodeFailed) {
@@ -263,6 +279,20 @@ void CanvasAsyncBlobCreator::encodeRowsJpegOnMainThread()
 void CanvasAsyncBlobCreator::createBlobAndInvokeCallback()
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(EnumerationHistogram, toBlobIdleTaskStatus, ("Blink.Canvas.ToBlob.IdleTaskStatus", IdleTaskNotSupported));

[xidachen, 2016/06/22 14:01:25]

xlai@: you are correct. I change the enum histogram like this. But one problem
is that we cannot measure the case when toBlob failed because that happens in
createNullAndInvokeCallback().

+    toBlobIdleTaskStatus.count(m_idleTaskStatus);
+
+    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, m_callback, 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()