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