perf.cpp

Go to the documentation of this file.
00001 /*
00002  * perf.cpp
00003  *
00004  * Copyright (C) 2006,2009  Thomas A. Vaughan
00005  * All rights reserved.
00006  *
00007  *
00008  * Redistribution and use in source and binary forms, with or without
00009  * modification, are permitted provided that the following conditions are met:
00010  *     * Redistributions of source code must retain the above copyright
00011  *       notice, this list of conditions and the following disclaimer.
00012  *     * Redistributions in binary form must reproduce the above copyright
00013  *       notice, this list of conditions and the following disclaimer in the
00014  *       documentation and/or other materials provided with the distribution.
00015  *     * Neither the name of the <organization> nor the
00016  *       names of its contributors may be used to endorse or promote products
00017  *       derived from this software without specific prior written permission.
00018  *
00019  * THIS SOFTWARE IS PROVIDED BY THOMAS A. VAUGHAN ''AS IS'' AND ANY
00020  * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
00021  * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
00022  * DISCLAIMED. IN NO EVENT SHALL THOMAS A. VAUGHAN BE LIABLE FOR ANY
00023  * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
00024  * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
00025  * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
00026  * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
00027  * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
00028  * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
00029  *
00030  *
00031  * Implementation of the timing library.  See perf.h
00032  */
00033 
00034 // includes --------------------------------------------------------------------
00035 #include "perf.h"               // always include our own header first
00036 
00037 #include <iostream>
00038 
00039 #include <sys/time.h>
00040 
00041 #include "threadsafe/threadsafe_map.h"
00042 
00043 
00044 namespace perf {
00045 
00046 
00047 struct timer_rec_t {
00048         // constructor, manipulator
00049         timer_rec_t(void) throw() {
00050                         calls = 0;
00051                         total.clear();
00052                 }
00053 
00054         void update(IN const time_t& delta) throw() {
00055                         mlock m(mutex);
00056 
00057                         calls++;
00058                         total.increment(delta);
00059                 }
00060 
00061         // data fields
00062         smart_mutex     mutex;
00063         long            calls;          // number of calls
00064         time_t          total;          // total time
00065 };
00066 
00067 typedef threadsafe_map<std::string, timer_rec_t *> map_timer_t;
00068 
00069 typedef std::multimap<double, std::string> map_time_name_t;
00070 
00071 
00072 static bool s_timersEnabled                     = true;
00073 
00074 static map_timer_t s_timers;            // master list of timers
00075 
00076 
00077 ////////////////////////////////////////////////////////////////////////////////
00078 //
00079 //      static helper methods
00080 //
00081 ////////////////////////////////////////////////////////////////////////////////
00082 
00083 static void *
00084 initializeTimer
00085 (
00086 IN const char * name
00087 )
00088 {
00089         ASSERT(name, "null");
00090 
00091         timer_rec_t * tr = NULL;
00092         if (s_timers.lookup(name, tr)) {
00093                 ASSERT(tr, "null timer record in map?");
00094                 return tr;
00095         }
00096 
00097         // need to create new entry
00098         tr = new timer_rec_t;
00099         ASSERT(tr, "out of memory");
00100 
00101         // create
00102         s_timers.insert(name, tr);
00103         return tr;
00104 }
00105 
00106 
00107 
00108 static void
00109 updateTimer
00110 (
00111 IN void * context,
00112 IN const time_t& delta
00113 )
00114 throw()
00115 {
00116         ASSERT(context, "null");
00117 
00118         timer_rec_t * tr = (timer_rec_t *) context;
00119 
00120         // increment count of calls, and accumulate the total time
00121         tr->update(delta);
00122 }
00123 
00124 
00125 
00126 ////////////////////////////////////////////////////////////////////////////////
00127 //
00128 //      perf::Timer implementation
00129 //
00130 ////////////////////////////////////////////////////////////////////////////////
00131 
00132 Timer::Timer
00133 (
00134 IN const char * name
00135 )
00136 {
00137         ASSERT(name, "null timer name?");
00138 
00139         if (!s_timersEnabled) {
00140                 m_context = 0;
00141                 return;
00142         }
00143 
00144         // create an empty record for this timer, so destructor doesn't have
00145         // to do any allocations etc.
00146         m_start_time = getNow();
00147         m_context = initializeTimer(name);
00148 }
00149 
00150 
00151 
00152 Timer::~Timer(void)
00153 {
00154         if (!m_context)
00155                 return;
00156 
00157         time_t delta = getNow();
00158         delta.decrement(m_start_time);
00159 
00160         updateTimer(m_context, delta);
00161 }
00162 
00163 
00164 
00165 ////////////////////////////////////////////////////////////////////////////////
00166 //
00167 //      DebugTimer
00168 //
00169 ////////////////////////////////////////////////////////////////////////////////
00170 
00171 DebugTimer::DebugTimer(IN const char * msg)
00172 {
00173         m_start_time = getNow();
00174         m_msg = msg;
00175 }
00176 
00177 
00178 DebugTimer::~DebugTimer(void) throw()
00179 {
00180         time_t now = getNow();
00181         now.decrement(m_start_time);
00182 
00183         long seconds = (long) now.getSeconds();
00184         long hours = seconds / 3600;
00185         long minutes = (seconds % 3600) / 60;
00186         DPRINTF("%s: %ld hours %ld minutes %ld seconds",
00187             m_msg.c_str(), hours, minutes, seconds % 60);
00188 }
00189 
00190 
00191 
00192 ////////////////////////////////////////////////////////////////////////////////
00193 //
00194 //      public API
00195 //
00196 ////////////////////////////////////////////////////////////////////////////////
00197 
00198 time_t
00199 getNow
00200 (
00201 void
00202 )
00203 throw()
00204 {
00205         /* 
00206         Bummer: clock_gettime() is not supported by 2.4* kernels
00207         struct timespec ts;
00208         ASSERT(!clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts),
00209             "Failed clock_gettime() call?");
00210         t.set(ts.tv_sec, (ts.tv_nsec + 500) / 1000);
00211          */
00212 
00213 /*
00214         this uses wall time--blah
00215         HOWEVER it is the only timer that doesn't have rollover problems
00216  */
00217         time_t t;
00218         struct timeval tv;
00219         ASSERT(!gettimeofday(&tv, NULL), "Failed calling gettimeofday()");
00220         t.set(tv.tv_sec, tv.tv_usec);
00221         return t;
00222 /*
00223         // Better: use process clock.  Rolls over every 72 minutes though!
00224         dword_t c = clock();
00225         // ASSERT(-1 != c, "clock() not supported?");
00226         dword_t dwSec = c / CLOCKS_PER_SEC;
00227         long seconds = (long) dwSec;
00228         if (seconds < 0) {
00229                 DPRINTF("Seconds < 0??? seconds = %ld", seconds);
00230                 seconds = 0;
00231         }
00232         long useconds = c % CLOCKS_PER_SEC;
00233         if (useconds < 0) {
00234                 DPRINTF("useconds < 0??? useconds = %ld", useconds);
00235                 useconds = 0;
00236         }
00237         t.set(seconds, useconds);
00238 */
00239 }
00240 
00241 
00242 
00243 void
00244 enableTimers
00245 (
00246 IN bool enable
00247 )
00248 throw()
00249 {
00250         s_timersEnabled = enable;
00251 
00252         if (enable) {
00253                 DPRINTF("Timers enabled");
00254         } else {
00255                 DPRINTF("Timers disabled");
00256         }
00257 }
00258 
00259 
00260 
00261 void
00262 getTimingSummary
00263 (
00264 OUT std::string& out
00265 )
00266 {
00267         out = "";
00268 
00269         char buffer[1024];
00270 
00271         // sort in order of time
00272         map_time_name_t map;
00273         map_timer_t::iterator_t M;
00274         s_timers.getIterator(M);
00275         std::string name;
00276         timer_rec_t * tr = NULL;
00277         while (s_timers.getNextElement(M, name, tr)) {
00278                 ASSERT(tr, "null timer record in timer map?");
00279                 map.insert(map_time_name_t::value_type(tr->total.getSeconds(), name));
00280         }
00281 
00282         // now walk in reverse order (from largest to smallest)
00283         for (map_time_name_t::reverse_iterator i = map.rbegin();
00284              i != map.rend(); ++i) {
00285 
00286                 const std::string& name = i->second;
00287                 timer_rec_t * tr;
00288                 ASSERT(s_timers.lookup(name, tr) && tr,
00289                     "Missing or invalid record for '%s'", name.c_str());
00290 
00291                 out += "  ";
00292 
00293                 sprintf(buffer, "%40s", name.c_str());
00294                 out += buffer;
00295                 out += ": ";
00296 
00297                 double s = tr->total.getSeconds();      // seconds total
00298                 double mpc = 1000.0 * s / tr->calls;    // milliseconds per call
00299 
00300                 int min = 0;            // minutes
00301                 if (s > 90.0) {
00302                         min = int(s / 60.0);
00303                         s = s - (60.0 * min);
00304                 }
00305 
00306                 if (min > 0) {
00307                         sprintf(buffer,
00308                            "%7ld calls, %2d minutes %4.1lf seconds total",
00309                             tr->calls, min, s);
00310                 } else {
00311                         sprintf(buffer,
00312                             "%7ld calls, %5.2lf seconds total", tr->calls, s);
00313                 }
00314                 out += buffer;
00315 
00316                 if (mpc < 1000.0) {
00317                         sprintf(buffer, " (%6.2lf ms per call)", mpc);
00318                         out += buffer;
00319                 }
00320 
00321                 out += "\n";
00322         }
00323 }
00324 
00325 
00326 
00327 void
00328 dumpTimingSummary
00329 (
00330 IO std::ostream& stream
00331 )
00332 {
00333         ASSERT(stream.good(), "bad?");
00334 
00335         std::string summary;
00336         getTimingSummary(summary);
00337         stream << "Timing Summary:\n";
00338         stream << summary;
00339         stream << "\n";
00340 }
00341 
00342 
00343 
00344 };      // perf namespace
00345