Measure frame decodes more accurately from ImageDecodeBench

third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp

Index: third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp
diff --git a/third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp b/third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp
index 11742a16be9d362831a00d0c6d9890075da9d734..8473e64785964dfa29d96fea7eb778f99749f375 100644
--- a/third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp
+++ b/third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp
@@ -10,6 +10,28 @@
 //   % ninja -C out/Release image_decode_bench &&
 //      ./out/Release/image_decode_bench file [iterations]
 //
+// If --raw-output is specified, the output file provided is formatted for use
+// in a .csv file (comma-separated variable).
+// Each row represents successive frames in an animated image.
+// (frame 0, frame 1, frame 2...)
+// Each column represents a single frame decoded from successive iterations.
+// Iteration 0: (frame 0, frame 1, frame 2...)
+// Iteration 1: (frame 0, frame 1, frame 2...)
+//
+// This means non-animated images will show up as one column.
+//
+// This .csv-formatted output file is a common format for spreadsheet and data
+// visualization programs. A user can take timings before and after a change,
+// import the two .csv files, and overlay their line graphs on top of each other
+// to see how the two measurements compare.
+//
+// Visualizing the measurements can provide insight into things like an
+// intermittent noise source or an unexpected measurement.
+//
+// Each frame is different and so comparing separate frames may not be fruitful.
+// For example, frame 1 may cover a large area and require more time to decode.
+// Frame 2 may have a small rect and be faster to decode.
+//
 // TODO(noel): Consider adding md5 checksum support to WTF. Use it to compute
 // the decoded image frame md5 and output that value.
 //
@@ -18,6 +40,7 @@
 // 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"
@@ -204,52 +227,164 @@ PassRefPtr<SharedBuffer> ReadFile(const char* file_name) {
   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);
+// 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>;
+using IterationsOfFrameTimings = std::vector<FrameTimings>;
+
+void Write2DResultsToFile(const IterationsOfFrameTimings& timings,
+                          const char* file_name) {
+  FILE* fp = fopen(file_name, "wb");
+  if (!fp) {
+    fprintf(stderr, "Can't open file %s\n", file_name);
+    exit(2);
+  }
 
-    int frame_count = decoder->FrameCount();
-    for (int i = 0; i < frame_count; ++i) {
-      if (!decoder->FrameBufferAtIndex(i))
-        return false;
+  FrameTimings first_iteration = timings[0];
+  for (size_t i = 0; i < first_iteration.size(); ++i) {
+    fprintf(fp, "\"Frame %zu\",", i);
+  }
+  fprintf(fp, "\n");
+
+  for (const FrameTimings& iteration : timings) {
+    for (double frame_time : iteration) {
+      fprintf(fp, "%f,", frame_time);
     }
+    fprintf(fp, "\n");
+  }
+  fprintf(fp, "\n");
 
-    return !decoder->Failed();
+  fclose(fp);
+}
+
+double GetMean(const IterationsOfFrameTimings& timings) {
+  size_t count = 0;
+  double total = 0;
+
+  for (const FrameTimings& iteration : timings) {
+    for (double frame_time : iteration) {
+      ++count;
+      total += frame_time;
+    }
   }
 
+  return total / count;
+}
+
+double GetStandardDeviation(const IterationsOfFrameTimings& timings,
+                            double mean) {
+  size_t count = 0;
+  double squared_difference_sum = 0;
+
+  for (const FrameTimings& iteration : timings) {
+    for (double frame_time : iteration) {
+      double difference = frame_time - mean;
+      double absolute_difference = fabs(difference);
+      double squared_difference = pow(absolute_difference, 2);
+      ++count;
+      squared_difference_sum += squared_difference;
+    }
+  }
+
+  return std::sqrt(squared_difference_sum / count);
+}
+
+IterationsOfFrameTimings TimeDecode(PassRefPtr<SharedBuffer> data,
+                                    bool apply_color_correction,
+                                    size_t iterations) {
+  // Find total frame count.
+  std::unique_ptr<ImageDecoder> frame_count_decoder =
+      ImageDecoder::Create(data.Get(), true, ImageDecoder::kAlphaPremultiplied,
+                           ColorBehavior::Ignore());
+  size_t frame_count = frame_count_decoder->FrameCount();
+
+  IterationsOfFrameTimings timings(iterations, FrameTimings(frame_count, 0.0));
+
+  for (size_t i = 0; i < iterations; ++i) {
+    std::unique_ptr<ImageDecoder> decoder = ImageDecoder::Create(
+        data.Get(), true, ImageDecoder::kAlphaPremultiplied,
+        apply_color_correction ? ColorBehavior::TransformToTargetForTesting()
+                               : ColorBehavior::Ignore());
+    bool all_data_received = true;
+    decoder->SetData(data.Get(), all_data_received);
+    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) {
+        fprintf(stderr, "Image decode failed\n");
+        exit(3);
+      }
+      timings[i][frame_index] = elapsed_time;
+    }
+  }
+
+  return timings;
+}
+
+// This function mimics deferred decoding in Chromium when not all data has been
+// received yet.
+IterationsOfFrameTimings TimePacketedDecode(PassRefPtr<SharedBuffer> data,
+                                            bool apply_color_correction,
+                                            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,

[scroggo_chromium, 2017/06/15 14:03:50]

Why not move "total_all_data_received" up here and use it here instead of
"true"?

[cblume, 2017/07/05 08:57:55]

Done.

+                           ColorBehavior::Ignore());
+
+  bool total_all_data_received = true;
+  frame_count_decoder->SetData(data.Get(), total_all_data_received);

[scroggo_chromium, 2017/06/15 14:03:51]

This line is unnecessary. Create has already set the data.

[cblume, 2017/07/05 08:57:55]

Done.

+  size_t total_frame_count = frame_count_decoder->FrameCount();

[scroggo_chromium, 2017/06/15 14:03:50]

The start of this method looks like it could use a refactor into its own method:

size_t GetFrameCount(PassRefPtr<SharedBuffer> data) {
  auto decoder = ImageDecoder::Create(...);
  if (!decoder) {
    fprintf(stderr, "Image decode failed\n");
    exit(3);
  }
  size_t frame_count = decoder->FrameCount();
  if (decoder->Failed()) {
    fprintf(stderr, "Image decode failed\n");
    exit(3);
  }
  return frame_count;
}

(I also added some failure cases. You currently catch the Failed() piece later.
Without the null check, we'd see a crash if you passed a file that is not an
image file we can decode. Maybe it's fine to leave that one out especially (user
error.))

[cblume, 2017/07/05 08:57:55]

Done.

+
+  IterationsOfFrameTimings timings(iterations,
+                                   FrameTimings(total_frame_count, 0.0));
+
   RefPtr<SharedBuffer> packet_data = SharedBuffer::Create();

[scroggo_chromium, 2017/06/15 14:03:51]

I think these three variables need to be inside the iterations loop. Otherwise,
you'll end up with a SharedBuffer that has the image repeated over and over
again. (And all_data_received will be false for all iterations beyond the first,
since position > data->size().)

[cblume, 2017/07/05 08:57:55]

Done.

   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)
+  for (size_t i = 0; i < iterations; ++i) {
+    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();
+
+      std::unique_ptr<ImageDecoder> decoder = ImageDecoder::Create(
+          data.Get(), true, ImageDecoder::kAlphaPremultiplied,

[scroggo_chromium, 2017/06/15 14:03:51]

The second parameter here is whether all the data has been received. So you
probably don't want true here, you want all_data_received.

Stepping back, though, what are we timing here? I *think* the goal is to create
a decoder, and then pass the data in packets, but that doesn't look to be what's
happening here. Instead, you're creating a new decoder with each packet.

You've moved the iterations loop inside this method, but it should still have
the same structure as the old way of doing it:

foreach iteration:
  decoder = ImageDecoder::Create()
  SharedBufffer packet_data;
  while true:
    packet_data->append(packet_size)
    DecodeTheFramesWeCan

[cblume, 2017/07/05 08:57:55]

Good catch.
I'm embarrassed. :) Thank you for seeing this.

+          apply_color_correction ? ColorBehavior::TransformToTargetForTesting()
+                                 : ColorBehavior::Ignore());
+      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) {
+        double start_time = GetCurrentTime();
+        ImageFrame* frame = decoder->FrameBufferAtIndex(next_frame_to_decode);
+        double elapsed_time = GetCurrentTime() - start_time;
+        if (frame->GetStatus() != ImageFrame::kFrameComplete) {
+          fprintf(stderr, "Image decode failed\n");

[scroggo_chromium, 2017/06/15 14:03:51]

In the old code, this was a "break" - we haven't decoded a full frame, so we
wait until we have more data. Why did you make this a failure case?

[Noel Gordon, 2017/06/16 17:32:56]

Good spot.  A second question is: why are we measuring the time of each frame of
multi-frame image anyway?  What does it buy us? 

Some frames of an animated image will cost X time to decode, some will cost X/10
to decode because they are a delta.  Most delta frames are relatively fast to
decode, which is the whole point of animated image formats.

Can't help thinking that all we want to know is how long does it take to decode
all frames of the given image.  And the code would be a hell of a lot simpler if
we did that (see code left).

[cblume, 2017/07/05 08:57:55]

Whoops. This shouldn't be a failure case.
When we added early exits in patch set 8 I accidentally added this.
Fixed.

+          exit(3);
+        }
+        timings[i][next_frame_to_decode] = elapsed_time;
+      }
+
+      if (all_data_received || decoder->Failed()) {

[scroggo_chromium, 2017/06/15 14:03:50]

In patch set 16 you said all_data_received should be removed from this line.
With it here, it seems like we would always hit this case eventually.

[cblume, 2017/07/05 08:57:55]

Done.

+        fprintf(stderr, "Image decode failed\n");
+        exit(3);
+      }
+
+      if (all_data_received)
         break;
     }
-
-    if (all_data_received || decoder->Failed())
-      break;
   }
 
-  return !decoder->Failed();
+  return timings;
 }
 
 }  // namespace
@@ -260,16 +395,31 @@ int Main(int argc, char* 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);
   }
 
+  const char* raw_output_file = nullptr;
+  if (argc >= 2 && strcmp(argv[1], "--raw-output") == 0) {
+    if (argc < 3) {
+      fprintf(stderr,
+              "--raw-output specified without also specifying a file after it");
+      exit(1);
+    }
+
+    raw_output_file = argv[2];
+    argc -= 2;
+    argv += 2;
+  }
+
   if (argc < 2) {
     fprintf(stderr,
-            "Usage: %s [--color-correct] file [iterations] [packetSize]\n",
+            "Usage: %s [--color-correct] [--raw-output output_file] image_file "
+            "[iterations] [packetSize]\n",
             argv[0]);
     exit(1);
   }
@@ -321,33 +471,22 @@ int Main(int argc, char* argv[]) {
 
   data->Data();
 
-  // Warm-up: throw out the first iteration for more consistent results.
-
-  if (!DecodeImageData(data.Get(), apply_color_correction, packet_size)) {
-    fprintf(stderr, "Image decode failed [%s]\n", argv[1]);
-    exit(3);
+  IterationsOfFrameTimings timings;
+  if (packet_size) {
+    timings = TimePacketedDecode(data.Get(), apply_color_correction,
+                                 packet_size, iterations);
+  } else {
+    timings = TimeDecode(data.Get(), apply_color_correction, iterations);
   }
 
-  // Image decode bench for iterations.
-
-  double total_time = 0.0;
+  if (raw_output_file)
+    Write2DResultsToFile(timings, raw_output_file);
 
-  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);
-    }
-  }
+  double mean = GetMean(timings);
+  double standard_deviation = GetStandardDeviation(timings, mean);
 
-  // Results to stdout.
+  printf("mean: %f standard deviation: %f\n", mean, standard_deviation);
 
-  double average_time = total_time / static_cast<double>(iterations);
-  printf("%f %f\n", total_time, average_time);
   return 0;
 }