Track performance of toBlob and its complete timeout delay

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

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #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"
 #include "platform/image-encoders/PNGImageEncoder.h"
 #include "platform/threading/BackgroundTaskRunner.h"
 #include "public/platform/Platform.h"
 #include "public/platform/WebScheduler.h"
 #include "public/platform/WebTaskRunner.h"
 #include "public/platform/WebThread.h"
 #include "public/platform/WebTraceLocation.h"
@@ skipping 69 matching lines @@
     : m_data(data)
     , m_size(size)
     , m_mimeType(mimeType)
     , m_callback(callback)
 {
     ASSERT(m_data->length() == (unsigned) (size.height() * size.width() * 4));
     m_encodedImage = adoptPtr(new Vector<unsigned char>());
     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()
 {
 }
 
 void CanvasAsyncBlobCreator::scheduleAsyncBlobCreation(bool canUseIdlePeriodScheduling, const double& quality)
 {
     ASSERT(isMainThread());
 
     if (canUseIdlePeriodScheduling) {
         m_idleTaskStatus = IdleTaskNotStarted;
         if (m_mimeType == MimeTypePng) {
             this->scheduleInitiatePngEncoding();
         } else if (m_mimeType == MimeTypeJpeg) {
             this->scheduleInitiateJpegEncoding(quality);
         } else {
             // Progressive encoding is only applicable to png and jpeg image format,
             // and thus idle tasks scheduling can only be applied to these image formats.
             // TODO(xlai): Progressive encoding on webp image formats (crbug.com/571399)
             ASSERT_NOT_REACHED();
         }
         // 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);
     }
 }
 
 void CanvasAsyncBlobCreator::scheduleInitiateJpegEncoding(const double& quality)
 {
     Platform::current()->mainThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind<double>(&CanvasAsyncBlobCreator::initiateJpegEncoding, this, quality));
 }
@@ skipping 121 matching lines @@
 
 void CanvasAsyncBlobCreator::createBlobAndInvokeCallback()
 {
     ASSERT(isMainThread());
     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));
     // Since toBlob is done, timeout events are no longer needed. So we 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.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()
 {
     ASSERT(isMainThread());
     Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&BlobCallback::handleEvent, m_callback, nullptr));
     // Since toBlob is done (failed), timeout events are no longer needed. So we
     // 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)
 {
     ASSERT(!isMainThread());
     ASSERT(m_mimeType == MimeTypeWebp);
 
     if (!ImageDataBuffer(m_size, m_data->data()).encodeImage("image/webp", quality, m_encodedImage.get())) {
         Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, threadSafeBind(&BlobCallback::handleEvent, wrapCrossThreadPersistent(m_callback.get()), nullptr));
         return;
@@ skipping 15 matching lines @@
 bool CanvasAsyncBlobCreator::initializeJpegStruct(double quality)
 {
     m_jpegEncoderState = JPEGImageEncoderState::create(m_size, quality, m_encodedImage.get());
     if (!m_jpegEncoderState) {
         this->createNullAndInvokeCallback();
         return false;
     }
     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
         // janks) to prevent toBlob being postponed forever in extreme cases.
         m_idleTaskStatus = IdleTaskSwitchedToMainThreadTask;
         signalTaskSwitchInStartTimeoutEventForTesting();
 
         if (m_mimeType == MimeTypePng) {
             if (initializePngStruct()) {
                 Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::encodeRowsPngOnMainThread, this));
@@ skipping 10 matching lines @@
                 this->signalAlternativeCodePathFinishedForTesting();
             }
         }
     } else {
         ASSERT(m_idleTaskStatus == IdleTaskFailed || m_idleTaskStatus == IdleTaskCompleted);
         this->signalAlternativeCodePathFinishedForTesting();
     }
 
 }
 
-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.
         m_idleTaskStatus = IdleTaskSwitchedToMainThreadTask;
         signalTaskSwitchInCompleteTimeoutEventForTesting();
 
         if (m_mimeType == MimeTypePng) {
             Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::encodeRowsPngOnMainThread, this));
         } else {
             ASSERT(m_mimeType == MimeTypeJpeg);
             Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::encodeRowsJpegOnMainThread, this));
         }
     } else {
         ASSERT(m_idleTaskStatus == IdleTaskFailed || m_idleTaskStatus == IdleTaskCompleted);
         this->signalAlternativeCodePathFinishedForTesting();
     }
 }
 
 void CanvasAsyncBlobCreator::postDelayedTaskToMainThread(const WebTraceLocation& location, std::unique_ptr<SameThreadClosure> task, double delayMs)
 {
     DCHECK(isMainThread());
     Platform::current()->mainThread()->getWebTaskRunner()->postDelayedTask(location, std::move(task), delayMs);
 }
 
 } // namespace blink