← Back to branch summary

~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring

« back to all changes in this revision

Viewing changes to drizzled/time_profile.h

  • Committer: Prafulla Tekawade
  • Date: 2010-08-17 14:58:30 UTC
  • Revision ID: prafulla_t@users.sourceforge.net-20100817145830-kr6gvo59y65ljd9a
Adding some more integration of timer classes with drizzled
mainline code.
Rtdtc based timer implementation is disabled by default.
because it does not give reliable timing information on certain
machine (maybe due to multi-core architecture?)

Show diffs side-by-side

added added

removed removed

Lines of Context:
drizzled/time_profile.h
19
19
#include <stdint.h>
20
20
#include <math.h>
21
21
#include <stdio.h>
22
 
#include <string.h>
23
22
#include <cassert>
24
23
#include <map>
25
24
#include <stack>
26
25
#include <sstream>
27
26
#include <iostream>
28
 
#include "debug.h"
29
27
#include <drizzled/session.h>
30
28
 
31
29
#define ONE_BILLION  1000000000ULL
32
30
#define ONE_MILLION  1000000
33
31
#define ONE_THOUSAND 1000
34
32
 
 
33
 
 
34
#if 0
 
35
#define ENABLE_RTDC_BASED_TIMER
 
36
#endif
 
37
 
 
38
 
 
39
//Set this to 1, if you want to profile the code.
 
40
#if 0
 
41
#define TIME_PROFILE_ON 1
 
42
#endif
 
43
 
 
44
#define _CONCAT(a,b) a ## b
 
45
#define CONCAT(a,b) _CONCAT(a, b)
 
46
 
35
47
namespace drizzled  {
36
48
namespace timer  {
37
49
 
56
68
inline const char* getTimePrecToStr(int ePrecRange);
57
69
 
58
70
 
 
71
enum {
 
72
  eRtdcImpl = 0,
 
73
  eClockTimeImpl,
 
74
  eGetToDImpl
 
75
};
 
76
 
 
77
enum {
 
78
  eSecPrec = 0,
 
79
  eMilliSecPrec,
 
80
  eMicroSecPrec,
 
81
  eNanoSecPrec
 
82
};
 
83
 
 
84
#ifdef TIME_PROFILE_ON
 
85
 
 
86
#define BLOCK_NANO_SEC_TIMER(sBlockName) drizzled::timer::FastTimerNanoSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
 
87
#define BLOCK_MICRO_SEC_TIMER(sBlockName) drizzled::timer::FastTimerMicroSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
 
88
#define BLOCK_MILLI_SEC_TIMER(sBlockName) drizzled::timer::FastTimerMilliSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
 
89
#define BLOCK_SEC_TIMER(sBlockName) drizzled::timer::FastTimerSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
 
90
 
 
91
#define START_PROFILING_PHASE(name, scale)                              \
 
92
  drizzled::timer::th_pushProfilePhase(name, scale);                    \
 
93
  drizzled::timer::AutoProfPhase autoPhase;
 
94
  
 
95
 
 
96
#define GET_ALL_PROFILING_RESULT(outputStream) drizzled::timer::thp().printAllOpTime(outputStream);
 
97
 
 
98
#else
 
99
 
 
100
#define START_PROFILING_PHASE(name, scale) 
 
101
#define END_PROFILING_AND_COLLECT_RESULT(outputStream)
 
102
#define BLOCK_NANO_SEC_TIMER(sBlockName)
 
103
#define BLOCK_MICRO_SEC_TIMER(sBlockName)
 
104
#define BLOCK_MILLI_SEC_TIMER(sBlockName)
 
105
#define BLOCK_SEC_TIMER(sBlockName) 
 
106
#define GET_ALL_PROFILING_RESULT(outputStream)
 
107
 
 
108
 
 
109
#endif
 
110
  
 
111
 
59
112
class TimeProfile {
60
113
private:
61
114
  typedef std::pair<uint64_t, uint64_t> AccOccTimePair;
62
115
  typedef std::map<std::string, AccOccTimePair> OpTimeMap;
63
 
 
64
116
public:
65
117
 
66
118
  TimeProfile():m_sProfName("{NoProfileName}"),
88
140
    oss << "{" << std::endl;
89
141
    while( itr != opTimeMap.end() )  {
90
142
      oss << itr->first;
91
 
      oss << ", acc= " << itr->second.first << " m_sScale";
 
143
      oss << ", acc= " << itr->second.first << " " <<  m_sScale;
92
144
      oss << ", occ=" << itr->second.second << std::endl;
93
145
      itr++;
94
146
    }
105
157
class ThreadProfile {
106
158
public:
107
159
 
108
 
  ThreadProfile() { }
 
160
  ThreadProfile():timeProfileStack(),
 
161
                  profileData() { }
109
162
  ~ThreadProfile() { }
110
163
  
111
164
  TimeProfile* cur() {
122
175
      return;
123
176
    timeProfileStack.pop();
124
177
  }
 
178
  
 
179
  void printAllOpTime(std::ostream& oss) {
 
180
    while( !timeProfileStack.empty() ) {
 
181
      timeProfileStack.top().printOpTime(oss);
 
182
      oss << std::endl;
 
183
      timeProfileStack.pop();
 
184
    }
 
185
    std::vector<std::string>::const_iterator it = profileData.begin();
 
186
    while(it != profileData.end()) {
 
187
      oss << *it;
 
188
      oss << std::endl;
 
189
      it++;
 
190
    }
 
191
    profileData.clear();
 
192
  }
 
193
 
 
194
  void saveProfileData(const char* pData) {
 
195
    std::string sStr(pData);
 
196
    if( sStr.length() )
 
197
      profileData.push_back(sStr);
 
198
  }
125
199
private:
126
 
  TimeProfile timeProfile;
127
200
  std::stack<TimeProfile> timeProfileStack;
 
201
  std::vector<std::string> profileData;
128
202
};
 
203
 
129
204
  
130
205
inline ThreadProfile& thp()  {
131
206
  return current_session->getThreadProfile();
144
219
  thp().popProfilePhase();
145
220
}
146
221
 
 
222
  
 
223
class AutoProfPhase {
 
224
public:
 
225
  explicit AutoProfPhase() { }
 
226
  void popAndSaveProfileData() const {
 
227
    std::stringstream ss;                                                    
 
228
    if( th_getProf() )                                 
 
229
      th_getProf()->printOpTime(ss);                   
 
230
    th_popProfilePhase();                              
 
231
    thp().saveProfileData(ss.str().c_str());                            
 
232
  }
 
233
 
 
234
  ~AutoProfPhase() {
 
235
    popAndSaveProfileData();
 
236
  }
 
237
};
 
238
 
 
239
 
147
240
namespace rtdcimpl  {
148
241
 
149
242
  inline uint64_t getTimeInNanoSec();
159
252
    asm volatile("rdtsc":"=A"(curTimeCntr));
160
253
#elif defined(__GNUC__) && defined(__x86_64__)
161
254
    uint64_t hi, lo;
162
 
    asm volatile("rdtc":"=a"(hi), "=b"(lo));
 
255
    asm volatile("rdtc":"=a"(hi), "=d"(lo));
163
256
    curTimeCntr = (((uint64_t)hi << 32) || low);
164
257
#else
165
258
    curTimeCntr = 0;
183
276
    double scale = (double)secondsToTest/deltaTime;
184
277
    return scale;
185
278
  }
186
 
  
187
 
  double processorrCounterScale = getProcTimerstampScale();
188
 
 
 
279
#ifdef ENABLE_RTDC_BASED_TIMER
 
280
  static double processorrCounterScale = getProcTimerstampScale();
 
281
#else
 
282
  static double processorrCounterScale = 0;
 
283
#endif
189
284
  inline uint64_t getTimeInSec()  {
190
285
    uint64_t procCounterValue = getProcTimestampCounter();
191
286
    return procCounterValue * processorrCounterScale;
269
364
  }
270
365
}
271
366
 
272
 
 
273
 
enum {
274
 
  eRtdcImpl = 0,
275
 
  eClockTimeImpl,
276
 
  eGetToDImpl
277
 
};
278
 
 
279
 
enum {
280
 
  eSecPrec = 0,
281
 
  eMilliSecPrec,
282
 
  eMicroSecPrec,
283
 
  eNanoSecPrec
284
 
};
 
367
#if defined(__GNUC__) && defined(__i386__)
 
368
#define HAVE_RTDC_IMPL
 
369
#elif defined(__GNUC__) && defined(__x86_64__)
 
370
#define HAVE_RTDC_IMPL
 
371
#endif
285
372
  
286
373
inline bool useRtdcImpl() {
287
 
#if defined(__GNUC__) && defined(__i386__)
288
 
  return true;
289
 
#elif defined(__GNUC__) && defined(__x86_64__)
 
374
#ifdef HAVE_RTDC_IMPL
290
375
  return true;
291
376
#else
292
377
  return false;
335
420
  }
336
421
  return NULL;
337
422
}
338
 
 
339
 
template<int eImplKind = eRtdcImpl, int ePrecRange = eNanoSecPrec >
 
423
/**
 
424
 * Class to capture timing information for C/C++ block
 
425
 * If opName is supplied, it adds this information to currect active Timing
 
426
 * profile object.
 
427
 * Following are some overhead information for this classes
 
428
 * eImplKind = eRtdcImpl (~50 ns on 2.7 GHz intel machine), This went to
 
429
 *             average ~20 ns for large number of operations (1 million in my example)
 
430
 * eImplKind = eClockTimeImpl (~1000 ns on 2.7 GHz intel machine)
 
431
 * eImplKind = eGetToDImpl  (~1500/2000 ns on 2.7 GHz intel machine)
 
432
 */
 
433
template<int eImplKind , int ePrecRange >
340
434
class AutoOpTimer {
341
435
public:
342
 
  explicit AutoOpTimer(const char* sOpName):m_sOpName(sOpName) {
 
436
  explicit AutoOpTimer(const char* sOpName):m_sOpName(sOpName)
 
437
  {
343
438
    acquire();
 
439
    // m_pTimeProf = thp().cur();
344
440
  }
345
441
 
346
442
  void acquire() {
375
471
    }
376
472
    return uCurTime;
377
473
  }
378
 
    
379
 
  uint64_t release() const {
 
474
 
 
475
  uint64_t getTimeElapsed() const {
380
476
    uint64_t uCurTime = getCurTime();
381
477
    uint64_t uDiff = (uCurTime - m_uBgnTime) * (uCurTime > m_uBgnTime);
382
478
    return uDiff;
383
479
  }
384
 
 
 
480
    
385
481
  ~AutoOpTimer() {
386
 
    uint64_t uTimeElapsed = release();
 
482
    uint64_t uTimeElapsed = getTimeElapsed();
387
483
    if( m_sOpName ) {
388
484
      if( th_getProf() )
389
485
        th_getProf()->addOpTime(m_sOpName, uTimeElapsed);
394
490
  uint64_t m_uBgnTime;
395
491
};
396
492
 
397
 
#define HAVE_RTDC 1
398
 
 
399
 
#if defined(HAVE_RTDC)
 
493
//Rtdc based timer do not give reliable timing information.
 
494
//so by default they are off. One can use them directly if they want in
 
495
//CPU-bound operation by using following Rtdc Timers and setting
 
496
//ENABLE_RTDC_BASED_TIMER macro above.
 
497
typedef AutoOpTimer<eRtdcImpl, eNanoSecPrec> RtdcTimerNanoSecPrec;
 
498
typedef AutoOpTimer<eRtdcImpl, eMilliSecPrec> RtdcTimerMilliSecPrec;
 
499
typedef AutoOpTimer<eRtdcImpl, eMicroSecPrec> RtdcTimerMicroSecPrec;
 
500
typedef AutoOpTimer<eRtdcImpl, eSecPrec> RtdcTimerSecPrec;
 
501
 
 
502
 
 
503
#if defined(HAVE_RTDC_IMPL)
400
504
typedef AutoOpTimer<eRtdcImpl, eNanoSecPrec> FastTimerNanoSecPrec;
401
505
typedef AutoOpTimer<eRtdcImpl, eMilliSecPrec> FastTimerMilliSecPrec;
402
506
typedef AutoOpTimer<eRtdcImpl, eMicroSecPrec> FastTimerMicroSecPrec;
403
507
typedef AutoOpTimer<eRtdcImpl, eSecPrec> FastTimerSecPrec;
404
 
#elif defined(HAVE_CLOCK)
 
508
#elif defined(HAVE_CLOCK_GETTIME)
405
509
typedef AutoOpTimer<eClockTimeImpl, eNanoSecPrec> FastTimerNanoSecPrec;
406
510
typedef AutoOpTimer<eClockTimeImpl, eMilliSecPrec> FastTimerMilliSecPrec;
407
511
typedef AutoOpTimer<eClockTimeImpl, eMicroSecPrec> FastTimerMicroSecPrec;
413
517
typedef AutoOpTimer<eGetToDImpl, eSecPrec> FastTimerSecPrec;
414
518
#endif
415
519
 
 
520
  
 
521
uint64_t getSecTime() {
 
522
  return FastTimerSecPrec::getCurTime();
 
523
}
 
524
 
 
525
uint64_t getMilliSecTime() {
 
526
  return FastTimerMilliSecPrec::getCurTime();
 
527
}
 
528
 
 
529
uint64_t getMicroSecTime() {
 
530
  return FastTimerMicroSecPrec::getCurTime();
 
531
}
 
532
 
 
533
uint64_t getNanoSecTime()  {
 
534
  return FastTimerNanoSecPrec::getCurTime();
 
535
}
 
536
 
416
537
 
417
538
#ifdef TEST_TIMER
418
539
 
497
618
void testTiming()  {
498
619
  double per = 3;
499
620
  {
500
 
    debug() << "----------------------------------------" << endl;
501
 
    debug() <<  "Testing get_clocktime based timer impl" << endl;
 
621
    cerr << "----------------------------------------" << endl;
 
622
    cerr <<  "Testing get_clocktime based timer impl" << endl;
502
623
    using clockimpl::getTimeInNanoSec;
503
624
    using clockimpl::getTimeInMilliSec;
504
625
    using clockimpl::getTimeInMicroSec;
524
645
  }
525
646
 
526
647
  {
527
 
    debug() << "----------------------------------------" << endl;
528
 
    debug() << endl << "Testing gettimeofday based timer impl" << endl;
 
648
    cerr << "----------------------------------------" << endl;
 
649
    cerr << endl << "Testing gettimeofday based timer impl" << endl;
529
650
    using todimpl::getTimeInNanoSec;
530
651
    using todimpl::getTimeInMilliSec;
531
652
    using todimpl::getTimeInMicroSec;
551
672
  }
552
673
 
553
674
  {
554
 
    debug() << "----------------------------------------" << endl;
555
 
    debug() << endl << "Testing rtdc based timer impl" << endl;
 
675
    cerr << "----------------------------------------" << endl;
 
676
    cerr << endl << "Testing rtdc based timer impl" << endl;
556
677
    using rtdcimpl::getTimeInNanoSec;
557
678
    using rtdcimpl::getTimeInMilliSec;
558
679
    using rtdcimpl::getTimeInMicroSec;
583
704
  testTimeProfile();
584
705
}
585
706
#endif
 
707
 
586
708
}/* namespace timer */
587
709
}/*namespace drizzled*/
 
710
 
 
711
 
588
712
#endif