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