Merge lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring into lp:~drizzle-trunk/drizzle/development

Proposed by PrafullaT
Status: Rejected
Rejected by: Lee Bieber
Proposed branch: lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring
Merge into: lp:~drizzle-trunk/drizzle/development
Diff against target: 1013 lines (+693/-16)
9 files modified
drizzled/drizzled.cc (+0/-1)
drizzled/filesort.cc (+35/-8)
drizzled/include.am (+1/-0)
drizzled/optimizer/range.cc (+2/-0)
drizzled/session.cc (+7/-2)
drizzled/session.h (+21/-2)
drizzled/sql_parse.cc (+13/-1)
drizzled/sql_select.cc (+0/-2)
drizzled/time_profile.h (+614/-0)
To merge this branch: bzr merge lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring
Reviewer Review Type Date Requested Status
Stewart Smith (community) Disapprove
Monty Taylor Pending
Brian Aker Pending
Review via email: mp+32887@code.launchpad.net

Description of the change

Hi
This is first attempt to have timer classes and easy macros
for doing time-related profiling of drizzle code.

We have three choice for timer classes.
rtdtc based timer
clock_gettime based timer
gettimeofday based timer.

As an example of how macros can be used, I have added few timer(uSec precision) profile related macros around filesort code.

Here what is dumped in error stream once query/command execution is done.

--------------------Profile Output------------------
Command : create table t(c1 int)
query
{
mysql_parse, acc= 71303 microsec, occ=1
}

---------------------------x------------------------
--------------------Profile Output------------------
Command : select * from t
query
{
mysql_parse, acc= 630 microsec, occ=1
}

---------------------------x------------------------
--------------------Profile Output------------------
Command : select * from t order by 1
query
{
mysql_parse, acc= 365 microsec, occ=1
}

filesort
{
estimateRowsUpperBound, acc= 4 microsec, occ=1
filesort, acc= 95 microsec, occ=1
find_all_keys, acc= 49 microsec, occ=1
innodb::releaselatches, acc= 3 microsec, occ=1
raw_read, acc= 28 microsec, occ=1
register_used_fields, acc= 2 microsec, occ=1
save_index, acc= 2 microsec, occ=1
}

---------------------------x------------------------

acc = accumulated time
occ = number of timers timer code was invoked.

In order to enable time profiling, we need to turn on TIME_PROFILE
macro in time_profile.h

I hope this would be helpful in profiling various part of drizzle code.
Could you please go over the code and suggest improvement if any ?

To post a comment you must log in.
Revision history for this message
PrafullaT (prafulla-t) wrote :

Hi
This branch has code from my other branches too.

Could you please look at the following files ?
drizzled/filesort.cc drizzled/session.cc
drizzled/session.h
drizzled/sql_parse.cc drizzled/time_profile.h
drizzled/optimizer/range.cc

Once it is reviewed, I will create separate branch with only
profiling related code. or hopefully by then my other changes
should already be in trunk.

Revision history for this message
Monty Taylor (mordred) wrote :

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 08/17/2010 08:18 AM, Prafulla Tekawade wrote:
> Prafulla Tekawade has proposed merging lp:~prafulla-tekawade/drizzle/drz-fast-timer-and-time-profile-refactoring into lp:drizzle.
>
> Requested reviews:
> Drizzle Merge Team (drizzle-merge)
>
>
> Hi
> This is first attempt to have timer classes and easy macros
> for doing time-related profiling of drizzle code.

This looks very potentially useful.

> We have three choice for timer classes.
> rtdtc based timer
> clock_gettime based timer
> gettimeofday based timer.

Could you also investigate Boost::DateTime and see if it's a useful
choice for timer class implementation? I'm looking at using it for some
other things as well and I'd love it if we could have one set of
time-related code.

However, if it's not suitable, that's fine.

> As an example of how macros can be used, I have added few timer(uSec precision) profile related macros around filesort code.
>
> Here what is dumped in error stream once query/command execution is done.
>
> -------------Profile Output----------
> query
> {
> mysql_parse, acc= 366639 microsec, occ=1
> }
>
> filesort
> {
> estimateRowsUpperBound, acc= 5 microsec, occ=1
> filesort, acc= 262365 microsec, occ=1
> find_all_keys, acc= 227612 microsec, occ=1
> innodb::releaselatches, acc= 3 microsec, occ=1
> make_char_array, acc= 18 microsec, occ=1
> optimizer::SqlSelect::skip_record, acc= 18647 microsec, occ=12010
> raw_read, acc= 68733 microsec, occ=12011
> write_keys, acc= 46767 microsec, occ=12010
> }
>
> acc = accumulated time
> occ = number of timers timer code was invoked.
>
> In order to enable time profiling, we need to turn on TIME_PROFILE
> macro in time_profile.h
>
> I hope this would be helpful in profiling various part of drizzle code.
> Could you please go over the code and suggest improvement if any ?
>

A few quick notes...

Please do not include config.h in drizzled/time_profile.h ... it will be
included by any .cc files that use it.

For the output - would you see if it's possible to hook in to the error
message infrastructure? (errmsg_printf and friends) - that way it's
conceivable that someone could use profiling in an infrastructure where
server messages are reported to a centralized server. Like
boost::datetime, it's possible this won't work well yet - I've been
meaning to add a stream-like interface to that system and just haven't
gotten there yet.

Other than that it looks reasonable (I haven't walked through the actual
timer impl code fully yet.)

Monty
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkxqq2AACgkQ2Jv7/VK1RgEAngCguk02ETTC9xj7ruBbalvLr/B7
n7IAoO7Yr/Py6y3bu6P8RFzQNfzQ1nY0
=UPvq
-----END PGP SIGNATURE-----

1701. By PrafullaT

Time profiling related macros were misplaced due to
wrong patch in filesort.cc
Putting them at right place now.

1702. By PrafullaT

Merge from mainline branch.

1703. By PrafullaT

o. Adding some printf which prints command along with profile data
   This would help associating profiling data with input command
   easily
o. Removing some unnecessary printfs in mysql_parse method
o. Replaced fprintf with errmsg_printf as suggested by Monty in review
o. Adding license information
o. Adding guards around use clock_gettime method as it may not
   available on some platform.

1704. By PrafullaT

Fixing some formatting issues.

1705. By PrafullaT

Some more formatting issues.

Revision history for this message
Brian Aker (brianaker) wrote :

Hi!

A couple of things:

1) We want to avoid using pthread_key_t because it ties sessions to threads, and we want sessions to float between threads.

2) At the beginning of each query we call gettimeofday() in Session. You can base any calls you need off of that initially.

3) The style in the code is off from our coding style.

How can we provide this data to a user? Have you thought about providing a table function to display it for the last query?

Cheers,
   -Brian

(BTW I will be offline for an extended period of time starting this weekend, so I will be slow to respond for the next two weeks).

Revision history for this message
PrafullaT (prafulla-t) wrote :

Hi,
Thanks for review Brian.

> Hi!
>
> A couple of things:
>
> 1) We want to avoid using pthread_key_t because it ties sessions to threads,
> and we want sessions to float between threads.

I see , I wanted profile code to be done for a single thread to avoid having
thread related complexity(mutex etc) in profiling code.
Do you suggest creating independent pthread_key_t for ThreadProfile ?
That was my original plan but then I saw sessions are created per thread so I hung
threadprofile object pointer off that class.

> 2) At the beginning of each query we call gettimeofday() in Session. You can
> base any calls you need off of that initially.
>
> 3) The style in the code is off from our coding style.

I will work on the style.

>
> How can we provide this data to a user? Have you thought about providing a
> table function to display it for the last query?

User ?
I thought this would be useful for developer working on drizzle code as profiling
related code will most probably have names of internal function etc.
But yes, the data can be made available to use through some user variable.
I'll think about this.

--
Thanks
Prafulla

1706. By PrafullaT

Merge from trunk

Revision history for this message
Brian Aker (brianaker) wrote :

hi!

Please ask monty (or Lee) to set you up with hudson param build to see how this patch does with performance regression on the benchmarks.

Cheers,
   -Brian

Revision history for this message
Monty Taylor (mordred) wrote :

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 08/20/2010 09:30 PM, Brian Aker wrote:
> hi!
>
> Please ask monty (or Lee) to set you up with hudson param build to see how this patch does with performance regression on the benchmarks.

Make yourself a user account on http://hudson.drizzle.org and then tell
me what it is.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkxvWDAACgkQ2Jv7/VK1RgGWUwCaAi0vS/FHhIKqV0dOTrL/6ChV
PWcAoOJcCCt95CiCzHerS+k5UVu7iaNk
=pk3X
-----END PGP SIGNATURE-----

1707. By PrafullaT

Fixing build failure on x86 machines
Also adding time_profile.h to include.am

1708. By PrafullaT

Chaning profiling to default off

1709. By PrafullaT

Merge from trunk

Revision history for this message
PrafullaT (prafulla-t) wrote :

Hi,

> Please ask monty (or Lee) to set you up with hudson param build to see how
> this patch does with performance regression on the benchmarks.

I ran few sysbench related test to see how it performs with this patch
Here are results.

With time profiling default on
https://lists.launchpad.net/drizzle-benchmark/msg03728.html

Without time profiling default off
https://lists.launchpad.net/drizzle-benchmark/msg03729.html

Performance becomes pretty bad with this time profiling default on.
This should be due to err_msgprintf which is used to print profile
output along with input command string.

I wrote this patch as an aid to developer working on performance
intensive project, to see which part of code is taking what time
etc. I do not think, this should be default on. We can however make user
timer to get timing information. Developer working
on performance related projects, should turn it on themselves. (Maybe
./configure can be modified to take extra param for this).

Let me know what you think

--
Thanks
Prafulla

1710. By PrafullaT

Making some changes to match up to drizzled coding standard

1711. By PrafullaT

Some more changes for coding standard

Revision history for this message
Brian Aker (brianaker) wrote :

(I am on vacation for the next two weeks, so my resonces will be slow).

If we don't print but only collect timing information, how does it effect performance ?

Revision history for this message
PrafullaT (prafulla-t) wrote :

> If we don't print but only collect timing information, how does it effect
> performance ?

If we have TIME_PROFILE_ON define'ed, it collects timing information as well as
prints it at the end of query execution using errmsg_printf,
This printing is what should be causing performance degradation.
In current branch TIME_PROFILE_ON is off by default, and hence performance
is pretty much within norm.

--
Thanks
Prauflla

1712. By PrafullaT

Disabling just printing of profiling code, to see
impact of priniting on performance.

1713. By PrafullaT

Fixing build failure

Revision history for this message
PrafullaT (prafulla-t) wrote :

> > If we don't print but only collect timing information, how does it effect
> > performance ?

I just ran tests without printing code and TIME_PROFILE_ON defin'ed

https://lists.launchpad.net/drizzle-benchmark/msg03772.html
https://lists.launchpad.net/drizzle-benchmark/msg03771.html

Performance is worse with this settings too.
I need to check root cause of these regression.

--
Thanks
Prafulla

Revision history for this message
Stewart Smith (stewart) wrote :

The regression is because any call getting a timer is relatively expensive. Also, when you have inline asm somewhere, it does limit what the compiler can do to optimise (think about instruction re-ordering around the getting of the timer).

I'd much prefer to see something based on the Linux perf-events infrastructure instead - it could be easily used to get a much better profile of what's going on instead of just what we think would ever be a bottleneck.

I guess you could hook into dtrace on OSX/Solaris but I don't think anybody really cares :)

review: Disapprove
Revision history for this message
Stewart Smith (stewart) wrote :

(that being said, for an implementation of this type of timers, this look relatively okay... I just disagree with the approach)

Unmerged revisions

1713. By PrafullaT

Fixing build failure

1712. By PrafullaT

Disabling just printing of profiling code, to see
impact of priniting on performance.

1711. By PrafullaT

Some more changes for coding standard

1710. By PrafullaT

Making some changes to match up to drizzled coding standard

1709. By PrafullaT

Merge from trunk

1708. By PrafullaT

Chaning profiling to default off

1707. By PrafullaT

Fixing build failure on x86 machines
Also adding time_profile.h to include.am

1706. By PrafullaT

Merge from trunk

1705. By PrafullaT

Some more formatting issues.

1704. By PrafullaT

Fixing some formatting issues.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'drizzled/drizzled.cc'
2--- drizzled/drizzled.cc 2010-08-24 01:36:17 +0000
3+++ drizzled/drizzled.cc 2010-08-26 04:32:43 +0000
4@@ -338,7 +338,6 @@
5 boost::mutex LOCK_open;
6 boost::mutex LOCK_global_system_variables;
7 boost::mutex LOCK_thread_count;
8-
9 boost::condition_variable COND_refresh;
10 boost::condition_variable COND_thread_count;
11 pthread_t signal_thread;
12
13=== modified file 'drizzled/filesort.cc'
14--- drizzled/filesort.cc 2010-08-17 01:34:55 +0000
15+++ drizzled/filesort.cc 2010-08-26 04:32:43 +0000
16@@ -41,6 +41,8 @@
17 #include "drizzled/internal/my_sys.h"
18 #include "plugin/myisam/myisam.h"
19 #include "drizzled/plugin/transactional_storage_engine.h"
20+#include "drizzled/time_profile.h"
21+
22
23 using namespace std;
24
25@@ -135,6 +137,8 @@
26 optimizer::SqlSelect *select, ha_rows max_rows,
27 bool sort_positions, ha_rows *examined_rows)
28 {
29+ START_PROFILING_PHASE("filesort", "microsec");
30+ BLOCK_MICRO_SEC_TIMER("filesort");
31 int error;
32 uint32_t memavl, min_sort_memory;
33 uint32_t maxbuffer;
34@@ -151,11 +155,14 @@
35
36 DRIZZLE_FILESORT_START(table->getShare()->getSchemaName(), table->getShare()->getTableName());
37
38- /*
39- Release InnoDB's adaptive hash index latch (if holding) before
40- running a sort.
41- */
42- plugin::TransactionalStorageEngine::releaseTemporaryLatches(session);
43+ {
44+ BLOCK_MICRO_SEC_TIMER("innodb::releaselatches");
45+ /*
46+ Release InnoDB's adaptive hash index latch (if holding) before
47+ running a sort.
48+ */
49+ plugin::TransactionalStorageEngine::releaseTemporaryLatches(session);
50+ }
51
52 /*
53 Don't use table->sort in filesort as it is also used by
54@@ -226,6 +233,7 @@
55 else
56 #endif
57 {
58+ BLOCK_MICRO_SEC_TIMER("estimateRowsUpperBound");
59 records= table->cursor->estimate_rows_upper_bound();
60 /*
61 If number of records is not known, use as much of sort buffer
62@@ -268,10 +276,12 @@
63 param.keys--; /* TODO: check why we do this */
64 param.sort_form= table;
65 param.end=(param.local_sortorder=sortorder)+s_length;
66+
67 if ((records=find_all_keys(session, &param,select,sort_keys, &buffpek_pointers,
68- &tempfile, selected_records_file)) ==
69- HA_POS_ERROR)
70+ &tempfile, selected_records_file)) == HA_POS_ERROR)
71 goto err;
72+
73+
74 maxbuffer= (uint32_t) (my_b_tell(&buffpek_pointers)/sizeof(*buffpek));
75
76 if (maxbuffer == 0) // The whole set is in memory
77@@ -363,7 +373,7 @@
78 DRIZZLE_FILESORT_DONE(error, records);
79 return (error ? HA_POS_ERROR : records);
80 } /* filesort */
81-
82+
83
84 void Table::filesort_free_buffers(bool full)
85 {
86@@ -421,6 +431,8 @@
87 static unsigned char *read_buffpek_from_file(internal::IO_CACHE *buffpek_pointers, uint32_t count,
88 unsigned char *buf)
89 {
90+
91+ BLOCK_MICRO_SEC_TIMER("read_buffpek_from_file");
92 uint32_t length= sizeof(buffpek_st)*count;
93 unsigned char *tmp= buf;
94 if (count > UINT_MAX/sizeof(buffpek_st))
95@@ -484,6 +496,7 @@
96 internal::IO_CACHE *buffpek_pointers,
97 internal::IO_CACHE *tempfile, internal::IO_CACHE *indexfile)
98 {
99+ BLOCK_MICRO_SEC_TIMER("find_all_keys");
100 int error,flag,quick_select;
101 uint32_t idx,indexpos,ref_length;
102 unsigned char *ref_pos,*next_pos,ref_buff[MAX_REFLENGTH];
103@@ -540,6 +553,7 @@
104 {
105 if (quick_select)
106 {
107+ BLOCK_MICRO_SEC_TIMER("quick_select_read");
108 if ((error= read_record_info.read_record(&read_record_info)))
109 {
110 error= HA_ERR_END_OF_FILE;
111@@ -551,6 +565,7 @@
112 {
113 if (indexfile)
114 {
115+ BLOCK_MICRO_SEC_TIMER("index_file_read");
116 if (my_b_read(indexfile,(unsigned char*) ref_pos,ref_length))
117 {
118 error= errno ? errno : -1; /* Abort */
119@@ -560,6 +575,7 @@
120 }
121 else
122 {
123+ BLOCK_MICRO_SEC_TIMER("raw_read");
124 error=file->rnd_next(sort_form->getInsertRecord());
125
126 if (!flag)
127@@ -663,6 +679,7 @@
128 write_keys(SORTPARAM *param, register unsigned char **sort_keys, uint32_t count,
129 internal::IO_CACHE *buffpek_pointers, internal::IO_CACHE *tempfile)
130 {
131+ BLOCK_MICRO_SEC_TIMER("write_keys");
132 size_t sort_length, rec_length;
133 unsigned char **end;
134 buffpek_st buffpek;
135@@ -699,6 +716,7 @@
136
137 static inline void store_length(unsigned char *to, uint32_t length, uint32_t pack_length)
138 {
139+ BLOCK_MICRO_SEC_TIMER("store_length");
140 switch (pack_length) {
141 case 1:
142 *to= (unsigned char) length;
143@@ -721,6 +739,7 @@
144 static void make_sortkey(register SORTPARAM *param,
145 register unsigned char *to, unsigned char *ref_pos)
146 {
147+ BLOCK_MICRO_SEC_TIMER("make_sortkey");
148 Field *field;
149 SortField *sort_field;
150 size_t length;
151@@ -954,6 +973,7 @@
152
153 static void register_used_fields(SORTPARAM *param)
154 {
155+ BLOCK_MICRO_SEC_TIMER("register_used_fields");
156 SortField *sort_field;
157 Table *table=param->sort_form;
158
159@@ -992,6 +1012,7 @@
160 static bool save_index(SORTPARAM *param, unsigned char **sort_keys, uint32_t count,
161 filesort_info_st *table_sort)
162 {
163+ BLOCK_MICRO_SEC_TIMER("save_index");
164 uint32_t offset,res_length;
165 unsigned char *to;
166
167@@ -1017,6 +1038,7 @@
168 int merge_many_buff(SORTPARAM *param, unsigned char *sort_buffer,
169 buffpek_st *buffpek, uint32_t *maxbuffer, internal::IO_CACHE *t_file)
170 {
171+ BLOCK_MICRO_SEC_TIMER("merge_many_buf");
172 register uint32_t i;
173 internal::IO_CACHE t_file2,*from_file,*to_file,*temp;
174 buffpek_st *lastbuff;
175@@ -1074,6 +1096,7 @@
176 uint32_t read_to_buffer(internal::IO_CACHE *fromfile, buffpek_st *buffpek,
177 uint32_t rec_length)
178 {
179+ BLOCK_MICRO_SEC_TIMER("read_to_buffer");
180 register uint32_t count;
181 uint32_t length;
182
183@@ -1130,6 +1153,7 @@
184 buffpek_st *lastbuff, buffpek_st *Fb, buffpek_st *Tb,
185 int flag)
186 {
187+ BLOCK_MICRO_SEC_TIMER("merge_buffers");
188 int error;
189 uint32_t rec_length,res_length,offset;
190 size_t sort_length;
191@@ -1336,6 +1360,7 @@
192 buffpek_st *buffpek, uint32_t maxbuffer,
193 internal::IO_CACHE *tempfile, internal::IO_CACHE *outfile)
194 {
195+ BLOCK_MICRO_SEC_TIMER("merge_index");
196 if (merge_buffers(param,tempfile,outfile,sort_buffer,buffpek,buffpek,
197 buffpek+maxbuffer,1))
198 return(1);
199@@ -1570,6 +1595,7 @@
200 static void
201 unpack_addon_fields(struct sort_addon_field_st *addon_field, unsigned char *buff)
202 {
203+ BLOCK_MICRO_SEC_TIMER("unpack_addon_fields");
204 Field *field;
205 sort_addon_field_st *addonf= addon_field;
206
207@@ -1594,6 +1620,7 @@
208
209 void change_double_for_sort(double nr,unsigned char *to)
210 {
211+ BLOCK_MICRO_SEC_TIMER("change_double_for_sort");
212 unsigned char *tmp=(unsigned char*) to;
213 if (nr == 0.0)
214 { /* Change to zero string */
215
216=== modified file 'drizzled/include.am'
217--- drizzled/include.am 2010-08-20 18:39:24 +0000
218+++ drizzled/include.am 2010-08-26 04:32:43 +0000
219@@ -428,6 +428,7 @@
220 drizzled/temporal_interval.h \
221 drizzled/thr_lock.h \
222 drizzled/time_functions.h \
223+ drizzled/time_profile.h \
224 drizzled/tmp_table_param.h \
225 drizzled/transaction_context.h \
226 drizzled/transaction_services.h \
227
228=== modified file 'drizzled/optimizer/range.cc'
229--- drizzled/optimizer/range.cc 2010-08-06 11:21:12 +0000
230+++ drizzled/optimizer/range.cc 2010-08-26 04:32:43 +0000
231@@ -132,6 +132,7 @@
232 #include "drizzled/records.h"
233 #include "drizzled/internal/my_sys.h"
234 #include "drizzled/internal/iocache.h"
235+#include "drizzled/time_profile.h"
236
237 #include "drizzled/temporal.h" /* Needed in get_mm_leaf() for timestamp -> datetime comparisons */
238
239@@ -420,6 +421,7 @@
240
241 bool optimizer::SqlSelect::skip_record()
242 {
243+ BLOCK_MICRO_SEC_TIMER("optimizer::SqlSelect::skip_record");
244 return (cond ? cond->val_int() == 0 : 0);
245 }
246
247
248=== modified file 'drizzled/session.cc'
249--- drizzled/session.cc 2010-08-24 16:45:09 +0000
250+++ drizzled/session.cc 2010-08-26 04:32:43 +0000
251@@ -47,6 +47,7 @@
252 #include "drizzled/pthread_globals.h"
253 #include "drizzled/transaction_services.h"
254 #include "drizzled/drizzled.h"
255+#include "drizzled/time_profile.h"
256
257 #include "drizzled/table_share_instance.h"
258
259@@ -160,6 +161,7 @@
260 scheduler(NULL),
261 scheduler_arg(NULL),
262 lock_id(&main_lock_id),
263+ pThreadProfile(NULL),
264 user_time(0),
265 ha_data(plugin::num_trx_monitored_objects),
266 arg_of_last_insert_id_function(false),
267@@ -254,7 +256,7 @@
268 thr_lock_owner_init(&main_lock_id, &lock_info);
269
270 m_internal_handler= NULL;
271-
272+ pThreadProfile = new drizzled::timer::ThreadProfile();
273 plugin::EventObserver::registerSessionEvents(*this);
274 }
275
276@@ -391,7 +393,10 @@
277 pthread_setspecific(THR_Session, 0);
278
279 plugin::Logging::postEndDo(this);
280- plugin::EventObserver::deregisterSessionEvents(*this);
281+ plugin::EventObserver::deregisterSessionEvents(*this);
282+
283+ delete pThreadProfile;
284+ pThreadProfile = NULL;
285
286 /* Ensure that no one is using Session */
287 LOCK_delete.unlock();
288
289=== modified file 'drizzled/session.h'
290--- drizzled/session.h 2010-08-24 16:45:09 +0000
291+++ drizzled/session.h 2010-08-26 04:32:43 +0000
292@@ -80,6 +80,11 @@
293 struct st_my_thread_var;
294 }
295
296+namespace timer
297+{
298+class ThreadProfile;
299+}
300+
301 class Lex_input_stream;
302 class user_var_entry;
303 class CopyField;
304@@ -418,7 +423,18 @@
305 struct system_status_var status_var; /**< Session-local status counters */
306 THR_LOCK_INFO lock_info; /**< Locking information for this session */
307 THR_LOCK_OWNER main_lock_id; /**< To use for conventional queries */
308- THR_LOCK_OWNER *lock_id; /**< If not main_lock_id, points to the lock_id of a cursor. */
309+ THR_LOCK_OWNER *lock_id; /**< If not main_lock_id, points to the lock_id of a
310+ *cursor. */
311+
312+ /**
313+ ThreadProfile class has been created to handle time-profiling related
314+ information for individual threads.(so as to reduce complexity of mutex etc
315+ in writing profiling classes) This is currenly hung off session object
316+ assuming it would be there per connection. Other alternative is to create
317+ pthread_key_t specifically for profiling and put object of threadProfile
318+ class there.
319+ */
320+ timer::ThreadProfile* pThreadProfile; /**< Data structure required for time profiling*/
321 private:
322 boost::mutex LOCK_delete; /**< Locked before session is deleted */
323 public:
324@@ -432,7 +448,10 @@
325 {
326 LOCK_delete.unlock();
327 }
328-
329+ timer::ThreadProfile& getThreadProfile() const {
330+ return *pThreadProfile;
331+ }
332+
333 /**
334 * A peek into the query string for the session. This is a best effort
335 * delivery, there is no guarantee whether the content is meaningful.
336
337=== modified file 'drizzled/sql_parse.cc'
338--- drizzled/sql_parse.cc 2010-08-24 16:45:09 +0000
339+++ drizzled/sql_parse.cc 2010-08-26 04:32:43 +0000
340@@ -41,6 +41,7 @@
341 #include "drizzled/probes.h"
342 #include "drizzled/session_list.h"
343 #include "drizzled/global_charset_info.h"
344+#include "drizzled/time_profile.h"
345
346 #include "drizzled/plugin/logging.h"
347 #include "drizzled/plugin/query_rewrite.h"
348@@ -214,6 +215,7 @@
349 }
350 case COM_QUERY:
351 {
352+ START_PROFILING_PHASE("query", "microsec");
353 if (! session->readAndStoreQuery(packet, packet_length))
354 break; // fatal error is set
355 DRIZZLE_QUERY_START(session->query.c_str(),
356@@ -222,7 +224,16 @@
357
358 plugin::QueryRewriter::rewriteQuery(session->db, session->query);
359 mysql_parse(session, session->query.c_str(), session->query.length());
360-
361+#if 0
362+ stringstream ss;
363+ GET_ALL_PROFILING_RESULT(ss);
364+ errmsg_printf(ERRMSG_LVL_DBUG,
365+ "--------------------Profile Output------------------\n");
366+ errmsg_printf(ERRMSG_LVL_DBUG,"Command : %s\n", session->query.c_str());
367+ errmsg_printf(ERRMSG_LVL_DBUG,ss.str().c_str());
368+ errmsg_printf(ERRMSG_LVL_DBUG,
369+ "---------------------------x------------------------\n");
370+#endif
371 break;
372 }
373 case COM_QUIT:
374@@ -716,6 +727,7 @@
375
376 void mysql_parse(Session *session, const char *inBuf, uint32_t length)
377 {
378+ drizzled::timer::FastTimerMicroSecPrec autoObj("mysql_parse");
379 uint64_t start_time= my_getsystime();
380 lex_start(session);
381 session->reset_for_next_command();
382
383=== modified file 'drizzled/sql_select.cc'
384--- drizzled/sql_select.cc 2010-08-21 04:05:07 +0000
385+++ drizzled/sql_select.cc 2010-08-26 04:32:43 +0000
386@@ -6594,8 +6594,6 @@
387 /* QQ: session may not be set for sub queries, but this should be fixed */
388 if(not session)
389 session= current_session;
390-
391-
392 str->append(STRING_WITH_LEN("select "));
393
394 /* First add options */
395
396=== added file 'drizzled/time_profile.h'
397--- drizzled/time_profile.h 1970-01-01 00:00:00 +0000
398+++ drizzled/time_profile.h 2010-08-26 04:32:43 +0000
399@@ -0,0 +1,614 @@
400+/* -*- mode: c++; c-basic-offset: 2; indent-tabs-mode: nil; -*-
401+ * vim:expandtab:shiftwidth=2:tabstop=2:smarttab:
402+ *
403+ * Copyright (C) 2010 Prafulla Tekawade
404+ *
405+ * This program is free software; you can redistribute it and/or modify
406+ * it under the terms of the GNU General Public License as published by
407+ * the Free Software Foundation; version 2 of the License.
408+ *
409+ * This program is distributed in the hope that it will be useful,
410+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
411+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
412+ * GNU General Public License for more details.
413+ *
414+ * You should have received a copy of the GNU General Public License
415+ * along with this program; if not, write to the Free Software
416+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
417+ */
418+
419+#ifndef DRIZZLED_TIME_PROFILE_H
420+#define DRIZZLED_TIME_PROFILE_H
421+
422+#include "drizzled/drizzle_time.h"
423+#if TIME_WITH_SYS_TIME
424+#include <sys/time.h>
425+#include <time.h>
426+#else
427+#if HAVE_SYS_TIME_H
428+#include <sys/time.h>
429+#else
430+#include <time.h>
431+#endif
432+
433+#endif
434+
435+#include <iostream>
436+#include <stdint.h>
437+#include <math.h>
438+#include <stdio.h>
439+#include <cassert>
440+#include <map>
441+#include <stack>
442+#include <sstream>
443+#include <iostream>
444+#include "drizzled/session.h"
445+#include "drizzled/errmsg_print.h"
446+
447+#define ONE_BILLION 1000000000ULL
448+#define ONE_MILLION 1000000
449+#define ONE_THOUSAND 1000
450+
451+
452+#if 0
453+#define ENABLE_RTDC_BASED_TIMER
454+#endif
455+
456+
457+//Set this to 1, if you want to profile the code.
458+#if 1
459+#define TIME_PROFILE_ON 1
460+#endif
461+
462+#define _CONCAT(a,b) a ## b
463+#define CONCAT(a,b) _CONCAT(a, b)
464+
465+namespace drizzled {
466+namespace timer {
467+
468+inline uint64_t getSecTime();
469+inline uint64_t getMicroSecTime();
470+inline uint64_t getNanoSecTime();
471+inline uint64_t getMilliSecTime();
472+
473+inline ThreadProfile& thp();
474+inline void th_pushProfilePhase(const char* sPhaseName,
475+ const char* sScale);
476+inline void th_popProfilePhase();
477+inline bool useRtdcImpl();
478+inline bool useClockGetTimeImpl();
479+inline const char* getTimePrecToStr(int ePrecRange);
480+
481+
482+enum
483+{
484+ eRtdcImpl = 0,
485+ eClockTimeImpl,
486+ eGetToDImpl
487+};
488+
489+enum
490+{
491+ eSecPrec = 0,
492+ eMilliSecPrec,
493+ eMicroSecPrec,
494+ eNanoSecPrec
495+};
496+
497+#ifdef TIME_PROFILE_ON
498+
499+#define BLOCK_NANO_SEC_TIMER(sBlockName) drizzled::timer::FastTimerNanoSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
500+#define BLOCK_MICRO_SEC_TIMER(sBlockName) drizzled::timer::FastTimerMicroSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
501+#define BLOCK_MILLI_SEC_TIMER(sBlockName) drizzled::timer::FastTimerMilliSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
502+#define BLOCK_SEC_TIMER(sBlockName) drizzled::timer::FastTimerSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
503+
504+#define START_PROFILING_PHASE(name, scale) \
505+ drizzled::timer::th_pushProfilePhase(name, scale); \
506+ drizzled::timer::AutoProfPhase autoPhase;
507+
508+
509+#define GET_ALL_PROFILING_RESULT(outputStream) drizzled::timer::thp().printAllOpTime(outputStream);
510+
511+#else
512+
513+#define START_PROFILING_PHASE(name, scale)
514+#define END_PROFILING_AND_COLLECT_RESULT(outputStream)
515+#define BLOCK_NANO_SEC_TIMER(sBlockName)
516+#define BLOCK_MICRO_SEC_TIMER(sBlockName)
517+#define BLOCK_MILLI_SEC_TIMER(sBlockName)
518+#define BLOCK_SEC_TIMER(sBlockName)
519+#define GET_ALL_PROFILING_RESULT(outputStream)
520+
521+
522+#endif
523+
524+class TimeProfile
525+{
526+private:
527+ typedef std::pair<uint64_t, uint64_t> AccOccTimePair;
528+ typedef std::map<std::string, AccOccTimePair> OpTimeMap;
529+public:
530+
531+ TimeProfile():prof_name("{NoProfileName}"),
532+ scale("NoScale")
533+ { }
534+ TimeProfile(const char* _prof_name,
535+ const char* _scale) : prof_name(_prof_name),
536+ scale(_scale)
537+ { }
538+
539+ void addOpTime(const char* name, uint64_t time)
540+ {
541+ std::pair<OpTimeMap::iterator, bool> ins_res_pair =
542+ opTimeMap.insert(std::make_pair(name, std::make_pair(time,1)));
543+
544+ if( !ins_res_pair.second ) { //If opName already exists, accumulate numTime
545+ //and increament occ counter.
546+ (ins_res_pair.first)->second.first += time;
547+ (ins_res_pair.first)->second.second++;
548+ }
549+ }
550+
551+ void printOpTime(std::ostream& oss)
552+ {
553+ OpTimeMap::iterator itr = opTimeMap.begin();
554+ oss << prof_name << std::endl;
555+ oss << "{" << std::endl;
556+ while( itr != opTimeMap.end() )
557+ {
558+ oss << itr->first;
559+ oss << ", acc= " << itr->second.first << " " << scale;
560+ oss << ", occ=" << itr->second.second << std::endl;
561+ itr++;
562+ }
563+ oss << "}" << std::endl;
564+ }
565+
566+private:
567+ OpTimeMap opTimeMap;
568+ const char* prof_name;
569+ const char* scale;
570+};
571+
572+
573+class ThreadProfile
574+{
575+public:
576+
577+ ThreadProfile():time_profile_stack(),
578+ profile_data() { }
579+ ~ThreadProfile() { }
580+
581+ TimeProfile* cur()
582+ {
583+ if( time_profile_stack.empty() )
584+ return NULL;
585+ return &(time_profile_stack.top());
586+ }
587+ void pushProfilePhase(const char* sPhaseName, const char* sScale)
588+ {
589+ time_profile_stack.push(TimeProfile(sPhaseName, sScale));
590+ }
591+
592+ void popProfilePhase()
593+ {
594+ if( time_profile_stack.empty() )
595+ return;
596+ time_profile_stack.pop();
597+ }
598+
599+ void printAllOpTime(std::ostream& oss)
600+ {
601+ while( !time_profile_stack.empty() )
602+ {
603+ time_profile_stack.top().printOpTime(oss);
604+ oss << std::endl;
605+ time_profile_stack.pop();
606+ }
607+ std::vector<std::string>::const_iterator it = profile_data.begin();
608+ while(it != profile_data.end())
609+ {
610+ oss << *it;
611+ oss << std::endl;
612+ it++;
613+ }
614+ profile_data.clear();
615+ }
616+
617+ void saveProfileData(const char* pData)
618+ {
619+ std::string sStr(pData);
620+ if( sStr.length() )
621+ profile_data.push_back(sStr);
622+ }
623+private:
624+ std::stack<TimeProfile> time_profile_stack;
625+ std::vector<std::string> profile_data;
626+};
627+
628+
629+inline ThreadProfile& thp()
630+{
631+ return current_session->getThreadProfile();
632+}
633+
634+inline TimeProfile* th_getProf()
635+{
636+ return thp().cur();
637+}
638+
639+inline void th_pushProfilePhase(const char* sPhaseName,
640+ const char* sScale)
641+{
642+ thp().pushProfilePhase(sPhaseName, sScale);
643+}
644+
645+inline void th_popProfilePhase()
646+{
647+ thp().popProfilePhase();
648+}
649+
650+
651+class AutoProfPhase
652+{
653+public:
654+ explicit AutoProfPhase()
655+ { }
656+ void popAndSaveProfileData() const
657+ {
658+ std::stringstream ss;
659+ if( th_getProf() )
660+ th_getProf()->printOpTime(ss);
661+ th_popProfilePhase();
662+ thp().saveProfileData(ss.str().c_str());
663+ }
664+
665+ ~AutoProfPhase() {
666+ popAndSaveProfileData();
667+ }
668+};
669+
670+
671+namespace rtdcimpl {
672+
673+ inline uint64_t getTimeInNanoSec();
674+ inline uint64_t getTimeInMicroSec();
675+ inline uint64_t getTimeInMilliSec();
676+ inline uint64_t getTimeInSec();
677+ inline uint64_t getProcTimestampCounter();
678+ inline double getProcTimerstampScale();
679+
680+ inline uint64_t getProcTimestampCounter()
681+ {
682+ uint64_t cur_time_cntr;
683+#if defined(__GNUC__) && defined(__i386__)
684+ asm volatile("rdtsc":"=A"(cur_time_cntr));
685+#elif defined(__GNUC__) && defined(__x86_64__)
686+ uint64_t hi, lo;
687+ asm volatile("rdtc":"=a"(hi), "=d"(lo));
688+ cur_time_cntr = (((uint64_t)hi << 32) || lo);
689+#else
690+ cur_time_cntr = 0;
691+ assert(!"Aborted: rdtsc unimplemented for this configuration.");
692+#endif
693+ return cur_time_cntr;;
694+ }
695+
696+ //Calculating how many seconds are spent in a tick
697+ //so that we can use this information to get nano/milli/micro secs
698+ inline double getProcTimerstampScale()
699+ {
700+ int seconds_to_test = 2;
701+ uint64_t delta_time = 0, retry_num = 3;
702+ do
703+ {
704+ uint64_t beforeTime = getProcTimestampCounter();
705+ sleep(seconds_to_test);
706+ delta_time = getProcTimestampCounter() - beforeTime;
707+ } while(retry_num-- && delta_time > 0);
708+ if (delta_time <= 0 )
709+ return 0;
710+ double scale = (double)seconds_to_test/delta_time;
711+ return scale;
712+ }
713+#ifdef ENABLE_RTDC_BASED_TIMER
714+ static double processort_counter_scale = getProcTimerstampScale();
715+#else
716+ static double processort_counter_scale = 0;
717+#endif
718+ inline uint64_t getTimeInSec()
719+ {
720+ uint64_t proc_counter_value = getProcTimestampCounter();
721+ return proc_counter_value * processort_counter_scale;
722+ }
723+
724+ inline uint64_t getTimeInMilliSec()
725+ {
726+ uint64_t proc_counter_value = getProcTimestampCounter();
727+ return proc_counter_value * ONE_THOUSAND * processort_counter_scale;
728+ }
729+
730+ inline uint64_t getTimeInMicroSec()
731+ {
732+ uint64_t proc_counter_value = getProcTimestampCounter();
733+ return proc_counter_value * ONE_MILLION * processort_counter_scale;
734+ }
735+
736+ inline uint64_t getTimeInNanoSec()
737+ {
738+ uint64_t proc_counter_value = getProcTimestampCounter();
739+ return proc_counter_value * ONE_BILLION * processort_counter_scale;
740+ }
741+}
742+
743+namespace todimpl {
744+ inline uint64_t getTimeInNanoSec();
745+ inline uint64_t getTimeInMicroSec();
746+ inline uint64_t getTimeInMilliSec();
747+ inline uint64_t getTimeInSec();
748+
749+ inline uint64_t getTimeInMilliSec()
750+ {
751+ struct timeval cur_time;
752+ gettimeofday(&cur_time, NULL);
753+ return cur_time.tv_sec*ONE_THOUSAND + cur_time.tv_usec/ONE_THOUSAND;
754+ }
755+
756+ inline uint64_t getTimeInMicroSec()
757+ {
758+ struct timeval cur_time;
759+ gettimeofday(&cur_time, NULL);
760+ return cur_time.tv_sec*ONE_MILLION + cur_time.tv_usec;
761+ }
762+
763+ inline uint64_t getTimeInNanoSec()
764+ {
765+ struct timeval cur_time;
766+ gettimeofday(&cur_time, NULL);
767+ return cur_time.tv_sec*ONE_BILLION + cur_time.tv_usec*ONE_THOUSAND;
768+ }
769+
770+ inline uint64_t getTimeInSec()
771+ {
772+ struct timeval cur_time;
773+ gettimeofday(&cur_time, NULL);
774+ return cur_time.tv_sec*ONE_BILLION + cur_time.tv_usec*ONE_MILLION;
775+ }
776+}
777+
778+namespace clockimpl {
779+ inline uint64_t getTimeInNanoSec();
780+ inline uint64_t getTimeInMicroSec();
781+ inline uint64_t getTimeInMilliSec();
782+ inline uint64_t getTimeInSec();
783+ inline void getClockTime(struct timespec& tp);
784+
785+ inline uint64_t getTimeInNanoSec()
786+ {
787+ struct timespec tp;
788+ clock_gettime(CLOCK_REALTIME, &tp);
789+ return tp.tv_sec*ONE_BILLION + tp.tv_nsec;
790+ }
791+
792+ inline uint64_t getTimeInMicroSec()
793+ {
794+ struct timespec tp;
795+ clock_gettime(CLOCK_REALTIME, &tp);
796+ return (uint64_t)tp.tv_sec*ONE_MILLION + (uint64_t)tp.tv_nsec/ONE_THOUSAND;
797+ }
798+
799+ inline uint64_t getTimeInMilliSec()
800+ {
801+ struct timespec tp;
802+ clock_gettime(CLOCK_REALTIME, &tp);
803+ return (uint64_t)tp.tv_sec*ONE_THOUSAND + (uint64_t)tp.tv_nsec/ONE_MILLION;
804+ }
805+
806+ inline uint64_t getTimeInSec()
807+ {
808+ struct timespec tp;
809+ return (uint64_t)tp.tv_sec + (uint64_t)tp.tv_nsec/ONE_BILLION;
810+ }
811+
812+ inline void getClockTime(struct timespec& tp)
813+ {
814+#if defined(HAVE_CLOCK_GETTIME)
815+ clock_gettime(CLOCK_REALTIME, &tp);
816+#else
817+ tp.tv_sec = 0;
818+ tp.tv_nsec = 0;
819+ errmsg_printf(ERRMSG_LVL_ERROR,
820+ "clock_gettime is not supported on this platform."\
821+ "Please use different timer implementation");
822+#endif
823+ }
824+}
825+
826+#if defined(__GNUC__) && defined(__i386__)
827+#define HAVE_RTDC_IMPL
828+#elif defined(__GNUC__) && defined(__x86_64__)
829+#define HAVE_RTDC_IMPL
830+#endif
831+
832+inline bool useRtdcImpl()
833+{
834+#ifdef HAVE_RTDC_IMPL
835+ return true;
836+#else
837+ return false;
838+#endif
839+}
840+
841+inline bool useClockGetTimeImpl()
842+{
843+#ifdef HAVE_CLOCK_GETTIME
844+ return true;
845+#else
846+ return false;
847+#endif
848+}
849+
850+
851+#define GET_TIME(timerimpl, cur_time) { \
852+ switch( ePrecRange ) { \
853+ case eSecPrec: \
854+ cur_time = timerimpl::getTimeInSec(); \
855+ break; \
856+ case eMilliSecPrec: \
857+ cur_time = timerimpl::getTimeInMilliSec(); \
858+ break; \
859+ case eMicroSecPrec: \
860+ cur_time = timerimpl::getTimeInMicroSec(); \
861+ break; \
862+ case eNanoSecPrec: \
863+ cur_time = timerimpl::getTimeInNanoSec(); \
864+ break; \
865+ } \
866+ } \
867+
868+
869+
870+inline const char* getTimePrecToStr(int ePrecRange)
871+{
872+ switch(ePrecRange) {
873+ case eMilliSecPrec:
874+ return "milli sec";
875+ case eMicroSecPrec:
876+ return "micro sec";
877+ case eNanoSecPrec:
878+ return "nano sec";
879+ case eSecPrec:
880+ return "sec";
881+
882+ }
883+ return NULL;
884+}
885+/**
886+ * Class to capture timing information for C/C++ block
887+ * If opName is supplied, it adds this information to currect active Timing
888+ * profile object.
889+ * Following are some overhead information for this classes
890+ * eImplKind = eRtdcImpl (~50 ns on 2.7 GHz intel machine), This went to
891+ * average ~20 ns for large number of operations (1 million in my example)
892+ * eImplKind = eClockTimeImpl (~1000 ns on 2.7 GHz intel machine)
893+ * eImplKind = eGetToDImpl (~1500/2000 ns on 2.7 GHz intel machine)
894+ */
895+template<int eImplKind , int ePrecRange >
896+class AutoOpTimer {
897+public:
898+ explicit AutoOpTimer(const char* sOpName):opr_name(sOpName), begin_time(0)
899+ {
900+ acquire();
901+ }
902+
903+ void acquire()
904+ {
905+ switch( eImplKind )
906+ {
907+ case eGetToDImpl:
908+ GET_TIME(todimpl, begin_time);
909+ break;
910+ case eClockTimeImpl:
911+ GET_TIME(clockimpl, begin_time);
912+ break;
913+ case eRtdcImpl:
914+ GET_TIME(rtdcimpl, begin_time);
915+ break;
916+ }
917+ }
918+
919+ uint64_t getBgnTime() const
920+ {
921+ return begin_time;
922+ }
923+
924+ static uint64_t getCurTime()
925+ {
926+ uint64_t cur_time = 0;
927+ switch( eImplKind )
928+ {
929+ case eGetToDImpl:
930+ GET_TIME(todimpl, cur_time);
931+ break;
932+ case eClockTimeImpl:
933+ GET_TIME(clockimpl, cur_time);
934+ break;
935+ case eRtdcImpl:
936+ GET_TIME(rtdcimpl, cur_time);
937+ break;
938+ }
939+ return cur_time;
940+ }
941+
942+ uint64_t getTimeElapsed() const
943+ {
944+ uint64_t cur_time = getCurTime();
945+ uint64_t diff = (cur_time - begin_time) * (cur_time > begin_time);
946+ return diff;
947+ }
948+
949+ ~AutoOpTimer()
950+ {
951+ uint64_t uTimeElapsed = getTimeElapsed();
952+ if( opr_name ) {
953+ if( th_getProf() )
954+ th_getProf()->addOpTime(opr_name, uTimeElapsed);
955+ }
956+ }
957+private:
958+ const char* opr_name;
959+ uint64_t begin_time;
960+};
961+
962+//Rtdc based timer do not give reliable timing information.
963+//so by default they are off. One can use them directly if they want in
964+//CPU-bound operation by using following Rtdc Timers and setting
965+//ENABLE_RTDC_BASED_TIMER macro above.
966+typedef AutoOpTimer<eRtdcImpl, eNanoSecPrec> RtdcTimerNanoSecPrec;
967+typedef AutoOpTimer<eRtdcImpl, eMilliSecPrec> RtdcTimerMilliSecPrec;
968+typedef AutoOpTimer<eRtdcImpl, eMicroSecPrec> RtdcTimerMicroSecPrec;
969+typedef AutoOpTimer<eRtdcImpl, eSecPrec> RtdcTimerSecPrec;
970+
971+
972+#if defined(HAVE_RTDC_IMPL) && defined(ENABLE_RTDC_BASED_TIMER)
973+typedef AutoOpTimer<eRtdcImpl, eNanoSecPrec> FastTimerNanoSecPrec;
974+typedef AutoOpTimer<eRtdcImpl, eMilliSecPrec> FastTimerMilliSecPrec;
975+typedef AutoOpTimer<eRtdcImpl, eMicroSecPrec> FastTimerMicroSecPrec;
976+typedef AutoOpTimer<eRtdcImpl, eSecPrec> FastTimerSecPrec;
977+#elif defined(HAVE_CLOCK_GETTIME)
978+typedef AutoOpTimer<eClockTimeImpl, eNanoSecPrec> FastTimerNanoSecPrec;
979+typedef AutoOpTimer<eClockTimeImpl, eMilliSecPrec> FastTimerMilliSecPrec;
980+typedef AutoOpTimer<eClockTimeImpl, eMicroSecPrec> FastTimerMicroSecPrec;
981+typedef AutoOpTimer<eClockTimeImpl, eSecPrec> FastTimerSecPrec;
982+#else
983+typedef AutoOpTimer<eGetToDImpl, eNanoSecPrec> FastTimerNanoSecPrec;
984+typedef AutoOpTimer<eGetToDImpl, eMilliSecPrec> FastTimerMilliSecPrec;
985+typedef AutoOpTimer<eGetToDImpl, eMicroSecPrec> FastTimerMicroSecPrec;
986+typedef AutoOpTimer<eGetToDImpl, eSecPrec> FastTimerSecPrec;
987+#endif
988+
989+
990+uint64_t getSecTime()
991+{
992+ return FastTimerSecPrec::getCurTime();
993+}
994+
995+uint64_t getMilliSecTime()
996+{
997+ return FastTimerMilliSecPrec::getCurTime();
998+}
999+
1000+uint64_t getMicroSecTime()
1001+{
1002+ return FastTimerMicroSecPrec::getCurTime();
1003+}
1004+
1005+uint64_t getNanoSecTime()
1006+{
1007+ return FastTimerNanoSecPrec::getCurTime();
1008+}
1009+}/* namespace timer */
1010+}/*namespace drizzled*/
1011+
1012+
1013+#endif