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 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 < 0 || 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 < 0 || 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 @@ -2499,6 +2541,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 @@ -2513,6 +2562,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 @@ -2825,6 +2880,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  #ifndef UNIV_LOG_DEBUG
 122         ut_ad(!ibuf_inside() || ibuf_page(space, zip_size, offset, 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 @@ -3178,6 +3241,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 @@ -3192,6 +3262,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 @@ -3217,13 +3293,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 @@ -3247,6 +3327,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 @@ -3324,13 +3405,17 @@
 194  #ifdef UNIV_DEBUG_FILE_ACCESSES
 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 @@ -3340,6 +3425,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 @@ -3362,6 +3450,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 @@ -3448,6 +3537,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 @@ -4349,7 +4349,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 @@ -4676,7 +4676,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 @@ -4701,8 +4701,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 @@ -4872,7 +4873,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 @@ -1528,6 +1528,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 @@ -1583,6 +1593,32 @@
 400  }
 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  Construct ha_innobase handler. */
 431  UNIV_INTERN
 432 @@ -9179,6 +9215,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/handler/innodb_patch_info.h b/storage/innobase/handler/innodb_patch_info.h
 459 --- a/storage/innobase/handler/innodb_patch_info.h      2010-12-03 17:36:44.293955189 +0900
 460 +++ b/storage/innobase/handler/innodb_patch_info.h      2010-12-03 17:42:42.094955866 +0900
 461 @@ -38,5 +38,6 @@
 462  {"innodb_recovery_patches","Bugfixes and adjustments about recovery process","","http://www.percona.com/docs/wiki/percona-xtradb"},
 463  {"innodb_admin_command_base","XtraDB specific command interface through i_s","","http://www.percona.com/docs/wiki/percona-xtradb"},
 464  {"innodb_show_lock_name","Show mutex/lock name instead of crated file/line","","http://www.percona.com/docs/wiki/percona-xtradb"},
 465 +{"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"},
 466  {NULL, NULL, NULL, NULL}
 467  };
 468 diff -ruN a/storage/innobase/include/buf0rea.h b/storage/innobase/include/buf0rea.h
 469 --- a/storage/innobase/include/buf0rea.h        2010-12-03 15:18:48.891024406 +0900
 470 +++ b/storage/innobase/include/buf0rea.h        2010-12-03 17:42:42.096026873 +0900
 471 @@ -27,6 +27,7 @@
 472  #define buf0rea_h
 473
 474  #include "univ.i"
 475 +#include "trx0types.h"
 476  #include "buf0types.h"
 477
 478  /********************************************************************//**
 479 @@ -41,7 +42,8 @@
 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 */
 484 +       ulint   offset, /*!< in: page number */
 485 +       trx_t*  trx);
 486  /********************************************************************//**
 487  Applies linear read-ahead if in the buf_pool the page is a border page of
 488  a linear read-ahead area and all the pages in the area have been accessed.
 489 @@ -72,8 +74,9 @@
 490  /*==================*/
 491         ulint   space,  /*!< in: space id */
 492         ulint   zip_size,/*!< in: compressed page size in bytes, or 0 */
 493 -       ulint   offset);/*!< in: page number of a page; NOTE: the current thread
 494 +       ulint   offset, /*!< in: page number of a page; NOTE: the current thread
 495                         must want access to this page (see NOTE 3 above) */
 496 +       trx_t*  trx);
 497  /********************************************************************//**
 498  Issues read requests for pages which the ibuf module wants to read in, in
 499  order to contract the insert buffer tree. Technically, this function is like
 500 diff -ruN a/storage/innobase/include/fil0fil.h b/storage/innobase/include/fil0fil.h
 501 --- a/storage/innobase/include/fil0fil.h        2010-12-03 15:09:51.290958543 +0900
 502 +++ b/storage/innobase/include/fil0fil.h        2010-12-03 17:42:42.097027548 +0900
 503 @@ -611,9 +611,12 @@
 504  Reads or writes data. This operation is asynchronous (aio).
 505  @return DB_SUCCESS, or DB_TABLESPACE_DELETED if we are trying to do
 506  i/o on a tablespace which does not exist */
 507 +#define fil_io(type, sync, space_id, zip_size, block_offset, byte_offset, len, buf, message) \
 508 +       _fil_io(type, sync, space_id, zip_size, block_offset, byte_offset, len, buf, message, NULL)
 509 +
 510  UNIV_INTERN
 511  ulint
 512 -fil_io(
 513 +_fil_io(
 514  /*===*/
 515         ulint   type,           /*!< in: OS_FILE_READ or OS_FILE_WRITE,
 516                                 ORed to OS_FILE_LOG, if a log i/o
 517 @@ -638,8 +641,9 @@
 518         void*   buf,            /*!< in/out: buffer where to store read data
 519                                 or from where to write; in aio this must be
 520                                 appropriately aligned */
 521 -       void*   message);       /*!< in: message for aio handler if non-sync
 522 +       void*   message,        /*!< in: message for aio handler if non-sync
 523                                 aio used, else ignored */
 524 +       trx_t*  trx);
 525  /**********************************************************************//**
 526  Waits for an aio operation to complete. This function is used to write the
 527  handler for completed requests. The aio array of pending requests is divided
 528 diff -ruN a/storage/innobase/include/os0file.h b/storage/innobase/include/os0file.h
 529 --- a/storage/innobase/include/os0file.h        2010-11-03 07:01:13.000000000 +0900
 530 +++ b/storage/innobase/include/os0file.h        2010-12-03 17:42:42.100023783 +0900
 531 @@ -36,6 +36,7 @@
 532  #define os0file_h
 533
 534  #include "univ.i"
 535 +#include "trx0types.h"
 536
 537  #ifndef __WIN__
 538  #include <dirent.h>
 539 @@ -277,13 +278,17 @@
 540         pfs_os_file_close_func(file, __FILE__, __LINE__)
 541
 542  # define os_aio(type, mode, name, file, buf, offset, offset_high,      \
 543 -               n, message1, message2)                                  \
 544 +               n, message1, message2, trx)                             \
 545         pfs_os_aio_func(type, mode, name, file, buf, offset,            \
 546 -                       offset_high, n, message1, message2,             \
 547 +                       offset_high, n, message1, message2, trx,        \
 548                         __FILE__, __LINE__)
 549
 550  # define os_file_read(file, buf, offset, offset_high, n)               \
 551 -       pfs_os_file_read_func(file, buf, offset, offset_high, n,        \
 552 +       pfs_os_file_read_func(file, buf, offset, offset_high, n, NULL,  \
 553 +                             __FILE__, __LINE__)
 554 +
 555 +# define os_file_read_trx(file, buf, offset, offset_high, n, trx)      \
 556 +       pfs_os_file_read_func(file, buf, offset, offset_high, n, trx,   \
 557                               __FILE__, __LINE__)
 558
 559  # define os_file_read_no_error_handling(file, buf, offset,             \
 560 @@ -319,12 +324,15 @@
 561  # define os_file_close(file)   os_file_close_func(file)
 562
 563  # define os_aio(type, mode, name, file, buf, offset, offset_high,      \
 564 -              n, message1, message2)                                   \
 565 +              n, message1, message2, trx)                              \
 566         os_aio_func(type, mode, name, file, buf, offset, offset_high, n,\
 567 -                   message1, message2)
 568 +                   message1, message2, trx)
 569
 570  # define os_file_read(file, buf, offset, offset_high, n)               \
 571 -       os_file_read_func(file, buf, offset, offset_high, n)
 572 +       os_file_read_func(file, buf, offset, offset_high, n, NULL)
 573 +
 574 +# define os_file_read_trx(file, buf, offset, offset_high, n, trx)      \
 575 +       os_file_read_func(file, buf, offset, offset_high, n, trx)
 576
 577  # define os_file_read_no_error_handling(file, buf, offset,             \
 578                                        offset_high, n)                  \
 579 @@ -690,6 +698,7 @@
 580         ulint           offset_high,/*!< in: most significant 32 bits of
 581                                 offset */
 582         ulint           n,      /*!< in: number of bytes to read */
 583 +       trx_t*          trx,
 584         const char*     src_file,/*!< in: file name where func invoked */
 585         ulint           src_line);/*!< in: line where the func invoked */
 586
 587 @@ -744,6 +753,7 @@
 588                                 (can be used to identify a completed
 589                                 aio operation); ignored if mode is
 590                                  OS_AIO_SYNC */
 591 +       trx_t*          trx,
 592         const char*     src_file,/*!< in: file name where func invoked */
 593         ulint           src_line);/*!< in: line where the func invoked */
 594  /*******************************************************************//**
 595 @@ -885,7 +895,8 @@
 596                                 offset where to read */
 597         ulint           offset_high,/*!< in: most significant 32 bits of
 598                                 offset */
 599 -       ulint           n);     /*!< in: number of bytes to read */
 600 +       ulint           n,      /*!< in: number of bytes to read */
 601 +       trx_t*          trx);
 602  /*******************************************************************//**
 603  Rewind file to its start, read at most size - 1 bytes from it to str, and
 604  NUL-terminate str. All errors are silently ignored. This function is
 605 @@ -1044,10 +1055,11 @@
 606                                 (can be used to identify a completed
 607                                 aio operation); ignored if mode is
 608                                 OS_AIO_SYNC */
 609 -       void*           message2);/*!< in: message for the aio handler
 610 +       void*           message2,/*!< in: message for the aio handler
 611                                 (can be used to identify a completed
 612                                 aio operation); ignored if mode is
 613                                 OS_AIO_SYNC */
 614 +       trx_t*          trx);
 615  /************************************************************************//**
 616  Wakes up all async i/o threads so that they know to exit themselves in
 617  shutdown. */
 618 diff -ruN a/storage/innobase/include/os0file.ic b/storage/innobase/include/os0file.ic
 619 --- a/storage/innobase/include/os0file.ic       2010-11-03 07:01:13.000000000 +0900
 620 +++ b/storage/innobase/include/os0file.ic       2010-12-03 17:42:42.102024458 +0900
 621 @@ -229,6 +229,7 @@
 622                                 (can be used to identify a completed
 623                                 aio operation); ignored if mode is
 624                                  OS_AIO_SYNC */
 625 +       trx_t*          trx,
 626         const char*     src_file,/*!< in: file name where func invoked */
 627         ulint           src_line)/*!< in: line where the func invoked */
 628  {
 629 @@ -244,7 +245,7 @@
 630                                    src_file, src_line);
 631
 632         result = os_aio_func(type, mode, name, file, buf, offset, offset_high,
 633 -                            n, message1, message2);
 634 +                            n, message1, message2, trx);
 635
 636         register_pfs_file_io_end(locker, n);
 637
 638 @@ -268,6 +269,7 @@
 639         ulint           offset_high,/*!< in: most significant 32 bits of
 640                                 offset */
 641         ulint           n,      /*!< in: number of bytes to read */
 642 +       trx_t*          trx,
 643         const char*     src_file,/*!< in: file name where func invoked */
 644         ulint           src_line)/*!< in: line where the func invoked */
 645  {
 646 @@ -278,7 +280,7 @@
 647         register_pfs_file_io_begin(&state, locker, file, n, PSI_FILE_READ,
 648                                    src_file, src_line);
 649
 650 -       result = os_file_read_func(file, buf, offset, offset_high, n);
 651 +       result = os_file_read_func(file, buf, offset, offset_high, n, trx);
 652
 653         register_pfs_file_io_end(locker, n);
 654
 655 diff -ruN a/storage/innobase/include/srv0srv.h b/storage/innobase/include/srv0srv.h
 656 --- a/storage/innobase/include/srv0srv.h        2010-12-03 17:32:15.634987408 +0900
 657 +++ b/storage/innobase/include/srv0srv.h        2010-12-03 17:42:42.104028644 +0900
 658 @@ -62,6 +62,9 @@
 659  #define SRV_AUTO_EXTEND_INCREMENT      \
 660         (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
 661
 662 +/* prototypes for new functions added to ha_innodb.cc */
 663 +ibool  innobase_get_slow_log();
 664 +
 665  /* This is set to TRUE if the MySQL user has set it in MySQL */
 666  extern ibool   srv_lower_case_table_names;
 667
 668 diff -ruN a/storage/innobase/include/trx0trx.h b/storage/innobase/include/trx0trx.h
 669 --- a/storage/innobase/include/trx0trx.h        2010-12-03 15:41:52.049372966 +0900
 670 +++ b/storage/innobase/include/trx0trx.h        2010-12-03 17:42:42.107024532 +0900
 671 @@ -728,6 +728,17 @@
 672         /*------------------------------*/
 673         char detailed_error[256];       /*!< detailed error message for last
 674                                         error, or empty. */
 675 +       /*------------------------------*/
 676 +       ulint           io_reads;
 677 +       ib_uint64_t     io_read;
 678 +       ulint           io_reads_wait_timer;
 679 +       ib_uint64_t     lock_que_wait_ustarted;
 680 +       ulint           lock_que_wait_timer;
 681 +       ulint           innodb_que_wait_timer;
 682 +       ulint           distinct_page_access;
 683 +#define        DPAH_SIZE       8192
 684 +       byte*           distinct_page_access_hash;
 685 +       ibool           take_stats;
 686  };
 687
 688  #define TRX_MAX_N_THREADS      32      /* maximum number of
 689 diff -ruN a/storage/innobase/lock/lock0lock.c b/storage/innobase/lock/lock0lock.c
 690 --- a/storage/innobase/lock/lock0lock.c 2010-12-03 15:09:51.297986437 +0900
 691 +++ b/storage/innobase/lock/lock0lock.c 2010-12-03 17:42:42.111024587 +0900
 692 @@ -1755,6 +1755,8 @@
 693  {
 694         lock_t* lock;
 695         trx_t*  trx;
 696 +       ulint   sec;
 697 +       ulint   ms;
 698
 699         ut_ad(mutex_own(&kernel_mutex));
 700
 701 @@ -1813,6 +1815,10 @@
 702         trx->que_state = TRX_QUE_LOCK_WAIT;
 703         trx->was_chosen_as_deadlock_victim = FALSE;
 704         trx->wait_started = time(NULL);
 705 +       if (innobase_get_slow_log() && trx->take_stats) {
 706 +               ut_usectime(&sec, &ms);
 707 +               trx->lock_que_wait_ustarted = (ib_uint64_t)sec * 1000000 + ms;
 708 +       }
 709
 710         ut_a(que_thr_stop(thr));
 711
 712 @@ -3692,6 +3698,8 @@
 713  {
 714         lock_t* lock;
 715         trx_t*  trx;
 716 +       ulint   sec;
 717 +       ulint   ms;
 718
 719         ut_ad(mutex_own(&kernel_mutex));
 720
 721 @@ -3747,6 +3755,10 @@
 722                 return(DB_SUCCESS);
 723         }
 724
 725 +       if (innobase_get_slow_log() && trx->take_stats) {
 726 +               ut_usectime(&sec, &ms);
 727 +               trx->lock_que_wait_ustarted = (ib_uint64_t)sec * 1000000 + ms;
 728 +       }
 729         trx->que_state = TRX_QUE_LOCK_WAIT;
 730         trx->was_chosen_as_deadlock_victim = FALSE;
 731         trx->wait_started = time(NULL);
 732 diff -ruN a/storage/innobase/os/os0file.c b/storage/innobase/os/os0file.c
 733 --- a/storage/innobase/os/os0file.c     2010-12-03 17:32:15.644024974 +0900
 734 +++ b/storage/innobase/os/os0file.c     2010-12-03 17:42:42.117023467 +0900
 735 @@ -43,6 +43,8 @@
 736  #include "srv0start.h"
 737  #include "fil0fil.h"
 738  #include "buf0buf.h"
 739 +#include "trx0sys.h"
 740 +#include "trx0trx.h"
 741  #include "log0recv.h"
 742  #ifndef UNIV_HOTBACKUP
 743  # include "os0sync.h"
 744 @@ -2175,13 +2177,18 @@
 745         ulint           n,      /*!< in: number of bytes to read */
 746         ulint           offset, /*!< in: least significant 32 bits of file
 747                                 offset from where to read */
 748 -       ulint           offset_high) /*!< in: most significant 32 bits of
 749 +       ulint           offset_high, /*!< in: most significant 32 bits of
 750                                 offset */
 751 +       trx_t*          trx)
 752  {
 753         off_t   offs;
 754  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 755         ssize_t n_bytes;
 756  #endif /* HAVE_PREAD && !HAVE_BROKEN_PREAD */
 757 +       ulint           sec;
 758 +       ulint           ms;
 759 +       ib_uint64_t     start_time;
 760 +       ib_uint64_t     finish_time;
 761
 762         ut_a((offset & 0xFFFFFFFFUL) == offset);
 763
 764 @@ -2202,6 +2209,15 @@
 765
 766         os_n_file_reads++;
 767
 768 +       if (innobase_get_slow_log() && trx && trx->take_stats)
 769 +       {
 770 +               trx->io_reads++;
 771 +               trx->io_read += n;
 772 +               ut_usectime(&sec, &ms);
 773 +               start_time = (ib_uint64_t)sec * 1000000 + ms;
 774 +       } else {
 775 +               start_time = 0;
 776 +       }
 777  #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
 778         os_mutex_enter(os_file_count_mutex);
 779         os_file_n_pending_preads++;
 780 @@ -2215,6 +2231,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(n_bytes);
 792  #else
 793         {
 794 @@ -2251,6 +2274,13 @@
 795                 os_n_pending_reads--;
 796                 os_mutex_exit(os_file_count_mutex);
 797
 798 +               if (innobase_get_slow_log() && trx && trx->take_stats && start_time)
 799 +               {
 800 +                       ut_usectime(&sec, &ms);
 801 +                       finish_time = (ib_uint64_t)sec * 1000000 + ms;
 802 +                       trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
 803 +               }
 804 +
 805                 return(ret);
 806         }
 807  #endif
 808 @@ -2391,7 +2421,8 @@
 809                                 offset where to read */
 810         ulint           offset_high, /*!< in: most significant 32 bits of
 811                                 offset */
 812 -       ulint           n)      /*!< in: number of bytes to read */
 813 +       ulint           n,      /*!< in: number of bytes to read */
 814 +       trx_t*          trx)
 815  {
 816  #ifdef __WIN__
 817         BOOL            ret;
 818 @@ -2463,7 +2494,7 @@
 819         os_bytes_read_since_printout += n;
 820
 821  try_again:
 822 -       ret = os_file_pread(file, buf, n, offset, offset_high);
 823 +       ret = os_file_pread(file, buf, n, offset, offset_high, trx);
 824
 825         if ((ulint)ret == n) {
 826
 827 @@ -2589,7 +2620,7 @@
 828         os_bytes_read_since_printout += n;
 829
 830  try_again:
 831 -       ret = os_file_pread(file, buf, n, offset, offset_high);
 832 +       ret = os_file_pread(file, buf, n, offset, offset_high, NULL);
 833
 834         if ((ulint)ret == n) {
 835
 836 @@ -3608,7 +3639,8 @@
 837                                 offset */
 838         ulint           offset_high, /*!< in: most significant 32 bits of
 839                                 offset */
 840 -       ulint           len)    /*!< in: length of the block to read or write */
 841 +       ulint           len,    /*!< in: length of the block to read or write */
 842 +       trx_t*          trx)
 843  {
 844         os_aio_slot_t*  slot = NULL;
 845  #ifdef WIN_ASYNC_IO
 846 @@ -3976,10 +4008,11 @@
 847                                 (can be used to identify a completed
 848                                 aio operation); ignored if mode is
 849                                 OS_AIO_SYNC */
 850 -       void*           message2)/*!< in: message for the aio handler
 851 +       void*           message2,/*!< in: message for the aio handler
 852                                 (can be used to identify a completed
 853                                 aio operation); ignored if mode is
 854                                 OS_AIO_SYNC */
 855 +       trx_t*          trx)
 856  {
 857         os_aio_array_t* array;
 858         os_aio_slot_t*  slot;
 859 @@ -4017,8 +4050,8 @@
 860                 wait in the Windows case. */
 861
 862                 if (type == OS_FILE_READ) {
 863 -                       return(os_file_read(file, buf, offset,
 864 -                                           offset_high, n));
 865 +                       return(os_file_read_trx(file, buf, offset,
 866 +                                           offset_high, n, trx));
 867                 }
 868
 869                 ut_a(type == OS_FILE_WRITE);
 870 @@ -4056,8 +4089,13 @@
 871                 ut_error;
 872         }
 873
 874 +       if (trx && type == OS_FILE_READ)
 875 +       {
 876 +               trx->io_reads++;
 877 +               trx->io_read += n;
 878 +       }
 879         slot = os_aio_array_reserve_slot(type, array, message1, message2, file,
 880 -                                        name, buf, offset, offset_high, n);
 881 +                                        name, buf, offset, offset_high, n, trx);
 882         if (type == OS_FILE_READ) {
 883                 if (srv_use_native_aio) {
 884                         os_n_file_reads++;
 885 diff -ruN a/storage/innobase/srv/srv0srv.c b/storage/innobase/srv/srv0srv.c
 886 --- a/storage/innobase/srv/srv0srv.c    2010-12-03 17:32:15.648024399 +0900
 887 +++ b/storage/innobase/srv/srv0srv.c    2010-12-03 17:45:05.067023254 +0900
 888 @@ -87,6 +87,9 @@
 889  #include "mysql/plugin.h"
 890  #include "mysql/service_thd_wait.h"
 891
 892 +/* prototypes for new functions added to ha_innodb.cc */
 893 +ibool  innobase_get_slow_log();
 894 +
 895  /* This is set to TRUE if the MySQL user has set it in MySQL; currently
 896  affects only FOREIGN KEY definition parsing */
 897  UNIV_INTERN ibool      srv_lower_case_table_names      = FALSE;
 898 @@ -1204,6 +1207,10 @@
 899         ibool                   has_slept = FALSE;
 900         srv_conc_slot_t*        slot      = NULL;
 901         ulint                   i;
 902 +       ib_uint64_t             start_time = 0L;
 903 +       ib_uint64_t             finish_time = 0L;
 904 +       ulint                   sec;
 905 +       ulint                   ms;
 906
 907         if (trx->mysql_thd != NULL
 908             && thd_is_replication_slave_thread(trx->mysql_thd)) {
 909 @@ -1280,6 +1287,7 @@
 910                 switches. */
 911                 if (SRV_THREAD_SLEEP_DELAY > 0) {
 912                         os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
 913 +                       trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
 914                 }
 915
 916                 trx->op_info = "";
 917 @@ -1335,6 +1343,13 @@
 918         /* Go to wait for the event; when a thread leaves InnoDB it will
 919         release this thread */
 920
 921 +       if (innobase_get_slow_log() && trx->take_stats) {
 922 +               ut_usectime(&sec, &ms);
 923 +               start_time = (ib_uint64_t)sec * 1000000 + ms;
 924 +       } else {
 925 +               start_time = 0;
 926 +       }
 927 +
 928         trx->op_info = "waiting in InnoDB queue";
 929
 930         thd_wait_begin(trx->mysql_thd, THD_WAIT_ROW_TABLE_LOCK);
 931 @@ -1343,6 +1358,12 @@
 932
 933         trx->op_info = "";
 934
 935 +       if (innobase_get_slow_log() && trx->take_stats && start_time) {
 936 +               ut_usectime(&sec, &ms);
 937 +               finish_time = (ib_uint64_t)sec * 1000000 + ms;
 938 +               trx->innodb_que_wait_timer += (ulint)(finish_time - start_time);
 939 +       }
 940 +
 941         os_fast_mutex_lock(&srv_conc_mutex);
 942
 943         srv_conc_n_waiting_threads--;
 944 diff -ruN a/storage/innobase/trx/trx0trx.c b/storage/innobase/trx/trx0trx.c
 945 --- a/storage/innobase/trx/trx0trx.c    2010-12-03 15:41:52.053955669 +0900
 946 +++ b/storage/innobase/trx/trx0trx.c    2010-12-03 17:42:42.127023410 +0900
 947 @@ -184,6 +184,15 @@
 948         trx->global_read_view = NULL;
 949         trx->read_view = NULL;
 950
 951 +       trx->io_reads = 0;
 952 +       trx->io_read = 0;
 953 +       trx->io_reads_wait_timer = 0;
 954 +       trx->lock_que_wait_timer = 0;
 955 +       trx->innodb_que_wait_timer = 0;
 956 +       trx->distinct_page_access = 0;
 957 +       trx->distinct_page_access_hash = NULL;
 958 +       trx->take_stats = FALSE;
 959 +
 960         /* Set X/Open XA transaction identification to NULL */
 961         memset(&trx->xid, 0, sizeof(trx->xid));
 962         trx->xid.formatID = -1;
 963 @@ -221,6 +230,11 @@
 964
 965         trx->mysql_process_no = os_proc_get_number();
 966
 967 +       if (innobase_get_slow_log() && trx->take_stats) {
 968 +               trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
 969 +               memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
 970 +       }
 971 +
 972         return(trx);
 973  }
 974
 975 @@ -352,6 +366,12 @@
 976  /*===============*/
 977         trx_t*  trx)    /*!< in, own: trx object */
 978  {
 979 +       if (trx->distinct_page_access_hash)
 980 +       {
 981 +               mem_free(trx->distinct_page_access_hash);
 982 +               trx->distinct_page_access_hash= NULL;
 983 +       }
 984 +
 985         mutex_enter(&kernel_mutex);
 986
 987         UT_LIST_REMOVE(mysql_trx_list, trx_sys->mysql_trx_list, trx);
 988 @@ -373,6 +393,12 @@
 989  /*====================*/
 990         trx_t*  trx)    /*!< in, own: trx object */
 991  {
 992 +       if (trx->distinct_page_access_hash)
 993 +       {
 994 +               mem_free(trx->distinct_page_access_hash);
 995 +               trx->distinct_page_access_hash= NULL;
 996 +       }
 997 +
 998         mutex_enter(&kernel_mutex);
 999
1000         trx_free(trx);
1001 @@ -1094,6 +1120,9 @@
1002         trx_t*  trx)    /*!< in: transaction */
1003  {
1004         que_thr_t*      thr;
1005 +       ulint           sec;
1006 +       ulint           ms;
1007 +       ib_uint64_t     now;
1008
1009         ut_ad(mutex_own(&kernel_mutex));
1010         ut_ad(trx->que_state == TRX_QUE_LOCK_WAIT);
1011 @@ -1108,6 +1137,11 @@
1012                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
1013         }
1014
1015 +       if (innobase_get_slow_log() && trx->take_stats) {
1016 +               ut_usectime(&sec, &ms);
1017 +               now = (ib_uint64_t)sec * 1000000 + ms;
1018 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
1019 +       }
1020         trx->que_state = TRX_QUE_RUNNING;
1021  }
1022
1023 @@ -1121,6 +1155,9 @@
1024         trx_t*  trx)    /*!< in: transaction in the TRX_QUE_LOCK_WAIT state */
1025  {
1026         que_thr_t*      thr;
1027 +       ulint           sec;
1028 +       ulint           ms;
1029 +       ib_uint64_t     now;
1030
1031         ut_ad(mutex_own(&kernel_mutex));
1032         ut_ad(trx->que_state == TRX_QUE_LOCK_WAIT);
1033 @@ -1135,6 +1172,11 @@
1034                 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
1035         }
1036
1037 +       if (innobase_get_slow_log() && trx->take_stats) {
1038 +               ut_usectime(&sec, &ms);
1039 +               now = (ib_uint64_t)sec * 1000000 + ms;
1040 +               trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
1041 +       }
1042         trx->que_state = TRX_QUE_RUNNING;
1043  }
1044