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 53 matching lines @@
     } else if (mimeType == "image/webp") {
         mimeTypeEnum = CanvasAsyncBlobCreator::MimeTypeWebp;
     } else {
         mimeTypeEnum = CanvasAsyncBlobCreator::NumberOfMimeTypeSupported;
     }
     return mimeTypeEnum;
 }
 
 } // 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>());
     m_pixelRowStride = size.width() * NumChannelsPng;
     m_idleTaskStatus = IdleTaskNotSupported;
     m_numRowsCompleted = 0;
 }
 
 CanvasAsyncBlobCreator::~CanvasAsyncBlobCreator()
 {
@@ skipping 19 matching lines @@
         // There's no risk of concurrency as both tasks are on main thread.
         this->postDelayedTaskToMainThread(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleTaskStartTimeoutEvent, this, quality), 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)
 {
+    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;
     }
 
     ASSERT(m_idleTaskStatus == IdleTaskNotStarted);
     m_idleTaskStatus = IdleTaskStarted;
 
     if (!initializeJpegStruct(quality)) {
         m_idleTaskStatus = IdleTaskFailed;
         return;
     }
     this->idleEncodeRowsJpeg(deadlineSeconds);
 }
 
 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;
     }
 
     ASSERT(m_idleTaskStatus == IdleTaskNotStarted);
     m_idleTaskStatus = IdleTaskStarted;
 
     if (!initializePngStruct()) {
         m_idleTaskStatus = IdleTaskFailed;
         return;
@@ skipping 17 matching lines @@
         }
         PNGImageEncoder::writeOneRowToPng(inputPixels, m_pngEncoderState.get());
         inputPixels += m_pixelRowStride;
     }
     m_numRowsCompleted = m_size.height();
     PNGImageEncoder::finalizePng(m_pngEncoderState.get());
 
     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();
     }
 }
 
 void CanvasAsyncBlobCreator::idleEncodeRowsJpeg(double deadlineSeconds)
 {
     ASSERT(isMainThread());
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
 
     m_numRowsCompleted = JPEGImageEncoder::progressiveEncodeRowsJpegHelper(m_jpegEncoderState.get(), m_data->data(), m_numRowsCompleted, SlackBeforeDeadline, 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();
         }
     } else if (m_numRowsCompleted == JPEGImageEncoder::ProgressiveEncodeFailed) {
         m_idleTaskStatus = IdleTaskFailed;
         this->createNullAndInvokeCallback();
     } else {
         Platform::current()->currentThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind<double>(&CanvasAsyncBlobCreator::idleEncodeRowsJpeg, this));
     }
@@ skipping 25 matching lines @@
     } else {
         this->createNullAndInvokeCallback();
     }
 
     this->signalAlternativeCodePathFinishedForTesting();
 }
 
 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));
 }
 
 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())) {
@@ skipping 49 matching lines @@
                 Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::encodeRowsJpegOnMainThread, this));
             } else {
                 // Failing in initialization of jpeg struct
                 this->signalAlternativeCodePathFinishedForTesting();
             }
         }
     } else {
         ASSERT(m_idleTaskStatus == IdleTaskFailed || m_idleTaskStatus == IdleTaskCompleted);
         this->signalAlternativeCodePathFinishedForTesting();
     }
-
 }
 
 void CanvasAsyncBlobCreator::idleTaskCompleteTimeoutEvent()
 {
     ASSERT(m_idleTaskStatus != IdleTaskNotStarted);
 
     if (m_idleTaskStatus == IdleTaskStarted) {
         // It has taken too long to complete for the idle task.
         m_idleTaskStatus = IdleTaskSwitchedToMainThreadTask;
         signalTaskSwitchInCompleteTimeoutEventForTesting();
@@ skipping 10 matching lines @@
     }
 }
 
 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