slow_extended.patch

   1 # name       : slow_extended.patch
   2 # introduced : 11 or before
   3 # maintainer : Oleg
   4 #
   5 #!!! notice !!!
   6 # Any small change to this file in the main branch
   7 # should be done or reviewed by the maintainer!
   8 diff -ruN a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp
   9 --- a/include/mysql/plugin_audit.h.pp   2011-04-09 18:48:05.000000000 +0400
  10 +++ b/include/mysql/plugin_audit.h.pp   2011-04-09 18:48:50.000000000 +0400
  11 @@ -178,6 +178,16 @@
  12  char *thd_security_context(void* thd, char *buffer, unsigned int length,
  13                             unsigned int max_query_len);
  14  void thd_inc_row_count(void* thd);
  15 +void increment_thd_innodb_stats(void* thd,
  16 +                    unsigned long long trx_id,
  17 +                    long io_reads,
  18 +                    long long io_read,
  19 +                    long io_reads_wait_timer,
  20 +                    long lock_que_wait_timer,
  21 +                    long que_wait_timer,
  22 +                    long page_access);
  23 +unsigned long thd_log_slow_verbosity(const void* thd);
  24 +int thd_opt_slow_log();
  25  int mysql_tmpfile(const char *prefix);
  26  int thd_killed(const void* thd);
  27  unsigned long thd_get_thread_id(const void* thd);
  28 diff -ruN a/include/mysql/plugin_auth.h.pp b/include/mysql/plugin_auth.h.pp
  29 --- a/include/mysql/plugin_auth.h.pp    2011-04-09 18:48:05.000000000 +0400
  30 +++ b/include/mysql/plugin_auth.h.pp    2011-04-09 18:48:50.000000000 +0400
  31 @@ -178,6 +178,16 @@
  32  char *thd_security_context(void* thd, char *buffer, unsigned int length,
  33                             unsigned int max_query_len);
  34  void thd_inc_row_count(void* thd);
  35 +void increment_thd_innodb_stats(void* thd,
  36 +                    unsigned long long trx_id,
  37 +                    long io_reads,
  38 +                    long long io_read,
  39 +                    long io_reads_wait_timer,
  40 +                    long lock_que_wait_timer,
  41 +                    long que_wait_timer,
  42 +                    long page_access);
  43 +unsigned long thd_log_slow_verbosity(const void* thd);
  44 +int thd_opt_slow_log();
  45  int mysql_tmpfile(const char *prefix);
  46  int thd_killed(const void* thd);
  47  unsigned long thd_get_thread_id(const void* thd);
  48 diff -ruN a/include/mysql/plugin_ftparser.h.pp b/include/mysql/plugin_ftparser.h.pp
  49 --- a/include/mysql/plugin_ftparser.h.pp        2011-04-09 18:48:05.000000000 +0400
  50 +++ b/include/mysql/plugin_ftparser.h.pp        2011-04-09 18:48:50.000000000 +0400
  51 @@ -131,6 +131,16 @@
  52  char *thd_security_context(void* thd, char *buffer, unsigned int length,
  53                             unsigned int max_query_len);
  54  void thd_inc_row_count(void* thd);
  55 +void increment_thd_innodb_stats(void* thd,
  56 +                    unsigned long long trx_id,
  57 +                    long io_reads,
  58 +                    long long io_read,
  59 +                    long io_reads_wait_timer,
  60 +                    long lock_que_wait_timer,
  61 +                    long que_wait_timer,
  62 +                    long page_access);
  63 +unsigned long thd_log_slow_verbosity(const void* thd);
  64 +int thd_opt_slow_log();
  65  int mysql_tmpfile(const char *prefix);
  66  int thd_killed(const void* thd);
  67  unsigned long thd_get_thread_id(const void* thd);
  68 diff -ruN a/include/mysql/plugin.h b/include/mysql/plugin.h
  69 --- a/include/mysql/plugin.h    2011-04-09 18:48:05.000000000 +0400
  70 +++ b/include/mysql/plugin.h    2011-04-09 18:48:50.000000000 +0400
  71 @@ -536,6 +536,17 @@
  72  /* Increments the row counter, see THD::row_count */
  73  void thd_inc_row_count(MYSQL_THD thd);
  74
  75 +void increment_thd_innodb_stats(MYSQL_THD thd,
  76 +                    unsigned long long trx_id,
  77 +                    long io_reads,
  78 +                    long long io_read,
  79 +                    long io_reads_wait_timer,
  80 +                    long lock_que_wait_timer,
  81 +                    long que_wait_timer,
  82 +                    long page_access);
  83 +unsigned long thd_log_slow_verbosity(const MYSQL_THD thd);
  84 +int thd_opt_slow_log();
  85 +#define EXTENDED_SLOWLOG
  86  /**
  87    Create a temporary file.
  88
  89 diff -ruN /dev/null b/patch_info/slow_extended.info
  90 --- /dev/null   1970-01-01 00:00:00.000000000 +0000
  91 +++ b/patch_info/slow_extended.info     2011-04-09 18:48:50.000000000 +0400
  92 @@ -0,0 +1,25 @@
  93 +File=slow_extended.patch
  94 +Name=Extended statistics in slow.log (not InnoDB part)
  95 +Version=1.3
  96 +Author=Percona <info@percona.com>
  97 +License=GPL
  98 +Comment=
  99 +Changelog
 100 +2008-11-26
 101 +YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
 102 +
 103 +2008-11-07
 104 +VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
 105 +
 106 +2008-11
 107 +Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
 108 +
 109 +2010-07
 110 +1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged)
 111 +2) Control global slow feature merged (control_global_slow.patch merged)
 112 +3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged)
 113 +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)
 114 +5) Fix innodb_stats on replication (Bug 600684)
 115 +6) Change variable types (system/command-line)
 116 +2011-01
 117 +Patch profiling_slow.patch was merged
 118 diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh
 119 --- a/scripts/mysqldumpslow.sh  2011-04-09 18:48:05.000000000 +0400
 120 +++ b/scripts/mysqldumpslow.sh  2011-04-09 18:48:50.000000000 +0400
 121 @@ -101,8 +101,8 @@
 122      s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
 123      my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
 124
 125 -    s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
 126 -    my ($t, $l, $r) = ($1, $2, $3);
 127 +    s/^# Query_time: (\d+(\.\d+)?)  Lock_time: (\d+(\.\d+)?)  Rows_sent: (\d+(\.\d+)?).*\n//;
 128 +    my ($t, $l, $r) = ($1, $3, $5);
 129      $t -= $l unless $opt{l};
 130
 131      # remove fluff that mysqld writes to log when it (re)starts:
 132 diff -ruN a/sql/event_scheduler.cc b/sql/event_scheduler.cc
 133 --- a/sql/event_scheduler.cc    2011-04-09 18:48:05.000000000 +0400
 134 +++ b/sql/event_scheduler.cc    2011-04-09 18:48:50.000000000 +0400
 135 @@ -195,6 +195,7 @@
 136    thd->client_capabilities|= CLIENT_MULTI_RESULTS;
 137    mysql_mutex_lock(&LOCK_thread_count);
 138    thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
 139 +  thd->write_to_slow_log = TRUE;
 140    mysql_mutex_unlock(&LOCK_thread_count);
 141
 142    /*
 143 diff -ruN a/sql/filesort.cc b/sql/filesort.cc
 144 --- a/sql/filesort.cc   2011-04-09 18:48:05.000000000 +0400
 145 +++ b/sql/filesort.cc   2011-04-09 18:48:50.000000000 +0400
 146 @@ -195,6 +195,7 @@
 147    {
 148      status_var_increment(thd->status_var.filesort_scan_count);
 149    }
 150 +  thd->query_plan_flags|= QPLAN_FILESORT;
 151  #ifdef CAN_TRUST_RANGE
 152    if (select && select->quick && select->quick->records > 0L)
 153    {
 154 @@ -260,6 +261,7 @@
 155    }
 156    else
 157    {
 158 +    thd->query_plan_flags|= QPLAN_FILESORT_DISK;
 159      if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
 160      {
 161        my_free(table_sort.buffpek);
 162 @@ -1219,6 +1221,7 @@
 163    DBUG_ENTER("merge_buffers");
 164
 165    status_var_increment(current_thd->status_var.filesort_merge_passes);
 166 +  current_thd->query_plan_fsort_passes++;
 167    if (param->not_killable)
 168    {
 169      killed= &not_killable;
 170 diff -ruN a/sql/log.cc b/sql/log.cc
 171 --- a/sql/log.cc        2011-04-09 18:48:05.000000000 +0400
 172 +++ b/sql/log.cc        2011-04-09 18:48:50.000000000 +0400
 173 @@ -715,11 +715,13 @@
 174  */
 175
 176  bool Log_to_csv_event_handler::
 177 -  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
 178 +  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
 179             const char *user_host, uint user_host_len,
 180             ulonglong query_utime, ulonglong lock_utime, bool is_command,
 181             const char *sql_text, uint sql_text_len)
 182  {
 183 +  time_t current_time= my_time_possible_from_micro(current_utime);
 184 +
 185    TABLE_LIST table_list;
 186    TABLE *table;
 187    bool result= TRUE;
 188 @@ -935,14 +937,14 @@
 189  /** Wrapper around MYSQL_LOG::write() for slow log. */
 190
 191  bool Log_to_file_event_handler::
 192 -  log_slow(THD *thd, time_t current_time, time_t query_start_arg,
 193 +  log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
 194             const char *user_host, uint user_host_len,
 195             ulonglong query_utime, ulonglong lock_utime, bool is_command,
 196             const char *sql_text, uint sql_text_len)
 197  {
 198    Silence_log_table_errors error_handler;
 199    thd->push_internal_handler(&error_handler);
 200 -  bool retval= mysql_slow_log.write(thd, current_time, query_start_arg,
 201 +  bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg,
 202                                      user_host, user_host_len,
 203                                      query_utime, lock_utime, is_command,
 204                                      sql_text, sql_text_len);
 205 @@ -1216,7 +1218,7 @@
 206      /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
 207      user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
 208                               sctx->priv_user ? sctx->priv_user : "", "[",
 209 -                             sctx->user ? sctx->user : "", "] @ ",
 210 +                             sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ",
 211                               sctx->host ? sctx->host : "", " [",
 212                               sctx->ip ? sctx->ip : "", "]", NullS) -
 213                      user_host_buff);
 214 @@ -1224,8 +1226,22 @@
 215      current_time= my_time_possible_from_micro(current_utime);
 216      if (thd->start_utime)
 217      {
 218 -      query_utime= (current_utime - thd->start_utime);
 219 -      lock_utime=  (thd->utime_after_lock - thd->start_utime);
 220 +      if(current_utime < thd->start_utime)
 221 +      {
 222 +        query_utime= 0;
 223 +      }
 224 +      else
 225 +      {
 226 +        query_utime= (current_utime - thd->start_utime);
 227 +      }
 228 +      if(thd->utime_after_lock < thd->start_utime)
 229 +      {
 230 +        lock_utime= 0;
 231 +      }
 232 +      else
 233 +      {
 234 +        lock_utime= (thd->utime_after_lock - thd->start_utime);
 235 +      }
 236      }
 237      else
 238      {
 239 @@ -1239,8 +1255,20 @@
 240        query_length= command_name[thd->command].length;
 241      }
 242
 243 +    if (!query_length)
 244 +    {
 245 +      thd->sent_row_count= thd->examined_row_count= 0;
 246 +      thd->sent_row_count= 0;
 247 +      thd->bytes_sent_old= thd->status_var.bytes_sent;
 248 +      thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
 249 +      thd->tmp_tables_size= 0;
 250 +      thd->innodb_was_used= FALSE;
 251 +      thd->query_plan_flags= QPLAN_NONE;
 252 +      thd->query_plan_fsort_passes= 0;
 253 +    }
 254 +
 255      for (current_handler= slow_log_handler_list; *current_handler ;)
 256 -      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
 257 +      error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
 258                                              user_host_buff, user_host_len,
 259                                              query_utime, lock_utime, is_command,
 260                                              query, query_length) || error;
 261 @@ -2656,12 +2684,13 @@
 262      TRUE - error occured
 263  */
 264
 265 -bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
 266 +bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
 267                              time_t query_start_arg, const char *user_host,
 268                              uint user_host_len, ulonglong query_utime,
 269                              ulonglong lock_utime, bool is_command,
 270                              const char *sql_text, uint sql_text_len)
 271  {
 272 +  time_t current_time= my_time_possible_from_micro(current_utime);
 273    bool error= 0;
 274    DBUG_ENTER("MYSQL_QUERY_LOG::write");
 275
 276 @@ -2683,17 +2712,28 @@
 277
 278      if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
 279      {
 280 -      if (current_time != last_time)
 281 +      if (opt_slow_query_log_timestamp_always || current_time != last_time)
 282        {
 283          last_time= current_time;
 284          struct tm start;
 285          localtime_r(&current_time, &start);
 286 -
 287 -        buff_len= my_snprintf(buff, sizeof buff,
 288 -                              "# Time: %02d%02d%02d %2d:%02d:%02d\n",
 289 -                              start.tm_year % 100, start.tm_mon + 1,
 290 -                              start.tm_mday, start.tm_hour,
 291 -                              start.tm_min, start.tm_sec);
 292 +       if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND)
 293 +       {
 294 +         ulonglong microsecond = current_utime % (1000 * 1000);
 295 +         buff_len= snprintf(buff, sizeof buff,
 296 +           "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
 297 +            start.tm_year % 100, start.tm_mon + 1,
 298 +           start.tm_mday, start.tm_hour,
 299 +           start.tm_min, start.tm_sec,microsecond);
 300 +       }
 301 +       else
 302 +       {
 303 +         buff_len= my_snprintf(buff, sizeof buff,
 304 +           "# Time: %02d%02d%02d %2d:%02d:%02d\n",
 305 +            start.tm_year % 100, start.tm_mon + 1,
 306 +           start.tm_mday, start.tm_hour,
 307 +           start.tm_min, start.tm_sec);
 308 +       }
 309
 310          /* Note that my_b_write() assumes it knows the length for this */
 311          if (my_b_write(&log_file, (uchar*) buff, buff_len))
 312 @@ -2711,12 +2751,69 @@
 313      sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
 314      sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
 315      if (my_b_printf(&log_file,
 316 -                    "# Query_time: %s  Lock_time: %s"
 317 -                    " Rows_sent: %lu  Rows_examined: %lu\n",
 318 +                    "# Thread_id: %lu  Schema: %s  Last_errno: %u  Killed: %u\n" \
 319 +                    "# Query_time: %s  Lock_time: %s  Rows_sent: %lu  Rows_examined: %lu  Rows_affected: %lu  Rows_read: %lu\n"
 320 +                    "# Bytes_sent: %lu  Tmp_tables: %lu  Tmp_disk_tables: %lu  Tmp_table_sizes: %lu\n",
 321 +                    (ulong) thd->thread_id, (thd->db ? thd->db : ""),
 322 +                    thd->last_errno, (uint) thd->killed,
 323                      query_time_buff, lock_time_buff,
 324                      (ulong) thd->sent_row_count,
 325 -                    (ulong) thd->examined_row_count) == (uint) -1)
 326 +                    (ulong) thd->examined_row_count,
 327 +                    ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
 328 +                    (ulong) thd->sent_row_count,
 329 +                    (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
 330 +                    (ulong) thd->tmp_tables_used,
 331 +                    (ulong) thd->tmp_tables_disk_used,
 332 +                    (ulong) thd->tmp_tables_size) == (uint) -1)
 333        tmp_errno= errno;
 334 +
 335 +#if defined(ENABLED_PROFILING)
 336 +    thd->profiling.print_current(&log_file);
 337 +#endif
 338 +    if (thd->innodb_was_used)
 339 +    {
 340 +      char buf[20];
 341 +      snprintf(buf, 20, "%llX", thd->innodb_trx_id);
 342 +      if (my_b_printf(&log_file,
 343 +                    "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
 344 +        tmp_errno=errno;
 345 +    }
 346 +    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
 347 +         my_b_printf(&log_file,
 348 +                    "# QC_Hit: %s  Full_scan: %s  Full_join: %s  Tmp_table: %s  Tmp_table_on_disk: %s\n" \
 349 +                    "# Filesort: %s  Filesort_on_disk: %s  Merge_passes: %lu\n",
 350 +                    ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
 351 +                    ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
 352 +                    ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
 353 +                    ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
 354 +                    ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
 355 +                    ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
 356 +                    ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
 357 +                    thd->query_plan_fsort_passes) == (uint) -1)
 358 +      tmp_errno=errno;
 359 +    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
 360 +    {
 361 +      char buf[3][20];
 362 +      snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
 363 +      snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
 364 +      snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
 365 +      if (my_b_printf(&log_file,
 366 +                      "#   InnoDB_IO_r_ops: %lu  InnoDB_IO_r_bytes: %lu  InnoDB_IO_r_wait: %s\n" \
 367 +                      "#   InnoDB_rec_lock_wait: %s  InnoDB_queue_wait: %s\n" \
 368 +                      "#   InnoDB_pages_distinct: %lu\n",
 369 +                      (ulong) thd->innodb_io_reads,
 370 +                      (ulong) thd->innodb_io_read,
 371 +                      buf[0], buf[1], buf[2],
 372 +                      (ulong) thd->innodb_page_access) == (uint) -1)
 373 +        tmp_errno=errno;
 374 +    }
 375 +    else
 376 +    {
 377 +      if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
 378 +          my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
 379 +        tmp_errno=errno;
 380 +    }
 381 +
 382      if (thd->db && strcmp(thd->db, db))
 383      {                                          // Database changed
 384        if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
 385 diff -ruN a/sql/log.h b/sql/log.h
 386 --- a/sql/log.h 2011-04-09 18:48:05.000000000 +0400
 387 +++ b/sql/log.h 2011-04-09 18:48:50.000000000 +0400
 388 @@ -242,7 +242,7 @@
 389               uint user_host_len, int thread_id,
 390               const char *command_type, uint command_type_len,
 391               const char *sql_text, uint sql_text_len);
 392 -  bool write(THD *thd, time_t current_time, time_t query_start_arg,
 393 +  bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
 394               const char *user_host, uint user_host_len,
 395               ulonglong query_utime, ulonglong lock_utime, bool is_command,
 396               const char *sql_text, uint sql_text_len);
 397 @@ -515,7 +515,7 @@
 398    virtual bool init()= 0;
 399    virtual void cleanup()= 0;
 400
 401 -  virtual bool log_slow(THD *thd, time_t current_time,
 402 +  virtual bool log_slow(THD *thd, ulonglong current_time,
 403                          time_t query_start_arg, const char *user_host,
 404                          uint user_host_len, ulonglong query_utime,
 405                          ulonglong lock_utime, bool is_command,
 406 @@ -544,7 +544,7 @@
 407    virtual bool init();
 408    virtual void cleanup();
 409
 410 -  virtual bool log_slow(THD *thd, time_t current_time,
 411 +  virtual bool log_slow(THD *thd, ulonglong current_utime,
 412                          time_t query_start_arg, const char *user_host,
 413                          uint user_host_len, ulonglong query_utime,
 414                          ulonglong lock_utime, bool is_command,
 415 @@ -576,7 +576,7 @@
 416    virtual bool init();
 417    virtual void cleanup();
 418
 419 -  virtual bool log_slow(THD *thd, time_t current_time,
 420 +  virtual bool log_slow(THD *thd, ulonglong current_utime,
 421                          time_t query_start_arg, const char *user_host,
 422                          uint user_host_len, ulonglong query_utime,
 423                          ulonglong lock_utime, bool is_command,
 424 diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
 425 --- a/sql/mysqld.cc     2011-04-09 18:48:20.000000000 +0400
 426 +++ b/sql/mysqld.cc     2011-04-09 18:48:50.000000000 +0400
 427 @@ -416,6 +416,10 @@
 428  char* opt_secure_file_priv;
 429  my_bool opt_log_slow_admin_statements= 0;
 430  my_bool opt_log_slow_slave_statements= 0;
 431 +my_bool opt_log_slow_sp_statements= 0;
 432 +my_bool opt_slow_query_log_timestamp_always= 0;
 433 +ulonglong opt_slow_query_log_use_global_control= 0;
 434 +ulong opt_slow_query_log_timestamp_precision= 0;
 435  my_bool lower_case_file_system= 0;
 436  my_bool opt_large_pages= 0;
 437  my_bool opt_super_large_pages= 0;
 438 @@ -5835,10 +5839,10 @@
 439     "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
 440     "the slow log if it is open.", &opt_log_slow_admin_statements,
 441     &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
 442 - {"log-slow-slave-statements", 0,
 443 + /*{"log-slow-slave-statements", 0,
 444    "Log slow statements executed by slave thread to the slow log if it is open.",
 445    &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
 446 -  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
 447 +  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
 448    {"log-slow-queries", OPT_SLOW_QUERY_LOG,
 449     "Log slow queries to a table or log file. Defaults logging to table "
 450     "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
 451 @@ -7227,6 +7231,10 @@
 452
 453  C_MODE_END
 454
 455 +/* defined in sys_vars.cc */
 456 +extern void init_log_slow_verbosity();
 457 +extern void init_slow_query_log_use_global_control();
 458 +
 459  /**
 460    Get server options from the command line,
 461    and perform related server initializations.
 462 @@ -7376,6 +7384,8 @@
 463    global_system_variables.long_query_time= (ulonglong)
 464      (global_system_variables.long_query_time_double * 1e6);
 465
 466 +  init_log_slow_verbosity();
 467 +  init_slow_query_log_use_global_control();
 468    if (opt_short_log_format)
 469      opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
 470
 471 diff -ruN a/sql/mysqld.h b/sql/mysqld.h
 472 --- a/sql/mysqld.h      2011-04-09 18:48:17.000000000 +0400
 473 +++ b/sql/mysqld.h      2011-04-09 18:48:50.000000000 +0400
 474 @@ -116,6 +116,10 @@
 475  extern char* opt_secure_backup_file_priv;
 476  extern size_t opt_secure_backup_file_priv_len;
 477  extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
 478 +extern my_bool opt_log_slow_sp_statements;
 479 +extern my_bool opt_slow_query_log_timestamp_always;
 480 +extern ulonglong opt_slow_query_log_use_global_control;
 481 +extern ulong opt_slow_query_log_timestamp_precision;
 482  extern my_bool sp_automatic_privileges, opt_noacl;
 483  extern my_bool opt_old_style_user_limits, trust_function_creators;
 484  extern uint opt_crash_binlog_innodb;
 485 diff -ruN a/sql/slave.cc b/sql/slave.cc
 486 --- a/sql/slave.cc      2011-04-09 18:48:05.000000000 +0400
 487 +++ b/sql/slave.cc      2011-04-09 18:48:50.000000000 +0400
 488 @@ -2038,6 +2038,7 @@
 489      + MAX_LOG_EVENT_HEADER;  /* note, incr over the global not session var */
 490    thd->slave_thread = 1;
 491    thd->enable_slow_log= opt_log_slow_slave_statements;
 492 +  thd->write_to_slow_log= opt_log_slow_slave_statements;
 493    set_slave_thread_options(thd);
 494    thd->client_capabilities = CLIENT_LOCAL_FILES;
 495    mysql_mutex_lock(&LOCK_thread_count);
 496 diff -ruN a/sql/sp_head.cc b/sql/sp_head.cc
 497 --- a/sql/sp_head.cc    2011-04-09 18:48:05.000000000 +0400
 498 +++ b/sql/sp_head.cc    2011-04-09 18:48:50.000000000 +0400
 499 @@ -2151,7 +2151,7 @@
 500      DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length,
 501                         m_name.str));
 502    }
 503 -  if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
 504 +  if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
 505    {
 506      DBUG_PRINT("info", ("Disabling slow log for the execution"));
 507      save_enable_slow_log= true;
 508 diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc
 509 --- a/sql/sql_cache.cc  2011-04-09 18:48:05.000000000 +0400
 510 +++ b/sql/sql_cache.cc  2011-04-09 18:48:50.000000000 +0400
 511 @@ -1756,6 +1756,7 @@
 512      response, we can't handle it anyway.
 513    */
 514    (void) trans_commit_stmt(thd);
 515 +  thd->query_plan_flags|= QPLAN_QC;
 516    if (!thd->stmt_da->is_set())
 517      thd->stmt_da->disable_status();
 518
 519 @@ -1766,6 +1767,7 @@
 520  err_unlock:
 521    unlock();
 522  err:
 523 +  thd->query_plan_flags|= QPLAN_QC_NO;
 524    MYSQL_QUERY_CACHE_MISS(thd->query());
 525    DBUG_RETURN(0);                              // Query was not cached
 526  }
 527 diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc
 528 --- a/sql/sql_class.cc  2011-04-09 18:48:05.000000000 +0400
 529 +++ b/sql/sql_class.cc  2011-04-09 18:48:50.000000000 +0400
 530 @@ -367,6 +367,37 @@
 531    thd->warning_info->inc_current_row_for_warning();
 532  }
 533
 534 +extern "C"
 535 +void increment_thd_innodb_stats(THD* thd,
 536 +                    unsigned long long trx_id,
 537 +                    long io_reads,
 538 +                    long long  io_read,
 539 +                    long      io_reads_wait_timer,
 540 +                    long      lock_que_wait_timer,
 541 +                    long      que_wait_timer,
 542 +                    long      page_access)
 543 +{
 544 +  thd->innodb_was_used = TRUE;
 545 +  thd->innodb_trx_id = trx_id;
 546 +  thd->innodb_io_reads += io_reads;
 547 +  thd->innodb_io_read += io_read;
 548 +  thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
 549 +  thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
 550 +  thd->innodb_innodb_que_wait_timer += que_wait_timer;
 551 +  thd->innodb_page_access += page_access;
 552 +}
 553 +
 554 +extern "C"
 555 +unsigned long thd_log_slow_verbosity(const THD *thd)
 556 +{
 557 +  return (unsigned long) thd->variables.log_slow_verbosity;
 558 +}
 559 +
 560 +extern "C"
 561 +int thd_opt_slow_log()
 562 +{
 563 +  return (int) opt_slow_log;
 564 +}
 565
 566  /**
 567    Dumps a text description of a thread, its security context
 568 @@ -661,6 +692,7 @@
 569      *cond_hdl= NULL;
 570      return FALSE;
 571    }
 572 +  last_errno= sql_errno;
 573
 574    for (Internal_error_handler *error_handler= m_internal_handler;
 575         error_handler;
 576 @@ -3385,6 +3417,12 @@
 577      first_successful_insert_id_in_prev_stmt;
 578    backup->first_successful_insert_id_in_cur_stmt=
 579      first_successful_insert_id_in_cur_stmt;
 580 +  backup->innodb_io_reads= innodb_io_reads;
 581 +  backup->innodb_io_read= innodb_io_read;
 582 +  backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
 583 +  backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
 584 +  backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
 585 +  backup->innodb_page_access= innodb_page_access;
 586
 587    if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
 588        !is_current_stmt_binlog_format_row())
 589 @@ -3405,6 +3443,14 @@
 590    cuted_fields= 0;
 591    transaction.savepoints= 0;
 592    first_successful_insert_id_in_cur_stmt= 0;
 593 +  last_errno= 0;
 594 +  innodb_trx_id= 0;
 595 +  innodb_io_reads= 0;
 596 +  innodb_io_read= 0;
 597 +  innodb_io_reads_wait_timer= 0;
 598 +  innodb_lock_que_wait_timer= 0;
 599 +  innodb_innodb_que_wait_timer= 0;
 600 +  innodb_page_access= 0;
 601  }
 602
 603
 604 @@ -3467,6 +3513,12 @@
 605    */
 606    examined_row_count+= backup->examined_row_count;
 607    cuted_fields+=       backup->cuted_fields;
 608 +  innodb_io_reads+= backup->innodb_io_reads;
 609 +  innodb_io_read+= backup->innodb_io_read;
 610 +  innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
 611 +  innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
 612 +  innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
 613 +  innodb_page_access+= backup->innodb_page_access;
 614    DBUG_VOID_RETURN;
 615  }
 616
 617 diff -ruN a/sql/sql_class.h b/sql/sql_class.h
 618 --- a/sql/sql_class.h   2011-04-09 18:48:19.000000000 +0400
 619 +++ b/sql/sql_class.h   2011-04-09 18:48:50.000000000 +0400
 620 @@ -60,6 +60,33 @@
 621  enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
 622  enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
 623                             DELAY_KEY_WRITE_ALL };
 624 +enum enum_slow_query_log_use_global_control {
 625 +  SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT
 626 +  , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME
 627 +  , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL
 628 +};
 629 +enum enum_log_slow_verbosity {
 630 +  SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB,
 631 +  SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
 632 +  SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
 633 +};
 634 +enum enum_slow_query_log_timestamp_precision {
 635 +  SLOG_SECOND, SLOG_MICROSECOND
 636 +};
 637 +#define QPLAN_NONE            0
 638 +#define QPLAN_QC              1 << 0
 639 +#define QPLAN_QC_NO           1 << 1
 640 +#define QPLAN_FULL_SCAN       1 << 2
 641 +#define QPLAN_FULL_JOIN       1 << 3
 642 +#define QPLAN_TMP_TABLE       1 << 4
 643 +#define QPLAN_TMP_DISK        1 << 5
 644 +#define QPLAN_FILESORT        1 << 6
 645 +#define QPLAN_FILESORT_DISK   1 << 7
 646 +enum enum_log_slow_filter {
 647 +  SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
 648 +  SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
 649 +  SLOG_F_FILESORT_DISK
 650 +};
 651  enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
 652                              SLAVE_EXEC_MODE_IDEMPOTENT,
 653                              SLAVE_EXEC_MODE_LAST_BIT};
 654 @@ -508,6 +535,17 @@
 655
 656    my_bool sysdate_is_now;
 657
 658 +  ulong log_slow_rate_limit;
 659 +  ulonglong log_slow_filter;
 660 +  ulonglong log_slow_verbosity;
 661 +
 662 +  ulong      innodb_io_reads;
 663 +  ulonglong  innodb_io_read;
 664 +  ulong      innodb_io_reads_wait_timer;
 665 +  ulong      innodb_lock_que_wait_timer;
 666 +  ulong      innodb_innodb_que_wait_timer;
 667 +  ulong      innodb_page_access;
 668 +
 669    double long_query_time_double;
 670
 671  } SV;
 672 @@ -1135,6 +1173,14 @@
 673    uint in_sub_stmt;
 674    bool enable_slow_log;
 675    bool last_insert_id_used;
 676 +
 677 +  ulong      innodb_io_reads;
 678 +  ulonglong  innodb_io_read;
 679 +  ulong      innodb_io_reads_wait_timer;
 680 +  ulong      innodb_lock_que_wait_timer;
 681 +  ulong      innodb_innodb_que_wait_timer;
 682 +  ulong      innodb_page_access;
 683 +
 684    SAVEPOINT *savepoints;
 685    enum enum_check_fields count_cuted_fields;
 686  };
 687 @@ -1583,6 +1629,26 @@
 688    thr_lock_type update_lock_default;
 689    Delayed_insert *di;
 690
 691 +  bool       write_to_slow_log;
 692 +
 693 +  ulonglong  bytes_sent_old;
 694 +  ulong      tmp_tables_used;
 695 +  ulong      tmp_tables_disk_used;
 696 +  ulonglong  tmp_tables_size;
 697 +  bool       innodb_was_used;
 698 +  ulonglong  innodb_trx_id;
 699 +  ulong      innodb_io_reads;
 700 +  ulonglong  innodb_io_read;
 701 +  ulong      innodb_io_reads_wait_timer;
 702 +  ulong      innodb_lock_que_wait_timer;
 703 +  ulong      innodb_innodb_que_wait_timer;
 704 +  ulong      innodb_page_access;
 705 +
 706 +  ulong      query_plan_flags;
 707 +  ulong      query_plan_fsort_passes;
 708 +
 709 +  uint       last_errno;
 710 +
 711    /* <> 0 if we are inside of trigger or stored function. */
 712    uint in_sub_stmt;
 713
 714 diff -ruN a/sql/sql_connect.cc b/sql/sql_connect.cc
 715 --- a/sql/sql_connect.cc        2011-04-09 18:48:05.000000000 +0400
 716 +++ b/sql/sql_connect.cc        2011-04-09 18:48:50.000000000 +0400
 717 @@ -764,4 +764,13 @@
 718
 719 +    /*
 720 +      If rate limiting of slow log writes is enabled, decide whether to log this
 721 +      new thread's queries or not. Uses extremely simple algorithm. :)
 722 +    */
 723 +    thd->write_to_slow_log= FALSE;
 724 +    if (thd->variables.log_slow_rate_limit <= 1 ||
 725 +        (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
 726 +         thd->write_to_slow_log= TRUE;
 727 +
 728      prepare_new_connection_state(thd);
 729
 730      while (!net->error && net->vio != 0 &&
 731 diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc
 732 --- a/sql/sql_parse.cc  2011-04-09 18:48:20.000000000 +0400
 733 +++ b/sql/sql_parse.cc  2011-04-09 18:48:50.000000000 +0400
 734 @@ -1430,7 +1430,6 @@
 735    DBUG_RETURN(error);
 736  }
 737
 738 -
 739  void log_slow_statement(THD *thd)
 740  {
 741    DBUG_ENTER("log_slow_statement");
 742 @@ -1443,6 +1442,42 @@
 743    if (unlikely(thd->in_sub_stmt))
 744      DBUG_VOID_RETURN;                           // Don't set time for sub stmt
 745
 746 +  /* Follow the slow log filter configuration. */
 747 +  if (thd->variables.log_slow_filter != 0 &&
 748 +      (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
 749 +       ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
 750 +        (thd->query_plan_flags & QPLAN_QC))))
 751 +    DBUG_VOID_RETURN;
 752 +
 753 +  /*
 754 +    Low long_query_time value most likely means user is debugging stuff and even
 755 +    though some thread's queries are not supposed to be logged b/c of the rate
 756 +    limit, if one of them takes long enough (>= 1 second) it will be sensible
 757 +    to make an exception and write to slow log anyway.
 758 +  */
 759 +
 760 +  ulonglong end_utime_of_query= thd->current_utime();
 761 +#define USE_GLOBAL_UPDATE(variable_name,enum_value_name)                \
 762 +  if (opt_slow_query_log_use_global_control & (ULL(1) << enum_value_name))    \
 763 +  {                                                                     \
 764 +    thd->variables. variable_name=                                      \
 765 +      global_system_variables. variable_name;                           \
 766 +  }
 767 +  USE_GLOBAL_UPDATE(log_slow_filter,SLOG_UG_LOG_SLOW_FILTER);
 768 +  USE_GLOBAL_UPDATE(log_slow_rate_limit,SLOG_UG_LOG_SLOW_RATE_LIMIT);
 769 +  USE_GLOBAL_UPDATE(log_slow_verbosity,SLOG_UG_LOG_SLOW_VERBOSITY);
 770 +  USE_GLOBAL_UPDATE(long_query_time,SLOG_UG_LONG_QUERY_TIME);
 771 +  USE_GLOBAL_UPDATE(long_query_time_double,SLOG_UG_LONG_QUERY_TIME);
 772 +  USE_GLOBAL_UPDATE(min_examined_row_limit,SLOG_UG_MIN_EXAMINED_ROW_LIMIT);
 773 +#undef USE_GLOBAL_UPDATE
 774 +
 775 +  /* Do not log this thread's queries due to rate limiting. */
 776 +  if (thd->write_to_slow_log != TRUE
 777 +      && (thd->variables.long_query_time >= 1000000
 778 +          || (ulong) (end_utime_of_query - thd->utime_after_lock) < 1000000))
 779 +    DBUG_VOID_RETURN;
 780 +
 781 +
 782    /*
 783      Do not log administrative statements unless the appropriate option is
 784      set.
 785 @@ -1818,6 +1853,9 @@
 786      context.resolve_in_table_list_only(select_lex->
 787                                         table_list.first);
 788
 789 +  /* Reset the counter at all cases for the extended slow query log */
 790 +  thd->sent_row_count= 0;
 791 +
 792    /*
 793      Reset warning count for each query that uses tables
 794      A better approach would be to reset this for any commands
 795 @@ -5252,6 +5290,21 @@
 796    thd->rand_used= 0;
 797    thd->sent_row_count= thd->examined_row_count= 0;
 798
 799 +  thd->bytes_sent_old= thd->status_var.bytes_sent;
 800 +  thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
 801 +  thd->tmp_tables_size= 0;
 802 +  thd->innodb_was_used= FALSE;
 803 +  thd->innodb_trx_id= 0;
 804 +  thd->innodb_io_reads= 0;
 805 +  thd->innodb_io_read= 0;
 806 +  thd->innodb_io_reads_wait_timer= 0;
 807 +  thd->innodb_lock_que_wait_timer= 0;
 808 +  thd->innodb_innodb_que_wait_timer= 0;
 809 +  thd->innodb_page_access= 0;
 810 +  thd->query_plan_flags= QPLAN_NONE;
 811 +  thd->query_plan_fsort_passes= 0;
 812 +  thd->last_errno= 0;
 813 +
 814    thd->reset_current_stmt_binlog_format_row();
 815    thd->binlog_unsafe_warning_flags= 0;
 816
 817 diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc
 818 --- a/sql/sql_select.cc 2011-04-09 18:48:17.000000000 +0400
 819 +++ b/sql/sql_select.cc 2011-04-09 18:48:50.000000000 +0400
 820 @@ -6902,7 +6902,10 @@
 821           {
 822             join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
 823             if (statistics)
 824 +            {
 825               status_var_increment(join->thd->status_var.select_scan_count);
 826 +              join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
 827 +            }
 828           }
 829         }
 830         else
 831 @@ -6916,7 +6919,10 @@
 832           {
 833             join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
 834             if (statistics)
 835 +            {
 836               status_var_increment(join->thd->status_var.select_full_join_count);
 837 +              join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
 838 +            }
 839           }
 840         }
 841         if (!table->no_keyread)
 842 @@ -10247,6 +10253,7 @@
 843                (ulong) rows_limit,test(group)));
 844
 845    status_var_increment(thd->status_var.created_tmp_tables);
 846 +  thd->query_plan_flags|= QPLAN_TMP_TABLE;
 847
 848    if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
 849      temp_pool_slot = bitmap_lock_set_next(&temp_pool);
 850 @@ -11145,6 +11152,7 @@
 851      goto err;
 852    }
 853    status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
 854 +  table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
 855    share->db_record_offset= 1;
 856    DBUG_RETURN(0);
 857   err:
 858 @@ -11163,6 +11171,14 @@
 859    save_proc_info=thd->proc_info;
 860    thd_proc_info(thd, "removing tmp table");
 861
 862 +  thd->tmp_tables_used++;
 863 +  if (entry->file)
 864 +  {
 865 +    thd->tmp_tables_size += entry->file->stats.data_file_length;
 866 +    if (entry->file->ht->db_type != DB_TYPE_HEAP)
 867 +      thd->tmp_tables_disk_used++;
 868 +  }
 869 +
 870    // Release latches since this can take a long time
 871    ha_release_temporary_latches(thd);
 872
 873 diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc
 874 --- a/sql/sql_show.cc   2011-04-09 18:48:20.000000000 +0400
 875 +++ b/sql/sql_show.cc   2011-04-09 18:48:50.000000000 +0400
 876 @@ -1950,8 +1950,17 @@
 877          table->field[4]->store(command_name[tmp->command].str,
 878                                 command_name[tmp->command].length, cs);
 879        /* MYSQL_TIME */
 880 -      table->field[5]->store((longlong)(tmp->start_time ?
 881 -                                      now - tmp->start_time : 0), FALSE);
 882 +      longlong value_in_time_column= 0;
 883 +      if(tmp->start_time)
 884 +      {
 885 +        value_in_time_column = (now - tmp->start_time);
 886 +        if(value_in_time_column > now)
 887 +        {
 888 +          value_in_time_column= 0;
 889 +        }
 890 +      }
 891 +      table->field[5]->store(value_in_time_column, FALSE);
 892 +
 893        /* STATE */
 894        if ((val= thread_state_info(tmp)))
 895        {
 896 diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc
 897 --- a/sql/sys_vars.cc   2011-04-09 18:48:19.000000000 +0400
 898 +++ b/sql/sys_vars.cc   2011-04-09 18:48:50.000000000 +0400
 899 @@ -2898,6 +2898,117 @@
 900         DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
 901         ON_UPDATE(fix_log_state));
 902
 903 +const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
 904 +                                      "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
 905 +static Sys_var_set Sys_log_slow_filter(
 906 +       "log_slow_filter",
 907 +       "Log only the queries that followed certain execution plan. "
 908 +       "Multiple flags allowed in a comma-separated string. "
 909 +       "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
 910 +       "filesort, filesort_on_disk]",
 911 +       SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
 912 +       log_slow_filter_name, DEFAULT(0));
 913 +static Sys_var_ulong sys_log_slow_rate_limit(
 914 +       "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
 915 +       SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
 916 +       VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
 917 +const char* log_slow_verbosity_name[] = {
 918 +  "microtime", "query_plan", "innodb",
 919 +  "profiling", "profling_use_getrusage",
 920 +  "minimal", "standard", "full", 0
 921 +};
 922 +static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
 923 +{
 924 +  if((value & what) == what)
 925 +  {
 926 +    value = value & (~what);
 927 +    value = value | by;
 928 +  }
 929 +  return value;
 930 +}
 931 +void update_log_slow_verbosity(ulonglong* value_ptr)
 932 +{
 933 +  ulonglong &value    = *value_ptr;
 934 +  ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
 935 +  ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
 936 +  ulonglong innodb= ULL(1) << SLOG_V_INNODB;
 937 +  ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
 938 +  ulonglong standard= ULL(1) << SLOG_V_STANDARD;
 939 +  ulonglong full= ULL(1) << SLOG_V_FULL;
 940 +  value= update_log_slow_verbosity_replace(value,minimal,microtime);
 941 +  value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
 942 +  value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
 943 +}
 944 +static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
 945 +                                          enum_var_type type)
 946 +{
 947 +  if(type == OPT_SESSION)
 948 +  {
 949 +    update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
 950 +  }
 951 +  else
 952 +  {
 953 +    update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
 954 +  }
 955 +  return false;
 956 +}
 957 +void init_slow_query_log_use_global_control()
 958 +{
 959 +  update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
 960 +}
 961 +static Sys_var_set Sys_log_slow_verbosity(
 962 +        "log_slow_verbosity",
 963 +        "Choose how verbose the messages to your slow log will be. "
 964 +        "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
 965 +        SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
 966 +        log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
 967 +        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
 968 +        ON_UPDATE(update_log_slow_verbosity_helper));
 969 +static Sys_var_mybool Sys_log_slow_slave_statements(
 970 +       "log_slow_slave_statements",
 971 +       "Log queries replayed be the slave SQL thread",
 972 +       GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
 973 +       DEFAULT(FALSE));
 974 +static Sys_var_mybool Sys_log_slow_sp_statements(
 975 +       "log_slow_sp_statements",
 976 +       "Log slow statements executed by stored procedure to the slow log if it is open.",
 977 +       GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
 978 +       DEFAULT(TRUE));
 979 +static Sys_var_mybool Sys_slow_query_log_timestamp_always(
 980 +       "slow_query_log_timestamp_always",
 981 +       "Timestamp is printed for all records of the slow log even if they are same time.",
 982 +       GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG),
 983 +       DEFAULT(FALSE));
 984 +const char *slow_query_log_use_global_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0};
 985 +static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/,
 986 +                                               enum_var_type /*type*/)
 987 +{
 988 +  if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
 989 +  {
 990 +    opt_slow_query_log_use_global_control=
 991 +      SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
 992 +      SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
 993 +  }
 994 +  return false;
 995 +}
 996 +void init_log_slow_verbosity()
 997 +{
 998 +  update_slow_query_log_use_global_control(0,0,OPT_GLOBAL);
 999 +}
1000 +static Sys_var_set Sys_slow_query_log_use_global_control(
1001 +       "slow_query_log_use_global_control",
1002 +       "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]",
1003 +       GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG),
1004 +       slow_query_log_use_global_control_name, DEFAULT(0),
1005 +        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
1006 +       ON_UPDATE(update_slow_query_log_use_global_control));
1007 +const char *slow_query_log_timestamp_precision_name[]= { "second", "microsecond", 0 };
1008 +static Sys_var_enum Sys_slow_query_log_timestamp_precision(
1009 +       "slow_query_log_timestamp_precision",
1010 +       "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]",
1011 +       GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
1012 +       slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
1013 +
1014  /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
1015  static Sys_var_mybool Sys_log_slow(
1016         "log_slow_queries",
1017 diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc
1018 --- a/sql/sql_profile.cc        2011-04-09 18:48:05.000000000 +0400
1019 +++ b/sql/sql_profile.cc        2011-04-09 18:48:50.000000000 +0400
1020 @@ -243,7 +243,8 @@
1021  {
1022    time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
1023  #ifdef HAVE_GETRUSAGE
1024 -  getrusage(RUSAGE_SELF, &rusage);
1025 +  if ((profile->get_profiling())->enabled_getrusage())
1026 +    getrusage(RUSAGE_SELF, &rusage);
1027  #elif defined(_WIN32)
1028    FILETIME ftDummy;
1029    // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
1030 @@ -251,6 +252,19 @@
1031    // measurable by this function.
1032    GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
1033  #endif
1034 +
1035 +#ifdef HAVE_CLOCK_GETTIME
1036 +  struct timespec tp;
1037 +
1038 +  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
1039 +  {
1040 +    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
1041 +  }
1042 +  else
1043 +#endif
1044 +  {
1045 +    cpu_time_usecs= 0;
1046 +  }
1047  }
1048
1049
1050 @@ -366,7 +380,8 @@
1051      finish_current_query();
1052    }
1053
1054 -  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
1055 +  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1056 +            ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
1057
1058    if (! enabled) DBUG_VOID_RETURN;
1059
1060 @@ -404,7 +419,8 @@
1061      status_change("ending", NULL, NULL, 0);
1062
1063      if ((enabled) &&                                    /* ON at start? */
1064 -        ((thd->variables.option_bits & OPTION_PROFILING) != 0) &&   /* and ON at end? */
1065 +        (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1066 +          ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) &&   /* and ON at end? */
1067          (current->query_source != NULL) &&
1068          (! current->entries.is_empty()))
1069      {
1070 @@ -505,6 +521,118 @@
1071    DBUG_VOID_RETURN;
1072  }
1073
1074 +bool PROFILING::enabled_getrusage()
1075 +{
1076 +  return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
1077 +}
1078 +
1079 +/**
1080 +   For a given profile entry specified by a name and 2 time measurements,
1081 +   print its normalized name (i.e. with all spaces replaced with underscores)
1082 +   along with its wall clock and CPU time.
1083 +*/
1084 +
1085 +static void my_b_print_status(IO_CACHE *log_file, const char *status,
1086 +                              PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
1087 +{
1088 +  DBUG_ENTER("my_b_print_status");
1089 +  DBUG_ASSERT(log_file != NULL && status != NULL);
1090 +  char query_time_buff[22+7];
1091 +  const char *tmp;
1092 +
1093 +  my_b_printf(log_file, "Profile_");
1094 +  for (tmp= status; *tmp; tmp++)
1095 +    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1096 +
1097 +  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1098 +           (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
1099 +  my_b_printf(log_file, ": %s ", query_time_buff);
1100 +
1101 +  my_b_printf(log_file, "Profile_");
1102 +  for (tmp= status; *tmp; tmp++)
1103 +    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1104 +  my_b_printf(log_file, "_cpu: ");
1105 +
1106 +  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1107 +           (stop->cpu_time_usecs - start->cpu_time_usecs) /
1108 +           (1000.0 * 1000 * 1000));
1109 +  my_b_printf(log_file, "%s ", query_time_buff);
1110 +
1111 +  DBUG_VOID_RETURN;
1112 +}
1113 +
1114 +/**
1115 +  Print output for current query to file
1116 +*/
1117 +
1118 +int PROFILING::print_current(IO_CACHE *log_file)
1119 +{
1120 +  DBUG_ENTER("PROFILING::print_current");
1121 +  ulonglong row_number= 0;
1122 +
1123 +  QUERY_PROFILE *query;
1124 +  /* Get current query */
1125 +  if (current == NULL)
1126 +  {
1127 +    DBUG_RETURN(0);
1128 +  }
1129 +
1130 +  query= current;
1131 +
1132 +  my_b_printf(log_file, "# ");
1133 +
1134 +    void *entry_iterator;
1135 +    PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
1136 +    /* ...and for each query, go through all its state-change steps. */
1137 +    for (entry_iterator= query->entries.new_iterator();
1138 +         entry_iterator != NULL;
1139 +         entry_iterator= query->entries.iterator_next(entry_iterator),
1140 +         previous=entry, row_number++)
1141 +    {
1142 +      entry= query->entries.iterator_value(entry_iterator);
1143 +
1144 +      /* Skip the first.  We count spans of fence, not fence-posts. */
1145 +      if (previous == NULL) {first= entry; continue;}
1146 +
1147 +      if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
1148 +      {
1149 +        /*
1150 +          We got here via a SHOW command.  That means that we stored
1151 +          information about the query we wish to show and that isn't
1152 +          in a WHERE clause at a higher level to filter out rows we
1153 +          wish to exclude.
1154 +
1155 +          Because that functionality isn't available in the server yet,
1156 +          we must filter here, at the wrong level.  Once one can con-
1157 +          struct where and having conditions at the SQL layer, then this
1158 +          condition should be ripped out.
1159 +        */
1160 +        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
1161 +        {
1162 +          if (query != last)
1163 +            continue;
1164 +        }
1165 +        else
1166 +        {
1167 +          if (thd->lex->profile_query_id != query->profiling_query_id)
1168 +            continue;
1169 +        }
1170 +      }
1171 +
1172 +      my_b_print_status(log_file, previous->status, previous, entry);
1173 +    }
1174 +
1175 +    my_b_write_byte(log_file, '\n');
1176 +    if ((entry != NULL) && (first != NULL))
1177 +    {
1178 +      my_b_printf(log_file, "# ");
1179 +      my_b_print_status(log_file, "total", first, entry);
1180 +      my_b_write_byte(log_file, '\n');
1181 +    }
1182 +
1183 +  DBUG_RETURN(0);
1184 +}
1185 +
1186  /**
1187    Fill the information schema table, "query_profile", as defined in show.cc .
1188    There are two ways to get to this function:  Selecting from the information
1189 @@ -600,6 +728,8 @@
1190
1191  #ifdef HAVE_GETRUSAGE
1192
1193 +      if (enabled_getrusage())
1194 +      {
1195        my_decimal cpu_utime_decimal, cpu_stime_decimal;
1196
1197        double2my_decimal(E_DEC_FATAL_ERROR,
1198 @@ -687,6 +817,7 @@
1199        table->field[14]->store((uint32)(entry->rusage.ru_nswap -
1200                               previous->rusage.ru_nswap), true);
1201        table->field[14]->set_notnull();
1202 +      }
1203  #else
1204        /* TODO: Add swap info for non-BSD systems */
1205  #endif
1206 diff -ruN a/sql/sql_profile.h b/sql/sql_profile.h
1207 --- a/sql/sql_profile.h 2011-04-09 18:48:05.000000000 +0400
1208 +++ b/sql/sql_profile.h 2011-04-09 18:48:50.000000000 +0400
1209 @@ -164,11 +164,15 @@
1210  */
1211  class PROF_MEASUREMENT
1212  {
1213 -private:
1214 -  friend class QUERY_PROFILE;
1215 -  friend class PROFILING;
1216 -
1217    QUERY_PROFILE *profile;
1218 +
1219 +  char *allocated_status_memory;
1220 +
1221 +  void set_label(const char *status_arg, const char *function_arg,
1222 +                  const char *file_arg, unsigned int line_arg);
1223 +  void clean_up();
1224 +
1225 +public:
1226    char *status;
1227  #ifdef HAVE_GETRUSAGE
1228    struct rusage rusage;
1229 @@ -181,12 +185,7 @@
1230    unsigned int line;
1231
1232    double time_usecs;
1233 -  char *allocated_status_memory;
1234 -
1235 -  void set_label(const char *status_arg, const char *function_arg,
1236 -                  const char *file_arg, unsigned int line_arg);
1237 -  void clean_up();
1238 -
1239 +  double cpu_time_usecs;
1240    PROF_MEASUREMENT();
1241    PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
1242    PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
1243 @@ -231,6 +230,11 @@
1244
1245    /* Show this profile.  This is called by PROFILING. */
1246    bool show(uint options);
1247 +
1248 +public:
1249 +
1250 +  inline PROFILING * get_profiling() { return profiling; };
1251 +
1252  };
1253
1254
1255 @@ -276,9 +280,11 @@
1256
1257    /* SHOW PROFILES */
1258    bool show_profiles();
1259 +  bool enabled_getrusage();
1260
1261    /* ... from INFORMATION_SCHEMA.PROFILING ... */
1262    int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
1263 +  int print_current(IO_CACHE *log_file);
1264  };
1265
1266  #  endif /* HAVE_PROFILING */