- more mysqld.conf changes: skip-locking, default-character-set

[packages/mysql.git] / slow_extended.patch

# name       : slow_extended.patch
# introduced : 11 or before
# maintainer : Oleg
#
#!!! notice !!!
# Any small change to this file in the main branch
# should be done or reviewed by the maintainer!
diff -ruN a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp
--- a/include/mysql/plugin_audit.h.pp	2010-11-03 01:01:11.000000000 +0300
+++ b/include/mysql/plugin_audit.h.pp	2010-12-16 04:27:46.000000000 +0300
@@ -178,6 +178,16 @@
 char *thd_security_context(void* thd, char *buffer, unsigned int length,
                            unsigned int max_query_len);
 void thd_inc_row_count(void* thd);
+void increment_thd_innodb_stats(void* thd,
+                    unsigned long long trx_id,
+                    long io_reads,
+                    long long io_read,
+                    long io_reads_wait_timer,
+                    long lock_que_wait_timer,
+                    long que_wait_timer,
+                    long page_access);
+unsigned long thd_log_slow_verbosity(const void* thd);
+int thd_opt_slow_log();
 int mysql_tmpfile(const char *prefix);
 int thd_killed(const void* thd);
 unsigned long thd_get_thread_id(const void* thd);
diff -ruN a/include/mysql/plugin_auth.h.pp b/include/mysql/plugin_auth.h.pp
--- a/include/mysql/plugin_auth.h.pp	2010-11-03 01:01:11.000000000 +0300
+++ b/include/mysql/plugin_auth.h.pp	2010-12-16 04:27:46.000000000 +0300
@@ -178,6 +178,16 @@
 char *thd_security_context(void* thd, char *buffer, unsigned int length,
                            unsigned int max_query_len);
 void thd_inc_row_count(void* thd);
+void increment_thd_innodb_stats(void* thd,
+                    unsigned long long trx_id,
+                    long io_reads,
+                    long long io_read,
+                    long io_reads_wait_timer,
+                    long lock_que_wait_timer,
+                    long que_wait_timer,
+                    long page_access);
+unsigned long thd_log_slow_verbosity(const void* thd);
+int thd_opt_slow_log();
 int mysql_tmpfile(const char *prefix);
 int thd_killed(const void* thd);
 unsigned long thd_get_thread_id(const void* thd);
diff -ruN a/include/mysql/plugin_ftparser.h.pp b/include/mysql/plugin_ftparser.h.pp
--- a/include/mysql/plugin_ftparser.h.pp	2010-11-03 01:01:11.000000000 +0300
+++ b/include/mysql/plugin_ftparser.h.pp	2010-12-16 04:27:46.000000000 +0300
@@ -131,6 +131,16 @@
 char *thd_security_context(void* thd, char *buffer, unsigned int length,
                            unsigned int max_query_len);
 void thd_inc_row_count(void* thd);
+void increment_thd_innodb_stats(void* thd,
+                    unsigned long long trx_id,
+                    long io_reads,
+                    long long io_read,
+                    long io_reads_wait_timer,
+                    long lock_que_wait_timer,
+                    long que_wait_timer,
+                    long page_access);
+unsigned long thd_log_slow_verbosity(const void* thd);
+int thd_opt_slow_log();
 int mysql_tmpfile(const char *prefix);
 int thd_killed(const void* thd);
 unsigned long thd_get_thread_id(const void* thd);
diff -ruN a/include/mysql/plugin.h b/include/mysql/plugin.h
--- a/include/mysql/plugin.h	2010-11-03 01:01:11.000000000 +0300
+++ b/include/mysql/plugin.h	2010-12-16 04:27:46.000000000 +0300
@@ -536,6 +536,17 @@
 /* Increments the row counter, see THD::row_count */
 void thd_inc_row_count(MYSQL_THD thd);
 
+void increment_thd_innodb_stats(MYSQL_THD thd,
+                    unsigned long long trx_id,
+                    long io_reads,
+                    long long io_read,
+                    long io_reads_wait_timer,
+                    long lock_que_wait_timer,
+                    long que_wait_timer,
+                    long page_access);
+unsigned long thd_log_slow_verbosity(const MYSQL_THD thd);
+int thd_opt_slow_log();
+#define EXTENDED_SLOWLOG
 /**
   Create a temporary file.
 
diff -ruN a/patch_info/slow_extended.info b/patch_info/slow_extended.info
--- a/patch_info/slow_extended.info	1970-01-01 03:00:00.000000000 +0300
+++ b/patch_info/slow_extended.info	2010-12-16 04:27:46.000000000 +0300
@@ -0,0 +1,25 @@
+File=slow_extended.patch
+Name=Extended statistics in slow.log (not InnoDB part)
+Version=1.3
+Author=Percona <info@percona.com>
+License=GPL
+Comment=
+Changelog
+2008-11-26
+YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
+
+2008-11-07
+VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
+
+2008-11
+Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
+
+2010-07
+1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged)
+2) Control global slow feature merged (control_global_slow.patch merged)
+3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged)
+4) Now use_global_long_query_time and use_global_log_slow_control are synonims. Add value "all" for use_global_log_slow_control (contol-global_slow-2.patch merged)
+5) Fix innodb_stats on replication (Bug 600684)
+6) Change variable types (system/command-line)
+2010-01
+Patch profiling_slow.patch was merged
diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh
--- a/scripts/mysqldumpslow.sh	2010-11-03 01:01:13.000000000 +0300
+++ b/scripts/mysqldumpslow.sh	2010-12-16 04:27:46.000000000 +0300
@@ -101,8 +101,8 @@
     s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
     my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
 
-    s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
-    my ($t, $l, $r) = ($1, $2, $3);
+    s/^# Query_time: (\d+(\.\d+)?)  Lock_time: (\d+(\.\d+)?)  Rows_sent: (\d+(\.\d+)?).*\n//;
+    my ($t, $l, $r) = ($1, $3, $5);
     $t -= $l unless $opt{l};
 
     # remove fluff that mysqld writes to log when it (re)starts:
diff -ruN a/sql/event_scheduler.cc b/sql/event_scheduler.cc
--- a/sql/event_scheduler.cc	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/event_scheduler.cc	2010-12-16 04:27:46.000000000 +0300
@@ -195,6 +195,7 @@
   thd->client_capabilities|= CLIENT_MULTI_RESULTS;
   mysql_mutex_lock(&LOCK_thread_count);
   thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
+  thd->write_to_slow_log = TRUE;
   mysql_mutex_unlock(&LOCK_thread_count);
 
   /*
diff -ruN a/sql/filesort.cc b/sql/filesort.cc
--- a/sql/filesort.cc	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/filesort.cc	2010-12-16 04:27:46.000000000 +0300
@@ -193,6 +193,7 @@
   {
     status_var_increment(thd->status_var.filesort_scan_count);
   }
+  thd->query_plan_flags|= QPLAN_FILESORT;
 #ifdef CAN_TRUST_RANGE
   if (select && select->quick && select->quick->records > 0L)
   {
@@ -258,6 +259,7 @@
   }
   else
   {
+    thd->query_plan_flags|= QPLAN_FILESORT_DISK;
     if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
     {
       my_free(table_sort.buffpek);
@@ -1197,6 +1199,7 @@
   DBUG_ENTER("merge_buffers");
 
   status_var_increment(current_thd->status_var.filesort_merge_passes);
+  current_thd->query_plan_fsort_passes++;
   if (param->not_killable)
   {
     killed= &not_killable;
diff -ruN a/sql/log.cc b/sql/log.cc
--- a/sql/log.cc	2010-11-03 07:01:14.000000000 +0900
+++ b/sql/log.cc	2010-12-02 19:28:31.337989417 +0900
@@ -715,11 +715,13 @@
 */
 
 bool Log_to_csv_event_handler::
-  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
+  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
            const char *user_host, uint user_host_len,
            ulonglong query_utime, ulonglong lock_utime, bool is_command,
            const char *sql_text, uint sql_text_len)
 {
+  time_t current_time= my_time_possible_from_micro(current_utime);
+
   TABLE_LIST table_list;
   TABLE *table;
   bool result= TRUE;
@@ -935,14 +937,14 @@
 /** Wrapper around MYSQL_LOG::write() for slow log. */
 
 bool Log_to_file_event_handler::
-  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
+  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
            const char *user_host, uint user_host_len,
            ulonglong query_utime, ulonglong lock_utime, bool is_command,
            const char *sql_text, uint sql_text_len)
 {
   Silence_log_table_errors error_handler;
   thd->push_internal_handler(&error_handler);
-  bool retval= mysql_slow_log.write(thd, current_time, query_start_arg,
+  bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg,
                                     user_host, user_host_len,
                                     query_utime, lock_utime, is_command,
                                     sql_text, sql_text_len);
@@ -1216,7 +1218,7 @@
     /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
     user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
                              sctx->priv_user ? sctx->priv_user : "", "[",
-                             sctx->user ? sctx->user : "", "] @ ",
+                             sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ",
                              sctx->host ? sctx->host : "", " [",
                              sctx->ip ? sctx->ip : "", "]", NullS) -
                     user_host_buff);
@@ -1224,8 +1226,22 @@
     current_time= my_time_possible_from_micro(current_utime);
     if (thd->start_utime)
     {
-      query_utime= (current_utime - thd->start_utime);
-      lock_utime=  (thd->utime_after_lock - thd->start_utime);
+      if(current_utime < thd->start_utime)
+      {
+        query_utime= 0;
+      }
+      else
+      {
+        query_utime= (current_utime - thd->start_utime);
+      }
+      if(thd->utime_after_lock < thd->start_utime)
+      {
+        lock_utime= 0;
+      }
+      else
+      {
+        lock_utime= (thd->utime_after_lock - thd->start_utime);
+      }
     }
     else
     {
@@ -1239,8 +1255,20 @@
       query_length= command_name[thd->command].length;
     }
 
+    if (!query_length)
+    {
+      thd->sent_row_count= thd->examined_row_count= 0;
+      thd->sent_row_count= 0;
+      thd->bytes_sent_old= thd->status_var.bytes_sent;
+      thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
+      thd->tmp_tables_size= 0;
+      thd->innodb_was_used= FALSE;
+      thd->query_plan_flags= QPLAN_NONE;
+      thd->query_plan_fsort_passes= 0;
+    }
+
     for (current_handler= slow_log_handler_list; *current_handler ;)
-      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
+      error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
                                             user_host_buff, user_host_len,
                                             query_utime, lock_utime, is_command,
                                             query, query_length) || error;
@@ -2656,12 +2684,13 @@
     TRUE - error occured
 */
 
-bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
+bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
                             time_t query_start_arg, const char *user_host,
                             uint user_host_len, ulonglong query_utime,
                             ulonglong lock_utime, bool is_command,
                             const char *sql_text, uint sql_text_len)
 {
+  time_t current_time= my_time_possible_from_micro(current_utime);
   bool error= 0;
   DBUG_ENTER("MYSQL_QUERY_LOG::write");
 
@@ -2683,17 +2712,28 @@
 
     if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
     {
-      if (current_time != last_time)
+      if (opt_log_slow_timestamp_every || current_time != last_time)
       {
         last_time= current_time;
         struct tm start;
         localtime_r(&current_time, &start);
-
-        buff_len= my_snprintf(buff, sizeof buff,
-                              "# Time: %02d%02d%02d %2d:%02d:%02d\n",
-                              start.tm_year % 100, start.tm_mon + 1,
-                              start.tm_mday, start.tm_hour,
-                              start.tm_min, start.tm_sec);
+	if(opt_slow_query_log_microseconds_timestamp)
+	{
+	  ulonglong microsecond = current_utime % (1000 * 1000);
+	  buff_len= snprintf(buff, sizeof buff,
+	    "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
+            start.tm_year % 100, start.tm_mon + 1,
+	    start.tm_mday, start.tm_hour,
+	    start.tm_min, start.tm_sec,microsecond);
+	}
+	else
+	{
+	  buff_len= my_snprintf(buff, sizeof buff,
+	    "# Time: %02d%02d%02d %2d:%02d:%02d\n",
+            start.tm_year % 100, start.tm_mon + 1,
+	    start.tm_mday, start.tm_hour,
+	    start.tm_min, start.tm_sec);
+	}
 
         /* Note that my_b_write() assumes it knows the length for this */
         if (my_b_write(&log_file, (uchar*) buff, buff_len))
@@ -2711,12 +2751,69 @@
     sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
     sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
     if (my_b_printf(&log_file,
-                    "# Query_time: %s  Lock_time: %s"
-                    " Rows_sent: %lu  Rows_examined: %lu\n",
+                    "# Thread_id: %lu  Schema: %s  Last_errno: %u  Killed: %u\n" \
+                    "# Query_time: %s  Lock_time: %s  Rows_sent: %lu  Rows_examined: %lu  Rows_affected: %lu  Rows_read: %lu\n"
+                    "# Bytes_sent: %lu  Tmp_tables: %lu  Tmp_disk_tables: %lu  Tmp_table_sizes: %lu\n",
+                    (ulong) thd->thread_id, (thd->db ? thd->db : ""),
+                    thd->last_errno, (uint) thd->killed,
                     query_time_buff, lock_time_buff,
                     (ulong) thd->sent_row_count,
-                    (ulong) thd->examined_row_count) == (uint) -1)
+                    (ulong) thd->examined_row_count,
+                    ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
+                    (ulong) thd->sent_row_count,
+                    (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
+                    (ulong) thd->tmp_tables_used,
+                    (ulong) thd->tmp_tables_disk_used,
+                    (ulong) thd->tmp_tables_size) == (uint) -1)
       tmp_errno= errno;
+
+#if defined(ENABLED_PROFILING)
+    thd->profiling.print_current(&log_file);
+#endif
+    if (thd->innodb_was_used)
+    {
+      char buf[20];
+      snprintf(buf, 20, "%llX", thd->innodb_trx_id);
+      if (my_b_printf(&log_file,
+                    "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
+        tmp_errno=errno;
+    }
+    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
+         my_b_printf(&log_file,
+                    "# QC_Hit: %s  Full_scan: %s  Full_join: %s  Tmp_table: %s  Tmp_table_on_disk: %s\n" \
+                    "# Filesort: %s  Filesort_on_disk: %s  Merge_passes: %lu\n",
+                    ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
+                    ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
+                    ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
+                    ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
+                    ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
+                    ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
+                    ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
+                    thd->query_plan_fsort_passes) == (uint) -1)
+      tmp_errno=errno;
+    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
+    {
+      char buf[3][20];
+      snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
+      snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
+      snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
+      if (my_b_printf(&log_file,
+                      "#   InnoDB_IO_r_ops: %lu  InnoDB_IO_r_bytes: %lu  InnoDB_IO_r_wait: %s\n" \
+                      "#   InnoDB_rec_lock_wait: %s  InnoDB_queue_wait: %s\n" \
+                      "#   InnoDB_pages_distinct: %lu\n",
+                      (ulong) thd->innodb_io_reads,
+                      (ulong) thd->innodb_io_read,
+                      buf[0], buf[1], buf[2],
+                      (ulong) thd->innodb_page_access) == (uint) -1)
+        tmp_errno=errno;
+    } 
+    else
+    {
+      if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
+          my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
+        tmp_errno=errno;
+    }
+
     if (thd->db && strcmp(thd->db, db))
     {						// Database changed
       if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
diff -ruN a/sql/log.h b/sql/log.h
--- a/sql/log.h	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/log.h	2010-12-16 04:27:46.000000000 +0300
@@ -242,7 +242,7 @@
              uint user_host_len, int thread_id,
              const char *command_type, uint command_type_len,
              const char *sql_text, uint sql_text_len);
-  bool write(THD *thd, time_t current_time, time_t query_start_arg,
+  bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
              const char *user_host, uint user_host_len,
              ulonglong query_utime, ulonglong lock_utime, bool is_command,
              const char *sql_text, uint sql_text_len);
@@ -492,7 +492,7 @@
   virtual bool init()= 0;
   virtual void cleanup()= 0;
 
-  virtual bool log_slow(THD *thd, time_t current_time,
+  virtual bool log_slow(THD *thd, ulonglong current_time,
                         time_t query_start_arg, const char *user_host,
                         uint user_host_len, ulonglong query_utime,
                         ulonglong lock_utime, bool is_command,
@@ -521,7 +521,7 @@
   virtual bool init();
   virtual void cleanup();
 
-  virtual bool log_slow(THD *thd, time_t current_time,
+  virtual bool log_slow(THD *thd, ulonglong current_utime,
                         time_t query_start_arg, const char *user_host,
                         uint user_host_len, ulonglong query_utime,
                         ulonglong lock_utime, bool is_command,
@@ -553,7 +553,7 @@
   virtual bool init();
   virtual void cleanup();
 
-  virtual bool log_slow(THD *thd, time_t current_time,
+  virtual bool log_slow(THD *thd, ulonglong current_utime,
                         time_t query_start_arg, const char *user_host,
                         uint user_host_len, ulonglong query_utime,
                         ulonglong lock_utime, bool is_command,
diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
--- a/sql/mysqld.cc	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/mysqld.cc	2010-12-16 04:27:46.000000000 +0300
@@ -418,6 +418,10 @@
 char* opt_secure_file_priv;
 my_bool opt_log_slow_admin_statements= 0;
 my_bool opt_log_slow_slave_statements= 0;
+my_bool opt_log_slow_sp_statements= 0;
+my_bool opt_log_slow_timestamp_every= 0;
+ulonglong opt_use_global_log_slow_control= 0;
+my_bool opt_slow_query_log_microseconds_timestamp= 0;
 my_bool lower_case_file_system= 0;
 my_bool opt_large_pages= 0;
 my_bool opt_super_large_pages= 0;
@@ -5784,10 +5788,10 @@
    "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
    "the slow log if it is open.", &opt_log_slow_admin_statements,
    &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
- {"log-slow-slave-statements", 0,
+ /*{"log-slow-slave-statements", 0,
   "Log slow statements executed by slave thread to the slow log if it is open.",
   &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
-  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
+  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
   {"log-slow-queries", OPT_SLOW_QUERY_LOG,
    "Log slow queries to a table or log file. Defaults logging to table "
    "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
@@ -7179,6 +7183,10 @@
 
 C_MODE_END
 
+/* defined in sys_vars.cc */
+extern void init_log_slow_verbosity();
+extern void init_use_global_log_slow_control();
+
 /**
   Get server options from the command line,
   and perform related server initializations.
@@ -7318,6 +7326,8 @@
   global_system_variables.long_query_time= (ulonglong)
     (global_system_variables.long_query_time_double * 1e6);
 
+  init_log_slow_verbosity();
+  init_use_global_log_slow_control();
   if (opt_short_log_format)
     opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
 
diff -ruN a/sql/mysqld.h b/sql/mysqld.h
--- a/sql/mysqld.h	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/mysqld.h	2010-12-16 04:27:46.000000000 +0300
@@ -116,6 +116,10 @@
 extern char* opt_secure_backup_file_priv;
 extern size_t opt_secure_backup_file_priv_len;
 extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
+extern my_bool opt_log_slow_sp_statements;
+extern my_bool opt_log_slow_timestamp_every;
+extern ulonglong opt_use_global_log_slow_control;
+extern my_bool opt_slow_query_log_microseconds_timestamp;
 extern my_bool sp_automatic_privileges, opt_noacl;
 extern my_bool opt_old_style_user_limits, trust_function_creators;
 extern uint opt_crash_binlog_innodb;
diff -ruN a/sql/slave.cc b/sql/slave.cc
--- a/sql/slave.cc	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/slave.cc	2010-12-16 04:27:46.000000000 +0300
@@ -2038,6 +2038,7 @@
     + MAX_LOG_EVENT_HEADER;  /* note, incr over the global not session var */
   thd->slave_thread = 1;
   thd->enable_slow_log= opt_log_slow_slave_statements;
+  thd->write_to_slow_log= opt_log_slow_slave_statements;
   set_slave_thread_options(thd);
   thd->client_capabilities = CLIENT_LOCAL_FILES;
   mysql_mutex_lock(&LOCK_thread_count);
diff -ruN a/sql/sp_head.cc b/sql/sp_head.cc
--- a/sql/sp_head.cc	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/sp_head.cc	2010-12-16 04:27:46.000000000 +0300
@@ -2151,7 +2151,7 @@
     DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length, 
                        m_name.str));
   }
-  if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
+  if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
   {
     DBUG_PRINT("info", ("Disabling slow log for the execution"));
     save_enable_slow_log= true;
diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc
--- a/sql/sql_cache.cc	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/sql_cache.cc	2010-12-16 04:27:46.000000000 +0300
@@ -1756,6 +1756,7 @@
     response, we can't handle it anyway.
   */
   (void) trans_commit_stmt(thd);
+  thd->query_plan_flags|= QPLAN_QC;
   if (!thd->stmt_da->is_set())
     thd->stmt_da->disable_status();
 
@@ -1766,6 +1767,7 @@
 err_unlock:
   unlock();
 err:
+  thd->query_plan_flags|= QPLAN_QC_NO;
   MYSQL_QUERY_CACHE_MISS(thd->query());
   DBUG_RETURN(0);				// Query was not cached
 }
diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc
--- a/sql/sql_class.cc	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/sql_class.cc	2010-12-16 04:27:46.000000000 +0300
@@ -367,6 +367,37 @@
   thd->warning_info->inc_current_row_for_warning();
 }
 
+extern "C"
+void increment_thd_innodb_stats(THD* thd,
+                    unsigned long long trx_id,
+                    long io_reads,
+                    long long  io_read,
+                    long      io_reads_wait_timer,
+                    long      lock_que_wait_timer,
+                    long      que_wait_timer,
+                    long      page_access)
+{
+  thd->innodb_was_used = TRUE;
+  thd->innodb_trx_id = trx_id;
+  thd->innodb_io_reads += io_reads;
+  thd->innodb_io_read += io_read;
+  thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
+  thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
+  thd->innodb_innodb_que_wait_timer += que_wait_timer;
+  thd->innodb_page_access += page_access;
+}
+
+extern "C"
+unsigned long thd_log_slow_verbosity(const THD *thd)
+{
+  return (unsigned long) thd->variables.log_slow_verbosity;
+}
+
+extern "C"
+int thd_opt_slow_log()
+{
+  return (int) opt_slow_log;
+}
 
 /**
   Dumps a text description of a thread, its security context
@@ -661,6 +692,7 @@
     *cond_hdl= NULL;
     return FALSE;
   }
+  last_errno= sql_errno;
 
   for (Internal_error_handler *error_handler= m_internal_handler;
        error_handler;
@@ -3389,6 +3421,12 @@
     first_successful_insert_id_in_prev_stmt;
   backup->first_successful_insert_id_in_cur_stmt= 
     first_successful_insert_id_in_cur_stmt;
+  backup->innodb_io_reads= innodb_io_reads;
+  backup->innodb_io_read= innodb_io_read;
+  backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
+  backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
+  backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
+  backup->innodb_page_access= innodb_page_access;
 
   if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
       !is_current_stmt_binlog_format_row())
@@ -3409,6 +3447,14 @@
   cuted_fields= 0;
   transaction.savepoints= 0;
   first_successful_insert_id_in_cur_stmt= 0;
+  last_errno= 0;
+  innodb_trx_id= 0;
+  innodb_io_reads= 0;
+  innodb_io_read= 0;
+  innodb_io_reads_wait_timer= 0;
+  innodb_lock_que_wait_timer= 0;
+  innodb_innodb_que_wait_timer= 0;
+  innodb_page_access= 0;
 }
 
 
@@ -3471,6 +3517,12 @@
   */
   examined_row_count+= backup->examined_row_count;
   cuted_fields+=       backup->cuted_fields;
+  innodb_io_reads+= backup->innodb_io_reads;
+  innodb_io_read+= backup->innodb_io_read;
+  innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
+  innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
+  innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
+  innodb_page_access+= backup->innodb_page_access;
   DBUG_VOID_RETURN;
 }
 
diff -ruN a/sql/sql_class.h b/sql/sql_class.h
--- a/sql/sql_class.h	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/sql_class.h	2010-12-16 04:27:46.000000000 +0300
@@ -60,6 +60,26 @@
 enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
 enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
 			    DELAY_KEY_WRITE_ALL };
+enum enum_use_global_log_slow_control { SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT, SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME, SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL };
+enum enum_log_slow_verbosity { 
+  SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB, 
+  SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
+  SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
+};
+#define QPLAN_NONE            0
+#define QPLAN_QC              1 << 0
+#define QPLAN_QC_NO           1 << 1
+#define QPLAN_FULL_SCAN       1 << 2
+#define QPLAN_FULL_JOIN       1 << 3
+#define QPLAN_TMP_TABLE       1 << 4
+#define QPLAN_TMP_DISK        1 << 5
+#define QPLAN_FILESORT        1 << 6
+#define QPLAN_FILESORT_DISK   1 << 7
+enum enum_log_slow_filter {
+  SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
+  SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
+  SLOG_F_FILESORT_DISK
+};
 enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
                             SLAVE_EXEC_MODE_IDEMPOTENT,
                             SLAVE_EXEC_MODE_LAST_BIT};
@@ -508,6 +528,17 @@
 
   my_bool sysdate_is_now;
 
+  ulong log_slow_rate_limit;
+  ulonglong log_slow_filter;
+  ulonglong log_slow_verbosity;
+
+  ulong      innodb_io_reads;
+  ulonglong  innodb_io_read;
+  ulong      innodb_io_reads_wait_timer;
+  ulong      innodb_lock_que_wait_timer;
+  ulong      innodb_innodb_que_wait_timer;
+  ulong      innodb_page_access;
+
   double long_query_time_double;
 
 } SV;
@@ -1140,6 +1171,14 @@
   uint in_sub_stmt;
   bool enable_slow_log;
   bool last_insert_id_used;
+
+  ulong      innodb_io_reads;
+  ulonglong  innodb_io_read;
+  ulong      innodb_io_reads_wait_timer;
+  ulong      innodb_lock_que_wait_timer;
+  ulong      innodb_innodb_que_wait_timer;
+  ulong      innodb_page_access;
+
   SAVEPOINT *savepoints;
   enum enum_check_fields count_cuted_fields;
 };
@@ -1575,6 +1614,26 @@
   thr_lock_type update_lock_default;
   Delayed_insert *di;
 
+  bool       write_to_slow_log;
+
+  ulonglong  bytes_sent_old;
+  ulong      tmp_tables_used;
+  ulong      tmp_tables_disk_used;
+  ulonglong  tmp_tables_size;
+  bool       innodb_was_used;
+  ulonglong  innodb_trx_id;
+  ulong      innodb_io_reads;
+  ulonglong  innodb_io_read;
+  ulong      innodb_io_reads_wait_timer;
+  ulong      innodb_lock_que_wait_timer;
+  ulong      innodb_innodb_que_wait_timer;
+  ulong      innodb_page_access;
+
+  ulong      query_plan_flags;
+  ulong      query_plan_fsort_passes;
+
+  uint       last_errno;
+
   /* <> 0 if we are inside of trigger or stored function. */
   uint in_sub_stmt;
 
diff -ruN a/sql/sql_connect.cc b/sql/sql_connect.cc
--- a/sql/sql_connect.cc	2010-11-03 01:01:14.000000000 +0300
+++ b/sql/sql_connect.cc	2010-12-16 04:27:46.000000000 +0300
@@ -741,6 +741,15 @@
 
     prepare_new_connection_state(thd);
 
+    /* 
+      If rate limiting of slow log writes is enabled, decide whether to log this 
+      new thread's queries or not. Uses extremely simple algorithm. :) 
+    */ 
+    thd->write_to_slow_log= FALSE; 
+    if (thd->variables.log_slow_rate_limit <= 1 ||  
+        (thd->thread_id % thd->variables.log_slow_rate_limit) == 0) 
+         thd->write_to_slow_log= TRUE; 
+
     while (!net->error && net->vio != 0 &&
            !(thd->killed == THD::KILL_CONNECTION))
     {
diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc
--- a/sql/sql_parse.cc	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/sql_parse.cc	2010-12-16 04:47:41.000000000 +0300
@@ -1431,7 +1431,6 @@
   DBUG_RETURN(error);
 }
 
-
 void log_slow_statement(THD *thd)
 {
   DBUG_ENTER("log_slow_statement");
@@ -1444,6 +1443,42 @@
   if (unlikely(thd->in_sub_stmt))
     DBUG_VOID_RETURN;                           // Don't set time for sub stmt
 
+  /* Follow the slow log filter configuration. */
+  if (thd->variables.log_slow_filter != 0 &&
+      (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
+       ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
+        (thd->query_plan_flags & QPLAN_QC))))
+    DBUG_VOID_RETURN;
+
+  /*
+    Low long_query_time value most likely means user is debugging stuff and even
+    though some thread's queries are not supposed to be logged b/c of the rate
+    limit, if one of them takes long enough (>= 1 second) it will be sensible
+    to make an exception and write to slow log anyway.
+  */
+
+  ulonglong end_utime_of_query= thd->current_utime();
+#define USE_GLOBAL_UPDATE(variable_name,enum_value_name)                \
+  if (opt_use_global_log_slow_control & (ULL(1) << enum_value_name))    \
+  {                                                                     \
+    thd->variables. variable_name=                                      \
+      global_system_variables. variable_name;                           \
+  }
+  USE_GLOBAL_UPDATE(log_slow_filter,SLOG_UG_LOG_SLOW_FILTER);
+  USE_GLOBAL_UPDATE(log_slow_rate_limit,SLOG_UG_LOG_SLOW_RATE_LIMIT);
+  USE_GLOBAL_UPDATE(log_slow_verbosity,SLOG_UG_LOG_SLOW_VERBOSITY);
+  USE_GLOBAL_UPDATE(long_query_time,SLOG_UG_LONG_QUERY_TIME);
+  USE_GLOBAL_UPDATE(long_query_time_double,SLOG_UG_LONG_QUERY_TIME);
+  USE_GLOBAL_UPDATE(min_examined_row_limit,SLOG_UG_MIN_EXAMINED_ROW_LIMIT);
+#undef USE_GLOBAL_UPDATE
+
+  /* Do not log this thread's queries due to rate limiting. */
+  if (thd->write_to_slow_log != TRUE
+      && (thd->variables.long_query_time >= 1000000
+          || (ulong) (end_utime_of_query - thd->utime_after_lock) < 1000000))
+    DBUG_VOID_RETURN;
+
+
   /*
     Do not log administrative statements unless the appropriate option is
     set.
@@ -1819,6 +1854,9 @@
     context.resolve_in_table_list_only(select_lex->
                                        table_list.first);
 
+  /* Reset the counter at all cases for the extended slow query log */
+  thd->sent_row_count= 0;
+
   /*
     Reset warning count for each query that uses tables
     A better approach would be to reset this for any commands
@@ -5258,6 +5296,21 @@
   thd->rand_used= 0;
   thd->sent_row_count= thd->examined_row_count= 0;
 
+  thd->bytes_sent_old= thd->status_var.bytes_sent;
+  thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
+  thd->tmp_tables_size= 0;
+  thd->innodb_was_used= FALSE;
+  thd->innodb_trx_id= 0;
+  thd->innodb_io_reads= 0;
+  thd->innodb_io_read= 0;
+  thd->innodb_io_reads_wait_timer= 0;
+  thd->innodb_lock_que_wait_timer= 0;
+  thd->innodb_innodb_que_wait_timer= 0;
+  thd->innodb_page_access= 0;
+  thd->query_plan_flags= QPLAN_NONE;
+  thd->query_plan_fsort_passes= 0;
+  thd->last_errno= 0;
+
   thd->reset_current_stmt_binlog_format_row();
   thd->binlog_unsafe_warning_flags= 0;
 
diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc
--- a/sql/sql_select.cc	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/sql_select.cc	2010-12-16 04:27:47.000000000 +0300
@@ -6872,7 +6872,10 @@
 	  {
 	    join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
 	    if (statistics)
+            {
 	      status_var_increment(join->thd->status_var.select_scan_count);
+              join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
+            }
 	  }
 	}
 	else
@@ -6886,7 +6889,10 @@
 	  {
 	    join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
 	    if (statistics)
+            {
 	      status_var_increment(join->thd->status_var.select_full_join_count);
+              join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
+            }
 	  }
 	}
 	if (!table->no_keyread)
@@ -10217,6 +10223,7 @@
               (ulong) rows_limit,test(group)));
 
   status_var_increment(thd->status_var.created_tmp_tables);
+  thd->query_plan_flags|= QPLAN_TMP_TABLE;
 
   if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
     temp_pool_slot = bitmap_lock_set_next(&temp_pool);
@@ -11115,6 +11122,7 @@
     goto err;
   }
   status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
+  table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
   share->db_record_offset= 1;
   DBUG_RETURN(0);
  err:
@@ -11133,6 +11141,14 @@
   save_proc_info=thd->proc_info;
   thd_proc_info(thd, "removing tmp table");
 
+  thd->tmp_tables_used++;
+  if (entry->file)
+  {
+    thd->tmp_tables_size += entry->file->stats.data_file_length;
+    if (entry->file->ht->db_type != DB_TYPE_HEAP)
+      thd->tmp_tables_disk_used++;
+  }
+
   // Release latches since this can take a long time
   ha_release_temporary_latches(thd);
 
diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc
--- a/sql/sql_show.cc	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/sql_show.cc	2010-12-16 04:27:47.000000000 +0300
@@ -1942,8 +1942,17 @@
         table->field[4]->store(command_name[tmp->command].str,
                                command_name[tmp->command].length, cs);
       /* MYSQL_TIME */
-      table->field[5]->store((longlong)(tmp->start_time ?
-                                      now - tmp->start_time : 0), FALSE);
+      longlong value_in_time_column= 0;
+      if(tmp->start_time)
+      {
+        value_in_time_column = (now - tmp->start_time);
+        if(value_in_time_column > now)
+        {
+          value_in_time_column= 0;
+        }
+      }
+      table->field[5]->store(value_in_time_column, FALSE);
+
       /* STATE */
       if ((val= thread_state_info(tmp)))
       {
diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc
--- a/sql/sys_vars.cc	2010-12-16 04:27:10.000000000 +0300
+++ b/sql/sys_vars.cc	2010-12-16 04:36:12.000000000 +0300
@@ -2852,6 +2852,116 @@
        DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
        ON_UPDATE(fix_log_state));
 
+const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
+                                      "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
+static Sys_var_set Sys_log_slow_filter(
+       "log_slow_filter",
+       "Log only the queries that followed certain execution plan. "
+       "Multiple flags allowed in a comma-separated string. "
+       "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
+       "filesort, filesort_on_disk]",
+       SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
+       log_slow_filter_name, DEFAULT(0));
+static Sys_var_ulong sys_log_slow_rate_limit(
+       "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
+       SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
+       VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
+const char* log_slow_verbosity_name[] = { 
+  "microtime", "query_plan", "innodb", 
+  "profiling", "profling_use_getrusage", 
+  "minimal", "standard", "full", 0
+};
+static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
+{
+  if((value & what) == what)
+  {
+    value = value & (~what);
+    value = value | by;
+  }
+  return value;
+}
+void update_log_slow_verbosity(ulonglong* value_ptr)
+{
+  ulonglong &value    = *value_ptr;
+  ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
+  ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
+  ulonglong innodb= ULL(1) << SLOG_V_INNODB;
+  ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
+  ulonglong standard= ULL(1) << SLOG_V_STANDARD;
+  ulonglong full= ULL(1) << SLOG_V_FULL;
+  value= update_log_slow_verbosity_replace(value,minimal,microtime);
+  value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
+  value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
+}
+static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
+                                          enum_var_type type)
+{
+  if(type == OPT_SESSION)
+  {
+    update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
+  }
+  else
+  {
+    update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
+  }
+  return false;
+}
+void init_use_global_log_slow_control()
+{
+  update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
+}
+static Sys_var_set Sys_log_slow_verbosity(
+        "log_slow_verbosity",
+        "Choose how verbose the messages to your slow log will be. "
+        "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
+        SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
+        log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
+        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
+        ON_UPDATE(update_log_slow_verbosity_helper));
+static Sys_var_mybool Sys_log_slow_slave_statements(
+       "log_slow_slave_statements",
+       "Log queries replayed be the slave SQL thread",
+       GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
+       DEFAULT(FALSE));
+static Sys_var_mybool Sys_log_slow_sp_statements(
+       "log_slow_sp_statements",
+       "Log slow statements executed by stored procedure to the slow log if it is open.",
+       GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
+       DEFAULT(TRUE));
+static Sys_var_mybool Sys_log_slow_timestamp_every(
+       "log_slow_timestamp_every",
+       "Timestamp is printed for all records of the slow log even if they are same time.",
+       GLOBAL_VAR(opt_log_slow_timestamp_every), CMD_LINE(OPT_ARG),
+       DEFAULT(FALSE));
+const char *use_global_log_slow_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0};
+static bool update_use_global_log_slow_control(sys_var */*self*/, THD */*thd*/,
+                                               enum_var_type /*type*/)
+{
+  if(opt_use_global_log_slow_control & (ULL(1) << SLOG_UG_ALL))
+  {
+    opt_use_global_log_slow_control=
+      SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
+      SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
+  }
+  return false;
+}
+void init_log_slow_verbosity()
+{
+  update_use_global_log_slow_control(0,0,OPT_GLOBAL);
+}
+static Sys_var_set Sys_use_global_log_slow_control(
+       "use_global_log_slow_control",
+       "Choose flags, wich always use the global variables. Multiple flags allowed in a comma-separated string. [none, log_slow_filter, log_slow_rate_limit, log_slow_verbosity, long_query_time, min_examined_row_limit, all]",
+       GLOBAL_VAR(opt_use_global_log_slow_control), CMD_LINE(REQUIRED_ARG),
+       use_global_log_slow_control_name, DEFAULT(0),
+        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
+       ON_UPDATE(update_use_global_log_slow_control));
+static Sys_var_mybool Sys_slow_query_log_microseconds_timestamp(
+       "slow_query_log_microseconds_timestamp",
+       "Log slow statements executed by stored procedure to the slow log if it is open.",
+       GLOBAL_VAR(opt_slow_query_log_microseconds_timestamp), CMD_LINE(OPT_ARG),
+       DEFAULT(FALSE));
+ 
 /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
 static Sys_var_mybool Sys_log_slow(
        "log_slow_queries",
diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc
--- a/sql/sql_profile.cc	2010-11-03 07:01:14.000000000 +0900
+++ b/sql/sql_profile.cc	2010-12-02 20:26:35.448357413 +0900
@@ -243,7 +243,8 @@
 {
   time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
 #ifdef HAVE_GETRUSAGE
-  getrusage(RUSAGE_SELF, &rusage);
+  if ((profile->get_profiling())->enabled_getrusage())
+    getrusage(RUSAGE_SELF, &rusage);
 #elif defined(_WIN32)
   FILETIME ftDummy;
   // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
@@ -251,6 +252,19 @@
   // measurable by this function.
   GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
 #endif
+
+#ifdef HAVE_CLOCK_GETTIME
+  struct timespec tp;
+
+  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
+  {
+    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
+  }
+  else
+#endif
+  {
+    cpu_time_usecs= 0;
+  }
 }
 
 
@@ -366,7 +380,8 @@
     finish_current_query();
   }
 
-  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
+  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
+            ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
 
   if (! enabled) DBUG_VOID_RETURN;
 
@@ -404,7 +419,8 @@
     status_change("ending", NULL, NULL, 0);
 
     if ((enabled) &&                                    /* ON at start? */
-        ((thd->variables.option_bits & OPTION_PROFILING) != 0) &&   /* and ON at end? */
+        (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
+          ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) &&   /* and ON at end? */
         (current->query_source != NULL) &&
         (! current->entries.is_empty()))
     {
@@ -505,6 +521,118 @@
   DBUG_VOID_RETURN;
 }
 
+bool PROFILING::enabled_getrusage()
+{
+  return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
+}
+
+/**
+   For a given profile entry specified by a name and 2 time measurements,
+   print its normalized name (i.e. with all spaces replaced with underscores)
+   along with its wall clock and CPU time.
+*/
+
+static void my_b_print_status(IO_CACHE *log_file, const char *status,
+                              PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
+{
+  DBUG_ENTER("my_b_print_status");
+  DBUG_ASSERT(log_file != NULL && status != NULL);
+  char query_time_buff[22+7];
+  const char *tmp;
+
+  my_b_printf(log_file, "Profile_");
+  for (tmp= status; *tmp; tmp++)
+    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
+
+  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
+           (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
+  my_b_printf(log_file, ": %s ", query_time_buff);
+
+  my_b_printf(log_file, "Profile_");
+  for (tmp= status; *tmp; tmp++)
+    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
+  my_b_printf(log_file, "_cpu: ");
+
+  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
+           (stop->cpu_time_usecs - start->cpu_time_usecs) /
+           (1000.0 * 1000 * 1000));
+  my_b_printf(log_file, "%s ", query_time_buff);
+
+  DBUG_VOID_RETURN;
+}
+
+/**
+  Print output for current query to file 
+*/
+
+int PROFILING::print_current(IO_CACHE *log_file)
+{
+  DBUG_ENTER("PROFILING::print_current");
+  ulonglong row_number= 0;
+
+  QUERY_PROFILE *query;
+  /* Get current query */
+  if (current == NULL)
+  {
+    DBUG_RETURN(0);
+  }
+
+  query= current;
+
+  my_b_printf(log_file, "# ");
+
+    void *entry_iterator;
+    PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
+    /* ...and for each query, go through all its state-change steps. */
+    for (entry_iterator= query->entries.new_iterator();
+         entry_iterator != NULL;
+         entry_iterator= query->entries.iterator_next(entry_iterator),
+         previous=entry, row_number++)
+    {
+      entry= query->entries.iterator_value(entry_iterator);
+
+      /* Skip the first.  We count spans of fence, not fence-posts. */
+      if (previous == NULL) {first= entry; continue;}
+
+      if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
+      {
+        /*
+          We got here via a SHOW command.  That means that we stored
+          information about the query we wish to show and that isn't
+          in a WHERE clause at a higher level to filter out rows we
+          wish to exclude.
+
+          Because that functionality isn't available in the server yet,
+          we must filter here, at the wrong level.  Once one can con-
+          struct where and having conditions at the SQL layer, then this
+          condition should be ripped out.
+        */
+        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
+        {
+          if (query != last)
+            continue;
+        }
+        else
+        {
+          if (thd->lex->profile_query_id != query->profiling_query_id)
+            continue;
+        }
+      }
+
+      my_b_print_status(log_file, previous->status, previous, entry);
+    }
+
+    my_b_write_byte(log_file, '\n');
+    if ((entry != NULL) && (first != NULL))
+    {
+      my_b_printf(log_file, "# ");
+      my_b_print_status(log_file, "total", first, entry);
+      my_b_write_byte(log_file, '\n');
+    }
+
+  DBUG_RETURN(0);
+}
+
 /**
   Fill the information schema table, "query_profile", as defined in show.cc .
   There are two ways to get to this function:  Selecting from the information
diff -ruN a/sql/sql_profile.h b/sql/sql_profile.h
--- a/sql/sql_profile.h	2010-11-03 07:01:14.000000000 +0900
+++ b/sql/sql_profile.h	2010-12-02 19:23:07.823955510 +0900
@@ -164,11 +164,15 @@
 */
 class PROF_MEASUREMENT
 {
-private:
-  friend class QUERY_PROFILE;
-  friend class PROFILING;
-
   QUERY_PROFILE *profile;
+
+  char *allocated_status_memory;
+
+  void set_label(const char *status_arg, const char *function_arg, 
+                  const char *file_arg, unsigned int line_arg);
+  void clean_up();
+
+public:
   char *status;
 #ifdef HAVE_GETRUSAGE
   struct rusage rusage;
@@ -181,12 +185,7 @@
   unsigned int line;
 
   double time_usecs;
-  char *allocated_status_memory;
-
-  void set_label(const char *status_arg, const char *function_arg, 
-                  const char *file_arg, unsigned int line_arg);
-  void clean_up();
-  
+  double cpu_time_usecs;
   PROF_MEASUREMENT();
   PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
   PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
@@ -231,6 +230,11 @@
 
   /* Show this profile.  This is called by PROFILING. */
   bool show(uint options);
+
+public:
+
+  inline PROFILING * get_profiling() { return profiling; };
+
 };
 
 
@@ -276,9 +280,11 @@
 
   /* SHOW PROFILES */
   bool show_profiles();
+  bool enabled_getrusage();
 
   /* ... from INFORMATION_SCHEMA.PROFILING ... */
   int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
+  int print_current(IO_CACHE *log_file);
 };
 
 #  endif /* HAVE_PROFILING */