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