mysql-innodb_extend_slow.patch

   1 # name       : innodb_extend_slow.patch
   2 # introduced : 11 or before
   3 # maintainer : Yasufumi
   4 #
   5 #!!! notice !!!
   6 # Any small change to this file in the main branch
   7 # should be done or reviewed by the maintainer!
   8 --- a/storage/innodb_plugin/buf/buf0buf.c
   9 +++ b/storage/innodb_plugin/buf/buf0buf.c
  10 @@ -51,6 +51,40 @@
  11  #include "dict0dict.h"
  12  #include "log0recv.h"
  13  #include "page0zip.h"
  14 +#include "trx0trx.h"
  15 +
  16 +/* prototypes for new functions added to ha_innodb.cc */
  17 +trx_t* innobase_get_trx();
  18 +
  19 +inline void _increment_page_get_statistics(buf_block_t* block, trx_t* trx)
  20 +{
  21 +       ulint           block_hash;
  22 +       ulint           block_hash_byte;
  23 +       byte            block_hash_offset;
  24 +
  25 +       ut_ad(block);
  26 +
  27 +       if (!innobase_get_slow_log() || !trx || !trx->take_stats)
  28 +               return;
  29 +
  30 +       if (!trx->distinct_page_access_hash) {
  31 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
  32 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
  33 +       }
  34 +
  35 +       block_hash = ut_hash_ulint((block->page.space << 20) + block->page.space +
  36 +                                       block->page.offset, DPAH_SIZE << 3);
  37 +       block_hash_byte = block_hash >> 3;
  38 +       block_hash_offset = (byte) block_hash & 0x07;
  39 +       if (block_hash_byte >= DPAH_SIZE)
  40 +               fprintf(stderr, "!!! block_hash_byte = %lu  block_hash_offset = %d !!!\n", block_hash_byte, block_hash_offset);
  41 +       if (block_hash_offset > 7)
  42 +               fprintf(stderr, "!!! block_hash_byte = %lu  block_hash_offset = %d !!!\n", block_hash_byte, block_hash_offset);
  43 +       if ((trx->distinct_page_access_hash[block_hash_byte] & ((byte) 0x01 << block_hash_offset)) == 0)
  44 +               trx->distinct_page_access++;
  45 +       trx->distinct_page_access_hash[block_hash_byte] |= (byte) 0x01 << block_hash_offset;
  46 +       return;
  47 +}
  48
  49  /*
  50                 IMPLEMENTATION OF THE BUFFER POOL
  51 @@ -1343,10 +1377,18 @@
  52         mutex_t*        block_mutex;
  53         ibool           must_read;
  54         unsigned        access_time;
  55 +       trx_t*          trx = NULL;
  56 +       ulint           sec;
  57 +       ulint           ms;
  58 +       ib_uint64_t     start_time;
  59 +       ib_uint64_t     finish_time;
  60
  61  #ifndef UNIV_LOG_DEBUG
  62         ut_ad(!ibuf_inside());
  63  #endif
  64 +       if (innobase_get_slow_log()) {
  65 +               trx = innobase_get_trx();
  66 +       }
  67         buf_pool->stat.n_page_gets++;
  68
  69         for (;;) {
  70 @@ -1363,7 +1405,7 @@
  71                 //buf_pool_mutex_exit();
  72                 rw_lock_s_unlock(&page_hash_latch);
  73
  74 -               buf_read_page(space, zip_size, offset);
  75 +               buf_read_page(space, zip_size, offset, trx);
  76
  77  #if defined UNIV_DEBUG || defined UNIV_BUF_DEBUG
  78                 ut_a(++buf_dbg_counter % 37 || buf_validate());
  79 @@ -1457,6 +1499,13 @@
  80                 /* Let us wait until the read operation
  81                 completes */
  82
  83 +               if (innobase_get_slow_log() && trx && trx->take_stats)
  84 +               {
  85 +                       ut_usectime(&sec, &ms);
  86 +                       start_time = (ib_uint64_t)sec * 1000000 + ms;
  87 +               } else {
  88 +                       start_time = 0;
  89 +               }
  90                 for (;;) {
  91                         enum buf_io_fix io_fix;
  92
  93 @@ -1471,6 +1520,12 @@
  94                                 break;
  95                         }
  96                 }
  97 +               if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
  98 +               {
  99 +                       ut_usectime(&sec, &ms);
 100 +                       finish_time = (ib_uint64_t)sec * 1000000 + ms;
 101 +                       trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 102 +               }
 103         }
 104
 105  #ifdef UNIV_IBUF_COUNT_DEBUG
 106 @@ -1730,6 +1785,11 @@
 107         ibool           must_read;
 108         ulint           retries = 0;
 109         mutex_t*        block_mutex = NULL;
 110 +       trx_t*          trx = NULL;
 111 +       ulint           sec;
 112 +       ulint           ms;
 113 +       ib_uint64_t     start_time;
 114 +       ib_uint64_t     finish_time;
 115
 116         ut_ad(mtr);
 117         ut_ad(mtr->state == MTR_ACTIVE);
 118 @@ -1754,6 +1814,9 @@
 119  #ifndef UNIV_LOG_DEBUG
 120         ut_ad(!ibuf_inside() || ibuf_page(space, zip_size, offset, NULL));
 121  #endif
 122 +       if (innobase_get_slow_log()) {
 123 +               trx = innobase_get_trx();
 124 +       }
 125         buf_pool->stat.n_page_gets++;
 126  loop:
 127         block = guess;
 128 @@ -1803,7 +1866,7 @@
 129                         return(NULL);
 130                 }
 131
 132 -               if (buf_read_page(space, zip_size, offset)) {
 133 +               if (buf_read_page(space, zip_size, offset, trx)) {
 134                         retries = 0;
 135                 } else if (retries < BUF_PAGE_READ_MAX_RETRIES) {
 136                         ++retries;
 137 @@ -2092,6 +2155,13 @@
 138                         /* Let us wait until the read operation
 139                         completes */
 140
 141 +                       if (innobase_get_slow_log() && trx && trx->take_stats)
 142 +                       {
 143 +                               ut_usectime(&sec, &ms);
 144 +                               start_time = (ib_uint64_t)sec * 1000000 + ms;
 145 +                       } else {
 146 +                               start_time = 0;
 147 +                       }
 148                         for (;;) {
 149                                 enum buf_io_fix io_fix;
 150
 151 @@ -2106,6 +2176,12 @@
 152                                         break;
 153                                 }
 154                         }
 155 +                       if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 156 +                       {
 157 +                               ut_usectime(&sec, &ms);
 158 +                               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 159 +                               trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 160 +                       }
 161                 }
 162
 163                 fix_type = MTR_MEMO_BUF_FIX;
 164 @@ -2131,13 +2207,17 @@
 165                 /* In the case of a first access, try to apply linear
 166                 read-ahead */
 167
 168 -               buf_read_ahead_linear(space, zip_size, offset);
 169 +               buf_read_ahead_linear(space, zip_size, offset, trx);
 170         }
 171
 172  #ifdef UNIV_IBUF_COUNT_DEBUG
 173         ut_a(ibuf_count_get(buf_block_get_space(block),
 174                             buf_block_get_page_no(block)) == 0);
 175  #endif
 176 +       if (innobase_get_slow_log()) {
 177 +               _increment_page_get_statistics(block, trx);
 178 +       }
 179 +
 180         return(block);
 181  }
 182
 183 @@ -2160,6 +2240,7 @@
 184         unsigned        access_time;
 185         ibool           success;
 186         ulint           fix_type;
 187 +       trx_t*          trx = NULL;
 188
 189         ut_ad(block);
 190         ut_ad(mtr);
 191 @@ -2237,13 +2318,17 @@
 192  #if defined UNIV_DEBUG_FILE_ACCESSES || defined UNIV_DEBUG
 193         ut_a(block->page.file_page_was_freed == FALSE);
 194  #endif
 195 +       if (innobase_get_slow_log()) {
 196 +               trx = innobase_get_trx();
 197 +       }
 198 +
 199         if (UNIV_UNLIKELY(!access_time)) {
 200                 /* In the case of a first access, try to apply linear
 201                 read-ahead */
 202
 203                 buf_read_ahead_linear(buf_block_get_space(block),
 204                                       buf_block_get_zip_size(block),
 205 -                                     buf_block_get_page_no(block));
 206 +                                     buf_block_get_page_no(block), trx);
 207         }
 208
 209  #ifdef UNIV_IBUF_COUNT_DEBUG
 210 @@ -2252,6 +2337,9 @@
 211  #endif
 212         buf_pool->stat.n_page_gets++;
 213
 214 +       if (innobase_get_slow_log()) {
 215 +               _increment_page_get_statistics(block, trx);
 216 +       }
 217         return(TRUE);
 218  }
 219
 220 @@ -2273,6 +2361,7 @@
 221  {
 222         ibool           success;
 223         ulint           fix_type;
 224 +       trx_t*          trx = NULL;
 225
 226         ut_ad(mtr);
 227         ut_ad(mtr->state == MTR_ACTIVE);
 228 @@ -2357,6 +2446,11 @@
 229  #endif
 230         buf_pool->stat.n_page_gets++;
 231
 232 +       if (innobase_get_slow_log()) {
 233 +               trx = innobase_get_trx();
 234 +               _increment_page_get_statistics(block, trx);
 235 +       }
 236 +
 237         return(TRUE);
 238  }
 239
 240 --- a/storage/innodb_plugin/buf/buf0rea.c
 241 +++ b/storage/innodb_plugin/buf/buf0rea.c
 242 @@ -83,7 +83,8 @@
 243                         treat the tablespace as dropped; this is a timestamp we
 244                         use to stop dangling page reads from a tablespace
 245                         which we have DISCARDed + IMPORTed back */
 246 -       ulint   offset) /*!< in: page number */
 247 +       ulint   offset, /*!< in: page number */
 248 +       trx_t*  trx)
 249  {
 250         buf_page_t*     bpage;
 251         ulint           wake_later;
 252 @@ -184,15 +185,15 @@
 253         ut_ad(buf_page_in_file(bpage));
 254
 255         if (zip_size) {
 256 -               *err = fil_io(OS_FILE_READ | wake_later,
 257 +               *err = _fil_io(OS_FILE_READ | wake_later,
 258                               sync, space, zip_size, offset, 0, zip_size,
 259 -                             bpage->zip.data, bpage);
 260 +                             bpage->zip.data, bpage, trx);
 261         } else {
 262                 ut_a(buf_page_get_state(bpage) == BUF_BLOCK_FILE_PAGE);
 263
 264 -               *err = fil_io(OS_FILE_READ | wake_later,
 265 +               *err = _fil_io(OS_FILE_READ | wake_later,
 266                               sync, space, 0, offset, 0, UNIV_PAGE_SIZE,
 267 -                             ((buf_block_t*) bpage)->frame, bpage);
 268 +                             ((buf_block_t*) bpage)->frame, bpage, trx);
 269         }
 270         ut_a(*err == DB_SUCCESS);
 271
 272 @@ -224,8 +225,9 @@
 273  /*==================*/
 274         ulint   space,  /*!< in: space id */
 275         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 276 -       ulint   offset) /*!< in: page number of a page which the current thread
 277 +       ulint   offset, /*!< in: page number of a page which the current thread
 278                         wants to access */
 279 +       trx_t*  trx)
 280  {
 281         ib_int64_t      tablespace_version;
 282         ulint           recent_blocks   = 0;
 283 @@ -332,7 +334,7 @@
 284                                 &err, FALSE,
 285                                 ibuf_mode | OS_AIO_SIMULATED_WAKE_LATER,
 286                                 space, zip_size, FALSE,
 287 -                               tablespace_version, i);
 288 +                               tablespace_version, i, trx);
 289                         if (err == DB_TABLESPACE_DELETED) {
 290                                 ut_print_timestamp(stderr);
 291                                 fprintf(stderr,
 292 @@ -382,13 +384,14 @@
 293  /*==========*/
 294         ulint   space,  /*!< in: space id */
 295         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 296 -       ulint   offset) /*!< in: page number */
 297 +       ulint   offset, /*!< in: page number */
 298 +       trx_t*  trx)
 299  {
 300         ib_int64_t      tablespace_version;
 301         ulint           count;
 302         ulint           err;
 303
 304 -       count = buf_read_ahead_random(space, zip_size, offset);
 305 +       count = buf_read_ahead_random(space, zip_size, offset, trx);
 306         srv_buf_pool_reads += count;
 307
 308         tablespace_version = fil_space_get_version(space);
 309 @@ -398,7 +401,7 @@
 310
 311         count = buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
 312                                   zip_size, FALSE,
 313 -                                 tablespace_version, offset);
 314 +                                 tablespace_version, offset, trx);
 315         srv_buf_pool_reads += count;
 316         if (err == DB_TABLESPACE_DELETED) {
 317                 ut_print_timestamp(stderr);
 318 @@ -449,8 +452,9 @@
 319  /*==================*/
 320         ulint   space,  /*!< in: space id */
 321         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 322 -       ulint   offset) /*!< in: page number of a page; NOTE: the current thread
 323 +       ulint   offset, /*!< in: page number of a page; NOTE: the current thread
 324                         must want access to this page (see NOTE 3 above) */
 325 +       trx_t*  trx)
 326  {
 327         ib_int64_t      tablespace_version;
 328         buf_page_t*     bpage;
 329 @@ -673,7 +677,7 @@
 330                         count += buf_read_page_low(
 331                                 &err, FALSE,
 332                                 ibuf_mode | OS_AIO_SIMULATED_WAKE_LATER,
 333 -                               space, zip_size, FALSE, tablespace_version, i);
 334 +                               space, zip_size, FALSE, tablespace_version, i, trx);
 335                         if (err == DB_TABLESPACE_DELETED) {
 336                                 ut_print_timestamp(stderr);
 337                                 fprintf(stderr,
 338 @@ -763,7 +767,7 @@
 339                 buf_read_page_low(&err, sync && (i + 1 == n_stored),
 340                                   BUF_READ_ANY_PAGE, space_ids[i],
 341                                   zip_size, TRUE, space_versions[i],
 342 -                                 page_nos[i]);
 343 +                                 page_nos[i], NULL);
 344
 345                 if (UNIV_UNLIKELY(err == DB_TABLESPACE_DELETED)) {
 346  tablespace_deleted:
 347 @@ -904,12 +908,12 @@
 348                 if ((i + 1 == n_stored) && sync) {
 349                         buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
 350                                           zip_size, TRUE, tablespace_version,
 351 -                                         page_nos[i]);
 352 +                                         page_nos[i], NULL);
 353                 } else {
 354                         buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE
 355                                           | OS_AIO_SIMULATED_WAKE_LATER,
 356                                           space, zip_size, TRUE,
 357 -                                         tablespace_version, page_nos[i]);
 358 +                                         tablespace_version, page_nos[i], NULL);
 359                 }
 360         }
 361
 362 --- a/storage/innodb_plugin/fil/fil0fil.c
 363 +++ b/storage/innodb_plugin/fil/fil0fil.c
 364 @@ -4697,7 +4697,7 @@
 365                                  node->name, node->handle, buf,
 366                                  offset_low, offset_high,
 367                                  page_size * n_pages,
 368 -                                NULL, NULL);
 369 +                                NULL, NULL, NULL);
 370  #endif
 371                 if (success) {
 372                         node->size += n_pages;
 373 @@ -5024,7 +5024,7 @@
 374  i/o on a tablespace which does not exist */
 375  UNIV_INTERN
 376  ulint
 377 -fil_io(
 378 +_fil_io(
 379  /*===*/
 380         ulint   type,           /*!< in: OS_FILE_READ or OS_FILE_WRITE,
 381                                 ORed to OS_FILE_LOG, if a log i/o
 382 @@ -5049,8 +5049,9 @@
 383         void*   buf,            /*!< in/out: buffer where to store read data
 384                                 or from where to write; in aio this must be
 385                                 appropriately aligned */
 386 -       void*   message)        /*!< in: message for aio handler if non-sync
 387 +       void*   message,        /*!< in: message for aio handler if non-sync
 388                                 aio used, else ignored */
 389 +       trx_t*  trx)
 390  {
 391         ulint           mode;
 392         fil_space_t*    space;
 393 @@ -5220,7 +5221,7 @@
 394  #else
 395         /* Queue the aio request */
 396         ret = os_aio(type, mode | wake_later, node->name, node->handle, buf,
 397 -                    offset_low, offset_high, len, node, message);
 398 +                    offset_low, offset_high, len, node, message, trx);
 399  #endif
 400         ut_a(ret);
 401
 402 --- a/storage/innodb_plugin/handler/ha_innodb.cc
 403 +++ b/storage/innodb_plugin/handler/ha_innodb.cc
 404 @@ -1392,6 +1392,16 @@
 405         trx->check_unique_secondary = !thd_test_options(
 406                 thd, OPTION_RELAXED_UNIQUE_CHECKS);
 407
 408 +#ifdef EXTENDED_SLOWLOG
 409 +       if (thd_log_slow_verbosity(thd) & SLOG_V_INNODB) {
 410 +               trx->take_stats = TRUE;
 411 +       } else {
 412 +               trx->take_stats = FALSE;
 413 +       }
 414 +#else
 415 +       trx->take_stats = FALSE;
 416 +#endif
 417 +
 418         DBUG_VOID_RETURN;
 419  }
 420
 421 @@ -1447,6 +1457,32 @@
 422  }
 423
 424
 425 +/*************************************************************************
 426 +Gets current trx. */
 427 +extern "C"
 428 +trx_t*
 429 +innobase_get_trx()
 430 +{
 431 +       THD *thd=current_thd;
 432 +       if (likely(thd != 0)) {
 433 +               trx_t*& trx = thd_to_trx(thd);
 434 +               return(trx);
 435 +       } else {
 436 +               return(NULL);
 437 +       }
 438 +}
 439 +
 440 +extern "C"
 441 +ibool
 442 +innobase_get_slow_log()
 443 +{
 444 +#ifdef EXTENDED_SLOWLOG
 445 +       return((ibool) thd_opt_slow_log());
 446 +#else
 447 +       return(FALSE);
 448 +#endif
 449 +}
 450 +
 451  /*********************************************************************//**
 452  Construct ha_innobase handler. */
 453  UNIV_INTERN
 454 @@ -8965,6 +9001,25 @@
 455         statement has ended */
 456
 457         if (trx->n_mysql_tables_in_use == 0) {
 458 +#ifdef EXTENDED_SLOWLOG
 459 +               increment_thd_innodb_stats(thd,
 460 +                                       (unsigned long long) ut_conv_dulint_to_longlong(trx->id),
 461 +                                       trx->io_reads,
 462 +                                       trx->io_read,
 463 +                                       trx->io_reads_wait_timer,
 464 +                                       trx->lock_que_wait_timer,
 465 +                                       trx->innodb_que_wait_timer,
 466 +                                       trx->distinct_page_access);
 467 +
 468 +               trx->io_reads = 0;
 469 +               trx->io_read = 0;
 470 +               trx->io_reads_wait_timer = 0;
 471 +               trx->lock_que_wait_timer = 0;
 472 +               trx->innodb_que_wait_timer = 0;
 473 +               trx->distinct_page_access = 0;
 474 +               if (trx->distinct_page_access_hash)
 475 +                       memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
 476 +#endif
 477
 478                 trx->mysql_n_tables_locked = 0;
 479                 prebuilt->used_in_HANDLER = FALSE;
 480 --- a/storage/innodb_plugin/handler/innodb_patch_info.h
 481 +++ b/storage/innodb_plugin/handler/innodb_patch_info.h
 482 @@ -39,5 +39,6 @@
 483  {"innodb_purge_thread","Enable to use purge devoted thread","","http://www.percona.com/docs/wiki/percona-xtradb"},
 484  {"innodb_admin_command_base","XtraDB specific command interface through i_s","","http://www.percona.com/docs/wiki/percona-xtradb"},
 485  {"innodb_show_lock_name","Show mutex/lock name instead of crated file/line","","http://www.percona.com/docs/wiki/percona-xtradb"},
 486 +{"innodb_extend_slow","Extended statistics in slow.log","It is InnoDB-part only. It needs to patch also to mysqld.","http://www.percona.com/docs/wiki/percona-xtradb"},
 487  {NULL, NULL, NULL, NULL}
 488  };
 489 --- a/storage/innodb_plugin/include/buf0rea.h
 490 +++ b/storage/innodb_plugin/include/buf0rea.h
 491 @@ -27,6 +27,7 @@
 492  #define buf0rea_h
 493
 494  #include "univ.i"
 495 +#include "trx0types.h"
 496  #include "buf0types.h"
 497
 498  /********************************************************************//**
 499 @@ -41,7 +42,8 @@
 500  /*==========*/
 501         ulint   space,  /*!< in: space id */
 502         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 503 -       ulint   offset);/*!< in: page number */
 504 +       ulint   offset, /*!< in: page number */
 505 +       trx_t*  trx);
 506  /********************************************************************//**
 507  Applies linear read-ahead if in the buf_pool the page is a border page of
 508  a linear read-ahead area and all the pages in the area have been accessed.
 509 @@ -72,8 +74,9 @@
 510  /*==================*/
 511         ulint   space,  /*!< in: space id */
 512         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 513 -       ulint   offset);/*!< in: page number of a page; NOTE: the current thread
 514 +       ulint   offset, /*!< in: page number of a page; NOTE: the current thread
 515                         must want access to this page (see NOTE 3 above) */
 516 +       trx_t*  trx);
 517  /********************************************************************//**
 518  Issues read requests for pages which the ibuf module wants to read in, in
 519  order to contract the insert buffer tree. Technically, this function is like
 520 --- a/storage/innodb_plugin/include/fil0fil.h
 521 +++ b/storage/innodb_plugin/include/fil0fil.h
 522 @@ -610,9 +610,12 @@
 523  Reads or writes data. This operation is asynchronous (aio).
 524  @return DB_SUCCESS, or DB_TABLESPACE_DELETED if we are trying to do
 525  i/o on a tablespace which does not exist */
 526 +#define fil_io(type, sync, space_id, zip_size, block_offset, byte_offset, len, buf, message) \
 527 +       _fil_io(type, sync, space_id, zip_size, block_offset, byte_offset, len, buf, message, NULL)
 528 +
 529  UNIV_INTERN
 530  ulint
 531 -fil_io(
 532 +_fil_io(
 533  /*===*/
 534         ulint   type,           /*!< in: OS_FILE_READ or OS_FILE_WRITE,
 535                                 ORed to OS_FILE_LOG, if a log i/o
 536 @@ -637,8 +640,9 @@
 537         void*   buf,            /*!< in/out: buffer where to store read data
 538                                 or from where to write; in aio this must be
 539                                 appropriately aligned */
 540 -       void*   message);       /*!< in: message for aio handler if non-sync
 541 +       void*   message,        /*!< in: message for aio handler if non-sync
 542                                 aio used, else ignored */
 543 +       trx_t*  trx);
 544  /**********************************************************************//**
 545  Waits for an aio operation to complete. This function is used to write the
 546  handler for completed requests. The aio array of pending requests is divided
 547 --- a/storage/innodb_plugin/include/os0file.h
 548 +++ b/storage/innodb_plugin/include/os0file.h
 549 @@ -36,6 +36,7 @@
 550  #define os0file_h
 551
 552  #include "univ.i"
 553 +#include "trx0types.h"
 554
 555  #ifndef __WIN__
 556  #include <dirent.h>
 557 @@ -483,9 +484,12 @@
 558  /*******************************************************************//**
 559  Requests a synchronous read operation.
 560  @return        TRUE if request was successful, FALSE if fail */
 561 +#define os_file_read(file, buf, offset, offset_high, n)         \
 562 +               _os_file_read(file, buf, offset, offset_high, n, NULL)
 563 +
 564  UNIV_INTERN
 565  ibool
 566 -os_file_read(
 567 +_os_file_read(
 568  /*=========*/
 569         os_file_t       file,   /*!< in: handle to a file */
 570         void*           buf,    /*!< in: buffer where to read */
 571 @@ -493,7 +497,8 @@
 572                                 offset where to read */
 573         ulint           offset_high,/*!< in: most significant 32 bits of
 574                                 offset */
 575 -       ulint           n);     /*!< in: number of bytes to read */
 576 +       ulint           n,      /*!< in: number of bytes to read */
 577 +       trx_t*          trx);
 578  /*******************************************************************//**
 579  Rewind file to its start, read at most size - 1 bytes from it to str, and
 580  NUL-terminate str. All errors are silently ignored. This function is
 581 @@ -647,10 +652,11 @@
 582                                 (can be used to identify a completed
 583                                 aio operation); ignored if mode is
 584                                 OS_AIO_SYNC */
 585 -       void*           message2);/*!< in: message for the aio handler
 586 +       void*           message2,/*!< in: message for the aio handler
 587                                 (can be used to identify a completed
 588                                 aio operation); ignored if mode is
 589                                 OS_AIO_SYNC */
 590 +       trx_t*          trx);
 591  /************************************************************************//**
 592  Wakes up all async i/o threads so that they know to exit themselves in
 593  shutdown. */
 594 --- a/storage/innodb_plugin/include/srv0srv.h
 595 +++ b/storage/innodb_plugin/include/srv0srv.h
 596 @@ -62,6 +62,9 @@
 597  #define SRV_AUTO_EXTEND_INCREMENT      \
 598         (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
 599
 600 +/* prototypes for new functions added to ha_innodb.cc */
 601 +ibool  innobase_get_slow_log();
 602 +
 603  /* This is set to TRUE if the MySQL user has set it in MySQL */
 604  extern ibool   srv_lower_case_table_names;
 605
 606 --- a/storage/innodb_plugin/include/trx0trx.h
 607 +++ b/storage/innodb_plugin/include/trx0trx.h
 608 @@ -749,6 +749,17 @@
 609         /*------------------------------*/
 610         char detailed_error[256];       /*!< detailed error message for last
 611                                         error, or empty. */
 612 +       /*------------------------------*/
 613 +       ulint           io_reads;
 614 +       ib_uint64_t     io_read;
 615 +       ulint           io_reads_wait_timer;
 616 +       ib_uint64_t     lock_que_wait_ustarted;
 617 +       ulint           lock_que_wait_timer;
 618 +       ulint           innodb_que_wait_timer;
 619 +       ulint           distinct_page_access;
 620 +#define        DPAH_SIZE       8192
 621 +       byte*           distinct_page_access_hash;
 622 +       ibool           take_stats;
 623  };
 624
 625  #define TRX_MAX_N_THREADS      32      /* maximum number of
 626 --- a/storage/innodb_plugin/lock/lock0lock.c
 627 +++ b/storage/innodb_plugin/lock/lock0lock.c
 628 @@ -1757,6 +1757,8 @@
 629  {
 630         lock_t* lock;
 631         trx_t*  trx;
 632 +       ulint   sec;
 633 +       ulint   ms;
 634
 635         ut_ad(mutex_own(&kernel_mutex));
 636
 637 @@ -1815,6 +1817,10 @@
 638         trx->que_state = TRX_QUE_LOCK_WAIT;
 639         trx->was_chosen_as_deadlock_victim = FALSE;
 640         trx->wait_started = time(NULL);
 641 +       if (innobase_get_slow_log() && trx->take_stats) {
 642 +               ut_usectime(&sec, &ms);
 643 +               trx->lock_que_wait_ustarted = (ib_uint64_t)sec * 1000000 + ms;
 644 +       }
 645
 646         ut_a(que_thr_stop(thr));
 647
 648 @@ -3767,6 +3773,8 @@
 649  {
 650         lock_t* lock;
 651         trx_t*  trx;
 652 +       ulint   sec;
 653 +       ulint   ms;
 654
 655         ut_ad(mutex_own(&kernel_mutex));
 656
 657 @@ -3822,6 +3830,10 @@
 658                 return(DB_SUCCESS);
 659         }
 660
 661 +       if (innobase_get_slow_log() && trx->take_stats) {
 662 +               ut_usectime(&sec, &ms);
 663 +               trx->lock_que_wait_ustarted = (ib_uint64_t)sec * 1000000 + ms;
 664 +       }
 665         trx->que_state = TRX_QUE_LOCK_WAIT;
 666         trx->was_chosen_as_deadlock_victim = FALSE;
 667         trx->wait_started = time(NULL);
 668 --- a/storage/innodb_plugin/os/os0file.c
 669 +++ b/storage/innodb_plugin/os/os0file.c
 670 @@ -38,6 +38,8 @@
 671  #include "srv0start.h"
 672  #include "fil0fil.h"
 673  #include "buf0buf.h"
 674 +#include "trx0sys.h"
 675 +#include "trx0trx.h"
 676  #include "log0recv.h"
 677  #ifndef UNIV_HOTBACKUP
 678  # include "os0sync.h"
 679 @@ -2098,22 +2100,30 @@
 680  /*******************************************************************//**
 681  Does a synchronous read operation in Posix.
 682  @return        number of bytes read, -1 if error */
 683 +#define os_file_pread(file, buf, n, offset, offset_high)        \
 684 +               _os_file_pread(file, buf, n, offset, offset_high, NULL);
 685 +
 686  static
 687  ssize_t
 688 -os_file_pread(
 689 +_os_file_pread(
 690  /*==========*/
 691         os_file_t       file,   /*!< in: handle to a file */
 692         void*           buf,    /*!< in: buffer where to read */
 693         ulint           n,      /*!< in: number of bytes to read */
 694         ulint           offset, /*!< in: least significant 32 bits of file
 695                                 offset from where to read */
 696 -       ulint           offset_high) /*!< in: most significant 32 bits of
 697 +       ulint           offset_high, /*!< in: most significant 32 bits of
 698                                 offset */
 699 +       trx_t*          trx)
 700  {
 701         off_t   offs;
 702  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 703         ssize_t n_bytes;
 704  #endif /* HAVE_PREAD && !HAVE_BROKEN_PREAD */
 705 +       ulint           sec;
 706 +       ulint           ms;
 707 +       ib_uint64_t     start_time;
 708 +       ib_uint64_t     finish_time;
 709
 710         ut_a((offset & 0xFFFFFFFFUL) == offset);
 711
 712 @@ -2134,6 +2144,15 @@
 713
 714         os_n_file_reads++;
 715
 716 +       if (innobase_get_slow_log() && trx && trx->take_stats)
 717 +       {
 718 +               trx->io_reads++;
 719 +               trx->io_read += n;
 720 +               ut_usectime(&sec, &ms);
 721 +               start_time = (ib_uint64_t)sec * 1000000 + ms;
 722 +       } else {
 723 +               start_time = 0;
 724 +       }
 725  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 726         os_mutex_enter(os_file_count_mutex);
 727         os_file_n_pending_preads++;
 728 @@ -2147,6 +2166,13 @@
 729         os_n_pending_reads--;
 730         os_mutex_exit(os_file_count_mutex);
 731
 732 +       if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 733 +       {
 734 +               ut_usectime(&sec, &ms);
 735 +               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 736 +               trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 737 +       }
 738 +
 739         return(n_bytes);
 740  #else
 741         {
 742 @@ -2183,6 +2209,13 @@
 743                 os_n_pending_reads--;
 744                 os_mutex_exit(os_file_count_mutex);
 745
 746 +               if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 747 +               {
 748 +                       ut_usectime(&sec, &ms);
 749 +                       finish_time = (ib_uint64_t)sec * 1000000 + ms;
 750 +                       trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 751 +               }
 752 +
 753                 return(ret);
 754         }
 755  #endif
 756 @@ -2313,7 +2346,7 @@
 757  @return        TRUE if request was successful, FALSE if fail */
 758  UNIV_INTERN
 759  ibool
 760 -os_file_read(
 761 +_os_file_read(
 762  /*=========*/
 763         os_file_t       file,   /*!< in: handle to a file */
 764         void*           buf,    /*!< in: buffer where to read */
 765 @@ -2321,7 +2354,8 @@
 766                                 offset where to read */
 767         ulint           offset_high, /*!< in: most significant 32 bits of
 768                                 offset */
 769 -       ulint           n)      /*!< in: number of bytes to read */
 770 +       ulint           n,      /*!< in: number of bytes to read */
 771 +       trx_t*          trx)
 772  {
 773  #ifdef __WIN__
 774         BOOL            ret;
 775 @@ -2396,7 +2430,7 @@
 776         os_bytes_read_since_printout += n;
 777
 778  try_again:
 779 -       ret = os_file_pread(file, buf, n, offset, offset_high);
 780 +       ret = _os_file_pread(file, buf, n, offset, offset_high, trx);
 781
 782         if ((ulint)ret == n) {
 783
 784 @@ -3653,10 +3687,11 @@
 785                                 (can be used to identify a completed
 786                                 aio operation); ignored if mode is
 787                                 OS_AIO_SYNC */
 788 -       void*           message2)/*!< in: message for the aio handler
 789 +       void*           message2,/*!< in: message for the aio handler
 790                                 (can be used to identify a completed
 791                                 aio operation); ignored if mode is
 792                                 OS_AIO_SYNC */
 793 +       trx_t*          trx)
 794  {
 795         os_aio_array_t* array;
 796         os_aio_slot_t*  slot;
 797 @@ -3698,8 +3733,8 @@
 798                 wait in the Windows case. */
 799
 800                 if (type == OS_FILE_READ) {
 801 -                       return(os_file_read(file, buf, offset,
 802 -                                           offset_high, n));
 803 +                       return(_os_file_read(file, buf, offset,
 804 +                                           offset_high, n, trx));
 805                 }
 806
 807                 ut_a(type == OS_FILE_WRITE);
 808 @@ -3732,6 +3767,11 @@
 809                 ut_error;
 810         }
 811
 812 +       if (trx && type == OS_FILE_READ)
 813 +       {
 814 +               trx->io_reads++;
 815 +               trx->io_read += n;
 816 +       }
 817         slot = os_aio_array_reserve_slot(type, array, message1, message2, file,
 818                                          name, buf, offset, offset_high, n);
 819         if (type == OS_FILE_READ) {
 820 --- a/storage/innodb_plugin/srv/srv0srv.c
 821 +++ b/storage/innodb_plugin/srv/srv0srv.c
 822 @@ -86,6 +86,9 @@
 823  #include "trx0i_s.h"
 824  #include "os0sync.h" /* for HAVE_ATOMIC_BUILTINS */
 825
 826 +/* prototypes for new functions added to ha_innodb.cc */
 827 +ibool  innobase_get_slow_log();
 828 +
 829  /* This is set to TRUE if the MySQL user has set it in MySQL; currently
 830  affects only FOREIGN KEY definition parsing */
 831  UNIV_INTERN ibool      srv_lower_case_table_names      = FALSE;
 832 @@ -1158,6 +1161,10 @@
 833         ibool                   has_slept = FALSE;
 834         srv_conc_slot_t*        slot      = NULL;
 835         ulint                   i;
 836 +       ib_uint64_t             start_time = 0L;
 837 +       ib_uint64_t             finish_time = 0L;
 838 +       ulint                   sec;
 839 +       ulint                   ms;
 840
 841         if (trx->mysql_thd != NULL
 842             && thd_is_replication_slave_thread(trx->mysql_thd)) {
 843 @@ -1234,6 +1241,7 @@
 844                 switches. */
 845                 if (SRV_THREAD_SLEEP_DELAY > 0) {
 846                         os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
 847 +                       trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
 848                 }
 849
 850                 trx->op_info = "";
 851 @@ -1289,12 +1297,25 @@
 852         /* Go to wait for the event; when a thread leaves InnoDB it will
 853         release this thread */
 854
 855 +       if (innobase_get_slow_log() && trx->take_stats) {
 856 +               ut_usectime(&sec, &ms);
 857 +               start_time = (ib_uint64_t)sec * 1000000 + ms;
 858 +       } else {
 859 +               start_time = 0;
 860 +       }
 861 +
 862         trx->op_info = "waiting in InnoDB queue";
 863
 864         os_event_wait(slot->event);
 865
 866         trx->op_info = "";
 867
 868 +       if (innobase_get_slow_log() && trx->take_stats && start_time) {
 869 +               ut_usectime(&sec, &ms);
 870 +               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 871 +               trx->innodb_que_wait_timer += (ulint)(finish_time - start_time);
 872 +       }
 873 +
 874         os_fast_mutex_lock(&srv_conc_mutex);
 875
 876         srv_conc_n_waiting_threads--;
 877 --- a/storage/innodb_plugin/trx/trx0trx.c
 878 +++ b/storage/innodb_plugin/trx/trx0trx.c
 879 @@ -182,6 +182,15 @@
 880         trx->global_read_view = NULL;
 881         trx->read_view = NULL;
 882
 883 +       trx->io_reads = 0;
 884 +       trx->io_read = 0;
 885 +       trx->io_reads_wait_timer = 0;
 886 +       trx->lock_que_wait_timer = 0;
 887 +       trx->innodb_que_wait_timer = 0;
 888 +       trx->distinct_page_access = 0;
 889 +       trx->distinct_page_access_hash = NULL;
 890 +       trx->take_stats = FALSE;
 891 +
 892         /* Set X/Open XA transaction identification to NULL */
 893         memset(&trx->xid, 0, sizeof(trx->xid));
 894         trx->xid.formatID = -1;
 895 @@ -219,6 +228,11 @@
 896
 897         trx->mysql_process_no = os_proc_get_number();
 898
 899 +       if (innobase_get_slow_log() && trx->take_stats) {
 900 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
 901 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
 902 +       }
 903 +
 904         return(trx);
 905  }
 906
 907 @@ -404,6 +418,12 @@
 908  /*===============*/
 909         trx_t*  trx)    /*!< in, own: trx object */
 910  {
 911 +       if (trx->distinct_page_access_hash)
 912 +       {
 913 +               mem_free(trx->distinct_page_access_hash);
 914 +               trx->distinct_page_access_hash= NULL;
 915 +       }
 916 +
 917         mutex_enter(&kernel_mutex);
 918
 919         UT_LIST_REMOVE(mysql_trx_list, trx_sys->mysql_trx_list, trx);
 920 @@ -425,6 +445,12 @@
 921  /*====================*/
 922         trx_t*  trx)    /*!< in, own: trx object */
 923  {
 924 +       if (trx->distinct_page_access_hash)
 925 +       {
 926 +               mem_free(trx->distinct_page_access_hash);
 927 +               trx->distinct_page_access_hash= NULL;
 928 +       }
 929 +
 930         mutex_enter(&kernel_mutex);
 931
 932         trx_free(trx);
 933 @@ -1157,6 +1183,9 @@
 934         trx_t*  trx)    /*!< in: transaction */
 935  {
 936         que_thr_t*      thr;
 937 +       ulint           sec;
 938 +       ulint           ms;
 939 +       ib_uint64_t     now;
 940
 941         ut_ad(mutex_own(&kernel_mutex));
 942         ut_ad(trx->que_state == TRX_QUE_LOCK_WAIT);
 943 @@ -1171,6 +1200,11 @@
 944                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
 945         }
 946
 947 +       if (innobase_get_slow_log() && trx->take_stats) {
 948 +               ut_usectime(&sec, &ms);
 949 +               now = (ib_uint64_t)sec * 1000000 + ms;
 950 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
 951 +       }
 952         trx->que_state = TRX_QUE_RUNNING;
 953  }
 954
 955 @@ -1184,6 +1218,9 @@
 956         trx_t*  trx)    /*!< in: transaction in the TRX_QUE_LOCK_WAIT state */
 957  {
 958         que_thr_t*      thr;
 959 +       ulint           sec;
 960 +       ulint           ms;
 961 +       ib_uint64_t     now;
 962
 963         ut_ad(mutex_own(&kernel_mutex));
 964         ut_ad(trx->que_state == TRX_QUE_LOCK_WAIT);
 965 @@ -1198,6 +1235,11 @@
 966                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
 967         }
 968
 969 +       if (innobase_get_slow_log() && trx->take_stats) {
 970 +               ut_usectime(&sec, &ms);
 971 +               now = (ib_uint64_t)sec * 1000000 + ms;
 972 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
 973 +       }
 974         trx->que_state = TRX_QUE_RUNNING;
 975  }
 976