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