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 diff -ruN a/storage/innobase/buf/buf0buf.c b/storage/innobase/buf/buf0buf.c
   9 --- a/storage/innobase/buf/buf0buf.c    2010-12-03 15:49:59.175955882 +0900
  10 +++ b/storage/innobase/buf/buf0buf.c    2010-12-03 17:42:42.074307123 +0900
  11 @@ -51,6 +51,40 @@
  12  #include "dict0dict.h"
  13  #include "log0recv.h"
  14  #include "page0zip.h"
  15 +#include "trx0trx.h"
  16 +
  17 +/* prototypes for new functions added to ha_innodb.cc */
  18 +trx_t* innobase_get_trx();
  19 +
  20 +inline void _increment_page_get_statistics(buf_block_t* block, trx_t* trx)
  21 +{
  22 +       ulint           block_hash;
  23 +       ulint           block_hash_byte;
  24 +       byte            block_hash_offset;
  25 +
  26 +       ut_ad(block);
  27 +
  28 +       if (!innobase_get_slow_log() || !trx || !trx->take_stats)
  29 +               return;
  30 +
  31 +       if (!trx->distinct_page_access_hash) {
  32 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
  33 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
  34 +       }
  35 +
  36 +       block_hash = ut_hash_ulint((block->page.space << 20) + block->page.space +
  37 +                                       block->page.offset, DPAH_SIZE << 3);
  38 +       block_hash_byte = block_hash >> 3;
  39 +       block_hash_offset = (byte) block_hash & 0x07;
  40 +       if (block_hash_byte >= DPAH_SIZE)
  41 +               fprintf(stderr, "!!! block_hash_byte = %lu  block_hash_offset = %d !!!\n", block_hash_byte, block_hash_offset);
  42 +       if (block_hash_offset > 7)
  43 +               fprintf(stderr, "!!! block_hash_byte = %lu  block_hash_offset = %d !!!\n", block_hash_byte, block_hash_offset);
  44 +       if ((trx->distinct_page_access_hash[block_hash_byte] & ((byte) 0x01 << block_hash_offset)) == 0)
  45 +               trx->distinct_page_access++;
  46 +       trx->distinct_page_access_hash[block_hash_byte] |= (byte) 0x01 << block_hash_offset;
  47 +       return;
  48 +}
  49
  50  /*
  51                 IMPLEMENTATION OF THE BUFFER POOL
  52 @@ -2399,11 +2433,19 @@
  53         mutex_t*        block_mutex;
  54         ibool           must_read;
  55         unsigned        access_time;
  56 +       trx_t*          trx = NULL;
  57 +       ulint           sec;
  58 +       ulint           ms;
  59 +       ib_uint64_t     start_time;
  60 +       ib_uint64_t     finish_time;
  61         buf_pool_t*     buf_pool = buf_pool_get(space, offset);
  62
  63  #ifndef UNIV_LOG_DEBUG
  64         ut_ad(!ibuf_inside());
  65  #endif
  66 +       if (innobase_get_slow_log()) {
  67 +               trx = innobase_get_trx();
  68 +       }
  69         buf_pool->stat.n_page_gets++;
  70
  71         for (;;) {
  72 @@ -2421,7 +2463,7 @@
  73                 //buf_pool_mutex_exit(buf_pool);
  74                 rw_lock_s_unlock(&buf_pool->page_hash_latch);
  75
  76 -               buf_read_page(space, zip_size, offset);
  77 +               buf_read_page(space, zip_size, offset, trx);
  78
  79  #if defined UNIV_DEBUG || defined UNIV_BUF_DEBUG
  80                 ut_a(++buf_dbg_counter % 37 || buf_validate());
  81 @@ -2498,6 +2540,13 @@
  82                 /* Let us wait until the read operation
  83                 completes */
  84
  85 +               if (innobase_get_slow_log() && trx && trx->take_stats)
  86 +               {
  87 +                       ut_usectime(&sec, &ms);
  88 +                       start_time = (ib_uint64_t)sec * 1000000 + ms;
  89 +               } else {
  90 +                       start_time = 0;
  91 +               }
  92                 for (;;) {
  93                         enum buf_io_fix io_fix;
  94
  95 @@ -2512,6 +2561,12 @@
  96                                 break;
  97                         }
  98                 }
  99 +               if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 100 +               {
 101 +                       ut_usectime(&sec, &ms);
 102 +                       finish_time = (ib_uint64_t)sec * 1000000 + ms;
 103 +                       trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 104 +               }
 105         }
 106
 107  #ifdef UNIV_IBUF_COUNT_DEBUG
 108 @@ -2824,6 +2879,11 @@
 109         ibool           must_read;
 110         ulint           retries = 0;
 111         mutex_t*        block_mutex = NULL;
 112 +       trx_t*          trx = NULL;
 113 +       ulint           sec;
 114 +       ulint           ms;
 115 +       ib_uint64_t     start_time;
 116 +       ib_uint64_t     finish_time;
 117         buf_pool_t*     buf_pool = buf_pool_get(space, offset);
 118
 119         ut_ad(mtr);
 120 @@ -2842,6 +2902,9 @@
 121         ut_ad(!ibuf_inside() || ibuf_page_low(space, zip_size, offset,
 122                                               FALSE, file, line, NULL));
 123  #endif
 124 +       if (innobase_get_slow_log()) {
 125 +               trx = innobase_get_trx();
 126 +       }
 127         buf_pool->stat.n_page_gets++;
 128         fold = buf_page_address_fold(space, offset);
 129  loop:
 130 @@ -2915,7 +2978,7 @@
 131                         return(NULL);
 132                 }
 133
 134 -               if (buf_read_page(space, zip_size, offset)) {
 135 +               if (buf_read_page(space, zip_size, offset, trx)) {
 136                         retries = 0;
 137                 } else if (retries < BUF_PAGE_READ_MAX_RETRIES) {
 138                         ++retries;
 139 @@ -3220,6 +3283,13 @@
 140                         /* Let us wait until the read operation
 141                         completes */
 142
 143 +                       if (innobase_get_slow_log() && trx && trx->take_stats)
 144 +                       {
 145 +                               ut_usectime(&sec, &ms);
 146 +                               start_time = (ib_uint64_t)sec * 1000000 + ms;
 147 +                       } else {
 148 +                               start_time = 0;
 149 +                       }
 150                         for (;;) {
 151                                 enum buf_io_fix io_fix;
 152
 153 @@ -3234,6 +3304,12 @@
 154                                         break;
 155                                 }
 156                         }
 157 +                       if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 158 +                       {
 159 +                               ut_usectime(&sec, &ms);
 160 +                               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 161 +                               trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 162 +                       }
 163                 }
 164
 165                 fix_type = MTR_MEMO_BUF_FIX;
 166 @@ -3259,13 +3335,17 @@
 167                 /* In the case of a first access, try to apply linear
 168                 read-ahead */
 169
 170 -               buf_read_ahead_linear(space, zip_size, offset);
 171 +               buf_read_ahead_linear(space, zip_size, offset, trx);
 172         }
 173
 174  #ifdef UNIV_IBUF_COUNT_DEBUG
 175         ut_a(ibuf_count_get(buf_block_get_space(block),
 176                             buf_block_get_page_no(block)) == 0);
 177  #endif
 178 +       if (innobase_get_slow_log()) {
 179 +               _increment_page_get_statistics(block, trx);
 180 +       }
 181 +
 182         return(block);
 183  }
 184
 185 @@ -3289,6 +3369,7 @@
 186         unsigned        access_time;
 187         ibool           success;
 188         ulint           fix_type;
 189 +       trx_t*          trx = NULL;
 190
 191         ut_ad(block);
 192         ut_ad(mtr);
 193 @@ -3366,13 +3447,17 @@
 194  #if defined UNIV_DEBUG_FILE_ACCESSES || defined UNIV_DEBUG
 195         ut_a(block->page.file_page_was_freed == FALSE);
 196  #endif
 197 +       if (innobase_get_slow_log()) {
 198 +               trx = innobase_get_trx();
 199 +       }
 200 +
 201         if (UNIV_UNLIKELY(!access_time)) {
 202                 /* In the case of a first access, try to apply linear
 203                 read-ahead */
 204
 205                 buf_read_ahead_linear(buf_block_get_space(block),
 206                                       buf_block_get_zip_size(block),
 207 -                                     buf_block_get_page_no(block));
 208 +                                     buf_block_get_page_no(block), trx);
 209         }
 210
 211  #ifdef UNIV_IBUF_COUNT_DEBUG
 212 @@ -3382,6 +3467,9 @@
 213         buf_pool = buf_pool_from_block(block);
 214         buf_pool->stat.n_page_gets++;
 215
 216 +       if (innobase_get_slow_log()) {
 217 +               _increment_page_get_statistics(block, trx);
 218 +       }
 219         return(TRUE);
 220  }
 221
 222 @@ -3404,6 +3492,7 @@
 223         buf_pool_t*     buf_pool;
 224         ibool           success;
 225         ulint           fix_type;
 226 +       trx_t*          trx = NULL;
 227
 228         ut_ad(mtr);
 229         ut_ad(mtr->state == MTR_ACTIVE);
 230 @@ -3490,6 +3579,11 @@
 231  #endif
 232         buf_pool->stat.n_page_gets++;
 233
 234 +       if (innobase_get_slow_log()) {
 235 +               trx = innobase_get_trx();
 236 +               _increment_page_get_statistics(block, trx);
 237 +       }
 238 +
 239         return(TRUE);
 240  }
 241
 242 diff -ruN a/storage/innobase/buf/buf0rea.c b/storage/innobase/buf/buf0rea.c
 243 --- a/storage/innobase/buf/buf0rea.c    2010-12-03 17:32:15.617037263 +0900
 244 +++ b/storage/innobase/buf/buf0rea.c    2010-12-03 17:42:42.075297193 +0900
 245 @@ -77,7 +77,8 @@
 246                         treat the tablespace as dropped; this is a timestamp we
 247                         use to stop dangling page reads from a tablespace
 248                         which we have DISCARDed + IMPORTed back */
 249 -       ulint   offset) /*!< in: page number */
 250 +       ulint   offset, /*!< in: page number */
 251 +       trx_t*  trx)
 252  {
 253         buf_page_t*     bpage;
 254         ulint           wake_later;
 255 @@ -179,15 +180,15 @@
 256
 257         thd_wait_begin(NULL, THD_WAIT_DISKIO);
 258         if (zip_size) {
 259 -               *err = fil_io(OS_FILE_READ | wake_later,
 260 +               *err = _fil_io(OS_FILE_READ | wake_later,
 261                               sync, space, zip_size, offset, 0, zip_size,
 262 -                             bpage->zip.data, bpage);
 263 +                             bpage->zip.data, bpage, trx);
 264         } else {
 265                 ut_a(buf_page_get_state(bpage) == BUF_BLOCK_FILE_PAGE);
 266
 267 -               *err = fil_io(OS_FILE_READ | wake_later,
 268 +               *err = _fil_io(OS_FILE_READ | wake_later,
 269                               sync, space, 0, offset, 0, UNIV_PAGE_SIZE,
 270 -                             ((buf_block_t*) bpage)->frame, bpage);
 271 +                             ((buf_block_t*) bpage)->frame, bpage, trx);
 272         }
 273         thd_wait_end(NULL);
 274         ut_a(*err == DB_SUCCESS);
 275 @@ -213,7 +214,8 @@
 276  /*==========*/
 277         ulint   space,  /*!< in: space id */
 278         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 279 -       ulint   offset) /*!< in: page number */
 280 +       ulint   offset, /*!< in: page number */
 281 +       trx_t*  trx)
 282  {
 283         buf_pool_t*     buf_pool = buf_pool_get(space, offset);
 284         ib_int64_t      tablespace_version;
 285 @@ -227,7 +229,7 @@
 286
 287         count = buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
 288                                   zip_size, FALSE,
 289 -                                 tablespace_version, offset);
 290 +                                 tablespace_version, offset, trx);
 291         srv_buf_pool_reads += count;
 292         if (err == DB_TABLESPACE_DELETED) {
 293                 ut_print_timestamp(stderr);
 294 @@ -278,8 +280,9 @@
 295  /*==================*/
 296         ulint   space,  /*!< in: space id */
 297         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 298 -       ulint   offset) /*!< in: page number of a page; NOTE: the current thread
 299 +       ulint   offset, /*!< in: page number of a page; NOTE: the current thread
 300                         must want access to this page (see NOTE 3 above) */
 301 +       trx_t*  trx)
 302  {
 303         buf_pool_t*     buf_pool = buf_pool_get(space, offset);
 304         ib_int64_t      tablespace_version;
 305 @@ -500,7 +503,7 @@
 306                         count += buf_read_page_low(
 307                                 &err, FALSE,
 308                                 ibuf_mode | OS_AIO_SIMULATED_WAKE_LATER,
 309 -                               space, zip_size, FALSE, tablespace_version, i);
 310 +                               space, zip_size, FALSE, tablespace_version, i, trx);
 311                         if (err == DB_TABLESPACE_DELETED) {
 312                                 ut_print_timestamp(stderr);
 313                                 fprintf(stderr,
 314 @@ -594,7 +597,7 @@
 315                 buf_read_page_low(&err, sync && (i + 1 == n_stored),
 316                                   BUF_READ_ANY_PAGE, space_ids[i],
 317                                   zip_size, TRUE, space_versions[i],
 318 -                                 page_nos[i]);
 319 +                                 page_nos[i], NULL);
 320
 321                 if (UNIV_UNLIKELY(err == DB_TABLESPACE_DELETED)) {
 322  tablespace_deleted:
 323 @@ -736,12 +739,12 @@
 324                 if ((i + 1 == n_stored) && sync) {
 325                         buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
 326                                           zip_size, TRUE, tablespace_version,
 327 -                                         page_nos[i]);
 328 +                                         page_nos[i], NULL);
 329                 } else {
 330                         buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE
 331                                           | OS_AIO_SIMULATED_WAKE_LATER,
 332                                           space, zip_size, TRUE,
 333 -                                         tablespace_version, page_nos[i]);
 334 +                                         tablespace_version, page_nos[i], NULL);
 335                 }
 336         }
 337
 338 diff -ruN a/storage/innobase/fil/fil0fil.c b/storage/innobase/fil/fil0fil.c
 339 --- a/storage/innobase/fil/fil0fil.c    2010-12-03 15:53:54.610037199 +0900
 340 +++ b/storage/innobase/fil/fil0fil.c    2010-12-03 17:42:42.079064198 +0900
 341 @@ -4423,7 +4423,7 @@
 342                                  node->name, node->handle, buf,
 343                                  offset_low, offset_high,
 344                                  page_size * n_pages,
 345 -                                NULL, NULL);
 346 +                                NULL, NULL, NULL);
 347  #endif
 348                 if (success) {
 349                         node->size += n_pages;
 350 @@ -4750,7 +4750,7 @@
 351  i/o on a tablespace which does not exist */
 352  UNIV_INTERN
 353  ulint
 354 -fil_io(
 355 +_fil_io(
 356  /*===*/
 357         ulint   type,           /*!< in: OS_FILE_READ or OS_FILE_WRITE,
 358                                 ORed to OS_FILE_LOG, if a log i/o
 359 @@ -4775,8 +4775,9 @@
 360         void*   buf,            /*!< in/out: buffer where to store read data
 361                                 or from where to write; in aio this must be
 362                                 appropriately aligned */
 363 -       void*   message)        /*!< in: message for aio handler if non-sync
 364 +       void*   message,        /*!< in: message for aio handler if non-sync
 365                                 aio used, else ignored */
 366 +       trx_t*  trx)
 367  {
 368         ulint           mode;
 369         fil_space_t*    space;
 370 @@ -4946,7 +4947,7 @@
 371  #else
 372         /* Queue the aio request */
 373         ret = os_aio(type, mode | wake_later, node->name, node->handle, buf,
 374 -                    offset_low, offset_high, len, node, message);
 375 +                    offset_low, offset_high, len, node, message, trx);
 376  #endif
 377         ut_a(ret);
 378
 379 diff -ruN a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
 380 --- a/storage/innobase/handler/ha_innodb.cc     2010-12-03 17:36:44.293955189 +0900
 381 +++ b/storage/innobase/handler/ha_innodb.cc     2010-12-03 17:42:42.090024586 +0900
 382 @@ -1546,6 +1546,16 @@
 383         trx->check_unique_secondary = !thd_test_options(
 384                 thd, OPTION_RELAXED_UNIQUE_CHECKS);
 385
 386 +#ifdef EXTENDED_SLOWLOG
 387 +       if (thd_log_slow_verbosity(thd) & SLOG_V_INNODB) {
 388 +               trx->take_stats = TRUE;
 389 +       } else {
 390 +               trx->take_stats = FALSE;
 391 +       }
 392 +#else
 393 +       trx->take_stats = FALSE;
 394 +#endif
 395 +
 396         DBUG_VOID_RETURN;
 397  }
 398
 399 @@ -1600,6 +1610,32 @@
 400         return(trx);
 401  }
 402
 403 +/*************************************************************************
 404 +Gets current trx. */
 405 +extern "C"
 406 +trx_t*
 407 +innobase_get_trx()
 408 +{
 409 +       THD *thd=current_thd;
 410 +       if (likely(thd != 0)) {
 411 +               trx_t*& trx = thd_to_trx(thd);
 412 +               return(trx);
 413 +       } else {
 414 +               return(NULL);
 415 +       }
 416 +}
 417 +
 418 +extern "C"
 419 +ibool
 420 +innobase_get_slow_log()
 421 +{
 422 +#ifdef EXTENDED_SLOWLOG
 423 +       return((ibool) thd_opt_slow_log());
 424 +#else
 425 +       return(FALSE);
 426 +#endif
 427 +}
 428 +
 429  /*********************************************************************//**
 430  Note that a transaction has been registered with MySQL.
 431  @return true if transaction is registered with MySQL 2PC coordinator */
 432 @@ -9284,6 +9320,25 @@
 433         statement has ended */
 434
 435         if (trx->n_mysql_tables_in_use == 0) {
 436 +#ifdef EXTENDED_SLOWLOG
 437 +               increment_thd_innodb_stats(thd,
 438 +                                       (unsigned long long) trx->id,
 439 +                                       trx->io_reads,
 440 +                                       trx->io_read,
 441 +                                       trx->io_reads_wait_timer,
 442 +                                       trx->lock_que_wait_timer,
 443 +                                       trx->innodb_que_wait_timer,
 444 +                                       trx->distinct_page_access);
 445 +
 446 +               trx->io_reads = 0;
 447 +               trx->io_read = 0;
 448 +               trx->io_reads_wait_timer = 0;
 449 +               trx->lock_que_wait_timer = 0;
 450 +               trx->innodb_que_wait_timer = 0;
 451 +               trx->distinct_page_access = 0;
 452 +               if (trx->distinct_page_access_hash)
 453 +                       memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
 454 +#endif
 455
 456                 trx->mysql_n_tables_locked = 0;
 457                 prebuilt->used_in_HANDLER = FALSE;
 458 diff -ruN a/storage/innobase/include/buf0rea.h b/storage/innobase/include/buf0rea.h
 459 --- a/storage/innobase/include/buf0rea.h        2010-12-03 15:18:48.891024406 +0900
 460 +++ b/storage/innobase/include/buf0rea.h        2010-12-03 17:42:42.096026873 +0900
 461 @@ -27,6 +27,7 @@
 462  #define buf0rea_h
 463
 464  #include "univ.i"
 465 +#include "trx0types.h"
 466  #include "buf0types.h"
 467
 468  /********************************************************************//**
 469 @@ -41,7 +42,8 @@
 470  /*==========*/
 471         ulint   space,  /*!< in: space id */
 472         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 473 -       ulint   offset);/*!< in: page number */
 474 +       ulint   offset, /*!< in: page number */
 475 +       trx_t*  trx);
 476  /********************************************************************//**
 477  Applies linear read-ahead if in the buf_pool the page is a border page of
 478  a linear read-ahead area and all the pages in the area have been accessed.
 479 @@ -72,8 +74,9 @@
 480  /*==================*/
 481         ulint   space,  /*!< in: space id */
 482         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 483 -       ulint   offset);/*!< in: page number of a page; NOTE: the current thread
 484 +       ulint   offset, /*!< in: page number of a page; NOTE: the current thread
 485                         must want access to this page (see NOTE 3 above) */
 486 +       trx_t*  trx);
 487  /********************************************************************//**
 488  Issues read requests for pages which the ibuf module wants to read in, in
 489  order to contract the insert buffer tree. Technically, this function is like
 490 diff -ruN a/storage/innobase/include/fil0fil.h b/storage/innobase/include/fil0fil.h
 491 --- a/storage/innobase/include/fil0fil.h        2010-12-03 15:09:51.290958543 +0900
 492 +++ b/storage/innobase/include/fil0fil.h        2010-12-03 17:42:42.097027548 +0900
 493 @@ -611,9 +611,12 @@
 494  Reads or writes data. This operation is asynchronous (aio).
 495  @return DB_SUCCESS, or DB_TABLESPACE_DELETED if we are trying to do
 496  i/o on a tablespace which does not exist */
 497 +#define fil_io(type, sync, space_id, zip_size, block_offset, byte_offset, len, buf, message) \
 498 +       _fil_io(type, sync, space_id, zip_size, block_offset, byte_offset, len, buf, message, NULL)
 499 +
 500  UNIV_INTERN
 501  ulint
 502 -fil_io(
 503 +_fil_io(
 504  /*===*/
 505         ulint   type,           /*!< in: OS_FILE_READ or OS_FILE_WRITE,
 506                                 ORed to OS_FILE_LOG, if a log i/o
 507 @@ -638,8 +641,9 @@
 508         void*   buf,            /*!< in/out: buffer where to store read data
 509                                 or from where to write; in aio this must be
 510                                 appropriately aligned */
 511 -       void*   message);       /*!< in: message for aio handler if non-sync
 512 +       void*   message,        /*!< in: message for aio handler if non-sync
 513                                 aio used, else ignored */
 514 +       trx_t*  trx);
 515  /**********************************************************************//**
 516  Waits for an aio operation to complete. This function is used to write the
 517  handler for completed requests. The aio array of pending requests is divided
 518 diff -ruN a/storage/innobase/include/os0file.h b/storage/innobase/include/os0file.h
 519 --- a/storage/innobase/include/os0file.h        2010-11-03 07:01:13.000000000 +0900
 520 +++ b/storage/innobase/include/os0file.h        2010-12-03 17:42:42.100023783 +0900
 521 @@ -36,6 +36,7 @@
 522  #define os0file_h
 523
 524  #include "univ.i"
 525 +#include "trx0types.h"
 526
 527  #ifndef __WIN__
 528  #include <dirent.h>
 529 @@ -277,13 +278,17 @@
 530         pfs_os_file_close_func(file, __FILE__, __LINE__)
 531
 532  # define os_aio(type, mode, name, file, buf, offset, offset_high,      \
 533 -               n, message1, message2)                                  \
 534 +               n, message1, message2, trx)                             \
 535         pfs_os_aio_func(type, mode, name, file, buf, offset,            \
 536 -                       offset_high, n, message1, message2,             \
 537 +                       offset_high, n, message1, message2, trx,        \
 538                         __FILE__, __LINE__)
 539
 540  # define os_file_read(file, buf, offset, offset_high, n)               \
 541 -       pfs_os_file_read_func(file, buf, offset, offset_high, n,        \
 542 +       pfs_os_file_read_func(file, buf, offset, offset_high, n, NULL,  \
 543 +                             __FILE__, __LINE__)
 544 +
 545 +# define os_file_read_trx(file, buf, offset, offset_high, n, trx)      \
 546 +       pfs_os_file_read_func(file, buf, offset, offset_high, n, trx,   \
 547                               __FILE__, __LINE__)
 548
 549  # define os_file_read_no_error_handling(file, buf, offset,             \
 550 @@ -319,12 +324,15 @@
 551  # define os_file_close(file)   os_file_close_func(file)
 552
 553  # define os_aio(type, mode, name, file, buf, offset, offset_high,      \
 554 -              n, message1, message2)                                   \
 555 +              n, message1, message2, trx)                              \
 556         os_aio_func(type, mode, name, file, buf, offset, offset_high, n,\
 557 -                   message1, message2)
 558 +                   message1, message2, trx)
 559
 560  # define os_file_read(file, buf, offset, offset_high, n)               \
 561 -       os_file_read_func(file, buf, offset, offset_high, n)
 562 +       os_file_read_func(file, buf, offset, offset_high, n, NULL)
 563 +
 564 +# define os_file_read_trx(file, buf, offset, offset_high, n, trx)      \
 565 +       os_file_read_func(file, buf, offset, offset_high, n, trx)
 566
 567  # define os_file_read_no_error_handling(file, buf, offset,             \
 568                                        offset_high, n)                  \
 569 @@ -692,6 +700,7 @@
 570         ulint           offset_high,/*!< in: most significant 32 bits of
 571                                 offset */
 572         ulint           n,      /*!< in: number of bytes to read */
 573 +       trx_t*          trx,
 574         const char*     src_file,/*!< in: file name where func invoked */
 575         ulint           src_line);/*!< in: line where the func invoked */
 576
 577 @@ -746,6 +755,7 @@
 578                                 (can be used to identify a completed
 579                                 aio operation); ignored if mode is
 580                                  OS_AIO_SYNC */
 581 +       trx_t*          trx,
 582         const char*     src_file,/*!< in: file name where func invoked */
 583         ulint           src_line);/*!< in: line where the func invoked */
 584  /*******************************************************************//**
 585 @@ -887,7 +897,8 @@
 586                                 offset where to read */
 587         ulint           offset_high,/*!< in: most significant 32 bits of
 588                                 offset */
 589 -       ulint           n);     /*!< in: number of bytes to read */
 590 +       ulint           n,      /*!< in: number of bytes to read */
 591 +       trx_t*          trx);
 592  /*******************************************************************//**
 593  Rewind file to its start, read at most size - 1 bytes from it to str, and
 594  NUL-terminate str. All errors are silently ignored. This function is
 595 @@ -1046,10 +1057,11 @@
 596                                 (can be used to identify a completed
 597                                 aio operation); ignored if mode is
 598                                 OS_AIO_SYNC */
 599 -       void*           message2);/*!< in: message for the aio handler
 600 +       void*           message2,/*!< in: message for the aio handler
 601                                 (can be used to identify a completed
 602                                 aio operation); ignored if mode is
 603                                 OS_AIO_SYNC */
 604 +       trx_t*          trx);
 605  /************************************************************************//**
 606  Wakes up all async i/o threads so that they know to exit themselves in
 607  shutdown. */
 608 diff -ruN a/storage/innobase/include/os0file.ic b/storage/innobase/include/os0file.ic
 609 --- a/storage/innobase/include/os0file.ic       2010-11-03 07:01:13.000000000 +0900
 610 +++ b/storage/innobase/include/os0file.ic       2010-12-03 17:42:42.102024458 +0900
 611 @@ -229,6 +229,7 @@
 612                                 (can be used to identify a completed
 613                                 aio operation); ignored if mode is
 614                                  OS_AIO_SYNC */
 615 +       trx_t*          trx,
 616         const char*     src_file,/*!< in: file name where func invoked */
 617         ulint           src_line)/*!< in: line where the func invoked */
 618  {
 619 @@ -244,7 +245,7 @@
 620                                    src_file, src_line);
 621
 622         result = os_aio_func(type, mode, name, file, buf, offset, offset_high,
 623 -                            n, message1, message2);
 624 +                            n, message1, message2, trx);
 625
 626         register_pfs_file_io_end(locker, n);
 627
 628 @@ -268,6 +269,7 @@
 629         ulint           offset_high,/*!< in: most significant 32 bits of
 630                                 offset */
 631         ulint           n,      /*!< in: number of bytes to read */
 632 +       trx_t*          trx,
 633         const char*     src_file,/*!< in: file name where func invoked */
 634         ulint           src_line)/*!< in: line where the func invoked */
 635  {
 636 @@ -278,7 +280,7 @@
 637         register_pfs_file_io_begin(&state, locker, file, n, PSI_FILE_READ,
 638                                    src_file, src_line);
 639
 640 -       result = os_file_read_func(file, buf, offset, offset_high, n);
 641 +       result = os_file_read_func(file, buf, offset, offset_high, n, trx);
 642
 643         register_pfs_file_io_end(locker, n);
 644
 645 diff -ruN a/storage/innobase/include/srv0srv.h b/storage/innobase/include/srv0srv.h
 646 --- a/storage/innobase/include/srv0srv.h        2010-12-03 17:32:15.634987408 +0900
 647 +++ b/storage/innobase/include/srv0srv.h        2010-12-03 17:42:42.104028644 +0900
 648 @@ -71,6 +71,9 @@
 649  #define SRV_AUTO_EXTEND_INCREMENT      \
 650         (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
 651
 652 +/* prototypes for new functions added to ha_innodb.cc */
 653 +ibool  innobase_get_slow_log();
 654 +
 655  /* This is set to the MySQL server value for this variable. */
 656  extern uint    srv_lower_case_table_names;
 657
 658 diff -ruN a/storage/innobase/include/trx0trx.h b/storage/innobase/include/trx0trx.h
 659 --- a/storage/innobase/include/trx0trx.h        2010-12-03 15:41:52.049372966 +0900
 660 +++ b/storage/innobase/include/trx0trx.h        2010-12-03 17:42:42.107024532 +0900
 661 @@ -738,6 +738,17 @@
 662         /*------------------------------*/
 663         char detailed_error[256];       /*!< detailed error message for last
 664                                         error, or empty. */
 665 +       /*------------------------------*/
 666 +       ulint           io_reads;
 667 +       ib_uint64_t     io_read;
 668 +       ulint           io_reads_wait_timer;
 669 +       ib_uint64_t     lock_que_wait_ustarted;
 670 +       ulint           lock_que_wait_timer;
 671 +       ulint           innodb_que_wait_timer;
 672 +       ulint           distinct_page_access;
 673 +#define        DPAH_SIZE       8192
 674 +       byte*           distinct_page_access_hash;
 675 +       ibool           take_stats;
 676  };
 677
 678  #define TRX_MAX_N_THREADS      32      /* maximum number of
 679 diff -ruN a/storage/innobase/lock/lock0lock.c b/storage/innobase/lock/lock0lock.c
 680 --- a/storage/innobase/lock/lock0lock.c 2010-12-03 15:09:51.297986437 +0900
 681 +++ b/storage/innobase/lock/lock0lock.c 2010-12-03 17:42:42.111024587 +0900
 682 @@ -1755,6 +1755,8 @@
 683  {
 684         lock_t* lock;
 685         trx_t*  trx;
 686 +       ulint   sec;
 687 +       ulint   ms;
 688
 689         ut_ad(mutex_own(&kernel_mutex));
 690
 691 @@ -1813,6 +1815,10 @@
 692         trx->que_state = TRX_QUE_LOCK_WAIT;
 693         trx->was_chosen_as_deadlock_victim = FALSE;
 694         trx->wait_started = time(NULL);
 695 +       if (innobase_get_slow_log() && trx->take_stats) {
 696 +               ut_usectime(&sec, &ms);
 697 +               trx->lock_que_wait_ustarted = (ib_uint64_t)sec * 1000000 + ms;
 698 +       }
 699
 700         ut_a(que_thr_stop(thr));
 701
 702 @@ -3764,6 +3770,8 @@
 703  {
 704         lock_t* lock;
 705         trx_t*  trx;
 706 +       ulint   sec;
 707 +       ulint   ms;
 708
 709         ut_ad(mutex_own(&kernel_mutex));
 710
 711 @@ -3819,6 +3827,10 @@
 712                 return(DB_SUCCESS);
 713         }
 714
 715 +       if (innobase_get_slow_log() && trx->take_stats) {
 716 +               ut_usectime(&sec, &ms);
 717 +               trx->lock_que_wait_ustarted = (ib_uint64_t)sec * 1000000 + ms;
 718 +       }
 719         trx->que_state = TRX_QUE_LOCK_WAIT;
 720         trx->was_chosen_as_deadlock_victim = FALSE;
 721         trx->wait_started = time(NULL);
 722 diff -ruN a/storage/innobase/os/os0file.c b/storage/innobase/os/os0file.c
 723 --- a/storage/innobase/os/os0file.c     2010-12-03 17:32:15.644024974 +0900
 724 +++ b/storage/innobase/os/os0file.c     2010-12-03 17:42:42.117023467 +0900
 725 @@ -43,6 +43,8 @@
 726  #include "srv0start.h"
 727  #include "fil0fil.h"
 728  #include "buf0buf.h"
 729 +#include "trx0sys.h"
 730 +#include "trx0trx.h"
 731  #include "log0recv.h"
 732  #ifndef UNIV_HOTBACKUP
 733  # include "os0sync.h"
 734 @@ -2202,13 +2204,18 @@
 735         ulint           n,      /*!< in: number of bytes to read */
 736         ulint           offset, /*!< in: least significant 32 bits of file
 737                                 offset from where to read */
 738 -       ulint           offset_high) /*!< in: most significant 32 bits of
 739 +       ulint           offset_high, /*!< in: most significant 32 bits of
 740                                 offset */
 741 +       trx_t*          trx)
 742  {
 743         off_t   offs;
 744  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 745         ssize_t n_bytes;
 746  #endif /* HAVE_PREAD && !HAVE_BROKEN_PREAD */
 747 +       ulint           sec;
 748 +       ulint           ms;
 749 +       ib_uint64_t     start_time;
 750 +       ib_uint64_t     finish_time;
 751
 752         ut_a((offset & 0xFFFFFFFFUL) == offset);
 753
 754 @@ -2229,6 +2236,15 @@
 755
 756         os_n_file_reads++;
 757
 758 +       if (innobase_get_slow_log() && trx && trx->take_stats)
 759 +       {
 760 +               trx->io_reads++;
 761 +               trx->io_read += n;
 762 +               ut_usectime(&sec, &ms);
 763 +               start_time = (ib_uint64_t)sec * 1000000 + ms;
 764 +       } else {
 765 +               start_time = 0;
 766 +       }
 767  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 768         os_mutex_enter(os_file_count_mutex);
 769         os_file_n_pending_preads++;
 770 @@ -2242,6 +2258,13 @@
 771         os_n_pending_reads--;
 772         os_mutex_exit(os_file_count_mutex);
 773
 774 +       if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 775 +       {
 776 +               ut_usectime(&sec, &ms);
 777 +               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 778 +               trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 779 +       }
 780 +
 781         return(n_bytes);
 782  #else
 783         {
 784 @@ -2278,6 +2301,13 @@
 785                 os_n_pending_reads--;
 786                 os_mutex_exit(os_file_count_mutex);
 787
 788 +               if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 789 +               {
 790 +                       ut_usectime(&sec, &ms);
 791 +                       finish_time = (ib_uint64_t)sec * 1000000 + ms;
 792 +                       trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 793 +               }
 794 +
 795                 return(ret);
 796         }
 797  #endif
 798 @@ -2418,7 +2448,8 @@
 799                                 offset where to read */
 800         ulint           offset_high, /*!< in: most significant 32 bits of
 801                                 offset */
 802 -       ulint           n)      /*!< in: number of bytes to read */
 803 +       ulint           n,      /*!< in: number of bytes to read */
 804 +       trx_t*          trx)
 805  {
 806  #ifdef __WIN__
 807         BOOL            ret;
 808 @@ -2493,7 +2524,7 @@
 809         os_bytes_read_since_printout += n;
 810
 811  try_again:
 812 -       ret = os_file_pread(file, buf, n, offset, offset_high);
 813 +       ret = os_file_pread(file, buf, n, offset, offset_high, trx);
 814
 815         if ((ulint)ret == n) {
 816
 817 @@ -2622,7 +2653,7 @@
 818         os_bytes_read_since_printout += n;
 819
 820  try_again:
 821 -       ret = os_file_pread(file, buf, n, offset, offset_high);
 822 +       ret = os_file_pread(file, buf, n, offset, offset_high, NULL);
 823
 824         if ((ulint)ret == n) {
 825
 826 @@ -4016,10 +4047,11 @@
 827                                 (can be used to identify a completed
 828                                 aio operation); ignored if mode is
 829                                 OS_AIO_SYNC */
 830 -       void*           message2)/*!< in: message for the aio handler
 831 +       void*           message2,/*!< in: message for the aio handler
 832                                 (can be used to identify a completed
 833                                 aio operation); ignored if mode is
 834                                 OS_AIO_SYNC */
 835 +       trx_t*          trx)
 836  {
 837         os_aio_array_t* array;
 838         os_aio_slot_t*  slot;
 839 @@ -4060,8 +4092,8 @@
 840                 wait in the Windows case. */
 841
 842                 if (type == OS_FILE_READ) {
 843 -                       return(os_file_read(file, buf, offset,
 844 -                                           offset_high, n));
 845 +                       return(os_file_read_trx(file, buf, offset,
 846 +                                           offset_high, n, trx));
 847                 }
 848
 849                 ut_a(type == OS_FILE_WRITE);
 850 @@ -4099,6 +4131,11 @@
 851                 ut_error;
 852         }
 853
 854 +       if (trx && type == OS_FILE_READ)
 855 +       {
 856 +               trx->io_reads++;
 857 +               trx->io_read += n;
 858 +       }
 859         slot = os_aio_array_reserve_slot(type, array, message1, message2, file,
 860                                          name, buf, offset, offset_high, n);
 861         if (type == OS_FILE_READ) {
 862 diff -ruN a/storage/innobase/srv/srv0srv.c b/storage/innobase/srv/srv0srv.c
 863 --- a/storage/innobase/srv/srv0srv.c    2010-12-03 17:32:15.648024399 +0900
 864 +++ b/storage/innobase/srv/srv0srv.c    2010-12-03 17:45:05.067023254 +0900
 865 @@ -88,6 +88,9 @@
 866  #include "mysql/plugin.h"
 867  #include "mysql/service_thd_wait.h"
 868
 869 +/* prototypes for new functions added to ha_innodb.cc */
 870 +ibool  innobase_get_slow_log();
 871 +
 872  /* This is set to the MySQL server value for this variable.  It is only
 873  needed for FOREIGN KEY definition parsing since FOREIGN KEY names are not
 874  stored in the server metadata. The server stores and enforces it for
 875 @@ -1259,6 +1262,10 @@
 876         ibool                   has_slept = FALSE;
 877         srv_conc_slot_t*        slot      = NULL;
 878         ulint                   i;
 879 +       ib_uint64_t             start_time = 0L;
 880 +       ib_uint64_t             finish_time = 0L;
 881 +       ulint                   sec;
 882 +       ulint                   ms;
 883
 884         if (trx->mysql_thd != NULL
 885             && thd_is_replication_slave_thread(trx->mysql_thd)) {
 886 @@ -1335,6 +1342,7 @@
 887                 switches. */
 888                 if (SRV_THREAD_SLEEP_DELAY > 0) {
 889                         os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
 890 +                       trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
 891                 }
 892
 893                 trx->op_info = "";
 894 @@ -1390,6 +1398,13 @@
 895         /* Go to wait for the event; when a thread leaves InnoDB it will
 896         release this thread */
 897
 898 +       if (innobase_get_slow_log() && trx->take_stats) {
 899 +               ut_usectime(&sec, &ms);
 900 +               start_time = (ib_uint64_t)sec * 1000000 + ms;
 901 +       } else {
 902 +               start_time = 0;
 903 +       }
 904 +
 905         trx->op_info = "waiting in InnoDB queue";
 906
 907         thd_wait_begin(trx->mysql_thd, THD_WAIT_ROW_TABLE_LOCK);
 908 @@ -1398,6 +1413,12 @@
 909
 910         trx->op_info = "";
 911
 912 +       if (innobase_get_slow_log() && trx->take_stats && start_time) {
 913 +               ut_usectime(&sec, &ms);
 914 +               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 915 +               trx->innodb_que_wait_timer += (ulint)(finish_time - start_time);
 916 +       }
 917 +
 918         os_fast_mutex_lock(&srv_conc_mutex);
 919
 920         srv_conc_n_waiting_threads--;
 921 diff -ruN a/storage/innobase/trx/trx0trx.c b/storage/innobase/trx/trx0trx.c
 922 --- a/storage/innobase/trx/trx0trx.c    2010-12-03 15:41:52.053955669 +0900
 923 +++ b/storage/innobase/trx/trx0trx.c    2010-12-03 17:42:42.127023410 +0900
 924 @@ -186,6 +186,15 @@
 925         trx->global_read_view = NULL;
 926         trx->read_view = NULL;
 927
 928 +       trx->io_reads = 0;
 929 +       trx->io_read = 0;
 930 +       trx->io_reads_wait_timer = 0;
 931 +       trx->lock_que_wait_timer = 0;
 932 +       trx->innodb_que_wait_timer = 0;
 933 +       trx->distinct_page_access = 0;
 934 +       trx->distinct_page_access_hash = NULL;
 935 +       trx->take_stats = FALSE;
 936 +
 937         /* Set X/Open XA transaction identification to NULL */
 938         memset(&trx->xid, 0, sizeof(trx->xid));
 939         trx->xid.formatID = -1;
 940 @@ -223,6 +232,11 @@
 941
 942         trx->mysql_process_no = os_proc_get_number();
 943
 944 +       if (innobase_get_slow_log() && trx->take_stats) {
 945 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
 946 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
 947 +       }
 948 +
 949         return(trx);
 950  }
 951
 952 @@ -354,6 +368,12 @@
 953  /*===============*/
 954         trx_t*  trx)    /*!< in, own: trx object */
 955  {
 956 +       if (trx->distinct_page_access_hash)
 957 +       {
 958 +               mem_free(trx->distinct_page_access_hash);
 959 +               trx->distinct_page_access_hash= NULL;
 960 +       }
 961 +
 962         mutex_enter(&kernel_mutex);
 963
 964         UT_LIST_REMOVE(mysql_trx_list, trx_sys->mysql_trx_list, trx);
 965 @@ -375,6 +395,12 @@
 966  /*====================*/
 967         trx_t*  trx)    /*!< in, own: trx object */
 968  {
 969 +       if (trx->distinct_page_access_hash)
 970 +       {
 971 +               mem_free(trx->distinct_page_access_hash);
 972 +               trx->distinct_page_access_hash= NULL;
 973 +       }
 974 +
 975         mutex_enter(&kernel_mutex);
 976
 977         trx_free(trx);
 978 @@ -1153,6 +1179,9 @@
 979         trx_t*  trx)    /*!< in: transaction */
 980  {
 981         que_thr_t*      thr;
 982 +       ulint           sec;
 983 +       ulint           ms;
 984 +       ib_uint64_t     now;
 985
 986         ut_ad(mutex_own(&kernel_mutex));
 987         ut_ad(trx->que_state == TRX_QUE_LOCK_WAIT);
 988 @@ -1167,6 +1196,11 @@
 989                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
 990         }
 991
 992 +       if (innobase_get_slow_log() && trx->take_stats) {
 993 +               ut_usectime(&sec, &ms);
 994 +               now = (ib_uint64_t)sec * 1000000 + ms;
 995 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
 996 +       }
 997         trx->que_state = TRX_QUE_RUNNING;
 998  }
 999
1000 @@ -1180,6 +1214,9 @@
1001         trx_t*  trx)    /*!< in: transaction in the TRX_QUE_LOCK_WAIT state */
1002  {
1003         que_thr_t*      thr;
1004 +       ulint           sec;
1005 +       ulint           ms;
1006 +       ib_uint64_t     now;
1007
1008         ut_ad(mutex_own(&kernel_mutex));
1009         ut_ad(trx->que_state == TRX_QUE_LOCK_WAIT);
1010 @@ -1194,6 +1231,11 @@
1011                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
1012         }
1013
1014 +       if (innobase_get_slow_log() && trx->take_stats) {
1015 +               ut_usectime(&sec, &ms);
1016 +               now = (ib_uint64_t)sec * 1000000 + ms;
1017 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
1018 +       }
1019         trx->que_state = TRX_QUE_RUNNING;
1020  }
1021