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, std::ostream * log_r = nullptr )
 142       : _ident  ( ident_r )
 143       , _level  ( _glevel )
 144       , _seq    ( 0 )
 145       , _log    ( log_r )
 146       {
 147         _glevel += "..";
 148         log() << _level << "START MEASURE(" << _ident << ")" << endl;
 149         _start.get();
 150       }
 151
 152       ~Impl()
 153       {
 154         _stop.get();
 155         ++_seq;
 156         std::ostream & str( log() << _level << "MEASURE(" << _ident << ") " );
 157         dumpMeasure( str );
 158         _glevel.erase( 0, 2 );
 159       }
 160
 161       void restart()
 162       {
 163         log() << _level << "RESTART MEASURE(" << _ident << ")" << endl;
 164         _start = _stop;
 165       }
 166
 167       void elapsed( const std::string & tag_r = std::string() ) const
 168       {
 169         _stop.get();
 170         ++_seq;
 171         std::ostream & str( log() << _level << "ELAPSED(" << _ident << ") " );
 172         dumpMeasure( str, tag_r );
 173         _elapsed = _stop;
 174       }
 175
 176       /** Return the log stream. */
 177       std::ostream & log() const
 178       { return _log ? *_log : INT; }
 179       std::ostream * logp() const
 180       { return _log; }
 181
 182     private:
 183       std::ostream & dumpMeasure( std::ostream & str_r, const std::string & tag_r = std::string() ) const
 184       {
 185         str_r << ( _stop - _start );
 186         if ( _seq > 1 ) // diff to previous _elapsed
 187           {
 188             str_r << " [" << ( _stop - _elapsed ) << "]";
 189           }
 190         if ( ! tag_r.empty() )
 191           str_r << " - " << tag_r;
 192         return str_r << endl;
 193       }
 194
 195     private:
 196       static std::string _glevel;
 197
 198       std::string       _ident;
 199       std::string       _level;
 200       Tm               _start;
 201       mutable unsigned _seq;
 202       mutable Tm       _elapsed;
 203       mutable Tm       _stop;
 204
 205       std::ostream *   _log = nullptr;
 206     };
 207
 208     std::string Measure::Impl::_glevel;
 209
 210     ///////////////////////////////////////////////////////////////////
 211
 212     ///////////////////////////////////////////////////////////////////
 213     //
 214     //  CLASS NAME : Measure
 215     //
 216     ///////////////////////////////////////////////////////////////////
 217
 218     Measure::Measure()
 219     {}
 220
 221     Measure::Measure( const std::string & ident_r )
 222     : _pimpl( new Impl( ident_r ) )
 223     {}
 224
 225     Measure::Measure( const std::string & ident_r, std::ostream & out_r )
 226     : _pimpl( new Impl( ident_r, &out_r ) )
 227     {}
 228
 229     Measure::~Measure()
 230     {}
 231
 232     void Measure::start( const std::string & ident_r )
 233     { stop(); _pimpl.reset( _pimpl ? new Impl( ident_r, _pimpl->logp() ) : new Impl( ident_r ) ); }
 234
 235     void Measure::restart()
 236     { _pimpl->restart(); }
 237
 238     void Measure::elapsed() const
 239     { if ( _pimpl ) _pimpl->elapsed(); }
 240     void Measure::elapsed( const std::string & tag_r ) const
 241     { if ( _pimpl ) _pimpl->elapsed( tag_r ); }
 242     void Measure::elapsed( long tag_r ) const
 243     { if ( _pimpl ) _pimpl->elapsed( asString( tag_r ) ); }
 244
 245     void Measure::stop()
 246     { _pimpl.reset(); }
 247
 248     /////////////////////////////////////////////////////////////////
 249   } // namespace debug
 250   ///////////////////////////////////////////////////////////////////
 251   /////////////////////////////////////////////////////////////////
 252 } // namespace zypp
 253 ///////////////////////////////////////////////////////////////////