zypp/base/Measure.cc

   1 /*---------------------------------------------------------------------\
   2 |                          ____ _   __ __ ___                          |
   3 |                         |__  / \ / / . \ . \                         |
   4 |                           / / \ V /|  _/  _/                         |
   5 |                          / /__ | | | | | |                           |
   6 |                         /_____||_| |_| |_|                           |
   7 |                                                                      |
   8 \---------------------------------------------------------------------*/
   9 /** \file       zypp/base/Measure.cc
  10  *
  11 */
  12 extern "C"
  13 {
  14 #include <sys/times.h>
  15 #include <unistd.h>
  16 }
  17 #include <iostream>
  18
  19 #include "zypp/base/Logger.h"
  20 #include "zypp/base/Measure.h"
  21 #include "zypp/base/String.h"
  22
  23 using std::endl;
  24
  25 #undef ZYPP_BASE_LOGGER_LOGGROUP
  26 #define ZYPP_BASE_LOGGER_LOGGROUP "Measure"
  27
  28 ///////////////////////////////////////////////////////////////////
  29 namespace zypp
  30 { /////////////////////////////////////////////////////////////////
  31   ///////////////////////////////////////////////////////////////////
  32   namespace debug
  33   { /////////////////////////////////////////////////////////////////
  34
  35       /** Times measured by \ref Measure. */
  36       struct Tm
  37       {
  38         Tm()
  39         : _real( 0 )
  40         , _proc( tmsEmpty )
  41         {}
  42
  43         void get()
  44         {
  45           _real = ::time(NULL);
  46           ::times( &_proc );
  47         }
  48
  49         Tm operator-( const Tm & rhs ) const
  50         {
  51           Tm ret( *this );
  52           ret._real -= rhs._real;
  53           ret._proc.tms_utime -= rhs._proc.tms_utime;
  54           ret._proc.tms_stime -= rhs._proc.tms_stime;
  55           ret._proc.tms_cutime -= rhs._proc.tms_cutime;
  56           ret._proc.tms_cstime -= rhs._proc.tms_cstime;
  57           return ret;
  58         }
  59
  60         std::string asString() const
  61         {
  62           std::string ret( timeStr( _real ) );
  63           ret += " (u ";
  64           ret += timeStr( asSec( _proc.tms_utime ) );
  65           ret += " s ";
  66           ret += timeStr( asSec( _proc.tms_stime ) );
  67           ret += " c ";
  68           ret += timeStr( asSec( _proc.tms_cutime + _proc.tms_cstime ) );
  69           ret += ")";
  70           return ret;
  71         }
  72
  73         std::string stringIf( clock_t ticks_r, const std::string & tag_r ) const
  74         {
  75           std::string ret;
  76           if ( ticks_r )
  77             {
  78               ret += tag_r;
  79               ret += timeStr( asSec( ticks_r ) );
  80             }
  81           return ret;
  82         }
  83
  84         double asSec( clock_t ticks_r ) const
  85         { return double(ticks_r) / ticks; }
  86
  87         std::string timeStr( time_t sec_r ) const
  88         {
  89           time_t h = sec_r/3600;
  90           sec_r -= h*3600;
  91           time_t m = sec_r/60;
  92           sec_r -= m*60;
  93           if ( h )
  94             return str::form( "%lu:%02lu:%02lu", h, m, sec_r );
  95           if ( m )
  96             return str::form( "%lu:%02lu", m, sec_r );
  97           return str::form( "%lu", sec_r );
  98         }
  99
 100         std::string timeStr( double sec_r ) const
 101         {
 102           time_t h = time_t(sec_r)/3600;
 103           sec_r -= h*3600;
 104           time_t m = time_t(sec_r)/60;
 105           sec_r -= m*60;
 106           if ( h )
 107             return str::form( "%lu:%02lu:%05.2lf", h, m, sec_r );
 108           if ( m )
 109             return str::form( "%lu:%05.2lf", m, sec_r );
 110           return str::form( "%.2lf", sec_r );
 111         }
 112
 113         /** Systems ticks per second. */
 114         static const long ticks;
 115         /** Empty struct tms. */
 116         static const struct tms tmsEmpty;
 117         /** Real time via \c ::time. */
 118         time_t      _real;
 119         /** Process times via \c ::times. */
 120         struct tms  _proc;
 121       };
 122
 123       const struct tms Tm::tmsEmpty = { 0, 0, 0, 0 };
 124       const long Tm::ticks = sysconf(_SC_CLK_TCK);
 125
 126       /** \refers Tm Stream output. */
 127       std::ostream & operator<<( std::ostream & str, const Tm & obj )
 128       {
 129         return str << obj.asString();
 130       }
 131
 132
 133     ///////////////////////////////////////////////////////////////////
 134     //
 135     //  CLASS NAME : Measure::Impl
 136     //
 137     /** Measure implementation. */
 138     class Measure::Impl
 139     {
 140     public:
 141       Impl( const std::string & ident_r )
 142       : _ident  ( ident_r )
 143       , _level  ( _glevel )
 144       , _seq    ( 0 )
 145       {
 146         _glevel += "..";
 147         log() << _level << "START MEASURE(" << _ident << ")" << endl;
 148         _start.get();
 149       }
 150
 151       ~Impl()
 152       {
 153         _stop.get();
 154         ++_seq;
 155         std::ostream & str( log() << _level << "MEASURE(" << _ident << ") " );
 156         dumpMeasure( str );
 157         _glevel.erase( 0, 2 );
 158       }
 159
 160       void restart()
 161       {
 162         log() << _level << "RESTART MEASURE(" << _ident << ")" << endl;
 163         _start = _stop;
 164       }
 165
 166       void elapsed( const std::string & tag_r = std::string() ) const
 167       {
 168         _stop.get();
 169         ++_seq;
 170         std::ostream & str( log() << _level << "ELAPSED(" << _ident << ") " );
 171         dumpMeasure( str, tag_r );
 172         _elapsed = _stop;
 173       }
 174
 175     private:
 176       /** Return the log stream. */
 177       std::ostream & log() const
 178       { return INT; }
 179
 180       std::ostream & dumpMeasure( std::ostream & str_r, const std::string & tag_r = std::string() ) const
 181       {
 182         str_r << ( _stop - _start );
 183         if ( _seq > 1 ) // diff to previous _elapsed
 184           {
 185             str_r << " [" << ( _stop - _elapsed ) << "]";
 186           }
 187         if ( ! tag_r.empty() )
 188           str_r << " - " << tag_r;
 189         return str_r << endl;
 190       }
 191
 192     private:
 193       static std::string _glevel;
 194
 195       std::string       _ident;
 196       std::string       _level;
 197       Tm               _start;
 198       mutable unsigned _seq;
 199       mutable Tm       _elapsed;
 200       mutable Tm       _stop;
 201     };
 202
 203     std::string Measure::Impl::_glevel;
 204
 205     ///////////////////////////////////////////////////////////////////
 206
 207     ///////////////////////////////////////////////////////////////////
 208     //
 209     //  CLASS NAME : Measure
 210     //
 211     ///////////////////////////////////////////////////////////////////
 212
 213     Measure::Measure()
 214     {}
 215
 216     Measure::Measure( const std::string & ident_r )
 217     : _pimpl( new Impl( ident_r ) )
 218     {}
 219
 220     Measure::~Measure()
 221     {}
 222
 223     void Measure::start( const std::string & ident_r )
 224     { stop(); _pimpl.reset( new Impl( ident_r ) ); }
 225
 226     void Measure::restart()
 227     { _pimpl->restart(); }
 228
 229     void Measure::elapsed() const
 230     { if ( _pimpl ) _pimpl->elapsed(); }
 231     void Measure::elapsed( const std::string & tag_r ) const
 232     { if ( _pimpl ) _pimpl->elapsed( tag_r ); }
 233     void Measure::elapsed( long tag_r ) const
 234     { if ( _pimpl ) _pimpl->elapsed( asString( tag_r ) ); }
 235
 236     void Measure::stop()
 237     { _pimpl.reset(); }
 238
 239     /////////////////////////////////////////////////////////////////
 240   } // namespace debug
 241   ///////////////////////////////////////////////////////////////////
 242   /////////////////////////////////////////////////////////////////
 243 } // namespace zypp
 244 ///////////////////////////////////////////////////////////////////