mysql-microslow_innodb.patch

   1 diff -ruN a/include/my_getopt.h b/include/my_getopt.h
   2 --- a/include/my_getopt.h       Tue Jul 28 23:39:12 2009 -0700
   3 +++ b/include/my_getopt.h       Tue Jul 28 23:42:44 2009 -0700
   4 @@ -28,7 +28,8 @@
   5  #define GET_ULL        8
   6  #define GET_STR        9
   7  #define GET_STR_ALLOC 10
   8 -#define GET_DISABLED  11
   9 +#define GET_MICROTIME 11
  10 +#define GET_DISABLED  12
  11
  12  #define GET_ASK_ADDR    128
  13  #define GET_TYPE_MASK   127
  14 diff -ruN a/include/my_time.h b/include/my_time.h
  15 --- a/include/my_time.h Tue Jul 28 23:39:12 2009 -0700
  16 +++ b/include/my_time.h Tue Jul 28 23:42:44 2009 -0700
  17 @@ -140,7 +140,7 @@
  18  int my_date_to_str(const MYSQL_TIME *l_time, char *to);
  19  int my_datetime_to_str(const MYSQL_TIME *l_time, char *to);
  20  int my_TIME_to_str(const MYSQL_TIME *l_time, char *to);
  21 -
  22 +ulonglong my_timer(ulonglong *ltime, ulonglong frequency);
  23  C_MODE_END
  24
  25  #endif /* _my_time_h_ */
  26 diff -ruN a/innobase/buf/buf0buf.c b/innobase/buf/buf0buf.c
  27 --- a/innobase/buf/buf0buf.c    Tue Jul 28 23:39:12 2009 -0700
  28 +++ b/innobase/buf/buf0buf.c    Tue Jul 28 23:42:44 2009 -0700
  29 @@ -37,6 +37,10 @@
  30  #include "log0log.h"
  31  #include "trx0undo.h"
  32  #include "srv0srv.h"
  33 +#include "trx0trx.h"
  34 +
  35 +/* prototypes for new functions added to ha_innodb.cc */
  36 +trx_t* innobase_get_trx();
  37
  38  /*
  39                 IMPLEMENTATION OF THE BUFFER POOL
  40 @@ -1086,6 +1090,36 @@
  41         return(block);
  42  }
  43
  44 +inline void _increment_page_get_statistics(buf_block_t* block, trx_t* trx)
  45 +{
  46 +       ulint           block_hash;
  47 +       ulint           block_hash_byte;
  48 +       byte            block_hash_offset;
  49 +
  50 +       ut_ad(block);
  51 +
  52 +       if (!srv_slow_log || !trx || !trx->take_stats)
  53 +               return;
  54 +
  55 +       if (!trx->distinct_page_access_hash) {
  56 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
  57 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
  58 +       }
  59 +
  60 +        block_hash = ut_hash_ulint((block->space << 20) + block->space +
  61 +                                       block->offset, DPAH_SIZE << 3);
  62 +       block_hash_byte = block_hash >> 3;
  63 +       block_hash_offset = (byte) block_hash & 0x07;
  64 +       if (block_hash_byte < 0 || block_hash_byte >= DPAH_SIZE)
  65 +               fprintf(stderr, "!!! block_hash_byte = %lu  block_hash_offset = %lu !!!\n", block_hash_byte, block_hash_offset);
  66 +       if (block_hash_offset < 0 || block_hash_offset > 7)
  67 +               fprintf(stderr, "!!! block_hash_byte = %lu  block_hash_offset = %lu !!!\n", block_hash_byte, block_hash_offset);
  68 +       if ((trx->distinct_page_access_hash[block_hash_byte] & ((byte) 0x01 << block_hash_offset)) == 0)
  69 +               trx->distinct_page_access++;
  70 +       trx->distinct_page_access_hash[block_hash_byte] |= (byte) 0x01 << block_hash_offset;
  71 +       return;
  72 +}
  73 +
  74  /************************************************************************
  75  This is the general function used to get access to a database page. */
  76
  77 @@ -1108,6 +1142,11 @@
  78         ulint           fix_type;
  79         ibool           success;
  80         ibool           must_read;
  81 +       trx_t*          trx = NULL;
  82 +       ulint           sec;
  83 +       ulint           ms;
  84 +       ib_longlong     start_time;
  85 +       ib_longlong     finish_time;
  86
  87         ut_ad(mtr);
  88         ut_ad((rw_latch == RW_S_LATCH)
  89 @@ -1119,6 +1158,9 @@
  90  #ifndef UNIV_LOG_DEBUG
  91         ut_ad(!ibuf_inside() || ibuf_page(space, offset));
  92  #endif
  93 +       if (srv_slow_log) {
  94 +               trx = innobase_get_trx();
  95 +       }
  96         buf_pool->n_page_gets++;
  97  loop:
  98         block = NULL;
  99 @@ -1148,7 +1190,7 @@
 100                         return(NULL);
 101                 }
 102
 103 -               buf_read_page(space, offset);
 104 +               buf_read_page(space, offset, trx);
 105
 106  #ifdef UNIV_DEBUG
 107                 buf_dbg_counter++;
 108 @@ -1261,6 +1303,11 @@
 109                         /* Let us wait until the read operation
 110                         completes */
 111
 112 +                       if (srv_slow_log && trx && trx->take_stats)
 113 +                       {
 114 +                               ut_usectime(&sec, &ms);
 115 +                               start_time = (ib_longlong)sec * 1000000 + ms;
 116 +                       }
 117                         for (;;) {
 118                                 mutex_enter(&block->mutex);
 119
 120 @@ -1276,6 +1323,12 @@
 121                                        break;
 122                                 }
 123                         }
 124 +                       if (srv_slow_log && trx && trx->take_stats && start_time)
 125 +                       {
 126 +                               ut_usectime(&sec, &ms);
 127 +                               finish_time = (ib_longlong)sec * 1000000 + ms;
 128 +                               trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 129 +                       }
 130                 }
 131
 132                 fix_type = MTR_MEMO_BUF_FIX;
 133 @@ -1296,12 +1349,17 @@
 134                 /* In the case of a first access, try to apply linear
 135                 read-ahead */
 136
 137 -               buf_read_ahead_linear(space, offset);
 138 +               buf_read_ahead_linear(space, offset, trx);
 139         }
 140
 141  #ifdef UNIV_IBUF_DEBUG
 142         ut_a(ibuf_count_get(block->space, block->offset) == 0);
 143  #endif
 144 +
 145 +       if (srv_slow_log) {
 146 +               _increment_page_get_statistics(block, trx);
 147 +       }
 148 +
 149         return(block->frame);
 150  }
 151
 152 @@ -1326,6 +1384,7 @@
 153         ibool           accessed;
 154         ibool           success;
 155         ulint           fix_type;
 156 +       trx_t*          trx = NULL;
 157
 158         ut_ad(mtr && block);
 159         ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
 160 @@ -1440,7 +1499,7 @@
 161                 read-ahead */
 162
 163                 buf_read_ahead_linear(buf_frame_get_space_id(guess),
 164 -                                       buf_frame_get_page_no(guess));
 165 +                                       buf_frame_get_page_no(guess), trx);
 166         }
 167
 168  #ifdef UNIV_IBUF_DEBUG
 169 @@ -1448,6 +1507,11 @@
 170  #endif
 171         buf_pool->n_page_gets++;
 172
 173 +       if (srv_slow_log) {
 174 +               trx = innobase_get_trx();
 175 +               _increment_page_get_statistics(block, trx);
 176 +       }
 177 +
 178         return(TRUE);
 179  }
 180
 181 @@ -1470,6 +1534,7 @@
 182         buf_block_t*    block;
 183         ibool           success;
 184         ulint           fix_type;
 185 +       trx_t*          trx = NULL;
 186
 187         ut_ad(mtr);
 188         ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
 189 @@ -1559,6 +1624,11 @@
 190  #endif
 191         buf_pool->n_page_gets++;
 192
 193 +       if (srv_slow_log) {
 194 +               trx = innobase_get_trx();
 195 +               _increment_page_get_statistics(block, trx);
 196 +       }
 197 +
 198         return(TRUE);
 199  }
 200
 201 diff -ruN a/innobase/buf/buf0rea.c b/innobase/buf/buf0rea.c
 202 --- a/innobase/buf/buf0rea.c    Tue Jul 28 23:39:12 2009 -0700
 203 +++ b/innobase/buf/buf0rea.c    Tue Jul 28 23:42:44 2009 -0700
 204 @@ -70,7 +70,8 @@
 205                         treat the tablespace as dropped; this is a timestamp we
 206                         use to stop dangling page reads from a tablespace
 207                         which we have DISCARDed + IMPORTed back */
 208 -       ulint   offset) /* in: page number */
 209 +       ulint   offset, /* in: page number */
 210 +       trx_t*  trx)
 211  {
 212         buf_block_t*    block;
 213         ulint           wake_later;
 214 @@ -140,10 +141,10 @@
 215
 216         ut_a(block->state == BUF_BLOCK_FILE_PAGE);
 217
 218 -       *err = fil_io(OS_FILE_READ | wake_later,
 219 +       *err = _fil_io(OS_FILE_READ | wake_later,
 220                         sync, space,
 221                         offset, 0, UNIV_PAGE_SIZE,
 222 -                       (void*)block->frame, (void*)block);
 223 +                       (void*)block->frame, (void*)block, trx);
 224         ut_a(*err == DB_SUCCESS);
 225
 226         if (sync) {
 227 @@ -174,8 +175,9 @@
 228                         the page at the given page number does not get
 229                         read even if we return a value > 0! */
 230         ulint   space,  /* in: space id */
 231 -       ulint   offset) /* in: page number of a page which the current thread
 232 +       ulint   offset, /* in: page number of a page which the current thread
 233                         wants to access */
 234 +       trx_t*  trx)
 235  {
 236         ib_longlong     tablespace_version;
 237         buf_block_t*    block;
 238 @@ -270,7 +272,7 @@
 239                 if (!ibuf_bitmap_page(i)) {
 240                         count += buf_read_page_low(&err, FALSE, ibuf_mode
 241                                         | OS_AIO_SIMULATED_WAKE_LATER,
 242 -                                       space, tablespace_version, i);
 243 +                                       space, tablespace_version, i, trx);
 244                         if (err == DB_TABLESPACE_DELETED) {
 245                                 ut_print_timestamp(stderr);
 246                                 fprintf(stderr,
 247 @@ -314,7 +316,8 @@
 248                         /* out: number of page read requests issued: this can
 249                         be > 1 if read-ahead occurred */
 250         ulint   space,  /* in: space id */
 251 -       ulint   offset) /* in: page number */
 252 +       ulint   offset, /* in: page number */
 253 +       trx_t*  trx)
 254  {
 255         ib_longlong     tablespace_version;
 256         ulint           count;
 257 @@ -323,13 +326,13 @@
 258
 259         tablespace_version = fil_space_get_version(space);
 260
 261 -       count = buf_read_ahead_random(space, offset);
 262 +       count = buf_read_ahead_random(space, offset, trx);
 263
 264         /* We do the i/o in the synchronous aio mode to save thread
 265         switches: hence TRUE */
 266
 267         count2 = buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
 268 -                                       tablespace_version, offset);
 269 +                                       tablespace_version, offset, trx);
 270          srv_buf_pool_reads+= count2;
 271         if (err == DB_TABLESPACE_DELETED) {
 272                 ut_print_timestamp(stderr);
 273 @@ -374,8 +377,9 @@
 274  /*==================*/
 275                         /* out: number of page read requests issued */
 276         ulint   space,  /* in: space id */
 277 -       ulint   offset) /* in: page number of a page; NOTE: the current thread
 278 +       ulint   offset, /* in: page number of a page; NOTE: the current thread
 279                         must want access to this page (see NOTE 3 above) */
 280 +       trx_t*  trx)
 281  {
 282         ib_longlong     tablespace_version;
 283         buf_block_t*    block;
 284 @@ -556,7 +560,7 @@
 285                 if (!ibuf_bitmap_page(i)) {
 286                         count += buf_read_page_low(&err, FALSE, ibuf_mode
 287                                         | OS_AIO_SIMULATED_WAKE_LATER,
 288 -                                       space,  tablespace_version, i);
 289 +                                       space,  tablespace_version, i, trx);
 290                         if (err == DB_TABLESPACE_DELETED) {
 291                                 ut_print_timestamp(stderr);
 292                                 fprintf(stderr,
 293 @@ -625,10 +629,10 @@
 294         for (i = 0; i < n_stored; i++) {
 295                 if ((i + 1 == n_stored) && sync) {
 296                         buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE,
 297 -                               space_ids[i], space_versions[i], page_nos[i]);
 298 +                               space_ids[i], space_versions[i], page_nos[i], NULL);
 299                 } else {
 300                         buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE,
 301 -                               space_ids[i], space_versions[i], page_nos[i]);
 302 +                               space_ids[i], space_versions[i], page_nos[i], NULL);
 303                 }
 304
 305                 if (err == DB_TABLESPACE_DELETED) {
 306 @@ -704,11 +708,11 @@
 307
 308                 if ((i + 1 == n_stored) && sync) {
 309                         buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
 310 -                                       tablespace_version, page_nos[i]);
 311 +                                       tablespace_version, page_nos[i], NULL);
 312                 } else {
 313                         buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE
 314                                         | OS_AIO_SIMULATED_WAKE_LATER,
 315 -                                      space, tablespace_version, page_nos[i]);
 316 +                                      space, tablespace_version, page_nos[i], NULL);
 317                 }
 318         }
 319
 320 diff -ruN a/innobase/fil/fil0fil.c b/innobase/fil/fil0fil.c
 321 --- a/innobase/fil/fil0fil.c    Tue Jul 28 23:39:12 2009 -0700
 322 +++ b/innobase/fil/fil0fil.c    Tue Jul 28 23:42:44 2009 -0700
 323 @@ -3527,7 +3527,7 @@
 324                         node->name, node->handle, buf,
 325                         offset_low, offset_high,
 326                         UNIV_PAGE_SIZE * n_pages,
 327 -                       NULL, NULL);
 328 +                       NULL, NULL, NULL);
 329  #endif
 330                 if (success) {
 331                         node->size += n_pages;
 332 @@ -3851,7 +3851,7 @@
 333  Reads or writes data. This operation is asynchronous (aio). */
 334
 335  ulint
 336 -fil_io(
 337 +_fil_io(
 338  /*===*/
 339                                 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
 340                                 if we are trying to do i/o on a tablespace
 341 @@ -3877,8 +3877,9 @@
 342         void*   buf,            /* in/out: buffer where to store read data
 343                                 or from where to write; in aio this must be
 344                                 appropriately aligned */
 345 -       void*   message)        /* in: message for aio handler if non-sync
 346 +       void*   message,        /* in: message for aio handler if non-sync
 347                                 aio used, else ignored */
 348 +       trx_t*  trx)
 349  {
 350         fil_system_t*   system          = fil_system;
 351         ulint           mode;
 352 @@ -4018,7 +4019,7 @@
 353  #else
 354         /* Queue the aio request */
 355         ret = os_aio(type, mode | wake_later, node->name, node->handle, buf,
 356 -                               offset_low, offset_high, len, node, message);
 357 +                               offset_low, offset_high, len, node, message, trx);
 358  #endif
 359         ut_a(ret);
 360
 361 diff -ruN a/innobase/include/buf0rea.h b/innobase/include/buf0rea.h
 362 --- a/innobase/include/buf0rea.h        Tue Jul 28 23:39:12 2009 -0700
 363 +++ b/innobase/include/buf0rea.h        Tue Jul 28 23:42:44 2009 -0700
 364 @@ -10,6 +10,7 @@
 365  #define buf0rea_h
 366
 367  #include "univ.i"
 368 +#include "trx0types.h"
 369  #include "buf0types.h"
 370
 371  /************************************************************************
 372 @@ -25,7 +26,8 @@
 373                         /* out: number of page read requests issued: this can
 374                         be > 1 if read-ahead occurred */
 375         ulint   space,  /* in: space id */
 376 -       ulint   offset);/* in: page number */
 377 +       ulint   offset, /* in: page number */
 378 +       trx_t*  trx);
 379  /************************************************************************
 380  Applies linear read-ahead if in the buf_pool the page is a border page of
 381  a linear read-ahead area and all the pages in the area have been accessed.
 382 @@ -55,8 +57,9 @@
 383  /*==================*/
 384                         /* out: number of page read requests issued */
 385         ulint   space,  /* in: space id */
 386 -       ulint   offset);/* in: page number of a page; NOTE: the current thread
 387 +       ulint   offset, /* in: page number of a page; NOTE: the current thread
 388                         must want access to this page (see NOTE 3 above) */
 389 +       trx_t*  trx);
 390  /************************************************************************
 391  Issues read requests for pages which the ibuf module wants to read in, in
 392  order to contract the insert buffer tree. Technically, this function is like
 393 diff -ruN a/innobase/include/fil0fil.h b/innobase/include/fil0fil.h
 394 --- a/innobase/include/fil0fil.h        Tue Jul 28 23:39:12 2009 -0700
 395 +++ b/innobase/include/fil0fil.h        Tue Jul 28 23:42:44 2009 -0700
 396 @@ -534,8 +534,11 @@
 397  /************************************************************************
 398  Reads or writes data. This operation is asynchronous (aio). */
 399
 400 +#define fil_io(type, sync, space_id, block_offset, byte_offset, len, buf, message) \
 401 +       _fil_io(type, sync, space_id, block_offset, byte_offset, len, buf, message, NULL)
 402 +
 403  ulint
 404 -fil_io(
 405 +_fil_io(
 406  /*===*/
 407                                 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
 408                                 if we are trying to do i/o on a tablespace
 409 @@ -561,8 +564,9 @@
 410         void*   buf,            /* in/out: buffer where to store read data
 411                                 or from where to write; in aio this must be
 412                                 appropriately aligned */
 413 -       void*   message);       /* in: message for aio handler if non-sync
 414 +       void*   message,        /* in: message for aio handler if non-sync
 415                                 aio used, else ignored */
 416 +       trx_t*  trx);
 417  /************************************************************************
 418  Reads data from a space to a buffer. Remember that the possible incomplete
 419  blocks at the end of file are ignored: they are not taken into account when
 420 diff -ruN a/innobase/include/os0file.h b/innobase/include/os0file.h
 421 --- a/innobase/include/os0file.h        Tue Jul 28 23:39:12 2009 -0700
 422 +++ b/innobase/include/os0file.h        Tue Jul 28 23:42:44 2009 -0700
 423 @@ -11,6 +11,8 @@
 424
 425  #include "univ.i"
 426
 427 +#include "trx0types.h"
 428 +
 429  #ifndef __WIN__
 430  #include <dirent.h>
 431  #include <sys/stat.h>
 432 @@ -421,8 +423,11 @@
 433  /***********************************************************************
 434  Requests a synchronous read operation. */
 435
 436 +#define os_file_read(file, buf, offset, offset_high, n)         \
 437 +               _os_file_read(file, buf, offset, offset_high, n, NULL)
 438 +
 439  ibool
 440 -os_file_read(
 441 +_os_file_read(
 442  /*=========*/
 443                                 /* out: TRUE if request was
 444                                 successful, FALSE if fail */
 445 @@ -432,7 +437,8 @@
 446                                 offset where to read */
 447         ulint           offset_high,/* in: most significant 32 bits of
 448                                 offset */
 449 -       ulint           n);     /* in: number of bytes to read */
 450 +       ulint           n,      /* in: number of bytes to read */
 451 +       trx_t*          trx);
 452  /***********************************************************************
 453  Rewind file to its start, read at most size - 1 bytes from it to str, and
 454  NUL-terminate str. All errors are silently ignored. This function is
 455 @@ -584,7 +590,8 @@
 456                                 can be used to identify a completed aio
 457                                 operation); if mode is OS_AIO_SYNC, these
 458                                 are ignored */
 459 -       void*           message2);
 460 +       void*           message2,
 461 +       trx_t*          trx);
 462  /****************************************************************************
 463  Wakes up all async i/o threads so that they know to exit themselves in
 464  shutdown. */
 465 diff -ruN a/innobase/include/srv0srv.h b/innobase/include/srv0srv.h
 466 --- a/innobase/include/srv0srv.h        Tue Jul 28 23:39:12 2009 -0700
 467 +++ b/innobase/include/srv0srv.h        Tue Jul 28 23:42:44 2009 -0700
 468 @@ -27,6 +27,8 @@
 469  #define SRV_AUTO_EXTEND_INCREMENT      \
 470         (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
 471
 472 +extern ibool   srv_slow_log;
 473 +
 474  /* This is set to TRUE if the MySQL user has set it in MySQL */
 475  extern ibool   srv_lower_case_table_names;
 476
 477 diff -ruN a/innobase/include/trx0trx.h b/innobase/include/trx0trx.h
 478 --- a/innobase/include/trx0trx.h        Tue Jul 28 23:39:12 2009 -0700
 479 +++ b/innobase/include/trx0trx.h        Tue Jul 28 23:42:44 2009 -0700
 480 @@ -666,6 +666,17 @@
 481         /*------------------------------*/
 482         char detailed_error[256];       /* detailed error message for last
 483                                         error, or empty. */
 484 +       /*------------------------------*/
 485 +       ulint           io_reads;
 486 +       ib_longlong     io_read;
 487 +       ulint           io_reads_wait_timer;
 488 +       ib_longlong     lock_que_wait_ustarted;
 489 +       ulint           lock_que_wait_timer;
 490 +       ulint           innodb_que_wait_timer;
 491 +       ulint           distinct_page_access;
 492 +#define        DPAH_SIZE       8192
 493 +       byte*           distinct_page_access_hash;
 494 +       ibool           take_stats;
 495  };
 496
 497  #define TRX_MAX_N_THREADS      32      /* maximum number of concurrent
 498 diff -ruN a/innobase/lock/lock0lock.c b/innobase/lock/lock0lock.c
 499 --- a/innobase/lock/lock0lock.c Tue Jul 28 23:39:12 2009 -0700
 500 +++ b/innobase/lock/lock0lock.c Tue Jul 28 23:42:44 2009 -0700
 501 @@ -1781,6 +1781,8 @@
 502  {
 503         lock_t* lock;
 504         trx_t*  trx;
 505 +       ulint   sec;
 506 +       ulint   ms;
 507
 508  #ifdef UNIV_SYNC_DEBUG
 509         ut_ad(mutex_own(&kernel_mutex));
 510 @@ -1836,6 +1838,10 @@
 511         trx->que_state = TRX_QUE_LOCK_WAIT;
 512         trx->was_chosen_as_deadlock_victim = FALSE;
 513         trx->wait_started = time(NULL);
 514 +       if (srv_slow_log && trx->take_stats) {
 515 +               ut_usectime(&sec, &ms);
 516 +               trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
 517 +       }
 518
 519         ut_a(que_thr_stop(thr));
 520
 521 @@ -3489,7 +3495,9 @@
 522  {
 523         lock_t* lock;
 524         trx_t*  trx;
 525 -
 526 +       ulint   sec;
 527 +       ulint   ms;
 528 +
 529  #ifdef UNIV_SYNC_DEBUG
 530         ut_ad(mutex_own(&kernel_mutex));
 531  #endif /* UNIV_SYNC_DEBUG */
 532 @@ -3539,6 +3547,10 @@
 533                 return(DB_SUCCESS);
 534         }
 535
 536 +       if (srv_slow_log && trx->take_stats) {
 537 +               ut_usectime(&sec, &ms);
 538 +               trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
 539 +       }
 540         trx->que_state = TRX_QUE_LOCK_WAIT;
 541         trx->was_chosen_as_deadlock_victim = FALSE;
 542         trx->wait_started = time(NULL);
 543 diff -ruN a/innobase/os/os0file.c b/innobase/os/os0file.c
 544 --- a/innobase/os/os0file.c     Tue Jul 28 23:39:12 2009 -0700
 545 +++ b/innobase/os/os0file.c     Tue Jul 28 23:42:44 2009 -0700
 546 @@ -14,6 +14,8 @@
 547  #include "srv0start.h"
 548  #include "fil0fil.h"
 549  #include "buf0buf.h"
 550 +#include "trx0sys.h"
 551 +#include "trx0trx.h"
 552
 553  #if defined(UNIV_HOTBACKUP) && defined(__WIN__)
 554  /* Add includes for the _stat() call to compile on Windows */
 555 @@ -1903,9 +1905,13 @@
 556  #ifndef __WIN__
 557  /***********************************************************************
 558  Does a synchronous read operation in Posix. */
 559 +
 560 +#define os_file_pread(file, buf, n, offset, offset_high)        \
 561 +               _os_file_pread(file, buf, n, offset, offset_high, NULL);
 562 +
 563  static
 564  ssize_t
 565 -os_file_pread(
 566 +_os_file_pread(
 567  /*==========*/
 568                                 /* out: number of bytes read, -1 if error */
 569         os_file_t       file,   /* in: handle to a file */
 570 @@ -1913,12 +1919,17 @@
 571         ulint           n,      /* in: number of bytes to read */
 572         ulint           offset, /* in: least significant 32 bits of file
 573                                 offset from where to read */
 574 -       ulint           offset_high) /* in: most significant 32 bits of
 575 +       ulint           offset_high, /* in: most significant 32 bits of
 576                                 offset */
 577 +        trx_t*         trx)
 578  {
 579          off_t  offs;
 580         ssize_t n_bytes;
 581 -
 582 +       ulint           sec;
 583 +       ulint           ms;
 584 +       ib_longlong     start_time;
 585 +       ib_longlong     finish_time;
 586 +
 587         ut_a((offset & 0xFFFFFFFFUL) == offset);
 588
 589          /* If off_t is > 4 bytes in size, then we assume we can pass a
 590 @@ -1937,7 +1948,13 @@
 591          }
 592
 593         os_n_file_reads++;
 594 -
 595 +       if (srv_slow_log && trx && trx->take_stats)
 596 +       {
 597 +               trx->io_reads++;
 598 +               trx->io_read += n;
 599 +               ut_usectime(&sec, &ms);
 600 +               start_time = (ib_longlong)sec * 1000000 + ms;
 601 +       }
 602  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 603          os_mutex_enter(os_file_count_mutex);
 604         os_file_n_pending_preads++;
 605 @@ -1951,6 +1968,13 @@
 606         os_n_pending_reads--;
 607          os_mutex_exit(os_file_count_mutex);
 608
 609 +        if (srv_slow_log && trx && trx->take_stats && start_time)
 610 +        {
 611 +               ut_usectime(&sec, &ms);
 612 +               finish_time = (ib_longlong)sec * 1000000 + ms;
 613 +                trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 614 +       }
 615 +
 616         return(n_bytes);
 617  #else
 618         {
 619 @@ -1981,6 +2005,13 @@
 620         os_n_pending_reads--;
 621          os_mutex_exit(os_file_count_mutex);
 622
 623 +        if (srv_slow_log && trx && trx->take_stats && start_time)
 624 +        {
 625 +               ut_usectime(&sec, &ms);
 626 +               finish_time = (ib_longlong)sec * 1000000 + ms;
 627 +                trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 628 +       }
 629 +
 630         return(ret);
 631         }
 632  #endif
 633 @@ -2103,7 +2134,7 @@
 634  Requests a synchronous positioned read operation. */
 635
 636  ibool
 637 -os_file_read(
 638 +_os_file_read(
 639  /*=========*/
 640                                 /* out: TRUE if request was
 641                                 successful, FALSE if fail */
 642 @@ -2113,7 +2144,8 @@
 643                                 offset where to read */
 644         ulint           offset_high, /* in: most significant 32 bits of
 645                                 offset */
 646 -       ulint           n)      /* in: number of bytes to read */
 647 +       ulint           n,      /* in: number of bytes to read */
 648 +        trx_t*         trx)
 649  {
 650  #ifdef __WIN__
 651         BOOL            ret;
 652 @@ -2177,7 +2209,7 @@
 653         os_bytes_read_since_printout += n;
 654
 655  try_again:
 656 -       ret = os_file_pread(file, buf, n, offset, offset_high);
 657 +       ret = _os_file_pread(file, buf, n, offset, offset_high, trx);
 658
 659         if ((ulint)ret == n) {
 660
 661 @@ -3137,7 +3169,8 @@
 662                                 offset */
 663         ulint           offset_high, /* in: most significant 32 bits of
 664                                 offset */
 665 -       ulint           len)    /* in: length of the block to read or write */
 666 +       ulint           len,    /* in: length of the block to read or write */
 667 +       trx_t*          trx)
 668  {
 669         os_aio_slot_t*  slot;
 670  #ifdef WIN_ASYNC_IO
 671 @@ -3390,7 +3423,8 @@
 672                                 can be used to identify a completed aio
 673                                 operation); if mode is OS_AIO_SYNC, these
 674                                 are ignored */
 675 -       void*           message2)
 676 +       void*           message2,
 677 +       trx_t*          trx)
 678  {
 679         os_aio_array_t* array;
 680         os_aio_slot_t*  slot;
 681 @@ -3429,8 +3463,8 @@
 682                 wait in the Windows case. */
 683
 684                 if (type == OS_FILE_READ) {
 685 -                       return(os_file_read(file, buf, offset,
 686 -                                                       offset_high, n));
 687 +                       return(_os_file_read(file, buf, offset,
 688 +                                                       offset_high, n, trx));
 689                 }
 690
 691                 ut_a(type == OS_FILE_WRITE);
 692 @@ -3463,8 +3497,13 @@
 693                 ut_error;
 694         }
 695
 696 +       if (trx && type == OS_FILE_READ)
 697 +       {
 698 +               trx->io_reads++;
 699 +               trx->io_read += n;
 700 +       }
 701         slot = os_aio_array_reserve_slot(type, array, message1, message2, file,
 702 -                                       name, buf, offset, offset_high, n);
 703 +                                       name, buf, offset, offset_high, n, trx);
 704         if (type == OS_FILE_READ) {
 705                 if (os_aio_use_native_aio) {
 706  #ifdef WIN_ASYNC_IO
 707 diff -ruN a/innobase/srv/srv0srv.c b/innobase/srv/srv0srv.c
 708 --- a/innobase/srv/srv0srv.c    Tue Jul 28 23:39:12 2009 -0700
 709 +++ b/innobase/srv/srv0srv.c    Tue Jul 28 23:42:44 2009 -0700
 710 @@ -48,6 +48,8 @@
 711  #include "srv0start.h"
 712  #include "row0mysql.h"
 713
 714 +ibool  srv_slow_log = 0;
 715 +
 716  /* This is set to TRUE if the MySQL user has set it in MySQL; currently
 717  affects only FOREIGN KEY definition parsing */
 718  ibool  srv_lower_case_table_names      = FALSE;
 719 @@ -1002,6 +1004,10 @@
 720         ibool                   has_slept = FALSE;
 721         srv_conc_slot_t*        slot      = NULL;
 722         ulint                   i;
 723 +       ib_longlong             start_time = 0L;
 724 +       ib_longlong             finish_time = 0L;
 725 +       ulint                   sec;
 726 +       ulint                   ms;
 727
 728         /* If trx has 'free tickets' to enter the engine left, then use one
 729         such ticket */
 730 @@ -1060,6 +1066,7 @@
 731      if (SRV_THREAD_SLEEP_DELAY > 0)
 732      {
 733        os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
 734 +      trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
 735      }
 736
 737                 trx->op_info = "";
 738 @@ -1115,12 +1122,23 @@
 739         /* Go to wait for the event; when a thread leaves InnoDB it will
 740         release this thread */
 741
 742 +       if (srv_slow_log && trx->take_stats) {
 743 +               ut_usectime(&sec, &ms);
 744 +               start_time = (ib_longlong)sec * 1000000 + ms;
 745 +       }
 746 +
 747         trx->op_info = "waiting in InnoDB queue";
 748
 749         os_event_wait(slot->event);
 750
 751         trx->op_info = "";
 752
 753 +       if (srv_slow_log && trx->take_stats && start_time) {
 754 +               ut_usectime(&sec, &ms);
 755 +               finish_time = (ib_longlong)sec * 1000000 + ms;
 756 +               trx->innodb_que_wait_timer += (ulint)(finish_time - start_time);
 757 +       }
 758 +
 759         os_fast_mutex_lock(&srv_conc_mutex);
 760
 761         srv_conc_n_waiting_threads--;
 762 diff -ruN a/innobase/trx/trx0trx.c b/innobase/trx/trx0trx.c
 763 --- a/innobase/trx/trx0trx.c    Tue Jul 28 23:39:12 2009 -0700
 764 +++ b/innobase/trx/trx0trx.c    Tue Jul 28 23:42:44 2009 -0700
 765 @@ -190,6 +190,15 @@
 766         trx->global_read_view_heap = mem_heap_create(256);
 767         trx->global_read_view = NULL;
 768         trx->read_view = NULL;
 769 +
 770 +       trx->io_reads = 0;
 771 +       trx->io_read = 0;
 772 +       trx->io_reads_wait_timer = 0;
 773 +       trx->lock_que_wait_timer = 0;
 774 +       trx->innodb_que_wait_timer = 0;
 775 +       trx->distinct_page_access = 0;
 776 +       trx->distinct_page_access_hash = NULL;
 777 +       trx->take_stats = FALSE;
 778
 779         /* Set X/Open XA transaction identification to NULL */
 780         memset(&trx->xid, 0, sizeof(trx->xid));
 781 @@ -230,6 +239,11 @@
 782
 783         trx->mysql_process_no = os_proc_get_number();
 784
 785 +       if (srv_slow_log && trx->take_stats) {
 786 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
 787 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
 788 +       }
 789 +
 790         return(trx);
 791  }
 792
 793 @@ -366,6 +380,12 @@
 794  /*===============*/
 795         trx_t*  trx)    /* in, own: trx object */
 796  {
 797 +       if (trx->distinct_page_access_hash)
 798 +       {
 799 +               mem_free(trx->distinct_page_access_hash);
 800 +               trx->distinct_page_access_hash= NULL;
 801 +       }
 802 +
 803         thr_local_free(trx->mysql_thread_id);
 804
 805         mutex_enter(&kernel_mutex);
 806 @@ -389,6 +409,12 @@
 807  /*====================*/
 808         trx_t*  trx)    /* in, own: trx object */
 809  {
 810 +       if (trx->distinct_page_access_hash)
 811 +       {
 812 +               mem_free(trx->distinct_page_access_hash);
 813 +               trx->distinct_page_access_hash= NULL;
 814 +       }
 815 +
 816         mutex_enter(&kernel_mutex);
 817
 818         trx_free(trx);
 819 @@ -1064,7 +1090,10 @@
 820         trx_t*  trx)    /* in: transaction */
 821  {
 822         que_thr_t*      thr;
 823 -
 824 +       ulint           sec;
 825 +       ulint           ms;
 826 +       ib_longlong     now;
 827 +
 828  #ifdef UNIV_SYNC_DEBUG
 829         ut_ad(mutex_own(&kernel_mutex));
 830  #endif /* UNIV_SYNC_DEBUG */
 831 @@ -1080,6 +1109,11 @@
 832                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
 833         }
 834
 835 +       if (srv_slow_log && trx->take_stats) {
 836 +               ut_usectime(&sec, &ms);
 837 +               now = (ib_longlong)sec * 1000000 + ms;
 838 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
 839 +       }
 840         trx->que_state = TRX_QUE_RUNNING;
 841  }
 842
 843 @@ -1093,6 +1127,9 @@
 844         trx_t*  trx)    /* in: transaction in the TRX_QUE_LOCK_WAIT state */
 845  {
 846         que_thr_t*      thr;
 847 +       ulint           sec;
 848 +       ulint           ms;
 849 +       ib_longlong     now;
 850
 851  #ifdef UNIV_SYNC_DEBUG
 852         ut_ad(mutex_own(&kernel_mutex));
 853 @@ -1109,6 +1146,11 @@
 854                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
 855         }
 856
 857 +       if (srv_slow_log && trx->take_stats) {
 858 +               ut_usectime(&sec, &ms);
 859 +               now = (ib_longlong)sec * 1000000 + ms;
 860 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
 861 +       }
 862         trx->que_state = TRX_QUE_RUNNING;
 863  }
 864
 865 diff -ruN a/mysys/my_getopt.c b/mysys/my_getopt.c
 866 --- a/mysys/my_getopt.c Tue Jul 28 23:39:12 2009 -0700
 867 +++ b/mysys/my_getopt.c Tue Jul 28 23:42:44 2009 -0700
 868 @@ -827,7 +827,8 @@
 869  #endif
 870      break;
 871    default:
 872 -    DBUG_ASSERT((optp->var_type & GET_TYPE_MASK) == GET_ULL);
 873 +    DBUG_ASSERT((optp->var_type & GET_TYPE_MASK) == GET_ULL
 874 +                || (optp->var_type & GET_TYPE_MASK) == GET_MICROTIME);
 875      break;
 876    }
 877
 878 @@ -1061,6 +1062,9 @@
 879        case GET_ULONG:
 880         printf("%lu\n", *((ulong*) value));
 881         break;
 882 +      case GET_MICROTIME:
 883 +       printf("%6f\n", ((double)(*((longlong*) value))) / 1000000.0);
 884 +       break;
 885        case GET_LL:
 886         printf("%s\n", llstr(*((longlong*) value), buff));
 887         break;
 888 diff -ruN /dev/null b/patch_info/microslow_innodb.info
 889 --- /dev/null   Thu Jan 01 00:00:00 1970 +0000
 890 +++ b/patch_info/microslow_innodb.info  Tue Jul 28 23:42:44 2009 -0700
 891 @@ -0,0 +1,15 @@
 892 +File=microslow_innodb.patch
 893 +Name=Extended statistics in slow.log
 894 +Version=1.2
 895 +Author=Percona <info@percona.com>
 896 +License=GPL
 897 +Comment=
 898 +Changelog
 899 +2008-11-26
 900 +YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
 901 +
 902 +2008-11-07
 903 +VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
 904 +
 905 +2008-11
 906 +Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
 907 diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh
 908 --- a/scripts/mysqldumpslow.sh  Tue Jul 28 23:39:12 2009 -0700
 909 +++ b/scripts/mysqldumpslow.sh  Tue Jul 28 23:42:44 2009 -0700
 910 @@ -83,8 +83,8 @@
 911      s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
 912      my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
 913
 914 -    s/^# Query_time: (\d+)  Lock_time: (\d+)  Rows_sent: (\d+).*\n//;
 915 -    my ($t, $l, $r) = ($1, $2, $3);
 916 +    s/^# Query_time: (\d+(\.\d+)?)  Lock_time: (\d+(\.\d+)?)  Rows_sent: (\d+(\.\d+)?).*\n//;
 917 +    my ($t, $l, $r) = ($1, $3, $5);
 918      $t -= $l unless $opt{l};
 919
 920      # remove fluff that mysqld writes to log when it (re)starts:
 921 diff -ruN a/sql-common/my_time.c b/sql-common/my_time.c
 922 --- a/sql-common/my_time.c      Tue Jul 28 23:39:12 2009 -0700
 923 +++ b/sql-common/my_time.c      Tue Jul 28 23:42:44 2009 -0700
 924 @@ -1251,3 +1251,37 @@
 925    return 0;
 926  }
 927
 928 +/*
 929 + int my_timer(ulonglong *ltime, ulonglong frequency)
 930 +
 931 + For performance measurement this function returns the number
 932 + of microseconds since the epoch (SVr4, BSD 4.3, POSIX 1003.1-2001)
 933 + or system start (Windows platforms).
 934 +
 935 + For windows platforms frequency value (obtained via
 936 + QueryPerformanceFrequency) has to be specified. The global frequency
 937 + value is set in mysqld.cc.
 938 +
 939 + If Windows platform doesn't support QueryPerformanceFrequency we will
 940 + obtain the time via GetClockCount, which supports microseconds only.
 941 +*/
 942 +
 943 +ulonglong my_timer(ulonglong *ltime, ulonglong frequency)
 944 +{
 945 +  ulonglong newtime= 0;
 946 +#ifdef __WIN__
 947 +  if (frequency)
 948 +  {
 949 +    QueryPerformanceCounter((LARGE_INTEGER *)&newtime);
 950 +    newtime/= (frequency * 1000000);
 951 +  } else
 952 +    newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */
 953 +#else
 954 +  struct timeval t;
 955 +  if (gettimeofday(&t, NULL) != -1)
 956 +    newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
 957 +#endif
 958 +  if (ltime)
 959 +    *ltime= newtime;
 960 +  return newtime;
 961 +}
 962 diff -ruN a/sql/filesort.cc b/sql/filesort.cc
 963 --- a/sql/filesort.cc   Tue Jul 28 23:39:12 2009 -0700
 964 +++ b/sql/filesort.cc   Tue Jul 28 23:42:44 2009 -0700
 965 @@ -182,6 +182,7 @@
 966    {
 967      statistic_increment(thd->status_var.filesort_scan_count, &LOCK_status);
 968    }
 969 +  thd->query_plan_flags|= QPLAN_FILESORT;
 970  #ifdef CAN_TRUST_RANGE
 971    if (select && select->quick && select->quick->records > 0L)
 972    {
 973 @@ -247,6 +248,7 @@
 974    }
 975    else
 976    {
 977 +    thd->query_plan_flags|= QPLAN_FILESORT_DISK;
 978      if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
 979      {
 980        x_free(table_sort.buffpek);
 981 @@ -1118,6 +1120,7 @@
 982
 983    statistic_increment(current_thd->status_var.filesort_merge_passes,
 984                       &LOCK_status);
 985 +  current_thd->query_plan_fsort_passes++;
 986    if (param->not_killable)
 987    {
 988      killed= &not_killable;
 989 diff -ruN a/sql/ha_innodb.cc b/sql/ha_innodb.cc
 990 --- a/sql/ha_innodb.cc  Tue Jul 28 23:39:12 2009 -0700
 991 +++ b/sql/ha_innodb.cc  Tue Jul 28 23:42:44 2009 -0700
 992 @@ -1,3 +1,4 @@
 993 +
 994  /* Copyright (C) 2000-2005 MySQL AB & Innobase Oy
 995
 996     This program is free software; you can redistribute it and/or modify
 997 @@ -804,9 +805,34 @@
 998                 trx->check_unique_secondary = TRUE;
 999         }
1000
1001 +       if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1002 +               trx->take_stats = TRUE;
1003 +       } else {
1004 +               trx->take_stats = FALSE;
1005 +       }
1006 +
1007         return(trx);
1008  }
1009
1010 +/*************************************************************************
1011 +Gets current trx. */
1012 +extern "C"
1013 +trx_t*
1014 +innobase_get_trx()
1015 +{
1016 +       THD *thd=current_thd;
1017 +       if (likely(thd != 0)) {
1018 +               return((trx_t*) thd->ha_data[innobase_hton.slot]);
1019 +       } else {
1020 +               return(NULL);
1021 +       }
1022 +}
1023 +
1024 +void
1025 +innobase_update_var_slow_log()
1026 +{
1027 +       srv_slow_log = (ibool) opt_slow_log;
1028 +}
1029
1030  /*************************************************************************
1031  Construct ha_innobase handler. */
1032 @@ -1309,6 +1335,8 @@
1033
1034         /* -------------- Log files ---------------------------*/
1035
1036 +       srv_slow_log = (ibool) opt_slow_log;
1037 +
1038         /* The default dir for log files is the datadir of MySQL */
1039
1040         if (!innobase_log_group_home_dir) {
1041 @@ -4687,6 +4715,12 @@
1042                 trx->check_unique_secondary = FALSE;
1043         }
1044
1045 +       if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1046 +               trx->take_stats = TRUE;
1047 +       } else {
1048 +               trx->take_stats = FALSE;
1049 +       }
1050 +
1051         if (lower_case_table_names) {
1052                 srv_lower_case_table_names = TRUE;
1053         } else {
1054 @@ -4959,6 +4993,12 @@
1055                 trx->check_unique_secondary = FALSE;
1056         }
1057
1058 +       if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1059 +               trx->take_stats = TRUE;
1060 +       } else {
1061 +               trx->take_stats = FALSE;
1062 +       }
1063 +
1064         name_len = strlen(name);
1065
1066         assert(name_len < 1000);
1067 @@ -5046,6 +5086,12 @@
1068                 trx->check_foreigns = FALSE;
1069         }
1070
1071 +       if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1072 +               trx->take_stats = TRUE;
1073 +       } else {
1074 +               trx->take_stats = FALSE;
1075 +       }
1076 +
1077         error = row_drop_database_for_mysql(namebuf, trx);
1078         my_free(namebuf, MYF(0));
1079
1080 @@ -5112,6 +5158,12 @@
1081                 trx->check_foreigns = FALSE;
1082         }
1083
1084 +       if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1085 +               trx->take_stats = TRUE;
1086 +       } else {
1087 +               trx->take_stats = FALSE;
1088 +       }
1089 +
1090         name_len1 = strlen(from);
1091         name_len2 = strlen(to);
1092
1093 @@ -6119,6 +6171,7 @@
1094  {
1095         row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
1096         trx_t*          trx;
1097 +       int i;
1098
1099         DBUG_ENTER("ha_innobase::external_lock");
1100         DBUG_PRINT("enter",("lock_type: %d", lock_type));
1101 @@ -6242,7 +6295,24 @@
1102
1103         if (trx->n_mysql_tables_in_use == 0) {
1104
1105 -               trx->mysql_n_tables_locked = 0;
1106 +               current_thd->innodb_was_used = TRUE;
1107 +               current_thd->innodb_io_reads += trx->io_reads;
1108 +               current_thd->innodb_io_read += trx->io_read;
1109 +               current_thd->innodb_io_reads_wait_timer += trx->io_reads_wait_timer;
1110 +               current_thd->innodb_lock_que_wait_timer += trx->lock_que_wait_timer;
1111 +               current_thd->innodb_innodb_que_wait_timer += trx->innodb_que_wait_timer;
1112 +                current_thd->innodb_page_access += trx->distinct_page_access;
1113 +
1114 +               trx->io_reads = 0;
1115 +               trx->io_read = 0;
1116 +               trx->io_reads_wait_timer = 0;
1117 +               trx->lock_que_wait_timer = 0;
1118 +               trx->innodb_que_wait_timer = 0;
1119 +               trx->distinct_page_access = 0;
1120 +               if (trx->distinct_page_access_hash)
1121 +                       memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
1122 +
1123 +               trx->mysql_n_tables_locked = 0;
1124                 prebuilt->used_in_HANDLER = FALSE;
1125
1126                 if (!(thd->options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN))) {
1127 diff -ruN a/sql/ha_innodb.h b/sql/ha_innodb.h
1128 --- a/sql/ha_innodb.h   Tue Jul 28 23:39:12 2009 -0700
1129 +++ b/sql/ha_innodb.h   Tue Jul 28 23:42:44 2009 -0700
1130 @@ -271,6 +271,8 @@
1131
1132  int innobase_start_trx_and_assign_read_view(THD* thd);
1133
1134 +void innobase_update_var_slow_log();
1135 +
1136  /***********************************************************************
1137  This function is used to prepare X/Open XA distributed transaction   */
1138
1139 diff -ruN a/sql/log.cc b/sql/log.cc
1140 --- a/sql/log.cc        Tue Jul 28 23:39:12 2009 -0700
1141 +++ b/sql/log.cc        Tue Jul 28 23:42:44 2009 -0700
1142 @@ -2291,11 +2291,12 @@
1143  */
1144
1145  bool MYSQL_LOG::write(THD *thd,const char *query, uint query_length,
1146 -                     time_t query_start_arg)
1147 +                     time_t query_start_arg, ulonglong query_start_timer)
1148  {
1149    bool error=0;
1150    time_t current_time;
1151 -  if (!is_open())
1152 +  ulonglong current_timer;
1153 +  if (!opt_slow_log || !is_open())
1154      return 0;
1155    DBUG_ENTER("MYSQL_LOG::write");
1156
1157 @@ -2305,7 +2306,8 @@
1158      int tmp_errno=0;
1159      char buff[80],*end;
1160      end=buff;
1161 -    if (!(thd->options & OPTION_UPDATE_LOG))
1162 +    if (!(thd->options & OPTION_UPDATE_LOG) &&
1163 +        !(thd->slave_thread && opt_log_slow_slave_statements))
1164      {
1165        VOID(pthread_mutex_unlock(&LOCK_log));
1166        DBUG_RETURN(0);
1167 @@ -2335,22 +2337,72 @@
1168        if (my_b_printf(&log_file, "# User@Host: %s[%s] @ %s [%s]\n",
1169                        sctx->priv_user ?
1170                        sctx->priv_user : "",
1171 -                      sctx->user ? sctx->user : "",
1172 +                      sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""),
1173                        sctx->host ? sctx->host : "",
1174                        sctx->ip ? sctx->ip : "") ==
1175            (uint) -1)
1176          tmp_errno=errno;
1177      }
1178 -    if (query_start_arg)
1179 +    if (query_start_timer)
1180      {
1181 +      char buf[5][20];
1182 +      ulonglong current_timer= my_timer(&current_timer, frequency);
1183 +      snprintf(buf[0], 20, "%.6f", (current_timer ? (current_timer - query_start_timer):0) / 1000000.0);
1184 +      snprintf(buf[1], 20, "%.6f", (thd->timer_after_lock - query_start_timer) / 1000000.0);
1185 +      if (!query_length)
1186 +      {
1187 +        thd->sent_row_count= thd->examined_row_count= 0;
1188 +        thd->row_count= 0;
1189 +        thd->innodb_was_used= FALSE;
1190 +        thd->query_plan_flags= QPLAN_NONE;
1191 +        thd->query_plan_fsort_passes= 0;
1192 +      }
1193 +
1194        /* For slow query log */
1195        if (my_b_printf(&log_file,
1196 -                      "# Query_time: %lu  Lock_time: %lu  Rows_sent: %lu  Rows_examined: %lu\n",
1197 -                      (ulong) (current_time - query_start_arg),
1198 -                      (ulong) (thd->time_after_lock - query_start_arg),
1199 +                      "# Thread_id: %lu  Schema: %s\n" \
1200 +                      "# Query_time: %s  Lock_time: %s  Rows_sent: %lu  Rows_examined: %lu  Rows_affected: %lu  Rows_read: %lu\n",
1201 +                      (ulong) thd->thread_id, (thd->db ? thd->db : ""),
1202 +                      buf[0], buf[1],
1203                        (ulong) thd->sent_row_count,
1204 -                      (ulong) thd->examined_row_count) == (uint) -1)
1205 +                      (ulong) thd->examined_row_count,
1206 +                      ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
1207 +                      (ulong) thd->row_count) == (uint) -1)
1208          tmp_errno=errno;
1209 +      if ((thd->variables.log_slow_verbosity & SLOG_V_QUERY_PLAN) &&
1210 +           my_b_printf(&log_file,
1211 +                      "# QC_Hit: %s  Full_scan: %s  Full_join: %s  Tmp_table: %s  Tmp_table_on_disk: %s\n" \
1212 +                      "# Filesort: %s  Filesort_on_disk: %s  Merge_passes: %lu\n",
1213 +                      ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
1214 +                      ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
1215 +                      ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
1216 +                      ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
1217 +                      ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
1218 +                      ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
1219 +                      ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
1220 +                      thd->query_plan_fsort_passes) == (uint) -1)
1221 +        tmp_errno=errno;
1222 +      if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) && thd->innodb_was_used)
1223 +      {
1224 +        snprintf(buf[2], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
1225 +        snprintf(buf[3], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
1226 +        snprintf(buf[4], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
1227 +        if (my_b_printf(&log_file,
1228 +                        "#   InnoDB_IO_r_ops: %lu  InnoDB_IO_r_bytes: %lu  InnoDB_IO_r_wait: %s\n" \
1229 +                        "#   InnoDB_rec_lock_wait: %s  InnoDB_queue_wait: %s\n" \
1230 +                        "#   InnoDB_pages_distinct: %lu\n",
1231 +                        (ulong) thd->innodb_io_reads,
1232 +                        (ulong) thd->innodb_io_read,
1233 +                        buf[2], buf[3], buf[4],
1234 +                        (ulong) thd->innodb_page_access) == (uint) -1)
1235 +          tmp_errno=errno;
1236 +      }
1237 +      else
1238 +      {
1239 +        if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) &&
1240 +            my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
1241 +          tmp_errno=errno;
1242 +      }
1243      }
1244      if (thd->db && strcmp(thd->db,db))
1245      {                                          // Database changed
1246 diff -ruN a/sql/log_event.cc b/sql/log_event.cc
1247 --- a/sql/log_event.cc  Tue Jul 28 23:39:12 2009 -0700
1248 +++ b/sql/log_event.cc  Tue Jul 28 23:42:44 2009 -0700
1249 @@ -2070,6 +2070,7 @@
1250        /* Execute the query (note that we bypass dispatch_command()) */
1251        const char* found_semicolon= NULL;
1252        mysql_parse(thd, thd->query, thd->query_length, &found_semicolon);
1253 +      log_slow_statement(thd);
1254
1255      }
1256      else
1257 diff -ruN a/sql/mysql_priv.h b/sql/mysql_priv.h
1258 --- a/sql/mysql_priv.h  Tue Jul 28 23:39:12 2009 -0700
1259 +++ b/sql/mysql_priv.h  Tue Jul 28 23:42:44 2009 -0700
1260 @@ -507,6 +507,78 @@
1261
1262  #define STRING_BUFFER_USUAL_SIZE 80
1263
1264 +/* Slow log */
1265 +
1266 +struct msl_opts
1267 +{
1268 +  ulong val;
1269 +  const char *name;
1270 +};
1271 +
1272 +#define SLOG_V_MICROTIME      1 << 0
1273 +#define SLOG_V_QUERY_PLAN     1 << 1
1274 +#define SLOG_V_INNODB         1 << 2
1275 +/* ... */
1276 +#define SLOG_V_INVALID        1 << 31
1277 +#define SLOG_V_NONE           SLOG_V_MICROTIME
1278 +
1279 +static const struct msl_opts slog_verb[]=
1280 +{
1281 +  /* Basic flags */
1282 +
1283 +  { SLOG_V_MICROTIME, "microtime" },
1284 +  { SLOG_V_QUERY_PLAN, "query_plan" },
1285 +  { SLOG_V_INNODB, "innodb" },
1286 +
1287 +  /* End of baisc flags */
1288 +
1289 +  { 0, "" },
1290 +
1291 +  /* Complex flags */
1292 +
1293 +  { SLOG_V_MICROTIME, "minimal" },
1294 +  { SLOG_V_MICROTIME|SLOG_V_QUERY_PLAN, "standard" },
1295 +  { SLOG_V_MICROTIME|SLOG_V_QUERY_PLAN|SLOG_V_INNODB, "full" },
1296 +
1297 +  /* End of complex flags */
1298 +
1299 +  { SLOG_V_INVALID, (char *)0 }
1300 +};
1301 +
1302 +#define QPLAN_NONE            0
1303 +#define QPLAN_QC              1 << 0
1304 +#define QPLAN_QC_NO           1 << 1
1305 +#define QPLAN_FULL_SCAN       1 << 2
1306 +#define QPLAN_FULL_JOIN       1 << 3
1307 +#define QPLAN_TMP_TABLE       1 << 4
1308 +#define QPLAN_TMP_DISK        1 << 5
1309 +#define QPLAN_FILESORT        1 << 6
1310 +#define QPLAN_FILESORT_DISK   1 << 7
1311 +/* ... */
1312 +#define QPLAN_MAX             1 << 31
1313 +
1314 +#define SLOG_F_QC_NO          QPLAN_QC_NO
1315 +#define SLOG_F_FULL_SCAN      QPLAN_FULL_SCAN
1316 +#define SLOG_F_FULL_JOIN      QPLAN_FULL_JOIN
1317 +#define SLOG_F_TMP_TABLE      QPLAN_TMP_TABLE
1318 +#define SLOG_F_TMP_DISK       QPLAN_TMP_DISK
1319 +#define SLOG_F_FILESORT       QPLAN_FILESORT
1320 +#define SLOG_F_FILESORT_DISK  QPLAN_FILESORT_DISK
1321 +#define SLOG_F_INVALID        1 << 31
1322 +#define SLOG_F_NONE           0
1323 +
1324 +static const struct msl_opts slog_filter[]=
1325 +{
1326 +  { SLOG_F_QC_NO,         "qc_miss" },
1327 +  { SLOG_F_FULL_SCAN,     "full_scan" },
1328 +  { SLOG_F_FULL_JOIN,     "full_join" },
1329 +  { SLOG_F_TMP_TABLE,     "tmp_table" },
1330 +  { SLOG_F_TMP_DISK,      "tmp_table_on_disk" },
1331 +  { SLOG_F_FILESORT,      "filesort" },
1332 +  { SLOG_F_FILESORT_DISK, "filesort_on_disk" },
1333 +  { SLOG_F_INVALID,       (char *)0 }
1334 +};
1335 +
1336  enum enum_parsing_place
1337  {
1338    NO_MATTER,
1339 @@ -1365,6 +1437,7 @@
1340  extern bool using_update_log, opt_large_files, server_id_supplied;
1341  extern bool opt_update_log, opt_bin_log, opt_error_log;
1342  extern my_bool opt_log, opt_slow_log, opt_log_queries_not_using_indexes;
1343 +extern char *opt_slow_logname;
1344  extern bool opt_disable_networking, opt_skip_show_db;
1345  extern my_bool opt_character_set_client_handshake;
1346  extern bool volatile abort_loop, shutdown_in_progress, grant_option;
1347 @@ -1376,7 +1449,8 @@
1348  extern my_bool opt_enable_named_pipe, opt_sync_frm, opt_allow_suspicious_udfs;
1349  extern my_bool opt_secure_auth;
1350  extern char* opt_secure_file_priv;
1351 -extern my_bool opt_log_slow_admin_statements;
1352 +extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
1353 +extern my_bool opt_use_global_long_query_time;
1354  extern my_bool sp_automatic_privileges, opt_noacl;
1355  extern my_bool opt_old_style_user_limits, trust_function_creators;
1356  extern uint opt_crash_binlog_innodb;
1357 diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
1358 --- a/sql/mysqld.cc     Tue Jul 28 23:39:12 2009 -0700
1359 +++ b/sql/mysqld.cc     Tue Jul 28 23:42:44 2009 -0700
1360 @@ -176,7 +176,6 @@
1361  static void getvolumeID(BYTE *volumeName);
1362  #endif /* __NETWARE__ */
1363
1364 -
1365  #ifdef _AIX41
1366  int initgroups(const char *,unsigned int);
1367  #endif
1368 @@ -411,10 +410,13 @@
1369  my_bool opt_secure_auth= 0;
1370  char* opt_secure_file_priv= 0;
1371  my_bool opt_log_slow_admin_statements= 0;
1372 +my_bool opt_log_slow_slave_statements= 0;
1373 +my_bool opt_use_global_long_query_time= 0;
1374  my_bool lower_case_file_system= 0;
1375  my_bool opt_large_pages= 0;
1376  uint    opt_large_page_size= 0;
1377  my_bool opt_old_style_user_limits= 0, trust_function_creators= 0;
1378 +char* opt_slow_logname= 0;
1379  /*
1380    True if there is at least one per-hour limit for some user, so we should
1381    check them before each query (and possibly reset counters when hour is
1382 @@ -509,6 +511,7 @@
1383  Ge_creator ge_creator;
1384  Le_creator le_creator;
1385
1386 +ulonglong frequency= 0;
1387
1388  FILE *bootstrap_file;
1389  int bootstrap_error;
1390 @@ -588,7 +591,7 @@
1391  static int cleanup_done;
1392  static ulong opt_specialflag, opt_myisam_block_size;
1393  static char *opt_logname, *opt_update_logname, *opt_binlog_index_name;
1394 -static char *opt_slow_logname, *opt_tc_heuristic_recover;
1395 +static char *opt_tc_heuristic_recover;
1396  static char *mysql_home_ptr, *pidfile_name_ptr;
1397  static char **defaults_argv;
1398  static char *opt_bin_logname;
1399 @@ -3700,6 +3703,8 @@
1400        unireg_abort(1);
1401      }
1402    }
1403 +  if (!QueryPerformanceFrequency((LARGE_INTEGER *)&frequency))
1404 +    frequency= 0;
1405  #endif /* __WIN__ */
1406
1407    if (init_common_variables(MYSQL_CONFIG_NAME,
1408 @@ -4963,7 +4968,7 @@
1409    OPT_INTERACTIVE_TIMEOUT, OPT_JOIN_BUFF_SIZE,
1410    OPT_KEY_BUFFER_SIZE, OPT_KEY_CACHE_BLOCK_SIZE,
1411    OPT_KEY_CACHE_DIVISION_LIMIT, OPT_KEY_CACHE_AGE_THRESHOLD,
1412 -  OPT_LONG_QUERY_TIME,
1413 +  OPT_LONG_QUERY_TIME, OPT_MIN_EXAMINED_ROW_LIMIT,
1414    OPT_LOWER_CASE_TABLE_NAMES, OPT_MAX_ALLOWED_PACKET,
1415    OPT_MAX_BINLOG_CACHE_SIZE, OPT_MAX_BINLOG_SIZE,
1416    OPT_MAX_CONNECTIONS, OPT_MAX_CONNECT_ERRORS,
1417 @@ -5055,11 +5060,18 @@
1418    OPT_TIMED_MUTEXES,
1419    OPT_OLD_STYLE_USER_LIMITS,
1420    OPT_LOG_SLOW_ADMIN_STATEMENTS,
1421 +  OPT_LOG_SLOW_SLAVE_STATEMENTS,
1422 +  OPT_LOG_SLOW_RATE_LIMIT,
1423 +  OPT_LOG_SLOW_VERBOSITY,
1424 +  OPT_LOG_SLOW_FILTER,
1425    OPT_TABLE_LOCK_WAIT_TIMEOUT,
1426    OPT_PLUGIN_DIR,
1427    OPT_PORT_OPEN_TIMEOUT,
1428    OPT_MERGE,
1429    OPT_PROFILING,
1430 +  OPT_SLOW_LOG,
1431 +  OPT_SLOW_QUERY_LOG_FILE,
1432 +  OPT_USE_GLOBAL_LONG_QUERY_TIME,
1433    OPT_INNODB_ROLLBACK_ON_TIMEOUT,
1434    OPT_SECURE_FILE_PRIV,
1435    OPT_KEEP_FILES_ON_CREATE,
1436 @@ -5459,10 +5471,19 @@
1437     (gptr*) &opt_log_slow_admin_statements,
1438     (gptr*) &opt_log_slow_admin_statements,
1439     0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
1440 +  {"log-slow-slave-statements", OPT_LOG_SLOW_SLAVE_STATEMENTS,
1441 +   "Log slow replicated statements to the slow log if it is open.",
1442 +   (gptr*) &opt_log_slow_slave_statements,
1443 +   (gptr*) &opt_log_slow_slave_statements,
1444 +   0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
1445    {"log-slow-queries", OPT_SLOW_QUERY_LOG,
1446      "Log slow queries to this log file. Defaults logging to hostname-slow.log file. Must be enabled to activate other slow log options.",
1447     (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1448     0, 0, 0, 0, 0, 0},
1449 +  {"slow_query_log_file", OPT_SLOW_QUERY_LOG_FILE,
1450 +    "Log slow queries to given log file. Defaults logging to hostname-slow.log. Must be enabled to activate other slow log options.",
1451 +   (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1452 +   0, 0, 0, 0, 0, 0},
1453    {"log-tc", OPT_LOG_TC,
1454     "Path to transaction coordinator log (used for transactions that affect "
1455     "more than one storage engine, when binary log is disabled)",
1456 @@ -5826,6 +5847,9 @@
1457     "Tells the slave thread to continue replication when a query returns an error from the provided list.",
1458     0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
1459  #endif
1460 +  {"slow-query-log", OPT_SLOW_LOG,
1461 +   "Enable|disable slow query log", (gptr*) &opt_slow_log,
1462 +   (gptr*) &opt_slow_log, 0, GET_BOOL, OPT_ARG, 0, 0, 0, 0, 0, 0},
1463    {"socket", OPT_SOCKET, "Socket file to use for connection.",
1464     (gptr*) &mysqld_unix_port, (gptr*) &mysqld_unix_port, 0, GET_STR,
1465     REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
1466 @@ -6128,11 +6152,31 @@
1467     (gptr*) 0,
1468     0, (GET_ULONG | GET_ASK_ADDR) , REQUIRED_ARG, 100,
1469     1, 100, 0, 1, 0},
1470 -  {"long_query_time", OPT_LONG_QUERY_TIME,
1471 -   "Log all queries that have taken more than long_query_time seconds to execute to file.",
1472 -   (gptr*) &global_system_variables.long_query_time,
1473 -   (gptr*) &max_system_variables.long_query_time, 0, GET_ULONG,
1474 -   REQUIRED_ARG, 10, 1, LONG_TIMEOUT, 0, 1, 0},
1475 +  {"log_slow_filter", OPT_LOG_SLOW_FILTER,
1476 +    "Log only the queries that followed certain execution plan. Multiple flags allowed in a comma-separated string. [qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, filesort, filesort_on_disk]",
1477 +    0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, SLOG_F_NONE, 0, 0},
1478 +  {"log_slow_rate_limit", OPT_LOG_SLOW_RATE_LIMIT,
1479 +    "Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
1480 +    (gptr*) &global_system_variables.log_slow_rate_limit,
1481 +    (gptr*) &max_system_variables.log_slow_rate_limit, 0, GET_ULONG,
1482 +    REQUIRED_ARG, 1, 1, LONG_MAX, 0, 1L, 0},
1483 +  {"log_slow_verbosity", OPT_LOG_SLOW_VERBOSITY,
1484 +    "Choose how verbose the messages to your slow log will be. Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb]",
1485 +    0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, SLOG_V_MICROTIME, 0, 0},
1486 +   {"long_query_time", OPT_LONG_QUERY_TIME,
1487 +    "Log all queries that have taken more than long_query_time seconds to execute to file.",
1488 +    (gptr*) &global_system_variables.long_query_time,
1489 +    (gptr*) &max_system_variables.long_query_time, 0, GET_MICROTIME,
1490 +    REQUIRED_ARG, 10000000, 0, LONG_TIMEOUT * 1000000, 0, 1, 0},
1491 +  {"min_examined_row_limit", OPT_MIN_EXAMINED_ROW_LIMIT,
1492 +    "Don't log queries which examine less than min_examined_row_limit rows to file.",
1493 +    (gptr*) &global_system_variables.min_examined_row_limit,
1494 +    (gptr*) &max_system_variables.min_examined_row_limit, 0, GET_ULONG,
1495 +    REQUIRED_ARG, 0, 0, LONG_MAX, 0, 1L, 0},
1496 +  {"use_global_long_query_time", OPT_USE_GLOBAL_LONG_QUERY_TIME,
1497 +   "Control always use global long_query_time or local long_query_time.",
1498 +   (gptr*) &opt_use_global_long_query_time, (gptr*) &opt_use_global_long_query_time,
1499 +   0, GET_BOOL, NO_ARG, 0, 0, 1, 0, 1, 0},
1500    {"lower_case_table_names", OPT_LOWER_CASE_TABLE_NAMES,
1501     "If set to 1 table names are stored in lowercase on disk and table names will be case-insensitive.  Should be set to 2 if you are using a case insensitive file system",
1502     (gptr*) &lower_case_table_names,
1503 @@ -6915,7 +6959,11 @@
1504    global_system_variables.max_join_size= (ulonglong) HA_POS_ERROR;
1505    max_system_variables.max_join_size=   (ulonglong) HA_POS_ERROR;
1506    global_system_variables.old_passwords= 0;
1507 -
1508 +  global_system_variables.long_query_time = 10000000;
1509 +  max_system_variables.long_query_time = LONG_TIMEOUT * 1000000;
1510 +  global_system_variables.log_slow_verbosity= SLOG_V_MICROTIME;
1511 +  global_system_variables.log_slow_filter= SLOG_F_NONE;
1512 +
1513    /*
1514      Default behavior for 4.1 and 5.0 is to treat NULL values as unequal
1515      when collecting index statistics for MyISAM tables.
1516 @@ -7386,6 +7434,35 @@
1517    case OPT_BOOTSTRAP:
1518      opt_noacl=opt_bootstrap=1;
1519      break;
1520 +  case OPT_LOG_SLOW_FILTER:
1521 +    if ((global_system_variables.log_slow_filter=
1522 +          msl_flag_resolve_by_name(slog_filter, argument,
1523 +                                   SLOG_F_NONE, SLOG_F_INVALID)) == SLOG_F_INVALID)
1524 +    {
1525 +      fprintf(stderr,"Invalid argument in log_slow_filter: %s\n", argument);
1526 +      exit(1);
1527 +    }
1528 +    break;
1529 +  case OPT_LOG_SLOW_VERBOSITY:
1530 +    if ((global_system_variables.log_slow_verbosity=
1531 +         msl_flag_resolve_by_name(slog_verb, argument,
1532 +                                  SLOG_V_NONE, SLOG_V_INVALID)) == SLOG_V_INVALID)
1533 +    {
1534 +      fprintf(stderr,"Invalid argument in log_slow_verbosity: %s\n", argument);
1535 +      exit(1);
1536 +    }
1537 +    break;
1538 +  case OPT_LONG_QUERY_TIME:
1539 +  {
1540 +    double doubleslow = strtod(argument,NULL);
1541 +    if (doubleslow < 0 || doubleslow > (LONG_TIMEOUT))
1542 +    {
1543 +      fprintf(stderr,"Out of range long_query_time value: %s\n", argument);
1544 +      exit(1);
1545 +    }
1546 +    global_system_variables.long_query_time = (ulonglong) (doubleslow * 1000000);
1547 +    break;
1548 +  }
1549    case OPT_STORAGE_ENGINE:
1550    {
1551      if ((enum db_type)((global_system_variables.table_type=
1552 @@ -7718,10 +7795,14 @@
1553    if (opt_bdb)
1554      sql_print_warning("this binary does not contain BDB storage engine");
1555  #endif
1556 -  if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes) &&
1557 +  if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes ||
1558 +        opt_log_slow_slave_statements) &&
1559        !opt_slow_log)
1560 -    sql_print_warning("options --log-slow-admin-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set");
1561 -
1562 +  {
1563 +    sql_print_warning("options --log-slow-admin-statements, --log-slow-slave-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set");
1564 +    opt_log_slow_slave_statements= FALSE;
1565 +  }
1566 +
1567    if (argc > 0)
1568    {
1569      fprintf(stderr, "%s: Too many arguments (first extra is '%s').\nUse --help to get a list of available options\n", my_progname, *argv);
1570 diff -ruN a/sql/set_var.cc b/sql/set_var.cc
1571 --- a/sql/set_var.cc    Tue Jul 28 23:39:12 2009 -0700
1572 +++ b/sql/set_var.cc    Tue Jul 28 23:42:44 2009 -0700
1573 @@ -218,9 +218,13 @@
1574    sys_log_queries_not_using_indexes("log_queries_not_using_indexes",
1575                                      &opt_log_queries_not_using_indexes);
1576  sys_var_thd_ulong      sys_log_warnings("log_warnings", &SV::log_warnings);
1577 -sys_var_thd_ulong      sys_long_query_time("long_query_time",
1578 +sys_var_thd_microtime  sys_long_query_time("long_query_time",
1579                                              &SV::long_query_time);
1580 +sys_var_bool_ptr       sys_use_global_long_query_time("use_global_long_query_time",
1581 +                                                       &opt_use_global_long_query_time);
1582  sys_var_bool_const_ptr sys_log_slow("log_slow_queries", &opt_slow_log);
1583 +sys_var_log_slow       sys_slow_query_log("slow_query_log", &opt_slow_log);
1584 +sys_var_const_str_ptr  sys_slow_query_log_file("slow_query_log_file", &opt_slow_logname);
1585  sys_var_thd_bool       sys_low_priority_updates("low_priority_updates",
1586                                                  &SV::low_priority_updates,
1587                                                  fix_low_priority_updates);
1588 @@ -284,6 +288,8 @@
1589                                            &SV::max_tmp_tables);
1590  sys_var_long_ptr       sys_max_write_lock_count("max_write_lock_count",
1591                                                  &max_write_lock_count);
1592 +sys_var_thd_ulong      sys_min_examined_row_limit("min_examined_row_limit",
1593 +                                            &SV::min_examined_row_limit);
1594  sys_var_thd_ulong       sys_multi_range_count("multi_range_count",
1595                                                &SV::multi_range_count);
1596  sys_var_long_ptr       sys_myisam_data_pointer_size("myisam_data_pointer_size",
1597 @@ -328,6 +334,20 @@
1598  sys_var_bool_ptr       sys_relay_log_purge("relay_log_purge",
1599                                              &relay_log_purge);
1600  #endif
1601 +sys_var_thd_ulong      sys_log_slow_rate_limit("log_slow_rate_limit",
1602 +                                            &SV::log_slow_rate_limit);
1603 +sys_var_thd_msl_flag   sys_log_slow_filter("log_slow_filter",
1604 +                                      &SV::log_slow_filter,
1605 +                                       SLOG_F_NONE,
1606 +                                       SLOG_F_NONE,
1607 +                                       SLOG_F_INVALID,
1608 +                                       slog_filter);
1609 +sys_var_thd_msl_flag   sys_log_slow_verbosity("log_slow_verbosity",
1610 +                                      &SV::log_slow_verbosity,
1611 +                                       SLOG_V_NONE,
1612 +                                       SLOG_V_MICROTIME,
1613 +                                       SLOG_V_INVALID,
1614 +                                       slog_verb);
1615  sys_var_long_ptr       sys_rpl_recovery_rank("rpl_recovery_rank",
1616                                               &rpl_recovery_rank);
1617  sys_var_long_ptr       sys_query_cache_size("query_cache_size",
1618 @@ -702,6 +722,10 @@
1619    &sys_log_off,
1620    &sys_log_queries_not_using_indexes,
1621    &sys_log_slow,
1622 +  &sys_log_slow_filter,
1623 +  &sys_log_slow_rate_limit,
1624 +  &sys_log_slow_verbosity,
1625 +  &sys_use_global_long_query_time,
1626    &sys_log_update,
1627    &sys_log_warnings,
1628    &sys_long_query_time,
1629 @@ -725,6 +749,7 @@
1630    &sys_max_tmp_tables,
1631    &sys_max_user_connections,
1632    &sys_max_write_lock_count,
1633 +  &sys_min_examined_row_limit,
1634    &sys_multi_range_count,
1635    &sys_myisam_data_pointer_size,
1636    &sys_myisam_max_sort_file_size,
1637 @@ -779,6 +804,8 @@
1638    &sys_slave_skip_counter,
1639  #endif
1640    &sys_slow_launch_time,
1641 +  &sys_slow_query_log,
1642 +  &sys_slow_query_log_file,
1643    &sys_sort_buffer,
1644    &sys_sql_big_tables,
1645    &sys_sql_low_priority_updates,
1646 @@ -1000,8 +1027,11 @@
1647    {"log_slave_updates",       (char*) &opt_log_slave_updates,       SHOW_MY_BOOL},
1648  #endif
1649    {sys_log_slow.name,         (char*) &sys_log_slow,                SHOW_SYS},
1650 +  {sys_log_slow_filter.name, (char*) &sys_log_slow_filter, SHOW_SYS},
1651 +  {sys_log_slow_rate_limit.name, (char*) &sys_log_slow_rate_limit, SHOW_SYS},
1652 +  {sys_log_slow_verbosity.name, (char*) &sys_log_slow_verbosity, SHOW_SYS},
1653    {sys_log_warnings.name,     (char*) &sys_log_warnings,           SHOW_SYS},
1654 -  {sys_long_query_time.name,  (char*) &sys_long_query_time,        SHOW_SYS},
1655 +  {sys_long_query_time.name,  (char*) &sys_long_query_time,        SHOW_MICROTIME},
1656    {sys_low_priority_updates.name, (char*) &sys_low_priority_updates, SHOW_SYS},
1657    {"lower_case_file_system",  (char*) &lower_case_file_system,      SHOW_MY_BOOL},
1658    {"lower_case_table_names",  (char*) &lower_case_table_names,      SHOW_INT},
1659 @@ -1028,6 +1058,7 @@
1660    {sys_max_tmp_tables.name,    (char*) &sys_max_tmp_tables,        SHOW_SYS},
1661    {sys_max_user_connections.name,(char*) &sys_max_user_connections, SHOW_SYS},
1662    {sys_max_write_lock_count.name, (char*) &sys_max_write_lock_count,SHOW_SYS},
1663 +  {sys_min_examined_row_limit.name, (char*) &sys_min_examined_row_limit, SHOW_SYS},
1664    {sys_multi_range_count.name,  (char*) &sys_multi_range_count,     SHOW_SYS},
1665    {sys_myisam_data_pointer_size.name, (char*) &sys_myisam_data_pointer_size, SHOW_SYS},
1666    {sys_myisam_max_sort_file_size.name, (char*) &sys_myisam_max_sort_file_size,
1667 @@ -1116,6 +1147,8 @@
1668    {sys_slave_trans_retries.name,(char*) &sys_slave_trans_retries,   SHOW_SYS},
1669  #endif
1670    {sys_slow_launch_time.name, (char*) &sys_slow_launch_time,        SHOW_SYS},
1671 +  {sys_slow_query_log.name,   (char*) &sys_slow_query_log,          SHOW_SYS},
1672 +  {sys_slow_query_log_file.name,(char*) &sys_slow_query_log_file,   SHOW_SYS},
1673  #ifdef HAVE_SYS_UN_H
1674    {"socket",                  (char*) &mysqld_unix_port,             SHOW_CHAR_PTR},
1675  #endif
1676 @@ -1156,6 +1189,7 @@
1677    {sys_tx_isolation.name,     (char*) &sys_tx_isolation,           SHOW_SYS},
1678    {sys_updatable_views_with_limit.name,
1679                                (char*) &sys_updatable_views_with_limit,SHOW_SYS},
1680 +  {sys_use_global_long_query_time.name, (char*) &sys_use_global_long_query_time, SHOW_SYS},
1681    {sys_version.name,          (char*) &sys_version,                 SHOW_SYS},
1682  #ifdef HAVE_BERKELEY_DB
1683    {sys_version_bdb.name,      (char*) &sys_version_bdb,             SHOW_SYS},
1684 @@ -1784,6 +1818,17 @@
1685  }
1686
1687
1688 +bool sys_var_thd_microtime::check(THD *thd, set_var *var)
1689 +{
1690 +  if (var->value->result_type() == DECIMAL_RESULT)
1691 +    var->save_result.ulonglong_value= (ulonglong)(var->value->val_real() * 1000000);
1692 +  else
1693 +    var->save_result.ulonglong_value= (ulonglong)(var->value->val_int() * 1000000);
1694 +
1695 +  return 0;
1696 +}
1697 +
1698 +
1699  bool sys_var_thd_bool::update(THD *thd,  set_var *var)
1700  {
1701    if (var->type == OPT_GLOBAL)
1702 @@ -1940,6 +1985,19 @@
1703      pthread_mutex_unlock(&LOCK_global_system_variables);
1704      return new Item_int(value);
1705    }
1706 +  case SHOW_MICROTIME:
1707 +  {
1708 +    longlong value;
1709 +    char buff[80];
1710 +    int len;
1711 +
1712 +    pthread_mutex_lock(&LOCK_global_system_variables);
1713 +    value= *(longlong*) value_ptr(thd, var_type, base);
1714 +    pthread_mutex_unlock(&LOCK_global_system_variables);
1715 +
1716 +    len = snprintf(buff, 80, "%f", ((double) value) / 1000000.0);
1717 +    return new Item_float(buff,len);
1718 +  }
1719    case SHOW_HA_ROWS:
1720    {
1721      ha_rows value;
1722 @@ -2772,6 +2830,30 @@
1723  }
1724
1725
1726 +bool sys_var_log_slow::update(THD *thd, set_var *var)
1727 +{
1728 +  bool ret;
1729 +
1730 +  pthread_mutex_lock(&LOCK_global_system_variables);
1731 +  if (var->save_result.ulong_value)
1732 +  {
1733 +    if(!mysql_slow_log.is_open())
1734 +    {
1735 +      mysql_slow_log.open_slow_log(opt_slow_logname);
1736 +    }
1737 +  }
1738 +  pthread_mutex_unlock(&LOCK_global_system_variables);
1739 +
1740 +  ret = sys_var_bool_ptr::update(thd, var);
1741 +
1742 +#ifdef HAVE_INNOBASE_DB
1743 +  innobase_update_var_slow_log();
1744 +#endif
1745 +
1746 +  return(ret);
1747 +}
1748 +
1749 +
1750  #ifdef HAVE_REPLICATION
1751  bool sys_var_slave_skip_counter::check(THD *thd, set_var *var)
1752  {
1753 @@ -3568,6 +3650,191 @@
1754  #endif
1755  }
1756
1757 +/* Slow log stuff */
1758 +
1759 +ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len)
1760 +{
1761 +  ulong i;
1762 +
1763 +  for (i=0; opts[i].name; i++)
1764 +  {
1765 +    if (!my_strnncoll(&my_charset_latin1,
1766 +                      (const uchar *)name, len,
1767 +                      (const uchar *)opts[i].name, strlen(opts[i].name)))
1768 +      return opts[i].val;
1769 +  }
1770 +  return opts[i].val;
1771 +}
1772 +
1773 +ulong msl_flag_resolve_by_name(const struct msl_opts *opts, const char *names_list,
1774 +                               const ulong none_val, const ulong invalid_val)
1775 +{
1776 +  const char *p, *e;
1777 +  ulong val= none_val;
1778 +
1779 +  if (!*names_list)
1780 +    return val;
1781 +
1782 +  for (p= e= names_list; ; e++)
1783 +  {
1784 +    ulong i;
1785 +
1786 +    if (*e != ',' && *e)
1787 +      continue;
1788 +    for (i=0; opts[i].name; i++)
1789 +    {
1790 +      if (!my_strnncoll(&my_charset_latin1,
1791 +                        (const uchar *)p, e - p,
1792 +                        (const uchar *)opts[i].name, strlen(opts[i].name)))
1793 +      {
1794 +        val= val | opts[i].val;
1795 +        break;
1796 +      }
1797 +    }
1798 +    if (opts[i].val == invalid_val)
1799 +      return invalid_val;
1800 +    if (!*e)
1801 +      break;
1802 +    p= e + 1;
1803 +  }
1804 +  return val;
1805 +}
1806 +
1807 +const char *msl_option_get_name(const struct msl_opts *opts, ulong val)
1808 +{
1809 +  for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1810 +  {
1811 +    if (opts[i].val == val)
1812 +      return opts[i].name;
1813 +  }
1814 +  return "*INVALID*";
1815 +}
1816 +
1817 +char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val)
1818 +{
1819 +  uint offset= 0;
1820 +
1821 +  *buf= '\0';
1822 +  for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1823 +  {
1824 +    if (opts[i].val & val)
1825 +      offset+= snprintf(buf+offset, STRING_BUFFER_USUAL_SIZE - offset - 1,
1826 +                        "%s%s", (offset ? "," : ""), opts[i].name);
1827 +  }
1828 +  return buf;
1829 +}
1830 +
1831 +/****************************************************************************
1832 + Functions to handle log_slow_verbosity
1833 +****************************************************************************/
1834 +
1835 +/* Based upon sys_var::check_enum() */
1836 +
1837 +bool sys_var_thd_msl_option::check(THD *thd, set_var *var)
1838 +{
1839 +  char buff[STRING_BUFFER_USUAL_SIZE];
1840 +  String str(buff, sizeof(buff), &my_charset_latin1), *res;
1841 +
1842 +  if (var->value->result_type() == STRING_RESULT)
1843 +  {
1844 +    ulong verb= this->invalid_val;
1845 +    if (!(res=var->value->val_str(&str)) ||
1846 +             (var->save_result.ulong_value=
1847 +          (ulong) (verb= msl_option_resolve_by_name(this->opts, res->ptr(), res->length()))) == this->invalid_val)
1848 +      goto err;
1849 +    return 0;
1850 +  }
1851 +
1852 +err:
1853 +  my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1854 +  return 1;
1855 +}
1856 +
1857 +byte *sys_var_thd_msl_option::value_ptr(THD *thd, enum_var_type type,
1858 +                                       LEX_STRING *base)
1859 +{
1860 +  ulong val;
1861 +  val= ((type == OPT_GLOBAL) ? global_system_variables.*offset :
1862 +        thd->variables.*offset);
1863 +  const char *verbosity= msl_option_get_name(this->opts, val);
1864 +  return (byte *) verbosity;
1865 +}
1866 +
1867 +
1868 +void sys_var_thd_msl_option::set_default(THD *thd, enum_var_type type)
1869 +{
1870 +  if (type == OPT_GLOBAL)
1871 +    global_system_variables.*offset= (ulong) this->default_val;
1872 +  else
1873 +    thd->variables.*offset= (ulong) (global_system_variables.*offset);
1874 +}
1875 +
1876 +
1877 +bool sys_var_thd_msl_option::update(THD *thd, set_var *var)
1878 +{
1879 +  if (var->type == OPT_GLOBAL)
1880 +    global_system_variables.*offset= var->save_result.ulong_value;
1881 +  else
1882 +    thd->variables.*offset= var->save_result.ulong_value;
1883 +  return 0;
1884 +}
1885 +
1886 +/****************************************************************************
1887 + Functions to handle log_slow_filter
1888 +****************************************************************************/
1889 +
1890 +/* Based upon sys_var::check_enum() */
1891 +
1892 +bool sys_var_thd_msl_flag::check(THD *thd, set_var *var)
1893 +{
1894 +  char buff[2 * STRING_BUFFER_USUAL_SIZE];
1895 +  String str(buff, sizeof(buff), &my_charset_latin1), *res;
1896 +
1897 +  if (var->value->result_type() == STRING_RESULT)
1898 +  {
1899 +    ulong filter= this->none_val;
1900 +    if (!(res=var->value->val_str(&str)) ||
1901 +        (var->save_result.ulong_value=
1902 +          (ulong) (filter= msl_flag_resolve_by_name(this->flags, res->ptr(), this->none_val,
1903 +                                                    this->invalid_val))) == this->invalid_val)
1904 +      goto err;
1905 +    return 0;
1906 +  }
1907 +
1908 +err:
1909 +  my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1910 +  return 1;
1911 +}
1912 +
1913 +byte *sys_var_thd_msl_flag::value_ptr(THD *thd, enum_var_type type,
1914 +                                       LEX_STRING *base)
1915 +{
1916 +  ulong val;
1917 +  val= ((type == OPT_GLOBAL) ? global_system_variables.*offset :
1918 +        thd->variables.*offset);
1919 +  msl_flag_get_name(this->flags, this->flags_string, val);
1920 +  return (byte *) this->flags_string;
1921 +}
1922 +
1923 +
1924 +void sys_var_thd_msl_flag::set_default(THD *thd, enum_var_type type)
1925 +{
1926 +  if (type == OPT_GLOBAL)
1927 +    global_system_variables.*offset= (ulong) this->default_val;
1928 +  else
1929 +    thd->variables.*offset= (ulong) (global_system_variables.*offset);
1930 +}
1931 +
1932 +
1933 +bool sys_var_thd_msl_flag::update(THD *thd, set_var *var)
1934 +{
1935 +  if (var->type == OPT_GLOBAL)
1936 +    global_system_variables.*offset= var->save_result.ulong_value;
1937 +  else
1938 +    thd->variables.*offset= var->save_result.ulong_value;
1939 +  return 0;
1940 +}
1941 +
1942  /****************************************************************************
1943   Functions to handle table_type
1944  ****************************************************************************/
1945 diff -ruN a/sql/set_var.h b/sql/set_var.h
1946 --- a/sql/set_var.h     Tue Jul 28 23:39:12 2009 -0700
1947 +++ b/sql/set_var.h     Tue Jul 28 23:42:44 2009 -0700
1948 @@ -132,6 +132,7 @@
1949  };
1950
1951
1952 +
1953  class sys_var_ulonglong_ptr :public sys_var
1954  {
1955  public:
1956 @@ -168,6 +169,13 @@
1957    bool check_update_type(Item_result type) { return 0; }
1958  };
1959
1960 +class sys_var_log_slow :public sys_var_bool_ptr
1961 +{
1962 +public:
1963 +  sys_var_log_slow(const char *name_arg, my_bool *value_arg)
1964 +    :sys_var_bool_ptr(name_arg, value_arg) {}
1965 +  bool update(THD *thd, set_var *var);
1966 +};
1967
1968  class sys_var_bool_const_ptr : public sys_var
1969  {
1970 @@ -340,7 +348,6 @@
1971    }
1972  };
1973
1974 -
1975  class sys_var_thd_ulong :public sys_var_thd
1976  {
1977    sys_check_func check_func;
1978 @@ -360,7 +367,6 @@
1979    byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1980  };
1981
1982 -
1983  class sys_var_thd_ha_rows :public sys_var_thd
1984  {
1985  public:
1986 @@ -378,7 +384,6 @@
1987    byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1988  };
1989
1990 -
1991  class sys_var_thd_ulonglong :public sys_var_thd
1992  {
1993  public:
1994 @@ -407,6 +412,19 @@
1995    }
1996  };
1997
1998 +class sys_var_thd_microtime :public sys_var_thd_ulonglong
1999 +{
2000 +public:
2001 +  sys_var_thd_microtime(const char *name_arg, ulonglong SV::*offset_arg)
2002 +    :sys_var_thd_ulonglong(name_arg, offset_arg)
2003 +  {}
2004 +  SHOW_TYPE show_type() { return SHOW_MICROTIME; }
2005 +  bool check(THD *thd, set_var *var);
2006 +  bool check_update_type(Item_result type)
2007 +  {
2008 +    return type != INT_RESULT && type != DECIMAL_RESULT;
2009 +  }
2010 +};
2011
2012  class sys_var_thd_bool :public sys_var_thd
2013  {
2014 @@ -478,6 +496,66 @@
2015  };
2016
2017
2018 +class sys_var_thd_msl_option :public sys_var_thd
2019 +{
2020 +protected:
2021 +  ulong SV::*offset;
2022 +  const ulong none_val;
2023 +  const ulong default_val;
2024 +  const ulong invalid_val;
2025 +  const struct msl_opts *opts;
2026 +public:
2027 +  sys_var_thd_msl_option(const char *name_arg, ulong SV::*offset_arg,
2028 +                         const ulong none_val_arg,
2029 +                         const ulong default_val_arg,
2030 +                         const ulong invalid_val_arg,
2031 +                         const struct msl_opts *opts_arg)
2032 +    :sys_var_thd(name_arg), offset(offset_arg), none_val(none_val_arg),
2033 +     default_val(default_val_arg), invalid_val(invalid_val_arg),
2034 +     opts(opts_arg)
2035 +  {}
2036 +  bool check(THD *thd, set_var *var);
2037 +  SHOW_TYPE show_type() { return SHOW_CHAR; }
2038 +  bool check_update_type(Item_result type)
2039 +  {
2040 +    return type != STRING_RESULT;              /* Only accept strings */
2041 +  }
2042 +  void set_default(THD *thd, enum_var_type type);
2043 +  bool update(THD *thd, set_var *var);
2044 +  byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
2045 +};
2046 +
2047 +
2048 +class sys_var_thd_msl_flag :public sys_var_thd
2049 +{
2050 +protected:
2051 +  char flags_string[2 * STRING_BUFFER_USUAL_SIZE];
2052 +  ulong SV::*offset;
2053 +  const ulong none_val;
2054 +  const ulong default_val;
2055 +  const ulong invalid_val;
2056 +  const struct msl_opts *flags;
2057 +public:
2058 +  sys_var_thd_msl_flag(const char *name_arg, ulong SV::*offset_arg,
2059 +                       const ulong none_val_arg,
2060 +                       const ulong default_val_arg,
2061 +                       const ulong invalid_val_arg,
2062 +                       const struct msl_opts *flags_arg)
2063 +    :sys_var_thd(name_arg), offset(offset_arg), none_val(none_val_arg),
2064 +     default_val(default_val_arg), invalid_val(invalid_val_arg),
2065 +     flags(flags_arg)
2066 +  {}
2067 +  bool check(THD *thd, set_var *var);
2068 +  SHOW_TYPE show_type() { return SHOW_CHAR; }
2069 +  bool check_update_type(Item_result type)
2070 +  {
2071 +    return type != STRING_RESULT;              /* Only accept strings */
2072 +  }
2073 +  void set_default(THD *thd, enum_var_type type);
2074 +  bool update(THD *thd, set_var *var);
2075 +  byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
2076 +};
2077 +
2078  class sys_var_thd_storage_engine :public sys_var_thd
2079  {
2080  protected:
2081 @@ -1109,3 +1187,11 @@
2082  bool process_key_caches(int (* func) (const char *name, KEY_CACHE *));
2083  void delete_elements(I_List<NAMED_LIST> *list,
2084                      void (*free_element)(const char*, gptr));
2085 +
2086 +/* Slow log functions */
2087 +
2088 +ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len);
2089 +ulong msl_flag_resolve_by_name(const struct msl_opts *opts, const char *names_list,
2090 +                               const ulong none_val, const ulong invalid_val);
2091 +const char *msl_option_get_name(const struct msl_opts *opts, ulong val);
2092 +char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val);
2093 diff -ruN a/sql/slave.cc b/sql/slave.cc
2094 --- a/sql/slave.cc      Tue Jul 28 23:39:12 2009 -0700
2095 +++ b/sql/slave.cc      Tue Jul 28 23:42:44 2009 -0700
2096 @@ -2981,6 +2981,12 @@
2097      + MAX_LOG_EVENT_HEADER;  /* note, incr over the global not session var */
2098    thd->slave_thread = 1;
2099    set_slave_thread_options(thd);
2100 +  if (opt_log_slow_slave_statements)
2101 +  {
2102 +    thd->enable_slow_log= TRUE;
2103 +    /* Slave thread is excluded from rate limiting the slow log writes. */
2104 +    thd->write_to_slow_log= TRUE;
2105 +  }
2106    thd->client_capabilities = CLIENT_LOCAL_FILES;
2107    thd->real_id=pthread_self();
2108    pthread_mutex_lock(&LOCK_thread_count);
2109 diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc
2110 --- a/sql/sql_cache.cc  Tue Jul 28 23:39:12 2009 -0700
2111 +++ b/sql/sql_cache.cc  Tue Jul 28 23:42:44 2009 -0700
2112 @@ -1402,6 +1402,7 @@
2113
2114    thd->limit_found_rows = query->found_rows();
2115    thd->status_var.last_query_cost= 0.0;
2116 +  thd->query_plan_flags|= QPLAN_QC;
2117
2118    BLOCK_UNLOCK_RD(query_block);
2119    DBUG_RETURN(1);                              // Result sent to client
2120 @@ -1409,6 +1410,7 @@
2121  err_unlock:
2122    STRUCT_UNLOCK(&structure_guard_mutex);
2123  err:
2124 +  thd->query_plan_flags|= QPLAN_QC_NO;
2125    DBUG_RETURN(0);                              // Query was not cached
2126  }
2127
2128 diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc
2129 --- a/sql/sql_class.cc  Tue Jul 28 23:39:12 2009 -0700
2130 +++ b/sql/sql_class.cc  Tue Jul 28 23:42:44 2009 -0700
2131 @@ -190,7 +190,7 @@
2132     table_map_for_update(0),
2133     global_read_lock(0), is_fatal_error(0),
2134     transaction_rollback_request(0), is_fatal_sub_stmt_error(0),
2135 -   rand_used(0), time_zone_used(0),
2136 +   rand_used(0), time_zone_used(0), user_timer(0),
2137     last_insert_id_used(0), last_insert_id_used_bin_log(0), insert_id_used(0),
2138     clear_next_insert_id(0), in_lock_tables(0), bootstrap(0),
2139     derived_tables_processing(FALSE), spcont(NULL),
2140 @@ -2253,6 +2253,12 @@
2141    backup->cuted_fields=     cuted_fields;
2142    backup->client_capabilities= client_capabilities;
2143    backup->savepoints= transaction.savepoints;
2144 +  backup->innodb_io_reads= innodb_io_reads;
2145 +  backup->innodb_io_read= innodb_io_read;
2146 +  backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
2147 +  backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
2148 +  backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
2149 +  backup->innodb_page_access= innodb_page_access;
2150
2151    if (!lex->requires_prelocking() || is_update_query(lex->sql_command))
2152      options&= ~OPTION_BIN_LOG;
2153 @@ -2269,7 +2275,13 @@
2154    sent_row_count= 0;
2155    cuted_fields= 0;
2156    transaction.savepoints= 0;
2157 -
2158 +  innodb_io_reads= 0;
2159 +  innodb_io_read= 0;
2160 +  innodb_io_reads_wait_timer= 0;
2161 +  innodb_lock_que_wait_timer= 0;
2162 +  innodb_innodb_que_wait_timer= 0;
2163 +  innodb_page_access= 0;
2164 +
2165    /* Surpress OK packets in case if we will execute statements */
2166    net.no_send_ok= TRUE;
2167  }
2168 @@ -2322,6 +2334,12 @@
2169    */
2170    examined_row_count+= backup->examined_row_count;
2171    cuted_fields+=       backup->cuted_fields;
2172 +  innodb_io_reads+= backup->innodb_io_reads;
2173 +  innodb_io_read+= backup->innodb_io_read;
2174 +  innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
2175 +  innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
2176 +  innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
2177 +  innodb_page_access+= backup->innodb_page_access;
2178  }
2179
2180
2181 --- mysql-5.0.92/sql/sql_class.h        Tue Jul 28 23:39:12 2009 -0700
2182 +++ mysql-5.0.92/sql/sql_class.h        Tue Jul 28 23:42:44 2009 -0700
2183 @@ -43,6 +43,7 @@
2184  extern char internal_table_name[2];
2185  extern char empty_c_string[1];
2186  extern const char **errmesg;
2187 +extern ulonglong frequency;
2188
2189  extern bool volatile shutdown_in_progress;
2190
2191 @@ -323,7 +324,7 @@
2192    bool write(THD *thd, enum enum_server_command command,
2193              const char *format, ...) ATTRIBUTE_FORMAT(printf, 4, 5);
2194    bool write(THD *thd, const char *query, uint query_length,
2195 -            time_t query_start=0);
2196 +            time_t query_start=0, ulonglong query_start_timer=0);
2197    bool write(Log_event* event_info); // binary log write
2198    bool write(THD *thd, IO_CACHE *cache, Log_event *commit_event);
2199
2200 @@ -529,13 +530,14 @@
2201    ulong auto_increment_increment, auto_increment_offset;
2202    ulong bulk_insert_buff_size;
2203    ulong join_buff_size;
2204 -  ulong long_query_time;
2205 +  ulonglong long_query_time;
2206    ulong max_allowed_packet;
2207    ulong max_error_count;
2208    ulong max_length_for_sort_data;
2209    ulong max_sort_length;
2210    ulong max_tmp_tables;
2211    ulong max_insert_delayed_threads;
2212 +  ulong min_examined_row_limit;
2213    ulong multi_range_count;
2214    ulong myisam_repair_threads;
2215    ulong myisam_sort_buff_size;
2216 @@ -551,10 +553,13 @@
2217    ulong preload_buff_size;
2218    ulong profiling_history_size;
2219    ulong query_cache_type;
2220 +  ulong log_slow_rate_limit;
2221    ulong read_buff_size;
2222    ulong read_rnd_buff_size;
2223    ulong div_precincrement;
2224    ulong sortbuff_size;
2225 +  ulong log_slow_filter;
2226 +  ulong log_slow_verbosity;
2227    ulong table_type;
2228    ulong tx_isolation;
2229    ulong completion_type;
2230 @@ -1127,6 +1132,12 @@
2231    uint in_sub_stmt;
2232    bool enable_slow_log, insert_id_used, clear_next_insert_id;
2233    bool last_insert_id_used;
2234 +  ulong      innodb_io_reads;
2235 +  ulonglong  innodb_io_read;
2236 +  ulong      innodb_io_reads_wait_timer;
2237 +  ulong      innodb_lock_que_wait_timer;
2238 +  ulong      innodb_innodb_que_wait_timer;
2239 +  ulong      innodb_page_access;
2240    my_bool no_send_ok;
2241    SAVEPOINT *savepoints;
2242  };
2243 @@ -1183,6 +1194,11 @@
2244  class THD :public Statement,
2245             public Open_tables_state
2246  {
2247 +private:
2248 +  inline ulonglong query_start_timer() { return start_timer; }
2249 +  inline void set_timer()    { if (user_timer) start_timer=timer_after_lock=user_timer; else timer_after_lock=my_timer(&start_timer, frequency); }
2250 +  inline void end_timer()    { my_timer(&start_timer, frequency); }
2251 +  inline void lock_timer()   { my_timer(&timer_after_lock, frequency); }
2252  public:
2253    /*
2254      Constant for THD::where initialization in the beginning of every query.
2255 @@ -1299,10 +1315,24 @@
2256    */
2257    const char *where;
2258    time_t     start_time,time_after_lock,user_time;
2259 +  ulonglong start_timer,timer_after_lock, user_timer;
2260    time_t     connect_time,thr_create_time; // track down slow pthread_create
2261    thr_lock_type update_lock_default;
2262    Delayed_insert *di;
2263
2264 +  bool       write_to_slow_log;
2265 +
2266 +  bool       innodb_was_used;
2267 +  ulong      innodb_io_reads;
2268 +  ulonglong  innodb_io_read;
2269 +  ulong      innodb_io_reads_wait_timer;
2270 +  ulong      innodb_lock_que_wait_timer;
2271 +  ulong      innodb_innodb_que_wait_timer;
2272 +  ulong      innodb_page_access;
2273 +
2274 +  ulong      query_plan_flags;
2275 +  ulong      query_plan_fsort_passes;
2276 +
2277    /* <> 0 if we are inside of trigger or stored function. */
2278    uint in_sub_stmt;
2279
2280 @@ -1732,11 +1732,11 @@
2281        sql_print_information("time() failed with %d", errno);
2282    }
2283
2284 -  inline time_t query_start() { query_start_used=1; return start_time; }
2285 -  inline void  set_time()    { if (user_time) start_time=time_after_lock=user_time; else { safe_time(&start_time); time_after_lock= start_time; }}
2286 -  inline void  end_time()    { safe_time(&start_time); }
2287 -  inline void  set_time(time_t t) { time_after_lock=start_time=user_time=t; }
2288 -  inline void  lock_time()   { safe_time(&time_after_lock); }
2289 +  inline time_t query_start() { query_start_timer(); query_start_used=1; return start_time; }
2290 +  inline void set_time()    { set_timer(); if (user_time) start_time=time_after_lock=user_time; else { safe_time(&start_time); time_after_lock= start_time; }}
2291 +  inline void  end_time()    { end_timer(); safe_time(&start_time); }
2292 +  inline void  set_time(time_t t) { set_timer(); time_after_lock=start_time=user_time=t; }
2293 +  inline void  lock_time()   { lock_timer(); safe_time(&time_after_lock); }
2294    /*TODO: this will be obsolete when we have support for 64 bit my_time_t */
2295    inline bool  is_valid_time()
2296    {
2297 diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc
2298 --- a/sql/sql_parse.cc  Tue Jul 28 23:39:12 2009 -0700
2299 +++ b/sql/sql_parse.cc  Tue Jul 28 23:42:44 2009 -0700
2300 @@ -20,6 +20,7 @@
2301  #include <m_ctype.h>
2302  #include <myisam.h>
2303  #include <my_dir.h>
2304 +#include <my_time.h>
2305
2306  #ifdef HAVE_INNOBASE_DB
2307  #include "ha_innodb.h"
2308 @@ -1233,6 +1234,15 @@
2309      my_net_set_read_timeout(net, thd->variables.net_read_timeout);
2310      my_net_set_write_timeout(net, thd->variables.net_write_timeout);
2311
2312 +    /*
2313 +      If rate limiting of slow log writes is enabled, decide whether to log this
2314 +      new thread's queries or not. Uses extremely simple algorithm. :)
2315 +    */
2316 +    thd->write_to_slow_log= FALSE;
2317 +    if (thd->variables.log_slow_rate_limit <= 1 ||
2318 +        (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
2319 +         thd->write_to_slow_log= TRUE;
2320 +
2321      while (!net->error && net->vio != 0 &&
2322             !(thd->killed == THD::KILL_CONNECTION))
2323      {
2324 @@ -2394,28 +2404,57 @@
2325      return;                                     // Don't set time for sub stmt
2326
2327    start_of_query= thd->start_time;
2328 -  thd->end_time();                             // Set start time
2329 +  ulonglong start_of_query_timer= thd->start_timer;
2330 +  thd->end_time();                             // Set start timea
2331 +
2332 +
2333 +  /* Follow the slow log filter configuration. */
2334 +  if (thd->variables.log_slow_filter != SLOG_F_NONE &&
2335 +      (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
2336 +       ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
2337 +        (thd->query_plan_flags & QPLAN_QC))))
2338 +    return;
2339 +
2340 +  /*
2341 +    Low long_query_time value most likely means user is debugging stuff and even
2342 +    though some thread's queries are not supposed to be logged b/c of the rate
2343 +    limit, if one of them takes long enough (>= 1 second) it will be sensible
2344 +    to make an exception and write to slow log anyway.
2345 +  */
2346 +
2347 +  if (opt_use_global_long_query_time)
2348 +    thd->variables.long_query_time = global_system_variables.long_query_time;
2349 +
2350 +  /* Do not log this thread's queries due to rate limiting. */
2351 +  if (thd->write_to_slow_log != TRUE
2352 +      && (thd->variables.long_query_time >= 1000000
2353 +          || (ulong) (thd->start_timer - thd->timer_after_lock) < 1000000))
2354 +    return;
2355 +
2356
2357    /*
2358      Do not log administrative statements unless the appropriate option is
2359      set; do not log into slow log if reading from backup.
2360    */
2361 -  if (thd->enable_slow_log && !thd->user_time)
2362 +  if (thd->enable_slow_log &&
2363 +      (!thd->user_time || (thd->slave_thread && opt_log_slow_slave_statements))
2364 +     )
2365 +
2366    {
2367      thd_proc_info(thd, "logging slow query");
2368
2369 -    if ((thd->start_time > thd->time_after_lock &&
2370 -         (ulong) (thd->start_time - thd->time_after_lock) >
2371 -       thd->variables.long_query_time) ||
2372 -        ((thd->server_status &
2373 -         (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
2374 -        opt_log_queries_not_using_indexes &&
2375 -        /* == SQLCOM_END unless this is a SHOW command */
2376 -        thd->lex->orig_sql_command == SQLCOM_END))
2377 +    if (((ulong) (thd->start_timer - thd->timer_after_lock) >=
2378 +         thd->variables.long_query_time ||
2379 +         (thd->server_status &
2380 +              (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
2381 +         opt_log_queries_not_using_indexes &&
2382 +         /* == SQLCOM_END unless this is a SHOW command */
2383 +         thd->lex->orig_sql_command == SQLCOM_END) &&
2384 +        thd->examined_row_count >= thd->variables.min_examined_row_limit)
2385      {
2386        thd_proc_info(thd, "logging slow query");
2387        thd->status_var.long_query_count++;
2388 -      mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query);
2389 +      mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query, start_of_query_timer);
2390      }
2391    }
2392  }
2393 @@ -2710,6 +2749,8 @@
2394      context.resolve_in_table_list_only((TABLE_LIST*)select_lex->
2395                                         table_list.first);
2396
2397 +  /* Reset the counter at all cases for the extended slow query log */
2398 +  thd->row_count= 1;
2399    /*
2400      Reset warning count for each query that uses tables
2401      A better approach would be to reset this for any commands
2402 @@ -6233,6 +6274,15 @@
2403      thd->total_warn_count=0;                   // Warnings for this query
2404      thd->rand_used= 0;
2405      thd->sent_row_count= thd->examined_row_count= 0;
2406 +    thd->innodb_was_used= FALSE;
2407 +    thd->innodb_io_reads= 0;
2408 +    thd->innodb_io_read= 0;
2409 +    thd->innodb_io_reads_wait_timer= 0;
2410 +    thd->innodb_lock_que_wait_timer= 0;
2411 +    thd->innodb_innodb_que_wait_timer= 0;
2412 +    thd->innodb_page_access= 0;
2413 +    thd->query_plan_flags= QPLAN_NONE;
2414 +    thd->query_plan_fsort_passes= 0;
2415    }
2416    DBUG_VOID_RETURN;
2417  }
2418 diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc
2419 --- a/sql/sql_select.cc Tue Jul 28 23:39:12 2009 -0700
2420 +++ b/sql/sql_select.cc Tue Jul 28 23:42:44 2009 -0700
2421 @@ -6371,8 +6371,11 @@
2422           {
2423             join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2424             if (statistics)
2425 +           {
2426               statistic_increment(join->thd->status_var.select_scan_count,
2427                                   &LOCK_status);
2428 +                               join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
2429 +      }
2430           }
2431         }
2432         else
2433 @@ -6387,8 +6390,11 @@
2434           {
2435             join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2436             if (statistics)
2437 +           {
2438               statistic_increment(join->thd->status_var.select_full_join_count,
2439                                   &LOCK_status);
2440 +                               join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
2441 +      }
2442           }
2443         }
2444         if (!table->no_keyread)
2445 @@ -9464,6 +9470,7 @@
2446                       (ulong) rows_limit,test(group)));
2447
2448    statistic_increment(thd->status_var.created_tmp_tables, &LOCK_status);
2449 +  thd->query_plan_flags|= QPLAN_TMP_TABLE;
2450
2451    if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
2452      temp_pool_slot = bitmap_set_next(&temp_pool);
2453 @@ -10325,6 +10332,7 @@
2454    }
2455    statistic_increment(table->in_use->status_var.created_tmp_disk_tables,
2456                       &LOCK_status);
2457 +       table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
2458    table->s->db_record_offset= 1;
2459    DBUG_RETURN(0);
2460   err:
2461 diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc
2462 --- a/sql/sql_show.cc   Tue Jul 28 23:39:12 2009 -0700
2463 +++ b/sql/sql_show.cc   Tue Jul 28 23:42:44 2009 -0700
2464 @@ -1558,6 +1558,12 @@
2465          case SHOW_LONGLONG:
2466            end= longlong10_to_str(*(longlong*) value, buff, 10);
2467            break;
2468 +        case SHOW_MICROTIME:
2469 +          show_type= ((sys_var*) value)->show_type();
2470 +          value=     (char*) ((sys_var*) value)->value_ptr(thd, value_type,
2471 +                                                           &null_lex_str);
2472 +          end= buff + sprintf(buff, "%f", (((double) (*(ulonglong*)value))) / 1000000.0);
2473 +          break;
2474          case SHOW_HA_ROWS:
2475            end= longlong10_to_str((longlong) *(ha_rows*) value, buff, 10);
2476            break;
2477 diff -ruN a/sql/structs.h b/sql/structs.h
2478 --- a/sql/structs.h     Tue Jul 28 23:39:12 2009 -0700
2479 +++ b/sql/structs.h     Tue Jul 28 23:42:44 2009 -0700
2480 @@ -174,8 +174,8 @@
2481  enum SHOW_TYPE
2482  {
2483    SHOW_UNDEF,
2484 -  SHOW_LONG, SHOW_LONGLONG, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
2485 -  SHOW_DOUBLE_STATUS,
2486 +  SHOW_LONG, SHOW_LONGLONG, SHOW_MICROTIME, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
2487 +  SHOW_DOUBLE_STATUS,
2488    SHOW_BOOL, SHOW_MY_BOOL, SHOW_OPENTABLES, SHOW_STARTTIME, SHOW_QUERIES,
2489    SHOW_LONG_CONST, SHOW_INT_CONST, SHOW_HAVE, SHOW_SYS, SHOW_HA_ROWS,
2490    SHOW_VARS,