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 54 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 = wrapUnique(new Vector<unsigned char>());
     m_pixelRowStride = size.width() * NumChannelsPng;
     m_idleTaskStatus = IdleTaskNotSupported;
     m_numRowsCompleted = 0;
 }
 
 CanvasAsyncBlobCreator::~CanvasAsyncBlobCreator()
 {
@@ skipping 27 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(&CanvasAsyncBlobCreator::initiateJpegEncoding, this, quality));
 }
 
 void CanvasAsyncBlobCreator::initiateJpegEncoding(const double& quality, double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGInitiateEncodingCounter, ("Blink.Canvas.ToBlob.InitiateEncodingDelay.JPEG", 0, 10000000, 50));
+    toBlobJPEGInitiateEncodingCounter.count((WTF::monotonicallyIncreasingTime() - 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(&CanvasAsyncBlobCreator::initiatePngEncoding, this));
 }
 
 void CanvasAsyncBlobCreator::initiatePngEncoding(double deadlineSeconds)
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGInitiateEncodingCounter, ("Blink.Canvas.ToBlob.InitiateEncodingDelay.PNG", 0, 10000000, 50));
+    toBlobPNGInitiateEncodingCounter.count((WTF::monotonicallyIncreasingTime() - m_scheduleInitiateStartTime) * 1000000.0);
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
 
     ASSERT(m_idleTaskStatus == IdleTaskNotStarted);
     m_idleTaskStatus = IdleTaskStarted;
 
     if (!initializePngStruct()) {
         m_idleTaskStatus = IdleTaskFailed;
         return;
     }
     this->idleEncodeRowsPng(deadlineSeconds);
 }
 
 void CanvasAsyncBlobCreator::idleEncodeRowsPng(double deadlineSeconds)
 {
     ASSERT(isMainThread());
     if (m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask) {
         return;
     }
 
+    double startTime = WTF::monotonicallyIncreasingTime();

[xlai (Olivia), 2016/06/24 14:56:09]

put this back.

     unsigned char* inputPixels = m_data->data() + m_pixelRowStride * m_numRowsCompleted;
     for (int y = m_numRowsCompleted; y < m_size.height(); ++y) {
         if (isDeadlineNearOrPassed(deadlineSeconds)) {
             m_numRowsCompleted = y;
+            m_elapsedTime += (WTF::monotonicallyIncreasingTime() - startTime);

[xlai (Olivia), 2016/06/24 14:56:09]

Put this back.

             Platform::current()->currentThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleEncodeRowsPng, this));
             return;
         }
         PNGImageEncoder::writeOneRowToPng(inputPixels, m_pngEncoderState.get());
         inputPixels += m_pixelRowStride;
     }
     m_numRowsCompleted = m_size.height();
     PNGImageEncoder::finalizePng(m_pngEncoderState.get());
 
     m_idleTaskStatus = IdleTaskCompleted;
+    DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobPNGIdleEncodeCounter, ("Blink.Canvas.ToBlob.IdleEncodeDuration.PNG", 0, 10000000, 50));
+    toBlobPNGIdleEncodeCounter.count(m_elapsedTime * 1000000.0);

[xlai (Olivia), 2016/06/23 17:07:37]

I think there is a logic flaw. Think of the scenario when in the last
idleEncodeRowsPng() call, the encoding finishes the last few rows of encoding
without hitting the deadline in that particular idle period, so the above
addition to m_elapsedTime at Line 201 is not executed. Then in here, the
recording will miss out the time spent in the last idleEncodeRowsPng() call.

[xidachen, 2016/06/24 11:17:52]

Good catch, the new patch should have that fixed.

 
     if (isDeadlineNearOrPassed(deadlineSeconds)) {
         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;
     }
 
+    double startTime = WTF::monotonicallyIncreasingTime();
     m_numRowsCompleted = JPEGImageEncoder::progressiveEncodeRowsJpegHelper(m_jpegEncoderState.get(), m_data->data(), m_numRowsCompleted, SlackBeforeDeadline, deadlineSeconds);
     if (m_numRowsCompleted == m_size.height()) {
         m_idleTaskStatus = IdleTaskCompleted;
+        DEFINE_STATIC_LOCAL(CustomCountHistogram, toBlobJPEGIdleEncodeCounter, ("Blink.Canvas.ToBlob.IdleEncodeDuration.JPEG", 0, 10000000, 50));
+        toBlobJPEGIdleEncodeCounter.count(m_elapsedTime * 1000000.0);
         if (isDeadlineNearOrPassed(deadlineSeconds)) {
             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 {
+        m_elapsedTime += (WTF::monotonicallyIncreasingTime() - startTime);

[xlai (Olivia), 2016/06/23 17:07:37]

There is also a logic flaw here similar to the PNG one but the solution may be
different. The function JPEGImageEncoder::progressiveEncodeRowsJpegHelper() will
stop when it uses up the deadlineSeconds passed into it. If it manages to
complete all encoding, you'll never hit the Line 244 and so your m_elapsedTime
does not record the time spent in encoding. My suggestion for this one would be
to move Line 244 to the position between Line 230 and Line 231. In that way, you
accumulate m_elapsedTime regardless of failed, complete, in-progress status.

[xidachen, 2016/06/24 11:17:52]

Done.

         Platform::current()->currentThread()->scheduler()->postIdleTask(BLINK_FROM_HERE, bind(&CanvasAsyncBlobCreator::idleEncodeRowsJpeg, this));
     }
 }
 
 void CanvasAsyncBlobCreator::encodeRowsPngOnMainThread()
 {
     ASSERT(m_idleTaskStatus == IdleTaskSwitchedToMainThreadTask);
 
     // Continue encoding from the last completed row
     unsigned char* inputPixels = m_data->data() + m_pixelRowStride * m_numRowsCompleted;
@@ skipping 17 matching lines @@
     } else {
         this->createNullAndInvokeCallback();
     }
 
     this->signalAlternativeCodePathFinishedForTesting();
 }
 
 void CanvasAsyncBlobCreator::createBlobAndInvokeCallback()
 {
     ASSERT(isMainThread());
+    DEFINE_STATIC_LOCAL(EnumerationHistogram, toBlobIdleTaskStatus, ("Blink.Canvas.ToBlob.IdleTaskStatus", IdleTaskNotSupported));
+    toBlobIdleTaskStatus.count(m_idleTaskStatus);

[xlai (Olivia), 2016/06/23 17:07:37]

You miss out the case when m_idleTaskStatus==IdleTaskFailed because
createBlobAndInvokeCallback() is only executed when idle encoding succeeds.

[xidachen, 2016/06/24 11:17:52]

Done.

+
+    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, wrapPersistent(m_callback.get()), resultBlob));
     // Avoid unwanted retention, see dispose().
     dispose();
 }
 
 void CanvasAsyncBlobCreator::createNullAndInvokeCallback()
 {
     ASSERT(isMainThread());
     Platform::current()->mainThread()->getWebTaskRunner()->postTask(BLINK_FROM_HERE, bind(&BlobCallback::handleEvent, wrapPersistent(m_callback.get()), nullptr));
@@ skipping 59 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