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