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

[PrafullaT]

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 ?

[PrafullaT (prafulla-t)]

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.

[Monty Taylor (mordred)]

-----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-----

[lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring]

1701. By PrafullaT on 2010-08-18

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

1702. By PrafullaT on 2010-08-18

Merge from mainline branch.

1703. By PrafullaT on 2010-08-18

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 on 2010-08-18

Fixing some formatting issues.

1705. By PrafullaT on 2010-08-18

Some more formatting issues.

[Brian Aker (brianaker)]

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).

[PrafullaT (prafulla-t)]

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

[lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring]

1706. By PrafullaT on 2010-08-20

Merge from trunk

[Brian Aker (brianaker)]

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

[Monty Taylor (mordred)]

-----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-----

[lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring]

1707. By PrafullaT on 2010-08-21

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

1708. By PrafullaT on 2010-08-22

Chaning profiling to default off

1709. By PrafullaT on 2010-08-22

Merge from trunk

[PrafullaT (prafulla-t)]

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

[lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring]

1710. By PrafullaT on 2010-08-25

Making some changes to match up to drizzled coding standard

1711. By PrafullaT on 2010-08-25

Some more changes for coding standard

[Brian Aker (brianaker)]

(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 ?

[PrafullaT (prafulla-t)]

> 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

[lp:~prafulla-t/drizzle/drz-fast-timer-and-time-profile-refactoring]

1712. By PrafullaT on 2010-08-26

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

1713. By PrafullaT on 2010-08-26

Fixing build failure

[PrafullaT (prafulla-t)]

> > 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

[Stewart Smith (stewart)]

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

[Stewart Smith (stewart)]

(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 on 2010-08-26

Fixing build failure

1712. By PrafullaT on 2010-08-26

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

1711. By PrafullaT on 2010-08-25

Some more changes for coding standard

1710. By PrafullaT on 2010-08-25

Making some changes to match up to drizzled coding standard

1709. By PrafullaT on 2010-08-22

Merge from trunk

1708. By PrafullaT on 2010-08-22

Chaning profiling to default off

1707. By PrafullaT on 2010-08-21

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

1706. By PrafullaT on 2010-08-20

Merge from trunk

1705. By PrafullaT on 2010-08-18

Some more formatting issues.

1704. By PrafullaT on 2010-08-18

Fixing some formatting issues.

=== modified file 'drizzled/drizzled.cc'
--- drizzled/drizzled.cc	2010-08-24 01:36:17 +0000
+++ drizzled/drizzled.cc	2010-08-26 04:32:43 +0000
@@ -338,7 +338,6 @@
 boost::mutex LOCK_open;
 boost::mutex LOCK_global_system_variables;
 boost::mutex LOCK_thread_count;
-
 boost::condition_variable COND_refresh;
 boost::condition_variable COND_thread_count;
 pthread_t signal_thread;
 
=== modified file 'drizzled/filesort.cc'
--- drizzled/filesort.cc	2010-08-17 01:34:55 +0000
+++ drizzled/filesort.cc	2010-08-26 04:32:43 +0000
@@ -41,6 +41,8 @@
 #include "drizzled/internal/my_sys.h"
 #include "plugin/myisam/myisam.h"
 #include "drizzled/plugin/transactional_storage_engine.h"
+#include "drizzled/time_profile.h"
+
 
 using namespace std;
 
@@ -135,6 +137,8 @@
 		 optimizer::SqlSelect *select, ha_rows max_rows,
                  bool sort_positions, ha_rows *examined_rows)
 {
+  START_PROFILING_PHASE("filesort", "microsec");
+  BLOCK_MICRO_SEC_TIMER("filesort");
   int error;
   uint32_t memavl, min_sort_memory;
   uint32_t maxbuffer;
@@ -151,11 +155,14 @@
 
   DRIZZLE_FILESORT_START(table->getShare()->getSchemaName(), table->getShare()->getTableName());
 
-  /*
-   Release InnoDB's adaptive hash index latch (if holding) before
-   running a sort.
-  */
-  plugin::TransactionalStorageEngine::releaseTemporaryLatches(session);
+  {
+    BLOCK_MICRO_SEC_TIMER("innodb::releaselatches");
+    /*
+      Release InnoDB's adaptive hash index latch (if holding) before
+      running a sort.
+    */
+    plugin::TransactionalStorageEngine::releaseTemporaryLatches(session);
+  }
 
   /*
     Don't use table->sort in filesort as it is also used by
@@ -226,6 +233,7 @@
   else
 #endif
   {
+    BLOCK_MICRO_SEC_TIMER("estimateRowsUpperBound");
     records= table->cursor->estimate_rows_upper_bound();
     /*
       If number of records is not known, use as much of sort buffer
@@ -268,10 +276,12 @@
   param.keys--;  			/* TODO: check why we do this */
   param.sort_form= table;
   param.end=(param.local_sortorder=sortorder)+s_length;
+
   if ((records=find_all_keys(session, &param,select,sort_keys, &buffpek_pointers,
-			     &tempfile, selected_records_file)) ==
-      HA_POS_ERROR)
+                             &tempfile, selected_records_file)) ==   HA_POS_ERROR)
     goto err;
+  
+  
   maxbuffer= (uint32_t) (my_b_tell(&buffpek_pointers)/sizeof(*buffpek));
 
   if (maxbuffer == 0)			// The whole set is in memory
@@ -363,7 +373,7 @@
   DRIZZLE_FILESORT_DONE(error, records);
   return (error ? HA_POS_ERROR : records);
 } /* filesort */
-
+  
 
 void Table::filesort_free_buffers(bool full)
 {
@@ -421,6 +431,8 @@
 static unsigned char *read_buffpek_from_file(internal::IO_CACHE *buffpek_pointers, uint32_t count,
                                      unsigned char *buf)
 {
+
+  BLOCK_MICRO_SEC_TIMER("read_buffpek_from_file");
   uint32_t length= sizeof(buffpek_st)*count;
   unsigned char *tmp= buf;
   if (count > UINT_MAX/sizeof(buffpek_st))
@@ -484,6 +496,7 @@
 			     internal::IO_CACHE *buffpek_pointers,
 			     internal::IO_CACHE *tempfile, internal::IO_CACHE *indexfile)
 {
+  BLOCK_MICRO_SEC_TIMER("find_all_keys");
   int error,flag,quick_select;
   uint32_t idx,indexpos,ref_length;
   unsigned char *ref_pos,*next_pos,ref_buff[MAX_REFLENGTH];
@@ -540,6 +553,7 @@
   {
     if (quick_select)
     {
+      BLOCK_MICRO_SEC_TIMER("quick_select_read");
       if ((error= read_record_info.read_record(&read_record_info)))
       {
         error= HA_ERR_END_OF_FILE;
@@ -551,6 +565,7 @@
     {
       if (indexfile)
       {
+        BLOCK_MICRO_SEC_TIMER("index_file_read");
 	if (my_b_read(indexfile,(unsigned char*) ref_pos,ref_length))
 	{
 	  error= errno ? errno : -1;		/* Abort */
@@ -560,6 +575,7 @@
       }
       else
       {
+        BLOCK_MICRO_SEC_TIMER("raw_read");
 	error=file->rnd_next(sort_form->getInsertRecord());
 
 	if (!flag)
@@ -663,6 +679,7 @@
 write_keys(SORTPARAM *param, register unsigned char **sort_keys, uint32_t count,
            internal::IO_CACHE *buffpek_pointers, internal::IO_CACHE *tempfile)
 {
+  BLOCK_MICRO_SEC_TIMER("write_keys");
   size_t sort_length, rec_length;
   unsigned char **end;
   buffpek_st buffpek;
@@ -699,6 +716,7 @@
 
 static inline void store_length(unsigned char *to, uint32_t length, uint32_t pack_length)
 {
+  BLOCK_MICRO_SEC_TIMER("store_length");
   switch (pack_length) {
   case 1:
     *to= (unsigned char) length;
@@ -721,6 +739,7 @@
 static void make_sortkey(register SORTPARAM *param,
 			 register unsigned char *to, unsigned char *ref_pos)
 {
+  BLOCK_MICRO_SEC_TIMER("make_sortkey");
   Field *field;
   SortField *sort_field;
   size_t length;
@@ -954,6 +973,7 @@
 
 static void register_used_fields(SORTPARAM *param)
 {
+  BLOCK_MICRO_SEC_TIMER("register_used_fields");
   SortField *sort_field;
   Table *table=param->sort_form;
 
@@ -992,6 +1012,7 @@
 static bool save_index(SORTPARAM *param, unsigned char **sort_keys, uint32_t count,
                        filesort_info_st *table_sort)
 {
+  BLOCK_MICRO_SEC_TIMER("save_index");
   uint32_t offset,res_length;
   unsigned char *to;
 
@@ -1017,6 +1038,7 @@
 int merge_many_buff(SORTPARAM *param, unsigned char *sort_buffer,
 		    buffpek_st *buffpek, uint32_t *maxbuffer, internal::IO_CACHE *t_file)
 {
+  BLOCK_MICRO_SEC_TIMER("merge_many_buf");
   register uint32_t i;
   internal::IO_CACHE t_file2,*from_file,*to_file,*temp;
   buffpek_st *lastbuff;
@@ -1074,6 +1096,7 @@
 uint32_t read_to_buffer(internal::IO_CACHE *fromfile, buffpek_st *buffpek,
                         uint32_t rec_length)
 {
+  BLOCK_MICRO_SEC_TIMER("read_to_buffer");
   register uint32_t count;
   uint32_t length;
 
@@ -1130,6 +1153,7 @@
                   buffpek_st *lastbuff, buffpek_st *Fb, buffpek_st *Tb,
                   int flag)
 {
+  BLOCK_MICRO_SEC_TIMER("merge_buffers");
   int error;
   uint32_t rec_length,res_length,offset;
   size_t sort_length;
@@ -1336,6 +1360,7 @@
 		       buffpek_st *buffpek, uint32_t maxbuffer,
 		       internal::IO_CACHE *tempfile, internal::IO_CACHE *outfile)
 {
+  BLOCK_MICRO_SEC_TIMER("merge_index");
   if (merge_buffers(param,tempfile,outfile,sort_buffer,buffpek,buffpek,
 		    buffpek+maxbuffer,1))
     return(1);
@@ -1570,6 +1595,7 @@
 static void
 unpack_addon_fields(struct sort_addon_field_st *addon_field, unsigned char *buff)
 {
+  BLOCK_MICRO_SEC_TIMER("unpack_addon_fields");
   Field *field;
   sort_addon_field_st *addonf= addon_field;
 
@@ -1594,6 +1620,7 @@
 
 void change_double_for_sort(double nr,unsigned char *to)
 {
+  BLOCK_MICRO_SEC_TIMER("change_double_for_sort");
   unsigned char *tmp=(unsigned char*) to;
   if (nr == 0.0)
   {						/* Change to zero string */
 
=== modified file 'drizzled/include.am'
--- drizzled/include.am	2010-08-20 18:39:24 +0000
+++ drizzled/include.am	2010-08-26 04:32:43 +0000
@@ -428,6 +428,7 @@
 			      drizzled/temporal_interval.h \
 			      drizzled/thr_lock.h \
 			      drizzled/time_functions.h \
+			      drizzled/time_profile.h	 \
 			      drizzled/tmp_table_param.h \
 			      drizzled/transaction_context.h \
 			      drizzled/transaction_services.h \
 
=== modified file 'drizzled/optimizer/range.cc'
--- drizzled/optimizer/range.cc	2010-08-06 11:21:12 +0000
+++ drizzled/optimizer/range.cc	2010-08-26 04:32:43 +0000
@@ -132,6 +132,7 @@
 #include "drizzled/records.h"
 #include "drizzled/internal/my_sys.h"
 #include "drizzled/internal/iocache.h"
+#include "drizzled/time_profile.h"
 
 #include "drizzled/temporal.h" /* Needed in get_mm_leaf() for timestamp -> datetime comparisons */
 
@@ -420,6 +421,7 @@
 
 bool optimizer::SqlSelect::skip_record()
 {
+  BLOCK_MICRO_SEC_TIMER("optimizer::SqlSelect::skip_record");
   return (cond ? cond->val_int() == 0 : 0);
 }
 
 
=== modified file 'drizzled/session.cc'
--- drizzled/session.cc	2010-08-24 16:45:09 +0000
+++ drizzled/session.cc	2010-08-26 04:32:43 +0000
@@ -47,6 +47,7 @@
 #include "drizzled/pthread_globals.h"
 #include "drizzled/transaction_services.h"
 #include "drizzled/drizzled.h"
+#include "drizzled/time_profile.h"
 
 #include "drizzled/table_share_instance.h"
 
@@ -160,6 +161,7 @@
   scheduler(NULL),
   scheduler_arg(NULL),
   lock_id(&main_lock_id),
+  pThreadProfile(NULL),
   user_time(0),
   ha_data(plugin::num_trx_monitored_objects),
   arg_of_last_insert_id_function(false),
@@ -254,7 +256,7 @@
   thr_lock_owner_init(&main_lock_id, &lock_info);
 
   m_internal_handler= NULL;
-  
+  pThreadProfile = new drizzled::timer::ThreadProfile();
   plugin::EventObserver::registerSessionEvents(*this); 
 }
 
@@ -391,7 +393,10 @@
   pthread_setspecific(THR_Session,  0);
 
   plugin::Logging::postEndDo(this);
-  plugin::EventObserver::deregisterSessionEvents(*this); 
+  plugin::EventObserver::deregisterSessionEvents(*this);
+
+  delete pThreadProfile;
+  pThreadProfile = NULL;
 
   /* Ensure that no one is using Session */
   LOCK_delete.unlock();
 
=== modified file 'drizzled/session.h'
--- drizzled/session.h	2010-08-24 16:45:09 +0000
+++ drizzled/session.h	2010-08-26 04:32:43 +0000
@@ -80,6 +80,11 @@
 struct st_my_thread_var;
 }
 
+namespace timer
+{
+class ThreadProfile;
+}
+
 class Lex_input_stream;
 class user_var_entry;
 class CopyField;
@@ -418,7 +423,18 @@
   struct system_status_var status_var; /**< Session-local status counters */
   THR_LOCK_INFO lock_info; /**< Locking information for this session */
   THR_LOCK_OWNER main_lock_id; /**< To use for conventional queries */
-  THR_LOCK_OWNER *lock_id; /**< If not main_lock_id, points to the lock_id of a cursor. */
+  THR_LOCK_OWNER *lock_id; /**< If not main_lock_id, points to the lock_id of a
+                            *cursor. */
+
+  /**
+   ThreadProfile class has been created to handle time-profiling related
+   information for individual threads.(so as to reduce complexity of mutex etc
+   in writing profiling classes) This is currenly hung off session object
+   assuming it would be there per connection.  Other alternative is to create
+   pthread_key_t specifically for profiling and put object of threadProfile
+   class there.
+  */
+  timer::ThreadProfile* pThreadProfile; /**< Data structure required for time profiling*/
 private:
   boost::mutex LOCK_delete; /**< Locked before session is deleted */
 public:
@@ -432,7 +448,10 @@
   {
     LOCK_delete.unlock();
   }
-
+  timer::ThreadProfile& getThreadProfile() const {
+    return *pThreadProfile;
+  }
+  
   /**
    * A peek into the query string for the session. This is a best effort
    * delivery, there is no guarantee whether the content is meaningful.
 
=== modified file 'drizzled/sql_parse.cc'
--- drizzled/sql_parse.cc	2010-08-24 16:45:09 +0000
+++ drizzled/sql_parse.cc	2010-08-26 04:32:43 +0000
@@ -41,6 +41,7 @@
 #include "drizzled/probes.h"
 #include "drizzled/session_list.h"
 #include "drizzled/global_charset_info.h"
+#include "drizzled/time_profile.h"
 
 #include "drizzled/plugin/logging.h"
 #include "drizzled/plugin/query_rewrite.h"
@@ -214,6 +215,7 @@
   }
   case COM_QUERY:
   {
+    START_PROFILING_PHASE("query", "microsec");
     if (! session->readAndStoreQuery(packet, packet_length))
       break;					// fatal error is set
     DRIZZLE_QUERY_START(session->query.c_str(),
@@ -222,7 +224,16 @@
 
     plugin::QueryRewriter::rewriteQuery(session->db, session->query);
     mysql_parse(session, session->query.c_str(), session->query.length());
-
+#if 0
+    stringstream ss;
+    GET_ALL_PROFILING_RESULT(ss);
+    errmsg_printf(ERRMSG_LVL_DBUG,
+                  "--------------------Profile Output------------------\n");
+    errmsg_printf(ERRMSG_LVL_DBUG,"Command : %s\n", session->query.c_str());
+    errmsg_printf(ERRMSG_LVL_DBUG,ss.str().c_str());
+    errmsg_printf(ERRMSG_LVL_DBUG,
+                  "---------------------------x------------------------\n");
+#endif    
     break;
   }
   case COM_QUIT:
@@ -716,6 +727,7 @@
 
 void mysql_parse(Session *session, const char *inBuf, uint32_t length)
 {
+  drizzled::timer::FastTimerMicroSecPrec autoObj("mysql_parse");
   uint64_t start_time= my_getsystime();
   lex_start(session);
   session->reset_for_next_command();
 
=== modified file 'drizzled/sql_select.cc'
--- drizzled/sql_select.cc	2010-08-21 04:05:07 +0000
+++ drizzled/sql_select.cc	2010-08-26 04:32:43 +0000
@@ -6594,8 +6594,6 @@
   /* QQ: session may not be set for sub queries, but this should be fixed */
   if(not session)
     session= current_session;
-
-
   str->append(STRING_WITH_LEN("select "));
 
   /* First add options */
 
=== added file 'drizzled/time_profile.h'
--- drizzled/time_profile.h	1970-01-01 00:00:00 +0000
+++ drizzled/time_profile.h	2010-08-26 04:32:43 +0000
@@ -0,0 +1,614 @@
+/* -*- mode: c++; c-basic-offset: 2; indent-tabs-mode: nil; -*-
+ *  vim:expandtab:shiftwidth=2:tabstop=2:smarttab:
+ *
+ *  Copyright (C) 2010 Prafulla Tekawade
+ *
+ *  This program is free software; you can redistribute it and/or modify
+ *  it under the terms of the GNU General Public License as published by
+ *  the Free Software Foundation; version 2 of the License.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU General Public License for more details.
+ *
+ *  You should have received a copy of the GNU General Public License
+ *  along with this program; if not, write to the Free Software
+ *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+
+#ifndef DRIZZLED_TIME_PROFILE_H
+#define DRIZZLED_TIME_PROFILE_H
+
+#include "drizzled/drizzle_time.h"
+#if TIME_WITH_SYS_TIME
+#include <sys/time.h>
+#include <time.h>
+#else
+#if HAVE_SYS_TIME_H
+#include <sys/time.h>
+#else
+#include <time.h>
+#endif
+
+#endif
+
+#include <iostream>
+#include <stdint.h>
+#include <math.h>
+#include <stdio.h>
+#include <cassert>
+#include <map>
+#include <stack>
+#include <sstream>
+#include <iostream>
+#include "drizzled/session.h"
+#include "drizzled/errmsg_print.h"
+
+#define ONE_BILLION  1000000000ULL
+#define ONE_MILLION  1000000
+#define ONE_THOUSAND 1000
+
+
+#if 0
+#define ENABLE_RTDC_BASED_TIMER
+#endif
+
+
+//Set this to 1, if you want to profile the code.
+#if 1
+#define TIME_PROFILE_ON 1
+#endif
+
+#define _CONCAT(a,b) a ## b
+#define CONCAT(a,b) _CONCAT(a, b)
+
+namespace drizzled  {
+namespace timer  {
+  
+inline uint64_t getSecTime();
+inline uint64_t getMicroSecTime();
+inline uint64_t getNanoSecTime();
+inline uint64_t getMilliSecTime();
+
+inline ThreadProfile& thp();
+inline void th_pushProfilePhase(const char* sPhaseName,
+                                const char* sScale);
+inline void th_popProfilePhase();
+inline bool useRtdcImpl();
+inline bool useClockGetTimeImpl();
+inline const char* getTimePrecToStr(int ePrecRange);
+
+
+enum
+{
+  eRtdcImpl = 0,
+  eClockTimeImpl,
+  eGetToDImpl
+};
+
+enum
+{
+  eSecPrec = 0,
+  eMilliSecPrec,
+  eMicroSecPrec,
+  eNanoSecPrec
+};
+
+#ifdef TIME_PROFILE_ON
+
+#define BLOCK_NANO_SEC_TIMER(sBlockName) drizzled::timer::FastTimerNanoSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
+#define BLOCK_MICRO_SEC_TIMER(sBlockName) drizzled::timer::FastTimerMicroSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
+#define BLOCK_MILLI_SEC_TIMER(sBlockName) drizzled::timer::FastTimerMilliSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
+#define BLOCK_SEC_TIMER(sBlockName) drizzled::timer::FastTimerSecPrec CONCAT(autoObj, __LINE__ )(sBlockName);
+
+#define START_PROFILING_PHASE(name, scale)                              \
+  drizzled::timer::th_pushProfilePhase(name, scale);                    \
+  drizzled::timer::AutoProfPhase autoPhase;
+  
+
+#define GET_ALL_PROFILING_RESULT(outputStream) drizzled::timer::thp().printAllOpTime(outputStream);
+
+#else
+
+#define START_PROFILING_PHASE(name, scale) 
+#define END_PROFILING_AND_COLLECT_RESULT(outputStream)
+#define BLOCK_NANO_SEC_TIMER(sBlockName)
+#define BLOCK_MICRO_SEC_TIMER(sBlockName)
+#define BLOCK_MILLI_SEC_TIMER(sBlockName)
+#define BLOCK_SEC_TIMER(sBlockName) 
+#define GET_ALL_PROFILING_RESULT(outputStream)
+
+
+#endif
+  
+class TimeProfile
+{
+private:
+  typedef std::pair<uint64_t, uint64_t> AccOccTimePair;
+  typedef std::map<std::string, AccOccTimePair> OpTimeMap;
+public:
+
+  TimeProfile():prof_name("{NoProfileName}"),
+                scale("NoScale")
+  { }
+  TimeProfile(const char* _prof_name,
+              const char* _scale) : prof_name(_prof_name),
+                                    scale(_scale)
+  { }
+
+  void addOpTime(const char* name, uint64_t time)
+  {
+    std::pair<OpTimeMap::iterator, bool> ins_res_pair =
+      opTimeMap.insert(std::make_pair(name, std::make_pair(time,1)));
+
+    if( !ins_res_pair.second ) { //If opName already exists, accumulate numTime
+                               //and increament occ counter.      
+      (ins_res_pair.first)->second.first += time;
+      (ins_res_pair.first)->second.second++;
+    }
+  }
+  
+  void printOpTime(std::ostream& oss)
+  {
+    OpTimeMap::iterator itr = opTimeMap.begin();
+    oss << prof_name << std::endl;
+    oss << "{" << std::endl;
+    while( itr != opTimeMap.end() )
+    {
+      oss << itr->first;
+      oss << ", acc= " << itr->second.first << " " <<  scale;
+      oss << ", occ=" << itr->second.second << std::endl;
+      itr++;
+    }
+    oss << "}" << std::endl;
+  }
+
+private:
+  OpTimeMap opTimeMap;
+  const char* prof_name;
+  const char* scale;
+};
+
+
+class ThreadProfile
+{
+public:
+
+  ThreadProfile():time_profile_stack(),
+                  profile_data() { }
+  ~ThreadProfile() { }
+  
+  TimeProfile* cur()
+  {
+    if( time_profile_stack.empty() )
+      return NULL;
+    return &(time_profile_stack.top());
+  }
+  void pushProfilePhase(const char* sPhaseName, const char* sScale)
+  {
+    time_profile_stack.push(TimeProfile(sPhaseName, sScale));
+  }
+
+  void popProfilePhase()
+  {
+    if( time_profile_stack.empty() )
+      return;
+    time_profile_stack.pop();
+  }
+  
+  void printAllOpTime(std::ostream& oss)
+  {
+    while( !time_profile_stack.empty() )
+    {
+      time_profile_stack.top().printOpTime(oss);
+      oss << std::endl;
+      time_profile_stack.pop();
+    }
+    std::vector<std::string>::const_iterator it = profile_data.begin();
+    while(it != profile_data.end())
+    {
+      oss << *it;
+      oss << std::endl;
+      it++;
+    }
+    profile_data.clear();
+  }
+
+  void saveProfileData(const char* pData)
+  {
+    std::string sStr(pData);
+    if( sStr.length() )
+      profile_data.push_back(sStr);
+  }
+private:
+  std::stack<TimeProfile> time_profile_stack;
+  std::vector<std::string> profile_data;
+};
+ 
+  
+inline ThreadProfile& thp()
+{
+  return current_session->getThreadProfile();
+}
+
+inline TimeProfile* th_getProf()
+{
+  return thp().cur();
+}
+
+inline void th_pushProfilePhase(const char* sPhaseName,
+                         const char* sScale)
+{
+  thp().pushProfilePhase(sPhaseName, sScale);
+}
+
+inline void th_popProfilePhase()
+{
+  thp().popProfilePhase();
+}
+
+  
+class AutoProfPhase
+{
+public:
+  explicit AutoProfPhase()
+  { }
+  void popAndSaveProfileData() const
+  {
+    std::stringstream ss;                                                    
+    if( th_getProf() )                                 
+      th_getProf()->printOpTime(ss);                   
+    th_popProfilePhase();                              
+    thp().saveProfileData(ss.str().c_str());                            
+  }
+
+  ~AutoProfPhase() {
+    popAndSaveProfileData();
+  }
+};
+
+
+namespace rtdcimpl  {
+
+  inline uint64_t getTimeInNanoSec();
+  inline uint64_t getTimeInMicroSec();
+  inline uint64_t getTimeInMilliSec();
+  inline uint64_t getTimeInSec();
+  inline uint64_t getProcTimestampCounter();
+  inline double getProcTimerstampScale();
+  
+  inline uint64_t getProcTimestampCounter()
+  {
+    uint64_t cur_time_cntr;
+#if defined(__GNUC__) && defined(__i386__)
+    asm volatile("rdtsc":"=A"(cur_time_cntr));
+#elif defined(__GNUC__) && defined(__x86_64__)
+    uint64_t hi, lo;
+    asm volatile("rdtc":"=a"(hi), "=d"(lo));
+    cur_time_cntr = (((uint64_t)hi << 32) || lo);
+#else
+    cur_time_cntr = 0;
+    assert(!"Aborted: rdtsc unimplemented for this configuration.");
+#endif
+    return cur_time_cntr;;
+  }
+  
+  //Calculating how many seconds are spent in a tick
+  //so that we can use this information to get nano/milli/micro secs
+  inline double getProcTimerstampScale()
+  {
+    int seconds_to_test = 2;
+    uint64_t delta_time = 0, retry_num = 3;
+    do
+    {
+      uint64_t beforeTime = getProcTimestampCounter();
+      sleep(seconds_to_test);
+      delta_time = getProcTimestampCounter() - beforeTime;
+    } while(retry_num-- && delta_time > 0);
+    if (delta_time <= 0 )
+      return 0;
+    double scale = (double)seconds_to_test/delta_time;
+    return scale;
+  }
+#ifdef ENABLE_RTDC_BASED_TIMER
+  static double processort_counter_scale = getProcTimerstampScale();
+#else
+  static double processort_counter_scale = 0;
+#endif
+  inline uint64_t getTimeInSec()
+  {
+    uint64_t proc_counter_value = getProcTimestampCounter();
+    return proc_counter_value * processort_counter_scale;
+  }
+  
+  inline uint64_t getTimeInMilliSec()
+  {
+    uint64_t proc_counter_value = getProcTimestampCounter();
+    return proc_counter_value * ONE_THOUSAND * processort_counter_scale;
+  }
+  
+  inline uint64_t getTimeInMicroSec()
+  {
+    uint64_t proc_counter_value = getProcTimestampCounter();
+    return proc_counter_value * ONE_MILLION * processort_counter_scale;
+  }
+  
+  inline uint64_t getTimeInNanoSec()
+  {
+    uint64_t proc_counter_value = getProcTimestampCounter();
+    return proc_counter_value * ONE_BILLION * processort_counter_scale;
+  }
+}
+
+namespace todimpl {
+  inline uint64_t getTimeInNanoSec();
+  inline uint64_t getTimeInMicroSec();
+  inline uint64_t getTimeInMilliSec();
+  inline uint64_t getTimeInSec();
+  
+  inline uint64_t getTimeInMilliSec()
+  {
+    struct timeval cur_time;
+    gettimeofday(&cur_time, NULL);
+    return cur_time.tv_sec*ONE_THOUSAND + cur_time.tv_usec/ONE_THOUSAND;
+  }
+  
+  inline uint64_t getTimeInMicroSec()
+  {
+    struct timeval cur_time;
+    gettimeofday(&cur_time, NULL);
+    return cur_time.tv_sec*ONE_MILLION + cur_time.tv_usec;
+  }
+
+  inline uint64_t getTimeInNanoSec()
+  {
+    struct timeval cur_time;
+    gettimeofday(&cur_time, NULL);
+    return cur_time.tv_sec*ONE_BILLION + cur_time.tv_usec*ONE_THOUSAND;
+  }
+
+  inline uint64_t getTimeInSec()
+  {
+    struct timeval cur_time;
+    gettimeofday(&cur_time, NULL);
+    return cur_time.tv_sec*ONE_BILLION + cur_time.tv_usec*ONE_MILLION;
+  }
+}
+
+namespace clockimpl {
+  inline uint64_t getTimeInNanoSec();
+  inline uint64_t getTimeInMicroSec();
+  inline uint64_t getTimeInMilliSec();
+  inline uint64_t getTimeInSec();
+  inline void getClockTime(struct timespec& tp);
+  
+  inline uint64_t getTimeInNanoSec()
+  {
+    struct timespec tp;
+    clock_gettime(CLOCK_REALTIME, &tp);
+    return tp.tv_sec*ONE_BILLION + tp.tv_nsec;
+  }
+
+  inline uint64_t getTimeInMicroSec()
+  {
+    struct timespec tp;
+    clock_gettime(CLOCK_REALTIME, &tp);
+    return (uint64_t)tp.tv_sec*ONE_MILLION + (uint64_t)tp.tv_nsec/ONE_THOUSAND;
+  }
+  
+  inline uint64_t getTimeInMilliSec()
+  {
+    struct timespec tp;
+    clock_gettime(CLOCK_REALTIME, &tp);
+    return (uint64_t)tp.tv_sec*ONE_THOUSAND + (uint64_t)tp.tv_nsec/ONE_MILLION;
+  }
+
+  inline uint64_t getTimeInSec()
+  {
+    struct timespec tp;
+    return (uint64_t)tp.tv_sec + (uint64_t)tp.tv_nsec/ONE_BILLION;
+  }
+
+  inline void getClockTime(struct timespec& tp)
+  {
+#if defined(HAVE_CLOCK_GETTIME)
+    clock_gettime(CLOCK_REALTIME, &tp);
+#else
+    tp.tv_sec = 0;
+    tp.tv_nsec = 0;
+    errmsg_printf(ERRMSG_LVL_ERROR,
+                  "clock_gettime is not supported on this platform."\
+                  "Please use different timer implementation");
+#endif
+  }
+}
+
+#if defined(__GNUC__) && defined(__i386__)
+#define HAVE_RTDC_IMPL
+#elif defined(__GNUC__) && defined(__x86_64__)
+#define HAVE_RTDC_IMPL
+#endif
+  
+inline bool useRtdcImpl()
+{
+#ifdef HAVE_RTDC_IMPL
+  return true;
+#else
+  return false;
+#endif
+}
+
+inline bool useClockGetTimeImpl()
+{
+#ifdef HAVE_CLOCK_GETTIME
+  return true;
+#else
+  return false;
+#endif
+}
+
+    
+#define GET_TIME(timerimpl, cur_time)   {        \
+    switch( ePrecRange ) {                      \
+    case eSecPrec:                              \
+      cur_time = timerimpl::getTimeInSec();      \
+      break;                                    \
+    case eMilliSecPrec:                         \
+      cur_time = timerimpl::getTimeInMilliSec(); \
+      break;                                    \
+    case eMicroSecPrec:                         \
+      cur_time = timerimpl::getTimeInMicroSec(); \
+      break;                                    \
+    case eNanoSecPrec:                          \
+      cur_time = timerimpl::getTimeInNanoSec();  \
+      break;                                    \
+    }                                           \
+  }                                             \
+
+
+
+inline const char* getTimePrecToStr(int ePrecRange)
+{
+  switch(ePrecRange) {
+  case eMilliSecPrec:
+    return "milli sec";
+  case eMicroSecPrec:
+    return "micro sec";
+  case eNanoSecPrec:
+    return "nano sec";
+  case eSecPrec:
+    return "sec";
+
+  }
+  return NULL;
+}
+/**
+ * Class to capture timing information for C/C++ block
+ * If opName is supplied, it adds this information to currect active Timing
+ * profile object.
+ * Following are some overhead information for this classes
+ * eImplKind = eRtdcImpl (~50 ns on 2.7 GHz intel machine), This went to
+ *             average ~20 ns for large number of operations (1 million in my example)
+ * eImplKind = eClockTimeImpl (~1000 ns on 2.7 GHz intel machine)
+ * eImplKind = eGetToDImpl  (~1500/2000 ns on 2.7 GHz intel machine)
+ */
+template<int eImplKind , int ePrecRange >
+class AutoOpTimer {
+public:
+  explicit AutoOpTimer(const char* sOpName):opr_name(sOpName), begin_time(0)
+  {
+    acquire();
+  }
+
+  void acquire()
+  {
+    switch( eImplKind )
+    {
+    case eGetToDImpl:
+      GET_TIME(todimpl, begin_time);
+      break;        
+    case eClockTimeImpl:
+      GET_TIME(clockimpl, begin_time);
+      break;
+    case eRtdcImpl:
+      GET_TIME(rtdcimpl, begin_time);
+      break;
+    }
+  }
+
+  uint64_t getBgnTime() const
+  {
+    return begin_time;
+  }
+
+  static uint64_t getCurTime()
+  {
+    uint64_t cur_time = 0;
+    switch( eImplKind )
+    {
+    case eGetToDImpl:
+      GET_TIME(todimpl, cur_time);
+      break;        
+    case eClockTimeImpl:
+      GET_TIME(clockimpl, cur_time);
+      break;
+    case eRtdcImpl:
+      GET_TIME(rtdcimpl, cur_time);
+      break;
+    }
+    return cur_time;
+  }
+
+  uint64_t getTimeElapsed() const
+  {
+    uint64_t cur_time = getCurTime();
+    uint64_t diff = (cur_time - begin_time) * (cur_time > begin_time);
+    return diff;
+  }
+    
+  ~AutoOpTimer()
+  {
+    uint64_t uTimeElapsed = getTimeElapsed();
+    if( opr_name ) {
+      if( th_getProf() )
+        th_getProf()->addOpTime(opr_name, uTimeElapsed);
+    }
+  }
+private:
+  const char* opr_name;
+  uint64_t begin_time;
+};
+
+//Rtdc based timer do not give reliable timing information.
+//so by default they are off. One can use them directly if they want in
+//CPU-bound operation by using following Rtdc Timers and setting
+//ENABLE_RTDC_BASED_TIMER macro above.
+typedef AutoOpTimer<eRtdcImpl, eNanoSecPrec> RtdcTimerNanoSecPrec;
+typedef AutoOpTimer<eRtdcImpl, eMilliSecPrec> RtdcTimerMilliSecPrec;
+typedef AutoOpTimer<eRtdcImpl, eMicroSecPrec> RtdcTimerMicroSecPrec;
+typedef AutoOpTimer<eRtdcImpl, eSecPrec> RtdcTimerSecPrec;
+
+
+#if defined(HAVE_RTDC_IMPL) && defined(ENABLE_RTDC_BASED_TIMER)
+typedef AutoOpTimer<eRtdcImpl, eNanoSecPrec> FastTimerNanoSecPrec;
+typedef AutoOpTimer<eRtdcImpl, eMilliSecPrec> FastTimerMilliSecPrec;
+typedef AutoOpTimer<eRtdcImpl, eMicroSecPrec> FastTimerMicroSecPrec;
+typedef AutoOpTimer<eRtdcImpl, eSecPrec> FastTimerSecPrec;
+#elif defined(HAVE_CLOCK_GETTIME)
+typedef AutoOpTimer<eClockTimeImpl, eNanoSecPrec> FastTimerNanoSecPrec;
+typedef AutoOpTimer<eClockTimeImpl, eMilliSecPrec> FastTimerMilliSecPrec;
+typedef AutoOpTimer<eClockTimeImpl, eMicroSecPrec> FastTimerMicroSecPrec;
+typedef AutoOpTimer<eClockTimeImpl, eSecPrec> FastTimerSecPrec;
+#else
+typedef AutoOpTimer<eGetToDImpl, eNanoSecPrec> FastTimerNanoSecPrec;
+typedef AutoOpTimer<eGetToDImpl, eMilliSecPrec> FastTimerMilliSecPrec;
+typedef AutoOpTimer<eGetToDImpl, eMicroSecPrec> FastTimerMicroSecPrec;
+typedef AutoOpTimer<eGetToDImpl, eSecPrec> FastTimerSecPrec;
+#endif
+
+  
+uint64_t getSecTime()
+{
+  return FastTimerSecPrec::getCurTime();
+}
+
+uint64_t getMilliSecTime()
+{
+  return FastTimerMilliSecPrec::getCurTime();
+}
+
+uint64_t getMicroSecTime()
+{
+  return FastTimerMicroSecPrec::getCurTime();
+}
+
+uint64_t getNanoSecTime()
+{
+  return FastTimerNanoSecPrec::getCurTime();
+}
+}/* namespace timer */
+}/*namespace drizzled*/
+
+
+#endif