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..9acbf329a49604997cb615f5f118cbaf6eeccfe0 100644
--- a/third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp
+++ b/third_party/WebKit/Source/platform/testing/ImageDecodeBench.cpp
@@ -10,6 +10,29 @@
 //   % ninja -C out/Release image_decode_bench &&
 //      ./out/Release/image_decode_bench file [iterations]
 //
+// If --raw-output is specified, the output is formatted for use in a .csv file

[scroggo_chromium, 2017/06/13 20:55:57]

- The description seems to imply that this is the default.
- "Otherwise, the output is..."
- This statement is confusing. In truth, the output appears to be a single line
with the mean and the standard deviation. --raw-output allows you to specify a
file to which you write the following data.

[cblume, 2017/06/14 21:18:37]

You are right. I hadn't updated the description after this change was made.

I've updated the description and changed this comment to make a more clear
distinction between the console output and the file output.

+// (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 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 ontop of each other
+// to see how the two measurements compare.
+//
+// It should tell the user 1.) if the change was an improvement, 2.) if so, how
+// much, and 3.) if the measurements are noisy and thus reduce our trust in the
+// improvement.
+//
+// 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.
 //
@@ -17,7 +40,9 @@
 // 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 <cmath>
 #include <memory>
+#include <vector>
 #include "base/command_line.h"
 #include "platform/SharedBuffer.h"
 #include "platform/image-decoders/ImageDecoder.h"
@@ -204,26 +229,120 @@ 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);
+  }
+
+  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");
+
+  fclose(fp);
+}
+
+double GetMean(const IterationsOfFrameTimings& timings) {

[scroggo_chromium, 2017/06/13 20:55:57]

The description explains why we shouldn't average all the frame iterations
together, but here we're doing it anyway.

[cblume, 2017/06/14 21:18:37]

Good point.
After we talked about the central limit theorem handling noise I am less worried
about the process getting swapped out and us not seeing it. Especially since we
added output to tell us our variance / standard deviation.

I spoke to a statistician here at Google (gusl@) and asked for his advice about
what we should track and how. He suggested the ideal thing to track would be the
minimum of a given run. This is because all possible noise is additive. The
minimum should be the noise-free, apples-to-apples ground truth that we can
compare.

But he also said the mean + standard deviation will mirror the minimum if we
make sure our standard deviation is the same before & after. We shouldn't be
introducing noise between runs so this should be fine. (I've timed this before &
after this patch to make sure we didn't change the standard deviation /
variance. I'll send that out later.)

Prior to this patch (without reporting the standard deviation / variance), using
the mean alone was actually a problem. Imagine a situation where we have made an
optimization so the minimum has decreased. However, when we measured we
accidentally increased our variance and effectively kept the mean at the same
place. We wouldn't have known that we didn't run enough iterations for the
central limit theorem to overcome that noise.

I'll update the description.

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

Should we report the min, too?

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

I say yes.
I just didn't want to rock the boat too much -- small steps are easier to
accept. :)

+  size_t count = 0;
+  double total = 0;
+
+  for (const FrameTimings& iteration : timings) {
+    for (double frame_time : iteration) {
+      ++count;
+      total += frame_time;
+    }
+  }
+
+  return total / count;
+}
 
-    int frame_count = decoder->FrameCount();
-    for (int i = 0; i < frame_count; ++i) {
-      if (!decoder->FrameBufferAtIndex(i))
-        return false;
+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 = std::abs(difference);
+      double squared_difference = std::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();
 
-    return !decoder->Failed();
+  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,
+                           ColorBehavior::Ignore());
+
+  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;
@@ -236,20 +355,34 @@ bool DecodeImageData(SharedBuffer* data,
     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 i = 0; i < iterations; ++i) {
+      std::unique_ptr<ImageDecoder> decoder = ImageDecoder::Create(
+          data.Get(), true, ImageDecoder::kAlphaPremultiplied,
+          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");
+          exit(3);
+        }
+        timings[i][next_frame_to_decode] = elapsed_time;
+      }
+
+      if (all_data_received || decoder->Failed()) {

[scroggo_chromium, 2017/06/13 20:55:57]

Wait, why do we print failure and exit if all_data_received?

[cblume, 2017/06/14 21:18:37]

Good question.
all_data_received should not be here.

The current ImageDecodeBench has this line. But rather than printing a failure
and exiting, it uses it to break from the infinite loop. This is how it knows we
have no more packets to test with.

It was my mistake to keep it as-is.

+        fprintf(stderr, "Image decode failed\n");
+        exit(3);
+      }
     }
-
-    if (all_data_received || decoder->Failed())
-      break;
   }
 
-  return !decoder->Failed();
+  return timings;
 }
 
 }  // namespace
@@ -260,16 +393,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] file "

[scroggo_chromium, 2017/06/13 20:55:57]

Maybe "file" should now be "input_file", or "image_file"?

[cblume, 2017/06/14 21:18:37]

Done.

+            "[iterations] [packetSize]\n",
             argv[0]);
     exit(1);
   }
@@ -321,33 +469,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;
 }