Mercurial > hg > svcore
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 |