Add a simple Profiler and instrument operator invocations in Interpreter.

PiperOrigin-RevId: 193133955

5 files changed, 575 insertions, 0 deletions

diff --git a/tensorflow/contrib/lite/profiling/BUILD b/tensorflow/contrib/lite/profiling/BUILD
new file mode 100644
index 0000000000..15999e5d41
--- /dev/null
+++ b/tensorflow/contrib/lite/profiling/BUILD
@@ -0,0 +1,44 @@
+package(default_visibility = ["//visibility:public"])
+
+licenses(["notice"])  # Apache 2.0
+
+common_copts = [
+    "-Wall",
+]
+
+cc_library(
+    name = "profiler",
+    hdrs = ["profiler.h"],
+    copts = common_copts,
+    deps = [":profile_buffer"],
+)
+
+cc_test(
+    name = "profiler_test",
+    srcs = ["profiler_test.cc"],
+    copts = ["-DTFLITE_PROFILING_ENABLED"],
+    defines = ["TFLITE_PROFILING_ENABLED"],
+    deps = [
+        ":profiler",
+        "//tensorflow/contrib/lite/testing:util",
+        "@com_google_googletest//:gtest",
+    ],
+)
+
+cc_library(
+    name = "profile_buffer",
+    hdrs = ["profile_buffer.h"],
+    copts = common_copts,
+)
+
+cc_test(
+    name = "profile_buffer_test",
+    srcs = ["profile_buffer_test.cc"],
+    copts = ["-DTFLITE_PROFILING_ENABLED"],
+    defines = ["TFLITE_PROFILING_ENABLED"],
+    deps = [
+        ":profile_buffer",
+        "//tensorflow/contrib/lite/testing:util",
+        "@com_google_googletest//:gtest",
+    ],
+)
diff --git a/tensorflow/contrib/lite/profiling/profile_buffer.h b/tensorflow/contrib/lite/profiling/profile_buffer.h
new file mode 100644
index 0000000000..3bfe02571b
--- /dev/null
+++ b/tensorflow/contrib/lite/profiling/profile_buffer.h
@@ -0,0 +1,150 @@
+/* Copyright 2018 The TensorFlow Authors. All Rights Reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+==============================================================================*/
+#ifndef TENSORFLOW_CONTRIB_LITE_PROFILING_PROFILE_BUFFER_H_
+#define TENSORFLOW_CONTRIB_LITE_PROFILING_PROFILE_BUFFER_H_
+
+#include <cstddef>
+#include <cstdint>
+
+namespace tflite {
+namespace profiling {
+
+// A profiling event.
+struct ProfileEvent {
+  // Describes the type of event.
+  // The event_metadata field may contain additional data for interpreting
+  // the event.
+  enum class EventType {
+    // Default event type, the metadata field has no special significance.
+    DEFAULT = 0,
+    // The event is an operator invocation and the event_metadata field is the
+    // index of operator node.
+    OPERATOR_INVOKE_EVENT = 1
+  };
+
+  // Label of the event. This usually describes the event.
+  const char* tag;
+  // Timestamp in microseconds when the event began.
+  int64_t begin_timestamp_ms;
+  // Timestamp in microseconds when the event ended.
+  int64_t end_timestamp_ms;
+  // The field containing the type of event. This must be one of the event types
+  // in EventType.
+  EventType event_type;
+  // Extra data describing the details of the event.
+  uint32_t event_metadata;
+};
+}  // namespace profiling
+}  // namespace tflite
+
+#ifdef TFLITE_PROFILING_ENABLED
+
+#include <sys/time.h>
+#include <vector>
+
+namespace tflite {
+namespace profiling {
+constexpr uint32_t kInvalidEventHandle = static_cast<uint32_t>(~0) - 1;
+
+// A ring buffer of profile events.
+// This class is not thread safe.
+class ProfileBuffer {
+ public:
+  ProfileBuffer(uint32_t max_num_entries, bool enabled)
+      : enabled_(enabled), current_index_(0), event_buffer_(max_num_entries) {}
+
+  // Adds an event to the buffer with begin timestamp set to the current
+  // timestamp. Returns a handle to event that can be used to call EndEvent. If
+  // buffer is disabled this has no affect.
+  // The tag of the event should remain valid till the buffer is valid.
+  uint32_t BeginEvent(const char* tag, ProfileEvent::EventType event_type,
+                      uint32_t event_metadata) {
+    if (!enabled_) {
+      return kInvalidEventHandle;
+    }
+    int64_t timestamp = NowMicros();
+    int index = current_index_ % event_buffer_.size();
+    event_buffer_[index].tag = tag;
+    event_buffer_[index].event_type = event_type;
+    event_buffer_[index].event_metadata = event_metadata;
+    event_buffer_[index].begin_timestamp_ms = timestamp;
+    event_buffer_[index].end_timestamp_ms = 0;
+    current_index_++;
+    return index;
+  }
+
+  // Sets the enabled state of buffer to |enabled|
+  void SetEnabled(bool enabled) { enabled_ = enabled; }
+
+  // Sets the end timestamp for event for the handle to current time.
+  // If the buffer is disabled or previous event has been overwritten this
+  // operation has not effect.
+  void EndEvent(uint32_t event_handle) {
+    if (!enabled_ || event_handle == kInvalidEventHandle ||
+        event_handle > current_index_) {
+      return;
+    }
+    const uint32_t max_size = event_buffer_.size();
+    if (current_index_ > (max_size + event_handle)) {
+      // Ignore, buffer has already overflowed.
+      return;
+    }
+
+    int event_index = event_handle % max_size;
+    event_buffer_[event_index].end_timestamp_ms = NowMicros();
+  }
+
+  // Returns the size of the buffer.
+  size_t Size() const {
+    return (current_index_ >= event_buffer_.size()) ? event_buffer_.size()
+                                                    : current_index_;
+  }
+
+  // Resets the buffer.
+  void Reset() {
+    enabled_ = false;
+    current_index_ = 0;
+  }
+
+  // Returns the profile event at the given index. If the index is invalid a
+  // nullptr is returned. The return event may get overwritten if more events
+  // are added to buffer.
+  const struct ProfileEvent* const At(int index) const {
+    size_t size = Size();
+    if (index >= size) {
+      return nullptr;
+    }
+    const uint32_t max_size = event_buffer_.size();
+    uint32_t start =
+        (current_index_ > max_size) ? current_index_ % max_size : max_size;
+    index = (index + start) % max_size;
+    return &event_buffer_[index];
+  }
+
+ private:
+  static int64_t NowMicros() {
+    // TODO(shashishekhar): Refactor this to a separate file.
+    struct timeval tv;
+    gettimeofday(&tv, nullptr);
+    return static_cast<uint64_t>(tv.tv_sec) * 1000000 + tv.tv_usec;
+  }
+  bool enabled_;
+  uint32_t current_index_;
+  std::vector<ProfileEvent> event_buffer_;
+};
+}  // namespace profiling
+}  // namespace tflite
+#endif  // TFLITE_PROFILING_ENABLED
+#endif  // TENSORFLOW_CONTRIB_LITE_PROFILING_PROFILE_BUFFER_H_
diff --git a/tensorflow/contrib/lite/profiling/profile_buffer_test.cc b/tensorflow/contrib/lite/profiling/profile_buffer_test.cc
new file mode 100644
index 0000000000..0c5f0cd314
--- /dev/null
+++ b/tensorflow/contrib/lite/profiling/profile_buffer_test.cc
@@ -0,0 +1,102 @@
+/* Copyright 2018 The TensorFlow Authors. All Rights Reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+==============================================================================*/
+#include <string>
+#include <vector>
+
+#include <gmock/gmock.h>
+#include <gtest/gtest.h>
+#include "tensorflow/contrib/lite/profiling/profile_buffer.h"
+#include "tensorflow/contrib/lite/testing/util.h"
+
+namespace tflite {
+namespace profiling {
+
+namespace {
+
+std::vector<const ProfileEvent*> GetProfileEvents(const ProfileBuffer& buffer) {
+  std::vector<const ProfileEvent*> events;
+  for (auto i = 0; i < buffer.Size(); i++) {
+    events.push_back(buffer.At(i));
+  }
+  return events;
+}
+
+TEST(ProfileBufferTest, Empty) {
+  ProfileBuffer buffer(/*max_size*/ 0, /*enabled*/ true);
+  EXPECT_EQ(0, buffer.Size());
+}
+
+TEST(ProfileBufferTest, AddEvent) {
+  ProfileBuffer buffer(/*max_size*/ 10, /*enabled*/ true);
+  EXPECT_EQ(0, buffer.Size());
+  auto event_handle = buffer.BeginEvent(
+      "hello", ProfileEvent::EventType::DEFAULT, /* event_metadata */ 42);
+
+  EXPECT_GE(event_handle, 0);
+  EXPECT_EQ(1, buffer.Size());
+
+  auto event = GetProfileEvents(buffer)[0];
+  EXPECT_EQ(event->tag, "hello");
+  EXPECT_GT(event->begin_timestamp_ms, 0);
+  EXPECT_EQ(event->event_type, ProfileEvent::EventType::DEFAULT);
+  EXPECT_EQ(event->event_metadata, 42);
+
+  buffer.EndEvent(event_handle);
+  EXPECT_EQ(1, buffer.Size());
+  EXPECT_GE(event->end_timestamp_ms, event->begin_timestamp_ms);
+}
+
+TEST(ProfileBufferTest, OverFlow) {
+  const int max_size = 4;
+  ProfileBuffer buffer{max_size, true};
+  std::vector<std::string> eventNames = {"first", "second", "third", "fourth"};
+  for (int i = 0; i < 2 * max_size; i++) {
+    buffer.BeginEvent(eventNames[i % 4].c_str(),
+                      ProfileEvent::EventType::DEFAULT, i);
+    size_t expected_size = std::min(i + 1, max_size);
+    EXPECT_EQ(expected_size, buffer.Size());
+  }
+  EXPECT_EQ(max_size, buffer.Size());
+  for (int j = 0; j < buffer.Size(); ++j) {
+    auto event = buffer.At(j);
+    EXPECT_EQ(eventNames[j % 4], event->tag);
+    EXPECT_EQ(ProfileEvent::EventType::DEFAULT, event->event_type);
+    EXPECT_EQ(4 + j, event->event_metadata);
+  }
+}
+
+TEST(ProfileBufferTest, Enable) {
+  ProfileBuffer buffer(/*max_size*/ 10, /*enabled*/ false);
+  EXPECT_EQ(0, buffer.Size());
+  auto event_handle = buffer.BeginEvent(
+      "hello", ProfileEvent::EventType::DEFAULT, /* event_metadata */ 42);
+  EXPECT_EQ(kInvalidEventHandle, event_handle);
+  EXPECT_EQ(0, buffer.Size());
+  buffer.SetEnabled(true);
+  event_handle = buffer.BeginEvent("hello", ProfileEvent::EventType::DEFAULT,
+                                   /* event_metadata */ 42);
+  EXPECT_GE(event_handle, 0);
+  EXPECT_EQ(1, buffer.Size());
+}
+
+}  // namespace
+}  // namespace profiling
+}  // namespace tflite
+
+int main(int argc, char** argv) {
+  ::tflite::LogToStderr();
+  ::testing::InitGoogleTest(&argc, argv);
+  return RUN_ALL_TESTS();
+}
diff --git a/tensorflow/contrib/lite/profiling/profiler.h b/tensorflow/contrib/lite/profiling/profiler.h
new file mode 100644
index 0000000000..dfa98a6708
--- /dev/null
+++ b/tensorflow/contrib/lite/profiling/profiler.h
@@ -0,0 +1,174 @@
+/* Copyright 2018 The TensorFlow Authors. All Rights Reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+==============================================================================*/
+#ifndef TENSORFLOW_CONTRIB_LITE_PROFILING_PROFILER_H_
+#define TENSORFLOW_CONTRIB_LITE_PROFILING_PROFILER_H_
+
+#include <vector>
+
+#include "tensorflow/contrib/lite/profiling/profile_buffer.h"
+
+#ifdef TFLITE_PROFILING_ENABLED
+
+namespace tflite {
+namespace profiling {
+class ScopedProfile;
+class ScopedOperatorProfile;
+
+// Controls whether profiling is enabled or disabled and collects profiles.
+// TFLite is used on platforms that don't have posix threads, so the profiler is
+// kept as simple as possible. It is designed to be used only on a single
+// thread.
+//
+// Profiles are collected using Scoped*Profile objects that begin and end a
+// profile event.
+// An example usage is shown in the example below:
+//
+// Say Worker class has a DoWork method and we are interested in profiling
+// the overall execution time for DoWork and time spent in Task1 and Task2
+// functions.
+//
+// class Worker {
+//  public:
+//   void DoWork() {
+//    ScopedProfile(&controller, "DoWork");
+//    Task1();
+//    Task2();
+//    .....
+//   }
+//
+//   void Task1() {
+//    ScopedProfile(&controller, "Task1");
+//    ....
+//   }
+//
+//   void Task2() {
+//    ScopedProfile(&controller, "Task2");
+//   }
+//
+//    Profiler profiler;
+// }
+//
+// We instrument the functions that need to be profiled.
+//
+// Profile can be collected by enable profiling and then getting profile
+// events.
+//
+//  void ProfileWorker() {
+//    Worker worker;
+//    worker.profiler.EnableProfiling();
+//    worker.DoWork();
+//    worker.profiler.DisableProfiling();
+//    // Profiling is complete, extract profiles.
+//    auto profile_events = worker.profiler.GetProfiles();
+//  }
+//
+//
+class Profiler {
+ public:
+  Profiler() : buffer_(1024, false) {}
+
+  void StartProfiling() { buffer_.SetEnabled(true); }
+  void StopProfiling() { buffer_.SetEnabled(false); }
+  void Reset() { buffer_.Reset(); }
+  std::vector<const ProfileEvent*> GetProfileEvents() {
+    std::vector<const ProfileEvent*> profile_events;
+    profile_events.reserve(buffer_.Size());
+    for (int i = 0; i < buffer_.Size(); i++) {
+      profile_events.push_back(buffer_.At(i));
+    }
+    return profile_events;
+  }
+
+ private:
+  friend class ScopedProfile;
+  friend class ScopedOperatorProfile;
+  ProfileBuffer* GetProfileBuffer() { return &buffer_; }
+  ProfileBuffer buffer_;
+};
+
+class ScopedProfile {
+ public:
+  // Adds a profile event to profile that begins with the construction
+  // of object and ends when the object goes out of scope.
+  // The lifetime of tag should be at least the lifetime of profiler.
+  ScopedProfile(Profiler* profiler, const char* tag) {
+    if (profiler) {
+      buffer_ = profiler->GetProfileBuffer();
+      event_handle_ =
+          buffer_->BeginEvent(tag, ProfileEvent::EventType::DEFAULT, 0);
+    }
+  }
+  ~ScopedProfile() {
+    if (buffer_) {
+      buffer_->EndEvent(event_handle_);
+    }
+  }
+
+ private:
+  ProfileBuffer* buffer_;
+  int32_t event_handle_;
+};
+
+class ScopedOperatorProfile {
+ public:
+  // Adds a profile event to profile that begins with the construction
+  // of object and ends when the object goes out of scope.
+  // The lifetime of tag should be at least the lifetime of profiler.
+  ScopedOperatorProfile(Profiler* profiler, const char* tag, int node_index) {
+    if (profiler) {
+      buffer_ = profiler->GetProfileBuffer();
+      event_handle_ = buffer_->BeginEvent(
+          tag, ProfileEvent::EventType::OPERATOR_INVOKE_EVENT, node_index);
+    }
+  }
+
+  ~ScopedOperatorProfile() {
+    if (buffer_) {
+      buffer_->EndEvent(event_handle_);
+    }
+  }
+
+ private:
+  ProfileBuffer* buffer_;
+  int32_t event_handle_;
+};
+
+}  // namespace profiling
+}  // namespace tflite
+
+#define SCOPED_OPERATOR_PROFILE(profiler, node_index)                       \
+  tflite::profiling::ScopedOperatorProfile _profile((profiler), "OpInvoke", \
+                                                    (node_index))
+#else
+
+namespace tflite {
+namespace profiling {
+// A noop version of profiler when profiling is disabled.
+class Profiler {
+ public:
+  Profiler() {}
+  void StartProfiling() {}
+  void StopProfiling() {}
+  void Reset() {}
+  std::vector<const ProfileEvent*> GetProfileEvents() { return {}; }
+};
+}  // namespace profiling
+}  // namespace tflite
+
+#define SCOPED_OPERATOR_PROFILE(profiler, node_index)
+
+#endif  // TFLITE_PROFILING_ENABLED
+
+#endif  // TENSORFLOW_CONTRIB_LITE_PROFILING_PROFILER_H_
diff --git a/tensorflow/contrib/lite/profiling/profiler_test.cc b/tensorflow/contrib/lite/profiling/profiler_test.cc
new file mode 100644
index 0000000000..994523a8fb
--- /dev/null
+++ b/tensorflow/contrib/lite/profiling/profiler_test.cc
@@ -0,0 +1,105 @@
+/* Copyright 2018 The TensorFlow Authors. All Rights Reserved.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+==============================================================================*/
+#include <unistd.h>
+
+#include <chrono>  // NOLINT(build/c++11)
+#include <cmath>
+#include <thread>  // NOLINT(build/c++11)
+
+#include <gmock/gmock.h>
+#include <gtest/gtest.h>
+#include "tensorflow/contrib/lite/profiling/profiler.h"
+#include "tensorflow/contrib/lite/testing/util.h"
+
+namespace tflite {
+namespace profiling {
+namespace {
+
+void AssertDurationOfEventAroundMs(const ProfileEvent* event,
+                                   double expected_ms, double eps_ms) {
+  double duration_ms =
+      (event->end_timestamp_ms - event->begin_timestamp_ms) / 1e3;
+  EXPECT_NEAR(expected_ms, duration_ms, eps_ms);
+}
+
+void SleepForQuarterSecond(Profiler* profiler) {
+  ScopedProfile profile(profiler, "SleepForQuarter");
+  std::this_thread::sleep_for(std::chrono::milliseconds(250));
+}
+
+void ChildFunction(Profiler* profiler) {
+  ScopedProfile profile(profiler, "Child");
+  SleepForQuarterSecond(profiler);
+}
+
+void ParentFunction(Profiler* profiler) {
+  ScopedProfile profile(profiler, "Parent");
+  for (int i = 0; i < 2; i++) {
+    ChildFunction(profiler);
+  }
+}
+
+TEST(ProfilerTest, NoProfilesAreCollectedWhenDisabled) {
+  Profiler profiler;
+  ParentFunction(&profiler);
+  auto profile_events = profiler.GetProfileEvents();
+  EXPECT_EQ(0, profile_events.size());
+}
+
+TEST(ProfilingTest, ProfilesAreCollected) {
+  Profiler profiler;
+  profiler.StartProfiling();
+  ParentFunction(&profiler);
+  profiler.StopProfiling();
+  auto profile_events = profiler.GetProfileEvents();
+  // ParentFunction calls the ChildFunction 2 times.
+  // Each ChildFunction calls SleepForQuarterSecond once.
+  // We expect 1 entry for ParentFunction, 2 for ChildFunction and 2 for
+  // SleepForQuarterSecond: Total: 1+ 2 + 2 = 5
+  //  Profiles should look like:
+  //  Parent ~ 500 ms (due to 2 Child calls)
+  //   - Child ~ 250 ms (due to SleepForQuarter calls)
+  //       - SleepForQuarter ~ 250ms
+  //   - Child ~ 250 ms (due to SleepForQuarter calls)
+  //      - SleepForQuarter ~ 250ms
+  //
+  ASSERT_EQ(5, profile_events.size());
+  EXPECT_EQ("Parent", profile_events[0]->tag);
+  EXPECT_EQ("Child", profile_events[1]->tag);
+  EXPECT_EQ("SleepForQuarter", profile_events[2]->tag);
+  EXPECT_EQ("Child", profile_events[3]->tag);
+  EXPECT_EQ("SleepForQuarter", profile_events[4]->tag);
+
+  AssertDurationOfEventAroundMs(profile_events[0], /*expected_ms*/ 500,
+                                /*eps_ms*/ 2);
+  AssertDurationOfEventAroundMs(profile_events[1], /*expected_ms*/ 250,
+                                /*eps_ms*/ 2);
+  AssertDurationOfEventAroundMs(profile_events[2], /*expected_ms*/ 250,
+                                /*eps_ms*/ 2);
+  AssertDurationOfEventAroundMs(profile_events[3], /*expected_ms*/ 250,
+                                /*eps_ms*/ 2);
+  AssertDurationOfEventAroundMs(profile_events[4], /*expected_ms*/ 250,
+                                /*eps_ms*/ 2);
+}
+
+}  // namespace
+}  // namespace profiling
+}  // namespace tflite
+
+int main(int argc, char** argv) {
+  ::tflite::LogToStderr();
+  ::testing::InitGoogleTest(&argc, argv);
+  return RUN_ALL_TESTS();
+}