perf.cpp

Go to the documentation of this file.

/*
 * perf.cpp
 *
 * Copyright (C) 2006,2009,2010  Thomas A. Vaughan
 * All rights reserved.
 *
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions are met:
 *     * Redistributions of source code must retain the above copyright
 *       notice, this list of conditions and the following disclaimer.
 *     * Redistributions in binary form must reproduce the above copyright
 *       notice, this list of conditions and the following disclaimer in the
 *       documentation and/or other materials provided with the distribution.
 *     * Neither the name of the <organization> nor the
 *       names of its contributors may be used to endorse or promote products
 *       derived from this software without specific prior written permission.
 *
 * THIS SOFTWARE IS PROVIDED BY THOMAS A. VAUGHAN ''AS IS'' AND ANY
 * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
 * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
 * DISCLAIMED. IN NO EVENT SHALL THOMAS A. VAUGHAN BE LIABLE FOR ANY
 * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
 * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
 * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
 * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 *
 *
 * Implementation of the timing library.  See perf.h
 */

// includes --------------------------------------------------------------------
#include "perf.h"               // always include our own header first

#include <iostream>

#ifdef WIN32
#include <winsock2.h>
#include <time.h>
#else   // WIN32
#include <sys/time.h>
#endif  // WIN32

#include "threadsafe/threadsafe_map.h"


#ifdef WIN32

#if defined(_MSC_VER) || defined(_MSC_EXTENSIONS)
  #define DELTA_EPOCH_IN_MICROSECS  11644473600000000Ui64
#else
  #define DELTA_EPOCH_IN_MICROSECS  11644473600000000ULL
#endif
  
// Definition of a gettimeofday function
// from  http://www.suacommunity.com/dictionary/gettimeofday-entry.php
int
gettimeofday
(
struct timeval *tv,
struct timezone *tz
)
{
  ASSERT(tv, "null");
  ASSERT(!tz, "do not support timezone");

//  DPRINTF("gettimeofday()");

// Define a structure to receive the current Windows filetime
  FILETIME ft;
 
// Initialize the present time to 0 and the timezone to UTC
  unsigned __int64 tmpres = 0;
 
    GetSystemTimeAsFileTime(&ft);
 
// The GetSystemTimeAsFileTime returns the number of 100 nanosecond 
// intervals since Jan 1, 1601 in a structure. Copy the high bits to 
// the 64 bit tmpres, shift it left by 32 then or in the low 32 bits.
    tmpres |= ft.dwHighDateTime;
    tmpres <<= 32;
    tmpres |= ft.dwLowDateTime;
 
// Convert to microseconds by dividing by 10
    tmpres /= 10;
 
// The Unix epoch starts on Jan 1 1970.  Need to subtract the difference 
// in seconds from Jan 1 1601.
    tmpres -= DELTA_EPOCH_IN_MICROSECS;
 
// Finally change microseconds to seconds and place in the seconds value. 
// The modulus picks up the microseconds.
    tv->tv_sec = (long)(tmpres / 1000000UL);
    tv->tv_usec = (long)(tmpres % 1000000UL);
  
  //  DPRINTF("tv_sec = %d", tv->tv_sec);

  return 0;
}

#endif // WIN32



namespace perf {


struct timer_rec_t {
        // constructor, manipulator
        timer_rec_t(void) throw() {
                        calls = 0;
                        total.clear();
                }

        void update(IN const time_t& delta) throw() {
                        mlock m(mutex);

                        calls++;
                        total.increment(delta);
                }

        // data fields
        smart_mutex     mutex;
        long            calls;          // number of calls
        time_t          total;          // total time
};

typedef threadsafe_map<std::string, timer_rec_t *> map_timer_t;

typedef std::multimap<double, std::string> map_time_name_t;


static bool s_timersEnabled                     = true;

static map_timer_t s_timers;            // master list of timers


////////////////////////////////////////////////////////////////////////////////
//
//      static helper methods
//
////////////////////////////////////////////////////////////////////////////////

static void *
initializeTimer
(
IN const char * name
)
{
        ASSERT(name, "null");

        timer_rec_t * tr = NULL;
        if (s_timers.lookup(name, tr)) {
                ASSERT(tr, "null timer record in map?");
                return tr;
        }

        // need to create new entry
        tr = new timer_rec_t;
        ASSERT(tr, "out of memory");

        // create
        s_timers.insert(name, tr);
        return tr;
}



static void
updateTimer
(
IN void * context,
IN const time_t& delta
)
throw()
{
        ASSERT(context, "null");

        timer_rec_t * tr = (timer_rec_t *) context;

        // increment count of calls, and accumulate the total time
        tr->update(delta);
}



////////////////////////////////////////////////////////////////////////////////
//
//      perf::Timer implementation
//
////////////////////////////////////////////////////////////////////////////////

Timer::Timer
(
IN const char * name
)
{
        ASSERT(name, "null timer name?");

        if (!s_timersEnabled) {
                m_context = 0;
                return;
        }

        // create an empty record for this timer, so destructor doesn't have
        // to do any allocations etc.
        m_start_time = getNow();
        m_context = initializeTimer(name);
}



Timer::~Timer(void)
{
        if (!m_context)
                return;

        time_t delta = getNow();
        delta.decrement(m_start_time);

        updateTimer(m_context, delta);
}



////////////////////////////////////////////////////////////////////////////////
//
//      DebugTimer
//
////////////////////////////////////////////////////////////////////////////////

DebugTimer::DebugTimer(IN const char * msg)
{
        m_start_time = getNow();
        m_msg = msg;
}


DebugTimer::~DebugTimer(void) throw()
{
        time_t now = getNow();
        now.decrement(m_start_time);

        long seconds = (long) now.getSeconds();
        long hours = seconds / 3600;
        long minutes = (seconds % 3600) / 60;
        DPRINTF("%s: %ld hours %ld minutes %ld seconds",
            m_msg.c_str(), hours, minutes, seconds % 60);
}



////////////////////////////////////////////////////////////////////////////////
//
//      public API
//
////////////////////////////////////////////////////////////////////////////////

time_t
getNow
(
void
)
throw()
{
        /* 
        Bummer: clock_gettime() is not supported by 2.4* kernels
        struct timespec ts;
        ASSERT(!clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts),
            "Failed clock_gettime() call?");
        t.set(ts.tv_sec, (ts.tv_nsec + 500) / 1000);
         */

/*
        this uses wall time--blah
        HOWEVER it is the only timer that doesn't have rollover problems
 */
        time_t t;
        struct timeval tv;
        ASSERT(!gettimeofday(&tv, NULL), "Failed calling gettimeofday()");
        t.set(tv.tv_sec, tv.tv_usec);
        return t;
/*
        // Better: use process clock.  Rolls over every 72 minutes though!
        dword_t c = clock();
        // ASSERT(-1 != c, "clock() not supported?");
        dword_t dwSec = c / CLOCKS_PER_SEC;
        long seconds = (long) dwSec;
        if (seconds < 0) {
                DPRINTF("Seconds < 0??? seconds = %ld", seconds);
                seconds = 0;
        }
        long useconds = c % CLOCKS_PER_SEC;
        if (useconds < 0) {
                DPRINTF("useconds < 0??? useconds = %ld", useconds);
                useconds = 0;
        }
        t.set(seconds, useconds);
*/
}



void
enableTimers
(
IN bool enable
)
throw()
{
        s_timersEnabled = enable;

        if (enable) {
                DPRINTF("Timers enabled");
        } else {
                DPRINTF("Timers disabled");
        }
}



void
getTimingSummary
(
OUT std::string& out
)
{
        out = "";

        char buffer[1024];

        // sort in order of time
        map_time_name_t map;
        map_timer_t::iterator_t M;
        s_timers.getIterator(M);
        std::string name;
        timer_rec_t * tr = NULL;
        while (s_timers.getNextElement(M, name, tr)) {
                ASSERT(tr, "null timer record in timer map?");
                map.insert(map_time_name_t::value_type(tr->total.getSeconds(), name));
        }

        // now walk in reverse order (from largest to smallest)
        for (map_time_name_t::reverse_iterator i = map.rbegin();
             i != map.rend(); ++i) {

                const std::string& name = i->second;
                timer_rec_t * tr;
                ASSERT(s_timers.lookup(name, tr) && tr,
                    "Missing or invalid record for '%s'", name.c_str());

                out += "  ";

                sprintf(buffer, "%31s", name.c_str());
                out += buffer;
                out += ": ";

                double s = tr->total.getSeconds();      // seconds total
                double mpc = 1000.0 * s / tr->calls;    // milliseconds per call

                int min = 0;            // minutes
                if (s > 90.0) {
                        min = int(s / 60.0);
                        s = s - (60.0 * min);
                }

                if (min > 0) {
                        sprintf(buffer,
                            "%7ld calls, %2d minutes %4.1lf seconds",
                            tr->calls, min, s);
                } else {
                        sprintf(buffer,
                            "%7ld calls, %5.2lf seconds", tr->calls, s);
                }
                out += buffer;

                if (mpc < 1000.0) {
                        sprintf(buffer, ": %6.2lf ms/call", mpc);
                        out += buffer;
                }

                out += "\n";
        }
}



void
dumpTimingSummary
(
IO std::ostream& stream
)
{
        ASSERT(stream.good(), "bad?");

        std::string summary;
        getTimingSummary(summary);
        stream << "Timing Summary:\n";
        stream << summary;
        stream << "\n";
}



};      // perf namespace