mysql-microslow_innodb.patch

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