1 /*
2  * Copyright (c) 2019 Simon Frasch
3  *
4  * Redistribution and use in source and binary forms, with or without
5  * modification, are permitted provided that the following conditions are met:
6  *
7  * 1. Redistributions of source code must retain the above copyright notice,
8  *    this list of conditions and the following disclaimer.
9  * 2. Redistributions in binary form must reproduce the above copyright
10  *    notice, this list of conditions and the following disclaimer in the
11  *    documentation and/or other materials provided with the distribution.
12  * 3. Neither the name of the copyright holder nor the names of its contributors
13  *    may be used to endorse or promote products derived from this software
14  *    without specific prior written permission.
15  *
16  * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
17  * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
18  * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
19  * ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE
20  * LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
21  * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
22  * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
23  * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
24  * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
25  * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
26  * POSSIBILITY OF SUCH DAMAGE.
27  */
28 
29 #include "rt_graph.hpp"
30 #include <algorithm>
31 #include <cmath>
32 #include <iomanip>
33 #include <numeric>
34 #include <ostream>
35 #include <ratio>
36 #include <sstream>
37 #include <string>
38 #include <tuple>
39 
40 namespace rt_graph {
41 
42 // ======================
43 // internal helper
44 // ======================
45 namespace internal {
46 namespace {
47 
48 struct Format {
Formatrt_graph::internal::__anonb6efb27b0111::Format49   Format(Stat stat_) : stat(stat_) {
50     switch (stat_) {
51       case Stat::Count:
52         header = "#";
53         space = 6;
54         break;
55       case Stat::Total:
56         header = "Total";
57         space = 14;
58         break;
59       case Stat::Mean:
60         header = "Mean";
61         space = 14;
62         break;
63       case Stat::Median:
64         header = "Median";
65         space = 14;
66         break;
67       case Stat::QuartileHigh:
68         header = "Quartile High";
69         space = 14;
70         break;
71       case Stat::QuartileLow:
72         header = "Quartile Low";
73         space = 14;
74         break;
75       case Stat::Min:
76         header = "Min";
77         space = 14;
78         break;
79       case Stat::Max:
80         header = "Max";
81         space = 14;
82         break;
83       case Stat::Percentage:
84         header = "%";
85         space = 11;
86         break;
87       case Stat::ParentPercentage:
88         header = "Parent %";
89         space = 11;
90         break;
91     }
92   }
93 
94   Stat stat;
95   std::string header;
96   std::size_t space;
97 };
98 
99 // format time input in seconds into string with appropriate unit
format_time(const double time_seconds)100 auto format_time(const double time_seconds) -> std::string {
101   if (time_seconds <= 0.0) return std::string("0 s");
102 
103   // time is always greater than 0 here
104   const double exponent = std::log10(std::abs(time_seconds));
105   const int siExponent = static_cast<int>(std::floor(exponent / 3.0) * 3);
106 
107   std::stringstream result;
108   result << std::fixed << std::setprecision(2);
109   result << time_seconds * std::pow(10.0, static_cast<double>(-siExponent));
110   result << " ";
111   switch (siExponent) {
112     case 24:
113       result << "Y";
114       break;
115     case 21:
116       result << "Z";
117       break;
118     case 18:
119       result << "E";
120       break;
121     case 15:
122       result << "P";
123       break;
124     case 12:
125       result << "T";
126       break;
127     case 9:
128       result << "G";
129       break;
130     case 6:
131       result << "M";
132       break;
133     case 3:
134       result << "k";
135       break;
136     case 0:
137       break;
138     case -3:
139       result << "m";
140       break;
141     case -6:
142       result << "u";
143       break;
144     case -9:
145       result << "n";
146       break;
147     case -12:
148       result << "p";
149       break;
150     case -15:
151       result << "f";
152       break;
153     case -18:
154       result << "a";
155       break;
156     case -21:
157       result << "z";
158       break;
159     case -24:
160       result << "y";
161       break;
162     default:
163       result << "?";
164   }
165   result << "s";
166   return result.str();
167 }
168 
calc_median(const std::vector<double>::const_iterator & begin,const std::vector<double>::const_iterator & end)169 auto calc_median(const std::vector<double>::const_iterator& begin,
170                  const std::vector<double>::const_iterator& end) -> double {
171   const auto n = end - begin;
172   if (n == 0) return 0.0;
173   if (n % 2 == 0) {
174     return (*(begin + n / 2) + *(begin + n / 2 - 1)) / 2.0;
175   } else {
176     return *(begin + n / 2);
177   }
178 }
179 
print_stat(std::ostream & out,const Format & format,const std::vector<double> & sortedTimings,double totalSum,double parentSum,double currentSum)180 auto print_stat(std::ostream& out, const Format& format, const std::vector<double>& sortedTimings,
181                 double totalSum, double parentSum, double currentSum) -> void {
182   switch (format.stat) {
183     case Stat::Count:
184       out << std::right << std::setw(format.space) << sortedTimings.size();
185       break;
186     case Stat::Total:
187       out << std::right << std::setw(format.space) << format_time(currentSum);
188       break;
189     case Stat::Mean:
190       out << std::right << std::setw(format.space)
191           << format_time(currentSum / sortedTimings.size());
192       break;
193     case Stat::Median:
194       out << std::right << std::setw(format.space)
195           << format_time(calc_median(sortedTimings.begin(), sortedTimings.end()));
196       break;
197     case Stat::QuartileHigh: {
198       const double upperQuartile =
199           calc_median(sortedTimings.begin() + sortedTimings.size() / 2 +
200                           (sortedTimings.size() % 2) * (sortedTimings.size() > 1),
201                       sortedTimings.end());
202       out << std::right << std::setw(format.space) << format_time(upperQuartile);
203     } break;
204     case Stat::QuartileLow: {
205       const double lowerQuartile =
206           calc_median(sortedTimings.begin(), sortedTimings.begin() + sortedTimings.size() / 2);
207       out << std::right << std::setw(format.space) << format_time(lowerQuartile);
208     } break;
209     case Stat::Min:
210       out << std::right << std::setw(format.space) << format_time(sortedTimings.front());
211       break;
212     case Stat::Max:
213       out << std::right << std::setw(format.space) << format_time(sortedTimings.back());
214       break;
215     case Stat::Percentage: {
216       const double p =
217           (totalSum < currentSum || totalSum == 0) ? 100.0 : currentSum / totalSum * 100.0;
218       out << std::right << std::fixed << std::setprecision(2) << std::setw(format.space) << p;
219     } break;
220     case Stat::ParentPercentage: {
221       const double p =
222           (parentSum < currentSum || parentSum == 0) ? 100.0 : currentSum / parentSum * 100.0;
223       out << std::right << std::fixed << std::setprecision(2) << std::setw(format.space) << p;
224     } break;
225   }
226 }
227 
228 // Helper struct for creating a tree of timings
229 struct TimeStampPair {
230   std::string identifier;
231   double time = 0.0;
232   std::size_t startIdx = 0;
233   std::size_t stopIdx = 0;
234   internal::TimingNode* nodePtr = nullptr;
235 };
236 
calculate_statistic(std::vector<double> values)237 auto calculate_statistic(std::vector<double> values)
238     -> std::tuple<double, double, double, double, double, double, double> {
239   if (values.empty()) return std::make_tuple(0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0);
240   std::sort(values.begin(), values.end());
241 
242   const double min = values.front();
243   const double max = values.back();
244 
245   const double median = calc_median(values.begin(), values.end());
246   const double sum = std::accumulate(values.begin(), values.end(), 0.0);
247   const double mean = sum / values.size();
248 
249   const double lowerQuartile = calc_median(values.begin(), values.begin() + values.size() / 2);
250   const double upperQuartile = calc_median(
251       values.begin() + values.size() / 2 + (values.size() % 2) * (values.size() > 1), values.end());
252 
253   return std::make_tuple(sum, mean, median, min, max, lowerQuartile, upperQuartile);
254 }
255 
256 // print rt_graph nodes in tree recursively
print_node(std::ostream & out,const std::vector<internal::Format> formats,const std::size_t identifierSpace,const std::string & nodePrefix,const internal::TimingNode & node,const bool isSubNode,const bool isLastSubnode,double parentTime,double totalTime)257 auto print_node(std::ostream& out, const std::vector<internal::Format> formats,
258                 const std::size_t identifierSpace, const std::string& nodePrefix,
259                 const internal::TimingNode& node, const bool isSubNode, const bool isLastSubnode,
260                 double parentTime, double totalTime) -> void {
261   double sum, mean, median, min, max, lowerQuartile, upperQuartile;
262   std::tie(sum, mean, median, min, max, lowerQuartile, upperQuartile) =
263       calculate_statistic(node.timings);
264 
265   if (!isSubNode) {
266     totalTime = sum;
267     parentTime = sum;
268   }
269 
270   const double totalPercentage =
271       (totalTime < sum || totalTime == 0) ? 100.0 : sum / totalTime * 100.0;
272 
273   const double parentPercentage =
274       (parentTime < sum || parentTime == 0) ? 100.0 : sum / parentTime * 100.0;
275 
276   std::stringstream totalPercentageStream;
277   totalPercentageStream << std::fixed << std::setprecision(2) << totalPercentage;
278   std::stringstream parentPercentageStream;
279   parentPercentageStream << std::fixed << std::setprecision(2) << parentPercentage;
280 
281   out << std::left << std::setw(identifierSpace);
282   if (isSubNode)
283     out << nodePrefix + "- " + node.identifier;
284   else
285     out << nodePrefix + node.identifier;
286 
287   auto sortedTimings = node.timings;
288   std::sort(sortedTimings.begin(), sortedTimings.end());
289 
290   const double currentTime = std::accumulate(sortedTimings.begin(), sortedTimings.end(), 0.0);
291   for (const auto& format : formats) {
292     print_stat(out, format, sortedTimings, totalTime, parentTime, currentTime);
293   }
294 
295   out << std::endl;
296 
297   for (const auto& subNode : node.subNodes) {
298     print_node(out, formats, identifierSpace, nodePrefix + std::string(" |"), subNode, true,
299                &subNode == &node.subNodes.back(), sum, totalTime);
300     if (!isLastSubnode && &subNode == &node.subNodes.back()) {
301       out << nodePrefix << std::endl;
302     }
303   }
304 }
305 
306 // determine length of padding required for printing entire tree identifiers recursively
max_node_identifier_length(const internal::TimingNode & node,const std::size_t recursionDepth,const std::size_t addPerLevel,const std::size_t parentMax)307 auto max_node_identifier_length(const internal::TimingNode& node, const std::size_t recursionDepth,
308                                 const std::size_t addPerLevel, const std::size_t parentMax)
309     -> std::size_t {
310   std::size_t currentLength = node.identifier.length() + recursionDepth * addPerLevel;
311   std::size_t max = currentLength > parentMax ? currentLength : parentMax;
312   for (const auto& subNode : node.subNodes) {
313     const std::size_t subMax =
314         max_node_identifier_length(subNode, recursionDepth + 1, addPerLevel, max);
315     if (subMax > max) max = subMax;
316   }
317 
318   return max;
319 }
320 
export_node_json(const std::string & padding,const std::list<internal::TimingNode> & nodeList,std::ostream & stream)321 auto export_node_json(const std::string& padding, const std::list<internal::TimingNode>& nodeList,
322                       std::ostream& stream) -> void {
323   stream << "{" << std::endl;
324   const std::string nodePadding = padding + "  ";
325   const std::string subNodePadding = nodePadding + "  ";
326   for (const auto& node : nodeList) {
327     stream << nodePadding << "\"" << node.identifier << "\" : {" << std::endl;
328     stream << subNodePadding << "\"timings\" : [";
329     for (const auto& value : node.timings) {
330       stream << value;
331       if (&value != &(node.timings.back())) stream << ", ";
332     }
333     stream << "]," << std::endl;
334     stream << subNodePadding << "\"sub-timings\" : ";
335     export_node_json(subNodePadding, node.subNodes, stream);
336     stream << nodePadding << "}";
337     if (&node != &(nodeList.back())) stream << ",";
338     stream << std::endl;
339   }
340   stream << padding << "}" << std::endl;
341 }
342 
extract_timings(const std::string & identifier,const std::list<TimingNode> & nodes,std::vector<double> & timings)343 auto extract_timings(const std::string& identifier, const std::list<TimingNode>& nodes,
344                      std::vector<double>& timings) -> void {
345   for (const auto& node : nodes) {
346     if (node.identifier == identifier) {
347       timings.insert(timings.end(), node.timings.begin(), node.timings.end());
348     }
349     extract_timings(identifier, node.subNodes, timings);
350   }
351 }
352 
353 }  // namespace
354 }  // namespace internal
355 
356 // ======================
357 // Timer
358 // ======================
process() const359 auto Timer::process() const -> TimingResult {
360   std::list<internal::TimingNode> results;
361   std::stringstream warnings;
362 
363   try {
364     std::vector<internal::TimeStampPair> timePairs;
365     timePairs.reserve(timeStamps_.size() / 2);
366 
367     // create pairs of start / stop timings
368     for (std::size_t i = 0; i < timeStamps_.size(); ++i) {
369       if (timeStamps_[i].type == internal::TimeStampType::Start) {
370         internal::TimeStampPair pair;
371         pair.startIdx = i;
372         pair.identifier = std::string(timeStamps_[i].identifierPtr);
373         std::size_t numInnerMatchingIdentifiers = 0;
374         // search for matching stop after start
375         for (std::size_t j = i + 1; j < timeStamps_.size(); ++j) {
376           // only consider matching identifiers
377           if (std::string(timeStamps_[j].identifierPtr) ==
378               std::string(timeStamps_[i].identifierPtr)) {
379             if (timeStamps_[j].type == internal::TimeStampType::Stop &&
380                 numInnerMatchingIdentifiers == 0) {
381               // Matching stop found
382               std::chrono::duration<double> duration = timeStamps_[j].time - timeStamps_[i].time;
383               pair.time = duration.count();
384               pair.stopIdx = j;
385               timePairs.push_back(pair);
386               if (pair.time < 0) {
387                 warnings << "rt_graph WARNING:Measured time is negative. Non-steady system-clock?!"
388                          << std::endl;
389               }
390               break;
391             } else if (timeStamps_[j].type == internal::TimeStampType::Stop &&
392                        numInnerMatchingIdentifiers > 0) {
393               // inner stop with matching identifier
394               --numInnerMatchingIdentifiers;
395             } else if (timeStamps_[j].type == internal::TimeStampType::Start) {
396               // inner start with matching identifier
397               ++numInnerMatchingIdentifiers;
398             }
399           }
400         }
401         if (pair.stopIdx == 0) {
402           warnings << "rt_graph WARNING: Start / stop time stamps do not match for \""
403                    << timeStamps_[i].identifierPtr << "\"!" << std::endl;
404         }
405       }
406     }
407 
408     // create tree of timings where sub-nodes represent timings fully enclosed by another start /
409     // stop pair Use the fact that timePairs is sorted by startIdx
410     for (std::size_t i = 0; i < timePairs.size(); ++i) {
411       auto& pair = timePairs[i];
412 
413       // find potential parent by going backwards through pairs, starting with the current pair
414       // position
415       for (auto timePairIt = timePairs.rbegin() + (timePairs.size() - i);
416            timePairIt != timePairs.rend(); ++timePairIt) {
417         if (timePairIt->stopIdx > pair.stopIdx && timePairIt->nodePtr != nullptr) {
418           auto& parentNode = *(timePairIt->nodePtr);
419           // check if sub-node with identifier exists
420           bool nodeFound = false;
421           for (auto& subNode : parentNode.subNodes) {
422             if (subNode.identifier == pair.identifier) {
423               nodeFound = true;
424               subNode.timings.push_back(pair.time);
425               // mark node position in pair for finding sub-nodes
426               pair.nodePtr = &(subNode);
427               break;
428             }
429           }
430           if (!nodeFound) {
431             // create new sub-node
432             internal::TimingNode newNode;
433             newNode.identifier = pair.identifier;
434             newNode.timings.push_back(pair.time);
435             parentNode.subNodes.push_back(std::move(newNode));
436             // mark node position in pair for finding sub-nodes
437             pair.nodePtr = &(parentNode.subNodes.back());
438           }
439           break;
440         }
441       }
442 
443       // No parent found, must be top level node
444       if (pair.nodePtr == nullptr) {
445         // Check if top level node with same name exists
446         for (auto& topNode : results) {
447           if (topNode.identifier == pair.identifier) {
448             topNode.timings.push_back(pair.time);
449             pair.nodePtr = &(topNode);
450             break;
451           }
452         }
453       }
454 
455       // New top level node
456       if (pair.nodePtr == nullptr) {
457         internal::TimingNode newNode;
458         newNode.identifier = pair.identifier;
459         newNode.timings.push_back(pair.time);
460         // newNode.parent = nullptr;
461         results.push_back(std::move(newNode));
462 
463         // mark node position in pair for finding sub-nodes
464         pair.nodePtr = &(results.back());
465       }
466     }
467   } catch (const std::exception& e) {
468     warnings << "rt_graph WARNING: Processing of timings failed: " << e.what() << std::endl;
469   } catch (...) {
470     warnings << "rt_graph WARNING: Processing of timings failed!" << std::endl;
471   }
472 
473   return TimingResult(std::move(results), warnings.str());
474 }
475 
476 // ======================
477 //
478 // ======================
479 
json() const480 auto TimingResult::json() const -> std::string {
481   std::stringstream jsonStream;
482   jsonStream << std::scientific;
483   internal::export_node_json("", rootNodes_, jsonStream);
484   return jsonStream.str();
485 }
486 
get_timings(const std::string & identifier) const487 auto TimingResult::get_timings(const std::string& identifier) const -> std::vector<double> {
488   std::vector<double> timings;
489   internal::extract_timings(identifier, rootNodes_, timings);
490   return timings;
491 }
492 
print(std::vector<Stat> statistic) const493 auto TimingResult::print(std::vector<Stat> statistic) const -> std::string {
494   std::stringstream stream;
495 
496   // print warnings
497   stream << warnings_;
498 
499   // calculate space for printing identifiers
500   std::size_t identifierSpace = 0;
501   for (const auto& node : rootNodes_) {
502     const auto nodeMax = internal::max_node_identifier_length(node, 0, 2, identifierSpace);
503     if (nodeMax > identifierSpace) identifierSpace = nodeMax;
504   }
505   identifierSpace += 3;
506 
507   auto totalSpace = identifierSpace;
508 
509   std::vector<internal::Format> formats;
510   formats.reserve(statistic.size());
511   for (const auto& stat : statistic) {
512     formats.emplace_back(stat);
513     totalSpace += formats.back().space;
514   }
515 
516   // Construct table header
517 
518   // Table start
519   stream << std::string(totalSpace, '=') << std::endl;
520 
521   // header
522   stream << std::right << std::setw(identifierSpace) << "";
523   for (const auto& format : formats) {
524     stream << std::right << std::setw(format.space) << format.header;
525   }
526   stream << std::endl;
527 
528   // Header separation line
529   stream << std::string(totalSpace, '-') << std::endl;
530 
531   // print all timings
532   for (const auto& node : rootNodes_) {
533     internal::print_node(stream, formats, identifierSpace, std::string(), node, false, true, 0.0,
534                          0.0);
535     stream << std::endl;
536   }
537 
538   // End table
539   stream << std::string(totalSpace, '=') << std::endl;
540 
541   return stream.str();
542 }
543 
544 }  // namespace rt_graph
545 
546