annotate base/Profiler.cpp @ 753:fb6313da1df6

3d model was marked as exportable, but without any export code
author Chris Cannam
date Tue, 11 Dec 2012 13:07:40 +0000
parents 29efe322ab47
children e802e550a1f2
rev   line source
Chris@49 1 /* -*- c-basic-offset: 4 indent-tabs-mode: nil -*- vi:set ts=8 sts=4 sw=4: */
Chris@0 2
Chris@0 3 /*
Chris@52 4 Sonic Visualiser
Chris@52 5 An audio file viewer and annotation editor.
Chris@52 6 Centre for Digital Music, Queen Mary, University of London.
Chris@0 7
Chris@52 8 This program is free software; you can redistribute it and/or
Chris@52 9 modify it under the terms of the GNU General Public License as
Chris@52 10 published by the Free Software Foundation; either version 2 of the
Chris@52 11 License, or (at your option) any later version. See the file
Chris@52 12 COPYING included with this distribution for more information.
Chris@0 13 */
Chris@0 14
Chris@0 15 /*
Chris@0 16 This is a modified version of a source file from the
Chris@0 17 Rosegarden MIDI and audio sequencer and notation editor.
Chris@202 18 This file copyright 2000-2006 Chris Cannam, Guillaume Laurent,
Chris@202 19 and QMUL.
Chris@0 20 */
Chris@0 21
Chris@0 22 #include <iostream>
Chris@0 23 #include "Profiler.h"
Chris@0 24
Chris@658 25 #include <cstdio>
Chris@658 26
Chris@0 27 #include <vector>
Chris@0 28 #include <algorithm>
Chris@183 29 #include <set>
Chris@183 30 #include <map>
Chris@0 31
Chris@0 32 using std::cerr;
Chris@0 33 using std::endl;
Chris@0 34
Chris@0 35 Profiles* Profiles::m_instance = 0;
Chris@0 36
Chris@0 37 Profiles* Profiles::getInstance()
Chris@0 38 {
Chris@0 39 if (!m_instance) m_instance = new Profiles();
Chris@0 40
Chris@0 41 return m_instance;
Chris@0 42 }
Chris@0 43
Chris@0 44 Profiles::Profiles()
Chris@0 45 {
Chris@0 46 }
Chris@0 47
Chris@0 48 Profiles::~Profiles()
Chris@0 49 {
Chris@0 50 dump();
Chris@0 51 }
Chris@0 52
Chris@259 53 void Profiles::accumulate(
Chris@259 54 #ifndef NO_TIMING
Chris@259 55 const char* id, clock_t time, RealTime rt
Chris@259 56 #else
Chris@259 57 const char*, clock_t, RealTime
Chris@259 58 #endif
Chris@259 59 )
Chris@0 60 {
Chris@0 61 #ifndef NO_TIMING
Chris@0 62 ProfilePair &pair(m_profiles[id]);
Chris@0 63 ++pair.first;
Chris@0 64 pair.second.first += time;
Chris@0 65 pair.second.second = pair.second.second + rt;
Chris@0 66
Chris@183 67 TimePair &lastPair(m_lastCalls[id]);
Chris@183 68 lastPair.first = time;
Chris@183 69 lastPair.second = rt;
Chris@183 70
Chris@183 71 TimePair &worstPair(m_worstCalls[id]);
Chris@183 72 if (time > worstPair.first) {
Chris@183 73 worstPair.first = time;
Chris@183 74 }
Chris@183 75 if (rt > worstPair.second) {
Chris@183 76 worstPair.second = rt;
Chris@183 77 }
Chris@0 78 #endif
Chris@0 79 }
Chris@0 80
Chris@183 81 void Profiles::dump() const
Chris@0 82 {
Chris@183 83 #ifndef NO_TIMING
Chris@0 84
Chris@183 85 fprintf(stderr, "Profiling points:\n");
Chris@0 86
Chris@183 87 fprintf(stderr, "\nBy name:\n");
Chris@183 88
Chris@183 89 typedef std::set<const char *, std::less<std::string> > StringSet;
Chris@183 90
Chris@183 91 StringSet profileNames;
Chris@183 92 for (ProfileMap::const_iterator i = m_profiles.begin();
Chris@183 93 i != m_profiles.end(); ++i) {
Chris@183 94 profileNames.insert(i->first);
Chris@0 95 }
Chris@0 96
Chris@183 97 for (StringSet::const_iterator i = profileNames.begin();
Chris@183 98 i != profileNames.end(); ++i) {
Chris@0 99
Chris@183 100 ProfileMap::const_iterator j = m_profiles.find(*i);
Chris@0 101
Chris@183 102 if (j == m_profiles.end()) continue;
Chris@0 103
Chris@183 104 const ProfilePair &pp(j->second);
Chris@0 105
Chris@183 106 fprintf(stderr, "%s(%d):\n", *i, pp.first);
Chris@183 107
Chris@183 108 fprintf(stderr, "\tCPU: \t%.9g ms/call \t[%d ms total]\n",
Chris@183 109 (((double)pp.second.first * 1000.0 /
Chris@183 110 (double)pp.first) / CLOCKS_PER_SEC),
Chris@183 111 int((pp.second.first * 1000.0) / CLOCKS_PER_SEC));
Chris@183 112
Chris@183 113 fprintf(stderr, "\tReal: \t%s ms \t[%s ms total]\n",
Chris@183 114 ((pp.second.second / pp.first) * 1000).toString().c_str(),
Chris@183 115 (pp.second.second * 1000).toString().c_str());
Chris@183 116
Chris@183 117 WorstCallMap::const_iterator k = m_worstCalls.find(*i);
Chris@183 118 if (k == m_worstCalls.end()) continue;
Chris@183 119
Chris@183 120 const TimePair &wc(k->second);
Chris@183 121
Chris@183 122 fprintf(stderr, "\tWorst:\t%s ms/call \t[%d ms CPU]\n",
Chris@183 123 (wc.second * 1000).toString().c_str(),
Chris@183 124 int((wc.first * 1000.0) / CLOCKS_PER_SEC));
Chris@0 125 }
Chris@0 126
Chris@183 127 typedef std::multimap<RealTime, const char *> TimeRMap;
Chris@183 128 typedef std::multimap<int, const char *> IntRMap;
Chris@183 129
Chris@183 130 TimeRMap totmap, avgmap, worstmap;
Chris@183 131 IntRMap ncallmap;
Chris@183 132
Chris@183 133 for (ProfileMap::const_iterator i = m_profiles.begin();
Chris@183 134 i != m_profiles.end(); ++i) {
Chris@183 135 totmap.insert(TimeRMap::value_type(i->second.second.second, i->first));
Chris@183 136 avgmap.insert(TimeRMap::value_type(i->second.second.second /
Chris@183 137 i->second.first, i->first));
Chris@183 138 ncallmap.insert(IntRMap::value_type(i->second.first, i->first));
Chris@183 139 }
Chris@183 140
Chris@183 141 for (WorstCallMap::const_iterator i = m_worstCalls.begin();
Chris@183 142 i != m_worstCalls.end(); ++i) {
Chris@183 143 worstmap.insert(TimeRMap::value_type(i->second.second,
Chris@183 144 i->first));
Chris@183 145 }
Chris@183 146
Chris@183 147
Chris@183 148 fprintf(stderr, "\nBy total:\n");
Chris@183 149 for (TimeRMap::const_iterator i = totmap.end(); i != totmap.begin(); ) {
Chris@183 150 --i;
Chris@183 151 fprintf(stderr, "%-40s %s ms\n", i->second,
Chris@183 152 (i->first * 1000).toString().c_str());
Chris@183 153 }
Chris@183 154
Chris@183 155 fprintf(stderr, "\nBy average:\n");
Chris@183 156 for (TimeRMap::const_iterator i = avgmap.end(); i != avgmap.begin(); ) {
Chris@183 157 --i;
Chris@183 158 fprintf(stderr, "%-40s %s ms\n", i->second,
Chris@183 159 (i->first * 1000).toString().c_str());
Chris@183 160 }
Chris@183 161
Chris@183 162 fprintf(stderr, "\nBy worst case:\n");
Chris@183 163 for (TimeRMap::const_iterator i = worstmap.end(); i != worstmap.begin(); ) {
Chris@183 164 --i;
Chris@183 165 fprintf(stderr, "%-40s %s ms\n", i->second,
Chris@408 166 (i->first * 1000).toString().c_str());
Chris@183 167 }
Chris@183 168
Chris@183 169 fprintf(stderr, "\nBy number of calls:\n");
Chris@183 170 for (IntRMap::const_iterator i = ncallmap.end(); i != ncallmap.begin(); ) {
Chris@183 171 --i;
Chris@183 172 fprintf(stderr, "%-40s %d\n", i->second, i->first);
Chris@183 173 }
Chris@183 174
Chris@0 175 #endif
Chris@0 176 }
Chris@0 177
Chris@183 178 #ifndef NO_TIMING
Chris@183 179
Chris@408 180 Profiler::Profiler(const char* c, bool showOnDestruct) :
Chris@408 181 m_c(c),
Chris@408 182 m_showOnDestruct(showOnDestruct),
Chris@408 183 m_ended(false)
Chris@0 184 {
Chris@0 185 m_startCPU = clock();
Chris@0 186
Chris@0 187 struct timeval tv;
Chris@0 188 (void)gettimeofday(&tv, 0);
Chris@26 189 m_startTime = RealTime::fromTimeval(tv);
Chris@0 190 }
Chris@0 191
Chris@0 192 void
Chris@183 193 Profiler::update() const
Chris@0 194 {
Chris@0 195 clock_t elapsedCPU = clock() - m_startCPU;
Chris@0 196
Chris@0 197 struct timeval tv;
Chris@0 198 (void)gettimeofday(&tv, 0);
Chris@26 199 RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime;
Chris@0 200
Chris@0 201 cerr << "Profiler : id = " << m_c
Chris@0 202 << " - elapsed so far = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC)
Chris@0 203 << "ms CPU, " << elapsedTime << " real" << endl;
Chris@0 204 }
Chris@0 205
Chris@0 206 Profiler::~Profiler()
Chris@0 207 {
Chris@408 208 if (!m_ended) end();
Chris@408 209 }
Chris@408 210
Chris@408 211 void
Chris@408 212 Profiler::end()
Chris@408 213 {
Chris@0 214 clock_t elapsedCPU = clock() - m_startCPU;
Chris@0 215
Chris@0 216 struct timeval tv;
Chris@0 217 (void)gettimeofday(&tv, 0);
Chris@26 218 RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime;
Chris@0 219
Chris@0 220 Profiles::getInstance()->accumulate(m_c, elapsedCPU, elapsedTime);
Chris@0 221
Chris@0 222 if (m_showOnDestruct)
Chris@0 223 cerr << "Profiler : id = " << m_c
Chris@0 224 << " - elapsed = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC)
Chris@0 225 << "ms CPU, " << elapsedTime << " real" << endl;
Chris@408 226
Chris@408 227 m_ended = true;
Chris@0 228 }
Chris@0 229
Chris@183 230 #endif
Chris@183 231