GNNE-1875 Feature/op profile with cpu ops

src/Native/include/nncase/runtime/stackvm/op_profile.h

@@ -13,41 +13,37 @@
  * limitations under the License.
  */
 #pragma once
+#include "opcode.h"
 #include <iomanip>
 #include <iostream>
-#include <map>
-#include <unordered_map>
+#include <tuple>
+#include <vector>
 
 extern "C" {
 double get_ms_time();
 }
 
 class op_profile {
   public:
-    op_profile(const std::string &op_type = "op_profile") : op_type_(op_type) {
+    op_profile(const std::string &op_name, uint8_t op_type)
+        : op_name_(op_name), op_type_(op_type) {
         begin_ = get_ms_time();
     }
 
     ~op_profile() {
         end_ = get_ms_time();
-        auto cast_time = end_ - begin_;
-        if (op_timing_.find(op_type_) == op_timing_.end()) {
-            op_timing_.emplace(op_type_, cast_time);
-            op_count_.emplace(op_type_, 1);
-        } else {
-            op_timing_[op_type_] += cast_time;
-            op_count_[op_type_] += 1;
-        }
+        op_timing_.push_back(std::make_tuple(op_name_, op_type_, begin_, end_));
     }
 
     static void print();
 
   public:
-    static std::unordered_map<std::string, double> op_timing_;
-    static std::map<std::string, size_t> op_count_;
+    static std::vector<std::tuple<std::string, uint8_t, double, double>>
+        op_timing_;
 
   private:
     double begin_;
     double end_;
-    std::string op_type_;
+    std::string op_name_;
+    uint8_t op_type_;
 };

src/Native/src/runtime/stackvm/op_profile.cpp

@@ -14,7 +14,9 @@
  */
 
 #include <algorithm>
+#include <map>
 #include <nncase/runtime/stackvm/op_profile.h>
+#include <unordered_map>
 #include <vector>
 
 #ifdef NNCASE_BAREMETAL
@@ -23,15 +25,51 @@ double get_ms_time();
 double get_ms_time() { return (double)clock() / 1000; }
 #endif
 
-std::unordered_map<std::string, double> op_profile::op_timing_;
-std::map<std::string, size_t> op_profile::op_count_;
+std::vector<std::tuple<std::string, uint8_t, double, double>>
+    op_profile::op_timing_;
+
 void op_profile::print() {
+    std::map<std::string, double> op_timing;
+    std::unordered_map<std::string, size_t> op_count;
+
+    std::cout << "stack OPs timeline" << std::endl;
+    std::cout << "|" << std::setw(24) << std::left << "stackvm tensor op"
+              << "|" << std::setw(24) << std::left << "start timing(ms)"
+              << "|" << std::setw(24) << std::left << "end timing(ms)"
+              << "|" << std::endl;
+
+    std::cout << "|" << std::setw(24) << std::left << "---"
+              << "|" << std::setw(24) << std::left << "---"
+              << "|" << std::setw(24) << std::left << "---"
+              << "|" << std::endl;
+    double init_timing = -1;
+    for (auto &&[op_name, op_type, begin, end] : op_timing_) {
+        if (init_timing == -1) {
+            init_timing = begin;
+        }
+        auto cast_time = end - begin;
+        if (op_timing.find(op_name) == op_timing.end()) {
+            op_timing.emplace(op_name, cast_time);
+            op_count.emplace(op_name, 1);
+        } else {
+            op_timing[op_name] += cast_time;
+            op_count[op_name] += 1;
+        }
+        if (op_type == (uint8_t)nncase::runtime::stackvm::opcode_t::EXTCALL ||
+            op_type == (uint8_t)nncase::runtime::stackvm::opcode_t::TENSOR ||
+            op_type == (uint8_t)nncase::runtime::stackvm::opcode_t::CUSCALL)
+            std::cout << "|" << std::setw(24) << std::left << op_name << "|"
+                      << std::setw(24) << begin - init_timing << "|"
+                      << std::setw(24) << end - init_timing << "|" << std::endl;
+    }
+
     double total = 0.f;
     std::vector<std::pair<std::string, double>> v;
-    for (auto e : op_timing_) {
+    for (auto e : op_timing) {
         total += e.second;
         v.push_back(e);
     }
+    std::cout << std::endl;
 
     std::sort(
         v.begin(), v.end(),
@@ -53,7 +91,7 @@ void op_profile::print() {
 
     auto total_count = 0;
     for (auto e : v) {
-        auto count = op_count_[e.first];
+        auto count = op_count[e.first];
         std::cout << "|" << std::setw(24) << std::left << e.first << "|"
                   << std::setw(6) << count << "|" << std::setw(12) << std::left
                   << e.second << "|" << std::setw(12) << std::left
@@ -67,5 +105,5 @@ void op_profile::print() {
               << std::left << total / total * 100 << "|" << std::endl
               << std::endl;
 
-    op_timing_.clear();
+    op_timing.clear();
 }

src/Native/src/runtime/stackvm/runtime_function.run.cpp

@@ -37,10 +37,10 @@ stackvm_runtime_function::run(gsl::span<const gsl::byte> text) noexcept {
 
     while (!reader_.empty()) {
         pc_ = reader_.tell();
-        auto opcode = reader_.read<opcode_t>();
+        opcode_t opcode = reader_.read<opcode_t>();
         if (opcode != opcode_t::TENSOR) {
 #ifdef ENABLE_OP_PROFILE
-            op_profile p(to_string(opcode));
+            op_profile p(to_string(opcode), (uint8_t)opcode);
 #endif
             switch (opcode) {
 #include "ops/control.inl"
@@ -55,7 +55,7 @@ stackvm_runtime_function::run(gsl::span<const gsl::byte> text) noexcept {
         } else {
             auto tensor_func = reader_.read_unaligned<tensor_function_t>();
 #ifdef ENABLE_OP_PROFILE
-            op_profile p(to_string(tensor_func));
+            op_profile p(to_string(tensor_func), (uint8_t)opcode);
 #endif
             try_(visit(tensor_func, reader_))
         }