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 a917430d263822706ba8eb916a46465db16dfaa2..823a3dbf1100bdf4c0ca22c3dee96207cbcccf92 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"
@@ -78,16 +79,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 = adoptPtr(new Vector<unsigned char>());
@@ -127,12 +129,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, WeakPersistentThisPointer<CanvasAsyncBlobCreator>(this), quality));
 }
 
 void CanvasAsyncBlobCreator::initiateJpegEncoding(const double& quality, double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    m_initiateStartTime = WTF::monotonicallyIncreasingTime();
+    DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGInitiateEncodingCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.InitiateEncodingDelay.JPEG", 0, 10000000, 50));
+    toBlobJPEGInitiateEncodingCounter.count((m_initiateStartTime - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
@@ -149,12 +155,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, WeakPersistentThisPointer<CanvasAsyncBlobCreator>(this)));
 }
 
 void CanvasAsyncBlobCreator::initiatePngEncoding(double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    m_initiateStartTime = WTF::monotonicallyIncreasingTime();
+    DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGInitiateEncodingCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.InitiateEncodingDelay.PNG", 0, 10000000, 50));
+    toBlobPNGInitiateEncodingCounter.count((m_initiateStartTime - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
@@ -192,6 +202,9 @@ void CanvasAsyncBlobCreator::idleEncodeRowsPng(double deadlineSeconds)
     m_idleTaskStatus = IdleTaskCompleted;
 
     if (isDeadlineNearOrPassed(deadlineSeconds)) {
+        double elapsedTime = WTF::monotonicallyIncreasingTime() - m_initiateStartTime;
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGIdleEncodeCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.IdleEncodeDuration.PNG", 0, 10000000, 50));

[Justin Novosad, 2016/06/13 21:21:35]

This stat is not very useful the way it is currently computed.  What we call an
"encode duration" should probably be the *sum* of the time spent in this
function for a given encode task.

+        toBlobPNGIdleEncodeCounter.count(elapsedTime * 1000000.0);

[xlai (Olivia), 2016/06/13 20:15:06]

Move this whole block of code before this if-else block.

[Justin Novosad, 2016/06/13 21:21:35]

actually, I was think more like doing "m_elapsedTime += ..." in the "if" part,
and recording the histogram in the "else" part.  Same thing for JPEG.

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

Yes, that makes perfect sense.

         Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::createBlobAndInvokeCallback, this));
     } else {
         this->createBlobAndInvokeCallback();
@@ -209,6 +222,9 @@ void CanvasAsyncBlobCreator::idleEncodeRowsJpeg(double deadlineSeconds)
     if (m_numRowsCompleted == m_size.height()) {
         m_idleTaskStatus = IdleTaskCompleted;
         if (isDeadlineNearOrPassed(deadlineSeconds)) {
+            double elapsedTime = WTF::monotonicallyIncreasingTime() - m_initiateStartTime;
+            DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGIdleEncodeCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.IdleEncodeDuration.JPEG", 0, 10000000, 50));
+            toBlobJPEGIdleEncodeCounter.count(elapsedTime * 1000000.0);

[xlai (Olivia), 2016/06/13 20:15:06]

Move this whole block of code before this if-else block.

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

Using Justin's suggestion.

             Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::createBlobAndInvokeCallback, this));
         } else {
             this->createBlobAndInvokeCallback();
@@ -254,12 +270,36 @@ void CanvasAsyncBlobCreator::encodeRowsJpegOnMainThread()
 void CanvasAsyncBlobCreator::createBlobAndInvokeCallback()
 {
     ASSERT(isMainThread());
+    if (m_idleTaskStatus == IdleTaskNotSupported) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, toBlobIdleNotSupported, new EnumerationHistogram("Blink.Canvas.ToBlob.IdleTask.NotSupported", IdleTaskNotSupported));
+        toBlobIdleNotSupported.count(m_idleTaskStatus);
+    } else if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, toBlobIdleSwitchedToMain, new EnumerationHistogram("Blink.Canvas.ToBlob.IdleTask.SwitchedToMain", IdleTaskNotSupported));

[xlai (Olivia), 2016/06/13 20:15:06]

The enum type "SwitchedToMain" is misleading. We are always on main thread.
Change the name to "IdleTaskSwitchedToMainThreadTask". Also change the other
names to look exactly same as the enum types in m_idleTaskStatus.

[Justin Novosad, 2016/06/13 21:21:35]

Also, in the case where we switch to main, there are two interesting timing
stats to record: the time spent encoding before and after the switch.

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

This actually brings up another question: currently we measure the time spent
encoding on the idle period. That time could be encoding the entire image, it
could also be encoding part of the image because the switch could happen. In
other words, that timing may not be so meaningful?

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

Done.

+        toBlobIdleSwitchedToMain.count(m_idleTaskStatus);
+    } else if  (m_idleTaskStatus == IdleTaskCompleted) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, toBlobIdleTaskCompleted, new EnumerationHistogram("Blink.Canvas.ToBlob.IdleTask.Completed", IdleTaskNotSupported));
+        toBlobIdleTaskCompleted.count(m_idleTaskStatus);
+    }
+
+    double elapsedTime = WTF::monotonicallyIncreasingTime() - m_startTime;
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGCounter, new CustomCountHistogram("Blink.Canvas.ToBlobDuration.PNG", 0, 10000000, 50));
+        toBlobPNGCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGCounter, new CustomCountHistogram("Blink.Canvas.ToBlobDuration.JPEG", 0, 10000000, 50));
+        toBlobJPEGCounter.count(elapsedTime * 1000000.0);
+    } else {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobWEBPCounter, new CustomCountHistogram("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));
 }
 
 void CanvasAsyncBlobCreator::createNullAndInvokeCallback()
 {
+    DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, toBlobFailed, new EnumerationHistogram("Blink.Canvas.ToBlob.IdleTask.Failed", IdleTaskNotSupported));
+    toBlobFailed.count(m_idleTaskStatus);
     ASSERT(isMainThread());
     Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&BlobCallback::handleEvent, m_callback, nullptr));
 }
@@ -329,7 +369,6 @@ void CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent(double quality)
         ASSERT(m_idleTaskStatus == IdleTaskFailed || m_idleTaskStatus == IdleTaskCompleted);
         this->signalAlternativeCodePathFinishedForTesting();
     }
-
 }
 
 void CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent()