1 /*
2  *    Copyright (C) 2019
3  *    Matthias P. Braendli (matthias.braendli@mpb.li)
4  *
5  *    This file is part of the welle.io.
6  *    Many of the ideas as implemented in welle.io are derived from
7  *    other work, made available through the GNU general Public License.
8  *    All copyrights of the original authors are recognized.
9  *
10  *    welle.io is free software; you can redistribute it and/or modify
11  *    it under the terms of the GNU General Public License as published by
12  *    the Free Software Foundation; either version 2 of the License, or
13  *    (at your option) any later version.
14  *
15  *    welle.io is distributed in the hope that it will be useful,
16  *    but WITHOUT ANY WARRANTY; without even the implied warranty of
17  *    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
18  *    GNU General Public License for more details.
19  *
20  *    You should have received a copy of the GNU General Public License
21  *    along with welle.io; if not, write to the Free Software
22  *    Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
23  *
24  */
25 
26 #if defined(WITH_PROFILING)
27 #include <iostream>
28 #include <fstream>
29 #include <map>
30 #include <utility>
31 #include <cmath>
32 
33 #include "various/profiling.h"
34 
35 using namespace std;
36 
37 static Profiler profiler;
38 
get_profiler()39 Profiler& get_profiler() {
40     return profiler;
41 }
42 
43 #define MARK_TO_CSTR_CASE(m) case ProfilingMark::m: return #m;
mark_to_cstr(const ProfilingMark & m)44 const char* mark_to_cstr(const ProfilingMark& m) {
45     switch (m) {
46         MARK_TO_CSTR_CASE(NotSynced)
47         MARK_TO_CSTR_CASE(SyncOnEndNull)
48         MARK_TO_CSTR_CASE(SyncOnPhase)
49         MARK_TO_CSTR_CASE(FindIndex)
50         MARK_TO_CSTR_CASE(DataSymbols)
51         MARK_TO_CSTR_CASE(PushAllSymbols)
52         MARK_TO_CSTR_CASE(OnNewNull)
53         MARK_TO_CSTR_CASE(DecodeTII)
54 
55         MARK_TO_CSTR_CASE(ProcessPRS)
56         MARK_TO_CSTR_CASE(ProcessSymbol)
57         MARK_TO_CSTR_CASE(Deinterleaver)
58         MARK_TO_CSTR_CASE(FICHandler)
59         MARK_TO_CSTR_CASE(MSCHandler)
60         MARK_TO_CSTR_CASE(SymbolProcessed)
61 
62         MARK_TO_CSTR_CASE(DAGetMSCData)
63         MARK_TO_CSTR_CASE(DADeinterleave)
64         MARK_TO_CSTR_CASE(DADeconvolve)
65         MARK_TO_CSTR_CASE(DADispersal)
66         MARK_TO_CSTR_CASE(DADecode)
67         MARK_TO_CSTR_CASE(DADone)
68     }
69 
70     return "unknown";
71 }
72 
Profiler()73 Profiler::Profiler() {
74     clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &startup_time_cputime);
75     clock_gettime(CLOCK_MONOTONIC, &startup_time_monotonic);
76 }
77 
operator +=(struct timespec & t1,const struct timespec & t2)78 struct timespec& operator+=(struct timespec& t1, const struct timespec& t2) {
79     t1.tv_sec += t2.tv_sec;
80     t1.tv_nsec += t2.tv_nsec;
81 
82     if (t1.tv_nsec >= 1000000000ll) {
83         t1.tv_nsec -= 1000000000ll;
84         t1.tv_sec += 1;
85     }
86 
87     return t1;
88 }
89 
operator -(struct timespec t1,struct timespec t2)90 struct timespec operator-(struct timespec t1, struct timespec t2) {
91     struct timespec t;
92 
93     if (t1.tv_sec < t2.tv_sec) {
94         cerr << "******************* Timestamp difference negative" << endl;
95         t.tv_sec = 0;
96         t.tv_nsec = 0;
97         return t;
98     }
99 
100     t.tv_sec = t1.tv_sec - t2.tv_sec;
101 
102     if (t1.tv_nsec >= t2.tv_nsec) {
103         t.tv_nsec = t1.tv_nsec - t2.tv_nsec;
104     }
105     else {
106         t.tv_sec -= 1;
107         t.tv_nsec = 1000000000ll + t1.tv_nsec - t2.tv_nsec;
108     }
109     return t;
110 }
111 
operator <<(std::ostream & out,const struct timespec & ts)112 std::ostream& operator<<(std::ostream& out, const struct timespec& ts)
113 {
114     char nanos[32];
115     snprintf(nanos, 31, "%09ld", ts.tv_nsec);
116     return out << ts.tv_sec << "." << nanos;
117 }
118 
~Profiler()119 Profiler::~Profiler() {
120     struct timespec stop_time_cputime;
121     struct timespec stop_time_monotonic;
122     clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &stop_time_cputime);
123     clock_gettime(CLOCK_MONOTONIC, &stop_time_monotonic);
124 
125     ofstream dump("profiling_points.csv");
126     dump << "thread_id,mark,time_sec,time_ns" << endl;
127     for (const auto tp: m_timepoints) {
128         for (const auto points : tp.second) {
129             dump << tp.first << "," <<
130                 mark_to_cstr(points.p) << "," <<
131                 points.timestamp.tv_sec << "," <<
132                 points.timestamp.tv_nsec << endl;
133         }
134     }
135 
136     ofstream profiling("profiling_stats.csv");
137     profiling << "cputime,start," << startup_time_cputime << endl;
138     profiling << "cputime,stop," << stop_time_cputime << endl;
139     profiling << "monotonic,start," << startup_time_monotonic << endl;
140     profiling << "monotonic,stop," << stop_time_monotonic << endl;
141     profiling << "cputime,diff," << stop_time_cputime - startup_time_cputime << endl;
142     profiling << "monotonic,diff," << stop_time_monotonic - startup_time_monotonic << endl;
143     profiling << "frames,decoded," << num_frames_decoded << endl;
144 
145     // See http://www.graphviz.org/documentation/
146     ofstream graph("profiling.dot");
147 
148     graph << "digraph G { " << endl;
149 
150     size_t count = 0;
151 
152     for (const auto tp: m_timepoints) {
153         if (tp.second.size() < 2) {
154             continue;
155         }
156 
157         graph << "subgraph cluster_" << tp.first << " { " << endl;
158         graph << "colorscheme=\"gnbu8\";" << endl;
159         graph << "bgcolor=" << (count % 8) + 1 << ";" << endl;
160         count++;
161 
162         map<pair<ProfilingMark, ProfilingMark>, struct timespec> from_to_times;
163 
164         for (auto it = tp.second.begin(); next(it) != tp.second.end(); ++it) {
165             from_to_times[make_pair(it->p, next(it)->p)] += next(it)->timestamp - it->timestamp;
166         }
167 
168         double maxw = 0;
169         for (auto& d : from_to_times) {
170             double w = log10(1 + d.second.tv_sec * 1000 + d.second.tv_nsec / 1000000);
171             if (w > maxw) maxw = w;
172         }
173 
174         for (auto& d : from_to_times) {
175             int w = (d.second.tv_sec * 1000 + d.second.tv_nsec / 1000000);
176 
177             char color[16];
178             snprintf(color, 15, "#%02x%02x%02x", (int)(255 * log10(w+1)/maxw), 0, 0);
179 
180             graph << mark_to_cstr(d.first.first) << " -> " << mark_to_cstr(d.first.second) <<
181                 " [color=\"" << color << "\""
182                 " label=\"" << w << "ms\""
183                 "];" << endl;
184         }
185         graph << "}" << endl;
186     }
187     graph << "}" << endl;
188 }
189 
save_time(const ProfilingMark m)190 void Profiler::save_time(const ProfilingMark m) {
191     const auto id = this_thread::get_id();
192 
193     struct timespec now;
194     clock_gettime(CLOCK_THREAD_CPUTIME_ID, &now);
195 
196     lock_guard<mutex> lock(m_mutex);
197     m_timepoints[id].emplace_back(now, m);
198 }
199 
frame_decoded()200 void Profiler::frame_decoded() {
201     num_frames_decoded++;
202 }
203 
204 #endif // defined(WITH_PROFILING)
205