add chrome trace

src/ngraph/runtime/interpreter/CMakeLists.txt

@@ -15,7 +15,8 @@
 # ******************************************************************************
 
 if (NGRAPH_INTERPRETER_ENABLE)
-    add_library(interpreter_backend SHARED int_backend.cpp node_wrapper.cpp int_executable.cpp)
+    add_library(interpreter_backend SHARED int_backend.cpp node_wrapper.cpp int_executable.cpp
+        chrome_trace.cpp)
     if(NGRAPH_LIB_VERSIONING_ENABLE)
         set_target_properties(interpreter_backend PROPERTIES
             VERSION ${NGRAPH_VERSION}

src/ngraph/runtime/interpreter/chrome_trace.cpp

+//*****************************************************************************
+// Copyright 2019 Intel Corporation
+//
+// 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 <iostream>
+#include <map>
+#include <sstream>
+#include <string>
+
+#include "chrome_trace.hpp"
+#include "ngraph/log.hpp"
+
+using namespace std;
+using namespace ngraph;
+
+static bool read_tracing_env_var()
+{
+    static const bool is_enabled = (getenv("NGRAPH_ENABLE_TRACING") != nullptr);
+
+    return is_enabled;
+}
+
+mutex runtime::interpreter::event::Manager::s_file_mutex;
+bool runtime::interpreter::event::Manager::s_tracing_enabled = read_tracing_env_var();
+
+runtime::interpreter::event::Duration::Duration(const string& name,
+                                                const string& category,
+                                                const string& args)
+{
+    if (Manager::is_tracing_enabled())
+    {
+        m_start = Manager::get_current_microseconds();
+        m_stop = 0;
+        m_name = name;
+        m_category = category;
+        m_args = args;
+    }
+}
+
+void runtime::interpreter::event::Duration::stop()
+{
+    if (Manager::is_tracing_enabled())
+    {
+        m_stop = Manager::get_current_microseconds();
+    }
+}
+
+void runtime::interpreter::event::Duration::write()
+{
+    if (Manager::is_tracing_enabled())
+    {
+        size_t stop_time = (m_stop != 0 ? m_stop : Manager::get_current_microseconds());
+
+        lock_guard<mutex> lock(Manager::get_mutex());
+
+        ofstream& out = runtime::interpreter::event::Manager::get_output_stream();
+        if (out.is_open() == false)
+        {
+            runtime::interpreter::event::Manager::open();
+        }
+        else
+        {
+            Manager::get_output_stream() << ",\n";
+        }
+
+        Manager::get_output_stream() <<
+            R"({"name":")" << m_name << R"(","cat":")" << m_category << R"(","ph":"X","pid":)"
+                                     << Manager::get_process_id() << R"(,"tid":)"
+                                     << Manager::get_thread_id() <<
+            R"(,"ts":)" << m_start << R"(,"dur":)" << (stop_time - m_start);
+        if (!m_args.empty())
+        {
+            out <<
+                R"(,"args":)" << m_args;
+        }
+        out << "}";
+    }
+}
+
+runtime::interpreter::event::Object::Object(const string& name, const string& args)
+    : m_name{name}
+    , m_id{static_cast<size_t>(chrono::high_resolution_clock::now().time_since_epoch().count())}
+{
+    if (Manager::is_tracing_enabled())
+    {
+        lock_guard<mutex> lock(Manager::get_mutex());
+
+        ofstream& out = runtime::interpreter::event::Manager::get_output_stream();
+        if (out.is_open() == false)
+        {
+            runtime::interpreter::event::Manager::open();
+        }
+        else
+        {
+            Manager::get_output_stream() << ",\n";
+        }
+        out << R"({"name":")" << m_name << R"(","ph":"N","id":")" << m_id <<
+            R"(","ts":)" << Manager::get_current_microseconds() <<
+            R"(,"pid":)" << Manager::get_process_id() << R"(,"tid":)" << Manager::get_thread_id();
+        if (!args.empty())
+        {
+            out <<
+                R"(,"args":)" << args;
+        }
+        out << "}";
+
+        write_snapshot(out, args);
+    }
+}
+
+void runtime::interpreter::event::Object::snapshot(const string& args)
+{
+    if (Manager::is_tracing_enabled())
+    {
+        lock_guard<mutex> lock(Manager::get_mutex());
+
+        ofstream& out = runtime::interpreter::event::Manager::get_output_stream();
+        if (out.is_open() == false)
+        {
+            runtime::interpreter::event::Manager::open();
+        }
+        else
+        {
+            Manager::get_output_stream() << ",\n";
+        }
+        write_snapshot(out, args);
+    }
+}
+
+void runtime::interpreter::event::Object::write_snapshot(ostream& out, const string& args)
+{
+    out << R"({"name":")" << m_name << R"(","ph":"O","id":")" << m_id <<
+        R"(","ts":)" << Manager::get_current_microseconds() <<
+        R"(,"pid":)" << Manager::get_process_id() << R"(,"tid":)" << Manager::get_thread_id();
+    if (!args.empty())
+    {
+        out <<
+            R"(,"args":)" << args;
+    }
+    out << "}";
+}
+
+void runtime::interpreter::event::Object::destroy()
+{
+    if (Manager::is_tracing_enabled())
+    {
+        lock_guard<mutex> lock(Manager::get_mutex());
+
+        ofstream& out = runtime::interpreter::event::Manager::get_output_stream();
+        if (out.is_open() == false)
+        {
+            runtime::interpreter::event::Manager::open();
+        }
+        else
+        {
+            Manager::get_output_stream() << ",\n";
+        }
+        out << R"({"name":")" << m_name << R"(","ph":"D","id":")" << m_id <<
+            R"(","ts":)" << Manager::get_current_microseconds() <<
+            R"(,"pid":)" << Manager::get_process_id() << R"(,"tid":)" << Manager::get_thread_id()
+            << "}";
+    }
+}
+
+void runtime::interpreter::event::Manager::open(const string& path)
+{
+    ofstream& out = get_output_stream();
+    if (out.is_open() == false)
+    {
+        out.open(path, ios_base::trunc);
+        out << "[\n";
+    }
+}
+
+void runtime::interpreter::event::Manager::close()
+{
+    ofstream& out = get_output_stream();
+    if (out.is_open())
+    {
+        out << "\n]\n";
+        out.close();
+    }
+}
+
+ofstream& runtime::interpreter::event::Manager::get_output_stream()
+{
+    static ofstream s_event_log;
+    return s_event_log;
+}
+
+const string& runtime::interpreter::event::Manager::get_process_id()
+{
+    static const string s_pid = to_string(getpid());
+    return s_pid;
+}
+
+void runtime::interpreter::event::Manager::enable_event_tracing()
+{
+    s_tracing_enabled = true;
+}
+
+void runtime::interpreter::event::Manager::disable_event_tracing()
+{
+    s_tracing_enabled = false;
+}
+
+bool runtime::interpreter::event::Manager::is_event_tracing_enabled()
+{
+    return s_tracing_enabled;
+}
+
+string runtime::interpreter::event::Manager::get_thread_id()
+{
+    thread::id tid = this_thread::get_id();
+    static map<thread::id, string> tid_map;
+    auto it = tid_map.find(tid);
+    string rc;
+    if (it == tid_map.end())
+    {
+        stringstream ss;
+        ss << "\"" << tid << "\"";
+        rc = ss.str();
+        tid_map.insert({tid, rc});
+    }
+    else
+    {
+        rc = it->second;
+    }
+    return rc;
+}

src/ngraph/runtime/interpreter/chrome_trace.hpp

+//*****************************************************************************
+// Copyright 2019 Intel Corporation
+//
+// 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.
+//*****************************************************************************
+
+#pragma once
+
+#include <chrono>
+#include <fstream>
+#include <iostream>
+#include <mutex>
+#include <string>
+#include <thread>
+#ifdef _WIN32
+#include <windows.h>
+// windows.h must be before processthreadsapi.h so we need this comment
+#include <processthreadsapi.h>
+#define getpid() GetCurrentProcessId()
+#else
+#include <unistd.h>
+#endif
+
+namespace ngraph
+{
+    namespace runtime
+    {
+        namespace interpreter
+        {
+            namespace event
+            {
+                class Duration;
+                class Object;
+                class Manager;
+            }
+        }
+    }
+}
+
+//
+// This class records timestamps for a given user defined event and
+// produces output in the chrome tracing format that can be used to view
+// the events of a running program
+//
+// Following is the format of a trace event
+//
+// {
+//   "name": "myName",
+//   "cat": "category,list",
+//   "ph": "B",
+//   "ts": 12345,
+//   "pid": 123,
+//   "tid": 456,
+//   "args": {
+//     "someArg": 1,
+//     "anotherArg": {
+//       "value": "my value"
+//     }
+//   }
+// }
+//
+// The trace file format is defined here:
+// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
+//
+// The trace file can be viewed by Chrome browser using the
+// URL: chrome://tracing/
+//
+// More information about this is at:
+// http://dev.chromium.org/developers/how-tos/trace-event-profiling-tool
+
+class ngraph::runtime::interpreter::event::Manager
+{
+    friend class Duration;
+    friend class Object;
+
+public:
+    static void open(const std::string& path = "interpreter_event_trace.json");
+    static void close();
+    static bool is_tracing_enabled() { return s_tracing_enabled; }
+    static void enable_event_tracing();
+    static void disable_event_tracing();
+    static bool is_event_tracing_enabled();
+
+private:
+    static std::ofstream& get_output_stream();
+    static const std::string& get_process_id();
+    static size_t get_current_microseconds()
+    {
+        return std::chrono::high_resolution_clock::now().time_since_epoch().count() / 1000;
+    }
+    static std::string get_thread_id();
+    static std::mutex& get_mutex() { return s_file_mutex; }
+    static std::ostream s_ostream;
+    static std::mutex s_file_mutex;
+    static bool s_tracing_enabled;
+};
+
+class ngraph::runtime::interpreter::event::Duration
+{
+public:
+    explicit Duration(const std::string& name,
+                      const std::string& category,
+                      const std::string& args = "");
+    ~Duration() { write(); }
+    /// \brief stop the timer without writing the data to the log file. To write the data
+    /// call the `write` method
+    /// Calls to stop() are optional
+    void stop();
+
+    /// \brief write the log data to the log file for this event
+    /// This funtion has an implicit stop() if stop() has not been previously called
+    void write();
+
+    Duration(const Duration&) = delete;
+    Duration& operator=(Duration const&) = delete;
+
+private:
+    std::string to_json() const;
+    size_t m_start;
+    size_t m_stop;
+    std::string m_name;
+    std::string m_category;
+    std::string m_args;
+};
+
+class ngraph::runtime::interpreter::event::Object
+{
+public:
+    Object(const std::string& name, const std::string& args);
+    void snapshot(const std::string& args);
+    void destroy();
+
+private:
+    void write_snapshot(std::ostream& out, const std::string& args);
+    const std::string m_name;
+    size_t m_id;
+};