svcore  1.9
Profiler.cpp
Go to the documentation of this file.
00001 /* -*- c-basic-offset: 4 indent-tabs-mode: nil -*-  vi:set ts=8 sts=4 sw=4: */
00002 
00003 /*
00004     Sonic Visualiser
00005     An audio file viewer and annotation editor.
00006     Centre for Digital Music, Queen Mary, University of London.
00007     
00008     This program is free software; you can redistribute it and/or
00009     modify it under the terms of the GNU General Public License as
00010     published by the Free Software Foundation; either version 2 of the
00011     License, or (at your option) any later version.  See the file
00012     COPYING included with this distribution for more information.
00013 */
00014 
00015 /*
00016    This is a modified version of a source file from the 
00017    Rosegarden MIDI and audio sequencer and notation editor.
00018    This file copyright 2000-2006 Chris Cannam, Guillaume Laurent,
00019    and QMUL.
00020 */
00021 
00022 #include <iostream>
00023 #include "Profiler.h"
00024 
00025 #include <cstdio>
00026 
00027 #include <vector>
00028 #include <algorithm>
00029 #include <set>
00030 #include <map>
00031 
00032 Profiles* Profiles::m_instance = 0;
00033 
00034 Profiles* Profiles::getInstance()
00035 {
00036     if (!m_instance) m_instance = new Profiles();
00037     
00038     return m_instance;
00039 }
00040 
00041 Profiles::Profiles()
00042 {
00043 }
00044 
00045 Profiles::~Profiles()
00046 {
00047     dump();
00048 }
00049 
00050 void Profiles::accumulate(
00051 #ifndef NO_TIMING
00052     const char* id, clock_t time, RealTime rt
00053 #else
00054     const char*, clock_t, RealTime
00055 #endif
00056 )
00057 {
00058 #ifndef NO_TIMING    
00059     ProfilePair &pair(m_profiles[id]);
00060     ++pair.first;
00061     pair.second.first += time;
00062     pair.second.second = pair.second.second + rt;
00063 
00064     TimePair &lastPair(m_lastCalls[id]);
00065     lastPair.first = time;
00066     lastPair.second = rt;
00067 
00068     TimePair &worstPair(m_worstCalls[id]);
00069     if (time > worstPair.first) {
00070         worstPair.first = time;
00071     }
00072     if (rt > worstPair.second) {
00073         worstPair.second = rt;
00074     }
00075 #endif
00076 }
00077 
00078 void Profiles::dump() const
00079 {
00080 #ifndef NO_TIMING
00081 
00082     fprintf(stderr, "Profiling points:\n");
00083 
00084     fprintf(stderr, "\nBy name:\n");
00085 
00086     typedef std::set<const char *, std::less<std::string> > StringSet;
00087 
00088     StringSet profileNames;
00089     for (ProfileMap::const_iterator i = m_profiles.begin();
00090          i != m_profiles.end(); ++i) {
00091         profileNames.insert(i->first);
00092     }
00093 
00094     for (StringSet::const_iterator i = profileNames.begin();
00095          i != profileNames.end(); ++i) {
00096 
00097         ProfileMap::const_iterator j = m_profiles.find(*i);
00098 
00099         if (j == m_profiles.end()) continue;
00100 
00101         const ProfilePair &pp(j->second);
00102 
00103         fprintf(stderr, "%s(%d):\n", *i, pp.first);
00104 
00105         fprintf(stderr, "\tCPU:  \t%.9g ms/call \t[%d ms total]\n",
00106                 (((double)pp.second.first * 1000.0 /
00107                   (double)pp.first) / CLOCKS_PER_SEC),
00108                 int((pp.second.first * 1000.0) / CLOCKS_PER_SEC));
00109 
00110         fprintf(stderr, "\tReal: \t%s ms      \t[%s ms total]\n",
00111                 ((pp.second.second / pp.first) * 1000).toString().c_str(),
00112                 (pp.second.second * 1000).toString().c_str());
00113 
00114         WorstCallMap::const_iterator k = m_worstCalls.find(*i);
00115         if (k == m_worstCalls.end()) continue;
00116         
00117         const TimePair &wc(k->second);
00118 
00119         fprintf(stderr, "\tWorst:\t%s ms/call \t[%d ms CPU]\n",
00120                 (wc.second * 1000).toString().c_str(),
00121                 int((wc.first * 1000.0) / CLOCKS_PER_SEC));
00122     }
00123 
00124     typedef std::multimap<RealTime, const char *> TimeRMap;
00125     typedef std::multimap<int, const char *> IntRMap;
00126     
00127     TimeRMap totmap, avgmap, worstmap;
00128     IntRMap ncallmap;
00129 
00130     for (ProfileMap::const_iterator i = m_profiles.begin();
00131          i != m_profiles.end(); ++i) {
00132         totmap.insert(TimeRMap::value_type(i->second.second.second, i->first));
00133         avgmap.insert(TimeRMap::value_type(i->second.second.second /
00134                                            i->second.first, i->first));
00135         ncallmap.insert(IntRMap::value_type(i->second.first, i->first));
00136     }
00137 
00138     for (WorstCallMap::const_iterator i = m_worstCalls.begin();
00139          i != m_worstCalls.end(); ++i) {
00140         worstmap.insert(TimeRMap::value_type(i->second.second,
00141                                              i->first));
00142     }
00143 
00144 
00145     fprintf(stderr, "\nBy total:\n");
00146     for (TimeRMap::const_iterator i = totmap.end(); i != totmap.begin(); ) {
00147         --i;
00148         fprintf(stderr, "%-40s  %s ms\n", i->second,
00149                 (i->first * 1000).toString().c_str());
00150     }
00151 
00152     fprintf(stderr, "\nBy average:\n");
00153     for (TimeRMap::const_iterator i = avgmap.end(); i != avgmap.begin(); ) {
00154         --i;
00155         fprintf(stderr, "%-40s  %s ms\n", i->second,
00156                 (i->first * 1000).toString().c_str());
00157     }
00158 
00159     fprintf(stderr, "\nBy worst case:\n");
00160     for (TimeRMap::const_iterator i = worstmap.end(); i != worstmap.begin(); ) {
00161         --i;
00162         fprintf(stderr, "%-40s  %s ms\n", i->second,
00163                 (i->first * 1000).toString().c_str());
00164     }
00165 
00166     fprintf(stderr, "\nBy number of calls:\n");
00167     for (IntRMap::const_iterator i = ncallmap.end(); i != ncallmap.begin(); ) {
00168         --i;
00169         fprintf(stderr, "%-40s  %d\n", i->second, i->first);
00170     }
00171 
00172 #endif
00173 }
00174 
00175 #ifndef NO_TIMING    
00176 
00177 Profiler::Profiler(const char* c, bool showOnDestruct) :
00178     m_c(c),
00179     m_showOnDestruct(showOnDestruct),
00180     m_ended(false)
00181 {
00182     m_startCPU = clock();
00183 
00184     struct timeval tv;
00185     (void)gettimeofday(&tv, 0);
00186     m_startTime = RealTime::fromTimeval(tv);
00187 }
00188 
00189 void
00190 Profiler::update() const
00191 {
00192     clock_t elapsedCPU = clock() - m_startCPU;
00193 
00194     struct timeval tv;
00195     (void)gettimeofday(&tv, 0);
00196     RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime;
00197 
00198     cerr << "Profiler : id = " << m_c
00199          << " - elapsed so far = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC)
00200          << "ms CPU, " << elapsedTime << " real" << endl;
00201 }    
00202 
00203 Profiler::~Profiler()
00204 {
00205     if (!m_ended) end();
00206 }
00207 
00208 void
00209 Profiler::end()
00210 {
00211     clock_t elapsedCPU = clock() - m_startCPU;
00212 
00213     struct timeval tv;
00214     (void)gettimeofday(&tv, 0);
00215     RealTime elapsedTime = RealTime::fromTimeval(tv) - m_startTime;
00216 
00217     Profiles::getInstance()->accumulate(m_c, elapsedCPU, elapsedTime);
00218 
00219     if (m_showOnDestruct)
00220         cerr << "Profiler : id = " << m_c
00221              << " - elapsed = " << ((elapsedCPU * 1000) / CLOCKS_PER_SEC)
00222              << "ms CPU, " << elapsedTime << " real" << endl;
00223 
00224     m_ended = true;
00225 }
00226  
00227 #endif
00228