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 @@ -186,6 +186,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 @@ -186,6 +186,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 @@ -139,6 +139,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 @@ -545,6 +545,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 @@ -193,6 +193,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 @@ -261,6 +262,7 @@
 147      /* filesort cannot handle zero-length records during merge. */
 148      DBUG_ASSERT(param.sort_length != 0);
 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 @@ -1209,6 +1211,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 @@ -1200,8 +1202,6 @@
 197
 198    if (*slow_log_handler_list)
 199    {
 200 -    time_t current_time;
 201 -
 202      /* do not log slow queries from replication threads */
 203      if (thd->slave_thread && !opt_log_slow_slave_statements)
 204        return 0;
 205 @@ -1216,16 +1216,29 @@
 206      /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
 207      user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
 208                               sctx->priv_user ? sctx->priv_user : "", "[",
 209 -                             sctx->user ? sctx->user : "", "] @ ",
 210 +                             sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ",
 211                               sctx->host ? sctx->host : "", " [",
 212                               sctx->ip ? sctx->ip : "", "]", NullS) -
 213                      user_host_buff);
 214
 215 -    current_time= my_time_possible_from_micro(current_utime);
 216      if (thd->start_utime)
 217      {
 218 -      query_utime= (current_utime - thd->start_utime);
 219 -      lock_utime=  (thd->utime_after_lock - thd->start_utime);
 220 +      if(current_utime < thd->start_utime)
 221 +      {
 222 +        query_utime= 0;
 223 +      }
 224 +      else
 225 +      {
 226 +        query_utime= (current_utime - thd->start_utime);
 227 +      }
 228 +      if(thd->utime_after_lock < thd->start_utime)
 229 +      {
 230 +        lock_utime= 0;
 231 +      }
 232 +      else
 233 +      {
 234 +        lock_utime= (thd->utime_after_lock - thd->start_utime);
 235 +      }
 236      }
 237      else
 238      {
 239 @@ -1240,7 +1253,7 @@
 240      }
 241
 242      for (current_handler= slow_log_handler_list; *current_handler ;)
 243 -      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
 244 +      error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
 245                                              user_host_buff, user_host_len,
 246                                              query_utime, lock_utime, is_command,
 247                                              query, query_length) || error;
 248 @@ -2656,12 +2669,13 @@
 249      TRUE - error occured
 250  */
 251
 252 -bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
 253 +bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
 254                              time_t query_start_arg, const char *user_host,
 255                              uint user_host_len, ulonglong query_utime,
 256                              ulonglong lock_utime, bool is_command,
 257                              const char *sql_text, uint sql_text_len)
 258  {
 259 +  time_t current_time= my_time_possible_from_micro(current_utime);
 260    bool error= 0;
 261    DBUG_ENTER("MYSQL_QUERY_LOG::write");
 262
 263 @@ -2683,17 +2697,28 @@
 264
 265      if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
 266      {
 267 -      if (current_time != last_time)
 268 +      if (opt_slow_query_log_timestamp_always || current_time != last_time)
 269        {
 270          last_time= current_time;
 271          struct tm start;
 272          localtime_r(&current_time, &start);
 273 -
 274 -        buff_len= my_snprintf(buff, sizeof buff,
 275 -                              "# Time: %02d%02d%02d %2d:%02d:%02d\n",
 276 -                              start.tm_year % 100, start.tm_mon + 1,
 277 -                              start.tm_mday, start.tm_hour,
 278 -                              start.tm_min, start.tm_sec);
 279 +       if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND)
 280 +       {
 281 +         ulonglong microsecond = current_utime % (1000 * 1000);
 282 +         buff_len= snprintf(buff, sizeof buff,
 283 +           "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
 284 +            start.tm_year % 100, start.tm_mon + 1,
 285 +           start.tm_mday, start.tm_hour,
 286 +           start.tm_min, start.tm_sec,microsecond);
 287 +       }
 288 +       else
 289 +       {
 290 +         buff_len= my_snprintf(buff, sizeof buff,
 291 +           "# Time: %02d%02d%02d %2d:%02d:%02d\n",
 292 +            start.tm_year % 100, start.tm_mon + 1,
 293 +           start.tm_mday, start.tm_hour,
 294 +           start.tm_min, start.tm_sec);
 295 +       }
 296
 297          /* Note that my_b_write() assumes it knows the length for this */
 298          if (my_b_write(&log_file, (uchar*) buff, buff_len))
 299 @@ -2710,13 +2735,71 @@
 300      /* For slow query log */
 301      sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
 302      sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
 303 +    DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno));
 304      if (my_b_printf(&log_file,
 305 -                    "# Query_time: %s  Lock_time: %s"
 306 -                    " Rows_sent: %lu  Rows_examined: %lu\n",
 307 +                    "# Thread_id: %lu  Schema: %s  Last_errno: %u  Killed: %u\n" \
 308 +                    "# Query_time: %s  Lock_time: %s  Rows_sent: %lu  Rows_examined: %lu  Rows_affected: %lu  Rows_read: %lu\n"
 309 +                    "# Bytes_sent: %lu  Tmp_tables: %lu  Tmp_disk_tables: %lu  Tmp_table_sizes: %lu\n",
 310 +                    (ulong) thd->thread_id, (thd->db ? thd->db : ""),
 311 +                    thd->last_errno, (uint) thd->killed,
 312                      query_time_buff, lock_time_buff,
 313                      (ulong) thd->sent_row_count,
 314 -                    (ulong) thd->examined_row_count) == (uint) -1)
 315 +                    (ulong) thd->examined_row_count,
 316 +                    ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
 317 +                    (ulong) thd->sent_row_count,
 318 +                    (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
 319 +                    (ulong) thd->tmp_tables_used,
 320 +                    (ulong) thd->tmp_tables_disk_used,
 321 +                    (ulong) thd->tmp_tables_size) == (uint) -1)
 322        tmp_errno= errno;
 323 +
 324 +#if defined(ENABLED_PROFILING)
 325 +    thd->profiling.print_current(&log_file);
 326 +#endif
 327 +    if (thd->innodb_was_used)
 328 +    {
 329 +      char buf[20];
 330 +      snprintf(buf, 20, "%llX", thd->innodb_trx_id);
 331 +      if (my_b_printf(&log_file,
 332 +                    "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
 333 +        tmp_errno=errno;
 334 +    }
 335 +    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
 336 +         my_b_printf(&log_file,
 337 +                    "# QC_Hit: %s  Full_scan: %s  Full_join: %s  Tmp_table: %s  Tmp_table_on_disk: %s\n" \
 338 +                    "# Filesort: %s  Filesort_on_disk: %s  Merge_passes: %lu\n",
 339 +                    ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
 340 +                    ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
 341 +                    ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
 342 +                    ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
 343 +                    ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
 344 +                    ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
 345 +                    ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
 346 +                    thd->query_plan_fsort_passes) == (uint) -1)
 347 +      tmp_errno=errno;
 348 +    if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
 349 +    {
 350 +      char buf[3][20];
 351 +      snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
 352 +      snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
 353 +      snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
 354 +      if (my_b_printf(&log_file,
 355 +                      "#   InnoDB_IO_r_ops: %lu  InnoDB_IO_r_bytes: %lu  InnoDB_IO_r_wait: %s\n" \
 356 +                      "#   InnoDB_rec_lock_wait: %s  InnoDB_queue_wait: %s\n" \
 357 +                      "#   InnoDB_pages_distinct: %lu\n",
 358 +                      (ulong) thd->innodb_io_reads,
 359 +                      (ulong) thd->innodb_io_read,
 360 +                      buf[0], buf[1], buf[2],
 361 +                      (ulong) thd->innodb_page_access) == (uint) -1)
 362 +        tmp_errno=errno;
 363 +    }
 364 +    else
 365 +    {
 366 +      if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
 367 +          my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
 368 +        tmp_errno=errno;
 369 +    }
 370 +
 371      if (thd->db && strcmp(thd->db, db))
 372      {                                          // Database changed
 373        if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
 374 --- a/sql/log.h
 375 +++ b/sql/log.h
 376 @@ -242,7 +242,7 @@
 377               uint user_host_len, int thread_id,
 378               const char *command_type, uint command_type_len,
 379               const char *sql_text, uint sql_text_len);
 380 -  bool write(THD *thd, time_t current_time, time_t query_start_arg,
 381 +  bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
 382               const char *user_host, uint user_host_len,
 383               ulonglong query_utime, ulonglong lock_utime, bool is_command,
 384               const char *sql_text, uint sql_text_len);
 385 @@ -517,7 +517,7 @@
 386    virtual bool init()= 0;
 387    virtual void cleanup()= 0;
 388
 389 -  virtual bool log_slow(THD *thd, time_t current_time,
 390 +  virtual bool log_slow(THD *thd, ulonglong current_time,
 391                          time_t query_start_arg, const char *user_host,
 392                          uint user_host_len, ulonglong query_utime,
 393                          ulonglong lock_utime, bool is_command,
 394 @@ -546,7 +546,7 @@
 395    virtual bool init();
 396    virtual void cleanup();
 397
 398 -  virtual bool log_slow(THD *thd, time_t current_time,
 399 +  virtual bool log_slow(THD *thd, ulonglong current_utime,
 400                          time_t query_start_arg, const char *user_host,
 401                          uint user_host_len, ulonglong query_utime,
 402                          ulonglong lock_utime, bool is_command,
 403 @@ -578,7 +578,7 @@
 404    virtual bool init();
 405    virtual void cleanup();
 406
 407 -  virtual bool log_slow(THD *thd, time_t current_time,
 408 +  virtual bool log_slow(THD *thd, ulonglong current_utime,
 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 --- a/sql/mysqld.cc
 413 +++ b/sql/mysqld.cc
 414 @@ -421,6 +421,11 @@
 415  char* opt_secure_file_priv;
 416  my_bool opt_log_slow_admin_statements= 0;
 417  my_bool opt_log_slow_slave_statements= 0;
 418 +my_bool opt_log_slow_sp_statements= 0;
 419 +my_bool opt_slow_query_log_timestamp_always= 0;
 420 +ulonglong opt_slow_query_log_use_global_control= 0;
 421 +ulong opt_slow_query_log_timestamp_precision= 0;
 422 +ulong opt_slow_query_log_rate_type= 0;
 423  my_bool lower_case_file_system= 0;
 424  my_bool opt_large_pages= 0;
 425  my_bool opt_super_large_pages= 0;
 426 @@ -5892,14 +5897,10 @@
 427     "Don't log extra information to update and slow-query logs.",
 428     &opt_short_log_format, &opt_short_log_format,
 429     0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
 430 -  {"log-slow-admin-statements", 0,
 431 -   "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
 432 -   "the slow log if it is open.", &opt_log_slow_admin_statements,
 433 -   &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
 434 - {"log-slow-slave-statements", 0,
 435 + /*{"log-slow-slave-statements", 0,
 436    "Log slow statements executed by slave thread to the slow log if it is open.",
 437    &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
 438 -  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
 439 +  0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
 440    {"log-slow-queries", OPT_SLOW_QUERY_LOG,
 441     "Log slow queries to a table or log file. Defaults logging to table "
 442     "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
 443 @@ -7288,6 +7289,10 @@
 444
 445  C_MODE_END
 446
 447 +/* defined in sys_vars.cc */
 448 +extern void init_log_slow_verbosity();
 449 +extern void init_slow_query_log_use_global_control();
 450 +
 451  /**
 452    Get server options from the command line,
 453    and perform related server initializations.
 454 @@ -7437,6 +7442,8 @@
 455    global_system_variables.long_query_time= (ulonglong)
 456      (global_system_variables.long_query_time_double * 1e6);
 457
 458 +  init_log_slow_verbosity();
 459 +  init_slow_query_log_use_global_control();
 460    if (opt_short_log_format)
 461      opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
 462
 463 --- a/sql/mysqld.h
 464 +++ b/sql/mysqld.h
 465 @@ -116,6 +116,11 @@
 466  extern char* opt_secure_backup_file_priv;
 467  extern size_t opt_secure_backup_file_priv_len;
 468  extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
 469 +extern my_bool opt_log_slow_sp_statements;
 470 +extern my_bool opt_slow_query_log_timestamp_always;
 471 +extern ulonglong opt_slow_query_log_use_global_control;
 472 +extern ulong opt_slow_query_log_timestamp_precision;
 473 +extern ulong opt_slow_query_log_rate_type;
 474  extern my_bool sp_automatic_privileges, opt_noacl;
 475  extern my_bool opt_old_style_user_limits, trust_function_creators;
 476  extern uint opt_crash_binlog_innodb;
 477 --- a/sql/slave.cc
 478 +++ b/sql/slave.cc
 479 @@ -2038,6 +2038,7 @@
 480      + MAX_LOG_EVENT_HEADER;  /* note, incr over the global not session var */
 481    thd->slave_thread = 1;
 482    thd->enable_slow_log= opt_log_slow_slave_statements;
 483 +  thd->write_to_slow_log= opt_log_slow_slave_statements;
 484    set_slave_thread_options(thd);
 485    thd->client_capabilities = CLIENT_LOCAL_FILES;
 486    mysql_mutex_lock(&LOCK_thread_count);
 487 --- a/sql/sp_head.cc
 488 +++ b/sql/sp_head.cc
 489 @@ -2164,7 +2164,7 @@
 490      DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length,
 491                         m_name.str));
 492    }
 493 -  if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
 494 +  if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
 495    {
 496      DBUG_PRINT("info", ("Disabling slow log for the execution"));
 497      save_enable_slow_log= true;
 498 --- a/sql/sql_cache.cc
 499 +++ b/sql/sql_cache.cc
 500 @@ -1780,6 +1780,7 @@
 501      response, we can't handle it anyway.
 502    */
 503    (void) trans_commit_stmt(thd);
 504 +  thd->query_plan_flags|= QPLAN_QC;
 505    if (!thd->stmt_da->is_set())
 506      thd->stmt_da->disable_status();
 507
 508 @@ -1790,6 +1791,7 @@
 509  err_unlock:
 510    unlock();
 511  err:
 512 +  thd->query_plan_flags|= QPLAN_QC_NO;
 513    MYSQL_QUERY_CACHE_MISS(thd->query());
 514    DBUG_RETURN(0);                              // Query was not cached
 515  }
 516 --- a/sql/sql_class.cc
 517 +++ b/sql/sql_class.cc
 518 @@ -616,6 +616,37 @@
 519    thd->warning_info->inc_current_row_for_warning();
 520  }
 521
 522 +extern "C"
 523 +void increment_thd_innodb_stats(THD* thd,
 524 +                                unsigned long long trx_id,
 525 +                                long io_reads,
 526 +                                long long  io_read,
 527 +                                long      io_reads_wait_timer,
 528 +                                long      lock_que_wait_timer,
 529 +                                long      que_wait_timer,
 530 +                                long      page_access)
 531 +{
 532 +  thd->innodb_was_used=               TRUE;
 533 +  thd->innodb_trx_id=                 trx_id;
 534 +  thd->innodb_io_reads+=              io_reads;
 535 +  thd->innodb_io_read+=               io_read;
 536 +  thd->innodb_io_reads_wait_timer+=   io_reads_wait_timer;
 537 +  thd->innodb_lock_que_wait_timer+=   lock_que_wait_timer;
 538 +  thd->innodb_innodb_que_wait_timer+= que_wait_timer;
 539 +  thd->innodb_page_access+=           page_access;
 540 +}
 541 +
 542 +extern "C"
 543 +unsigned long thd_log_slow_verbosity(const THD *thd)
 544 +{
 545 +  return (unsigned long) thd->variables.log_slow_verbosity;
 546 +}
 547 +
 548 +extern "C"
 549 +int thd_opt_slow_log()
 550 +{
 551 +  return (int) opt_slow_log;
 552 +}
 553
 554  /**
 555    Dumps a text description of a thread, its security context
 556 @@ -942,6 +973,8 @@
 557                             const char* msg,
 558                             MYSQL_ERROR ** cond_hdl)
 559  {
 560 +  last_errno= sql_errno;
 561 +
 562    if (!m_internal_handler)
 563    {
 564      *cond_hdl= NULL;
 565 @@ -1236,6 +1269,8 @@
 566    /* Initialize the Debug Sync Facility. See debug_sync.cc. */
 567    debug_sync_init_thread(this);
 568  #endif /* defined(ENABLED_DEBUG_SYNC) */
 569 +
 570 +  clear_slow_extended();
 571  }
 572
 573
 574 @@ -3687,8 +3722,6 @@
 575    backup->in_sub_stmt=     in_sub_stmt;
 576    backup->enable_slow_log= enable_slow_log;
 577    backup->limit_found_rows= limit_found_rows;
 578 -  backup->examined_row_count= examined_row_count;
 579 -  backup->sent_row_count=   sent_row_count;
 580    backup->cuted_fields=     cuted_fields;
 581    backup->client_capabilities= client_capabilities;
 582    backup->savepoints= transaction.savepoints;
 583 @@ -3696,6 +3729,7 @@
 584      first_successful_insert_id_in_prev_stmt;
 585    backup->first_successful_insert_id_in_cur_stmt=
 586      first_successful_insert_id_in_cur_stmt;
 587 +  reset_sub_statement_state_slow_extended(backup);
 588
 589    if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
 590        !is_current_stmt_binlog_format_row())
 591 @@ -3711,13 +3745,74 @@
 592    /* Disable result sets */
 593    client_capabilities &= ~CLIENT_MULTI_RESULTS;
 594    in_sub_stmt|= new_state;
 595 -  examined_row_count= 0;
 596 -  sent_row_count= 0;
 597    cuted_fields= 0;
 598    transaction.savepoints= 0;
 599    first_successful_insert_id_in_cur_stmt= 0;
 600  }
 601
 602 +void THD::clear_slow_extended()
 603 +{
 604 +  DBUG_ENTER("THD::clear_slow_extended");
 605 +  sent_row_count=               0;
 606 +  examined_row_count=           0;
 607 +  bytes_sent_old=               status_var.bytes_sent;
 608 +  tmp_tables_used=              0;
 609 +  tmp_tables_disk_used=         0;
 610 +  tmp_tables_size=              0;
 611 +  innodb_was_used=              FALSE;
 612 +  innodb_trx_id=                0;
 613 +  innodb_io_reads=              0;
 614 +  innodb_io_read=               0;
 615 +  innodb_io_reads_wait_timer=   0;
 616 +  innodb_lock_que_wait_timer=   0;
 617 +  innodb_innodb_que_wait_timer= 0;
 618 +  innodb_page_access=           0;
 619 +  query_plan_flags=             QPLAN_NONE;
 620 +  query_plan_fsort_passes=      0;
 621 +  last_errno=                   0;
 622 +  DBUG_VOID_RETURN;
 623 +}
 624 +
 625 +void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup)
 626 +{
 627 +  DBUG_ENTER("THD::reset_sub_statement_state_slow_extended");
 628 +  backup->sent_row_count=               sent_row_count;
 629 +  backup->examined_row_count=           examined_row_count;
 630 +  backup->tmp_tables_used=              tmp_tables_used;
 631 +  backup->tmp_tables_disk_used=         tmp_tables_disk_used;
 632 +  backup->tmp_tables_size=              tmp_tables_size;
 633 +  backup->innodb_was_used=              innodb_was_used;
 634 +  backup->innodb_io_reads=              innodb_io_reads;
 635 +  backup->innodb_io_read=               innodb_io_read;
 636 +  backup->innodb_io_reads_wait_timer=   innodb_io_reads_wait_timer;
 637 +  backup->innodb_lock_que_wait_timer=   innodb_lock_que_wait_timer;
 638 +  backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
 639 +  backup->innodb_page_access=           innodb_page_access;
 640 +  backup->query_plan_flags=             query_plan_flags;
 641 +  backup->query_plan_fsort_passes=      query_plan_fsort_passes;
 642 +  clear_slow_extended();
 643 +  DBUG_VOID_RETURN;
 644 +}
 645 +
 646 +void THD::restore_sub_statement_state_slow_extended(const Sub_statement_state *backup)
 647 +{
 648 +  DBUG_ENTER("THD::restore_sub_statement_state_slow_extended");
 649 +  sent_row_count=                backup->sent_row_count;
 650 +  examined_row_count+=           backup->examined_row_count;
 651 +  tmp_tables_used+=              backup->tmp_tables_used;
 652 +  tmp_tables_disk_used+=         backup->tmp_tables_disk_used;
 653 +  tmp_tables_size+=              backup->tmp_tables_size;
 654 +  innodb_was_used=               (innodb_was_used || backup->innodb_was_used);
 655 +  innodb_io_reads+=              backup->innodb_io_reads;
 656 +  innodb_io_read+=               backup->innodb_io_read;
 657 +  innodb_io_reads_wait_timer+=   backup->innodb_io_reads_wait_timer;
 658 +  innodb_lock_que_wait_timer+=   backup->innodb_lock_que_wait_timer;
 659 +  innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
 660 +  innodb_page_access+=           backup->innodb_page_access;
 661 +  query_plan_flags|=             backup->query_plan_flags;
 662 +  query_plan_fsort_passes+=      backup->query_plan_fsort_passes;
 663 +  DBUG_VOID_RETURN;
 664 +}
 665
 666  void THD::restore_sub_statement_state(Sub_statement_state *backup)
 667  {
 668 @@ -3758,7 +3853,6 @@
 669    first_successful_insert_id_in_cur_stmt=
 670      backup->first_successful_insert_id_in_cur_stmt;
 671    limit_found_rows= backup->limit_found_rows;
 672 -  sent_row_count=   backup->sent_row_count;
 673    client_capabilities= backup->client_capabilities;
 674    /*
 675      If we've left sub-statement mode, reset the fatal error flag.
 676 @@ -3776,8 +3870,8 @@
 677      The following is added to the old values as we are interested in the
 678      total complexity of the query
 679    */
 680 -  examined_row_count+= backup->examined_row_count;
 681    cuted_fields+=       backup->cuted_fields;
 682 +  restore_sub_statement_state_slow_extended(backup);
 683    DBUG_VOID_RETURN;
 684  }
 685
 686 @@ -3802,7 +3896,7 @@
 687  {
 688    mysql_mutex_lock(&LOCK_thd_data);
 689    set_query_inner(query_arg, query_length_arg, cs);
 690 -  query_id= new_query_id;
 691 +  do_set_query_id(new_query_id);
 692    mysql_mutex_unlock(&LOCK_thd_data);
 693  }
 694
 695 @@ -3811,9 +3905,25 @@
 696  void THD::set_query_id(query_id_t new_query_id)
 697  {
 698    mysql_mutex_lock(&LOCK_thd_data);
 699 -  query_id= new_query_id;
 700 +  do_set_query_id(new_query_id);
 701    mysql_mutex_unlock(&LOCK_thd_data);
 702  }
 703 +void THD::do_set_query_id(query_id_t new_query_id)
 704 +{
 705 +#ifndef DBUG_OFF
 706 +  if (variables.query_exec_id != 0 &&
 707 +      lex->sql_command != SQLCOM_SET_OPTION)
 708 +  {
 709 +    new_query_id= variables.query_exec_id;
 710 +  }
 711 +#endif /* DBUG_OFF */
 712 +  query_id= new_query_id;
 713 +  if (opt_slow_query_log_rate_type == SLOG_RT_QUERY)
 714 +  {
 715 +    const ulong& limit= variables.log_slow_rate_limit;
 716 +    write_to_slow_log= limit == 0 || (query_id % limit) == 0;
 717 +  }
 718 +}
 719
 720  /** Assign a new value to thd->mysys_var.  */
 721  void THD::set_mysys_var(struct st_my_thread_var *new_mysys_var)
 722 --- a/sql/sql_class.h
 723 +++ b/sql/sql_class.h
 724 @@ -60,6 +60,36 @@
 725  enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
 726  enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
 727                             DELAY_KEY_WRITE_ALL };
 728 +enum enum_slow_query_log_use_global_control {
 729 +  SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT
 730 +  , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME
 731 +  , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL
 732 +};
 733 +enum enum_log_slow_verbosity {
 734 +  SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB,
 735 +  SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
 736 +  SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
 737 +};
 738 +enum enum_slow_query_log_timestamp_precision {
 739 +  SLOG_SECOND, SLOG_MICROSECOND
 740 +};
 741 +enum enum_slow_query_log_rate_type {
 742 +  SLOG_RT_SESSION, SLOG_RT_QUERY
 743 +};
 744 +#define QPLAN_NONE            0
 745 +#define QPLAN_QC              1 << 0
 746 +#define QPLAN_QC_NO           1 << 1
 747 +#define QPLAN_FULL_SCAN       1 << 2
 748 +#define QPLAN_FULL_JOIN       1 << 3
 749 +#define QPLAN_TMP_TABLE       1 << 4
 750 +#define QPLAN_TMP_DISK        1 << 5
 751 +#define QPLAN_FILESORT        1 << 6
 752 +#define QPLAN_FILESORT_DISK   1 << 7
 753 +enum enum_log_slow_filter {
 754 +  SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
 755 +  SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
 756 +  SLOG_F_FILESORT_DISK
 757 +};
 758  enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
 759                              SLAVE_EXEC_MODE_IDEMPOTENT,
 760                              SLAVE_EXEC_MODE_LAST_BIT};
 761 @@ -508,6 +538,22 @@
 762
 763    my_bool sysdate_is_now;
 764
 765 +#ifndef DBUG_OFF
 766 +  ulonglong query_exec_time;
 767 +  double    query_exec_time_double;
 768 +  ulong     query_exec_id;
 769 +#endif
 770 +  ulong log_slow_rate_limit;
 771 +  ulonglong log_slow_filter;
 772 +  ulonglong log_slow_verbosity;
 773 +
 774 +  ulong      innodb_io_reads;
 775 +  ulonglong  innodb_io_read;
 776 +  ulong      innodb_io_reads_wait_timer;
 777 +  ulong      innodb_lock_que_wait_timer;
 778 +  ulong      innodb_innodb_que_wait_timer;
 779 +  ulong      innodb_page_access;
 780 +
 781    double long_query_time_double;
 782
 783  } SV;
 784 @@ -1140,6 +1186,24 @@
 785    uint in_sub_stmt;
 786    bool enable_slow_log;
 787    bool last_insert_id_used;
 788 +
 789 +  /*** Following variables used in slow_extended.patch ***/
 790 +  ulong      tmp_tables_used;
 791 +  ulong      tmp_tables_disk_used;
 792 +  ulonglong  tmp_tables_size;
 793 +
 794 +  bool       innodb_was_used;
 795 +  ulong      innodb_io_reads;
 796 +  ulonglong  innodb_io_read;
 797 +  ulong      innodb_io_reads_wait_timer;
 798 +  ulong      innodb_lock_que_wait_timer;
 799 +  ulong      innodb_innodb_que_wait_timer;
 800 +  ulong      innodb_page_access;
 801 +
 802 +  ulong      query_plan_flags;
 803 +  ulong      query_plan_fsort_passes;
 804 +  /*** The variables above used in slow_extended.patch ***/
 805 +
 806    SAVEPOINT *savepoints;
 807    enum enum_check_fields count_cuted_fields;
 808  };
 809 @@ -1588,6 +1652,71 @@
 810    thr_lock_type update_lock_default;
 811    Delayed_insert *di;
 812
 813 +  /*** Following variables used in slow_extended.patch ***/
 814 +  /*
 815 +    Variable write_to_slow_log:
 816 +     1) initialized in
 817 +       * sql_connect.cc (log_slow_rate_limit support)
 818 +       * slave.cc       (log_slow_slave_statements support)
 819 +     2) The variable is initialized on the thread startup and remains
 820 +        constant afterwards.  This will change when
 821 +        LP #712396 ("log_slow_slave_statements not work on replication
 822 +        threads without RESTART") is implemented.
 823 +     3) An implementation of LP #688646 ("Make query sampling possible by query") should use it.
 824 +  */
 825 +  bool       write_to_slow_log;
 826 +  /*
 827 +    Variable bytes_send_old saves value of thd->status_var.bytes_sent
 828 +    before query execution.
 829 +  */
 830 +  ulonglong  bytes_sent_old;
 831 +  /*
 832 +    Variables tmp_tables_*** collect statistics about usage of temporary tables
 833 +  */
 834 +  ulong      tmp_tables_used;
 835 +  ulong      tmp_tables_disk_used;
 836 +  ulonglong  tmp_tables_size;
 837 +  /*
 838 +    Variable innodb_was_used shows used or not InnoDB engine in current query.
 839 +  */
 840 +  bool       innodb_was_used;
 841 +  /*
 842 +    Following Variables innodb_*** (is |should be) different from
 843 +    default values only if (innodb_was_used==TRUE)
 844 +  */
 845 +  ulonglong  innodb_trx_id;
 846 +  ulong      innodb_io_reads;
 847 +  ulonglong  innodb_io_read;
 848 +  ulong      innodb_io_reads_wait_timer;
 849 +  ulong      innodb_lock_que_wait_timer;
 850 +  ulong      innodb_innodb_que_wait_timer;
 851 +  ulong      innodb_page_access;
 852 +
 853 +  /*
 854 +    Variable query_plan_flags collects information about query plan entites
 855 +    used on query execution.
 856 +  */
 857 +  ulong      query_plan_flags;
 858 +  /*
 859 +    Variable query_plan_fsort_passes collects information about file sort passes
 860 +    acquired during query execution.
 861 +  */
 862 +  ulong      query_plan_fsort_passes;
 863 +  /*
 864 +    Query can generate several errors/warnings during execution
 865 +    (see THD::handle_condition comment in sql_class.h)
 866 +    Variable last_errno contains the last error/warning acquired during
 867 +    query execution.
 868 +  */
 869 +  uint       last_errno;
 870 +  /*** The variables above used in slow_extended.patch ***/
 871 +
 872 +  /*** Following methods used in slow_extended.patch ***/
 873 +  void clear_slow_extended();
 874 +  void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
 875 +  void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup);
 876 +  /*** The methods above used in slow_extended.patch ***/
 877 +
 878    /* <> 0 if we are inside of trigger or stored function. */
 879    uint in_sub_stmt;
 880
 881 @@ -2784,6 +2913,9 @@
 882    void set_query_and_id(char *query_arg, uint32 query_length_arg,
 883                          CHARSET_INFO *cs, query_id_t new_query_id);
 884    void set_query_id(query_id_t new_query_id);
 885 +private:
 886 +  void do_set_query_id(query_id_t new_query_id);
 887 +public:
 888    void set_open_tables(TABLE *open_tables_arg)
 889    {
 890      mysql_mutex_lock(&LOCK_thd_data);
 891 --- a/sql/sql_connect.cc
 892 +++ b/sql/sql_connect.cc
 893 @@ -721,6 +721,14 @@
 894    MYSQL_CONNECTION_START(thd->thread_id, &thd->security_ctx->priv_user[0],
 895                           (char *) thd->security_ctx->host_or_ip);
 896
 897 +  /*
 898 +    If rate limiting of slow log writes is enabled, decide whether to log this
 899 +    new thread's queries or not. Uses extremely simple algorithm. :)
 900 +  */
 901 +  const ulong& limit= thd->variables.log_slow_rate_limit;
 902 +  thd->write_to_slow_log= opt_slow_query_log_rate_type == SLOG_RT_SESSION &&
 903 +                          (limit == 0 || (thd->thread_id % limit) == 0);
 904 +
 905    prepare_new_connection_state(thd);
 906    return FALSE;
 907  }
 908 --- a/sql/sql_parse.cc
 909 +++ b/sql/sql_parse.cc
 910 @@ -114,6 +114,7 @@
 911
 912  static bool execute_sqlcom_select(THD *thd, TABLE_LIST *all_tables);
 913  static void sql_kill(THD *thd, ulong id, bool only_kill_query);
 914 +static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime);
 915
 916  const char *any_db="*any*";    // Special symbol for check_access
 917
 918 @@ -890,6 +891,7 @@
 919      the slow log only if opt_log_slow_admin_statements is set.
 920    */
 921    thd->enable_slow_log= TRUE;
 922 +  thd->clear_slow_extended();
 923    thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
 924    thd->set_time();
 925    if (!thd->is_valid_time())
 926 @@ -1440,6 +1442,60 @@
 927    DBUG_RETURN(error);
 928  }
 929
 930 +/**
 931 +   Calculate execution time for the current query.
 932 +
 933 +   For debug builds, check the session value of query_exec_time
 934 +   and if it is not zero, return it instead of the actual execution time.
 935 +
 936 +   SET queries are ignored so that statements changing query_exec_time are not
 937 +   affected by themselves.
 938 +
 939 +   @param thd              thread handle
 940 +   @param lex              current relative time in microseconds
 941 +
 942 +   @return                 time in microseconds from utime_after_lock
 943 +*/
 944 +
 945 +static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
 946 +{
 947 +  ulonglong res;
 948 +#ifndef DBUG_OFF
 949 +  if (thd->variables.query_exec_time != 0)
 950 +    res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
 951 +      thd->variables.query_exec_time : 0;
 952 +  else
 953 +#endif
 954 +
 955 +  res= cur_utime - thd->utime_after_lock;
 956 +
 957 +  if (res > thd->variables.long_query_time)
 958 +    thd->server_status|= SERVER_QUERY_WAS_SLOW;
 959 +  else
 960 +    thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
 961 +
 962 +  return res;
 963 +}
 964 +
 965 +
 966 +static inline void copy_global_to_session(THD *thd, ulong flag,
 967 +                                          const ulong *val)
 968 +{
 969 +  my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
 970 +  if (opt_slow_query_log_use_global_control & (1ULL << flag))
 971 +    *(ulong *)((char *) &thd->variables + offset) = *val;
 972 +}
 973 +
 974 +
 975 +static inline void copy_global_to_session(THD *thd, ulong flag,
 976 +                                          const ulonglong *val)
 977 +{
 978 +  my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
 979 +  if (opt_slow_query_log_use_global_control & (1ULL << flag))
 980 +    *(ulonglong *)((char *) &thd->variables + offset) = *val;
 981 +}
 982 +
 983 +
 984
 985  void log_slow_statement(THD *thd)
 986  {
 987 @@ -1453,13 +1509,47 @@
 988    if (unlikely(thd->in_sub_stmt))
 989      DBUG_VOID_RETURN;                           // Don't set time for sub stmt
 990
 991 +  /* Follow the slow log filter configuration. */
 992 +  if (thd->variables.log_slow_filter != 0 &&
 993 +      (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
 994 +       ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
 995 +        (thd->query_plan_flags & QPLAN_QC))))
 996 +    DBUG_VOID_RETURN;
 997 +
 998 +  ulonglong end_utime_of_query= thd->current_utime();
 999 +  ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query);
1000 +
1001 +  /*
1002 +    Low long_query_time value most likely means user is debugging stuff and even
1003 +    though some thread's queries are not supposed to be logged b/c of the rate
1004 +    limit, if one of them takes long enough (>= 1 second) it will be sensible
1005 +    to make an exception and write to slow log anyway.
1006 +  */
1007 +
1008 +  system_variables const &g= global_system_variables;
1009 +  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_FILTER,
1010 +                         &g.log_slow_filter);
1011 +  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_RATE_LIMIT,
1012 +                         &g.log_slow_rate_limit);
1013 +  copy_global_to_session(thd, SLOG_UG_LOG_SLOW_VERBOSITY,
1014 +                         &g.log_slow_verbosity);
1015 +  copy_global_to_session(thd, SLOG_UG_LONG_QUERY_TIME,
1016 +                         &g.long_query_time);
1017 +  copy_global_to_session(thd, SLOG_UG_MIN_EXAMINED_ROW_LIMIT,
1018 +                         &g.min_examined_row_limit);
1019 +
1020 +  /* Do not log this thread's queries due to rate limiting. */
1021 +  if (!thd->write_to_slow_log && (thd->variables.long_query_time >= 1000000
1022 +                                  || (ulong) query_exec_time < 1000000))
1023 +    DBUG_VOID_RETURN;
1024 +
1025 +
1026    /*
1027      Do not log administrative statements unless the appropriate option is
1028      set.
1029    */
1030    if (thd->enable_slow_log)
1031    {
1032 -    ulonglong end_utime_of_query= thd->current_utime();
1033      thd_proc_info(thd, "logging slow query");
1034
1035      if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
1036 @@ -5368,7 +5459,8 @@
1037    thd->stmt_da->reset_diagnostics_area();
1038    thd->warning_info->reset_for_next_command();
1039    thd->rand_used= 0;
1040 -  thd->sent_row_count= thd->examined_row_count= 0;
1041 +
1042 +  thd->clear_slow_extended();
1043
1044    thd->reset_current_stmt_binlog_format_row();
1045    thd->binlog_unsafe_warning_flags= 0;
1046 --- a/sql/sql_select.cc
1047 +++ b/sql/sql_select.cc
1048 @@ -6912,7 +6912,10 @@
1049           {
1050             join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
1051             if (statistics)
1052 +            {
1053               status_var_increment(join->thd->status_var.select_scan_count);
1054 +              join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
1055 +            }
1056           }
1057         }
1058         else
1059 @@ -6926,7 +6929,10 @@
1060           {
1061             join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
1062             if (statistics)
1063 +            {
1064               status_var_increment(join->thd->status_var.select_full_join_count);
1065 +              join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
1066 +            }
1067           }
1068         }
1069         if (!table->no_keyread)
1070 @@ -10274,6 +10280,7 @@
1071                (ulong) rows_limit,test(group)));
1072
1073    status_var_increment(thd->status_var.created_tmp_tables);
1074 +  thd->query_plan_flags|= QPLAN_TMP_TABLE;
1075
1076    if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
1077      temp_pool_slot = bitmap_lock_set_next(&temp_pool);
1078 @@ -11175,6 +11182,7 @@
1079      goto err;
1080    }
1081    status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
1082 +  table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
1083    share->db_record_offset= 1;
1084    DBUG_RETURN(0);
1085   err:
1086 @@ -11193,6 +11201,14 @@
1087    save_proc_info=thd->proc_info;
1088    thd_proc_info(thd, "removing tmp table");
1089
1090 +  thd->tmp_tables_used++;
1091 +  if (entry->file)
1092 +  {
1093 +    thd->tmp_tables_size += entry->file->stats.data_file_length;
1094 +    if (entry->file->ht->db_type != DB_TYPE_HEAP)
1095 +      thd->tmp_tables_disk_used++;
1096 +  }
1097 +
1098    // Release latches since this can take a long time
1099    ha_release_temporary_latches(thd);
1100
1101 --- a/sql/sql_show.cc
1102 +++ b/sql/sql_show.cc
1103 @@ -1950,8 +1950,17 @@
1104          table->field[4]->store(command_name[tmp->command].str,
1105                                 command_name[tmp->command].length, cs);
1106        /* MYSQL_TIME */
1107 -      table->field[5]->store((longlong)(tmp->start_time ?
1108 -                                      now - tmp->start_time : 0), FALSE);
1109 +      longlong value_in_time_column= 0;
1110 +      if(tmp->start_time)
1111 +      {
1112 +        value_in_time_column = (now - tmp->start_time);
1113 +        if(value_in_time_column > now)
1114 +        {
1115 +          value_in_time_column= 0;
1116 +        }
1117 +      }
1118 +      table->field[5]->store(value_in_time_column, FALSE);
1119 +
1120        /* STATE */
1121        if ((val= thread_state_info(tmp)))
1122        {
1123 --- a/sql/sys_vars.cc
1124 +++ b/sql/sys_vars.cc
1125 @@ -972,6 +972,36 @@
1126         NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
1127         ON_UPDATE(update_cached_long_query_time));
1128
1129 +#ifndef DBUG_OFF
1130 +static bool update_cached_query_exec_time(sys_var *self, THD *thd,
1131 +                                          enum_var_type type)
1132 +{
1133 +  if (type == OPT_SESSION)
1134 +    thd->variables.query_exec_time=
1135 +      double2ulonglong(thd->variables.query_exec_time_double * 1e6);
1136 +  else
1137 +    global_system_variables.query_exec_time=
1138 +      double2ulonglong(global_system_variables.query_exec_time_double * 1e6);
1139 +  return false;
1140 +}
1141 +
1142 +static Sys_var_double Sys_query_exec_time(
1143 +       "query_exec_time",
1144 +       "Pretend queries take this many seconds. When 0 (the default) use the "
1145 +       "actual execution time. Used only for debugging.",
1146 +       SESSION_VAR(query_exec_time_double),
1147 +       NO_CMD_LINE, VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(0),
1148 +       NO_MUTEX_GUARD, IN_BINLOG, ON_CHECK(0),
1149 +       ON_UPDATE(update_cached_query_exec_time));
1150 +static Sys_var_ulong sys_query_exec_id(
1151 +       "query_exec_id",
1152 +       "Pretend queries take this query id. When 0 (the default) use the"
1153 +       "actual query id. Used only for debugging.",
1154 +       SESSION_VAR(query_exec_id),
1155 +       NO_CMD_LINE, VALID_RANGE(0, ULONG_MAX), DEFAULT(0), BLOCK_SIZE(1),
1156 +       NO_MUTEX_GUARD, IN_BINLOG);
1157 +#endif
1158 +
1159  static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type)
1160  {
1161    if (type == OPT_SESSION)
1162 @@ -2898,6 +2928,134 @@
1163         DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
1164         ON_UPDATE(fix_log_state));
1165
1166 +const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
1167 +                                      "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
1168 +static Sys_var_set Sys_log_slow_filter(
1169 +       "log_slow_filter",
1170 +       "Log only the queries that followed certain execution plan. "
1171 +       "Multiple flags allowed in a comma-separated string. "
1172 +       "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
1173 +       "filesort, filesort_on_disk]",
1174 +       SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
1175 +       log_slow_filter_name, DEFAULT(0));
1176 +static Sys_var_ulong sys_log_slow_rate_limit(
1177 +       "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
1178 +       SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
1179 +       VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
1180 +const char* log_slow_verbosity_name[] = {
1181 +  "microtime", "query_plan", "innodb",
1182 +  "profiling", "profling_use_getrusage",
1183 +  "minimal", "standard", "full", 0
1184 +};
1185 +static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
1186 +{
1187 +  if((value & what) == what)
1188 +  {
1189 +    value = value & (~what);
1190 +    value = value | by;
1191 +  }
1192 +  return value;
1193 +}
1194 +void update_log_slow_verbosity(ulonglong* value_ptr)
1195 +{
1196 +  ulonglong &value    = *value_ptr;
1197 +  ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
1198 +  ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
1199 +  ulonglong innodb= ULL(1) << SLOG_V_INNODB;
1200 +  ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
1201 +  ulonglong standard= ULL(1) << SLOG_V_STANDARD;
1202 +  ulonglong full= ULL(1) << SLOG_V_FULL;
1203 +  value= update_log_slow_verbosity_replace(value,minimal,microtime);
1204 +  value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
1205 +  value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
1206 +}
1207 +static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
1208 +                                          enum_var_type type)
1209 +{
1210 +  if(type == OPT_SESSION)
1211 +  {
1212 +    update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
1213 +  }
1214 +  else
1215 +  {
1216 +    update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
1217 +  }
1218 +  return false;
1219 +}
1220 +void init_slow_query_log_use_global_control()
1221 +{
1222 +  update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
1223 +}
1224 +static Sys_var_set Sys_log_slow_verbosity(
1225 +        "log_slow_verbosity",
1226 +        "Choose how verbose the messages to your slow log will be. "
1227 +        "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
1228 +        SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
1229 +        log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
1230 +        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
1231 +        ON_UPDATE(update_log_slow_verbosity_helper));
1232 +static Sys_var_mybool Sys_log_slow_slave_statements(
1233 +       "log_slow_slave_statements",
1234 +       "Log queries replayed be the slave SQL thread",
1235 +       GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
1236 +       DEFAULT(FALSE));
1237 +static Sys_var_mybool Sys_log_slow_admin_statements(
1238 +       "log_slow_admin_statements",
1239 +       "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements"
1240 +       " to the slow log if it is open.",
1241 +       GLOBAL_VAR(opt_log_slow_admin_statements), CMD_LINE(OPT_ARG),
1242 +       DEFAULT(FALSE));
1243 +static Sys_var_mybool Sys_log_slow_sp_statements(
1244 +       "log_slow_sp_statements",
1245 +       "Log slow statements executed by stored procedure to the slow log if it is open.",
1246 +       GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
1247 +       DEFAULT(TRUE));
1248 +static Sys_var_mybool Sys_slow_query_log_timestamp_always(
1249 +       "slow_query_log_timestamp_always",
1250 +       "Timestamp is printed for all records of the slow log even if they are same time.",
1251 +       GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG),
1252 +       DEFAULT(FALSE));
1253 +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};
1254 +static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/,
1255 +                                               enum_var_type /*type*/)
1256 +{
1257 +  if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
1258 +  {
1259 +    opt_slow_query_log_use_global_control=
1260 +      SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
1261 +      SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
1262 +  }
1263 +  return false;
1264 +}
1265 +void init_log_slow_verbosity()
1266 +{
1267 +  update_slow_query_log_use_global_control(0,0,OPT_GLOBAL);
1268 +}
1269 +static Sys_var_set Sys_slow_query_log_use_global_control(
1270 +       "slow_query_log_use_global_control",
1271 +       "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]",
1272 +       GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG),
1273 +       slow_query_log_use_global_control_name, DEFAULT(0),
1274 +        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
1275 +       ON_UPDATE(update_slow_query_log_use_global_control));
1276 +const char *slow_query_log_timestamp_precision_name[]= { "second", "microsecond", 0 };
1277 +static Sys_var_enum Sys_slow_query_log_timestamp_precision(
1278 +       "slow_query_log_timestamp_precision",
1279 +       "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]",
1280 +       GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
1281 +       slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
1282 +
1283 +const char* slow_query_log_rate_name[]= {"session", "query", 0};
1284 +static Sys_var_enum Sys_slow_query_log_rate_type(
1285 +       "log_slow_rate_type",
1286 +       "Choose the log_slow_rate_limit behavior: session or query. "
1287 +       "When you choose 'session' - every %log_slow_rate_limit connection "
1288 +       "will be processed to slow query log. "
1289 +       "When you choose 'query' - every %log_slow_rate_limit query "
1290 +       "will be processed to slow query log. "
1291 +       "[session, query]",
1292 +       GLOBAL_VAR(opt_slow_query_log_rate_type), CMD_LINE(REQUIRED_ARG),
1293 +       slow_query_log_rate_name, DEFAULT(SLOG_RT_SESSION));
1294  /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
1295  static Sys_var_mybool Sys_log_slow(
1296         "log_slow_queries",
1297 --- a/sql/sql_profile.cc
1298 +++ b/sql/sql_profile.cc
1299 @@ -243,7 +243,8 @@
1300  {
1301    time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
1302  #ifdef HAVE_GETRUSAGE
1303 -  getrusage(RUSAGE_SELF, &rusage);
1304 +  if ((profile->get_profiling())->enabled_getrusage())
1305 +    getrusage(RUSAGE_SELF, &rusage);
1306  #elif defined(_WIN32)
1307    FILETIME ftDummy;
1308    // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
1309 @@ -251,6 +252,19 @@
1310    // measurable by this function.
1311    GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
1312  #endif
1313 +
1314 +#ifdef HAVE_CLOCK_GETTIME
1315 +  struct timespec tp;
1316 +
1317 +  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
1318 +  {
1319 +    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
1320 +  }
1321 +  else
1322 +#endif
1323 +  {
1324 +    cpu_time_usecs= 0;
1325 +  }
1326  }
1327
1328
1329 @@ -366,7 +380,8 @@
1330      finish_current_query();
1331    }
1332
1333 -  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
1334 +  enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1335 +            ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
1336
1337    if (! enabled) DBUG_VOID_RETURN;
1338
1339 @@ -404,7 +419,8 @@
1340      status_change("ending", NULL, NULL, 0);
1341
1342      if ((enabled) &&                                    /* ON at start? */
1343 -        ((thd->variables.option_bits & OPTION_PROFILING) != 0) &&   /* and ON at end? */
1344 +        (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1345 +          ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) &&   /* and ON at end? */
1346          (current->query_source != NULL) &&
1347          (! current->entries.is_empty()))
1348      {
1349 @@ -505,6 +521,118 @@
1350    DBUG_VOID_RETURN;
1351  }
1352
1353 +bool PROFILING::enabled_getrusage()
1354 +{
1355 +  return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
1356 +}
1357 +
1358 +/**
1359 +   For a given profile entry specified by a name and 2 time measurements,
1360 +   print its normalized name (i.e. with all spaces replaced with underscores)
1361 +   along with its wall clock and CPU time.
1362 +*/
1363 +
1364 +static void my_b_print_status(IO_CACHE *log_file, const char *status,
1365 +                              PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
1366 +{
1367 +  DBUG_ENTER("my_b_print_status");
1368 +  DBUG_ASSERT(log_file != NULL && status != NULL);
1369 +  char query_time_buff[22+7];
1370 +  const char *tmp;
1371 +
1372 +  my_b_printf(log_file, "Profile_");
1373 +  for (tmp= status; *tmp; tmp++)
1374 +    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1375 +
1376 +  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1377 +           (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
1378 +  my_b_printf(log_file, ": %s ", query_time_buff);
1379 +
1380 +  my_b_printf(log_file, "Profile_");
1381 +  for (tmp= status; *tmp; tmp++)
1382 +    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1383 +  my_b_printf(log_file, "_cpu: ");
1384 +
1385 +  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1386 +           (stop->cpu_time_usecs - start->cpu_time_usecs) /
1387 +           (1000.0 * 1000 * 1000));
1388 +  my_b_printf(log_file, "%s ", query_time_buff);
1389 +
1390 +  DBUG_VOID_RETURN;
1391 +}
1392 +
1393 +/**
1394 +  Print output for current query to file
1395 +*/
1396 +
1397 +int PROFILING::print_current(IO_CACHE *log_file)
1398 +{
1399 +  DBUG_ENTER("PROFILING::print_current");
1400 +  ulonglong row_number= 0;
1401 +
1402 +  QUERY_PROFILE *query;
1403 +  /* Get current query */
1404 +  if (current == NULL)
1405 +  {
1406 +    DBUG_RETURN(0);
1407 +  }
1408 +
1409 +  query= current;
1410 +
1411 +  my_b_printf(log_file, "# ");
1412 +
1413 +    void *entry_iterator;
1414 +    PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
1415 +    /* ...and for each query, go through all its state-change steps. */
1416 +    for (entry_iterator= query->entries.new_iterator();
1417 +         entry_iterator != NULL;
1418 +         entry_iterator= query->entries.iterator_next(entry_iterator),
1419 +         previous=entry, row_number++)
1420 +    {
1421 +      entry= query->entries.iterator_value(entry_iterator);
1422 +
1423 +      /* Skip the first.  We count spans of fence, not fence-posts. */
1424 +      if (previous == NULL) {first= entry; continue;}
1425 +
1426 +      if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
1427 +      {
1428 +        /*
1429 +          We got here via a SHOW command.  That means that we stored
1430 +          information about the query we wish to show and that isn't
1431 +          in a WHERE clause at a higher level to filter out rows we
1432 +          wish to exclude.
1433 +
1434 +          Because that functionality isn't available in the server yet,
1435 +          we must filter here, at the wrong level.  Once one can con-
1436 +          struct where and having conditions at the SQL layer, then this
1437 +          condition should be ripped out.
1438 +        */
1439 +        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
1440 +        {
1441 +          if (query != last)
1442 +            continue;
1443 +        }
1444 +        else
1445 +        {
1446 +          if (thd->lex->profile_query_id != query->profiling_query_id)
1447 +            continue;
1448 +        }
1449 +      }
1450 +
1451 +      my_b_print_status(log_file, previous->status, previous, entry);
1452 +    }
1453 +
1454 +    my_b_write_byte(log_file, '\n');
1455 +    if ((entry != NULL) && (first != NULL))
1456 +    {
1457 +      my_b_printf(log_file, "# ");
1458 +      my_b_print_status(log_file, "total", first, entry);
1459 +      my_b_write_byte(log_file, '\n');
1460 +    }
1461 +
1462 +  DBUG_RETURN(0);
1463 +}
1464 +
1465  /**
1466    Fill the information schema table, "query_profile", as defined in show.cc .
1467    There are two ways to get to this function:  Selecting from the information
1468 @@ -600,6 +728,8 @@
1469
1470  #ifdef HAVE_GETRUSAGE
1471
1472 +      if (enabled_getrusage())
1473 +      {
1474        my_decimal cpu_utime_decimal, cpu_stime_decimal;
1475
1476        double2my_decimal(E_DEC_FATAL_ERROR,
1477 @@ -687,6 +817,7 @@
1478        table->field[14]->store((uint32)(entry->rusage.ru_nswap -
1479                               previous->rusage.ru_nswap), true);
1480        table->field[14]->set_notnull();
1481 +      }
1482  #else
1483        /* TODO: Add swap info for non-BSD systems */
1484  #endif
1485 --- a/sql/sql_profile.h
1486 +++ b/sql/sql_profile.h
1487 @@ -164,11 +164,15 @@
1488  */
1489  class PROF_MEASUREMENT
1490  {
1491 -private:
1492 -  friend class QUERY_PROFILE;
1493 -  friend class PROFILING;
1494 -
1495    QUERY_PROFILE *profile;
1496 +
1497 +  char *allocated_status_memory;
1498 +
1499 +  void set_label(const char *status_arg, const char *function_arg,
1500 +                  const char *file_arg, unsigned int line_arg);
1501 +  void clean_up();
1502 +
1503 +public:
1504    char *status;
1505  #ifdef HAVE_GETRUSAGE
1506    struct rusage rusage;
1507 @@ -181,12 +185,7 @@
1508    unsigned int line;
1509
1510    double time_usecs;
1511 -  char *allocated_status_memory;
1512 -
1513 -  void set_label(const char *status_arg, const char *function_arg,
1514 -                  const char *file_arg, unsigned int line_arg);
1515 -  void clean_up();
1516 -
1517 +  double cpu_time_usecs;
1518    PROF_MEASUREMENT();
1519    PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
1520    PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
1521 @@ -231,6 +230,11 @@
1522
1523    /* Show this profile.  This is called by PROFILING. */
1524    bool show(uint options);
1525 +
1526 +public:
1527 +
1528 +  inline PROFILING * get_profiling() { return profiling; };
1529 +
1530  };
1531
1532
1533 @@ -276,9 +280,11 @@
1534
1535    /* SHOW PROFILES */
1536    bool show_profiles();
1537 +  bool enabled_getrusage();
1538
1539    /* ... from INFORMATION_SCHEMA.PROFILING ... */
1540    int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
1541 +  int print_current(IO_CACHE *log_file);
1542  };
1543
1544  #  endif /* HAVE_PROFILING */
1545 --- /dev/null
1546 +++ b/mysql-test/include/log_grep.inc
1547 @@ -0,0 +1,41 @@
1548 +--echo [log_grep.inc] file: $log_file pattern: $grep_pattern
1549 +perl;
1550 +  $log_file=           $ENV{'log_file'};
1551 +  $log_file_full_path= $ENV{'log_file_full_path'};
1552 +  $log_slow_rate_test= $ENV{'log_slow_rate_test'};
1553 +  open(FILE, "$log_file_full_path")
1554 +    or die("Cannot open file $log_file_full_path: $!\n");
1555 +
1556 +  if ($log_slow_rate_test) {
1557 +    $one= 0;
1558 +    $two= 0;
1559 +    $three= 0;
1560 +    while(<FILE>) {
1561 +      $one++   if(/'connection_one'/);
1562 +      $two++   if(/'connection_two'/);
1563 +      $three++ if(/'connection_three'/);
1564 +    }
1565 +    $sum= $one + $two + $three;
1566 +    $zero= 0;
1567 +    if ($one == 0) {
1568 +      $zero++;
1569 +    }
1570 +    if ($two == 0) {
1571 +      $zero++;
1572 +    }
1573 +    if ($three == 0) {
1574 +      $zero++;
1575 +    }
1576 +    print "[log_grep.inc] sum:  $sum\n";
1577 +    print "[log_grep.inc] zero: $zero\n";
1578 +  }
1579 +  else {
1580 +    $grep_pattern=       $ENV{'grep_pattern'};
1581 +    $lines= 0;
1582 +    while(<FILE>) {
1583 +      $lines++ if (/$grep_pattern/);
1584 +    }
1585 +    print "[log_grep.inc] lines:   $lines\n";
1586 +  }
1587 +  close(FILE);
1588 +EOF
1589 --- /dev/null
1590 +++ b/mysql-test/include/log_start.inc
1591 @@ -0,0 +1,16 @@
1592 +--disable_query_log
1593 +--let log_file_full_path = $MYSQLTEST_VARDIR/$log_file
1594 +SET @slow_query_log_old=@@slow_query_log;
1595 +SET @slow_query_log_file_old= @@slow_query_log_file;
1596 +SET GLOBAL slow_query_log=OFF;
1597 +perl;
1598 +  $log_file_full_path= $ENV{'log_file_full_path'};
1599 +  unlink $log_file_full_path;
1600 +  open(FILE, '>', $log_file_full_path)
1601 +    or die "Cannot create log file $log_file_full_path, reason: $!";
1602 +  close(FILE);
1603 +EOF
1604 +--echo [log_start.inc] $log_file
1605 +EVAL SET GLOBAL slow_query_log_file="$log_file_full_path";
1606 +SET GLOBAL slow_query_log=ON;
1607 +--enable_query_log
1608 --- /dev/null
1609 +++ b/mysql-test/include/log_stop.inc
1610 @@ -0,0 +1,7 @@
1611 +--disable_query_log
1612 +FLUSH LOGS;
1613 +SET GLOBAL slow_query_log=OFF;
1614 +--echo [log_stop.inc] $log_file
1615 +SET GLOBAL slow_query_log_file= @slow_query_log_file_old;
1616 +SET GLOBAL slow_query_log=      @slow_query_log_old;
1617 +--enable_query_log
1618 --- /dev/null
1619 +++ b/mysql-test/r/percona_bug643149.result
1620 @@ -0,0 +1,21 @@
1621 +SET @old_slow_query_log_file=@@global.slow_query_log_file;
1622 +SET GLOBAL slow_query_log=on;
1623 +SET LOCAL log_slow_verbosity='profiling';
1624 +SET LOCAL long_query_time=0;
1625 +SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';;
1626 +SELECT 1;
1627 +1
1628 +1
1629 +# User@Host: root[root] @ localhost []
1630 +# Thread_id: X  Schema: test  Last_errno: X  Killed: X
1631 +# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
1632 +# Bytes_sent: X  Tmp_tables: X  Tmp_disk_tables: X  Tmp_table_sizes: X
1633 +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X
1634 +# Profile_total: X.X Profile_total_cpu: X.X
1635 +# User@Host: root[root] @ localhost []
1636 +# Thread_id: X  Schema: test  Last_errno: X  Killed: X
1637 +# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
1638 +# Bytes_sent: X  Tmp_tables: X  Tmp_disk_tables: X  Tmp_table_sizes: X
1639 +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X
1640 +# Profile_total: X.X Profile_total_cpu: X.X
1641 +SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
1642 --- /dev/null
1643 +++ b/mysql-test/r/percona_log_slow_filter-cl.result
1644 @@ -0,0 +1,6 @@
1645 +SHOW VARIABLES LIKE 'log_slow_filter';
1646 +Variable_name  Value
1647 +log_slow_filter        full_join
1648 +SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
1649 +Variable_name  Value
1650 +log_slow_filter        full_join
1651 --- /dev/null
1652 +++ b/mysql-test/r/percona_log_slow_filter.result
1653 @@ -0,0 +1,16 @@
1654 +CREATE TABLE t(id INT PRIMARY KEY);
1655 +INSERT INTO t VALUES(1);
1656 +INSERT INTO t VALUES(2);
1657 +INSERT INTO t VALUES(3);
1658 +SET long_query_time=1;
1659 +SET log_slow_filter=full_join;
1660 +[log_start.inc] percona.slow_extended.log_slow_filter
1661 +SET query_exec_time = 1.1;
1662 +SELECT * FROM t AS t1, t AS t2;
1663 +SET query_exec_time = default;
1664 +[log_stop.inc] percona.slow_extended.log_slow_filter
1665 +SET log_slow_filter=default;
1666 +SET long_query_time=default;
1667 +[log_grep.inc] file: percona.slow_extended.log_slow_filter pattern: Query_time
1668 +[log_grep.inc] lines:   1
1669 +DROP TABLE t;
1670 --- /dev/null
1671 +++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result
1672 @@ -0,0 +1,6 @@
1673 +SHOW VARIABLES LIKE 'log_slow_slave_statements';
1674 +Variable_name  Value
1675 +log_slow_slave_statements      ON
1676 +SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
1677 +Variable_name  Value
1678 +log_slow_slave_statements      ON
1679 --- /dev/null
1680 +++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result
1681 @@ -0,0 +1,19 @@
1682 +include/master-slave.inc
1683 +[connection master]
1684 +DROP TABLE IF EXISTS t;
1685 +CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
1686 +INSERT INTO t VALUES
1687 +(1,"aaaaabbbbbcccccdddddeeeeefffff"),
1688 +(2,"aaaaabbbbbcccccdddddeeeeefffff"),
1689 +(3,"aaaaabbbbbcccccdddddeeeeefffff"),
1690 +(4,"aaaaabbbbbcccccdddddeeeeefffff"),
1691 +(5,"aaaaabbbbbcccccdddddeeeeefffff");
1692 +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
1693 +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
1694 +[log_start.inc] percona.slow_extended.log_slow_slave_statements-innodb
1695 +INSERT INTO t SELECT t.id,t.data from t;
1696 +[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb
1697 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops
1698 +[log_grep.inc] lines:   1
1699 +DROP TABLE t;
1700 +include/rpl_end.inc
1701 --- /dev/null
1702 +++ b/mysql-test/r/percona_log_slow_slave_statements.result
1703 @@ -0,0 +1,45 @@
1704 +include/master-slave.inc
1705 +[connection master]
1706 +DROP TABLE IF EXISTS t;
1707 +CREATE TABLE t(id INT);
1708 +[log_start.inc] percona.slow_extended.log_slow_slave_statements
1709 +LINE 1
1710 +LOG_SLOW_SLAVE_STATAMENTS is OFF
1711 +LOG_SLOW_SLAVE_STATEMENTS=ON
1712 +LOG_SLOW_SLAVE_STATAMENTS is ON
1713 +LINE 2
1714 +include/restart_slave.inc
1715 +LOG_SLOW_SLAVE_STATAMENTS is ON
1716 +LINE 3
1717 +LOG_SLOW_SLAVE_STATAMENTS is ON
1718 +LOG_SLOW_SLAVE_STATEMENTS=OFF
1719 +LOG_SLOW_SLAVE_STATAMENTS is OFF
1720 +LINE 4
1721 +include/restart_slave.inc
1722 +LOG_SLOW_SLAVE_STATAMENTS is OFF
1723 +LINE 5
1724 +LOG_SLOW_SLAVE_STATAMENTS is OFF
1725 +LOG_SLOW_SLAVE_STATEMENTS=ON
1726 +LOG_SLOW_SLAVE_STATAMENTS is ON
1727 +LINE 6
1728 +include/restart_slave.inc
1729 +LOG_SLOW_SLAVE_STATAMENTS is ON
1730 +LINE 7
1731 +[log_stop.inc] percona.slow_extended.log_slow_slave_statements
1732 +SET GLOBAL log_slow_slave_statements=default;
1733 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(1\)
1734 +[log_grep.inc] lines:   0
1735 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(2\)
1736 +[log_grep.inc] lines:   0
1737 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(3\)
1738 +[log_grep.inc] lines:   1
1739 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(4\)
1740 +[log_grep.inc] lines:   0
1741 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(5\)
1742 +[log_grep.inc] lines:   0
1743 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(6\)
1744 +[log_grep.inc] lines:   0
1745 +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(7\)
1746 +[log_grep.inc] lines:   1
1747 +DROP TABLE t;
1748 +include/rpl_end.inc
1749 --- /dev/null
1750 +++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result
1751 @@ -0,0 +1,6 @@
1752 +SHOW VARIABLES LIKE 'log_slow_sp_statements';
1753 +Variable_name  Value
1754 +log_slow_sp_statements ON
1755 +SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
1756 +Variable_name  Value
1757 +log_slow_sp_statements ON
1758 --- /dev/null
1759 +++ b/mysql-test/r/percona_log_slow_sp_statements.result
1760 @@ -0,0 +1,25 @@
1761 +SET long_query_time=1;
1762 +SET GLOBAL log_slow_sp_statements=ON;
1763 +SET SESSION query_exec_time=0.1;
1764 +[log_start.inc] percona.slow_extended.log_slow_sp_statements
1765 +CREATE PROCEDURE test_f()
1766 +BEGIN
1767 +SET SESSION query_exec_time=1.1; SELECT 1;
1768 +SET SESSION query_exec_time=2.1; SELECT 1;
1769 +SET SESSION query_exec_time=3.1; SELECT 1;
1770 +SET SESSION query_exec_time=0.1;
1771 +END^
1772 +CALL test_f();
1773 +1
1774 +1
1775 +1
1776 +1
1777 +1
1778 +1
1779 +[log_stop.inc] percona.slow_extended.log_slow_sp_statements
1780 +SET SESSION query_exec_time=default;
1781 +SET GLOBAL log_slow_sp_statements=default;
1782 +SET long_query_time=default;
1783 +[log_grep.inc] file: percona.slow_extended.log_slow_sp_statements pattern: Query_time
1784 +[log_grep.inc] lines:   3
1785 +DROP PROCEDURE test_f;
1786 --- /dev/null
1787 +++ b/mysql-test/r/percona_log_slow_verbosity-cl.result
1788 @@ -0,0 +1,6 @@
1789 +SHOW VARIABLES LIKE 'log_slow_verbosity';
1790 +Variable_name  Value
1791 +log_slow_verbosity     microtime,query_plan,innodb
1792 +SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
1793 +Variable_name  Value
1794 +log_slow_verbosity     microtime,query_plan,innodb
1795 --- /dev/null
1796 +++ b/mysql-test/r/percona_log_slow_verbosity.result
1797 @@ -0,0 +1,16 @@
1798 +SET SESSION long_query_time=1;
1799 +[log_start.inc] percona.slow_extended.log_slow_verbosity
1800 +SET SESSION query_exec_time=2.1;
1801 +SELECT 1;
1802 +1
1803 +1
1804 +SET SESSION log_slow_verbosity=innodb;
1805 +SELECT 1;
1806 +1
1807 +1
1808 +SET SESSION query_exec_time=default;
1809 +[log_stop.inc] percona.slow_extended.log_slow_verbosity
1810 +SET log_slow_verbosity=default;
1811 +SET long_query_time=default;
1812 +[log_grep.inc] file: percona.slow_extended.log_slow_verbosity pattern: No InnoDB statistics available for this query
1813 +[log_grep.inc] lines:   1
1814 --- /dev/null
1815 +++ b/mysql-test/r/percona_long_query_time.result
1816 @@ -0,0 +1,33 @@
1817 +SET long_query_time=2;
1818 +[log_start.inc] percona.slow_extended.long_query_time
1819 +SET SESSION query_exec_time=1.1;
1820 +SELECT 1;
1821 +1
1822 +1
1823 +SET SESSION query_exec_time=3.1;
1824 +SELECT 1;
1825 +1
1826 +1
1827 +SET SESSION query_exec_time=5.1;
1828 +SELECT 1;
1829 +1
1830 +1
1831 +SET long_query_time=4;
1832 +SET SESSION query_exec_time=1.1;
1833 +SELECT 1;
1834 +1
1835 +1
1836 +SET SESSION query_exec_time=3.1;
1837 +SELECT 1;
1838 +1
1839 +1
1840 +SET SESSION query_exec_time=5.1;
1841 +SELECT 1;
1842 +1
1843 +1
1844 +SET SESSION query_exec_time=default;
1845 +SET long_query_time=2;
1846 +[log_stop.inc] percona.slow_extended.long_query_time
1847 +SET long_query_time=default;
1848 +[log_grep.inc] file: percona.slow_extended.long_query_time pattern: Query_time
1849 +[log_grep.inc] lines:   3
1850 --- /dev/null
1851 +++ b/mysql-test/r/percona_slow_query_log_timestamp_always-cl.result
1852 @@ -0,0 +1,6 @@
1853 +SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
1854 +Variable_name  Value
1855 +slow_query_log_timestamp_always        ON
1856 +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
1857 +Variable_name  Value
1858 +slow_query_log_timestamp_always        ON
1859 --- /dev/null
1860 +++ b/mysql-test/r/percona_slow_query_log_timestamp_always.result
1861 @@ -0,0 +1,41 @@
1862 +SET long_query_time=2;
1863 +SET GLOBAL slow_query_log_timestamp_always=ON;
1864 +[log_start.inc] percona.slow_extended.slow_query_log_timestamp_always
1865 +SET SESSION query_exec_time=2.1;
1866 +SELECT 1;
1867 +1
1868 +1
1869 +SELECT 1;
1870 +1
1871 +1
1872 +SELECT 1;
1873 +1
1874 +1
1875 +SET GLOBAL slow_query_log_timestamp_always=OFF;
1876 +SET SESSION query_exec_time=2.1;
1877 +SELECT 1;
1878 +1
1879 +1
1880 +SELECT 1;
1881 +1
1882 +1
1883 +SELECT 1;
1884 +1
1885 +1
1886 +SET GLOBAL slow_query_log_timestamp_always=ON;
1887 +SET SESSION query_exec_time=2.1;
1888 +SELECT 1;
1889 +1
1890 +1
1891 +SELECT 1;
1892 +1
1893 +1
1894 +SELECT 1;
1895 +1
1896 +1
1897 +SET SESSION query_exec_time=default;
1898 +[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_always
1899 +SET GLOBAL slow_query_log_timestamp_always=default;
1900 +SET long_query_time=default;
1901 +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_always pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
1902 +[log_grep.inc] lines:   6
1903 --- /dev/null
1904 +++ b/mysql-test/r/percona_slow_query_log_timestamp_precision-cl.result
1905 @@ -0,0 +1,6 @@
1906 +SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
1907 +Variable_name  Value
1908 +slow_query_log_timestamp_precision     microsecond
1909 +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
1910 +Variable_name  Value
1911 +slow_query_log_timestamp_precision     microsecond
1912 --- /dev/null
1913 +++ b/mysql-test/r/percona_slow_query_log_timestamp_precision.result
1914 @@ -0,0 +1,18 @@
1915 +SET long_query_time=2;
1916 +[log_start.inc] percona.slow_extended.slow_query_log_timestamp_precision
1917 +SET SESSION query_exec_time=2.1;
1918 +SELECT 1;
1919 +1
1920 +1
1921 +SET GLOBAL slow_query_log_timestamp_precision='microsecond';
1922 +SELECT 1;
1923 +1
1924 +1
1925 +SET SESSION query_exec_time=default;
1926 +[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_precision
1927 +SET GLOBAL slow_query_log_timestamp_precision=default;
1928 +SET long_query_time=default;
1929 +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
1930 +[log_grep.inc] lines:   1
1931 +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
1932 +[log_grep.inc] lines:   2
1933 --- /dev/null
1934 +++ b/mysql-test/r/percona_slow_query_log_use_global_control.result
1935 @@ -0,0 +1,18 @@
1936 +SET GLOBAL long_query_time=1;
1937 +[log_start.inc] percona.slow_extended.slow_query_log_use_global_control
1938 +SET SESSION query_exec_time=1.1;
1939 +SELECT 1;
1940 +1
1941 +1
1942 +SET GLOBAL log_slow_verbosity=innodb;
1943 +SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
1944 +SELECT 1;
1945 +1
1946 +1
1947 +SET SESSION query_exec_time=default;
1948 +[log_stop.inc] percona.slow_extended.slow_query_log_use_global_control
1949 +SET GLOBAL slow_query_log_use_global_control=default;
1950 +SET GLOBAL log_slow_verbosity=default;
1951 +SET GLOBAL long_query_time=default;
1952 +[log_grep.inc] file: percona.slow_extended.slow_query_log_use_global_control pattern: No InnoDB statistics available for this query
1953 +[log_grep.inc] lines:   1
1954 --- /dev/null
1955 +++ b/mysql-test/t/percona_bug643149.test
1956 @@ -0,0 +1,49 @@
1957 +#
1958 +# This test suffers from server
1959 +# Bug#38124 "general_log_file" variable silently unset when using expression
1960 +# In short:
1961 +#    SET GLOBAL general_log_file = @<whatever>
1962 +#    SET GLOBAL slow_query_log = @<whatever>
1963 +# cause that the value of these server system variables is set to default
1964 +# instead of the assigned values. There comes no error message or warning.
1965 +# If this bug is fixed please
1966 +# 1. try this test with "let $fixed_bug38124 = 0;"
1967 +# 2. remove all workarounds if 1. was successful.
1968 +--source include/have_profiling.inc
1969 +let $fixed_bug38124 = 0;
1970 +
1971 +SET @old_slow_query_log_file=@@global.slow_query_log_file;
1972 +SET GLOBAL slow_query_log=on;
1973 +SET LOCAL log_slow_verbosity='profiling';
1974 +SET LOCAL long_query_time=0;
1975 +
1976 +let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log;
1977 +--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
1978 +--eval SET GLOBAL slow_query_log_file='$slogfile';
1979 +
1980 +SELECT 1;
1981 +
1982 +perl;
1983 +  $slogfile= $ENV{'slogfile'};
1984 +
1985 +  open(FILE, "$slogfile") or
1986 +    die("Unable to read slow query log file $slogfile: $!\n");
1987 +  while(<FILE>) {
1988 +    next if (!/^#/);
1989 +    next if (/^# Time:/);
1990 +    s/[0-9]+/X/g;
1991 +    print;
1992 +  }
1993 +
1994 +  close(FILE);
1995 +EOF
1996 +
1997 +SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
1998 +
1999 +if(!$fixed_bug38124)
2000 +{
2001 +  --disable_query_log
2002 +  let $my_var = `SELECT @old_slow_query_log_file`;
2003 +  eval SET @@global.slow_query_log_file = '$my_var';
2004 +  --enable_query_log
2005 +}
2006 --- /dev/null
2007 +++ b/mysql-test/t/percona_log_slow_filter-cl-master.opt
2008 @@ -0,0 +1 @@
2009 +--log_slow_filter=full_join
2010 --- /dev/null
2011 +++ b/mysql-test/t/percona_log_slow_filter-cl.test
2012 @@ -0,0 +1,2 @@
2013 +SHOW VARIABLES LIKE 'log_slow_filter';
2014 +SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
2015 --- /dev/null
2016 +++ b/mysql-test/t/percona_log_slow_filter.test
2017 @@ -0,0 +1,26 @@
2018 +--source include/have_debug.inc
2019 +
2020 +CREATE TABLE t(id INT PRIMARY KEY);
2021 +INSERT INTO t VALUES(1);
2022 +INSERT INTO t VALUES(2);
2023 +INSERT INTO t VALUES(3);
2024 +
2025 +SET long_query_time=1;
2026 +SET log_slow_filter=full_join;
2027 +--let log_file=percona.slow_extended.log_slow_filter
2028 +--source include/log_start.inc
2029 +
2030 +SET query_exec_time = 1.1;
2031 +--disable_result_log
2032 +SELECT * FROM t AS t1, t AS t2;
2033 +--enable_result_log
2034 +SET query_exec_time = default;
2035 +
2036 +--source include/log_stop.inc
2037 +SET log_slow_filter=default;
2038 +SET long_query_time=default;
2039 +
2040 +--let grep_pattern = Query_time
2041 +--source include/log_grep.inc
2042 +
2043 +DROP TABLE t;
2044 --- /dev/null
2045 +++ b/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt
2046 @@ -0,0 +1 @@
2047 +--log_slow_slave_statements
2048 \ No newline at end of file
2049 --- /dev/null
2050 +++ b/mysql-test/t/percona_log_slow_slave_statements-cl.test
2051 @@ -0,0 +1,3 @@
2052 +SHOW VARIABLES LIKE 'log_slow_slave_statements';
2053 +SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
2054 +
2055 --- /dev/null
2056 +++ b/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt
2057 @@ -0,0 +1 @@
2058 +--long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb
2059 \ No newline at end of file
2060 --- /dev/null
2061 +++ b/mysql-test/t/percona_log_slow_slave_statements-innodb.test
2062 @@ -0,0 +1,42 @@
2063 +--source include/have_binlog_format_statement.inc
2064 +--source include/master-slave.inc
2065 +--source include/have_innodb.inc
2066 +--let log_file=percona.slow_extended.log_slow_slave_statements-innodb
2067 +
2068 +connection master;
2069 +-- disable_warnings
2070 +DROP TABLE IF EXISTS t;
2071 +-- enable_warnings
2072 +
2073 +CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
2074 +INSERT INTO t VALUES
2075 +(1,"aaaaabbbbbcccccdddddeeeeefffff"),
2076 +(2,"aaaaabbbbbcccccdddddeeeeefffff"),
2077 +(3,"aaaaabbbbbcccccdddddeeeeefffff"),
2078 +(4,"aaaaabbbbbcccccdddddeeeeefffff"),
2079 +(5,"aaaaabbbbbcccccdddddeeeeefffff");
2080 +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
2081 +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
2082 +sync_slave_with_master;
2083 +
2084 +connection slave;
2085 +--source include/log_start.inc
2086 +
2087 +connection master;
2088 +INSERT INTO t SELECT t.id,t.data from t;
2089 +sync_slave_with_master;
2090 +
2091 +connection slave;
2092 +--source include/log_stop.inc
2093 +
2094 +--enable_query_log
2095 +--enable_result_log
2096 +
2097 +--let grep_pattern =  InnoDB_IO_r_ops
2098 +--source include/log_grep.inc
2099 +
2100 +connection master;
2101 +DROP TABLE t;
2102 +sync_slave_with_master;
2103 +
2104 +--source include/rpl_end.inc
2105 --- /dev/null
2106 +++ b/mysql-test/t/percona_log_slow_slave_statements-slave.opt
2107 @@ -0,0 +1 @@
2108 +--long_query_time=0
2109 \ No newline at end of file
2110 --- /dev/null
2111 +++ b/mysql-test/t/percona_log_slow_slave_statements.test
2112 @@ -0,0 +1,117 @@
2113 +-- source include/have_binlog_format_statement.inc
2114 +-- source include/master-slave.inc
2115 +--let log_file=percona.slow_extended.log_slow_slave_statements
2116 +--let show=SELECT Variable_value FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name LIKE 'log_slow_slave_statements';
2117 +
2118 +connection master;
2119 +-- disable_warnings
2120 +DROP TABLE IF EXISTS t;
2121 +-- enable_warnings
2122 +
2123 +CREATE TABLE t(id INT);
2124 +sync_slave_with_master;
2125 +
2126 +connection slave;
2127 +--source include/log_start.inc
2128 +
2129 +--disable_query_log
2130 +--disable_result_log
2131 +
2132 +--echo LINE 1
2133 +connection master;
2134 +INSERT INTO t VALUES (1);
2135 +sync_slave_with_master;
2136 +
2137 +connection slave;
2138 +--let value=`$show`
2139 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2140 +--echo LOG_SLOW_SLAVE_STATEMENTS=ON
2141 +SET GLOBAL log_slow_slave_statements=ON;
2142 +--let value=`$show`
2143 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2144 +
2145 +--echo LINE 2
2146 +connection master;
2147 +INSERT INTO t VALUES (2);
2148 +sync_slave_with_master;
2149 +
2150 +--source include/restart_slave_sql.inc
2151 +
2152 +connection slave;
2153 +--let value=`$show`
2154 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2155 +
2156 +--echo LINE 3
2157 +connection master;
2158 +INSERT INTO t VALUES (3);
2159 +sync_slave_with_master;
2160 +
2161 +connection slave;
2162 +--let value=`$show`
2163 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2164 +--echo LOG_SLOW_SLAVE_STATEMENTS=OFF
2165 +SET GLOBAL log_slow_slave_statements=OFF;
2166 +--let value=`$show`
2167 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2168 +
2169 +--echo LINE 4
2170 +connection master;
2171 +INSERT INTO t VALUES (4);
2172 +sync_slave_with_master;
2173 +
2174 +--source include/restart_slave_sql.inc
2175 +
2176 +connection slave;
2177 +--let value=`$show`
2178 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2179 +
2180 +--echo LINE 5
2181 +connection master;
2182 +INSERT INTO t VALUES (5);
2183 +sync_slave_with_master;
2184 +
2185 +connection slave;
2186 +--let value=`$show`
2187 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2188 +--echo LOG_SLOW_SLAVE_STATEMENTS=ON
2189 +SET GLOBAL log_slow_slave_statements=ON;
2190 +--let value=`$show`
2191 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2192 +
2193 +--echo LINE 6
2194 +connection master;
2195 +INSERT INTO t VALUES (6);
2196 +sync_slave_with_master;
2197 +
2198 +--source include/restart_slave_sql.inc
2199 +
2200 +connection slave;
2201 +--let value=`$show`
2202 +--echo LOG_SLOW_SLAVE_STATAMENTS is $value
2203 +
2204 +--echo LINE 7
2205 +connection master;
2206 +INSERT INTO t VALUES (7);
2207 +sync_slave_with_master;
2208 +
2209 +--enable_query_log
2210 +--enable_result_log
2211 +
2212 +connection slave;
2213 +--source include/log_stop.inc
2214 +SET GLOBAL log_slow_slave_statements=default;
2215 +
2216 +connection slave;
2217 +--let i=1
2218 +while($i < 8)
2219 +{
2220 +--let grep_pattern= INSERT INTO t VALUES \($i\)
2221 +--source include/log_grep.inc
2222 +  inc $i;
2223 +}
2224 +
2225 +connection master;
2226 +DROP TABLE t;
2227 +sync_slave_with_master;
2228 +
2229 +--source include/rpl_end.inc
2230 --- /dev/null
2231 +++ b/mysql-test/t/percona_log_slow_sp_statements-cl-master.opt
2232 @@ -0,0 +1 @@
2233 +--log_slow_sp_statements
2234 --- /dev/null
2235 +++ b/mysql-test/t/percona_log_slow_sp_statements-cl.test
2236 @@ -0,0 +1,2 @@
2237 +SHOW VARIABLES LIKE 'log_slow_sp_statements';
2238 +SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
2239 --- /dev/null
2240 +++ b/mysql-test/t/percona_log_slow_sp_statements.test
2241 @@ -0,0 +1,29 @@
2242 +--source include/have_debug.inc
2243 +
2244 +SET long_query_time=1;
2245 +SET GLOBAL log_slow_sp_statements=ON;
2246 +SET SESSION query_exec_time=0.1;
2247 +--let log_file=percona.slow_extended.log_slow_sp_statements
2248 +--source include/log_start.inc
2249 +
2250 +delimiter ^;
2251 +CREATE PROCEDURE test_f()
2252 +BEGIN
2253 +  SET SESSION query_exec_time=1.1; SELECT 1;
2254 +  SET SESSION query_exec_time=2.1; SELECT 1;
2255 +  SET SESSION query_exec_time=3.1; SELECT 1;
2256 +  SET SESSION query_exec_time=0.1;
2257 +END^
2258 +delimiter ;^
2259 +
2260 +CALL test_f();
2261 +
2262 +--source include/log_stop.inc
2263 +SET SESSION query_exec_time=default;
2264 +SET GLOBAL log_slow_sp_statements=default;
2265 +SET long_query_time=default;
2266 +
2267 +--let grep_pattern = Query_time
2268 +--source include/log_grep.inc
2269 +
2270 +DROP PROCEDURE test_f;
2271 --- /dev/null
2272 +++ b/mysql-test/t/percona_log_slow_verbosity-cl-master.opt
2273 @@ -0,0 +1 @@
2274 +--log_slow_verbosity="full"
2275 --- /dev/null
2276 +++ b/mysql-test/t/percona_log_slow_verbosity-cl.test
2277 @@ -0,0 +1,2 @@
2278 +SHOW VARIABLES LIKE 'log_slow_verbosity';
2279 +SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
2280 --- /dev/null
2281 +++ b/mysql-test/t/percona_log_slow_verbosity.test
2282 @@ -0,0 +1,19 @@
2283 +--source include/have_innodb.inc
2284 +--source include/have_debug.inc
2285 +
2286 +SET SESSION long_query_time=1;
2287 +--let log_file=percona.slow_extended.log_slow_verbosity
2288 +--source include/log_start.inc
2289 +
2290 +SET SESSION query_exec_time=2.1;
2291 +SELECT 1;
2292 +SET SESSION log_slow_verbosity=innodb;
2293 +SELECT 1;
2294 +SET SESSION query_exec_time=default;
2295 +
2296 +--source include/log_stop.inc
2297 +SET log_slow_verbosity=default;
2298 +SET long_query_time=default;
2299 +
2300 +--let grep_pattern = No InnoDB statistics available for this query
2301 +--source include/log_grep.inc
2302 --- /dev/null
2303 +++ b/mysql-test/t/percona_long_query_time.test
2304 @@ -0,0 +1,25 @@
2305 +--source include/have_debug.inc
2306 +
2307 +SET long_query_time=2;
2308 +--let log_file=percona.slow_extended.long_query_time
2309 +--source include/log_start.inc
2310 +
2311 +SET SESSION query_exec_time=1.1; SELECT 1;
2312 +SET SESSION query_exec_time=3.1; SELECT 1;
2313 +SET SESSION query_exec_time=5.1; SELECT 1;
2314 +
2315 +SET long_query_time=4;
2316 +
2317 +SET SESSION query_exec_time=1.1; SELECT 1;
2318 +SET SESSION query_exec_time=3.1; SELECT 1;
2319 +SET SESSION query_exec_time=5.1; SELECT 1;
2320 +
2321 +SET SESSION query_exec_time=default;
2322 +
2323 +SET long_query_time=2;
2324 +
2325 +--source include/log_stop.inc
2326 +SET long_query_time=default;
2327 +
2328 +--let grep_pattern = Query_time
2329 +--source include/log_grep.inc
2330 --- /dev/null
2331 +++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl-master.opt
2332 @@ -0,0 +1 @@
2333 +--slow_query_log_timestamp_always
2334 \ No newline at end of file
2335 --- /dev/null
2336 +++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl.test
2337 @@ -0,0 +1,2 @@
2338 +SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
2339 +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
2340 --- /dev/null
2341 +++ b/mysql-test/t/percona_slow_query_log_timestamp_always.test
2342 @@ -0,0 +1,34 @@
2343 +--source include/have_debug.inc
2344 +
2345 +SET long_query_time=2;
2346 +SET GLOBAL slow_query_log_timestamp_always=ON;
2347 +--let log_file=percona.slow_extended.slow_query_log_timestamp_always
2348 +--source include/log_start.inc
2349 +
2350 +SET SESSION query_exec_time=2.1;
2351 +SELECT 1;
2352 +SELECT 1;
2353 +SELECT 1;
2354 +
2355 +SET GLOBAL slow_query_log_timestamp_always=OFF;
2356 +
2357 +SET SESSION query_exec_time=2.1;
2358 +SELECT 1;
2359 +SELECT 1;
2360 +SELECT 1;
2361 +
2362 +SET GLOBAL slow_query_log_timestamp_always=ON;
2363 +
2364 +SET SESSION query_exec_time=2.1;
2365 +SELECT 1;
2366 +SELECT 1;
2367 +SELECT 1;
2368 +
2369 +SET SESSION query_exec_time=default;
2370 +
2371 +--source include/log_stop.inc
2372 +SET GLOBAL slow_query_log_timestamp_always=default;
2373 +SET long_query_time=default;
2374 +
2375 +--let grep_pattern =  # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
2376 +--source include/log_grep.inc
2377 --- /dev/null
2378 +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl-master.opt
2379 @@ -0,0 +1 @@
2380 +--slow_query_log_timestamp_precision='microsecond'
2381 \ No newline at end of file
2382 --- /dev/null
2383 +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl.test
2384 @@ -0,0 +1,2 @@
2385 +SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
2386 +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
2387 --- /dev/null
2388 +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-master.opt
2389 @@ -0,0 +1 @@
2390 +--slow_query_log_timestamp_always
2391 \ No newline at end of file
2392 --- /dev/null
2393 +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision.test
2394 @@ -0,0 +1,25 @@
2395 +--source include/have_debug.inc
2396 +
2397 +SET long_query_time=2;
2398 +--let log_file=percona.slow_extended.slow_query_log_timestamp_precision
2399 +--source include/log_start.inc
2400 +
2401 +SET SESSION query_exec_time=2.1;
2402 +
2403 +SELECT 1;
2404 +
2405 +SET GLOBAL slow_query_log_timestamp_precision='microsecond';
2406 +
2407 +SELECT 1;
2408 +
2409 +SET SESSION query_exec_time=default;
2410 +
2411 +--source include/log_stop.inc
2412 +SET GLOBAL slow_query_log_timestamp_precision=default;
2413 +SET long_query_time=default;
2414 +
2415 +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
2416 +--source include/log_grep.inc
2417 +
2418 +--let grep_pattern =  # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
2419 +--source include/log_grep.inc
2420 --- /dev/null
2421 +++ b/mysql-test/t/percona_slow_query_log_use_global_control.test
2422 @@ -0,0 +1,28 @@
2423 +--source include/have_debug.inc
2424 +--source include/have_innodb.inc
2425 +
2426 +SET GLOBAL long_query_time=1;
2427 +
2428 +--let log_file=percona.slow_extended.slow_query_log_use_global_control
2429 +--source include/log_start.inc
2430 +
2431 +SET SESSION query_exec_time=1.1;
2432 +SELECT 1;
2433 +
2434 +SET GLOBAL log_slow_verbosity=innodb;
2435 +SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
2436 +
2437 +SELECT 1;
2438 +
2439 +SET SESSION query_exec_time=default;
2440 +
2441 +--source include/log_stop.inc
2442 +
2443 +
2444 +SET GLOBAL slow_query_log_use_global_control=default;
2445 +SET GLOBAL log_slow_verbosity=default;
2446 +SET GLOBAL long_query_time=default;
2447 +
2448 +--let grep_pattern = No InnoDB statistics available for this query
2449 +--source include/log_grep.inc
2450 +
2451 --- /dev/null
2452 +++ b/mysql-test/r/percona_slow_query_log_use_global_control-cl.result
2453 @@ -0,0 +1,6 @@
2454 +SHOW VARIABLES LIKE 'slow_query_log_use_global_control';
2455 +Variable_name  Value
2456 +slow_query_log_use_global_control      log_slow_verbosity,long_query_time
2457 +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control';
2458 +Variable_name  Value
2459 +slow_query_log_use_global_control      log_slow_verbosity,long_query_time
2460 --- /dev/null
2461 +++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl-master.opt
2462 @@ -0,0 +1 @@
2463 +--slow_query_log_use_global_control="log_slow_verbosity,long_query_time"
2464 --- /dev/null
2465 +++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl.test
2466 @@ -0,0 +1,2 @@
2467 +SHOW VARIABLES LIKE 'slow_query_log_use_global_control';
2468 +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control';
2469 --- /dev/null
2470 +++ b/mysql-test/r/percona_min_examined_row_limit.result
2471 @@ -0,0 +1,35 @@
2472 +drop table if exists t;
2473 +create table t(id INT PRIMARY KEY);
2474 +insert into t values(1);
2475 +insert into t values(2);
2476 +insert into t values(3);
2477 +SET GLOBAL long_query_time=2;
2478 +SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit';
2479 +[log_start.inc] percona.slow_extended.min_examined_row_limit
2480 +SET SESSION query_exec_time=2.1;
2481 +SELECT 1;
2482 +1
2483 +1
2484 +SET GLOBAL min_examined_row_limit=5;
2485 +select * from t as t1, t as t2;
2486 +id     id
2487 +1      1
2488 +2      1
2489 +3      1
2490 +1      2
2491 +2      2
2492 +3      2
2493 +1      3
2494 +2      3
2495 +3      3
2496 +SELECT 1;
2497 +1
2498 +1
2499 +SET SESSION query_exec_time=default;
2500 +[log_stop.inc] percona.slow_extended.min_examined_row_limit
2501 +SET GLOBAL min_examined_row_limit=default;
2502 +SET GLOBAL slow_query_log_use_global_control=default;
2503 +SET GLOBAL long_query_time=default;
2504 +[log_grep.inc] file: percona.slow_extended.min_examined_row_limit pattern: Query_time
2505 +[log_grep.inc] lines:   1
2506 +DROP TABLE t;
2507 --- /dev/null
2508 +++ b/mysql-test/t/percona_min_examined_row_limit.test
2509 @@ -0,0 +1,35 @@
2510 +--source include/have_debug.inc
2511 +
2512 +--disable_warnings
2513 +drop table if exists t;
2514 +--enable_warnings
2515 +
2516 +create table t(id INT PRIMARY KEY);
2517 +insert into t values(1);
2518 +insert into t values(2);
2519 +insert into t values(3);
2520 +
2521 +SET GLOBAL long_query_time=2;
2522 +SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit';
2523 +--let log_file=percona.slow_extended.min_examined_row_limit
2524 +--source include/log_start.inc
2525 +
2526 +SET SESSION query_exec_time=2.1;
2527 +SELECT 1;
2528 +
2529 +SET GLOBAL min_examined_row_limit=5;
2530 +
2531 +select * from t as t1, t as t2;
2532 +SELECT 1;
2533 +
2534 +SET SESSION query_exec_time=default;
2535 +
2536 +--source include/log_stop.inc
2537 +SET GLOBAL min_examined_row_limit=default;
2538 +SET GLOBAL slow_query_log_use_global_control=default;
2539 +SET GLOBAL long_query_time=default;
2540 +
2541 +--let grep_pattern = Query_time
2542 +--source include/log_grep.inc
2543 +
2544 +DROP TABLE t;
2545 --- a/sql/log_event.cc
2546 +++ b/sql/log_event.cc
2547 @@ -2385,6 +2385,14 @@
2548        start+= host.length;
2549      }
2550    }
2551 +#ifndef DBUG_OFF
2552 +  if (thd && thd->variables.query_exec_time > 0)
2553 +  {
2554 +    *start++= Q_QUERY_EXEC_TIME;
2555 +    int8store(start, thd->variables.query_exec_time);
2556 +    start+= 8;
2557 +  }
2558 +#endif
2559    /*
2560      NOTE: When adding new status vars, please don't forget to update
2561      the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update the function
2562 @@ -2871,6 +2879,17 @@
2563        data_written= master_data_written= uint4korr(pos);
2564        pos+= 4;
2565        break;
2566 +#if !defined(DBUG_OFF) && !defined(MYSQL_CLIENT)
2567 +    case Q_QUERY_EXEC_TIME:
2568 +    {
2569 +      THD *thd= current_thd;
2570 +      CHECK_SPACE(pos, end, 8);
2571 +      if (thd)
2572 +        thd->variables.query_exec_time= uint8korr(pos);
2573 +      pos+= 8;
2574 +      break;
2575 +    }
2576 +#endif
2577      case Q_INVOKER:
2578      {
2579        CHECK_SPACE(pos, end, 1);
2580 --- a/sql/log_event.h
2581 +++ b/sql/log_event.h
2582 @@ -343,6 +343,10 @@
2583
2584  #define Q_INVOKER 11
2585
2586 +#ifndef DBUG_OFF
2587 +#define Q_QUERY_EXEC_TIME 250
2588 +#endif
2589 +
2590  /* Intvar event post-header */
2591
2592  /* Intvar event data */
2593 --- /dev/null
2594 +++ b/mysql-test/suite/sys_vars/r/query_exec_time_basic.result
2595 @@ -0,0 +1,2 @@
2596 +SET GLOBAL query_exec_time=default;
2597 +SET SESSION query_exec_time=default;
2598 --- /dev/null
2599 +++ b/mysql-test/suite/sys_vars/t/query_exec_time_basic.test
2600 @@ -0,0 +1,4 @@
2601 +--source include/have_debug.inc
2602 +
2603 +SET GLOBAL query_exec_time=default;
2604 +SET SESSION query_exec_time=default;
2605 --- /dev/null
2606 +++ b/mysql-test/r/percona_log_slow_global_control_default.result
2607 @@ -0,0 +1 @@
2608 +SET GLOBAL slow_query_log_use_global_control=default;
2609 --- /dev/null
2610 +++ b/mysql-test/t/percona_log_slow_global_control_default.test
2611 @@ -0,0 +1 @@
2612 +SET GLOBAL slow_query_log_use_global_control=default;
2613 --- /dev/null
2614 +++ b/mysql-test/r/percona_slow_extended_log_error.result
2615 @@ -0,0 +1,10 @@
2616 +SET long_query_time=0;
2617 +DROP TABLE IF EXISTS t1;
2618 +CREATE TABLE t(a INT);
2619 +[log_start.inc] percona.slow_extended.log_error
2620 +CREATE TABLE t(a INT);
2621 +ERROR 42S01: Table 't' already exists
2622 +[log_stop.inc] percona.slow_extended.log_error
2623 +[log_grep.inc] file: percona.slow_extended.log_error pattern: Last_errno: 1050
2624 +[log_grep.inc] lines:   1
2625 +DROP TABLE t;
2626 --- /dev/null
2627 +++ b/mysql-test/t/percona_slow_extended_log_error.test
2628 @@ -0,0 +1,15 @@
2629 +--let log_file=percona.slow_extended.log_error
2630 +SET long_query_time=0;
2631 +--disable_warnings
2632 +DROP TABLE IF EXISTS t1;
2633 +--enable_warnings
2634 +CREATE TABLE t(a INT);
2635 +--source include/log_start.inc
2636 +
2637 +--error ER_TABLE_EXISTS_ERROR
2638 +CREATE TABLE t(a INT);
2639 +
2640 +--source include/log_stop.inc
2641 +--let grep_pattern = Last_errno: 1050
2642 +--source include/log_grep.inc
2643 +DROP TABLE t;
2644 --- /dev/null
2645 +++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test
2646 @@ -0,0 +1 @@
2647 +SELECT @@global.log_slow_admin_statements;
2648 --- /dev/null
2649 +++ b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_basic.result
2650 @@ -0,0 +1,3 @@
2651 +SELECT @@global.log_slow_admin_statements;
2652 +@@global.log_slow_admin_statements
2653 +0
2654 --- /dev/null
2655 +++ b/mysql-test/r/percona_log_slow_admin_statements.result
2656 @@ -0,0 +1,35 @@
2657 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2658 +Variable_name  Value
2659 +log_slow_admin_statements      OFF
2660 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2661 +VARIABLE_NAME  VARIABLE_VALUE
2662 +LOG_SLOW_ADMIN_STATEMENTS      OFF
2663 +SET GLOBAL log_slow_admin_statements=true;
2664 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2665 +Variable_name  Value
2666 +log_slow_admin_statements      ON
2667 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2668 +VARIABLE_NAME  VARIABLE_VALUE
2669 +LOG_SLOW_ADMIN_STATEMENTS      ON
2670 +SET GLOBAL log_slow_admin_statements=false;
2671 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2672 +Variable_name  Value
2673 +log_slow_admin_statements      OFF
2674 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2675 +VARIABLE_NAME  VARIABLE_VALUE
2676 +LOG_SLOW_ADMIN_STATEMENTS      OFF
2677 +SET GLOBAL log_slow_admin_statements=foo;
2678 +ERROR 42000: Variable 'log_slow_admin_statements' can't be set to the value of 'foo'
2679 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2680 +Variable_name  Value
2681 +log_slow_admin_statements      OFF
2682 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2683 +VARIABLE_NAME  VARIABLE_VALUE
2684 +LOG_SLOW_ADMIN_STATEMENTS      OFF
2685 +SET GLOBAL log_slow_admin_statements=default;
2686 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2687 +Variable_name  Value
2688 +log_slow_admin_statements      OFF
2689 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2690 +VARIABLE_NAME  VARIABLE_VALUE
2691 +LOG_SLOW_ADMIN_STATEMENTS      OFF
2692 --- /dev/null
2693 +++ b/mysql-test/r/percona_log_slow_admin_statements-config_false.result
2694 @@ -0,0 +1,6 @@
2695 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2696 +Variable_name  Value
2697 +log_slow_admin_statements      OFF
2698 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2699 +VARIABLE_NAME  VARIABLE_VALUE
2700 +LOG_SLOW_ADMIN_STATEMENTS      OFF
2701 --- /dev/null
2702 +++ b/mysql-test/r/percona_log_slow_admin_statements-config_foo.result
2703 @@ -0,0 +1,7 @@
2704 +call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF.");
2705 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2706 +Variable_name  Value
2707 +log_slow_admin_statements      OFF
2708 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2709 +VARIABLE_NAME  VARIABLE_VALUE
2710 +LOG_SLOW_ADMIN_STATEMENTS      OFF
2711 --- /dev/null
2712 +++ b/mysql-test/r/percona_log_slow_admin_statements-config_true.result
2713 @@ -0,0 +1,6 @@
2714 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2715 +Variable_name  Value
2716 +log_slow_admin_statements      ON
2717 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2718 +VARIABLE_NAME  VARIABLE_VALUE
2719 +LOG_SLOW_ADMIN_STATEMENTS      ON
2720 --- /dev/null
2721 +++ b/mysql-test/r/percona_log_slow_admin_statements-config.result
2722 @@ -0,0 +1,6 @@
2723 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2724 +Variable_name  Value
2725 +log_slow_admin_statements      ON
2726 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2727 +VARIABLE_NAME  VARIABLE_VALUE
2728 +LOG_SLOW_ADMIN_STATEMENTS      ON
2729 --- /dev/null
2730 +++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.cnf
2731 @@ -0,0 +1,2 @@
2732 +[mysqld.1]
2733 +log-slow-admin-statements=false
2734 --- /dev/null
2735 +++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.cnf
2736 @@ -0,0 +1,2 @@
2737 +[mysqld.1]
2738 +log-slow-admin-statements=foo
2739 --- /dev/null
2740 +++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.cnf
2741 @@ -0,0 +1,2 @@
2742 +[mysqld.1]
2743 +log-slow-admin-statements=true
2744 --- /dev/null
2745 +++ b/mysql-test/t/percona_log_slow_admin_statements-config.cnf
2746 @@ -0,0 +1,2 @@
2747 +[mysqld.1]
2748 +log-slow-admin-statements
2749 --- /dev/null
2750 +++ b/mysql-test/t/percona_log_slow_admin_statements.test
2751 @@ -0,0 +1,20 @@
2752 +# default value
2753 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2754 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2755 +# set value to 'true'
2756 +SET GLOBAL log_slow_admin_statements=true;
2757 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2758 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2759 +# set value to 'false'
2760 +SET GLOBAL log_slow_admin_statements=false;
2761 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2762 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2763 +# set value to 'foo'
2764 +--error ER_WRONG_VALUE_FOR_VAR
2765 +SET GLOBAL log_slow_admin_statements=foo;
2766 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2767 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2768 +# set value to default
2769 +SET GLOBAL log_slow_admin_statements=default;
2770 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2771 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2772 --- /dev/null
2773 +++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.test
2774 @@ -0,0 +1,2 @@
2775 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2776 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2777 --- /dev/null
2778 +++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.test
2779 @@ -0,0 +1,3 @@
2780 +call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF.");
2781 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2782 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2783 --- /dev/null
2784 +++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.test
2785 @@ -0,0 +1,2 @@
2786 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2787 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2788 --- /dev/null
2789 +++ b/mysql-test/t/percona_log_slow_admin_statements-config.test
2790 @@ -0,0 +1,2 @@
2791 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2792 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2793 --- a/mysql-test/r/mysqld--help-notwin.result
2794 +++ b/mysql-test/r/mysqld--help-notwin.result
2795 @@ -250,15 +250,38 @@
2796   --log-slow-admin-statements
2797   Log slow OPTIMIZE, ANALYZE, ALTER and other
2798   administrative statements to the slow log if it is open.
2799 + --log-slow-filter=name
2800 + Log only the queries that followed certain execution
2801 + plan. Multiple flags allowed in a comma-separated string.
2802 + [qc_miss, full_scan, full_join, tmp_table,
2803 + tmp_table_on_disk, filesort, filesort_on_disk]
2804   --log-slow-queries[=name]
2805   Log slow queries to a table or log file. Defaults logging
2806   to table mysql.slow_log or hostname-slow.log if
2807   --log-output=file is used. Must be enabled to activate
2808   other slow log options. Deprecated option, use
2809   --slow-query-log/--slow-query-log-file instead.
2810 + --log-slow-rate-limit=#
2811 + Rate limit statement writes to slow log to only those
2812 + from every (1/log_slow_rate_limit) session.
2813 + --log-slow-rate-type=name
2814 + Choose the log_slow_rate_limit behavior: session or
2815 + query. When you choose 'session' - every
2816 + %log_slow_rate_limit connection will be processed to slow
2817 + query log. When you choose 'query' - every
2818 + %log_slow_rate_limit query will be processed to slow
2819 + query log. [session, query]
2820   --log-slow-slave-statements
2821 - Log slow statements executed by slave thread to the slow
2822 - log if it is open.
2823 + Log queries replayed be the slave SQL thread
2824 + --log-slow-sp-statements
2825 + Log slow statements executed by stored procedure to the
2826 + slow log if it is open.
2827 + (Defaults to on; use --skip-log-slow-sp-statements to disable.)
2828 + --log-slow-verbosity=name
2829 + Choose how verbose the messages to your slow log will be.
2830 + Multiple flags allowed in a comma-separated string.
2831 + [microtime, query_plan, innodb, profiling,
2832 + profiling_use_getrusage]
2833   --log-tc=name       Path to transaction coordinator log (used for
2834   transactions that affect more than one storage engine,
2835   when binary log is disabled).
2836 @@ -660,6 +683,18 @@
2837   Log slow queries to given log file. Defaults logging to
2838   hostname-slow.log. Must be enabled to activate other slow
2839   log options
2840 + --slow-query-log-timestamp-always
2841 + Timestamp is printed for all records of the slow log even
2842 + if they are same time.
2843 + --slow-query-log-timestamp-precision=name
2844 + Log slow statements executed by stored procedure to the
2845 + slow log if it is open. [second, microsecond]
2846 + --slow-query-log-use-global-control=name
2847 + Choose flags, wich always use the global variables.
2848 + Multiple flags allowed in a comma-separated string.
2849 + [none, log_slow_filter, log_slow_rate_limit,
2850 + log_slow_verbosity, long_query_time,
2851 + min_examined_row_limit, all]
2852   --socket=name       Socket file to use for connection
2853   --sort-buffer-size=#
2854   Each thread that needs to do a sort allocates a buffer of
2855 @@ -817,7 +852,12 @@
2856  log-short-format FALSE
2857  log-slave-updates FALSE
2858  log-slow-admin-statements FALSE
2859 +log-slow-filter
2860 +log-slow-rate-limit 1
2861 +log-slow-rate-type session
2862  log-slow-slave-statements FALSE
2863 +log-slow-sp-statements TRUE
2864 +log-slow-verbosity
2865  log-tc tc.log
2866  log-tc-size 24576
2867  log-warnings 1
2868 @@ -933,6 +973,9 @@
2869  slave-type-conversions
2870  slow-launch-time 2
2871  slow-query-log FALSE
2872 +slow-query-log-timestamp-always FALSE
2873 +slow-query-log-timestamp-precision second
2874 +slow-query-log-use-global-control
2875  sort-buffer-size 2097152
2876  sporadic-binlog-dump-fail FALSE
2877  sql-mode
2878 --- /dev/null
2879 +++ b/mysql-test/r/percona_slow_query_log_rate.result
2880 @@ -0,0 +1,78 @@
2881 +SET GLOBAL long_query_time=1;
2882 +SET GLOBAL log_slow_rate_type='session';
2883 +SET GLOBAL log_slow_rate_limit=3;
2884 +[log_start.inc] percona.slow_extended.log_slow_rate_limit
2885 +SET SESSION query_exec_time=1.1;
2886 +SET SESSION query_exec_id=1;
2887 +SELECT 'connection_one';
2888 +connection_one
2889 +connection_one
2890 +SET SESSION query_exec_time=1.1;
2891 +SET SESSION query_exec_id=2;
2892 +SELECT 'connection_two';
2893 +connection_two
2894 +connection_two
2895 +SET SESSION query_exec_time=1.1;
2896 +SET SESSION query_exec_id=3;
2897 +SELECT 'connection_three';
2898 +connection_three
2899 +connection_three
2900 +SET SESSION query_exec_time=1.1;
2901 +SET SESSION query_exec_id=4;
2902 +SELECT 'connection_one';
2903 +connection_one
2904 +connection_one
2905 +SET SESSION query_exec_time=1.1;
2906 +SET SESSION query_exec_id=5;
2907 +SELECT 'connection_two';
2908 +connection_two
2909 +connection_two
2910 +SET SESSION query_exec_time=1.1;
2911 +SET SESSION query_exec_id=6;
2912 +SELECT 'connection_three';
2913 +connection_three
2914 +connection_three
2915 +[log_stop.inc] percona.slow_extended.log_slow_rate_limit
2916 +[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern:
2917 +[log_grep.inc] sum:  2
2918 +[log_grep.inc] zero: 2
2919 +SET GLOBAL log_slow_rate_type='query';
2920 +SET GLOBAL log_slow_rate_limit=2;
2921 +[log_start.inc] percona.slow_extended.log_slow_rate_limit
2922 +SET SESSION query_exec_time=1.1;
2923 +SET SESSION query_exec_id=1;
2924 +SELECT 'connection_one';
2925 +connection_one
2926 +connection_one
2927 +SET SESSION query_exec_time=1.1;
2928 +SET SESSION query_exec_id=2;
2929 +SELECT 'connection_two';
2930 +connection_two
2931 +connection_two
2932 +SET SESSION query_exec_time=1.1;
2933 +SET SESSION query_exec_id=3;
2934 +SELECT 'connection_three';
2935 +connection_three
2936 +connection_three
2937 +SET SESSION query_exec_time=1.1;
2938 +SET SESSION query_exec_id=4;
2939 +SELECT 'connection_one';
2940 +connection_one
2941 +connection_one
2942 +SET SESSION query_exec_time=1.1;
2943 +SET SESSION query_exec_id=5;
2944 +SELECT 'connection_two';
2945 +connection_two
2946 +connection_two
2947 +SET SESSION query_exec_time=1.1;
2948 +SET SESSION query_exec_id=6;
2949 +SELECT 'connection_three';
2950 +connection_three
2951 +connection_three
2952 +[log_stop.inc] percona.slow_extended.log_slow_rate_limit
2953 +[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern:
2954 +[log_grep.inc] sum:  3
2955 +[log_grep.inc] zero: 0
2956 +SET GLOBAL long_query_time=default;
2957 +SET GLOBAL log_slow_rate_type=default;
2958 +SET GLOBAL log_slow_rate_limit=default;
2959 --- /dev/null
2960 +++ b/mysql-test/t/percona_slow_query_log_rate.test
2961 @@ -0,0 +1,16 @@
2962 +--source include/have_debug.inc
2963 +--let log_file=percona.slow_extended.log_slow_rate_limit
2964 +
2965 +SET GLOBAL long_query_time=1;
2966 +
2967 +SET GLOBAL log_slow_rate_type='session';
2968 +SET GLOBAL log_slow_rate_limit=3;
2969 +--source include/percona_slow_query_log_rate.inc
2970 +
2971 +SET GLOBAL log_slow_rate_type='query';
2972 +SET GLOBAL log_slow_rate_limit=2;
2973 +--source include/percona_slow_query_log_rate.inc
2974 +
2975 +SET GLOBAL long_query_time=default;
2976 +SET GLOBAL log_slow_rate_type=default;
2977 +SET GLOBAL log_slow_rate_limit=default;
2978 --- /dev/null
2979 +++ b/mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test
2980 @@ -0,0 +1 @@
2981 +SELECT @@global.log_slow_rate_limit;
2982 --- /dev/null
2983 +++ b/mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result
2984 @@ -0,0 +1,3 @@
2985 +SELECT @@global.log_slow_rate_limit;
2986 +@@global.log_slow_rate_limit
2987 +1
2988 --- /dev/null
2989 +++ b/mysql-test/suite/sys_vars/t/log_slow_rate_type_basic.test
2990 @@ -0,0 +1 @@
2991 +SELECT @@global.log_slow_rate_type;
2992 --- /dev/null
2993 +++ b/mysql-test/suite/sys_vars/r/log_slow_rate_type_basic.result
2994 @@ -0,0 +1,3 @@
2995 +SELECT @@global.log_slow_rate_type;
2996 +@@global.log_slow_rate_type
2997 +session
2998 --- /dev/null
2999 +++ b/mysql-test/include/percona_slow_query_log_rate.inc
3000 @@ -0,0 +1,42 @@
3001 +--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
3002 +--connection default
3003 +--source include/log_start.inc
3004 +
3005 +--connect (connection_one,localhost,root,,)
3006 +--connect (connection_two,localhost,root,,)
3007 +--connect (connection_three,localhost,root,,)
3008 +
3009 +--let i=2
3010 +--let k=1
3011 +
3012 +while($i)
3013 +{
3014 +--connection connection_one
3015 +SET SESSION query_exec_time=1.1;
3016 +eval SET SESSION query_exec_id=$k;
3017 +inc $k;
3018 +SELECT 'connection_one';
3019 +
3020 +--connection connection_two
3021 +SET SESSION query_exec_time=1.1;
3022 +eval SET SESSION query_exec_id=$k;
3023 +inc $k;
3024 +SELECT 'connection_two';
3025 +
3026 +--connection connection_three
3027 +SET SESSION query_exec_time=1.1;
3028 +eval SET SESSION query_exec_id=$k;
3029 +inc $k;
3030 +SELECT 'connection_three';
3031 +
3032 +dec $i;
3033 +}
3034 +
3035 +--connection default
3036 +--disconnect connection_one
3037 +--disconnect connection_two
3038 +--disconnect connection_three
3039 +--source include/wait_condition.inc
3040 +--source include/log_stop.inc
3041 +--let log_slow_rate_test=1
3042 +--source include/log_grep.inc
3043 --- /dev/null
3044 +++ b/mysql-test/suite/sys_vars/r/query_exec_id_basic.result
3045 @@ -0,0 +1,2 @@
3046 +SET GLOBAL query_exec_id=default;
3047 +SET SESSION query_exec_id=default;
3048 --- /dev/null
3049 +++ b/mysql-test/suite/sys_vars/t/query_exec_id_basic.test
3050 @@ -0,0 +1,4 @@
3051 +--source include/have_debug.inc
3052 +
3053 +SET GLOBAL query_exec_id=default;
3054 +SET SESSION query_exec_id=default;