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