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