runtime/onert/core/src/util/EventWriter.cc

   1 /*
   2  * Copyright (c) 2020 Samsung Electronics Co., Ltd. All Rights Reserved
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *    http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16
  17 #include "util/EventWriter.h"
  18
  19 #include <sstream>
  20 #include <vector>
  21 #include <unordered_map>
  22 #include <json/json.h>
  23 #include <assert.h>
  24 #include <utility>
  25 #include <map>
  26 #include <set>
  27 #include <stdint.h>
  28 #include <fstream>
  29
  30 // json type for Chrome Event Trace
  31 namespace
  32 {
  33
  34 std::string quote(const std::string &value)
  35 {
  36   std::stringstream ss;
  37   ss << '"' << value << '"';
  38   return ss.str();
  39 }
  40
  41 std::string field(const std::string &k, const std::string &v)
  42 {
  43   std::stringstream ss;
  44   ss << quote(k) << " : " << quote(v);
  45   return ss.str();
  46 }
  47
  48 struct Content // One Entry in Chrome Event Trace
  49 {
  50   std::vector<std::pair<std::string, std::string>> flds;
  51   std::vector<std::pair<std::string, std::string>> args;
  52 };
  53
  54 std::string object(const Content &content)
  55 {
  56   std::stringstream ss;
  57
  58   ss << "{ ";
  59
  60   ss << field(content.flds[0].first, content.flds[0].second);
  61
  62   for (uint32_t n = 1; n < content.flds.size(); ++n)
  63   {
  64     ss << ", " << field(content.flds.at(n).first, content.flds.at(n).second);
  65   }
  66
  67   if (content.args.size() > 0)
  68   {
  69     ss << ", " << quote("args") << " : { ";
  70     ss << field(content.args.at(0).first, content.args.at(0).second);
  71
  72     for (uint32_t n = 1; n < content.args.size(); ++n)
  73     {
  74       ss << ", " << field(content.args.at(n).first, content.args.at(n).second);
  75     }
  76
  77     ss << "}";
  78   }
  79
  80   ss << " }";
  81
  82   return ss.str();
  83 }
  84
  85 void fill(Content &content, const Event &evt)
  86 {
  87   content.flds.emplace_back("name", evt.name);
  88   content.flds.emplace_back("pid", "0");
  89   content.flds.emplace_back("tid", evt.tid);
  90   content.flds.emplace_back("ph", evt.ph);
  91   content.flds.emplace_back("ts", evt.ts);
  92 }
  93
  94 std::string object(const DurationEvent &evt)
  95 {
  96   Content content;
  97
  98   fill(content, evt);
  99
 100   return ::object(content);
 101 }
 102
 103 std::string object(const CounterEvent &evt)
 104 {
 105   Content content;
 106
 107   fill(content, evt);
 108
 109   for (auto it = evt.values.begin(); it != evt.values.end(); ++it)
 110   {
 111     content.args.emplace_back(it->first, it->second);
 112   }
 113
 114   return ::object(content);
 115 }
 116
 117 } // namespace
 118
 119 // md table type
 120 namespace
 121 {
 122
 123 void writeMDTableRow(std::ostream &os, const std::vector<std::string> &list)
 124 {
 125   os << "| ";
 126   for (auto &key : list)
 127   {
 128     os << key << " | ";
 129   }
 130   os << "\n";
 131 }
 132
 133 struct MDContent
 134 {
 135   std::string name;
 136   uint64_t begin_ts;
 137   uint64_t end_ts;
 138   uint32_t min_rss;
 139   uint32_t max_rss;
 140   uint32_t min_page_reclaims;
 141   uint32_t max_page_reclaims;
 142
 143   MDContent()
 144       : begin_ts(0), end_ts(0), min_rss(UINT32_MAX), max_rss(0), min_page_reclaims(UINT32_MAX),
 145         max_page_reclaims(0)
 146   {
 147     // DO NOTHING
 148   }
 149
 150   virtual ~MDContent() = default;
 151
 152   void updateRss(uint32_t rss)
 153   {
 154     if (min_rss == UINT32_MAX)
 155       min_rss = rss;
 156     if (max_rss == 0)
 157       max_rss = rss;
 158
 159     if (min_rss > rss)
 160       min_rss = rss;
 161     else if (max_rss < rss)
 162       max_rss = rss;
 163   }
 164
 165   void updateMinflt(uint32_t minflt)
 166   {
 167     if (min_page_reclaims == UINT32_MAX)
 168       min_page_reclaims = minflt;
 169     if (max_page_reclaims == 0)
 170       max_page_reclaims = minflt;
 171
 172     if (min_page_reclaims > minflt)
 173       min_page_reclaims = minflt;
 174     else if (max_page_reclaims < minflt)
 175       max_page_reclaims = minflt;
 176   }
 177
 178   virtual void write(std::ostream &os) const = 0;
 179 };
 180
 181 struct OpSeq : public MDContent
 182 {
 183   std::string backend;
 184   uint64_t graph_latency;
 185
 186   struct OpSeqCmp
 187   {
 188     bool operator()(const OpSeq &lhs, const OpSeq &rhs) const
 189     {
 190       return lhs.begin_ts < rhs.begin_ts;
 191     }
 192     bool operator()(const OpSeq &lhs, const OpSeq &rhs) { return lhs.begin_ts < rhs.begin_ts; }
 193     bool operator()(OpSeq &lhs, OpSeq &rhs) { return lhs.begin_ts < rhs.begin_ts; }
 194   };
 195
 196   void write(std::ostream &os) const override
 197   {
 198     uint64_t opseq_latency = end_ts - begin_ts;
 199     double opseq_per = static_cast<double>(opseq_latency) / graph_latency * 100.0;
 200     writeMDTableRow(os, {name, backend, std::to_string(opseq_latency), std::to_string(opseq_per),
 201                          std::to_string(min_rss), std::to_string(max_rss),
 202                          std::to_string(min_page_reclaims), std::to_string(max_page_reclaims)});
 203   }
 204 };
 205
 206 struct Graph : public MDContent
 207 {
 208   std::set<OpSeq, OpSeq::OpSeqCmp> opseqs;
 209
 210   void setOpSeqs(const std::map<std::string, OpSeq> &name_to_opseq)
 211   {
 212     uint64_t graph_latency = end_ts - begin_ts;
 213     for (auto it : name_to_opseq)
 214     {
 215       auto opseq = it.second;
 216       opseq.graph_latency = graph_latency;
 217
 218       opseqs.insert(opseq);
 219
 220       updateRss(opseq.min_rss);
 221       updateRss(opseq.max_rss);
 222       updateMinflt(opseq.min_page_reclaims);
 223       updateMinflt(opseq.max_page_reclaims);
 224     }
 225   }
 226
 227   void write(std::ostream &os) const override
 228   {
 229     static std::vector<std::string> graph_headers{"latency(us)", "rss_min(kb)", "rss_max(kb)",
 230                                                   "page_reclaims_min", "page_reclaims_max"};
 231
 232     static std::vector<std::string> graph_headers_line{"-----------", "-------", "-------",
 233                                                        "-----------------", "-----------------"};
 234
 235     // Graph's Header
 236     writeMDTableRow(os, graph_headers);
 237     writeMDTableRow(os, graph_headers_line);
 238
 239     // Graph's contents
 240     writeMDTableRow(os, {std::to_string(end_ts - begin_ts), std::to_string(min_rss),
 241                          std::to_string(max_rss), std::to_string(min_page_reclaims),
 242                          std::to_string(max_page_reclaims)});
 243
 244     os << "\n";
 245
 246     static std::vector<std::string> opseq_headers{
 247         "OpSeq name",  "backend",     "latency(us)",       "latency(%)",
 248         "rss_min(kb)", "rss_max(kb)", "page_reclaims_min", "page_reclaims_max"};
 249
 250     static std::vector<std::string> opseq_headers_line{
 251         "----------", "-------", "-----------",       "-----------",
 252         "-------",    "-------", "-----------------", "-----------------"};
 253
 254     os << "## OpSequences \n";
 255
 256     // OpSeq's Header
 257     writeMDTableRow(os, opseq_headers);
 258     writeMDTableRow(os, opseq_headers_line);
 259
 260     // OpSeq's contents
 261     for (auto opseq : opseqs)
 262     {
 263       opseq.write(os);
 264     }
 265
 266     os << "\n";
 267   }
 268 };
 269
 270 struct MDTableBuilder
 271 {
 272   MDTableBuilder(const std::vector<DurationEvent> &duration_events,
 273                  const std::vector<CounterEvent> &counter_events)
 274       : _duration_events(duration_events), _counter_events(counter_events)
 275   {
 276 // when ready with low overhead in release build
 277 #ifdef DEBUG
 278     for (const auto &evt : _counter_events)
 279     {
 280       uint64_t ts = std::stoull(evt.ts);
 281       auto &name = evt.name;
 282       assert(name.compare("maxrss") == 0 || name.compare("minflt") == 0);
 283       assert(evt.values.size() == 1);
 284       auto &val = evt.values.begin()->second;
 285       if (_ts_to_values.find(ts) == _ts_to_values.end())
 286       {
 287         std::pair<uint32_t, uint32_t> values;
 288         if (name.compare("maxrss") == 0)
 289           values.first = std::stoul(val);
 290         else
 291           values.second = std::stoul(val);
 292         _ts_to_values.insert({ts, values});
 293       }
 294       else
 295       {
 296         auto &values = _ts_to_values.at(ts);
 297         if (name.compare("maxrss") == 0)
 298           values.first = std::stoul(val);
 299         else
 300           values.second = std::stoul(val);
 301       }
 302     }
 303 #endif
 304   }
 305
 306   MDTableBuilder &build()
 307   {
 308     for (auto &it : divideGraph())
 309     {
 310       size_t begin_idx = it.first;
 311       size_t end_idx = it.second;
 312       std::map<std::string, OpSeq> name_to_opseq;
 313       for (size_t i = begin_idx + 1; i < end_idx; ++i)
 314       {
 315         const auto &evt = _duration_events[i];
 316         assert(evt.name.compare("Graph") != 0);
 317         assert(evt.ph.compare("B") == 0 || evt.ph.compare("E") == 0);
 318         if (evt.ph.compare("B") == 0)
 319         {
 320           assert(name_to_opseq.find(evt.name) == name_to_opseq.end());
 321           name_to_opseq.insert({evt.name, makeOpSeq(evt)});
 322         }
 323         else
 324         {
 325           assert(name_to_opseq.find(evt.name) != name_to_opseq.end());
 326           auto &opseq = name_to_opseq.at(evt.name);
 327           updateOpSeq(opseq, evt);
 328         }
 329       }
 330
 331       _graphs.emplace_back(makeGraph(begin_idx, end_idx, name_to_opseq));
 332     }
 333
 334     return *this;
 335   }
 336
 337   std::vector<std::pair<size_t, size_t>> divideGraph()
 338   {
 339     std::vector<std::pair<size_t, size_t>> graph_idx_list; // pair<begin_idx, end_idx>
 340     for (size_t i = 0, begin_idx = 0; i < _duration_events.size(); ++i)
 341     {
 342       const auto &evt = _duration_events.at(i);
 343       if (evt.name.compare("Graph") == 0)
 344       {
 345         if (evt.ph.compare("B") == 0)
 346           begin_idx = i;
 347         else
 348           graph_idx_list.emplace_back(begin_idx, i);
 349       }
 350     }
 351     return graph_idx_list;
 352   }
 353
 354   OpSeq makeOpSeq(const DurationEvent &evt)
 355   {
 356     OpSeq opseq;
 357     opseq.name = evt.name;
 358     opseq.begin_ts = std::stoull(evt.ts);
 359     opseq.backend = evt.tid;
 360 #ifdef DEBUG
 361     opseq.updateRss(_ts_to_values.at(opseq.begin_ts).first);
 362     opseq.updateMinflt(_ts_to_values.at(opseq.begin_ts).second);
 363 #else
 364     opseq.updateRss(0);
 365     opseq.updateMinflt(0);
 366 #endif
 367     return opseq;
 368   }
 369
 370   void updateOpSeq(OpSeq &opseq, const DurationEvent &evt)
 371   {
 372     opseq.end_ts = std::stoull(evt.ts);
 373 #ifdef DEBUG
 374     opseq.updateRss(_ts_to_values.at(opseq.end_ts).first);
 375     opseq.updateMinflt(_ts_to_values.at(opseq.end_ts).second);
 376 #else
 377     opseq.updateRss(0);
 378     opseq.updateMinflt(0);
 379 #endif
 380   }
 381
 382   Graph makeGraph(size_t begin_idx, size_t end_idx,
 383                   const std::map<std::string, OpSeq> &name_to_opseq)
 384   {
 385     Graph graph;
 386     graph.name = "Graph";
 387     graph.begin_ts = std::stoull(_duration_events[begin_idx].ts);
 388     graph.end_ts = std::stoull(_duration_events[end_idx].ts);
 389     graph.setOpSeqs(name_to_opseq);
 390 #ifdef DEBUG
 391     graph.updateRss(_ts_to_values.at(graph.begin_ts).first);
 392     graph.updateMinflt(_ts_to_values.at(graph.begin_ts).second);
 393     graph.updateRss(_ts_to_values.at(graph.end_ts).first);
 394     graph.updateMinflt(_ts_to_values.at(graph.end_ts).second);
 395 #else
 396     graph.updateRss(0);
 397     graph.updateMinflt(0);
 398 #endif
 399     return graph;
 400   }
 401
 402   void write(std::ostream &os)
 403   {
 404     // Write contents
 405     for (size_t i = 0; i < _graphs.size(); ++i)
 406     {
 407       os << "# Graph " << i << "\n";
 408       _graphs.at(i).write(os);
 409     }
 410   }
 411
 412   const std::vector<DurationEvent> &_duration_events;
 413   const std::vector<CounterEvent> &_counter_events;
 414   // timestamp to std::pair<maxrss, minflt>
 415   std::unordered_map<uint64_t, std::pair<uint32_t, uint32_t>> _ts_to_values;
 416   std::vector<Graph> _graphs;
 417 };
 418
 419 } // namespace
 420
 421 EventWriter::EventWriter(const EventRecorder &recorder) : _recorder(recorder)
 422 {
 423   // DO NOTHING
 424 }
 425
 426 void EventWriter::writeToFiles(const std::string &base_filepath)
 427 {
 428   // Note. According to an internal issue, let snpe json as just file name not '.snpe.json'
 429   writeToFile(base_filepath, WriteFormat::SNPE_BENCHMARK);
 430   writeToFile(base_filepath + ".chrome.json", WriteFormat::CHROME_TRACING);
 431   writeToFile(base_filepath + ".table.md", WriteFormat::MD_TABLE);
 432 }
 433
 434 void EventWriter::writeToFile(const std::string &filepath, WriteFormat write_format)
 435 {
 436   std::ofstream os{filepath, std::ofstream::out};
 437   switch (write_format)
 438   {
 439     case WriteFormat::CHROME_TRACING:
 440       writeChromeTrace(os);
 441       break;
 442     case WriteFormat::SNPE_BENCHMARK:
 443       writeSNPEBenchmark(os);
 444       break;
 445     case WriteFormat::MD_TABLE:
 446       writeMDTable(os);
 447       break;
 448     default:
 449       assert(!"Invalid value");
 450       break;
 451   }
 452 }
 453
 454 void EventWriter::writeSNPEBenchmark(std::ostream &os)
 455 {
 456   Json::Value root;
 457   auto &exec_data = root["Execution_Data"] = Json::Value{Json::objectValue};
 458
 459   struct Stat
 460   {
 461     uint64_t sum = 0;
 462     uint64_t count = 0;
 463     uint64_t max = 0;
 464     uint64_t min = std::numeric_limits<uint64_t>::max();
 465
 466     void accumulate(uint64_t val)
 467     {
 468       sum += val;
 469       count++;
 470       max = std::max(max, val);
 471       min = std::min(min, val);
 472     }
 473   };
 474
 475   // Memory
 476   {
 477     std::unordered_map<std::string, Stat> mem_stats;
 478     for (auto &evt : _recorder.counter_events())
 479     {
 480       auto &mem_stat = mem_stats[evt.name];
 481       uint64_t val = std::stoull(evt.values.at("value"));
 482       mem_stat.accumulate(val);
 483     }
 484
 485     auto &mem = exec_data["memory"] = Json::Value{Json::objectValue};
 486     for (auto &kv : mem_stats)
 487     {
 488       auto &key = kv.first;
 489       auto &val = kv.second;
 490       mem[key]["Avg_Size"] = val.sum / val.count;
 491       mem[key]["Max_Size"] = val.max;
 492       mem[key]["Min_Size"] = val.min;
 493       mem[key]["Runtime"] = "NA";
 494     }
 495   }
 496
 497   // Operation Execution Time
 498   {
 499     // NOTE This assumes _duration_events is sorted by "ts" ascending
 500
 501     // 2D keys : stats[tid][name]
 502     std::unordered_map<std::string, std::unordered_map<std::string, Stat>> stats;
 503     std::unordered_map<std::string, std::unordered_map<std::string, uint64_t>> begin_timestamps;
 504     for (auto &evt : _recorder.duration_events())
 505     {
 506       auto &stat = stats[evt.tid][evt.name];
 507       auto &begin_ts = begin_timestamps[evt.tid][evt.name];
 508       uint64_t timestamp = std::stoull(evt.ts);
 509       if (evt.ph == "B")
 510       {
 511         if (begin_ts != 0)
 512           throw std::runtime_error{"Invalid Data"};
 513         begin_ts = timestamp;
 514       }
 515       else if (evt.ph == "E")
 516       {
 517         if (begin_ts == 0 || timestamp < begin_ts)
 518           throw std::runtime_error{"Invalid Data"};
 519         stat.accumulate(timestamp - begin_ts);
 520         begin_ts = 0;
 521       }
 522       else
 523         throw std::runtime_error{"Invalid Data - invalid value for \"ph\" : \"" + evt.ph + "\""};
 524     }
 525
 526     for (auto &kv : begin_timestamps)
 527       for (auto &kv2 : kv.second)
 528         if (kv2.second != 0)
 529           throw std::runtime_error{"Invalid Data - B and E pair does not match."};
 530
 531     for (auto &kv : stats)
 532     {
 533       auto &tid = kv.first;
 534       auto &map = kv.second;
 535       auto &json_tid = exec_data[tid] = Json::Value{Json::objectValue};
 536       for (auto &kv : map)
 537       {
 538         auto &name = kv.first;
 539         auto &val = kv.second;
 540         json_tid[name]["Avg_Time"] = val.sum / val.count;
 541         json_tid[name]["Max_Time"] = val.max;
 542         json_tid[name]["Min_Time"] = val.min;
 543         json_tid[name]["Runtime"] = tid;
 544       }
 545     }
 546   }
 547
 548   os << root;
 549 }
 550
 551 void EventWriter::writeChromeTrace(std::ostream &os)
 552 {
 553   os << "{\n";
 554   os << "  " << quote("traceEvents") << ": [\n";
 555
 556   for (auto &evt : _recorder.duration_events())
 557   {
 558     os << "    " << object(evt) << ",\n";
 559   }
 560
 561   for (auto &evt : _recorder.counter_events())
 562   {
 563     os << "    " << object(evt) << ",\n";
 564   }
 565
 566   os << "    { }\n";
 567   os << "  ]\n";
 568   os << "}\n";
 569 }
 570
 571 void EventWriter::writeMDTable(std::ostream &os)
 572 {
 573   MDTableBuilder(_recorder.duration_events(), _recorder.counter_events()).build().write(os);
 574 }