add activity profiler plugin interface and test (#202)

Summary:
Pull Request resolved: #202

# Activity Profiler Interface
Adds the child Activiity profiler interface and implementation. This interface can be used by libraries and frameworks to supply trace events to Kineto.
The first version only consolidates trace events and does not handle correlation yet.

## Details
* Add Activity Profiler interface header that includes both profiler and the profiler session.
   A session manages all the trace event data captured by the respective profiler
* Also had to move GenericTrace activity to includes dir as it used in the profiler session interface.
* Creates sessions and starts and stops them in the primary ActivityProfilers flow.
* First use-case is to integrate with Glow (Graph Lowering Compiler) , adding a glow_runtime event type for it.
https://github.com/pytorch/glow/blob/master/docs/Tracing.md

Reviewed By: gdankel

Differential Revision: D27601906

fbshipit-source-id: 38e608a3a1a6e1b9e69f80d07312e388ed7ad339

Author: Brian Coutinho

libkineto/include/ActivityType.h

@@ -21,6 +21,7 @@ enum class ActivityType {
     CONCURRENT_KERNEL, // on-device kernels
     EXTERNAL_CORRELATION,
     CUDA_RUNTIME, // host side cuda runtime events
+    GLOW_RUNTIME, // host side glow runtime events
     CPU_INSTANT_EVENT, // host side point-like events
     ENUM_COUNT
 };

libkineto/include/IActivityProfiler.h

@@ -0,0 +1,102 @@
+/*
+ * Copyright (c) Facebook, Inc. and its affiliates.
+ * All rights reserved.
+ * This source code is licensed under the BSD-style license found in the
+ * LICENSE file in the root directory of this source tree.
+ */
+
+#pragma once
+
+#include <memory>
+#include <set>
+#include <vector>
+
+#include "GenericTraceActivity.h"
+#include "ActivityTraceInterface.h"
+
+/* This file includes an abstract base class for an activity profiler
+ * that can be implemented by multiple tracing agents in the application.
+ * The high level Kineto profiler can co-ordinate start and end of tracing
+ * and combine together events from multiple such activity profilers.
+ */
+
+namespace libkineto {
+
+enum class TraceStatus {
+  READY, // Accepting trace requests
+  WARMUP, // Performing trace warmup
+  RECORDING, // Actively collecting activities
+  PROCESSING, // Recording is complete, preparing results
+  ERROR, // One or more errors (and possibly also warnings) occurred.
+  WARNING, // One or more warnings occurred.
+};
+
+/* IActivityProfilerSession:
+ *   an opaque object that can be used by a high level profiler to
+ *   start/stop and return trace events.
+ */
+class IActivityProfilerSession {
+
+ public:
+  virtual ~IActivityProfilerSession() {}
+
+  // start the trace collection synchronously
+  virtual void start() = 0;
+
+  // stop the trace collection synchronously
+  virtual void stop() = 0;
+
+  TraceStatus status() {
+    return status_;
+  }
+
+  // returns list of Trace Activities
+  virtual std::vector<GenericTraceActivity>& activities() = 0;
+
+  // returns errors with this trace
+  virtual std::vector<std::string> errors() = 0;
+
+  // processes trace activities using logger
+  virtual void processTrace(ActivityLogger& logger) = 0;
+
+  // XXX define trace formats
+  // virtual save(string name, TraceFormat format)
+
+ protected:
+  TraceStatus status_ = TraceStatus::READY;
+};
+
+
+/* Activity Profiler Plugins:
+ *   These allow other frameworks to integrate into Kineto's primariy
+ *   activity profiler. While the primary activity profiler handles
+ *   timing the trace collections and correlating events the plugins
+ *   can become source of new trace activity types.
+ */
+class IActivityProfiler {
+
+ public:
+
+  virtual ~IActivityProfiler() {}
+
+  // name of profiler
+  virtual const std::string& name() const = 0;
+
+  // returns activity types this profiler supports
+  virtual const std::set<ActivityType>& availableActivities() const = 0;
+
+  // Calls prepare() on registered tracer providers passing in the relevant
+  // activity types. Returns a profiler session handle (including uuid?).
+  virtual std::unique_ptr<IActivityProfilerSession> configure(
+      const std::set<ActivityType>& activity_types,
+      const std::string& config="") = 0;
+
+  // asynchronous version of the above with future timestamp and duration.
+  virtual std::unique_ptr<IActivityProfilerSession> configure(
+      int64_t ts_ms,
+      int64_t duration_ms,
+      const std::set<ActivityType>& activity_types,
+      const std::string& config = "") = 0;
+};
+
+} // namespace libkineto

libkineto/libkineto_defs.bzl

@@ -57,6 +57,8 @@ def get_libkineto_public_headers():
         "include/ClientInterface.h",
         "include/GenericTraceActivity.h",
         "include/TraceActivity.h",
+        "include/GenericTraceActivity.h",
+        "include/IActivityProfiler.h",
         "include/TraceSpan.h",
         "include/ThreadUtil.h",
         "include/libkineto.h",

libkineto/src/ActivityProfiler.cpp

@@ -159,6 +159,11 @@ void ActivityProfiler::processTraceInternal(ActivityLogger& logger) {
   }
 #endif // HAS_CUPTI
 
+  for (const auto& session : sessions_){
+    LOG(INFO) << "Processing child profiler trace";
+    session->processTrace(logger);
+  }
+
   finalizeTrace(*config_, logger);
 }
 
@@ -440,6 +445,24 @@ void ActivityProfiler::handleCuptiActivity(const CUpti_Activity* record, Activit
 }
 #endif // HAS_CUPTI
 
+void ActivityProfiler::configureChildProfilers() {
+  // If child profilers are enabled create profiler sessions
+  for (auto& profiler: profilers_) {
+    int64_t start_time_ms = duration_cast<milliseconds>(
+        profileStartTime_.time_since_epoch()).count();
+    LOG(INFO) << "Running child profiler " << profiler->name() << " for "
+            << config_->activitiesOnDemandDuration().count() << " ms";
+    auto session = profiler->configure(
+        start_time_ms,
+        config_->activitiesOnDemandDuration().count(),
+        std::set<ActivityType>{ActivityType::CPU_OP} // TODO make configurable
+    );
+    if (session) {
+      sessions_.push_back(std::move(session));
+    }
+  }
+}
+
 void ActivityProfiler::configure(
     const Config& config,
     const time_point<system_clock>& now) {
@@ -503,6 +526,11 @@ void ActivityProfiler::configure(
   if (profileStartTime_ < now) {
     profileStartTime_ = now + config_->activitiesWarmupDuration();
   }
+
+  if (profilers_.size() > 0) {
+    configureChildProfilers();
+  }
+
   LOG(INFO) << "Tracing starting in "
             << duration_cast<seconds>(profileStartTime_ - now).count() << "s";
 
@@ -517,6 +545,10 @@ void ActivityProfiler::startTraceInternal(const time_point<system_clock>& now) {
     libkineto::api().client()->start();
   }
   VLOG(0) << "Warmup -> CollectTrace";
+  for (auto& session: sessions_){
+    LOG(INFO) << "Starting child profiler session";
+    session->start();
+  }
   currentRunloopState_ = RunloopState::CollectTrace;
 }
 
@@ -545,6 +577,10 @@ void ActivityProfiler::stopTraceInternal(const time_point<system_clock>& now) {
         static_cast<std::underlying_type<RunloopState>::type>(
             currentRunloopState_.load());
   }
+  for (auto& session: sessions_){
+    LOG(INFO) << "Stopping child profiler session";
+    session->stop();
+  }
   currentRunloopState_ = RunloopState::ProcessTrace;
 }
 
@@ -701,6 +737,7 @@ void ActivityProfiler::resetTraceData() {
   disabledTraceSpans_.clear();
   traceBuffers_ = nullptr;
   metadata_.clear();
+  sessions_.clear();
 }
 
 

libkineto/src/ActivityProfiler.h

@@ -26,6 +26,7 @@
 #include "libkineto.h"
 #include "output_base.h"
 #include "GenericTraceActivity.h"
+#include "IActivityProfiler.h"
 
 namespace KINETO_NAMESPACE {
 
@@ -117,12 +118,19 @@ class ActivityProfiler {
     metadata_[key] = value;
   }
 
+  void addActivityProfiler(
+      std::shared_ptr<IActivityProfiler> profiler) {
+    std::lock_guard<std::mutex> guard(mutex_);
+    profilers_.push_back(profiler);
+  }
+
  protected:
 
   using CpuGpuSpanPair = std::pair<TraceSpan, TraceSpan>;
   static const CpuGpuSpanPair& defaultTraceSpan();
 
  private:
+
   class ExternalEventMap {
    public:
 
@@ -203,6 +211,8 @@ class ActivityProfiler {
 
   void finalizeTrace(const Config& config, ActivityLogger& logger);
 
+  void configureChildProfilers();
+
   // Process a single CPU trace
   void processCpuTrace(
       libkineto::CpuTraceBuffer& cpuTrace,
@@ -357,6 +367,11 @@ class ActivityProfiler {
   // Trace metadata
   std::unordered_map<std::string, std::string> metadata_;
 
+  // child activity profilers
+  std::vector<std::shared_ptr<IActivityProfiler>> profilers_;
+
+  // a vector of active profiler plugin sessions
+  std::vector<std::unique_ptr<IActivityProfilerSession>> sessions_;
 };
 
 } // namespace KINETO_NAMESPACE

libkineto/src/ActivityType.cpp

@@ -25,6 +25,7 @@ static constexpr std::array<ActivityTypeName, activityTypeCount + 1> map{{
     {"kernel", ActivityType::CONCURRENT_KERNEL},
     {"external_correlation", ActivityType::EXTERNAL_CORRELATION},
     {"cuda_runtime", ActivityType::CUDA_RUNTIME},
+    {"glow_runtime", ActivityType::GLOW_RUNTIME},
     {"cpu_instant_event", ActivityType::CPU_INSTANT_EVENT},
     {"ENUM_COUNT", ActivityType::ENUM_COUNT}
 }};

libkineto/test/ActivityProfilerTest.cpp

@@ -28,13 +28,21 @@
 #include "src/output_membuf.h"
 
 #include "src/Logger.h"
+#include "test/MockActivitySubProfiler.h"
 
 using namespace std::chrono;
 using namespace KINETO_NAMESPACE;
 
 #define CUDA_LAUNCH_KERNEL CUPTI_RUNTIME_TRACE_CBID_cudaLaunchKernel_v7000
 #define CUDA_MEMCPY CUPTI_RUNTIME_TRACE_CBID_cudaMemcpy_v3020
 
+namespace {
+const TraceSpan& defaultTraceSpan() {
+  static TraceSpan span(0, 0, "Unknown", "");
+  return span;
+}
+}
+
 // Provides ability to easily create a few test CPU-side ops
 struct MockCpuActivityBuffer : public CpuTraceBuffer {
   MockCpuActivityBuffer(int64_t startTime, int64_t endTime) {
@@ -375,6 +383,78 @@ TEST_F(ActivityProfilerTest, CorrelatedTimestampTest) {
   EXPECT_EQ(counts["launchKernel"], 1);
 }
 
+TEST_F(ActivityProfilerTest, SubActivityProfilers) {
+  using ::testing::Return;
+  using ::testing::ByMove;
+
+  // Verbose logging is useful for debugging
+  std::vector<std::string> log_modules(
+      {"ActivityProfiler.cpp"});
+  SET_LOG_VERBOSITY_LEVEL(2, log_modules);
+
+  // Setup example events to test
+  GenericTraceActivity ev{defaultTraceSpan(), ActivityType::GLOW_RUNTIME, ""};
+  ev.device = 1;
+  ev.resource = 0;
+
+  int64_t start_time_us = 100;
+  int64_t duration_us = 1000;
+  auto start_time = time_point<system_clock>(microseconds(start_time_us));
+
+  std::vector<GenericTraceActivity> test_activities{3, ev};
+  test_activities[0].startTime = start_time_us;
+  test_activities[0].endTime = start_time_us + 5000;
+  test_activities[0].activityName = "SubGraph A execution";
+  test_activities[1].startTime = start_time_us;
+  test_activities[1].endTime = start_time_us + 2000;
+  test_activities[1].activityName = "Operator foo";
+  test_activities[2].startTime = start_time_us + 2500;
+  test_activities[2].endTime = start_time_us + 2900;
+  test_activities[2].activityName = "Operator bar";
+
+  auto mock_activity_profiler =
+    std::make_shared<MockActivityProfiler>(test_activities);
+
+  MockCuptiActivities activities;
+  ActivityProfiler profiler(activities, /*cpu only*/ true);
+  profiler.addActivityProfiler(mock_activity_profiler);
+
+  profiler.configure(*cfg_, start_time);
+  profiler.startTrace(start_time);
+  EXPECT_TRUE(profiler.isActive());
+
+  profiler.stopTrace(start_time + microseconds(duration_us));
+  EXPECT_TRUE(profiler.isActive());
+
+  char filename[] = "/tmp/libkineto_testXXXXXX.json";
+  mkstemps(filename, 5);
+  LOG(INFO) << "Logging to tmp file " << filename;
+
+  // process trace
+  auto logger = std::make_unique<MemoryTraceLogger>(*cfg_);
+  profiler.processTrace(*logger);
+  profiler.setLogger(logger.get());
+
+  ActivityTrace trace(std::move(logger), loggerFactory);
+  trace.save(filename);
+  const auto& traced_activites = trace.activities();
+
+  // Test we have all the events
+  EXPECT_EQ(traced_activites->size(), test_activities.size());
+
+  // Check that the expected file was written and that it has some content
+  int fd = open(filename, O_RDONLY);
+  if (!fd) {
+    perror(filename);
+  }
+  EXPECT_TRUE(fd);
+
+  // Should expect at least 100 bytes
+  struct stat buf{};
+  fstat(fd, &buf);
+  EXPECT_GT(buf.st_size, 100);
+}
+
 TEST_F(ActivityProfilerTest, BufferSizeLimitTestWarmup) {
   ActivityProfiler profiler(cuptiActivities_, /*cpu only*/ false);
 

libkineto/test/ConfigTest.cpp

@@ -92,6 +92,7 @@ TEST(ParseTest, ActivityTypes) {
                             ActivityType::GPU_MEMSET,
                             ActivityType::CONCURRENT_KERNEL,
                             ActivityType::EXTERNAL_CORRELATION,
+                            ActivityType::GLOW_RUNTIME,
                             ActivityType::CUDA_RUNTIME}));
 
   Config cfg2;