1 diff -r 1242d4575291 include/my_getopt.h
2 --- a/include/my_getopt.h Tue Jul 28 23:39:12 2009 -0700
3 +++ b/include/my_getopt.h Tue Jul 28 23:42:44 2009 -0700
7 #define GET_STR_ALLOC 10
8 -#define GET_DISABLED 11
9 +#define GET_MICROTIME 11
10 +#define GET_DISABLED 12
12 #define GET_ASK_ADDR 128
13 #define GET_TYPE_MASK 127
14 diff -r 1242d4575291 include/my_time.h
15 --- a/include/my_time.h Tue Jul 28 23:39:12 2009 -0700
16 +++ b/include/my_time.h Tue Jul 28 23:42:44 2009 -0700
18 int my_date_to_str(const MYSQL_TIME *l_time, char *to);
19 int my_datetime_to_str(const MYSQL_TIME *l_time, char *to);
20 int my_TIME_to_str(const MYSQL_TIME *l_time, char *to);
22 +ulonglong my_timer(ulonglong *ltime, ulonglong frequency);
25 #endif /* _my_time_h_ */
26 diff -r 1242d4575291 innobase/buf/buf0buf.c
27 --- a/innobase/buf/buf0buf.c Tue Jul 28 23:39:12 2009 -0700
28 +++ b/innobase/buf/buf0buf.c Tue Jul 28 23:42:44 2009 -0700
35 +/* prototypes for new functions added to ha_innodb.cc */
36 +trx_t* innobase_get_trx();
39 IMPLEMENTATION OF THE BUFFER POOL
40 @@ -1086,6 +1090,36 @@
44 +inline void _increment_page_get_statistics(buf_block_t* block, trx_t* trx)
47 + ulint block_hash_byte;
48 + byte block_hash_offset;
52 + if (!srv_slow_log || !trx || !trx->take_stats)
55 + if (!trx->distinct_page_access_hash) {
56 + trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
57 + memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
60 + block_hash = ut_hash_ulint((block->space << 20) + block->space +
61 + block->offset, DPAH_SIZE << 3);
62 + block_hash_byte = block_hash >> 3;
63 + block_hash_offset = (byte) block_hash & 0x07;
64 + if (block_hash_byte < 0 || block_hash_byte >= DPAH_SIZE)
65 + fprintf(stderr, "!!! block_hash_byte = %lu block_hash_offset = %lu !!!\n", block_hash_byte, block_hash_offset);
66 + if (block_hash_offset < 0 || block_hash_offset > 7)
67 + fprintf(stderr, "!!! block_hash_byte = %lu block_hash_offset = %lu !!!\n", block_hash_byte, block_hash_offset);
68 + if ((trx->distinct_page_access_hash[block_hash_byte] & ((byte) 0x01 << block_hash_offset)) == 0)
69 + trx->distinct_page_access++;
70 + trx->distinct_page_access_hash[block_hash_byte] |= (byte) 0x01 << block_hash_offset;
74 /************************************************************************
75 This is the general function used to get access to a database page. */
77 @@ -1108,6 +1142,11 @@
84 + ib_longlong start_time;
85 + ib_longlong finish_time;
88 ut_ad((rw_latch == RW_S_LATCH)
90 #ifndef UNIV_LOG_DEBUG
91 ut_ad(!ibuf_inside() || ibuf_page(space, offset));
94 + trx = innobase_get_trx();
96 buf_pool->n_page_gets++;
103 - buf_read_page(space, offset);
104 + buf_read_page(space, offset, trx);
108 @@ -1261,6 +1303,11 @@
109 /* Let us wait until the read operation
112 + if (srv_slow_log && trx && trx->take_stats)
114 + ut_usectime(&sec, &ms);
115 + start_time = (ib_longlong)sec * 1000000 + ms;
118 mutex_enter(&block->mutex);
120 @@ -1276,6 +1323,12 @@
124 + if (srv_slow_log && trx && trx->take_stats && start_time)
126 + ut_usectime(&sec, &ms);
127 + finish_time = (ib_longlong)sec * 1000000 + ms;
128 + trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
132 fix_type = MTR_MEMO_BUF_FIX;
133 @@ -1296,12 +1349,17 @@
134 /* In the case of a first access, try to apply linear
137 - buf_read_ahead_linear(space, offset);
138 + buf_read_ahead_linear(space, offset, trx);
141 #ifdef UNIV_IBUF_DEBUG
142 ut_a(ibuf_count_get(block->space, block->offset) == 0);
145 + if (srv_slow_log) {
146 + _increment_page_get_statistics(block, trx);
149 return(block->frame);
152 @@ -1326,6 +1384,7 @@
159 ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
160 @@ -1440,7 +1499,7 @@
163 buf_read_ahead_linear(buf_frame_get_space_id(guess),
164 - buf_frame_get_page_no(guess));
165 + buf_frame_get_page_no(guess), trx);
168 #ifdef UNIV_IBUF_DEBUG
169 @@ -1448,6 +1507,11 @@
171 buf_pool->n_page_gets++;
173 + if (srv_slow_log) {
174 + trx = innobase_get_trx();
175 + _increment_page_get_statistics(block, trx);
181 @@ -1470,6 +1534,7 @@
188 ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
189 @@ -1559,6 +1624,11 @@
191 buf_pool->n_page_gets++;
193 + if (srv_slow_log) {
194 + trx = innobase_get_trx();
195 + _increment_page_get_statistics(block, trx);
201 diff -r 1242d4575291 innobase/buf/buf0rea.c
202 --- a/innobase/buf/buf0rea.c Tue Jul 28 23:39:12 2009 -0700
203 +++ b/innobase/buf/buf0rea.c Tue Jul 28 23:42:44 2009 -0700
205 treat the tablespace as dropped; this is a timestamp we
206 use to stop dangling page reads from a tablespace
207 which we have DISCARDed + IMPORTed back */
208 - ulint offset) /* in: page number */
209 + ulint offset, /* in: page number */
214 @@ -140,10 +141,10 @@
216 ut_a(block->state == BUF_BLOCK_FILE_PAGE);
218 - *err = fil_io(OS_FILE_READ | wake_later,
219 + *err = _fil_io(OS_FILE_READ | wake_later,
221 offset, 0, UNIV_PAGE_SIZE,
222 - (void*)block->frame, (void*)block);
223 + (void*)block->frame, (void*)block, trx);
224 ut_a(*err == DB_SUCCESS);
228 the page at the given page number does not get
229 read even if we return a value > 0! */
230 ulint space, /* in: space id */
231 - ulint offset) /* in: page number of a page which the current thread
232 + ulint offset, /* in: page number of a page which the current thread
236 ib_longlong tablespace_version;
239 if (!ibuf_bitmap_page(i)) {
240 count += buf_read_page_low(&err, FALSE, ibuf_mode
241 | OS_AIO_SIMULATED_WAKE_LATER,
242 - space, tablespace_version, i);
243 + space, tablespace_version, i, trx);
244 if (err == DB_TABLESPACE_DELETED) {
245 ut_print_timestamp(stderr);
248 /* out: number of page read requests issued: this can
249 be > 1 if read-ahead occurred */
250 ulint space, /* in: space id */
251 - ulint offset) /* in: page number */
252 + ulint offset, /* in: page number */
255 ib_longlong tablespace_version;
257 @@ -323,13 +326,13 @@
259 tablespace_version = fil_space_get_version(space);
261 - count = buf_read_ahead_random(space, offset);
262 + count = buf_read_ahead_random(space, offset, trx);
264 /* We do the i/o in the synchronous aio mode to save thread
265 switches: hence TRUE */
267 count2 = buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
268 - tablespace_version, offset);
269 + tablespace_version, offset, trx);
270 srv_buf_pool_reads+= count2;
271 if (err == DB_TABLESPACE_DELETED) {
272 ut_print_timestamp(stderr);
274 /*==================*/
275 /* out: number of page read requests issued */
276 ulint space, /* in: space id */
277 - ulint offset) /* in: page number of a page; NOTE: the current thread
278 + ulint offset, /* in: page number of a page; NOTE: the current thread
279 must want access to this page (see NOTE 3 above) */
282 ib_longlong tablespace_version;
285 if (!ibuf_bitmap_page(i)) {
286 count += buf_read_page_low(&err, FALSE, ibuf_mode
287 | OS_AIO_SIMULATED_WAKE_LATER,
288 - space, tablespace_version, i);
289 + space, tablespace_version, i, trx);
290 if (err == DB_TABLESPACE_DELETED) {
291 ut_print_timestamp(stderr);
293 @@ -625,10 +629,10 @@
294 for (i = 0; i < n_stored; i++) {
295 if ((i + 1 == n_stored) && sync) {
296 buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE,
297 - space_ids[i], space_versions[i], page_nos[i]);
298 + space_ids[i], space_versions[i], page_nos[i], NULL);
300 buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE,
301 - space_ids[i], space_versions[i], page_nos[i]);
302 + space_ids[i], space_versions[i], page_nos[i], NULL);
305 if (err == DB_TABLESPACE_DELETED) {
306 @@ -704,11 +708,11 @@
308 if ((i + 1 == n_stored) && sync) {
309 buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
310 - tablespace_version, page_nos[i]);
311 + tablespace_version, page_nos[i], NULL);
313 buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE
314 | OS_AIO_SIMULATED_WAKE_LATER,
315 - space, tablespace_version, page_nos[i]);
316 + space, tablespace_version, page_nos[i], NULL);
320 diff -r 1242d4575291 innobase/fil/fil0fil.c
321 --- a/innobase/fil/fil0fil.c Tue Jul 28 23:39:12 2009 -0700
322 +++ b/innobase/fil/fil0fil.c Tue Jul 28 23:42:44 2009 -0700
323 @@ -3527,7 +3527,7 @@
324 node->name, node->handle, buf,
325 offset_low, offset_high,
326 UNIV_PAGE_SIZE * n_pages,
331 node->size += n_pages;
332 @@ -3851,7 +3851,7 @@
333 Reads or writes data. This operation is asynchronous (aio). */
339 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
340 if we are trying to do i/o on a tablespace
341 @@ -3877,8 +3877,9 @@
342 void* buf, /* in/out: buffer where to store read data
343 or from where to write; in aio this must be
344 appropriately aligned */
345 - void* message) /* in: message for aio handler if non-sync
346 + void* message, /* in: message for aio handler if non-sync
347 aio used, else ignored */
350 fil_system_t* system = fil_system;
352 @@ -4018,7 +4019,7 @@
354 /* Queue the aio request */
355 ret = os_aio(type, mode | wake_later, node->name, node->handle, buf,
356 - offset_low, offset_high, len, node, message);
357 + offset_low, offset_high, len, node, message, trx);
361 diff -r 1242d4575291 innobase/include/buf0rea.h
362 --- a/innobase/include/buf0rea.h Tue Jul 28 23:39:12 2009 -0700
363 +++ b/innobase/include/buf0rea.h Tue Jul 28 23:42:44 2009 -0700
368 +#include "trx0types.h"
369 #include "buf0types.h"
371 /************************************************************************
373 /* out: number of page read requests issued: this can
374 be > 1 if read-ahead occurred */
375 ulint space, /* in: space id */
376 - ulint offset);/* in: page number */
377 + ulint offset, /* in: page number */
379 /************************************************************************
380 Applies linear read-ahead if in the buf_pool the page is a border page of
381 a linear read-ahead area and all the pages in the area have been accessed.
383 /*==================*/
384 /* out: number of page read requests issued */
385 ulint space, /* in: space id */
386 - ulint offset);/* in: page number of a page; NOTE: the current thread
387 + ulint offset, /* in: page number of a page; NOTE: the current thread
388 must want access to this page (see NOTE 3 above) */
390 /************************************************************************
391 Issues read requests for pages which the ibuf module wants to read in, in
392 order to contract the insert buffer tree. Technically, this function is like
393 diff -r 1242d4575291 innobase/include/fil0fil.h
394 --- a/innobase/include/fil0fil.h Tue Jul 28 23:39:12 2009 -0700
395 +++ b/innobase/include/fil0fil.h Tue Jul 28 23:42:44 2009 -0700
397 /************************************************************************
398 Reads or writes data. This operation is asynchronous (aio). */
400 +#define fil_io(type, sync, space_id, block_offset, byte_offset, len, buf, message) \
401 + _fil_io(type, sync, space_id, block_offset, byte_offset, len, buf, message, NULL)
407 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
408 if we are trying to do i/o on a tablespace
410 void* buf, /* in/out: buffer where to store read data
411 or from where to write; in aio this must be
412 appropriately aligned */
413 - void* message); /* in: message for aio handler if non-sync
414 + void* message, /* in: message for aio handler if non-sync
415 aio used, else ignored */
417 /************************************************************************
418 Reads data from a space to a buffer. Remember that the possible incomplete
419 blocks at the end of file are ignored: they are not taken into account when
420 diff -r 1242d4575291 innobase/include/os0file.h
421 --- a/innobase/include/os0file.h Tue Jul 28 23:39:12 2009 -0700
422 +++ b/innobase/include/os0file.h Tue Jul 28 23:42:44 2009 -0700
427 +#include "trx0types.h"
431 #include <sys/stat.h>
433 /***********************************************************************
434 Requests a synchronous read operation. */
436 +#define os_file_read(file, buf, offset, offset_high, n) \
437 + _os_file_read(file, buf, offset, offset_high, n, NULL)
443 /* out: TRUE if request was
444 successful, FALSE if fail */
446 offset where to read */
447 ulint offset_high,/* in: most significant 32 bits of
449 - ulint n); /* in: number of bytes to read */
450 + ulint n, /* in: number of bytes to read */
452 /***********************************************************************
453 Rewind file to its start, read at most size - 1 bytes from it to str, and
454 NUL-terminate str. All errors are silently ignored. This function is
456 can be used to identify a completed aio
457 operation); if mode is OS_AIO_SYNC, these
462 /****************************************************************************
463 Wakes up all async i/o threads so that they know to exit themselves in
465 diff -r 1242d4575291 innobase/include/srv0srv.h
466 --- a/innobase/include/srv0srv.h Tue Jul 28 23:39:12 2009 -0700
467 +++ b/innobase/include/srv0srv.h Tue Jul 28 23:42:44 2009 -0700
469 #define SRV_AUTO_EXTEND_INCREMENT \
470 (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
472 +extern ibool srv_slow_log;
474 /* This is set to TRUE if the MySQL user has set it in MySQL */
475 extern ibool srv_lower_case_table_names;
477 diff -r 1242d4575291 innobase/include/trx0trx.h
478 --- a/innobase/include/trx0trx.h Tue Jul 28 23:39:12 2009 -0700
479 +++ b/innobase/include/trx0trx.h Tue Jul 28 23:42:44 2009 -0700
481 /*------------------------------*/
482 char detailed_error[256]; /* detailed error message for last
484 + /*------------------------------*/
486 + ib_longlong io_read;
487 + ulint io_reads_wait_timer;
488 + ib_longlong lock_que_wait_ustarted;
489 + ulint lock_que_wait_timer;
490 + ulint innodb_que_wait_timer;
491 + ulint distinct_page_access;
492 +#define DPAH_SIZE 8192
493 + byte* distinct_page_access_hash;
497 #define TRX_MAX_N_THREADS 32 /* maximum number of concurrent
498 diff -r 1242d4575291 innobase/lock/lock0lock.c
499 --- a/innobase/lock/lock0lock.c Tue Jul 28 23:39:12 2009 -0700
500 +++ b/innobase/lock/lock0lock.c Tue Jul 28 23:42:44 2009 -0700
501 @@ -1806,6 +1806,8 @@
508 #ifdef UNIV_SYNC_DEBUG
509 ut_ad(mutex_own(&kernel_mutex));
510 @@ -1861,6 +1863,10 @@
511 trx->que_state = TRX_QUE_LOCK_WAIT;
512 trx->was_chosen_as_deadlock_victim = FALSE;
513 trx->wait_started = time(NULL);
514 + if (srv_slow_log && trx->take_stats) {
515 + ut_usectime(&sec, &ms);
516 + trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
519 ut_a(que_thr_stop(thr));
521 @@ -3514,7 +3520,9 @@
529 #ifdef UNIV_SYNC_DEBUG
530 ut_ad(mutex_own(&kernel_mutex));
531 #endif /* UNIV_SYNC_DEBUG */
532 @@ -3564,6 +3572,10 @@
536 + if (srv_slow_log && trx->take_stats) {
537 + ut_usectime(&sec, &ms);
538 + trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
540 trx->que_state = TRX_QUE_LOCK_WAIT;
541 trx->was_chosen_as_deadlock_victim = FALSE;
542 trx->wait_started = time(NULL);
543 diff -r 1242d4575291 innobase/os/os0file.c
544 --- a/innobase/os/os0file.c Tue Jul 28 23:39:12 2009 -0700
545 +++ b/innobase/os/os0file.c Tue Jul 28 23:42:44 2009 -0700
547 #include "srv0start.h"
550 +#include "trx0sys.h"
551 +#include "trx0trx.h"
553 #if defined(UNIV_HOTBACKUP) && defined(__WIN__)
554 /* Add includes for the _stat() call to compile on Windows */
555 @@ -1903,9 +1905,13 @@
557 /***********************************************************************
558 Does a synchronous read operation in Posix. */
560 +#define os_file_pread(file, buf, n, offset, offset_high) \
561 + _os_file_pread(file, buf, n, offset, offset_high, NULL);
568 /* out: number of bytes read, -1 if error */
569 os_file_t file, /* in: handle to a file */
570 @@ -1913,12 +1919,17 @@
571 ulint n, /* in: number of bytes to read */
572 ulint offset, /* in: least significant 32 bits of file
573 offset from where to read */
574 - ulint offset_high) /* in: most significant 32 bits of
576 + ulint offset_high, /* in: most significant 32 bits of
585 + ib_longlong start_time;
586 + ib_longlong finish_time;
588 ut_a((offset & 0xFFFFFFFFUL) == offset);
590 /* If off_t is > 4 bytes in size, then we assume we can pass a
591 @@ -1937,7 +1948,13 @@
596 + if (srv_slow_log && trx && trx->take_stats)
600 + ut_usectime(&sec, &ms);
601 + start_time = (ib_longlong)sec * 1000000 + ms;
603 #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
604 os_mutex_enter(os_file_count_mutex);
605 os_file_n_pending_preads++;
606 @@ -1951,6 +1968,13 @@
607 os_n_pending_reads--;
608 os_mutex_exit(os_file_count_mutex);
610 + if (srv_slow_log && trx && trx->take_stats && start_time)
612 + ut_usectime(&sec, &ms);
613 + finish_time = (ib_longlong)sec * 1000000 + ms;
614 + trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
620 @@ -1981,6 +2005,13 @@
621 os_n_pending_reads--;
622 os_mutex_exit(os_file_count_mutex);
624 + if (srv_slow_log && trx && trx->take_stats && start_time)
626 + ut_usectime(&sec, &ms);
627 + finish_time = (ib_longlong)sec * 1000000 + ms;
628 + trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
634 @@ -2103,7 +2134,7 @@
635 Requests a synchronous positioned read operation. */
641 /* out: TRUE if request was
642 successful, FALSE if fail */
643 @@ -2113,7 +2144,8 @@
644 offset where to read */
645 ulint offset_high, /* in: most significant 32 bits of
647 - ulint n) /* in: number of bytes to read */
648 + ulint n, /* in: number of bytes to read */
653 @@ -2177,7 +2209,7 @@
654 os_bytes_read_since_printout += n;
657 - ret = os_file_pread(file, buf, n, offset, offset_high);
658 + ret = _os_file_pread(file, buf, n, offset, offset_high, trx);
660 if ((ulint)ret == n) {
662 @@ -3137,7 +3169,8 @@
664 ulint offset_high, /* in: most significant 32 bits of
666 - ulint len) /* in: length of the block to read or write */
667 + ulint len, /* in: length of the block to read or write */
672 @@ -3390,7 +3423,8 @@
673 can be used to identify a completed aio
674 operation); if mode is OS_AIO_SYNC, these
680 os_aio_array_t* array;
682 @@ -3429,8 +3463,8 @@
683 wait in the Windows case. */
685 if (type == OS_FILE_READ) {
686 - return(os_file_read(file, buf, offset,
688 + return(_os_file_read(file, buf, offset,
689 + offset_high, n, trx));
692 ut_a(type == OS_FILE_WRITE);
693 @@ -3463,8 +3497,13 @@
697 + if (trx && type == OS_FILE_READ)
702 slot = os_aio_array_reserve_slot(type, array, message1, message2, file,
703 - name, buf, offset, offset_high, n);
704 + name, buf, offset, offset_high, n, trx);
705 if (type == OS_FILE_READ) {
706 if (os_aio_use_native_aio) {
708 diff -r 1242d4575291 innobase/srv/srv0srv.c
709 --- a/innobase/srv/srv0srv.c Tue Jul 28 23:39:12 2009 -0700
710 +++ b/innobase/srv/srv0srv.c Tue Jul 28 23:42:44 2009 -0700
712 #include "srv0start.h"
713 #include "row0mysql.h"
715 +ibool srv_slow_log = 0;
717 /* This is set to TRUE if the MySQL user has set it in MySQL; currently
718 affects only FOREIGN KEY definition parsing */
719 ibool srv_lower_case_table_names = FALSE;
720 @@ -1002,6 +1004,10 @@
721 ibool has_slept = FALSE;
722 srv_conc_slot_t* slot = NULL;
724 + ib_longlong start_time = 0L;
725 + ib_longlong finish_time = 0L;
729 /* If trx has 'free tickets' to enter the engine left, then use one
731 @@ -1060,6 +1066,7 @@
732 if (SRV_THREAD_SLEEP_DELAY > 0)
734 os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
735 + trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
739 @@ -1115,12 +1122,23 @@
740 /* Go to wait for the event; when a thread leaves InnoDB it will
741 release this thread */
743 + if (srv_slow_log && trx->take_stats) {
744 + ut_usectime(&sec, &ms);
745 + start_time = (ib_longlong)sec * 1000000 + ms;
748 trx->op_info = "waiting in InnoDB queue";
750 os_event_wait(slot->event);
754 + if (srv_slow_log && trx->take_stats && start_time) {
755 + ut_usectime(&sec, &ms);
756 + finish_time = (ib_longlong)sec * 1000000 + ms;
757 + trx->innodb_que_wait_timer += (ulint)(finish_time - start_time);
760 os_fast_mutex_lock(&srv_conc_mutex);
762 srv_conc_n_waiting_threads--;
763 diff -r 1242d4575291 innobase/trx/trx0trx.c
764 --- a/innobase/trx/trx0trx.c Tue Jul 28 23:39:12 2009 -0700
765 +++ b/innobase/trx/trx0trx.c Tue Jul 28 23:42:44 2009 -0700
767 trx->global_read_view_heap = mem_heap_create(256);
768 trx->global_read_view = NULL;
769 trx->read_view = NULL;
773 + trx->io_reads_wait_timer = 0;
774 + trx->lock_que_wait_timer = 0;
775 + trx->innodb_que_wait_timer = 0;
776 + trx->distinct_page_access = 0;
777 + trx->distinct_page_access_hash = NULL;
778 + trx->take_stats = FALSE;
780 /* Set X/Open XA transaction identification to NULL */
781 memset(&trx->xid, 0, sizeof(trx->xid));
784 trx->mysql_process_no = os_proc_get_number();
786 + if (srv_slow_log && trx->take_stats) {
787 + trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
788 + memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
796 trx_t* trx) /* in, own: trx object */
798 + if (trx->distinct_page_access_hash)
800 + mem_free(trx->distinct_page_access_hash);
801 + trx->distinct_page_access_hash= NULL;
804 thr_local_free(trx->mysql_thread_id);
806 mutex_enter(&kernel_mutex);
808 /*====================*/
809 trx_t* trx) /* in, own: trx object */
811 + if (trx->distinct_page_access_hash)
813 + mem_free(trx->distinct_page_access_hash);
814 + trx->distinct_page_access_hash= NULL;
817 mutex_enter(&kernel_mutex);
820 @@ -1064,7 +1090,10 @@
821 trx_t* trx) /* in: transaction */
829 #ifdef UNIV_SYNC_DEBUG
830 ut_ad(mutex_own(&kernel_mutex));
831 #endif /* UNIV_SYNC_DEBUG */
832 @@ -1080,6 +1109,11 @@
833 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
836 + if (srv_slow_log && trx->take_stats) {
837 + ut_usectime(&sec, &ms);
838 + now = (ib_longlong)sec * 1000000 + ms;
839 + trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
841 trx->que_state = TRX_QUE_RUNNING;
844 @@ -1093,6 +1127,9 @@
845 trx_t* trx) /* in: transaction in the TRX_QUE_LOCK_WAIT state */
852 #ifdef UNIV_SYNC_DEBUG
853 ut_ad(mutex_own(&kernel_mutex));
854 @@ -1109,6 +1146,11 @@
855 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
858 + if (srv_slow_log && trx->take_stats) {
859 + ut_usectime(&sec, &ms);
860 + now = (ib_longlong)sec * 1000000 + ms;
861 + trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
863 trx->que_state = TRX_QUE_RUNNING;
866 diff -r 1242d4575291 mysys/my_getopt.c
867 --- a/mysys/my_getopt.c Tue Jul 28 23:39:12 2009 -0700
868 +++ b/mysys/my_getopt.c Tue Jul 28 23:42:44 2009 -0700
873 - DBUG_ASSERT((optp->var_type & GET_TYPE_MASK) == GET_ULL);
874 + DBUG_ASSERT((optp->var_type & GET_TYPE_MASK) == GET_ULL
875 + || (optp->var_type & GET_TYPE_MASK) == GET_MICROTIME);
879 @@ -1061,6 +1062,9 @@
881 printf("%lu\n", *((ulong*) value));
883 + case GET_MICROTIME:
884 + printf("%6f\n", ((double)(*((longlong*) value))) / 1000000.0);
887 printf("%s\n", llstr(*((longlong*) value), buff));
889 diff -r 1242d4575291 patch_info/microslow_innodb.info
890 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
891 +++ b/patch_info/microslow_innodb.info Tue Jul 28 23:42:44 2009 -0700
893 +File=microslow_innodb.patch
894 +Name=Extended statistics in slow.log
896 +Author=Percona <info@percona.com>
901 +YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
904 +VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
907 +Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
908 diff -r 1242d4575291 scripts/mysqldumpslow.sh
909 --- a/scripts/mysqldumpslow.sh Tue Jul 28 23:39:12 2009 -0700
910 +++ b/scripts/mysqldumpslow.sh Tue Jul 28 23:42:44 2009 -0700
912 s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
913 my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
915 - s/^# Query_time: (\d+) Lock_time: (\d+) Rows_sent: (\d+).*\n//;
916 - my ($t, $l, $r) = ($1, $2, $3);
917 + s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//;
918 + my ($t, $l, $r) = ($1, $3, $5);
919 $t -= $l unless $opt{l};
921 # remove fluff that mysqld writes to log when it (re)starts:
922 diff -r 1242d4575291 sql-common/my_time.c
923 --- a/sql-common/my_time.c Tue Jul 28 23:39:12 2009 -0700
924 +++ b/sql-common/my_time.c Tue Jul 28 23:42:44 2009 -0700
925 @@ -1253,3 +1253,37 @@
930 + int my_timer(ulonglong *ltime, ulonglong frequency)
932 + For performance measurement this function returns the number
933 + of microseconds since the epoch (SVr4, BSD 4.3, POSIX 1003.1-2001)
934 + or system start (Windows platforms).
936 + For windows platforms frequency value (obtained via
937 + QueryPerformanceFrequency) has to be specified. The global frequency
938 + value is set in mysqld.cc.
940 + If Windows platform doesn't support QueryPerformanceFrequency we will
941 + obtain the time via GetClockCount, which supports microseconds only.
944 +ulonglong my_timer(ulonglong *ltime, ulonglong frequency)
946 + ulonglong newtime= 0;
950 + QueryPerformanceCounter((LARGE_INTEGER *)&newtime);
951 + newtime/= (frequency * 1000000);
953 + newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */
956 + if (gettimeofday(&t, NULL) != -1)
957 + newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
963 diff -r 1242d4575291 sql/filesort.cc
964 --- a/sql/filesort.cc Tue Jul 28 23:39:12 2009 -0700
965 +++ b/sql/filesort.cc Tue Jul 28 23:42:44 2009 -0700
968 statistic_increment(thd->status_var.filesort_scan_count, &LOCK_status);
970 + thd->query_plan_flags|= QPLAN_FILESORT;
971 #ifdef CAN_TRUST_RANGE
972 if (select && select->quick && select->quick->records > 0L)
978 + thd->query_plan_flags|= QPLAN_FILESORT_DISK;
979 if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
981 x_free(table_sort.buffpek);
982 @@ -1116,6 +1118,7 @@
984 statistic_increment(current_thd->status_var.filesort_merge_passes,
986 + current_thd->query_plan_fsort_passes++;
987 if (param->not_killable)
989 killed= ¬_killable;
990 diff -r 1242d4575291 sql/ha_innodb.cc
991 --- a/sql/ha_innodb.cc Tue Jul 28 23:39:12 2009 -0700
992 +++ b/sql/ha_innodb.cc Tue Jul 28 23:42:44 2009 -0700
995 /* Copyright (C) 2000-2005 MySQL AB & Innobase Oy
997 This program is free software; you can redistribute it and/or modify
999 trx->check_unique_secondary = TRUE;
1002 + if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1003 + trx->take_stats = TRUE;
1005 + trx->take_stats = FALSE;
1011 +/*************************************************************************
1012 +Gets current trx. */
1017 + THD *thd=current_thd;
1018 + if (likely(thd != 0)) {
1019 + return((trx_t*) thd->ha_data[innobase_hton.slot]);
1026 +innobase_update_var_slow_log()
1028 + srv_slow_log = (ibool) opt_slow_log;
1031 /*************************************************************************
1032 Construct ha_innobase handler. */
1033 @@ -1324,6 +1350,8 @@
1035 /* -------------- Log files ---------------------------*/
1037 + srv_slow_log = (ibool) opt_slow_log;
1039 /* The default dir for log files is the datadir of MySQL */
1041 if (!innobase_log_group_home_dir) {
1042 @@ -4697,6 +4725,12 @@
1043 trx->check_unique_secondary = FALSE;
1046 + if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1047 + trx->take_stats = TRUE;
1049 + trx->take_stats = FALSE;
1052 if (lower_case_table_names) {
1053 srv_lower_case_table_names = TRUE;
1055 @@ -4962,6 +4996,12 @@
1056 trx->check_unique_secondary = FALSE;
1059 + if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1060 + trx->take_stats = TRUE;
1062 + trx->take_stats = FALSE;
1065 name_len = strlen(name);
1067 assert(name_len < 1000);
1068 @@ -5049,6 +5089,12 @@
1069 trx->check_foreigns = FALSE;
1072 + if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1073 + trx->take_stats = TRUE;
1075 + trx->take_stats = FALSE;
1078 error = row_drop_database_for_mysql(namebuf, trx);
1079 my_free(namebuf, MYF(0));
1081 @@ -5115,6 +5161,12 @@
1082 trx->check_foreigns = FALSE;
1085 + if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1086 + trx->take_stats = TRUE;
1088 + trx->take_stats = FALSE;
1091 name_len1 = strlen(from);
1092 name_len2 = strlen(to);
1094 @@ -6122,6 +6174,7 @@
1096 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
1100 DBUG_ENTER("ha_innobase::external_lock");
1101 DBUG_PRINT("enter",("lock_type: %d", lock_type));
1102 @@ -6245,7 +6298,24 @@
1104 if (trx->n_mysql_tables_in_use == 0) {
1106 - trx->mysql_n_tables_locked = 0;
1107 + current_thd->innodb_was_used = TRUE;
1108 + current_thd->innodb_io_reads += trx->io_reads;
1109 + current_thd->innodb_io_read += trx->io_read;
1110 + current_thd->innodb_io_reads_wait_timer += trx->io_reads_wait_timer;
1111 + current_thd->innodb_lock_que_wait_timer += trx->lock_que_wait_timer;
1112 + current_thd->innodb_innodb_que_wait_timer += trx->innodb_que_wait_timer;
1113 + current_thd->innodb_page_access += trx->distinct_page_access;
1115 + trx->io_reads = 0;
1117 + trx->io_reads_wait_timer = 0;
1118 + trx->lock_que_wait_timer = 0;
1119 + trx->innodb_que_wait_timer = 0;
1120 + trx->distinct_page_access = 0;
1121 + if (trx->distinct_page_access_hash)
1122 + memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
1124 + trx->mysql_n_tables_locked = 0;
1125 prebuilt->used_in_HANDLER = FALSE;
1127 if (!(thd->options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN))) {
1128 diff -r 1242d4575291 sql/ha_innodb.h
1129 --- a/sql/ha_innodb.h Tue Jul 28 23:39:12 2009 -0700
1130 +++ b/sql/ha_innodb.h Tue Jul 28 23:42:44 2009 -0700
1133 int innobase_start_trx_and_assign_read_view(THD* thd);
1135 +void innobase_update_var_slow_log();
1137 /***********************************************************************
1138 This function is used to prepare X/Open XA distributed transaction */
1140 diff -r 1242d4575291 sql/log.cc
1141 --- a/sql/log.cc Tue Jul 28 23:39:12 2009 -0700
1142 +++ b/sql/log.cc Tue Jul 28 23:42:44 2009 -0700
1143 @@ -2289,11 +2289,12 @@
1146 bool MYSQL_LOG::write(THD *thd,const char *query, uint query_length,
1147 - time_t query_start_arg)
1148 + time_t query_start_arg, ulonglong query_start_timer)
1151 time_t current_time;
1153 + ulonglong current_timer;
1154 + if (!opt_slow_log || !is_open())
1156 DBUG_ENTER("MYSQL_LOG::write");
1158 @@ -2303,7 +2304,8 @@
1162 - if (!(thd->options & OPTION_UPDATE_LOG))
1163 + if (!(thd->options & OPTION_UPDATE_LOG) &&
1164 + !(thd->slave_thread && opt_log_slow_slave_statements))
1166 VOID(pthread_mutex_unlock(&LOCK_log));
1168 @@ -2333,22 +2335,72 @@
1169 if (my_b_printf(&log_file, "# User@Host: %s[%s] @ %s [%s]\n",
1171 sctx->priv_user : "",
1172 - sctx->user ? sctx->user : "",
1173 + sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""),
1174 sctx->host ? sctx->host : "",
1175 sctx->ip ? sctx->ip : "") ==
1179 - if (query_start_arg)
1180 + if (query_start_timer)
1183 + ulonglong current_timer= my_timer(¤t_timer, frequency);
1184 + snprintf(buf[0], 20, "%.6f", (current_timer ? (current_timer - query_start_timer):0) / 1000000.0);
1185 + snprintf(buf[1], 20, "%.6f", (thd->timer_after_lock - query_start_timer) / 1000000.0);
1186 + if (!query_length)
1188 + thd->sent_row_count= thd->examined_row_count= 0;
1189 + thd->row_count= 0;
1190 + thd->innodb_was_used= FALSE;
1191 + thd->query_plan_flags= QPLAN_NONE;
1192 + thd->query_plan_fsort_passes= 0;
1195 /* For slow query log */
1196 if (my_b_printf(&log_file,
1197 - "# Query_time: %lu Lock_time: %lu Rows_sent: %lu Rows_examined: %lu\n",
1198 - (ulong) (current_time - query_start_arg),
1199 - (ulong) (thd->time_after_lock - query_start_arg),
1200 + "# Thread_id: %lu Schema: %s\n" \
1201 + "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n",
1202 + (ulong) thd->thread_id, (thd->db ? thd->db : ""),
1204 (ulong) thd->sent_row_count,
1205 - (ulong) thd->examined_row_count) == (uint) -1)
1206 + (ulong) thd->examined_row_count,
1207 + ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
1208 + (ulong) thd->row_count) == (uint) -1)
1210 + if ((thd->variables.log_slow_verbosity & SLOG_V_QUERY_PLAN) &&
1211 + my_b_printf(&log_file,
1212 + "# QC_Hit: %s Full_scan: %s Full_join: %s Tmp_table: %s Tmp_table_on_disk: %s\n" \
1213 + "# Filesort: %s Filesort_on_disk: %s Merge_passes: %lu\n",
1214 + ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
1215 + ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
1216 + ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
1217 + ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
1218 + ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
1219 + ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
1220 + ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
1221 + thd->query_plan_fsort_passes) == (uint) -1)
1223 + if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) && thd->innodb_was_used)
1225 + snprintf(buf[2], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
1226 + snprintf(buf[3], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
1227 + snprintf(buf[4], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
1228 + if (my_b_printf(&log_file,
1229 + "# InnoDB_IO_r_ops: %lu InnoDB_IO_r_bytes: %lu InnoDB_IO_r_wait: %s\n" \
1230 + "# InnoDB_rec_lock_wait: %s InnoDB_queue_wait: %s\n" \
1231 + "# InnoDB_pages_distinct: %lu\n",
1232 + (ulong) thd->innodb_io_reads,
1233 + (ulong) thd->innodb_io_read,
1234 + buf[2], buf[3], buf[4],
1235 + (ulong) thd->innodb_page_access) == (uint) -1)
1240 + if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) &&
1241 + my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
1245 if (thd->db && strcmp(thd->db,db))
1246 { // Database changed
1247 diff -r 1242d4575291 sql/log_event.cc
1248 --- a/sql/log_event.cc Tue Jul 28 23:39:12 2009 -0700
1249 +++ b/sql/log_event.cc Tue Jul 28 23:42:44 2009 -0700
1250 @@ -2061,6 +2061,7 @@
1251 /* Execute the query (note that we bypass dispatch_command()) */
1252 const char* found_semicolon= NULL;
1253 mysql_parse(thd, thd->query, thd->query_length, &found_semicolon);
1254 + log_slow_statement(thd);
1258 diff -r 1242d4575291 sql/mysql_priv.h
1259 --- a/sql/mysql_priv.h Tue Jul 28 23:39:12 2009 -0700
1260 +++ b/sql/mysql_priv.h Tue Jul 28 23:42:44 2009 -0700
1261 @@ -507,6 +507,78 @@
1263 #define STRING_BUFFER_USUAL_SIZE 80
1273 +#define SLOG_V_MICROTIME 1 << 0
1274 +#define SLOG_V_QUERY_PLAN 1 << 1
1275 +#define SLOG_V_INNODB 1 << 2
1277 +#define SLOG_V_INVALID 1 << 31
1278 +#define SLOG_V_NONE SLOG_V_MICROTIME
1280 +static const struct msl_opts slog_verb[]=
1284 + { SLOG_V_MICROTIME, "microtime" },
1285 + { SLOG_V_QUERY_PLAN, "query_plan" },
1286 + { SLOG_V_INNODB, "innodb" },
1288 + /* End of baisc flags */
1292 + /* Complex flags */
1294 + { SLOG_V_MICROTIME, "minimal" },
1295 + { SLOG_V_MICROTIME|SLOG_V_QUERY_PLAN, "standard" },
1296 + { SLOG_V_MICROTIME|SLOG_V_QUERY_PLAN|SLOG_V_INNODB, "full" },
1298 + /* End of complex flags */
1300 + { SLOG_V_INVALID, (char *)0 }
1303 +#define QPLAN_NONE 0
1304 +#define QPLAN_QC 1 << 0
1305 +#define QPLAN_QC_NO 1 << 1
1306 +#define QPLAN_FULL_SCAN 1 << 2
1307 +#define QPLAN_FULL_JOIN 1 << 3
1308 +#define QPLAN_TMP_TABLE 1 << 4
1309 +#define QPLAN_TMP_DISK 1 << 5
1310 +#define QPLAN_FILESORT 1 << 6
1311 +#define QPLAN_FILESORT_DISK 1 << 7
1313 +#define QPLAN_MAX 1 << 31
1315 +#define SLOG_F_QC_NO QPLAN_QC_NO
1316 +#define SLOG_F_FULL_SCAN QPLAN_FULL_SCAN
1317 +#define SLOG_F_FULL_JOIN QPLAN_FULL_JOIN
1318 +#define SLOG_F_TMP_TABLE QPLAN_TMP_TABLE
1319 +#define SLOG_F_TMP_DISK QPLAN_TMP_DISK
1320 +#define SLOG_F_FILESORT QPLAN_FILESORT
1321 +#define SLOG_F_FILESORT_DISK QPLAN_FILESORT_DISK
1322 +#define SLOG_F_INVALID 1 << 31
1323 +#define SLOG_F_NONE 0
1325 +static const struct msl_opts slog_filter[]=
1327 + { SLOG_F_QC_NO, "qc_miss" },
1328 + { SLOG_F_FULL_SCAN, "full_scan" },
1329 + { SLOG_F_FULL_JOIN, "full_join" },
1330 + { SLOG_F_TMP_TABLE, "tmp_table" },
1331 + { SLOG_F_TMP_DISK, "tmp_table_on_disk" },
1332 + { SLOG_F_FILESORT, "filesort" },
1333 + { SLOG_F_FILESORT_DISK, "filesort_on_disk" },
1334 + { SLOG_F_INVALID, (char *)0 }
1337 enum enum_parsing_place
1340 @@ -1365,6 +1437,7 @@
1341 extern bool using_update_log, opt_large_files, server_id_supplied;
1342 extern bool opt_update_log, opt_bin_log, opt_error_log;
1343 extern my_bool opt_log, opt_slow_log, opt_log_queries_not_using_indexes;
1344 +extern char *opt_slow_logname;
1345 extern bool opt_disable_networking, opt_skip_show_db;
1346 extern my_bool opt_character_set_client_handshake;
1347 extern bool volatile abort_loop, shutdown_in_progress, grant_option;
1348 @@ -1376,7 +1449,8 @@
1349 extern my_bool opt_enable_named_pipe, opt_sync_frm, opt_allow_suspicious_udfs;
1350 extern my_bool opt_secure_auth;
1351 extern char* opt_secure_file_priv;
1352 -extern my_bool opt_log_slow_admin_statements;
1353 +extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
1354 +extern my_bool opt_use_global_long_query_time;
1355 extern my_bool sp_automatic_privileges, opt_noacl;
1356 extern my_bool opt_old_style_user_limits, trust_function_creators;
1357 extern uint opt_crash_binlog_innodb;
1358 diff -r 1242d4575291 sql/mysqld.cc
1359 --- a/sql/mysqld.cc Tue Jul 28 23:39:12 2009 -0700
1360 +++ b/sql/mysqld.cc Tue Jul 28 23:42:44 2009 -0700
1362 static void getvolumeID(BYTE *volumeName);
1363 #endif /* __NETWARE__ */
1367 int initgroups(const char *,unsigned int);
1369 @@ -411,10 +410,13 @@
1370 my_bool opt_secure_auth= 0;
1371 char* opt_secure_file_priv= 0;
1372 my_bool opt_log_slow_admin_statements= 0;
1373 +my_bool opt_log_slow_slave_statements= 0;
1374 +my_bool opt_use_global_long_query_time= 0;
1375 my_bool lower_case_file_system= 0;
1376 my_bool opt_large_pages= 0;
1377 uint opt_large_page_size= 0;
1378 my_bool opt_old_style_user_limits= 0, trust_function_creators= 0;
1379 +char* opt_slow_logname= 0;
1381 True if there is at least one per-hour limit for some user, so we should
1382 check them before each query (and possibly reset counters when hour is
1384 Ge_creator ge_creator;
1385 Le_creator le_creator;
1387 +ulonglong frequency= 0;
1389 FILE *bootstrap_file;
1390 int bootstrap_error;
1392 static int cleanup_done;
1393 static ulong opt_specialflag, opt_myisam_block_size;
1394 static char *opt_logname, *opt_update_logname, *opt_binlog_index_name;
1395 -static char *opt_slow_logname, *opt_tc_heuristic_recover;
1396 +static char *opt_tc_heuristic_recover;
1397 static char *mysql_home_ptr, *pidfile_name_ptr;
1398 static char **defaults_argv;
1399 static char *opt_bin_logname;
1400 @@ -3697,6 +3700,8 @@
1404 + if (!QueryPerformanceFrequency((LARGE_INTEGER *)&frequency))
1406 #endif /* __WIN__ */
1408 if (init_common_variables(MYSQL_CONFIG_NAME,
1409 @@ -4947,7 +4952,7 @@
1410 OPT_INTERACTIVE_TIMEOUT, OPT_JOIN_BUFF_SIZE,
1411 OPT_KEY_BUFFER_SIZE, OPT_KEY_CACHE_BLOCK_SIZE,
1412 OPT_KEY_CACHE_DIVISION_LIMIT, OPT_KEY_CACHE_AGE_THRESHOLD,
1413 - OPT_LONG_QUERY_TIME,
1414 + OPT_LONG_QUERY_TIME, OPT_MIN_EXAMINED_ROW_LIMIT,
1415 OPT_LOWER_CASE_TABLE_NAMES, OPT_MAX_ALLOWED_PACKET,
1416 OPT_MAX_BINLOG_CACHE_SIZE, OPT_MAX_BINLOG_SIZE,
1417 OPT_MAX_CONNECTIONS, OPT_MAX_CONNECT_ERRORS,
1418 @@ -5038,11 +5043,18 @@
1420 OPT_OLD_STYLE_USER_LIMITS,
1421 OPT_LOG_SLOW_ADMIN_STATEMENTS,
1422 + OPT_LOG_SLOW_SLAVE_STATEMENTS,
1423 + OPT_LOG_SLOW_RATE_LIMIT,
1424 + OPT_LOG_SLOW_VERBOSITY,
1425 + OPT_LOG_SLOW_FILTER,
1426 OPT_TABLE_LOCK_WAIT_TIMEOUT,
1428 OPT_PORT_OPEN_TIMEOUT,
1432 + OPT_SLOW_QUERY_LOG_FILE,
1433 + OPT_USE_GLOBAL_LONG_QUERY_TIME,
1434 OPT_INNODB_ROLLBACK_ON_TIMEOUT,
1435 OPT_SECURE_FILE_PRIV,
1436 OPT_KEEP_FILES_ON_CREATE,
1437 @@ -5441,10 +5453,19 @@
1438 (gptr*) &opt_log_slow_admin_statements,
1439 (gptr*) &opt_log_slow_admin_statements,
1440 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
1441 + {"log-slow-slave-statements", OPT_LOG_SLOW_SLAVE_STATEMENTS,
1442 + "Log slow replicated statements to the slow log if it is open.",
1443 + (gptr*) &opt_log_slow_slave_statements,
1444 + (gptr*) &opt_log_slow_slave_statements,
1445 + 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
1446 {"log-slow-queries", OPT_SLOW_QUERY_LOG,
1447 "Log slow queries to this log file. Defaults logging to hostname-slow.log file. Must be enabled to activate other slow log options.",
1448 (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1450 + {"slow_query_log_file", OPT_SLOW_QUERY_LOG_FILE,
1451 + "Log slow queries to given log file. Defaults logging to hostname-slow.log. Must be enabled to activate other slow log options.",
1452 + (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1453 + 0, 0, 0, 0, 0, 0},
1454 {"log-tc", OPT_LOG_TC,
1455 "Path to transaction coordinator log (used for transactions that affect "
1456 "more than one storage engine, when binary log is disabled)",
1457 @@ -5808,6 +5829,9 @@
1458 "Tells the slave thread to continue replication when a query returns an error from the provided list.",
1459 0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
1461 + {"slow-query-log", OPT_SLOW_LOG,
1462 + "Enable|disable slow query log", (gptr*) &opt_slow_log,
1463 + (gptr*) &opt_slow_log, 0, GET_BOOL, OPT_ARG, 0, 0, 0, 0, 0, 0},
1464 {"socket", OPT_SOCKET, "Socket file to use for connection.",
1465 (gptr*) &mysqld_unix_port, (gptr*) &mysqld_unix_port, 0, GET_STR,
1466 REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
1467 @@ -6110,11 +6134,31 @@
1469 0, (GET_ULONG | GET_ASK_ADDR) , REQUIRED_ARG, 100,
1471 - {"long_query_time", OPT_LONG_QUERY_TIME,
1472 - "Log all queries that have taken more than long_query_time seconds to execute to file.",
1473 - (gptr*) &global_system_variables.long_query_time,
1474 - (gptr*) &max_system_variables.long_query_time, 0, GET_ULONG,
1475 - REQUIRED_ARG, 10, 1, LONG_TIMEOUT, 0, 1, 0},
1476 + {"log_slow_filter", OPT_LOG_SLOW_FILTER,
1477 + "Log only the queries that followed certain execution plan. Multiple flags allowed in a comma-separated string. [qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, filesort, filesort_on_disk]",
1478 + 0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, SLOG_F_NONE, 0, 0},
1479 + {"log_slow_rate_limit", OPT_LOG_SLOW_RATE_LIMIT,
1480 + "Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
1481 + (gptr*) &global_system_variables.log_slow_rate_limit,
1482 + (gptr*) &max_system_variables.log_slow_rate_limit, 0, GET_ULONG,
1483 + REQUIRED_ARG, 1, 1, LONG_MAX, 0, 1L, 0},
1484 + {"log_slow_verbosity", OPT_LOG_SLOW_VERBOSITY,
1485 + "Choose how verbose the messages to your slow log will be. Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb]",
1486 + 0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, SLOG_V_MICROTIME, 0, 0},
1487 + {"long_query_time", OPT_LONG_QUERY_TIME,
1488 + "Log all queries that have taken more than long_query_time seconds to execute to file.",
1489 + (gptr*) &global_system_variables.long_query_time,
1490 + (gptr*) &max_system_variables.long_query_time, 0, GET_MICROTIME,
1491 + REQUIRED_ARG, 10000000, 0, LONG_TIMEOUT * 1000000, 0, 1, 0},
1492 + {"min_examined_row_limit", OPT_MIN_EXAMINED_ROW_LIMIT,
1493 + "Don't log queries which examine less than min_examined_row_limit rows to file.",
1494 + (gptr*) &global_system_variables.min_examined_row_limit,
1495 + (gptr*) &max_system_variables.min_examined_row_limit, 0, GET_ULONG,
1496 + REQUIRED_ARG, 0, 0, LONG_MAX, 0, 1L, 0},
1497 + {"use_global_long_query_time", OPT_USE_GLOBAL_LONG_QUERY_TIME,
1498 + "Control always use global long_query_time or local long_query_time.",
1499 + (gptr*) &opt_use_global_long_query_time, (gptr*) &opt_use_global_long_query_time,
1500 + 0, GET_BOOL, NO_ARG, 0, 0, 1, 0, 1, 0},
1501 {"lower_case_table_names", OPT_LOWER_CASE_TABLE_NAMES,
1502 "If set to 1 table names are stored in lowercase on disk and table names will be case-insensitive. Should be set to 2 if you are using a case insensitive file system",
1503 (gptr*) &lower_case_table_names,
1504 @@ -6893,7 +6937,11 @@
1505 global_system_variables.max_join_size= (ulonglong) HA_POS_ERROR;
1506 max_system_variables.max_join_size= (ulonglong) HA_POS_ERROR;
1507 global_system_variables.old_passwords= 0;
1509 + global_system_variables.long_query_time = 10000000;
1510 + max_system_variables.long_query_time = LONG_TIMEOUT * 1000000;
1511 + global_system_variables.log_slow_verbosity= SLOG_V_MICROTIME;
1512 + global_system_variables.log_slow_filter= SLOG_F_NONE;
1515 Default behavior for 4.1 and 5.0 is to treat NULL values as unequal
1516 when collecting index statistics for MyISAM tables.
1517 @@ -7364,6 +7412,35 @@
1519 opt_noacl=opt_bootstrap=1;
1521 + case OPT_LOG_SLOW_FILTER:
1522 + if ((global_system_variables.log_slow_filter=
1523 + msl_flag_resolve_by_name(slog_filter, argument,
1524 + SLOG_F_NONE, SLOG_F_INVALID)) == SLOG_F_INVALID)
1526 + fprintf(stderr,"Invalid argument in log_slow_filter: %s\n", argument);
1530 + case OPT_LOG_SLOW_VERBOSITY:
1531 + if ((global_system_variables.log_slow_verbosity=
1532 + msl_flag_resolve_by_name(slog_verb, argument,
1533 + SLOG_V_NONE, SLOG_V_INVALID)) == SLOG_V_INVALID)
1535 + fprintf(stderr,"Invalid argument in log_slow_verbosity: %s\n", argument);
1539 + case OPT_LONG_QUERY_TIME:
1541 + double doubleslow = strtod(argument,NULL);
1542 + if (doubleslow < 0 || doubleslow > (LONG_TIMEOUT))
1544 + fprintf(stderr,"Out of range long_query_time value: %s\n", argument);
1547 + global_system_variables.long_query_time = (ulonglong) (doubleslow * 1000000);
1550 case OPT_STORAGE_ENGINE:
1552 if ((enum db_type)((global_system_variables.table_type=
1553 @@ -7696,10 +7773,14 @@
1555 sql_print_warning("this binary does not contain BDB storage engine");
1557 - if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes) &&
1558 + if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes ||
1559 + opt_log_slow_slave_statements) &&
1561 - sql_print_warning("options --log-slow-admin-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set");
1564 + sql_print_warning("options --log-slow-admin-statements, --log-slow-slave-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set");
1565 + opt_log_slow_slave_statements= FALSE;
1570 fprintf(stderr, "%s: Too many arguments (first extra is '%s').\nUse --help to get a list of available options\n", my_progname, *argv);
1571 diff -r 1242d4575291 sql/set_var.cc
1572 --- a/sql/set_var.cc Tue Jul 28 23:39:12 2009 -0700
1573 +++ b/sql/set_var.cc Tue Jul 28 23:42:44 2009 -0700
1574 @@ -217,9 +217,13 @@
1575 sys_log_queries_not_using_indexes("log_queries_not_using_indexes",
1576 &opt_log_queries_not_using_indexes);
1577 sys_var_thd_ulong sys_log_warnings("log_warnings", &SV::log_warnings);
1578 -sys_var_thd_ulong sys_long_query_time("long_query_time",
1579 +sys_var_thd_microtime sys_long_query_time("long_query_time",
1580 &SV::long_query_time);
1581 +sys_var_bool_ptr sys_use_global_long_query_time("use_global_long_query_time",
1582 + &opt_use_global_long_query_time);
1583 sys_var_bool_const_ptr sys_log_slow("log_slow_queries", &opt_slow_log);
1584 +sys_var_log_slow sys_slow_query_log("slow_query_log", &opt_slow_log);
1585 +sys_var_const_str_ptr sys_slow_query_log_file("slow_query_log_file", &opt_slow_logname);
1586 sys_var_thd_bool sys_low_priority_updates("low_priority_updates",
1587 &SV::low_priority_updates,
1588 fix_low_priority_updates);
1590 &SV::max_tmp_tables);
1591 sys_var_long_ptr sys_max_write_lock_count("max_write_lock_count",
1592 &max_write_lock_count);
1593 +sys_var_thd_ulong sys_min_examined_row_limit("min_examined_row_limit",
1594 + &SV::min_examined_row_limit);
1595 sys_var_thd_ulong sys_multi_range_count("multi_range_count",
1596 &SV::multi_range_count);
1597 sys_var_long_ptr sys_myisam_data_pointer_size("myisam_data_pointer_size",
1598 @@ -327,6 +333,20 @@
1599 sys_var_bool_ptr sys_relay_log_purge("relay_log_purge",
1602 +sys_var_thd_ulong sys_log_slow_rate_limit("log_slow_rate_limit",
1603 + &SV::log_slow_rate_limit);
1604 +sys_var_thd_msl_flag sys_log_slow_filter("log_slow_filter",
1605 + &SV::log_slow_filter,
1610 +sys_var_thd_msl_flag sys_log_slow_verbosity("log_slow_verbosity",
1611 + &SV::log_slow_verbosity,
1616 sys_var_long_ptr sys_rpl_recovery_rank("rpl_recovery_rank",
1617 &rpl_recovery_rank);
1618 sys_var_long_ptr sys_query_cache_size("query_cache_size",
1619 @@ -697,6 +717,10 @@
1621 &sys_log_queries_not_using_indexes,
1623 + &sys_log_slow_filter,
1624 + &sys_log_slow_rate_limit,
1625 + &sys_log_slow_verbosity,
1626 + &sys_use_global_long_query_time,
1629 &sys_long_query_time,
1631 &sys_max_tmp_tables,
1632 &sys_max_user_connections,
1633 &sys_max_write_lock_count,
1634 + &sys_min_examined_row_limit,
1635 &sys_multi_range_count,
1636 &sys_myisam_data_pointer_size,
1637 &sys_myisam_max_sort_file_size,
1639 &sys_slave_skip_counter,
1641 &sys_slow_launch_time,
1642 + &sys_slow_query_log,
1643 + &sys_slow_query_log_file,
1645 &sys_sql_big_tables,
1646 &sys_sql_low_priority_updates,
1647 @@ -994,8 +1021,11 @@
1648 {"log_slave_updates", (char*) &opt_log_slave_updates, SHOW_MY_BOOL},
1650 {sys_log_slow.name, (char*) &sys_log_slow, SHOW_SYS},
1651 + {sys_log_slow_filter.name, (char*) &sys_log_slow_filter, SHOW_SYS},
1652 + {sys_log_slow_rate_limit.name, (char*) &sys_log_slow_rate_limit, SHOW_SYS},
1653 + {sys_log_slow_verbosity.name, (char*) &sys_log_slow_verbosity, SHOW_SYS},
1654 {sys_log_warnings.name, (char*) &sys_log_warnings, SHOW_SYS},
1655 - {sys_long_query_time.name, (char*) &sys_long_query_time, SHOW_SYS},
1656 + {sys_long_query_time.name, (char*) &sys_long_query_time, SHOW_MICROTIME},
1657 {sys_low_priority_updates.name, (char*) &sys_low_priority_updates, SHOW_SYS},
1658 {"lower_case_file_system", (char*) &lower_case_file_system, SHOW_MY_BOOL},
1659 {"lower_case_table_names", (char*) &lower_case_table_names, SHOW_INT},
1660 @@ -1022,6 +1052,7 @@
1661 {sys_max_tmp_tables.name, (char*) &sys_max_tmp_tables, SHOW_SYS},
1662 {sys_max_user_connections.name,(char*) &sys_max_user_connections, SHOW_SYS},
1663 {sys_max_write_lock_count.name, (char*) &sys_max_write_lock_count,SHOW_SYS},
1664 + {sys_min_examined_row_limit.name, (char*) &sys_min_examined_row_limit, SHOW_SYS},
1665 {sys_multi_range_count.name, (char*) &sys_multi_range_count, SHOW_SYS},
1666 {sys_myisam_data_pointer_size.name, (char*) &sys_myisam_data_pointer_size, SHOW_SYS},
1667 {sys_myisam_max_sort_file_size.name, (char*) &sys_myisam_max_sort_file_size,
1668 @@ -1109,6 +1140,8 @@
1669 {sys_slave_trans_retries.name,(char*) &sys_slave_trans_retries, SHOW_SYS},
1671 {sys_slow_launch_time.name, (char*) &sys_slow_launch_time, SHOW_SYS},
1672 + {sys_slow_query_log.name, (char*) &sys_slow_query_log, SHOW_SYS},
1673 + {sys_slow_query_log_file.name,(char*) &sys_slow_query_log_file, SHOW_SYS},
1674 #ifdef HAVE_SYS_UN_H
1675 {"socket", (char*) &mysqld_unix_port, SHOW_CHAR_PTR},
1677 @@ -1149,6 +1182,7 @@
1678 {sys_tx_isolation.name, (char*) &sys_tx_isolation, SHOW_SYS},
1679 {sys_updatable_views_with_limit.name,
1680 (char*) &sys_updatable_views_with_limit,SHOW_SYS},
1681 + {sys_use_global_long_query_time.name, (char*) &sys_use_global_long_query_time, SHOW_SYS},
1682 {sys_version.name, (char*) &sys_version, SHOW_SYS},
1683 #ifdef HAVE_BERKELEY_DB
1684 {sys_version_bdb.name, (char*) &sys_version_bdb, SHOW_SYS},
1685 @@ -1777,6 +1811,17 @@
1689 +bool sys_var_thd_microtime::check(THD *thd, set_var *var)
1691 + if (var->value->result_type() == DECIMAL_RESULT)
1692 + var->save_result.ulonglong_value= (ulonglong)(var->value->val_real() * 1000000);
1694 + var->save_result.ulonglong_value= (ulonglong)(var->value->val_int() * 1000000);
1700 bool sys_var_thd_bool::update(THD *thd, set_var *var)
1702 if (var->type == OPT_GLOBAL)
1703 @@ -1933,6 +1978,19 @@
1704 pthread_mutex_unlock(&LOCK_global_system_variables);
1705 return new Item_int(value);
1707 + case SHOW_MICROTIME:
1713 + pthread_mutex_lock(&LOCK_global_system_variables);
1714 + value= *(longlong*) value_ptr(thd, var_type, base);
1715 + pthread_mutex_unlock(&LOCK_global_system_variables);
1717 + len = snprintf(buff, 80, "%f", ((double) value) / 1000000.0);
1718 + return new Item_float(buff,len);
1723 @@ -2765,6 +2823,30 @@
1727 +bool sys_var_log_slow::update(THD *thd, set_var *var)
1731 + pthread_mutex_lock(&LOCK_global_system_variables);
1732 + if (var->save_result.ulong_value)
1734 + if(!mysql_slow_log.is_open())
1736 + mysql_slow_log.open_slow_log(opt_slow_logname);
1739 + pthread_mutex_unlock(&LOCK_global_system_variables);
1741 + ret = sys_var_bool_ptr::update(thd, var);
1743 +#ifdef HAVE_INNOBASE_DB
1744 + innobase_update_var_slow_log();
1751 #ifdef HAVE_REPLICATION
1752 bool sys_var_slave_skip_counter::check(THD *thd, set_var *var)
1754 @@ -3549,6 +3631,191 @@
1758 +/* Slow log stuff */
1760 +ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len)
1764 + for (i=0; opts[i].name; i++)
1766 + if (!my_strnncoll(&my_charset_latin1,
1767 + (const uchar *)name, len,
1768 + (const uchar *)opts[i].name, strlen(opts[i].name)))
1769 + return opts[i].val;
1771 + return opts[i].val;
1774 +ulong msl_flag_resolve_by_name(const struct msl_opts *opts, const char *names_list,
1775 + const ulong none_val, const ulong invalid_val)
1777 + const char *p, *e;
1778 + ulong val= none_val;
1783 + for (p= e= names_list; ; e++)
1787 + if (*e != ',' && *e)
1789 + for (i=0; opts[i].name; i++)
1791 + if (!my_strnncoll(&my_charset_latin1,
1792 + (const uchar *)p, e - p,
1793 + (const uchar *)opts[i].name, strlen(opts[i].name)))
1795 + val= val | opts[i].val;
1799 + if (opts[i].val == invalid_val)
1800 + return invalid_val;
1808 +const char *msl_option_get_name(const struct msl_opts *opts, ulong val)
1810 + for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1812 + if (opts[i].val == val)
1813 + return opts[i].name;
1815 + return "*INVALID*";
1818 +char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val)
1823 + for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1825 + if (opts[i].val & val)
1826 + offset+= snprintf(buf+offset, STRING_BUFFER_USUAL_SIZE - offset - 1,
1827 + "%s%s", (offset ? "," : ""), opts[i].name);
1832 +/****************************************************************************
1833 + Functions to handle log_slow_verbosity
1834 +****************************************************************************/
1836 +/* Based upon sys_var::check_enum() */
1838 +bool sys_var_thd_msl_option::check(THD *thd, set_var *var)
1840 + char buff[STRING_BUFFER_USUAL_SIZE];
1841 + String str(buff, sizeof(buff), &my_charset_latin1), *res;
1843 + if (var->value->result_type() == STRING_RESULT)
1845 + ulong verb= this->invalid_val;
1846 + if (!(res=var->value->val_str(&str)) ||
1847 + (var->save_result.ulong_value=
1848 + (ulong) (verb= msl_option_resolve_by_name(this->opts, res->ptr(), res->length()))) == this->invalid_val)
1854 + my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1858 +byte *sys_var_thd_msl_option::value_ptr(THD *thd, enum_var_type type,
1862 + val= ((type == OPT_GLOBAL) ? global_system_variables.*offset :
1863 + thd->variables.*offset);
1864 + const char *verbosity= msl_option_get_name(this->opts, val);
1865 + return (byte *) verbosity;
1869 +void sys_var_thd_msl_option::set_default(THD *thd, enum_var_type type)
1871 + if (type == OPT_GLOBAL)
1872 + global_system_variables.*offset= (ulong) this->default_val;
1874 + thd->variables.*offset= (ulong) (global_system_variables.*offset);
1878 +bool sys_var_thd_msl_option::update(THD *thd, set_var *var)
1880 + if (var->type == OPT_GLOBAL)
1881 + global_system_variables.*offset= var->save_result.ulong_value;
1883 + thd->variables.*offset= var->save_result.ulong_value;
1887 +/****************************************************************************
1888 + Functions to handle log_slow_filter
1889 +****************************************************************************/
1891 +/* Based upon sys_var::check_enum() */
1893 +bool sys_var_thd_msl_flag::check(THD *thd, set_var *var)
1895 + char buff[2 * STRING_BUFFER_USUAL_SIZE];
1896 + String str(buff, sizeof(buff), &my_charset_latin1), *res;
1898 + if (var->value->result_type() == STRING_RESULT)
1900 + ulong filter= this->none_val;
1901 + if (!(res=var->value->val_str(&str)) ||
1902 + (var->save_result.ulong_value=
1903 + (ulong) (filter= msl_flag_resolve_by_name(this->flags, res->ptr(), this->none_val,
1904 + this->invalid_val))) == this->invalid_val)
1910 + my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1914 +byte *sys_var_thd_msl_flag::value_ptr(THD *thd, enum_var_type type,
1918 + val= ((type == OPT_GLOBAL) ? global_system_variables.*offset :
1919 + thd->variables.*offset);
1920 + msl_flag_get_name(this->flags, this->flags_string, val);
1921 + return (byte *) this->flags_string;
1925 +void sys_var_thd_msl_flag::set_default(THD *thd, enum_var_type type)
1927 + if (type == OPT_GLOBAL)
1928 + global_system_variables.*offset= (ulong) this->default_val;
1930 + thd->variables.*offset= (ulong) (global_system_variables.*offset);
1934 +bool sys_var_thd_msl_flag::update(THD *thd, set_var *var)
1936 + if (var->type == OPT_GLOBAL)
1937 + global_system_variables.*offset= var->save_result.ulong_value;
1939 + thd->variables.*offset= var->save_result.ulong_value;
1943 /****************************************************************************
1944 Functions to handle table_type
1945 ****************************************************************************/
1946 diff -r 1242d4575291 sql/set_var.h
1947 --- a/sql/set_var.h Tue Jul 28 23:39:12 2009 -0700
1948 +++ b/sql/set_var.h Tue Jul 28 23:42:44 2009 -0700
1954 class sys_var_ulonglong_ptr :public sys_var
1957 @@ -168,6 +169,13 @@
1958 bool check_update_type(Item_result type) { return 0; }
1961 +class sys_var_log_slow :public sys_var_bool_ptr
1964 + sys_var_log_slow(const char *name_arg, my_bool *value_arg)
1965 + :sys_var_bool_ptr(name_arg, value_arg) {}
1966 + bool update(THD *thd, set_var *var);
1969 class sys_var_bool_const_ptr : public sys_var
1976 class sys_var_thd_ulong :public sys_var_thd
1978 sys_check_func check_func;
1980 byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1984 class sys_var_thd_ha_rows :public sys_var_thd
1988 byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1992 class sys_var_thd_ulonglong :public sys_var_thd
1995 @@ -407,6 +412,19 @@
1999 +class sys_var_thd_microtime :public sys_var_thd_ulonglong
2002 + sys_var_thd_microtime(const char *name_arg, ulonglong SV::*offset_arg)
2003 + :sys_var_thd_ulonglong(name_arg, offset_arg)
2005 + SHOW_TYPE show_type() { return SHOW_MICROTIME; }
2006 + bool check(THD *thd, set_var *var);
2007 + bool check_update_type(Item_result type)
2009 + return type != INT_RESULT && type != DECIMAL_RESULT;
2013 class sys_var_thd_bool :public sys_var_thd
2015 @@ -478,6 +496,66 @@
2019 +class sys_var_thd_msl_option :public sys_var_thd
2022 + ulong SV::*offset;
2023 + const ulong none_val;
2024 + const ulong default_val;
2025 + const ulong invalid_val;
2026 + const struct msl_opts *opts;
2028 + sys_var_thd_msl_option(const char *name_arg, ulong SV::*offset_arg,
2029 + const ulong none_val_arg,
2030 + const ulong default_val_arg,
2031 + const ulong invalid_val_arg,
2032 + const struct msl_opts *opts_arg)
2033 + :sys_var_thd(name_arg), offset(offset_arg), none_val(none_val_arg),
2034 + default_val(default_val_arg), invalid_val(invalid_val_arg),
2037 + bool check(THD *thd, set_var *var);
2038 + SHOW_TYPE show_type() { return SHOW_CHAR; }
2039 + bool check_update_type(Item_result type)
2041 + return type != STRING_RESULT; /* Only accept strings */
2043 + void set_default(THD *thd, enum_var_type type);
2044 + bool update(THD *thd, set_var *var);
2045 + byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
2049 +class sys_var_thd_msl_flag :public sys_var_thd
2052 + char flags_string[2 * STRING_BUFFER_USUAL_SIZE];
2053 + ulong SV::*offset;
2054 + const ulong none_val;
2055 + const ulong default_val;
2056 + const ulong invalid_val;
2057 + const struct msl_opts *flags;
2059 + sys_var_thd_msl_flag(const char *name_arg, ulong SV::*offset_arg,
2060 + const ulong none_val_arg,
2061 + const ulong default_val_arg,
2062 + const ulong invalid_val_arg,
2063 + const struct msl_opts *flags_arg)
2064 + :sys_var_thd(name_arg), offset(offset_arg), none_val(none_val_arg),
2065 + default_val(default_val_arg), invalid_val(invalid_val_arg),
2068 + bool check(THD *thd, set_var *var);
2069 + SHOW_TYPE show_type() { return SHOW_CHAR; }
2070 + bool check_update_type(Item_result type)
2072 + return type != STRING_RESULT; /* Only accept strings */
2074 + void set_default(THD *thd, enum_var_type type);
2075 + bool update(THD *thd, set_var *var);
2076 + byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
2079 class sys_var_thd_storage_engine :public sys_var_thd
2082 @@ -1109,3 +1187,11 @@
2083 bool process_key_caches(int (* func) (const char *name, KEY_CACHE *));
2084 void delete_elements(I_List<NAMED_LIST> *list,
2085 void (*free_element)(const char*, gptr));
2087 +/* Slow log functions */
2089 +ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len);
2090 +ulong msl_flag_resolve_by_name(const struct msl_opts *opts, const char *names_list,
2091 + const ulong none_val, const ulong invalid_val);
2092 +const char *msl_option_get_name(const struct msl_opts *opts, ulong val);
2093 +char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val);
2094 diff -r 1242d4575291 sql/slave.cc
2095 --- a/sql/slave.cc Tue Jul 28 23:39:12 2009 -0700
2096 +++ b/sql/slave.cc Tue Jul 28 23:42:44 2009 -0700
2097 @@ -2983,6 +2983,12 @@
2098 + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */
2099 thd->slave_thread = 1;
2100 set_slave_thread_options(thd);
2101 + if (opt_log_slow_slave_statements)
2103 + thd->enable_slow_log= TRUE;
2104 + /* Slave thread is excluded from rate limiting the slow log writes. */
2105 + thd->write_to_slow_log= TRUE;
2107 thd->client_capabilities = CLIENT_LOCAL_FILES;
2108 thd->real_id=pthread_self();
2109 pthread_mutex_lock(&LOCK_thread_count);
2110 diff -r 1242d4575291 sql/sql_cache.cc
2111 --- a/sql/sql_cache.cc Tue Jul 28 23:39:12 2009 -0700
2112 +++ b/sql/sql_cache.cc Tue Jul 28 23:42:44 2009 -0700
2113 @@ -1402,6 +1402,7 @@
2115 thd->limit_found_rows = query->found_rows();
2116 thd->status_var.last_query_cost= 0.0;
2117 + thd->query_plan_flags|= QPLAN_QC;
2119 BLOCK_UNLOCK_RD(query_block);
2120 DBUG_RETURN(1); // Result sent to client
2121 @@ -1409,6 +1410,7 @@
2123 STRUCT_UNLOCK(&structure_guard_mutex);
2125 + thd->query_plan_flags|= QPLAN_QC_NO;
2126 DBUG_RETURN(0); // Query was not cached
2129 diff -r 1242d4575291 sql/sql_class.cc
2130 --- a/sql/sql_class.cc Tue Jul 28 23:39:12 2009 -0700
2131 +++ b/sql/sql_class.cc Tue Jul 28 23:42:44 2009 -0700
2133 table_map_for_update(0),
2134 global_read_lock(0), is_fatal_error(0),
2135 transaction_rollback_request(0), is_fatal_sub_stmt_error(0),
2136 - rand_used(0), time_zone_used(0),
2137 + rand_used(0), time_zone_used(0), user_timer(0),
2138 last_insert_id_used(0), last_insert_id_used_bin_log(0), insert_id_used(0),
2139 clear_next_insert_id(0), in_lock_tables(0), bootstrap(0),
2140 derived_tables_processing(FALSE), spcont(NULL),
2141 @@ -2251,6 +2251,12 @@
2142 backup->cuted_fields= cuted_fields;
2143 backup->client_capabilities= client_capabilities;
2144 backup->savepoints= transaction.savepoints;
2145 + backup->innodb_io_reads= innodb_io_reads;
2146 + backup->innodb_io_read= innodb_io_read;
2147 + backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
2148 + backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
2149 + backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
2150 + backup->innodb_page_access= innodb_page_access;
2152 if (!lex->requires_prelocking() || is_update_query(lex->sql_command))
2153 options&= ~OPTION_BIN_LOG;
2154 @@ -2267,7 +2273,13 @@
2157 transaction.savepoints= 0;
2159 + innodb_io_reads= 0;
2160 + innodb_io_read= 0;
2161 + innodb_io_reads_wait_timer= 0;
2162 + innodb_lock_que_wait_timer= 0;
2163 + innodb_innodb_que_wait_timer= 0;
2164 + innodb_page_access= 0;
2166 /* Surpress OK packets in case if we will execute statements */
2167 net.no_send_ok= TRUE;
2169 @@ -2320,6 +2332,12 @@
2171 examined_row_count+= backup->examined_row_count;
2172 cuted_fields+= backup->cuted_fields;
2173 + innodb_io_reads+= backup->innodb_io_reads;
2174 + innodb_io_read+= backup->innodb_io_read;
2175 + innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
2176 + innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
2177 + innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
2178 + innodb_page_access+= backup->innodb_page_access;
2182 diff -r 1242d4575291 sql/sql_class.h
2183 --- a/sql/sql_class.h Tue Jul 28 23:39:12 2009 -0700
2184 +++ b/sql/sql_class.h Tue Jul 28 23:42:44 2009 -0700
2186 extern char internal_table_name[2];
2187 extern char empty_c_string[1];
2188 extern const char **errmesg;
2189 +extern ulonglong frequency;
2191 #define TC_LOG_PAGE_SIZE 8192
2192 #define TC_LOG_MIN_SIZE (3*TC_LOG_PAGE_SIZE)
2194 bool write(THD *thd, enum enum_server_command command,
2195 const char *format, ...) ATTRIBUTE_FORMAT(printf, 4, 5);
2196 bool write(THD *thd, const char *query, uint query_length,
2197 - time_t query_start=0);
2198 + time_t query_start=0, ulonglong query_start_timer=0);
2199 bool write(Log_event* event_info); // binary log write
2200 bool write(THD *thd, IO_CACHE *cache, Log_event *commit_event);
2202 @@ -527,13 +528,14 @@
2203 ulong auto_increment_increment, auto_increment_offset;
2204 ulong bulk_insert_buff_size;
2205 ulong join_buff_size;
2206 - ulong long_query_time;
2207 + ulonglong long_query_time;
2208 ulong max_allowed_packet;
2209 ulong max_error_count;
2210 ulong max_length_for_sort_data;
2211 ulong max_sort_length;
2212 ulong max_tmp_tables;
2213 ulong max_insert_delayed_threads;
2214 + ulong min_examined_row_limit;
2215 ulong multi_range_count;
2216 ulong myisam_repair_threads;
2217 ulong myisam_sort_buff_size;
2218 @@ -549,10 +551,13 @@
2219 ulong preload_buff_size;
2220 ulong profiling_history_size;
2221 ulong query_cache_type;
2222 + ulong log_slow_rate_limit;
2223 ulong read_buff_size;
2224 ulong read_rnd_buff_size;
2225 ulong div_precincrement;
2226 ulong sortbuff_size;
2227 + ulong log_slow_filter;
2228 + ulong log_slow_verbosity;
2231 ulong completion_type;
2232 @@ -1129,6 +1134,12 @@
2234 bool enable_slow_log, insert_id_used, clear_next_insert_id;
2235 bool last_insert_id_used;
2236 + ulong innodb_io_reads;
2237 + ulonglong innodb_io_read;
2238 + ulong innodb_io_reads_wait_timer;
2239 + ulong innodb_lock_que_wait_timer;
2240 + ulong innodb_innodb_que_wait_timer;
2241 + ulong innodb_page_access;
2243 SAVEPOINT *savepoints;
2245 @@ -1185,6 +1196,11 @@
2246 class THD :public Statement,
2247 public Open_tables_state
2250 + inline ulonglong query_start_timer() { return start_timer; }
2251 + inline void set_timer() { if (user_timer) start_timer=timer_after_lock=user_timer; else timer_after_lock=my_timer(&start_timer, frequency); }
2252 + inline void end_timer() { my_timer(&start_timer, frequency); }
2253 + inline void lock_timer() { my_timer(&timer_after_lock, frequency); }
2256 Constant for THD::where initialization in the beginning of every query.
2257 @@ -1293,10 +1309,24 @@
2260 time_t start_time,time_after_lock,user_time;
2261 + ulonglong start_timer,timer_after_lock, user_timer;
2262 time_t connect_time,thr_create_time; // track down slow pthread_create
2263 thr_lock_type update_lock_default;
2266 + bool write_to_slow_log;
2268 + bool innodb_was_used;
2269 + ulong innodb_io_reads;
2270 + ulonglong innodb_io_read;
2271 + ulong innodb_io_reads_wait_timer;
2272 + ulong innodb_lock_que_wait_timer;
2273 + ulong innodb_innodb_que_wait_timer;
2274 + ulong innodb_page_access;
2276 + ulong query_plan_flags;
2277 + ulong query_plan_fsort_passes;
2279 /* <> 0 if we are inside of trigger or stored function. */
2282 @@ -1696,11 +1726,11 @@
2283 sql_print_information("time() failed with %d", errno);
2286 - inline time_t query_start() { query_start_used=1; return start_time; }
2287 - inline void set_time() { if (user_time) start_time=time_after_lock=user_time; else { safe_time(&start_time); time_after_lock= start_time; }}
2288 - inline void end_time() { safe_time(&start_time); }
2289 - inline void set_time(time_t t) { time_after_lock=start_time=user_time=t; }
2290 - inline void lock_time() { safe_time(&time_after_lock); }
2291 + inline time_t query_start() { query_start_timer(); query_start_used=1; return start_time; }
2292 + inline void set_time() { set_timer(); if (user_time) start_time=time_after_lock=user_time; else { safe_time(&start_time); time_after_lock= start_time; }}
2293 + inline void end_time() { end_timer(); safe_time(&start_time); }
2294 + inline void set_time(time_t t) { set_timer(); time_after_lock=start_time=user_time=t; }
2295 + inline void lock_time() { lock_timer(); safe_time(&time_after_lock); }
2296 inline void insert_id(ulonglong id_arg)
2298 last_insert_id= id_arg;
2299 diff -r 1242d4575291 sql/sql_parse.cc
2300 --- a/sql/sql_parse.cc Tue Jul 28 23:39:12 2009 -0700
2301 +++ b/sql/sql_parse.cc Tue Jul 28 23:42:44 2009 -0700
2303 #include <m_ctype.h>
2306 +#include <my_time.h>
2308 #ifdef HAVE_INNOBASE_DB
2309 #include "ha_innodb.h"
2310 @@ -1227,6 +1228,15 @@
2311 my_net_set_read_timeout(net, thd->variables.net_read_timeout);
2312 my_net_set_write_timeout(net, thd->variables.net_write_timeout);
2315 + If rate limiting of slow log writes is enabled, decide whether to log this
2316 + new thread's queries or not. Uses extremely simple algorithm. :)
2318 + thd->write_to_slow_log= FALSE;
2319 + if (thd->variables.log_slow_rate_limit <= 1 ||
2320 + (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
2321 + thd->write_to_slow_log= TRUE;
2323 while (!net->error && net->vio != 0 &&
2324 !(thd->killed == THD::KILL_CONNECTION))
2326 @@ -2353,28 +2363,57 @@
2327 return; // Don't set time for sub stmt
2329 start_of_query= thd->start_time;
2330 - thd->end_time(); // Set start time
2331 + ulonglong start_of_query_timer= thd->start_timer;
2332 + thd->end_time(); // Set start timea
2335 + /* Follow the slow log filter configuration. */
2336 + if (thd->variables.log_slow_filter != SLOG_F_NONE &&
2337 + (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
2338 + ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
2339 + (thd->query_plan_flags & QPLAN_QC))))
2343 + Low long_query_time value most likely means user is debugging stuff and even
2344 + though some thread's queries are not supposed to be logged b/c of the rate
2345 + limit, if one of them takes long enough (>= 1 second) it will be sensible
2346 + to make an exception and write to slow log anyway.
2349 + if (opt_use_global_long_query_time)
2350 + thd->variables.long_query_time = global_system_variables.long_query_time;
2352 + /* Do not log this thread's queries due to rate limiting. */
2353 + if (thd->write_to_slow_log != TRUE
2354 + && (thd->variables.long_query_time >= 1000000
2355 + || (ulong) (thd->start_timer - thd->timer_after_lock) < 1000000))
2360 Do not log administrative statements unless the appropriate option is
2361 set; do not log into slow log if reading from backup.
2363 - if (thd->enable_slow_log && !thd->user_time)
2364 + if (thd->enable_slow_log &&
2365 + (!thd->user_time || (thd->slave_thread && opt_log_slow_slave_statements))
2369 thd_proc_info(thd, "logging slow query");
2371 - if ((thd->start_time > thd->time_after_lock &&
2372 - (ulong) (thd->start_time - thd->time_after_lock) >
2373 - thd->variables.long_query_time) ||
2374 - ((thd->server_status &
2375 - (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
2376 - opt_log_queries_not_using_indexes &&
2377 - /* == SQLCOM_END unless this is a SHOW command */
2378 - thd->lex->orig_sql_command == SQLCOM_END))
2379 + if (((ulong) (thd->start_timer - thd->timer_after_lock) >=
2380 + thd->variables.long_query_time ||
2381 + (thd->server_status &
2382 + (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
2383 + opt_log_queries_not_using_indexes &&
2384 + /* == SQLCOM_END unless this is a SHOW command */
2385 + thd->lex->orig_sql_command == SQLCOM_END) &&
2386 + thd->examined_row_count >= thd->variables.min_examined_row_limit)
2388 thd_proc_info(thd, "logging slow query");
2389 thd->status_var.long_query_count++;
2390 - mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query);
2391 + mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query, start_of_query_timer);
2395 @@ -2669,6 +2708,8 @@
2396 context.resolve_in_table_list_only((TABLE_LIST*)select_lex->
2399 + /* Reset the counter at all cases for the extended slow query log */
2400 + thd->row_count= 1;
2402 Reset warning count for each query that uses tables
2403 A better approach would be to reset this for any commands
2404 @@ -6203,6 +6244,15 @@
2405 thd->total_warn_count=0; // Warnings for this query
2407 thd->sent_row_count= thd->examined_row_count= 0;
2408 + thd->innodb_was_used= FALSE;
2409 + thd->innodb_io_reads= 0;
2410 + thd->innodb_io_read= 0;
2411 + thd->innodb_io_reads_wait_timer= 0;
2412 + thd->innodb_lock_que_wait_timer= 0;
2413 + thd->innodb_innodb_que_wait_timer= 0;
2414 + thd->innodb_page_access= 0;
2415 + thd->query_plan_flags= QPLAN_NONE;
2416 + thd->query_plan_fsort_passes= 0;
2420 diff -r 1242d4575291 sql/sql_select.cc
2421 --- a/sql/sql_select.cc Tue Jul 28 23:39:12 2009 -0700
2422 +++ b/sql/sql_select.cc Tue Jul 28 23:42:44 2009 -0700
2423 @@ -6272,8 +6272,11 @@
2425 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2428 statistic_increment(join->thd->status_var.select_scan_count,
2430 + join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
2435 @@ -6288,8 +6291,11 @@
2437 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2440 statistic_increment(join->thd->status_var.select_full_join_count,
2442 + join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
2446 if (!table->no_keyread)
2447 @@ -9350,6 +9356,7 @@
2448 (ulong) rows_limit,test(group)));
2450 statistic_increment(thd->status_var.created_tmp_tables, &LOCK_status);
2451 + thd->query_plan_flags|= QPLAN_TMP_TABLE;
2453 if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
2454 temp_pool_slot = bitmap_set_next(&temp_pool);
2455 @@ -10210,6 +10217,7 @@
2457 statistic_increment(table->in_use->status_var.created_tmp_disk_tables,
2459 + table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
2460 table->s->db_record_offset= 1;
2463 diff -r 1242d4575291 sql/sql_show.cc
2464 --- a/sql/sql_show.cc Tue Jul 28 23:39:12 2009 -0700
2465 +++ b/sql/sql_show.cc Tue Jul 28 23:42:44 2009 -0700
2466 @@ -1560,6 +1560,12 @@
2468 end= longlong10_to_str(*(longlong*) value, buff, 10);
2470 + case SHOW_MICROTIME:
2471 + show_type= ((sys_var*) value)->show_type();
2472 + value= (char*) ((sys_var*) value)->value_ptr(thd, value_type,
2474 + end= buff + sprintf(buff, "%f", (((double) (*(ulonglong*)value))) / 1000000.0);
2477 end= longlong10_to_str((longlong) *(ha_rows*) value, buff, 10);
2479 diff -r 1242d4575291 sql/structs.h
2480 --- a/sql/structs.h Tue Jul 28 23:39:12 2009 -0700
2481 +++ b/sql/structs.h Tue Jul 28 23:42:44 2009 -0700
2486 - SHOW_LONG, SHOW_LONGLONG, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
2487 - SHOW_DOUBLE_STATUS,
2488 + SHOW_LONG, SHOW_LONGLONG, SHOW_MICROTIME, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
2489 + SHOW_DOUBLE_STATUS,
2490 SHOW_BOOL, SHOW_MY_BOOL, SHOW_OPENTABLES, SHOW_STARTTIME, SHOW_QUERIES,
2491 SHOW_LONG_CONST, SHOW_INT_CONST, SHOW_HAVE, SHOW_SYS, SHOW_HA_ROWS,