mysql-microslow_innodb.patch

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