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   content.args = evt.args;
  93 }
  94
  95 std::string object(const DurationEvent &evt)
  96 {
  97   Content content;
  98
  99   fill(content, evt);
 100
 101   return ::object(content);
 102 }
 103
 104 std::string object(const CounterEvent &evt)
 105 {
 106   Content content;
 107
 108   fill(content, evt);
 109
 110   for (auto it = evt.values.begin(); it != evt.values.end(); ++it)
 111   {
 112     content.args.emplace_back(it->first, it->second);
 113   }
 114
 115   return ::object(content);
 116 }
 117
 118 } // namespace
 119
 120 // md table type
 121 namespace
 122 {
 123
 124 void writeMDTableRow(std::ostream &os, const std::vector<std::string> &list)
 125 {
 126   os << "| ";
 127   for (auto &key : list)
 128   {
 129     os << key << " | ";
 130   }
 131   os << "\n";
 132 }
 133
 134 struct MDContent
 135 {
 136   std::string name;
 137   uint64_t begin_ts;
 138   uint64_t end_ts;
 139   uint32_t min_rss;
 140   uint32_t max_rss;
 141   uint32_t min_page_reclaims;
 142   uint32_t max_page_reclaims;
 143
 144   MDContent()
 145       : begin_ts(0), end_ts(0), min_rss(UINT32_MAX), max_rss(0), min_page_reclaims(UINT32_MAX),
 146         max_page_reclaims(0)
 147   {
 148     // DO NOTHING
 149   }
 150
 151   virtual ~MDContent() = default;
 152
 153   void updateRss(uint32_t rss)
 154   {
 155     if (min_rss == UINT32_MAX)
 156       min_rss = rss;
 157     if (max_rss == 0)
 158       max_rss = rss;
 159
 160     if (min_rss > rss)
 161       min_rss = rss;
 162     else if (max_rss < rss)
 163       max_rss = rss;
 164   }
 165
 166   void updateMinflt(uint32_t minflt)
 167   {
 168     if (min_page_reclaims == UINT32_MAX)
 169       min_page_reclaims = minflt;
 170     if (max_page_reclaims == 0)
 171       max_page_reclaims = minflt;
 172
 173     if (min_page_reclaims > minflt)
 174       min_page_reclaims = minflt;
 175     else if (max_page_reclaims < minflt)
 176       max_page_reclaims = minflt;
 177   }
 178
 179   virtual void write(std::ostream &os) const = 0;
 180 };
 181
 182 struct OpSeq : public MDContent
 183 {
 184   std::string backend;
 185   uint64_t graph_latency;
 186
 187   struct OpSeqCmp
 188   {
 189     bool operator()(const OpSeq &lhs, const OpSeq &rhs) const
 190     {
 191       return lhs.begin_ts < rhs.begin_ts;
 192     }
 193     bool operator()(const OpSeq &lhs, const OpSeq &rhs) { return lhs.begin_ts < rhs.begin_ts; }
 194     bool operator()(OpSeq &lhs, OpSeq &rhs) { return lhs.begin_ts < rhs.begin_ts; }
 195   };
 196
 197   void write(std::ostream &os) const override
 198   {
 199     uint64_t opseq_latency = end_ts - begin_ts;
 200     double opseq_per = static_cast<double>(opseq_latency) / graph_latency * 100.0;
 201     writeMDTableRow(os, {name, backend, std::to_string(opseq_latency), std::to_string(opseq_per),
 202                          std::to_string(min_rss), std::to_string(max_rss),
 203                          std::to_string(min_page_reclaims), std::to_string(max_page_reclaims)});
 204   }
 205 };
 206
 207 struct Graph : public MDContent
 208 {
 209   std::set<OpSeq, OpSeq::OpSeqCmp> opseqs;
 210
 211   void setOpSeqs(const std::map<std::string, OpSeq> &name_to_opseq)
 212   {
 213     uint64_t graph_latency = end_ts - begin_ts;
 214     for (auto it : name_to_opseq)
 215     {
 216       auto opseq = it.second;
 217       opseq.graph_latency = graph_latency;
 218
 219       opseqs.insert(opseq);
 220
 221       updateRss(opseq.min_rss);
 222       updateRss(opseq.max_rss);
 223       updateMinflt(opseq.min_page_reclaims);
 224       updateMinflt(opseq.max_page_reclaims);
 225     }
 226   }
 227
 228   void write(std::ostream &os) const override
 229   {
 230     static std::vector<std::string> graph_headers{"latency(us)", "rss_min(kb)", "rss_max(kb)",
 231                                                   "page_reclaims_min", "page_reclaims_max"};
 232
 233     static std::vector<std::string> graph_headers_line{"-----------", "-------", "-------",
 234                                                        "-----------------", "-----------------"};
 235
 236     // Graph's Header
 237     writeMDTableRow(os, graph_headers);
 238     writeMDTableRow(os, graph_headers_line);
 239
 240     // Graph's contents
 241     writeMDTableRow(os, {std::to_string(end_ts - begin_ts), std::to_string(min_rss),
 242                          std::to_string(max_rss), std::to_string(min_page_reclaims),
 243                          std::to_string(max_page_reclaims)});
 244
 245     os << "\n";
 246
 247     static std::vector<std::string> opseq_headers{
 248         "OpSeq name",  "backend",     "latency(us)",       "latency(%)",
 249         "rss_min(kb)", "rss_max(kb)", "page_reclaims_min", "page_reclaims_max"};
 250
 251     static std::vector<std::string> opseq_headers_line{
 252         "----------", "-------", "-----------",       "-----------",
 253         "-------",    "-------", "-----------------", "-----------------"};
 254
 255     os << "## OpSequences \n";
 256
 257     // OpSeq's Header
 258     writeMDTableRow(os, opseq_headers);
 259     writeMDTableRow(os, opseq_headers_line);
 260
 261     // OpSeq's contents
 262     for (auto opseq : opseqs)
 263     {
 264       opseq.write(os);
 265     }
 266
 267     os << "\n";
 268   }
 269 };
 270
 271 struct MDTableBuilder
 272 {
 273   MDTableBuilder(const std::vector<DurationEvent> &duration_events,
 274                  const std::vector<CounterEvent> &counter_events)
 275       : _duration_events(duration_events), _counter_events(counter_events)
 276   {
 277 // when ready with low overhead in release build
 278 #ifdef DEBUG
 279     for (const auto &evt : _counter_events)
 280     {
 281       uint64_t ts = std::stoull(evt.ts);
 282       auto &name = evt.name;
 283       assert(name.compare("maxrss") == 0 || name.compare("minflt") == 0);
 284       assert(evt.values.size() == 1);
 285       auto &val = evt.values.begin()->second;
 286       if (_ts_to_values.find(ts) == _ts_to_values.end())
 287       {
 288         std::pair<uint32_t, uint32_t> values;
 289         if (name.compare("maxrss") == 0)
 290           values.first = std::stoul(val);
 291         else
 292           values.second = std::stoul(val);
 293         _ts_to_values.insert({ts, values});
 294       }
 295       else
 296       {
 297         auto &values = _ts_to_values.at(ts);
 298         if (name.compare("maxrss") == 0)
 299           values.first = std::stoul(val);
 300         else
 301           values.second = std::stoul(val);
 302       }
 303     }
 304 #endif
 305   }
 306
 307   MDTableBuilder &build()
 308   {
 309     for (auto &it : divideGraph())
 310     {
 311       size_t begin_idx = it.first;
 312       size_t end_idx = it.second;
 313       std::map<std::string, OpSeq> name_to_opseq;
 314       for (size_t i = begin_idx + 1; i < end_idx; ++i)
 315       {
 316         const auto &evt = _duration_events[i];
 317         assert(evt.name.compare("Graph") != 0);
 318         assert(evt.ph.compare("B") == 0 || evt.ph.compare("E") == 0);
 319         if (evt.ph.compare("B") == 0)
 320         {
 321           assert(name_to_opseq.find(evt.name) == name_to_opseq.end());
 322           name_to_opseq.insert({evt.name, makeOpSeq(evt)});
 323         }
 324         else
 325         {
 326           assert(name_to_opseq.find(evt.name) != name_to_opseq.end());
 327           auto &opseq = name_to_opseq.at(evt.name);
 328           updateOpSeq(opseq, evt);
 329         }
 330       }
 331
 332       _graphs.emplace_back(makeGraph(begin_idx, end_idx, name_to_opseq));
 333     }
 334
 335     return *this;
 336   }
 337
 338   std::vector<std::pair<size_t, size_t>> divideGraph()
 339   {
 340     std::vector<std::pair<size_t, size_t>> graph_idx_list; // pair<begin_idx, end_idx>
 341     for (size_t i = 0, begin_idx = 0; i < _duration_events.size(); ++i)
 342     {
 343       const auto &evt = _duration_events.at(i);
 344       if (evt.name.compare("Graph") == 0)
 345       {
 346         if (evt.ph.compare("B") == 0)
 347           begin_idx = i;
 348         else
 349           graph_idx_list.emplace_back(begin_idx, i);
 350       }
 351     }
 352     return graph_idx_list;
 353   }
 354
 355   OpSeq makeOpSeq(const DurationEvent &evt)
 356   {
 357     OpSeq opseq;
 358     opseq.name = evt.name;
 359     opseq.begin_ts = std::stoull(evt.ts);
 360     opseq.backend = evt.tid;
 361 #ifdef DEBUG
 362     opseq.updateRss(_ts_to_values.at(opseq.begin_ts).first);
 363     opseq.updateMinflt(_ts_to_values.at(opseq.begin_ts).second);
 364 #else
 365     opseq.updateRss(0);
 366     opseq.updateMinflt(0);
 367 #endif
 368     return opseq;
 369   }
 370
 371   void updateOpSeq(OpSeq &opseq, const DurationEvent &evt)
 372   {
 373     opseq.end_ts = std::stoull(evt.ts);
 374 #ifdef DEBUG
 375     opseq.updateRss(_ts_to_values.at(opseq.end_ts).first);
 376     opseq.updateMinflt(_ts_to_values.at(opseq.end_ts).second);
 377 #else
 378     opseq.updateRss(0);
 379     opseq.updateMinflt(0);
 380 #endif
 381   }
 382
 383   Graph makeGraph(size_t begin_idx, size_t end_idx,
 384                   const std::map<std::string, OpSeq> &name_to_opseq)
 385   {
 386     Graph graph;
 387     graph.name = "Graph";
 388     graph.begin_ts = std::stoull(_duration_events[begin_idx].ts);
 389     graph.end_ts = std::stoull(_duration_events[end_idx].ts);
 390     graph.setOpSeqs(name_to_opseq);
 391 #ifdef DEBUG
 392     graph.updateRss(_ts_to_values.at(graph.begin_ts).first);
 393     graph.updateMinflt(_ts_to_values.at(graph.begin_ts).second);
 394     graph.updateRss(_ts_to_values.at(graph.end_ts).first);
 395     graph.updateMinflt(_ts_to_values.at(graph.end_ts).second);
 396 #else
 397     graph.updateRss(0);
 398     graph.updateMinflt(0);
 399 #endif
 400     return graph;
 401   }
 402
 403   void write(std::ostream &os)
 404   {
 405     // Write contents
 406     for (size_t i = 0; i < _graphs.size(); ++i)
 407     {
 408       os << "# Graph " << i << "\n";
 409       _graphs.at(i).write(os);
 410     }
 411   }
 412
 413   const std::vector<DurationEvent> &_duration_events;
 414   const std::vector<CounterEvent> &_counter_events;
 415   // timestamp to std::pair<maxrss, minflt>
 416   std::unordered_map<uint64_t, std::pair<uint32_t, uint32_t>> _ts_to_values;
 417   std::vector<Graph> _graphs;
 418 };
 419
 420 } // namespace
 421
 422 void SNPEWriter::flush(const std::vector<std::unique_ptr<EventRecorder>> &recorders)
 423 {
 424   Json::Value root;
 425   auto &exec_data = root["Execution_Data"] = Json::Value{Json::objectValue};
 426
 427   struct Stat
 428   {
 429     uint64_t sum = 0;
 430     uint64_t count = 0;
 431     uint64_t max = 0;
 432     uint64_t min = std::numeric_limits<uint64_t>::max();
 433
 434     void accumulate(uint64_t val)
 435     {
 436       sum += val;
 437       count++;
 438       max = std::max(max, val);
 439       min = std::min(min, val);
 440     }
 441   };
 442
 443   // Memory
 444   {
 445     std::unordered_map<std::string, Stat> mem_stats;
 446     for (auto &recorder : recorders)
 447     {
 448       for (auto &evt : recorder->counter_events())
 449       {
 450         auto &mem_stat = mem_stats[evt.name];
 451         uint64_t val = std::stoull(evt.values.at("value"));
 452         mem_stat.accumulate(val);
 453       }
 454     }
 455
 456     auto &mem = exec_data["memory"] = Json::Value{Json::objectValue};
 457     for (auto &kv : mem_stats)
 458     {
 459       auto &key = kv.first;
 460       auto &val = kv.second;
 461       mem[key]["Avg_Size"] = val.sum / val.count;
 462       mem[key]["Max_Size"] = val.max;
 463       mem[key]["Min_Size"] = val.min;
 464       mem[key]["Runtime"] = "NA";
 465     }
 466   }
 467
 468   // Operation Execution Time
 469   {
 470     // NOTE This assumes _duration_events is sorted by "ts" ascending
 471
 472     // 2D keys : stats[tid][name]
 473     std::unordered_map<std::string, std::unordered_map<std::string, Stat>> stats;
 474     std::unordered_map<std::string, std::unordered_map<std::string, uint64_t>> begin_timestamps;
 475     for (auto &recorder : recorders)
 476     {
 477       for (auto &evt : recorder->duration_events())
 478       {
 479         auto &stat = stats[evt.tid][evt.name];
 480         auto &begin_ts = begin_timestamps[evt.tid][evt.name];
 481         uint64_t timestamp = std::stoull(evt.ts);
 482         if (evt.ph == "B")
 483         {
 484           if (begin_ts != 0)
 485             throw std::runtime_error{"Invalid Data"};
 486           begin_ts = timestamp;
 487         }
 488         else if (evt.ph == "E")
 489         {
 490           if (begin_ts == 0 || timestamp < begin_ts)
 491             throw std::runtime_error{"Invalid Data"};
 492           stat.accumulate(timestamp - begin_ts);
 493           begin_ts = 0;
 494         }
 495         else
 496           throw std::runtime_error{"Invalid Data - invalid value for \"ph\" : \"" + evt.ph + "\""};
 497       }
 498     }
 499
 500     for (auto &kv : begin_timestamps)
 501       for (auto &kv2 : kv.second)
 502         if (kv2.second != 0)
 503           throw std::runtime_error{"Invalid Data - B and E pair does not match."};
 504
 505     for (auto &kv : stats)
 506     {
 507       auto &tid = kv.first;
 508       auto &map = kv.second;
 509       auto &json_tid = exec_data[tid] = Json::Value{Json::objectValue};
 510       for (auto &kv : map)
 511       {
 512         auto &name = kv.first;
 513         auto &val = kv.second;
 514         json_tid[name]["Avg_Time"] = val.sum / val.count;
 515         json_tid[name]["Max_Time"] = val.max;
 516         json_tid[name]["Min_Time"] = val.min;
 517         json_tid[name]["Runtime"] = tid;
 518       }
 519     }
 520   }
 521
 522   _os << root;
 523 }
 524
 525 void ChromeTracingWriter::flush(const std::vector<std::unique_ptr<EventRecorder>> &recorders)
 526 {
 527   _os << "{\n";
 528   _os << "  " << quote("traceEvents") << ": [\n";
 529
 530   for (auto &recorder : recorders)
 531   {
 532     flushOneRecord(*recorder);
 533   }
 534
 535   _os << "    { }\n";
 536   _os << "  ]\n";
 537   _os << "}\n";
 538 }
 539
 540 void ChromeTracingWriter::flushOneRecord(const EventRecorder &recorder)
 541 {
 542   for (auto &evt : recorder.duration_events())
 543   {
 544     _os << "    " << object(evt) << ",\n";
 545   }
 546
 547   for (auto &evt : recorder.counter_events())
 548   {
 549     _os << "    " << object(evt) << ",\n";
 550   }
 551 }
 552
 553 void MDTableWriter::flush(const std::vector<std::unique_ptr<EventRecorder>> &records)
 554 {
 555   for (auto &recorder : records)
 556   {
 557     MDTableBuilder(recorder->duration_events(), recorder->counter_events()).build().write(_os);
 558   }
 559 }
 560
 561 // initialization
 562 std::mutex EventWriter::_mutex;
 563
 564 void EventWriter::readyToFlush(std::unique_ptr<EventRecorder> &&recorder)
 565 {
 566   {
 567     std::unique_lock<std::mutex> lock{_mutex};
 568
 569     _recorders.emplace_back(std::move(recorder));
 570
 571     if (--_ref_count > 0)
 572       return;
 573   }
 574   // The caller of this method is the last instance that uses EventWriter.
 575   // Let's write log files.
 576
 577   // Note. According to an internal issue, let snpe json as just file name not '.snpe.json'
 578   flush(WriteFormat::SNPE_BENCHMARK);
 579   flush(WriteFormat::CHROME_TRACING);
 580   flush(WriteFormat::MD_TABLE);
 581 }
 582
 583 void EventWriter::flush(WriteFormat write_format)
 584 {
 585   auto *writer = _actual_writers[write_format].get();
 586   assert(writer);
 587
 588   writer->flush(_recorders);
 589 }