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 01136649524082b8b79b83dda662a2a4852c957e..c0830271c4e9e1402f7ae7e7925f56d1bfda80c7 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"
@@ -94,6 +95,7 @@ CanvasAsyncBlobCreator::CanvasAsyncBlobCreator(DOMUint8ClampedArray* data, MimeT
     m_pixelRowStride = size.width() * NumChannelsPng;
     m_idleTaskStatus = IdleTaskNotSupported;
     m_numRowsCompleted = 0;
+    m_startTime = WTF::monotonicallyIncreasingTime();

[xlai (Olivia), 2016/06/07 16:08:14]

To measure the total elapsed time of toBlob API call, I find it odd to start the
measurement from here. The CanvasAsyncBlobCreator is created in the *middle* of
the toBlob API call. You should start the timer from the beginning of
HTMLCanvasElement::toBlob().

[xidachen, 2016/06/07 20:46:29]

Yes, that makes total sense. I place the start after checking originClean() and
isPaintable().

 }
 
 CanvasAsyncBlobCreator::~CanvasAsyncBlobCreator()
@@ -118,7 +120,8 @@ void CanvasAsyncBlobCreator::scheduleAsyncBlobCreation(bool canUseIdlePeriodSche
         }
         // We post the below task to check if the above idle task isn't late.
         // There's no risk of concurrency as both tasks are on main thread.
-        this->postDelayedTaskToMainThread(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent, this, quality), IdleTaskStartTimeoutDelay);
+        double startTime = WTF::monotonicallyIncreasingTime();
+        this->postDelayedTaskToMainThread(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent, this, quality, startTime), IdleTaskStartTimeoutDelay);
     } else if (m_mimeType == MimeTypeWebp) {
         BackgroundTaskRunner::TaskSize taskSize = (m_size.height() * m_size.width() >= LongTaskImageSizeThreshold) ? BackgroundTaskRunner::TaskSizeLongRunningTask : BackgroundTaskRunner::TaskSizeShortRunningTask;
         BackgroundTaskRunner::postOnBackgroundThread(BLINK_FROM_HERE, threadSafeBind(&CanvasAsyncBlobCreator::encodeImageOnEncoderThread, wrapCrossThreadPersistent(this), quality), taskSize);
@@ -260,6 +263,20 @@ void CanvasAsyncBlobCreator::createBlobAndInvokeCallback()
     // non-GC members to allow teardown of CanvasAsyncBlobCreator.
     m_data.clear();
     m_callback.clear();
+    double elapsedTime = WTF::monotonicallyIncreasingTime()  - m_startTime;
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.PNG.Succeed", 0, 10000000, 50));
+        toBlobPNGCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.JPEG.Succeed", 0, 10000000, 50));
+        toBlobJPEGCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeWebp) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobWEBPCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.WEBP.Succeed", 0, 10000000, 50));
+        toBlobWEBPCounter.count(elapsedTime * 1000000.0);
+    } else {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobUnknownCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.Unknown.Succeed", 0, 10000000, 50));

[xlai (Olivia), 2016/06/07 16:08:14]

"Unknown" type is impossible to reach here. See "ASSERT_NOT_REACH()" in above
code.

[xidachen, 2016/06/07 20:46:28]

Done.

+        toBlobUnknownCounter.count(elapsedTime * 1000000.0);
+    }
 }
 
 void CanvasAsyncBlobCreator::createNullAndInvokeCallback()
@@ -270,6 +287,20 @@ void CanvasAsyncBlobCreator::createNullAndInvokeCallback()
     // clear non-GC members to allow teardown of CanvasAsyncBlobCreator.
     m_data.clear();
     m_callback.clear();
+    double elapsedTime = WTF::monotonicallyIncreasingTime()  - m_startTime;
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.PNG.Failed", 0, 10000000, 50));

[xlai (Olivia), 2016/06/07 16:08:14]

I sincerely feels that such a detailed histogram for "Failed" use case is
unnecessary. I don't really think we're interested to know how long it takes to
fail. 

[xidachen, 2016/06/07 20:46:28]

Done.

+        toBlobPNGCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.JPEG.Failed", 0, 10000000, 50));
+        toBlobJPEGCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeWebp) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobWEBPCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.WEBP.Failed", 0, 10000000, 50));
+        toBlobWEBPCounter.count(elapsedTime * 1000000.0);
+    } else {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobUnknownCounter, new CustomCountHistogram("Blink.Canvas.ToBlob.Unknown.Failed", 0, 10000000, 50));
+        toBlobUnknownCounter.count(elapsedTime * 1000000.0);
+    }
 }
 
 void CanvasAsyncBlobCreator::encodeImageOnEncoderThread(double quality)
@@ -305,11 +336,45 @@ bool CanvasAsyncBlobCreator::initializeJpegStruct(double quality)
     return true;
 }
 
-void CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent(double quality)
+void CanvasAsyncBlobCreator::recordTimeoutEvent(IdleTaskTimeoutType type)
 {
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, idleTaskTimeoutEventPNG, new EnumerationHistogram("Canvas.ToBlob.IdleTaskTimeout.PNG", IdleTaskTimeoutSupported));

[xlai (Olivia), 2016/06/07 16:08:14]

What is the purpose of this histogram?

[xidachen, 2016/06/07 20:46:29]

Change this to record the occurrence of switch from idle to main thread.

+        idleTaskTimeoutEventPNG.count(type);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, idleTaskTimeoutEventJPEG, new EnumerationHistogram("Canvas.ToBlob.IdleTaskTimeout.JPEG", IdleTaskTimeoutSupported));
+        idleTaskTimeoutEventJPEG.count(type);
+    } else if (m_mimeType == MimeTypeWebp) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, idleTaskTimeoutEventWEBP, new EnumerationHistogram("Canvas.ToBlob.IdleTaskTimeout.WEBP", IdleTaskTimeoutSupported));
+        idleTaskTimeoutEventWEBP.count(type);
+    } else {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(EnumerationHistogram, idleTaskTimeoutEventUnknown, new EnumerationHistogram("Canvas.ToBlob.IdleTaskTimeout.Unknown", IdleTaskTimeoutSupported));
+        idleTaskTimeoutEventUnknown.count(type);
+    }
+}
+
+void CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent(double quality, double startTime)
+{
+    recordTimeoutEvent(IdleTaskStartTimeout);
+    double elapsedTime = WTF::monotonicallyIncreasingTime()  - startTime;
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGStartTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.PNG.Start", 0, 10000000, 50));
+        toBlobPNGStartTimeoutCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGStartTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.JPEG.Start", 0, 10000000, 50));
+        toBlobJPEGStartTimeoutCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeWebp) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobWEBPStartTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.WEBP.Start", 0, 10000000, 50));
+        toBlobWEBPStartTimeoutCounter.count(elapsedTime * 1000000.0);
+    } else {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobUnknownStartTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.Unknown.Start", 0, 10000000, 50));

[xlai (Olivia), 2016/06/07 16:08:14]

Same comment for "unknown".

[xidachen, 2016/06/07 20:46:28]

Done.

+        toBlobUnknownStartTimeoutCounter.count(elapsedTime * 1000000.0);
+    }
+
     if (m_idleTaskStatus == IdleTaskStarted) {
         // Even if the task started quickly, we still want to ensure completion
-        this->postDelayedTaskToMainThread(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent, this), IdleTaskCompleteTimeoutDelay);
+        startTime = WTF::monotonicallyIncreasingTime();
+        this->postDelayedTaskToMainThread(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent, this, startTime), IdleTaskCompleteTimeoutDelay);
     } else if (m_idleTaskStatus == IdleTaskNotStarted) {
         // If the idle task does not start after a delay threshold, we will
         // force it to happen on main thread (even though it may cause more
@@ -340,9 +405,24 @@ void CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent(double quality)
 
 }
 
-void CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent()
+void CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent(double startTime)
 {
     ASSERT(m_idleTaskStatus != IdleTaskNotStarted);
+    recordTimeoutEvent(IdleTaskCompleteTimeout);
+    double elapsedTime = WTF::monotonicallyIncreasingTime()  - startTime;
+    if (m_mimeType == MimeTypePng) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGCompleteTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.PNG.Complete", 0, 10000000, 50));
+        toBlobPNGCompleteTimeoutCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeJpeg) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGCompleteTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.JPEG.Complete", 0, 10000000, 50));
+        toBlobJPEGCompleteTimeoutCounter.count(elapsedTime * 1000000.0);
+    } else if (m_mimeType == MimeTypeWebp) {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobWEBPCompleteTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.WEBP.Complete", 0, 10000000, 50));
+        toBlobWEBPCompleteTimeoutCounter.count(elapsedTime * 1000000.0);
+    } else {
+        DEFINE_THREAD_SAFE_STATIC_LOCAL(CustomCountHistogram, toBlobUnknownCompleteTimeoutCounter, new CustomCountHistogram("Blink.Canvas.ToBlobTimeoutDuration.Unknown.Complete", 0, 10000000, 50));
+        toBlobUnknownCompleteTimeoutCounter.count(elapsedTime * 1000000.0);
+    }
 
     if (m_idleTaskStatus == IdleTaskStarted) {
         // It has taken too long to complete for the idle task.