mysql-microslow_innodb.patch

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