Measure frame decodes more accurately from ImageDecodeBench

third_party/WebKit/Source/platform/testing/ImageDecodeBench.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.
 
 // Provides a minimal wrapping of the Blink image decoders. Used to perform
 // a non-threaded, memory-to-memory image decode using micro second accuracy
 // clocks to measure image decode time. Optionally applies color correction
 // during image decoding on supported platforms (default off). Usage:
 //
 //   % ninja -C out/Release image_decode_bench &&
 //      ./out/Release/image_decode_bench file [iterations]
 //
+// The output is formatted for use in a csv file (comma-separated variable).
+// Each row represents suceessive frames in an animated image.

[scroggo_chromium, 2017/05/22 13:07:40]

successive*

[cblume, 2017/05/23 00:43:56]

Done.

+// Each column represents a successive iteration of decoding the whole animated

[scroggo_chromium, 2017/05/22 13:07:40]

I don't think this is correct. A row shows a single time for each frame.
The second row shows a single time for each frame (on the second iteration). So
a column represents all the times for a single frame, right?

[cblume, 2017/05/23 00:43:56]

Hrmmm I think this comment is correct.

With the names below,
FrameTimings = std::vector<double>
IterationsOfFrameTimings = std::vector<FrameTimings>

And Print2DResults:
for (FrameTimings iteration : timings) {
  for (double frame_time : iteration) {
    printf("%f,", frame_time);
  }
  printf("\n");

(The code currently has const std::vector<double>& in the outer loop instead of
FrameTimings. I'm going to fix that to clarify.)

So with the names and print, it should be printing a row of frame times before
continuing to the next row for the next iteration.

This was intentional: Google Sheets allows you to use =ARRAYFORMULA for columns
but not rows. And you'll want to compare frame 1 with other frame 1s to trim out
noise if necessary. So I want each column to represent that frame.

Anyway, the other part of this I should check is if we're filling the vector in
this order as well. TimeDecode() fills the inner-vector with animation frame N.
So does TimePacketedDecode().

Yeah, I think this comment is correct.

[scroggo_chromium, 2017/05/23 15:42:23]

Agreed. This is covered by the comment above. ("Each row represents suceessive
frames in an animated image.")
In
https://codereview.chromium.org/2880953002/diff/1/third_party/WebKit/Source/p...
I asked how you are visualizing the data. This comment answers that question,
and I think would be helpful in the code.
That's my interpretation of what it does. Just to be clear, when you say
"frame", you mean an |ImageFrame|, as returned by
ImageDecoder::FrameBufferAtIndex, right? The comment says "Each column
represents a successive iteration of decoding *the whole animated image*"
(emphasis mine). "The whole animated image" does not sound like a single frame,
it sounds like all of the frames.
My interpretation of this code review comment is that a column represents a
single frame. That's not what the comment in the code sounds like to me.

[cblume, 2017/05/23 19:44:34]

That is probably a good idea.
I'll add comments after the "this is csv formatted" to help the user understand
how to then use the data.
Yes, I mean an individual frame.

Hrmmm I guess this is not very clear, huh?

What I mean is column 0 represents frame 0. Column 1 represents frame 1.

Each entry in the column is a separate timing.
And the timing happens after all the other animation frames have been decoded.
So (0,0) is the first frame and first iteration. This code will decode the rest
of the animation frames before decoding (0,1) which is the first frame of the
second iteration.

That is why I mentioned the whole image. But I think mentioning that makes
things less clear.

I'll change it to:
"Each column represents a single frame decoded from successive iterations."

In fact, I think I want to add examples.
"Each row represents successive frames in an animated image.
(frame 1, frame 2, frame 3...)
Each column represents a single frame decoded from successive iterations.
Iteration 1: (frame 1, frame 2, frame 3...)
Iteration 2: (frame 1, frame 2, frame 3...)"

+// image.
+// This means non-animated images will show up as a column.

[scroggo_chromium, 2017/05/22 13:07:40]

nit: Instead of saying "as a column", I think it would be clearer to say either
"as a single column" or "as one column".

[cblume, 2017/05/23 00:43:56]

Done.

+// Raster timing also shows up as a column.

[scroggo_chromium, 2017/05/22 13:07:40]

Since you've moved raster timing to its own patch, this comment is no longer
necessary here.

[cblume, 2017/05/23 00:43:56]

Done.

+//
 // TODO(noel): Consider adding md5 checksum support to WTF. Use it to compute
 // the decoded image frame md5 and output that value.
 //
 // TODO(noel): Consider integrating this tool in Chrome telemetry for realz,
 // using the image corpii used to assess Blink image decode performance. Refer
 // to http://crbug.com/398235#c103 and http://crbug.com/258324#c5
 
 #include <memory>
+#include <vector>
 #include "base/command_line.h"
 #include "platform/SharedBuffer.h"
 #include "platform/image-decoders/ImageDecoder.h"
 #include "platform/wtf/PassRefPtr.h"
 #include "platform/wtf/PtrUtil.h"
 #include "public/platform/Platform.h"
 #include "ui/gfx/test/icc_profiles.h"
 
 #if defined(_WIN32)
 #include <mmsystem.h>
@@ skipping 166 matching lines @@
       WrapArrayUnique(new unsigned char[file_size]);
   if (file_size != fread(buffer.get(), 1, file_size, fp)) {
     fprintf(stderr, "Error reading file %s\n", file_name);
     exit(2);
   }
 
   fclose(fp);
   return SharedBuffer::Create(buffer.get(), file_size);
 }
 
-bool DecodeImageData(SharedBuffer* data,
-                     bool color_correction,
-                     size_t packet_size) {
-  std::unique_ptr<ImageDecoder> decoder = ImageDecoder::Create(
-      data, true, ImageDecoder::kAlphaPremultiplied,
-      color_correction ? ColorBehavior::TransformToTargetForTesting()
-                       : ColorBehavior::Ignore());
-  if (!packet_size) {
-    bool all_data_received = true;
-    decoder->SetData(data, all_data_received);
+using FrameTimings = std::vector<double>;

[scroggo_chromium, 2017/05/22 13:07:40]

The names help, but I think a comment here might be useful, too. Something like:

// This vector represents a single iteration of one (possibly animated)
// image. Each entry is a single timing of a single frame.
using FrameTimings = std::vector<double>;

I thought about suggesting a comment for the second one, but I think it's pretty
clear once you know what a FrameTiming is.

[cblume, 2017/05/23 00:43:56]

I agree. Your suggested comment is very clear. Thank you.
Done.

+using IterationsOfFrameTimings = std::vector<FrameTimings>;
 
-    int frame_count = decoder->FrameCount();
-    for (int i = 0; i < frame_count; ++i) {
-      if (!decoder->FrameBufferAtIndex(i))
-        return false;
+void Print2DResults(const IterationsOfFrameTimings& timings) {
+  for (const std::vector<double>& iteration : timings) {
+    for (double frame_time : iteration) {
+      printf("%f,", frame_time);
     }
+    printf("\n");
+  }
+  printf("\n");
+}
 
-    return !decoder->Failed();
+void TimeDecode(ImageDecoder* decoder,
+                PassRefPtr<SharedBuffer> data,
+                size_t iterations) {
+  bool all_data_received = true;
+  decoder->SetData(data.Get(), all_data_received);
+
+  size_t frame_count = decoder->FrameCount();
+
+  IterationsOfFrameTimings timings(iterations, FrameTimings(frame_count, 0.0));
+
+  for (size_t iteration = 0; iteration < iterations; ++iteration) {
+    for (size_t frame_index = 0; frame_index < frame_count; ++frame_index) {
+      double start_time = GetCurrentTime();
+      ImageFrame* frame = decoder->FrameBufferAtIndex(frame_index);
+      double elapsed_time = GetCurrentTime() - start_time;
+      if (frame->GetStatus() != ImageFrame::kFrameComplete) {

[scroggo_chromium, 2017/05/22 13:07:40]

Should this print an error message?

[cblume, 2017/05/23 00:43:56]

Done.
I also am using exit(3); to mirror current behavior as closely as I can.

+        return;
+      }
+      timings[iteration][frame_index] = elapsed_time;
+    }
   }
 
+  Print2DResults(timings);
+}
+
+// This function mimics deferred decoding in Chromium when not all data has been
+// received yet.
+void TimePacketedDecode(ImageDecoder* decoder,
+                        PassRefPtr<SharedBuffer> data,
+                        size_t packet_size,
+                        size_t iterations) {
+  // Find total frame count.
+  // Doing this requires a decoder with full data (no packet size).
+  std::unique_ptr<ImageDecoder> frame_count_decoder =
+      ImageDecoder::Create(data.Get(), true, ImageDecoder::kAlphaPremultiplied,
+                           ColorBehavior::Ignore());
+
+  constexpr bool total_all_data_received = true;
+  frame_count_decoder->SetData(data.Get(), total_all_data_received);
+  size_t total_frame_count = frame_count_decoder->FrameCount();
+
+  IterationsOfFrameTimings timings(iterations,
+                                   FrameTimings(total_frame_count, 0.0));
+
   RefPtr<SharedBuffer> packet_data = SharedBuffer::Create();
   size_t position = 0;
   size_t next_frame_to_decode = 0;
   while (true) {
     const char* packet;
     size_t length = data->GetSomeData(packet, position);
 
     length = std::min(length, packet_size);
     packet_data->Append(packet, length);
     position += length;
 
     bool all_data_received = position == data->size();
-    decoder->SetData(packet_data.Get(), all_data_received);
 
     size_t frame_count = decoder->FrameCount();
-    for (; next_frame_to_decode < frame_count; ++next_frame_to_decode) {
-      ImageFrame* frame = decoder->FrameBufferAtIndex(next_frame_to_decode);
-      if (frame->GetStatus() != ImageFrame::kFrameComplete)
-        break;
+    for (size_t iteration = 0; iteration < iterations; ++iteration) {

[scroggo_chromium, 2017/05/22 13:07:40]

nit: I think this would be easier to follow if you changed "iteration" to "i".

[cblume, 2017/05/23 00:43:56]

Done.

+      for (; next_frame_to_decode < frame_count; ++next_frame_to_decode) {
+        decoder->SetData(packet_data.Get(), all_data_received);
+        double start_time = GetCurrentTime();
+        ImageFrame* frame = decoder->FrameBufferAtIndex(next_frame_to_decode);
+        double elapsed_time = GetCurrentTime() - start_time;
+        if (frame->GetStatus() != ImageFrame::kFrameComplete)
+          break;
+        timings[iteration][next_frame_to_decode] = elapsed_time;
+        decoder->SetData(PassRefPtr<SegmentReader>(nullptr), false);
+        decoder->ClearCacheExceptFrame(next_frame_to_decode);

[scroggo_chromium, 2017/05/22 13:07:40]

I thought we had agreed to remove this? Was that on a different CL?

[cblume, 2017/05/23 00:43:56]

Right.
I thought I had removed it, too.
It looks like it was a different CL:
https://codereview.chromium.org/2880533002
That CL is upstream of this one. So we should pick this up when I rebase in a
bit.

[scroggo_chromium, 2017/05/23 15:42:23]

I don't think rebasing works the way you expect. This CR shows that you are
adding this line.

[cblume, 2017/05/23 19:44:34]

Right. I hadn't rebased by the time you saw this line here.
But I also didn't check *after* rebasing and it is still there. It looks like
the auto-rebase didn't pick it up since things had been moved around.

I'll remove it.
Thanks for spotting this.

+      }
     }
 
     if (all_data_received || decoder->Failed())

[scroggo_chromium, 2017/05/22 13:07:40]

Should this print an error statement?

[cblume, 2017/05/23 00:43:56]

Done.

-      break;
+      return;
   }
 
-  return !decoder->Failed();
+  Print2DResults(timings);
 }
 
 }  // namespace
 
 int Main(int argc, char* argv[]) {
   base::CommandLine::Init(argc, argv);
 
   // If the platform supports color correction, allow it to be controlled.
 
   bool apply_color_correction = false;
-
   if (argc >= 2 && strcmp(argv[1], "--color-correct") == 0) {
-    apply_color_correction = (--argc, ++argv, true);
+    --argc;
+    ++argv;
+    apply_color_correction = true;
     gfx::ICCProfile profile = gfx::ICCProfileForTestingColorSpin();
     ColorBehavior::SetGlobalTargetColorProfile(profile);
   }
 
   if (argc < 2) {
     fprintf(stderr,
             "Usage: %s [--color-correct] file [iterations] [packetSize]\n",
             argv[0]);
     exit(1);
   }
@@ skipping 38 matching lines @@
   // segments into one, contiguous block of memory.
 
   RefPtr<SharedBuffer> data = ReadFile(argv[1]);
   if (!data.Get() || !data->size()) {
     fprintf(stderr, "Error reading image data from [%s]\n", argv[1]);
     exit(2);
   }
 
   data->Data();
 
-  // Warm-up: throw out the first iteration for more consistent results.
+  // Image decode bench for iterations.
 
-  if (!DecodeImageData(data.Get(), apply_color_correction, packet_size)) {
-    fprintf(stderr, "Image decode failed [%s]\n", argv[1]);
-    exit(3);
+  std::unique_ptr<ImageDecoder> decoder = ImageDecoder::Create(
+      data, true, ImageDecoder::kAlphaPremultiplied,
+      apply_color_correction ? ColorBehavior::TransformToTargetForTesting()
+                             : ColorBehavior::Ignore());
+  if (packet_size) {
+    blink::TimePacketedDecode(decoder.get(), data.Get(), packet_size,

[scroggo_chromium, 2017/05/22 13:07:40]

This whole file looks to be inside namespace blink, so "blink::" is not
necessary here.

[cblume, 2017/05/23 00:43:56]

Done.

+                              iterations);
+  } else {
+    blink::TimeDecode(decoder.get(), data.Get(), iterations);
   }
 
-  // Image decode bench for iterations.
-
-  double total_time = 0.0;
-
-  for (size_t i = 0; i < iterations; ++i) {
-    double start_time = GetCurrentTime();
-    bool decoded =
-        DecodeImageData(data.Get(), apply_color_correction, packet_size);
-    double elapsed_time = GetCurrentTime() - start_time;
-    total_time += elapsed_time;
-    if (!decoded) {
-      fprintf(stderr, "Image decode failed [%s]\n", argv[1]);
-      exit(3);
-    }
-  }
-
-  // Results to stdout.
-
-  double average_time = total_time / static_cast<double>(iterations);
-  printf("%f %f\n", total_time, average_time);
   return 0;
 }
 
 }  // namespace blink
 
 int main(int argc, char* argv[]) {
   return blink::Main(argc, argv);
 }