comparison base/Profiler.cpp @ 183:146eb9e35baa

* Improve output from Profiler class and make it incur less (no) overhead in release builds with NO_TIMING defined * Fix a lock contention issue in spectrogram * Marginal optimisations elsewhere
author Chris Cannam
date Tue, 10 Oct 2006 14:51:17 +0000
parents fb8422cf4326
children 91fdc752e540
comparison
equal deleted inserted replaced
182:f75f8a1cd7b1 183:146eb9e35baa
21 #include <iostream> 21 #include <iostream>
22 #include "Profiler.h" 22 #include "Profiler.h"
23 23
24 #include <vector> 24 #include <vector>
25 #include <algorithm> 25 #include <algorithm>
26 26 #include <set>
27 //#define NO_TIMING 1 27 #include <map>
28
29 #define WANT_TIMING 1
30
31 #ifdef NDEBUG
32 #ifndef WANT_TIMING
33 #define NO_TIMING 1
34 #endif
35 #endif
36 28
37 using std::cerr; 29 using std::cerr;
38 using std::endl; 30 using std::endl;
39 31
40 Profiles* Profiles::m_instance = 0; 32 Profiles* Profiles::m_instance = 0;
61 ProfilePair &pair(m_profiles[id]); 53 ProfilePair &pair(m_profiles[id]);
62 ++pair.first; 54 ++pair.first;
63 pair.second.first += time; 55 pair.second.first += time;
64 pair.second.second = pair.second.second + rt; 56 pair.second.second = pair.second.second + rt;
65 57
66 TimePair &timePair(m_lastCalls[id]); 58 TimePair &lastPair(m_lastCalls[id]);
67 timePair.first = time; 59 lastPair.first = time;
68 timePair.second = rt; 60 lastPair.second = rt;
61
62 TimePair &worstPair(m_worstCalls[id]);
63 if (time > worstPair.first) {
64 worstPair.first = time;
65 }
66 if (rt > worstPair.second) {
67 worstPair.second = rt;
68 }
69 #endif 69 #endif
70 } 70 }
71 71
72 void Profiles::dump() 72 void Profiles::dump() const
73 { 73 {
74 #ifndef NO_TIMING
75
76 fprintf(stderr, "Profiling points:\n");
77
78 fprintf(stderr, "\nBy name:\n");
79
80 typedef std::set<const char *, std::less<std::string> > StringSet;
81
82 StringSet profileNames;
83 for (ProfileMap::const_iterator i = m_profiles.begin();
84 i != m_profiles.end(); ++i) {
85 profileNames.insert(i->first);
86 }
87
88 for (StringSet::const_iterator i = profileNames.begin();
89 i != profileNames.end(); ++i) {
90
91 ProfileMap::const_iterator j = m_profiles.find(*i);
92
93 if (j == m_profiles.end()) continue;
94
95 const ProfilePair &pp(j->second);
96
97 fprintf(stderr, "%s(%d):\n", *i, pp.first);
98
99 fprintf(stderr, "\tCPU: \t%.9g ms/call \t[%d ms total]\n",
100 (((double)pp.second.first * 1000.0 /
101 (double)pp.first) / CLOCKS_PER_SEC),
102 int((pp.second.first * 1000.0) / CLOCKS_PER_SEC));
103
104 fprintf(stderr, "\tReal: \t%s ms \t[%s ms total]\n",
105 ((pp.second.second / pp.first) * 1000).toString().c_str(),
106 (pp.second.second * 1000).toString().c_str());
107
108 WorstCallMap::const_iterator k = m_worstCalls.find(*i);
109 if (k == m_worstCalls.end()) continue;
110
111 const TimePair &wc(k->second);
112
113 fprintf(stderr, "\tWorst:\t%s ms/call \t[%d ms CPU]\n",
114 (wc.second * 1000).toString().c_str(),
115 int((wc.first * 1000.0) / CLOCKS_PER_SEC));
116 }
117
118 typedef std::multimap<RealTime, const char *> TimeRMap;
119 typedef std::multimap<int, const char *> IntRMap;
120
121 TimeRMap totmap, avgmap, worstmap;
122 IntRMap ncallmap;
123
124 for (ProfileMap::const_iterator i = m_profiles.begin();
125 i != m_profiles.end(); ++i) {
126 totmap.insert(TimeRMap::value_type(i->second.second.second, i->first));
127 avgmap.insert(TimeRMap::value_type(i->second.second.second /
128 i->second.first, i->first));
129 ncallmap.insert(IntRMap::value_type(i->second.first, i->first));
130 }
131
132 for (WorstCallMap::const_iterator i = m_worstCalls.begin();
133 i != m_worstCalls.end(); ++i) {
134 worstmap.insert(TimeRMap::value_type(i->second.second,
135 i->first));
136 }
137
138
139 fprintf(stderr, "\nBy total:\n");
140 for (TimeRMap::const_iterator i = totmap.end(); i != totmap.begin(); ) {
141 --i;
142 fprintf(stderr, "%-40s %s ms\n", i->second,
143 (i->first * 1000).toString().c_str());
144 }
145
146 fprintf(stderr, "\nBy average:\n");
147 for (TimeRMap::const_iterator i = avgmap.end(); i != avgmap.begin(); ) {
148 --i;
149 fprintf(stderr, "%-40s %s ms\n", i->second,
150 (i->first * 1000).toString().c_str());
151 }
152
153 fprintf(stderr, "\nBy worst case:\n");
154 for (TimeRMap::const_iterator i = worstmap.end(); i != worstmap.begin(); ) {
155 --i;
156 fprintf(stderr, "%-40s %s ms\n", i->second,
157 (i->first * 1000).toString().c_str(), i->second);
158 }
159
160 fprintf(stderr, "\nBy number of calls:\n");
161 for (IntRMap::const_iterator i = ncallmap.end(); i != ncallmap.begin(); ) {
162 --i;
163 fprintf(stderr, "%-40s %d\n", i->second, i->first);
164 }
165
166 #endif
167 }
168
74 #ifndef NO_TIMING 169 #ifndef NO_TIMING
75 cerr << "Profiles::dump() :\n";
76
77 // I'm finding these two confusing dumped out in random order,
78 // so I'm going to sort them alphabetically:
79
80 std::vector<const char *> profileNames;
81 for (ProfileMap::iterator i = m_profiles.begin();
82 i != m_profiles.end(); ++i) {
83 profileNames.push_back((*i).first);
84 }
85
86 std::sort(profileNames.begin(), profileNames.end());
87
88 for (std::vector<const char *>::iterator i = profileNames.begin();
89 i != profileNames.end(); ++i) {
90
91 cerr << "-> " << *i << ": CPU: "
92 << m_profiles[*i].first << " calls, "
93 << int((m_profiles[*i].second.first * 1000.0) / CLOCKS_PER_SEC) << "ms, "
94 << (((double)m_profiles[*i].second.first * 1000000.0 /
95 (double)m_profiles[*i].first) / CLOCKS_PER_SEC) << "us/call"
96 << endl;
97
98 cerr << "-> " << *i << ": real: "
99 << m_profiles[*i].first << " calls, "
100 << m_profiles[*i].second.second << ", "
101 << (m_profiles[*i].second.second / m_profiles[*i].first)
102 << "/call"
103 << endl;
104
105 cerr << "-> " << *i << ": last: CPU: "
106 << int((m_lastCalls[*i].first * 1000.0) / CLOCKS_PER_SEC) << "ms, "
107 << " real: "
108 << m_lastCalls[*i].second << endl;
109 }
110
111 cerr << "Profiles::dump() finished\n";
112 #endif
113 }
114 170
115 Profiler::Profiler(const char* c, bool showOnDestruct) 171 Profiler::Profiler(const char* c, bool showOnDestruct)
116 : m_c(c), 172 : m_c(c),
117 m_showOnDestruct(showOnDestruct) 173 m_showOnDestruct(showOnDestruct)
118 { 174 {
119 #ifndef NO_TIMING
120 m_startCPU = clock(); 175 m_startCPU = clock();
121 176
122 struct timeval tv; 177 struct timeval tv;
123 (void)gettimeofday(&tv, 0); 178 (void)gettimeofday(&tv, 0);
124 m_startTime = RealTime::fromTimeval(tv); 179 m_startTime = RealTime::fromTimeval(tv);
125 #endif
126 } 180 }
127 181
128 void 182 void
129 Profiler::update() 183 Profiler::update() const
130 { 184 {
131 #ifndef NO_TIMING
132 clock_t elapsedCPU = clock() - m_startCPU; 185 clock_t elapsedCPU = clock() - m_startCPU;
133 186
134 struct timeval tv; 187 struct timeval tv;
135 (void)gettimeofday(&tv, 0); 188 (void)gettimeofday(&tv, 0);
136 RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime; 189 RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime;
137 190
138 cerr << "Profiler : id = " << m_c 191 cerr << "Profiler : id = " << m_c
139 << " - elapsed so far = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC) 192 << " - elapsed so far = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC)
140 << "ms CPU, " << elapsedTime << " real" << endl; 193 << "ms CPU, " << elapsedTime << " real" << endl;
141 #endif
142 } 194 }
143 195
144 Profiler::~Profiler() 196 Profiler::~Profiler()
145 { 197 {
146 #ifndef NO_TIMING
147 clock_t elapsedCPU = clock() - m_startCPU; 198 clock_t elapsedCPU = clock() - m_startCPU;
148 199
149 struct timeval tv; 200 struct timeval tv;
150 (void)gettimeofday(&tv, 0); 201 (void)gettimeofday(&tv, 0);
151 RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime; 202 RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime;
154 205
155 if (m_showOnDestruct) 206 if (m_showOnDestruct)
156 cerr << "Profiler : id = " << m_c 207 cerr << "Profiler : id = " << m_c
157 << " - elapsed = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC) 208 << " - elapsed = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC)
158 << "ms CPU, " << elapsedTime << " real" << endl; 209 << "ms CPU, " << elapsedTime << " real" << endl;
210 }
211
159 #endif 212 #endif
160 } 213
161