]> git.pld-linux.org Git - packages/mysql.git/blame - mysql-microslow_innodb.patch
projects / packages / mysql.git / blame
? search:
summary | shortlog | log | commit | commitdiff | tree
blob | blame (incremental) | history | HEAD
- percona patches updated by fax; rel 2
[packages/mysql.git] / mysql-microslow_innodb.patch
CommitLineData
6f73e838
ER		 1diff -r 25523be1816e include/my_getopt.h
2--- a/include/my_getopt.h Mon Dec 22 00:25:06 2008 -0800
3+++ b/include/my_getopt.h Mon Dec 22 00:26:39 2008 -0800
4@@ -28,7 +28,8 @@
5 #define GET_ULL 8
6 #define GET_STR 9
7 #define GET_STR_ALLOC 10
8-#define GET_DISABLED 11
9+#define GET_DOUBLE 11
10+#define GET_DISABLED 12
11
12 #define GET_ASK_ADDR 128
13 #define GET_TYPE_MASK 127
14diff -r 25523be1816e include/my_time.h
15--- a/include/my_time.h Mon Dec 22 00:25:06 2008 -0800
16+++ b/include/my_time.h Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 17@@ -140,7 +140,7 @@
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);
21-
22+ulonglong my_timer(ulonglong *ltime, ulonglong frequency);
23 C_MODE_END
24
25 #endif /* _my_time_h_ */
6f73e838
ER		 26diff -r 25523be1816e innobase/buf/buf0buf.c
27--- a/innobase/buf/buf0buf.c Mon Dec 22 00:25:06 2008 -0800
28+++ b/innobase/buf/buf0buf.c Mon Dec 22 00:26:39 2008 -0800
29@@ -37,6 +37,9 @@
833f2639
ER		 30 #include "log0log.h"
31 #include "trx0undo.h"
32 #include "srv0srv.h"
6f73e838
ER		 33+
34+/* prototypes for new functions added to ha_innodb.cc */
35+trx_t* innobase_get_trx();
833f2639
ER		 36
37 /*
38 IMPLEMENTATION OF THE BUFFER POOL
6f73e838 39@@ -1086,6 +1089,36 @@
833f2639
ER		 40 return(block);
41 }
42
43+inline void _increment_page_get_statistics(buf_block_t* block, trx_t* trx)
44+{
45+ ulint block_hash;
46+ ulint block_hash_byte;
47+ byte block_hash_offset;
48+
49+ ut_ad(block);
50+
6f73e838 51+ if (!srv_slow_log || !trx || !trx->take_stats)
833f2639
ER		 52+ return;
53+
6f73e838
ER		 54+ if (!trx->distinct_page_access_hash) {
55+ trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
56+ memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
57+ }
58+
833f2639
ER		 59+ block_hash = ut_hash_ulint((block->space << 20) + block->space +
60+ block->offset, DPAH_SIZE << 3);
61+ block_hash_byte = block_hash >> 3;
62+ block_hash_offset = (byte) block_hash & 0x07;
63+ if (block_hash_byte < 0 || block_hash_byte >= DPAH_SIZE)
64+ fprintf(stderr, "!!! block_hash_byte = %lu block_hash_offset = %lu !!!\n", block_hash_byte, block_hash_offset);
65+ if (block_hash_offset < 0 || block_hash_offset > 7)
66+ fprintf(stderr, "!!! block_hash_byte = %lu block_hash_offset = %lu !!!\n", block_hash_byte, block_hash_offset);
67+ if ((trx->distinct_page_access_hash[block_hash_byte] & ((byte) 0x01 << block_hash_offset)) == 0)
68+ trx->distinct_page_access++;
69+ trx->distinct_page_access_hash[block_hash_byte] |= (byte) 0x01 << block_hash_offset;
70+ return;
71+}
72+
73 /************************************************************************
74 This is the general function used to get access to a database page. */
75
6f73e838 76@@ -1108,6 +1141,11 @@
833f2639
ER		 77 ulint fix_type;
78 ibool success;
79 ibool must_read;
6f73e838 80+ trx_t* trx = NULL;
833f2639
ER		 81+ ulint sec;
82+ ulint ms;
83+ ib_longlong start_time;
84+ ib_longlong finish_time;
85
86 ut_ad(mtr);
87 ut_ad((rw_latch == RW_S_LATCH)
6f73e838 88@@ -1119,6 +1157,9 @@
833f2639
ER		 89 #ifndef UNIV_LOG_DEBUG
90 ut_ad(!ibuf_inside() || ibuf_page(space, offset));
91 #endif
6f73e838
ER		 92+ if (srv_slow_log) {
93+ trx = innobase_get_trx();
94+ }
833f2639
ER		 95 buf_pool->n_page_gets++;
96 loop:
97 block = NULL;
6f73e838 98@@ -1148,7 +1189,7 @@
833f2639
ER		 99 return(NULL);
100 }
101
102- buf_read_page(space, offset);
103+ buf_read_page(space, offset, trx);
104
105 #ifdef UNIV_DEBUG
106 buf_dbg_counter++;
6f73e838 107@@ -1261,6 +1302,11 @@
833f2639
ER		 108 /* Let us wait until the read operation
109 completes */
110
6f73e838 111+ if (srv_slow_log && trx && trx->take_stats)
833f2639
ER		 112+ {
113+ ut_usectime(&sec, &ms);
114+ start_time = (ib_longlong)sec * 1000000 + ms;
115+ }
116 for (;;) {
117 mutex_enter(&block->mutex);
118
6f73e838 119@@ -1275,6 +1321,12 @@
833f2639
ER		 120
121 break;
122 }
123+ }
6f73e838 124+ if (srv_slow_log && trx && trx->take_stats && start_time)
833f2639
ER		 125+ {
126+ ut_usectime(&sec, &ms);
127+ finish_time = (ib_longlong)sec * 1000000 + ms;
128+ trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
129 }
130 }
131
6f73e838 132@@ -1296,12 +1348,17 @@
833f2639
ER		 133 /* In the case of a first access, try to apply linear
134 read-ahead */
135
136- buf_read_ahead_linear(space, offset);
137+ buf_read_ahead_linear(space, offset, trx);
138 }
139
140 #ifdef UNIV_IBUF_DEBUG
141 ut_a(ibuf_count_get(block->space, block->offset) == 0);
142 #endif
143+
6f73e838
ER		 144+ if (srv_slow_log) {
145+ _increment_page_get_statistics(block, trx);
146+ }
833f2639
ER		 147+
148 return(block->frame);
149 }
150
6f73e838 151@@ -1326,6 +1383,7 @@
833f2639
ER		 152 ibool accessed;
153 ibool success;
154 ulint fix_type;
6f73e838 155+ trx_t* trx = NULL;
833f2639
ER		 156
157 ut_ad(mtr && block);
158 ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
6f73e838 159@@ -1440,13 +1498,18 @@
833f2639
ER		 160 read-ahead */
161
162 buf_read_ahead_linear(buf_frame_get_space_id(guess),
163- buf_frame_get_page_no(guess));
164+ buf_frame_get_page_no(guess), trx);
165 }
166
167 #ifdef UNIV_IBUF_DEBUG
168 ut_a(ibuf_count_get(block->space, block->offset) == 0);
169 #endif
170 buf_pool->n_page_gets++;
171+
6f73e838
ER		 172+ if (srv_slow_log) {
173+ trx = innobase_get_trx();
174+ _increment_page_get_statistics(block, trx);
175+ }
833f2639
ER		 176
177 return(TRUE);
178 }
6f73e838 179@@ -1470,6 +1533,7 @@
833f2639
ER		 180 buf_block_t* block;
181 ibool success;
182 ulint fix_type;
6f73e838 183+ trx_t* trx = NULL;
833f2639
ER		 184
185 ut_ad(mtr);
186 ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
6f73e838 187@@ -1558,6 +1622,11 @@
833f2639
ER		 188 || (ibuf_count_get(block->space, block->offset) == 0));
189 #endif
190 buf_pool->n_page_gets++;
191+
6f73e838
ER		 192+ if (srv_slow_log) {
193+ trx = innobase_get_trx();
194+ _increment_page_get_statistics(block, trx);
195+ }
833f2639
ER		 196
197 return(TRUE);
198 }
6f73e838
ER		 199diff -r 25523be1816e innobase/buf/buf0rea.c
200--- a/innobase/buf/buf0rea.c Mon Dec 22 00:25:06 2008 -0800
201+++ b/innobase/buf/buf0rea.c Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 202@@ -70,7 +70,8 @@
203 treat the tablespace as dropped; this is a timestamp we
204 use to stop dangling page reads from a tablespace
205 which we have DISCARDed + IMPORTed back */
206- ulint offset) /* in: page number */
207+ ulint offset, /* in: page number */
208+ trx_t* trx)
209 {
210 buf_block_t* block;
211 ulint wake_later;
212@@ -140,10 +141,10 @@
213
214 ut_a(block->state == BUF_BLOCK_FILE_PAGE);
215
216- *err = fil_io(OS_FILE_READ | wake_later,
217+ *err = _fil_io(OS_FILE_READ | wake_later,
218 sync, space,
219 offset, 0, UNIV_PAGE_SIZE,
220- (void*)block->frame, (void*)block);
221+ (void*)block->frame, (void*)block, trx);
222 ut_a(*err == DB_SUCCESS);
223
224 if (sync) {
225@@ -174,8 +175,9 @@
226 the page at the given page number does not get
227 read even if we return a value > 0! */
228 ulint space, /* in: space id */
229- ulint offset) /* in: page number of a page which the current thread
230+ ulint offset, /* in: page number of a page which the current thread
231 wants to access */
232+ trx_t* trx)
233 {
234 ib_longlong tablespace_version;
235 buf_block_t* block;
236@@ -270,7 +272,7 @@
237 if (!ibuf_bitmap_page(i)) {
238 count += buf_read_page_low(&err, FALSE, ibuf_mode
239 | OS_AIO_SIMULATED_WAKE_LATER,
240- space, tablespace_version, i);
241+ space, tablespace_version, i, trx);
242 if (err == DB_TABLESPACE_DELETED) {
243 ut_print_timestamp(stderr);
244 fprintf(stderr,
245@@ -314,7 +316,8 @@
246 /* out: number of page read requests issued: this can
247 be > 1 if read-ahead occurred */
248 ulint space, /* in: space id */
249- ulint offset) /* in: page number */
250+ ulint offset, /* in: page number */
251+ trx_t* trx)
252 {
253 ib_longlong tablespace_version;
254 ulint count;
255@@ -323,13 +326,13 @@
256
257 tablespace_version = fil_space_get_version(space);
258
259- count = buf_read_ahead_random(space, offset);
260+ count = buf_read_ahead_random(space, offset, trx);
261
262 /* We do the i/o in the synchronous aio mode to save thread
263 switches: hence TRUE */
264
265 count2 = buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
266- tablespace_version, offset);
267+ tablespace_version, offset, trx);
268 srv_buf_pool_reads+= count2;
269 if (err == DB_TABLESPACE_DELETED) {
270 ut_print_timestamp(stderr);
271@@ -374,8 +377,9 @@
272 /*==================*/
273 /* out: number of page read requests issued */
274 ulint space, /* in: space id */
275- ulint offset) /* in: page number of a page; NOTE: the current thread
276+ ulint offset, /* in: page number of a page; NOTE: the current thread
277 must want access to this page (see NOTE 3 above) */
278+ trx_t* trx)
279 {
280 ib_longlong tablespace_version;
281 buf_block_t* block;
282@@ -556,7 +560,7 @@
283 if (!ibuf_bitmap_page(i)) {
284 count += buf_read_page_low(&err, FALSE, ibuf_mode
285 | OS_AIO_SIMULATED_WAKE_LATER,
286- space, tablespace_version, i);
287+ space, tablespace_version, i, trx);
288 if (err == DB_TABLESPACE_DELETED) {
289 ut_print_timestamp(stderr);
290 fprintf(stderr,
291@@ -625,10 +629,10 @@
292 for (i = 0; i < n_stored; i++) {
293 if ((i + 1 == n_stored) && sync) {
294 buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE,
295- space_ids[i], space_versions[i], page_nos[i]);
296+ space_ids[i], space_versions[i], page_nos[i], NULL);
297 } else {
298 buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE,
299- space_ids[i], space_versions[i], page_nos[i]);
300+ space_ids[i], space_versions[i], page_nos[i], NULL);
301 }
302
303 if (err == DB_TABLESPACE_DELETED) {
304@@ -704,11 +708,11 @@
305
306 if ((i + 1 == n_stored) && sync) {
307 buf_read_page_low(&err, TRUE, BUF_READ_ANY_PAGE, space,
308- tablespace_version, page_nos[i]);
309+ tablespace_version, page_nos[i], NULL);
310 } else {
311 buf_read_page_low(&err, FALSE, BUF_READ_ANY_PAGE
312 | OS_AIO_SIMULATED_WAKE_LATER,
313- space, tablespace_version, page_nos[i]);
314+ space, tablespace_version, page_nos[i], NULL);
315 }
316 }
317
6f73e838
ER		 318diff -r 25523be1816e innobase/fil/fil0fil.c
319--- a/innobase/fil/fil0fil.c Mon Dec 22 00:25:06 2008 -0800
320+++ b/innobase/fil/fil0fil.c Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 321@@ -3527,7 +3527,7 @@
322 node->name, node->handle, buf,
323 offset_low, offset_high,
324 UNIV_PAGE_SIZE * n_pages,
325- NULL, NULL);
326+ NULL, NULL, NULL);
327 #endif
328 if (success) {
329 node->size += n_pages;
330@@ -3851,7 +3851,7 @@
331 Reads or writes data. This operation is asynchronous (aio). */
332
333 ulint
334-fil_io(
335+_fil_io(
336 /*===*/
337 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
338 if we are trying to do i/o on a tablespace
339@@ -3877,8 +3877,9 @@
340 void* buf, /* in/out: buffer where to store read data
341 or from where to write; in aio this must be
342 appropriately aligned */
343- void* message) /* in: message for aio handler if non-sync
344+ void* message, /* in: message for aio handler if non-sync
345 aio used, else ignored */
346+ trx_t* trx)
347 {
348 fil_system_t* system = fil_system;
349 ulint mode;
350@@ -4018,7 +4019,7 @@
351 #else
352 /* Queue the aio request */
353 ret = os_aio(type, mode | wake_later, node->name, node->handle, buf,
354- offset_low, offset_high, len, node, message);
355+ offset_low, offset_high, len, node, message, trx);
356 #endif
357 ut_a(ret);
358
6f73e838
ER		 359diff -r 25523be1816e innobase/include/buf0rea.h
360--- a/innobase/include/buf0rea.h Mon Dec 22 00:25:06 2008 -0800
361+++ b/innobase/include/buf0rea.h Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 362@@ -10,6 +10,7 @@
363 #define buf0rea_h
364
365 #include "univ.i"
366+#include "trx0types.h"
367 #include "buf0types.h"
368
369 /************************************************************************
370@@ -25,7 +26,8 @@
371 /* out: number of page read requests issued: this can
372 be > 1 if read-ahead occurred */
373 ulint space, /* in: space id */
374- ulint offset);/* in: page number */
375+ ulint offset, /* in: page number */
376+ trx_t* trx);
377 /************************************************************************
378 Applies linear read-ahead if in the buf_pool the page is a border page of
379 a linear read-ahead area and all the pages in the area have been accessed.
380@@ -55,8 +57,9 @@
381 /*==================*/
382 /* out: number of page read requests issued */
383 ulint space, /* in: space id */
384- ulint offset);/* in: page number of a page; NOTE: the current thread
385+ ulint offset, /* in: page number of a page; NOTE: the current thread
386 must want access to this page (see NOTE 3 above) */
387+ trx_t* trx);
388 /************************************************************************
389 Issues read requests for pages which the ibuf module wants to read in, in
390 order to contract the insert buffer tree. Technically, this function is like
6f73e838
ER		 391diff -r 25523be1816e innobase/include/fil0fil.h
392--- a/innobase/include/fil0fil.h Mon Dec 22 00:25:06 2008 -0800
393+++ b/innobase/include/fil0fil.h Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 394@@ -534,8 +534,11 @@
395 /************************************************************************
396 Reads or writes data. This operation is asynchronous (aio). */
397
398+#define fil_io(type, sync, space_id, block_offset, byte_offset, len, buf, message) \
399+ _fil_io(type, sync, space_id, block_offset, byte_offset, len, buf, message, NULL)
400+
401 ulint
402-fil_io(
403+_fil_io(
404 /*===*/
405 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
406 if we are trying to do i/o on a tablespace
407@@ -561,8 +564,9 @@
408 void* buf, /* in/out: buffer where to store read data
409 or from where to write; in aio this must be
410 appropriately aligned */
411- void* message); /* in: message for aio handler if non-sync
412+ void* message, /* in: message for aio handler if non-sync
413 aio used, else ignored */
414+ trx_t* trx);
415 /************************************************************************
416 Reads data from a space to a buffer. Remember that the possible incomplete
417 blocks at the end of file are ignored: they are not taken into account when
6f73e838
ER		 418diff -r 25523be1816e innobase/include/os0file.h
419--- a/innobase/include/os0file.h Mon Dec 22 00:25:06 2008 -0800
420+++ b/innobase/include/os0file.h Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 421@@ -10,6 +10,8 @@
422 #define os0file_h
423
424 #include "univ.i"
425+
426+#include "trx0types.h"
427
428 #ifndef __WIN__
429 #include <dirent.h>
430@@ -421,8 +423,11 @@
431 /***********************************************************************
432 Requests a synchronous read operation. */
433
434+#define os_file_read(file, buf, offset, offset_high, n) \
435+ _os_file_read(file, buf, offset, offset_high, n, NULL)
436+
437 ibool
438-os_file_read(
439+_os_file_read(
440 /*=========*/
441 /* out: TRUE if request was
442 successful, FALSE if fail */
443@@ -432,7 +437,8 @@
444 offset where to read */
445 ulint offset_high,/* in: most significant 32 bits of
446 offset */
447- ulint n); /* in: number of bytes to read */
448+ ulint n, /* in: number of bytes to read */
449+ trx_t* trx);
450 /***********************************************************************
451 Rewind file to its start, read at most size - 1 bytes from it to str, and
452 NUL-terminate str. All errors are silently ignored. This function is
453@@ -584,7 +590,8 @@
454 can be used to identify a completed aio
455 operation); if mode is OS_AIO_SYNC, these
456 are ignored */
457- void* message2);
458+ void* message2,
459+ trx_t* trx);
460 /****************************************************************************
461 Wakes up all async i/o threads so that they know to exit themselves in
462 shutdown. */
6f73e838
ER		 463diff -r 25523be1816e innobase/include/srv0srv.h
464--- a/innobase/include/srv0srv.h Mon Dec 22 00:25:06 2008 -0800
465+++ b/innobase/include/srv0srv.h Mon Dec 22 00:26:39 2008 -0800
466@@ -26,6 +26,8 @@
467 at a time */
468 #define SRV_AUTO_EXTEND_INCREMENT \
469 (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
470+
471+extern ibool srv_slow_log;
472
473 /* This is set to TRUE if the MySQL user has set it in MySQL */
474 extern ibool srv_lower_case_table_names;
475diff -r 25523be1816e innobase/include/trx0trx.h
476--- a/innobase/include/trx0trx.h Mon Dec 22 00:25:06 2008 -0800
477+++ b/innobase/include/trx0trx.h Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 478@@ -668,6 +668,17 @@
479 /*------------------------------*/
480 char detailed_error[256]; /* detailed error message for last
481 error, or empty. */
482+ /*------------------------------*/
833f2639
ER		 483+ ulint io_reads;
484+ ib_longlong io_read;
485+ ulint io_reads_wait_timer;
486+ ib_longlong lock_que_wait_ustarted;
487+ ulint lock_que_wait_timer;
488+ ulint innodb_que_wait_timer;
489+ ulint distinct_page_access;
490+#define DPAH_SIZE 8192
491+ byte* distinct_page_access_hash;
6f73e838 492+ ibool take_stats;
833f2639
ER		 493 };
494
495 #define TRX_MAX_N_THREADS 32 /* maximum number of concurrent
6f73e838
ER		 496diff -r 25523be1816e innobase/lock/lock0lock.c
497--- a/innobase/lock/lock0lock.c Mon Dec 22 00:25:06 2008 -0800
498+++ b/innobase/lock/lock0lock.c Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 499@@ -1806,6 +1806,8 @@
500 {
501 lock_t* lock;
502 trx_t* trx;
503+ ulint sec;
504+ ulint ms;
505
506 #ifdef UNIV_SYNC_DEBUG
507 ut_ad(mutex_own(&kernel_mutex));
6f73e838 508@@ -1861,6 +1863,10 @@
833f2639
ER		 509 trx->que_state = TRX_QUE_LOCK_WAIT;
510 trx->was_chosen_as_deadlock_victim = FALSE;
511 trx->wait_started = time(NULL);
6f73e838
ER		 512+ if (srv_slow_log && trx->take_stats) {
513+ ut_usectime(&sec, &ms);
514+ trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
515+ }
833f2639
ER		 516
517 ut_a(que_thr_stop(thr));
518
6f73e838 519@@ -3514,7 +3520,9 @@
833f2639
ER		 520 {
521 lock_t* lock;
522 trx_t* trx;
523-
524+ ulint sec;
525+ ulint ms;
526+
527 #ifdef UNIV_SYNC_DEBUG
528 ut_ad(mutex_own(&kernel_mutex));
529 #endif /* UNIV_SYNC_DEBUG */
6f73e838 530@@ -3564,6 +3572,10 @@
833f2639
ER		 531 return(DB_SUCCESS);
532 }
6f73e838
ER		 533
534+ if (srv_slow_log && trx->take_stats) {
535+ ut_usectime(&sec, &ms);
536+ trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
537+ }
833f2639
ER		 538 trx->que_state = TRX_QUE_LOCK_WAIT;
539 trx->was_chosen_as_deadlock_victim = FALSE;
540 trx->wait_started = time(NULL);
6f73e838
ER		 541diff -r 25523be1816e innobase/os/os0file.c
542--- a/innobase/os/os0file.c Mon Dec 22 00:25:06 2008 -0800
543+++ b/innobase/os/os0file.c Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 544@@ -14,6 +14,7 @@
545 #include "srv0start.h"
546 #include "fil0fil.h"
547 #include "buf0buf.h"
548+#include "trx0sys.h"
549
550 #if defined(UNIV_HOTBACKUP) && defined(__WIN__)
551 /* Add includes for the _stat() call to compile on Windows */
6f73e838 552@@ -1903,9 +1904,13 @@
833f2639
ER		 553 #ifndef __WIN__
554 /***********************************************************************
555 Does a synchronous read operation in Posix. */
556+
557+#define os_file_pread(file, buf, n, offset, offset_high) \
558+ _os_file_pread(file, buf, n, offset, offset_high, NULL);
559+
560 static
561 ssize_t
562-os_file_pread(
563+_os_file_pread(
564 /*==========*/
565 /* out: number of bytes read, -1 if error */
566 os_file_t file, /* in: handle to a file */
6f73e838 567@@ -1913,12 +1918,17 @@
833f2639
ER		 568 ulint n, /* in: number of bytes to read */
569 ulint offset, /* in: least significant 32 bits of file
570 offset from where to read */
571- ulint offset_high) /* in: most significant 32 bits of
572- offset */
573+ ulint offset_high, /* in: most significant 32 bits of
574+ offset */
575+ trx_t* trx)
576 {
577 off_t offs;
578 ssize_t n_bytes;
579-
580+ ulint sec;
581+ ulint ms;
582+ ib_longlong start_time;
583+ ib_longlong finish_time;
584+
585 ut_a((offset & 0xFFFFFFFFUL) == offset);
586
587 /* If off_t is > 4 bytes in size, then we assume we can pass a
6f73e838 588@@ -1937,7 +1947,13 @@
833f2639
ER		 589 }
590
591 os_n_file_reads++;
592-
6f73e838 593+ if (srv_slow_log && trx && trx->take_stats)
833f2639
ER		 594+ {
595+ trx->io_reads++;
596+ trx->io_read += n;
597+ ut_usectime(&sec, &ms);
598+ start_time = (ib_longlong)sec * 1000000 + ms;
599+ }
600 #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
601 os_mutex_enter(os_file_count_mutex);
602 os_file_n_pending_preads++;
6f73e838 603@@ -1951,6 +1967,13 @@
833f2639
ER		 604 os_n_pending_reads--;
605 os_mutex_exit(os_file_count_mutex);
606
6f73e838 607+ if (srv_slow_log && trx && trx->take_stats && start_time)
833f2639
ER		 608+ {
609+ ut_usectime(&sec, &ms);
610+ finish_time = (ib_longlong)sec * 1000000 + ms;
611+ trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
612+ }
613+
614 return(n_bytes);
615 #else
616 {
6f73e838 617@@ -1980,6 +2003,13 @@
833f2639
ER		 618 os_mutex_enter(os_file_count_mutex);
619 os_n_pending_reads--;
620 os_mutex_exit(os_file_count_mutex);
621+
6f73e838 622+ if (srv_slow_log && trx && trx->take_stats && start_time)
833f2639
ER		 623+ {
624+ ut_usectime(&sec, &ms);
625+ finish_time = (ib_longlong)sec * 1000000 + ms;
626+ trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
627+ }
628
629 return(ret);
630 }
6f73e838 631@@ -2103,7 +2133,7 @@
833f2639
ER		 632 Requests a synchronous positioned read operation. */
633
634 ibool
635-os_file_read(
636+_os_file_read(
637 /*=========*/
638 /* out: TRUE if request was
639 successful, FALSE if fail */
6f73e838 640@@ -2113,7 +2143,8 @@
833f2639
ER		 641 offset where to read */
642 ulint offset_high, /* in: most significant 32 bits of
643 offset */
644- ulint n) /* in: number of bytes to read */
645+ ulint n, /* in: number of bytes to read */
646+ trx_t* trx)
647 {
648 #ifdef __WIN__
649 BOOL ret;
833f2639
ER		 650@@ -2177,7 +2208,7 @@
651 os_bytes_read_since_printout += n;
652
653 try_again:
654- ret = os_file_pread(file, buf, n, offset, offset_high);
655+ ret = _os_file_pread(file, buf, n, offset, offset_high, trx);
656
657 if ((ulint)ret == n) {
658
659@@ -3137,7 +3168,8 @@
660 offset */
661 ulint offset_high, /* in: most significant 32 bits of
662 offset */
663- ulint len) /* in: length of the block to read or write */
664+ ulint len, /* in: length of the block to read or write */
665+ trx_t* trx)
666 {
667 os_aio_slot_t* slot;
668 #ifdef WIN_ASYNC_IO
833f2639
ER		 669@@ -3390,7 +3422,8 @@
670 can be used to identify a completed aio
671 operation); if mode is OS_AIO_SYNC, these
672 are ignored */
673- void* message2)
674+ void* message2,
675+ trx_t* trx)
676 {
677 os_aio_array_t* array;
678 os_aio_slot_t* slot;
679@@ -3429,8 +3462,8 @@
680 wait in the Windows case. */
681
682 if (type == OS_FILE_READ) {
683- return(os_file_read(file, buf, offset,
684- offset_high, n));
685+ return(_os_file_read(file, buf, offset,
686+ offset_high, n, trx));
687 }
688
689 ut_a(type == OS_FILE_WRITE);
6f73e838 690@@ -3463,8 +3496,13 @@
833f2639
ER		 691 ut_error;
692 }
693
694+ if (trx && type == OS_FILE_READ)
695+ {
696+ trx->io_reads++;
697+ trx->io_read += n;
698+ }
699 slot = os_aio_array_reserve_slot(type, array, message1, message2, file,
700- name, buf, offset, offset_high, n);
701+ name, buf, offset, offset_high, n, trx);
702 if (type == OS_FILE_READ) {
703 if (os_aio_use_native_aio) {
704 #ifdef WIN_ASYNC_IO
6f73e838
ER		 705diff -r 25523be1816e innobase/srv/srv0srv.c
706--- a/innobase/srv/srv0srv.c Mon Dec 22 00:25:06 2008 -0800
707+++ b/innobase/srv/srv0srv.c Mon Dec 22 00:26:39 2008 -0800
708@@ -47,6 +47,8 @@
709 #include "dict0boot.h"
710 #include "srv0start.h"
711 #include "row0mysql.h"
712+
713+ibool srv_slow_log = 0;
833f2639 714
6f73e838
ER		 715 /* This is set to TRUE if the MySQL user has set it in MySQL; currently
716 affects only FOREIGN KEY definition parsing */
717@@ -996,6 +998,10 @@
833f2639
ER		 718 ibool has_slept = FALSE;
719 srv_conc_slot_t* slot = NULL;
720 ulint i;
721+ ib_longlong start_time = 0L;
722+ ib_longlong finish_time = 0L;
723+ ulint sec;
724+ ulint ms;
725
726 /* If trx has 'free tickets' to enter the engine left, then use one
727 such ticket */
6f73e838 728@@ -1054,6 +1060,7 @@
833f2639
ER		 729 if (SRV_THREAD_SLEEP_DELAY > 0)
730 {
731 os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
732+ trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
733 }
734
735 trx->op_info = "";
6f73e838 736@@ -1109,11 +1116,22 @@
833f2639
ER		 737 /* Go to wait for the event; when a thread leaves InnoDB it will
738 release this thread */
739
6f73e838
ER		 740+ if (srv_slow_log && trx->take_stats) {
741+ ut_usectime(&sec, &ms);
742+ start_time = (ib_longlong)sec * 1000000 + ms;
743+ }
833f2639
ER		 744+
745 trx->op_info = "waiting in InnoDB queue";
746
747 os_event_wait(slot->event);
748
749 trx->op_info = "";
750+
6f73e838
ER		 751+ if (srv_slow_log && trx->take_stats && start_time) {
752+ ut_usectime(&sec, &ms);
753+ finish_time = (ib_longlong)sec * 1000000 + ms;
754+ trx->innodb_que_wait_timer += (ulint)(finish_time - start_time);
755+ }
833f2639
ER		 756
757 os_fast_mutex_lock(&srv_conc_mutex);
758
6f73e838
ER		 759diff -r 25523be1816e innobase/trx/trx0trx.c
760--- a/innobase/trx/trx0trx.c Mon Dec 22 00:25:06 2008 -0800
761+++ b/innobase/trx/trx0trx.c Mon Dec 22 00:26:39 2008 -0800
762@@ -190,6 +190,15 @@
833f2639
ER		 763 trx->global_read_view_heap = mem_heap_create(256);
764 trx->global_read_view = NULL;
765 trx->read_view = NULL;
766+
767+ trx->io_reads = 0;
768+ trx->io_read = 0;
769+ trx->io_reads_wait_timer = 0;
770+ trx->lock_que_wait_timer = 0;
771+ trx->innodb_que_wait_timer = 0;
772+ trx->distinct_page_access = 0;
773+ trx->distinct_page_access_hash = NULL;
6f73e838 774+ trx->take_stats = FALSE;
833f2639
ER		 775
776 /* Set X/Open XA transaction identification to NULL */
777 memset(&trx->xid, 0, sizeof(trx->xid));
6f73e838 778@@ -230,6 +239,11 @@
833f2639
ER		 779
780 trx->mysql_process_no = os_proc_get_number();
781
6f73e838
ER		 782+ if (srv_slow_log && trx->take_stats) {
783+ trx->distinct_page_access_hash = mem_alloc(DPAH_SIZE);
784+ memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
785+ }
833f2639
ER		 786+
787 return(trx);
788 }
789
6f73e838 790@@ -366,6 +380,12 @@
833f2639
ER		 791 /*===============*/
792 trx_t* trx) /* in, own: trx object */
793 {
794+ if (trx->distinct_page_access_hash)
795+ {
796+ mem_free(trx->distinct_page_access_hash);
797+ trx->distinct_page_access_hash= NULL;
798+ }
799+
800 thr_local_free(trx->mysql_thread_id);
801
802 mutex_enter(&kernel_mutex);
6f73e838
ER		 803@@ -389,6 +409,12 @@
804 /*====================*/
805 trx_t* trx) /* in, own: trx object */
806 {
807+ if (trx->distinct_page_access_hash)
808+ {
809+ mem_free(trx->distinct_page_access_hash);
810+ trx->distinct_page_access_hash= NULL;
811+ }
812+
813 mutex_enter(&kernel_mutex);
814
815 trx_free(trx);
816@@ -1064,7 +1090,10 @@
833f2639
ER		 817 trx_t* trx) /* in: transaction */
818 {
819 que_thr_t* thr;
820-
821+ ulint sec;
822+ ulint ms;
823+ ib_longlong now;
824+
825 #ifdef UNIV_SYNC_DEBUG
826 ut_ad(mutex_own(&kernel_mutex));
827 #endif /* UNIV_SYNC_DEBUG */
6f73e838 828@@ -1080,6 +1109,11 @@
833f2639
ER		 829 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
830 }
831
6f73e838
ER		 832+ if (srv_slow_log && trx->take_stats) {
833+ ut_usectime(&sec, &ms);
834+ now = (ib_longlong)sec * 1000000 + ms;
835+ trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
836+ }
833f2639
ER		 837 trx->que_state = TRX_QUE_RUNNING;
838 }
839
6f73e838 840@@ -1093,6 +1127,9 @@
833f2639
ER		 841 trx_t* trx) /* in: transaction in the TRX_QUE_LOCK_WAIT state */
842 {
843 que_thr_t* thr;
844+ ulint sec;
845+ ulint ms;
846+ ib_longlong now;
847
848 #ifdef UNIV_SYNC_DEBUG
849 ut_ad(mutex_own(&kernel_mutex));
6f73e838 850@@ -1109,6 +1146,11 @@
833f2639
ER		 851 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
852 }
853
6f73e838
ER		 854+ if (srv_slow_log && trx->take_stats) {
855+ ut_usectime(&sec, &ms);
856+ now = (ib_longlong)sec * 1000000 + ms;
857+ trx->lock_que_wait_timer += (ulint)(now - trx->lock_que_wait_ustarted);
858+ }
833f2639
ER		 859 trx->que_state = TRX_QUE_RUNNING;
860 }
861
6f73e838
ER		 862diff -r 25523be1816e mysys/my_getopt.c
863--- a/mysys/my_getopt.c Mon Dec 22 00:25:06 2008 -0800
864+++ b/mysys/my_getopt.c Mon Dec 22 00:26:39 2008 -0800
865@@ -1061,6 +1061,9 @@
866 case GET_ULONG:
867 printf("%lu\n", *((ulong*) value));
868 break;
869+ case GET_DOUBLE:
870+ printf("%6f\n", *((double*) value));
871+ break;
872 case GET_LL:
873 printf("%s\n", llstr(*((longlong*) value), buff));
874 break;
875diff -r 25523be1816e patch_info/microslow_innodb.info
833f2639 876--- /dev/null Thu Jan 01 00:00:00 1970 +0000
6f73e838
ER		 877+++ b/patch_info/microslow_innodb.info Mon Dec 22 00:26:39 2008 -0800
878@@ -0,0 +1,15 @@
833f2639
ER		 879+File=microslow_innodb.patch
880+Name=Extended statistics in slow.log
dcc72bc6 881+Version=1.2
833f2639
ER		 882+Author=Percona <info@percona.com>
883+License=GPL
884+Comment=
6f73e838
ER		 885+Changelog
886+2008-11-26
887+YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
888+
889+2008-11-07
890+VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
891+
892+2008-11
893+Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
894diff -r 25523be1816e scripts/mysqldumpslow.sh
895--- a/scripts/mysqldumpslow.sh Mon Dec 22 00:25:06 2008 -0800
896+++ b/scripts/mysqldumpslow.sh Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 897@@ -83,8 +83,8 @@
898 s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
899 my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
900
901- s/^# Query_time: (\d+) Lock_time: (\d+) Rows_sent: (\d+).*\n//;
902- my ($t, $l, $r) = ($1, $2, $3);
903+ s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//;
904+ my ($t, $l, $r) = ($1, $3, $5);
905 $t -= $l unless $opt{l};
906
907 # remove fluff that mysqld writes to log when it (re)starts:
6f73e838
ER		 908diff -r 25523be1816e sql-common/my_time.c
909--- a/sql-common/my_time.c Mon Dec 22 00:25:06 2008 -0800
910+++ b/sql-common/my_time.c Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 911@@ -1252,3 +1252,37 @@
912 return 0;
913 }
914
915+/*
916+ int my_timer(ulonglong *ltime, ulonglong frequency)
917+
918+ For performance measurement this function returns the number
919+ of microseconds since the epoch (SVr4, BSD 4.3, POSIX 1003.1-2001)
920+ or system start (Windows platforms).
921+
922+ For windows platforms frequency value (obtained via
923+ QueryPerformanceFrequency) has to be specified. The global frequency
924+ value is set in mysqld.cc.
925+
926+ If Windows platform doesn't support QueryPerformanceFrequency we will
927+ obtain the time via GetClockCount, which supports microseconds only.
928+*/
929+
930+ulonglong my_timer(ulonglong *ltime, ulonglong frequency)
931+{
932+ ulonglong newtime= 0;
933+#ifdef __WIN__
934+ if (frequency)
935+ {
936+ QueryPerformanceCounter((LARGE_INTEGER *)&newtime);
937+ newtime/= (frequency * 1000000);
938+ } else
939+ newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */
940+#else
941+ struct timeval t;
dcc72bc6
ER		 942+ if (gettimeofday(&t, NULL) != -1)
943+ newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
833f2639
ER		 944+#endif
945+ if (ltime)
946+ *ltime= newtime;
947+ return newtime;
948+}
6f73e838
ER		 949diff -r 25523be1816e sql/filesort.cc
950--- a/sql/filesort.cc Mon Dec 22 00:25:06 2008 -0800
951+++ b/sql/filesort.cc Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 952@@ -180,6 +180,7 @@
953 {
954 statistic_increment(thd->status_var.filesort_scan_count, &LOCK_status);
955 }
956+ thd->query_plan_flags|= QPLAN_FILESORT;
957 #ifdef CAN_TRUST_RANGE
958 if (select && select->quick && select->quick->records > 0L)
959 {
960@@ -245,6 +246,7 @@
961 }
962 else
963 {
964+ thd->query_plan_flags|= QPLAN_FILESORT_DISK;
965 if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
966 {
967 x_free(table_sort.buffpek);
968@@ -1116,6 +1118,7 @@
969
970 statistic_increment(current_thd->status_var.filesort_merge_passes,
971 &LOCK_status);
972+ current_thd->query_plan_fsort_passes++;
973 if (param->not_killable)
974 {
975 killed= &not_killable;
6f73e838
ER		 976diff -r 25523be1816e sql/ha_innodb.cc
977--- a/sql/ha_innodb.cc Mon Dec 22 00:25:06 2008 -0800
978+++ b/sql/ha_innodb.cc Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 979@@ -1,3 +1,4 @@
980+
981 /* Copyright (C) 2000-2005 MySQL AB & Innobase Oy
982
983 This program is free software; you can redistribute it and/or modify
6f73e838
ER		 984@@ -805,9 +806,34 @@
985 trx->check_unique_secondary = TRUE;
986 }
987
988+ if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
989+ trx->take_stats = TRUE;
990+ } else {
991+ trx->take_stats = FALSE;
992+ }
993+
994 return(trx);
995 }
996
997+/*************************************************************************
998+Gets current trx. */
999+extern "C"
1000+trx_t*
1001+innobase_get_trx()
1002+{
1003+ THD *thd=current_thd;
1004+ if (likely(thd != 0)) {
1005+ return((trx_t*) thd->ha_data[innobase_hton.slot]);
1006+ } else {
1007+ return(NULL);
1008+ }
1009+}
1010+
1011+void
1012+innobase_update_var_slow_log()
1013+{
1014+ srv_slow_log = (ibool) opt_slow_log;
1015+}
1016
1017 /*************************************************************************
1018 Construct ha_innobase handler. */
1019@@ -1309,6 +1335,8 @@
1020 }
1021
1022 /* -------------- Log files ---------------------------*/
1023+
1024+ srv_slow_log = (ibool) opt_slow_log;
1025
1026 /* The default dir for log files is the datadir of MySQL */
1027
1028@@ -4673,6 +4701,12 @@
1029 trx->check_unique_secondary = FALSE;
1030 }
1031
1032+ if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1033+ trx->take_stats = TRUE;
1034+ } else {
1035+ trx->take_stats = FALSE;
1036+ }
1037+
1038 if (lower_case_table_names) {
1039 srv_lower_case_table_names = TRUE;
1040 } else {
1041@@ -4938,6 +4972,12 @@
1042 trx->check_unique_secondary = FALSE;
1043 }
1044
1045+ if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1046+ trx->take_stats = TRUE;
1047+ } else {
1048+ trx->take_stats = FALSE;
1049+ }
1050+
1051 name_len = strlen(name);
1052
1053 assert(name_len < 1000);
1054@@ -5025,6 +5065,12 @@
1055 trx->check_foreigns = FALSE;
1056 }
1057
1058+ if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1059+ trx->take_stats = TRUE;
1060+ } else {
1061+ trx->take_stats = FALSE;
1062+ }
1063+
1064 error = row_drop_database_for_mysql(namebuf, trx);
1065 my_free(namebuf, MYF(0));
1066
1067@@ -5089,6 +5135,12 @@
1068
1069 if (current_thd->options & OPTION_NO_FOREIGN_KEY_CHECKS) {
1070 trx->check_foreigns = FALSE;
1071+ }
1072+
1073+ if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1074+ trx->take_stats = TRUE;
1075+ } else {
1076+ trx->take_stats = FALSE;
1077 }
1078
1079 name_len1 = strlen(from);
1080@@ -6098,6 +6150,7 @@
833f2639
ER		 1081 {
1082 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
1083 trx_t* trx;
1084+ int i;
1085
1086 DBUG_ENTER("ha_innobase::external_lock");
1087 DBUG_PRINT("enter",("lock_type: %d", lock_type));
6f73e838 1088@@ -6221,7 +6274,24 @@
833f2639
ER		 1089
1090 if (trx->n_mysql_tables_in_use == 0) {
1091
1092- trx->mysql_n_tables_locked = 0;
1093+ current_thd->innodb_was_used = TRUE;
1094+ current_thd->innodb_io_reads += trx->io_reads;
1095+ current_thd->innodb_io_read += trx->io_read;
1096+ current_thd->innodb_io_reads_wait_timer += trx->io_reads_wait_timer;
1097+ current_thd->innodb_lock_que_wait_timer += trx->lock_que_wait_timer;
1098+ current_thd->innodb_innodb_que_wait_timer += trx->innodb_que_wait_timer;
1099+ current_thd->innodb_page_access += trx->distinct_page_access;
1100+
1101+ trx->io_reads = 0;
1102+ trx->io_read = 0;
1103+ trx->io_reads_wait_timer = 0;
1104+ trx->lock_que_wait_timer = 0;
1105+ trx->innodb_que_wait_timer = 0;
1106+ trx->distinct_page_access = 0;
1107+ if (trx->distinct_page_access_hash)
1108+ memset(trx->distinct_page_access_hash, 0, DPAH_SIZE);
1109+
1110+ trx->mysql_n_tables_locked = 0;
1111 prebuilt->used_in_HANDLER = FALSE;
1112
1113 if (!(thd->options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN))) {
6f73e838
ER		 1114diff -r 25523be1816e sql/ha_innodb.h
1115--- a/sql/ha_innodb.h Mon Dec 22 00:25:06 2008 -0800
1116+++ b/sql/ha_innodb.h Mon Dec 22 00:26:39 2008 -0800
1117@@ -266,6 +266,8 @@
1118
1119 int innobase_start_trx_and_assign_read_view(THD* thd);
1120
1121+void innobase_update_var_slow_log();
1122+
1123 /***********************************************************************
1124 This function is used to prepare X/Open XA distributed transaction */
1125
1126diff -r 25523be1816e sql/log.cc
1127--- a/sql/log.cc Mon Dec 22 00:25:06 2008 -0800
1128+++ b/sql/log.cc Mon Dec 22 00:26:39 2008 -0800
1129@@ -2229,11 +2229,12 @@
833f2639
ER		 1130 */
1131
1132 bool MYSQL_LOG::write(THD *thd,const char *query, uint query_length,
1133- time_t query_start_arg)
1134+ time_t query_start_arg, ulonglong query_start_timer)
1135 {
1136 bool error=0;
1137 time_t current_time;
6f73e838 1138- if (!is_open())
833f2639 1139+ ulonglong current_timer;
6f73e838 1140+ if (!opt_slow_log || !is_open())
833f2639
ER		 1141 return 0;
1142 DBUG_ENTER("MYSQL_LOG::write");
6f73e838 1143
833f2639
ER		 1144@@ -2243,7 +2244,8 @@
1145 int tmp_errno=0;
1146 char buff[80],*end;
1147 end=buff;
1148- if (!(thd->options & OPTION_UPDATE_LOG))
1149+ if (!(thd->options & OPTION_UPDATE_LOG) &&
1150+ !(thd->slave_thread && opt_log_slow_slave_statements))
1151 {
1152 VOID(pthread_mutex_unlock(&LOCK_log));
1153 DBUG_RETURN(0);
dcc72bc6 1154@@ -2273,22 +2275,72 @@
833f2639
ER		 1155 if (my_b_printf(&log_file, "# User@Host: %s[%s] @ %s [%s]\n",
1156 sctx->priv_user ?
1157 sctx->priv_user : "",
1158- sctx->user ? sctx->user : "",
1159+ sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""),
1160 sctx->host ? sctx->host : "",
1161 sctx->ip ? sctx->ip : "") ==
1162 (uint) -1)
1163 tmp_errno=errno;
1164 }
1165- if (query_start_arg)
1166+ if (query_start_timer)
1167 {
1168+ char buf[5][20];
1169+ ulonglong current_timer= my_timer(&current_timer, frequency);
dcc72bc6
ER		 1170+ snprintf(buf[0], 20, "%.6f", (current_timer ? (current_timer - query_start_timer):0) / 1000000.0);
1171+ snprintf(buf[1], 20, "%.6f", (thd->timer_after_lock - query_start_timer) / 1000000.0);
833f2639
ER		 1172+ if (!query_length)
1173+ {
1174+ thd->sent_row_count= thd->examined_row_count= 0;
dcc72bc6 1175+ thd->row_count= 0;
833f2639
ER		 1176+ thd->innodb_was_used= FALSE;
1177+ thd->query_plan_flags= QPLAN_NONE;
1178+ thd->query_plan_fsort_passes= 0;
1179+ }
1180+
1181 /* For slow query log */
1182 if (my_b_printf(&log_file,
1183- "# Query_time: %lu Lock_time: %lu Rows_sent: %lu Rows_examined: %lu\n",
1184- (ulong) (current_time - query_start_arg),
1185- (ulong) (thd->time_after_lock - query_start_arg),
1186+ "# Thread_id: %lu Schema: %s\n" \
6f73e838 1187+ "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n",
833f2639
ER		 1188+ (ulong) thd->thread_id, (thd->db ? thd->db : ""),
1189+ buf[0], buf[1],
1190 (ulong) thd->sent_row_count,
6f73e838
ER		 1191- (ulong) thd->examined_row_count) == (uint) -1)
1192+ (ulong) thd->examined_row_count,
1193+ ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
1194+ (ulong) thd->row_count) == (uint) -1)
833f2639
ER		 1195 tmp_errno=errno;
1196+ if ((thd->variables.log_slow_verbosity & SLOG_V_QUERY_PLAN) &&
1197+ my_b_printf(&log_file,
1198+ "# QC_Hit: %s Full_scan: %s Full_join: %s Tmp_table: %s Tmp_table_on_disk: %s\n" \
1199+ "# Filesort: %s Filesort_on_disk: %s Merge_passes: %lu\n",
1200+ ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
1201+ ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
1202+ ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
1203+ ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
1204+ ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
1205+ ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
1206+ ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
1207+ thd->query_plan_fsort_passes) == (uint) -1)
1208+ tmp_errno=errno;
1209+ if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) && thd->innodb_was_used)
1210+ {
dcc72bc6
ER		 1211+ snprintf(buf[2], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
1212+ snprintf(buf[3], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
1213+ snprintf(buf[4], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
833f2639
ER		 1214+ if (my_b_printf(&log_file,
1215+ "# InnoDB_IO_r_ops: %lu InnoDB_IO_r_bytes: %lu InnoDB_IO_r_wait: %s\n" \
1216+ "# InnoDB_rec_lock_wait: %s InnoDB_queue_wait: %s\n" \
1217+ "# InnoDB_pages_distinct: %lu\n",
1218+ (ulong) thd->innodb_io_reads,
1219+ (ulong) thd->innodb_io_read,
1220+ buf[2], buf[3], buf[4],
1221+ (ulong) thd->innodb_page_access) == (uint) -1)
1222+ tmp_errno=errno;
1223+ }
1224+ else
1225+ {
1226+ if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) &&
1227+ my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
1228+ tmp_errno=errno;
1229+ }
1230 }
1231 if (thd->db && strcmp(thd->db,db))
1232 { // Database changed
6f73e838
ER		 1233diff -r 25523be1816e sql/log_event.cc
1234--- a/sql/log_event.cc Mon Dec 22 00:25:06 2008 -0800
1235+++ b/sql/log_event.cc Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 1236@@ -2039,6 +2039,7 @@
1237 /* Execute the query (note that we bypass dispatch_command()) */
1238 const char* found_semicolon= NULL;
1239 mysql_parse(thd, thd->query, thd->query_length, &found_semicolon);
1240+ log_slow_statement(thd);
1241
1242 }
1243 else
6f73e838
ER		 1244diff -r 25523be1816e sql/mysql_priv.h
1245--- a/sql/mysql_priv.h Mon Dec 22 00:25:06 2008 -0800
1246+++ b/sql/mysql_priv.h Mon Dec 22 00:26:39 2008 -0800
1247@@ -489,6 +489,78 @@
833f2639
ER		 1248 #define WEEK_FIRST_WEEKDAY 4
1249
1250 #define STRING_BUFFER_USUAL_SIZE 80
1251+
1252+/* Slow log */
1253+
1254+struct msl_opts
1255+{
1256+ ulong val;
1257+ const char *name;
1258+};
1259+
1260+#define SLOG_V_MICROTIME 1 << 0
1261+#define SLOG_V_QUERY_PLAN 1 << 1
1262+#define SLOG_V_INNODB 1 << 2
1263+/* ... */
1264+#define SLOG_V_INVALID 1 << 31
1265+#define SLOG_V_NONE SLOG_V_MICROTIME
1266+
1267+static const struct msl_opts slog_verb[]=
1268+{
1269+ /* Basic flags */
1270+
1271+ { SLOG_V_MICROTIME, "microtime" },
1272+ { SLOG_V_QUERY_PLAN, "query_plan" },
1273+ { SLOG_V_INNODB, "innodb" },
1274+
1275+ /* End of baisc flags */
1276+
1277+ { 0, "" },
1278+
1279+ /* Complex flags */
1280+
1281+ { SLOG_V_MICROTIME, "minimal" },
1282+ { SLOG_V_MICROTIME|SLOG_V_QUERY_PLAN, "standard" },
1283+ { SLOG_V_MICROTIME|SLOG_V_QUERY_PLAN|SLOG_V_INNODB, "full" },
1284+
1285+ /* End of complex flags */
1286+
1287+ { SLOG_V_INVALID, (char *)0 }
1288+};
1289+
1290+#define QPLAN_NONE 0
1291+#define QPLAN_QC 1 << 0
1292+#define QPLAN_QC_NO 1 << 1
1293+#define QPLAN_FULL_SCAN 1 << 2
1294+#define QPLAN_FULL_JOIN 1 << 3
1295+#define QPLAN_TMP_TABLE 1 << 4
1296+#define QPLAN_TMP_DISK 1 << 5
1297+#define QPLAN_FILESORT 1 << 6
1298+#define QPLAN_FILESORT_DISK 1 << 7
1299+/* ... */
1300+#define QPLAN_MAX 1 << 31
1301+
1302+#define SLOG_F_QC_NO QPLAN_QC_NO
1303+#define SLOG_F_FULL_SCAN QPLAN_FULL_SCAN
1304+#define SLOG_F_FULL_JOIN QPLAN_FULL_JOIN
1305+#define SLOG_F_TMP_TABLE QPLAN_TMP_TABLE
1306+#define SLOG_F_TMP_DISK QPLAN_TMP_DISK
1307+#define SLOG_F_FILESORT QPLAN_FILESORT
1308+#define SLOG_F_FILESORT_DISK QPLAN_FILESORT_DISK
1309+#define SLOG_F_INVALID 1 << 31
1310+#define SLOG_F_NONE 0
1311+
1312+static const struct msl_opts slog_filter[]=
1313+{
1314+ { SLOG_F_QC_NO, "qc_miss" },
1315+ { SLOG_F_FULL_SCAN, "full_scan" },
1316+ { SLOG_F_FULL_JOIN, "full_join" },
1317+ { SLOG_F_TMP_TABLE, "tmp_table" },
1318+ { SLOG_F_TMP_DISK, "tmp_table_on_disk" },
1319+ { SLOG_F_FILESORT, "filesort" },
1320+ { SLOG_F_FILESORT_DISK, "filesort_on_disk" },
1321+ { SLOG_F_INVALID, (char *)0 }
1322+};
1323
1324 enum enum_parsing_place
1325 {
6f73e838
ER		 1326@@ -1345,6 +1417,7 @@
1327 extern bool using_update_log, opt_large_files, server_id_supplied;
1328 extern bool opt_update_log, opt_bin_log, opt_error_log;
1329 extern my_bool opt_log, opt_slow_log, opt_log_queries_not_using_indexes;
1330+extern char *opt_slow_logname;
1331 extern bool opt_disable_networking, opt_skip_show_db;
1332 extern my_bool opt_character_set_client_handshake;
1333 extern bool volatile abort_loop, shutdown_in_progress, grant_option;
dcc72bc6 1334@@ -1356,7 +1429,8 @@
833f2639
ER		 1335 extern my_bool opt_enable_named_pipe, opt_sync_frm, opt_allow_suspicious_udfs;
1336 extern my_bool opt_secure_auth;
1337 extern char* opt_secure_file_priv;
1338-extern my_bool opt_log_slow_admin_statements;
1339+extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
dcc72bc6 1340+extern my_bool opt_use_global_long_query_time;
833f2639
ER		 1341 extern my_bool sp_automatic_privileges, opt_noacl;
1342 extern my_bool opt_old_style_user_limits, trust_function_creators;
1343 extern uint opt_crash_binlog_innodb;
6f73e838
ER		 1344diff -r 25523be1816e sql/mysqld.cc
1345--- a/sql/mysqld.cc Mon Dec 22 00:25:06 2008 -0800
1346+++ b/sql/mysqld.cc Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 1347@@ -175,7 +175,6 @@
1348 static void getvolumename();
1349 static void getvolumeID(BYTE *volumeName);
1350 #endif /* __NETWARE__ */
1351-
1352
1353 #ifdef _AIX41
1354 int initgroups(const char *,unsigned int);
dcc72bc6 1355@@ -409,10 +408,13 @@
833f2639
ER		 1356 my_bool opt_secure_auth= 0;
1357 char* opt_secure_file_priv= 0;
1358 my_bool opt_log_slow_admin_statements= 0;
1359+my_bool opt_log_slow_slave_statements= 0;
dcc72bc6 1360+my_bool opt_use_global_long_query_time= 0;
833f2639
ER		 1361 my_bool lower_case_file_system= 0;
1362 my_bool opt_large_pages= 0;
1363 uint opt_large_page_size= 0;
6f73e838
ER		 1364 my_bool opt_old_style_user_limits= 0, trust_function_creators= 0;
1365+char* opt_slow_logname= 0;
1366 /*
1367 True if there is at least one per-hour limit for some user, so we should
1368 check them before each query (and possibly reset counters when hour is
1369@@ -507,6 +508,7 @@
833f2639
ER		 1370 Ge_creator ge_creator;
1371 Le_creator le_creator;
1372
1373+ulonglong frequency= 0;
1374
1375 FILE *bootstrap_file;
1376 int bootstrap_error;
6f73e838
ER		 1377@@ -584,7 +586,7 @@
1378 static int cleanup_done;
1379 static ulong opt_specialflag, opt_myisam_block_size;
1380 static char *opt_logname, *opt_update_logname, *opt_binlog_index_name;
1381-static char *opt_slow_logname, *opt_tc_heuristic_recover;
1382+static char *opt_tc_heuristic_recover;
1383 static char *mysql_home_ptr, *pidfile_name_ptr;
1384 static char **defaults_argv;
1385 static char *opt_bin_logname;
1386@@ -3655,6 +3657,8 @@
833f2639
ER		 1387 unireg_abort(1);
1388 }
1389 }
1390+ if (!QueryPerformanceFrequency((LARGE_INTEGER *)&frequency))
1391+ frequency= 0;
1392 #endif /* __WIN__ */
1393
1394 if (init_common_variables(MYSQL_CONFIG_NAME,
6f73e838 1395@@ -4901,7 +4905,7 @@
833f2639
ER		 1396 OPT_INTERACTIVE_TIMEOUT, OPT_JOIN_BUFF_SIZE,
1397 OPT_KEY_BUFFER_SIZE, OPT_KEY_CACHE_BLOCK_SIZE,
1398 OPT_KEY_CACHE_DIVISION_LIMIT, OPT_KEY_CACHE_AGE_THRESHOLD,
1399- OPT_LONG_QUERY_TIME,
1400+ OPT_LONG_QUERY_TIME, OPT_MIN_EXAMINED_ROW_LIMIT,
1401 OPT_LOWER_CASE_TABLE_NAMES, OPT_MAX_ALLOWED_PACKET,
1402 OPT_MAX_BINLOG_CACHE_SIZE, OPT_MAX_BINLOG_SIZE,
1403 OPT_MAX_CONNECTIONS, OPT_MAX_CONNECT_ERRORS,
dcc72bc6 1404@@ -4992,11 +4996,18 @@
833f2639
ER		 1405 OPT_TIMED_MUTEXES,
1406 OPT_OLD_STYLE_USER_LIMITS,
1407 OPT_LOG_SLOW_ADMIN_STATEMENTS,
1408+ OPT_LOG_SLOW_SLAVE_STATEMENTS,
1409+ OPT_LOG_SLOW_RATE_LIMIT,
1410+ OPT_LOG_SLOW_VERBOSITY,
1411+ OPT_LOG_SLOW_FILTER,
1412 OPT_TABLE_LOCK_WAIT_TIMEOUT,
6f73e838 1413 OPT_PLUGIN_DIR,
833f2639
ER		 1414 OPT_PORT_OPEN_TIMEOUT,
1415 OPT_MERGE,
6f73e838
ER		 1416 OPT_PROFILING,
1417+ OPT_SLOW_LOG,
1418+ OPT_SLOW_QUERY_LOG_FILE,
dcc72bc6 1419+ OPT_USE_GLOBAL_LONG_QUERY_TIME,
6f73e838
ER		 1420 OPT_INNODB_ROLLBACK_ON_TIMEOUT,
1421 OPT_SECURE_FILE_PRIV,
1422 OPT_KEEP_FILES_ON_CREATE,
1423@@ -5386,8 +5396,17 @@
833f2639
ER		 1424 (gptr*) &opt_log_slow_admin_statements,
1425 (gptr*) &opt_log_slow_admin_statements,
6f73e838 1426 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
833f2639
ER		 1427+ {"log-slow-slave-statements", OPT_LOG_SLOW_SLAVE_STATEMENTS,
1428+ "Log slow replicated statements to the slow log if it is open.",
1429+ (gptr*) &opt_log_slow_slave_statements,
1430+ (gptr*) &opt_log_slow_slave_statements,
6f73e838 1431+ 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
833f2639
ER		 1432 {"log-slow-queries", OPT_SLOW_QUERY_LOG,
1433 "Log slow queries to this log file. Defaults logging to hostname-slow.log file. Must be enabled to activate other slow log options.",
6f73e838
ER		 1434+ (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1435+ 0, 0, 0, 0, 0, 0},
1436+ {"slow_query_log_file", OPT_SLOW_QUERY_LOG_FILE,
1437+ "Log slow queries to given log file. Defaults logging to hostname-slow.log. Must be enabled to activate other slow log options.",
1438 (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1439 0, 0, 0, 0, 0, 0},
1440 {"log-tc", OPT_LOG_TC,
1441@@ -5753,6 +5772,9 @@
1442 "Tells the slave thread to continue replication when a query returns an error from the provided list.",
1443 0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
1444 #endif
1445+ {"slow-query-log", OPT_SLOW_LOG,
1446+ "Enable|disable slow query log", (gptr*) &opt_slow_log,
1447+ (gptr*) &opt_slow_log, 0, GET_BOOL, OPT_ARG, 0, 0, 0, 0, 0, 0},
1448 {"socket", OPT_SOCKET, "Socket file to use for connection.",
1449 (gptr*) &mysqld_unix_port, (gptr*) &mysqld_unix_port, 0, GET_STR,
1450 REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
dcc72bc6 1451@@ -6055,11 +6077,31 @@
833f2639
ER		 1452 (gptr*) 0,
1453 0, (GET_ULONG | GET_ASK_ADDR) , REQUIRED_ARG, 100,
1454 1, 100, 0, 1, 0},
6f73e838
ER		 1455- {"long_query_time", OPT_LONG_QUERY_TIME,
1456- "Log all queries that have taken more than long_query_time seconds to execute to file.",
1457- (gptr*) &global_system_variables.long_query_time,
1458- (gptr*) &max_system_variables.long_query_time, 0, GET_ULONG,
1459- REQUIRED_ARG, 10, 1, LONG_TIMEOUT, 0, 1, 0},
833f2639
ER		 1460+ {"log_slow_filter", OPT_LOG_SLOW_FILTER,
1461+ "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]",
1462+ 0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, SLOG_F_NONE, 0, 0},
1463+ {"log_slow_rate_limit", OPT_LOG_SLOW_RATE_LIMIT,
1464+ "Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
1465+ (gptr*) &global_system_variables.log_slow_rate_limit,
1466+ (gptr*) &max_system_variables.log_slow_rate_limit, 0, GET_ULONG,
6f73e838 1467+ REQUIRED_ARG, 1, 1, LONG_MAX, 0, 1L, 0},
833f2639
ER		 1468+ {"log_slow_verbosity", OPT_LOG_SLOW_VERBOSITY,
1469+ "Choose how verbose the messages to your slow log will be. Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb]",
1470+ 0, 0, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, SLOG_V_MICROTIME, 0, 0},
6f73e838
ER		 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_DOUBLE,
833f2639
ER		 1475+ REQUIRED_ARG, 10000000, 0, LONG_TIMEOUT * 1000000, 0, 1, 0},
1476+ {"min_examined_row_limit", OPT_MIN_EXAMINED_ROW_LIMIT,
1477+ "Don't log queries which examine less than min_examined_row_limit rows to file.",
1478+ (gptr*) &global_system_variables.min_examined_row_limit,
1479+ (gptr*) &max_system_variables.min_examined_row_limit, 0, GET_ULONG,
6f73e838 1480+ REQUIRED_ARG, 0, 0, LONG_MAX, 0, 1L, 0},
dcc72bc6
ER		 1481+ {"use_global_long_query_time", OPT_USE_GLOBAL_LONG_QUERY_TIME,
1482+ "Control always use global long_query_time or local long_query_time.",
1483+ (gptr*) &opt_use_global_long_query_time, (gptr*) &opt_use_global_long_query_time,
1484+ 0, GET_BOOL, NO_ARG, 0, 0, 1, 0, 1, 0},
833f2639
ER		 1485 {"lower_case_table_names", OPT_LOWER_CASE_TABLE_NAMES,
1486 "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",
1487 (gptr*) &lower_case_table_names,
6f73e838 1488@@ -6835,7 +6873,11 @@
833f2639
ER		 1489 global_system_variables.max_join_size= (ulonglong) HA_POS_ERROR;
1490 max_system_variables.max_join_size= (ulonglong) HA_POS_ERROR;
1491 global_system_variables.old_passwords= 0;
1492-
6f73e838
ER		 1493+ global_system_variables.long_query_time = 10000000;
1494+ max_system_variables.long_query_time = LONG_TIMEOUT * 1000000;
833f2639
ER		 1495+ global_system_variables.log_slow_verbosity= SLOG_V_MICROTIME;
1496+ global_system_variables.log_slow_filter= SLOG_F_NONE;
1497+
1498 /*
1499 Default behavior for 4.1 and 5.0 is to treat NULL values as unequal
1500 when collecting index statistics for MyISAM tables.
6f73e838 1501@@ -7296,6 +7338,35 @@
833f2639
ER		 1502 case OPT_BOOTSTRAP:
1503 opt_noacl=opt_bootstrap=1;
1504 break;
1505+ case OPT_LOG_SLOW_FILTER:
1506+ if ((global_system_variables.log_slow_filter=
1507+ msl_flag_resolve_by_name(slog_filter, argument,
1508+ SLOG_F_NONE, SLOG_F_INVALID)) == SLOG_F_INVALID)
1509+ {
6f73e838 1510+ fprintf(stderr,"Invalid argument in log_slow_filter: %s\n", argument);
833f2639
ER		 1511+ exit(1);
1512+ }
1513+ break;
1514+ case OPT_LOG_SLOW_VERBOSITY:
1515+ if ((global_system_variables.log_slow_verbosity=
1516+ msl_flag_resolve_by_name(slog_verb, argument,
1517+ SLOG_V_NONE, SLOG_V_INVALID)) == SLOG_V_INVALID)
1518+ {
6f73e838
ER		 1519+ fprintf(stderr,"Invalid argument in log_slow_verbosity: %s\n", argument);
1520+ exit(1);
1521+ }
1522+ break;
1523+ case OPT_LONG_QUERY_TIME:
1524+ {
1525+ double doubleslow = strtod(argument,NULL);
1526+ if (doubleslow < 0 || doubleslow > (LONG_TIMEOUT))
1527+ {
1528+ fprintf(stderr,"Out of range long_query_time value: %s\n", argument);
833f2639
ER		 1529+ exit(1);
1530+ }
6f73e838 1531+ global_system_variables.long_query_time = (ulonglong) (doubleslow * 1000000);
833f2639 1532+ break;
6f73e838 1533+ }
833f2639
ER		 1534 case OPT_STORAGE_ENGINE:
1535 {
1536 if ((enum db_type)((global_system_variables.table_type=
6f73e838 1537@@ -7628,10 +7699,14 @@
833f2639
ER		 1538 if (opt_bdb)
1539 sql_print_warning("this binary does not contain BDB storage engine");
1540 #endif
1541- if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes) &&
1542+ if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes ||
1543+ opt_log_slow_slave_statements) &&
1544 !opt_slow_log)
1545- sql_print_warning("options --log-slow-admin-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set");
1546-
1547+ {
1548+ 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");
1549+ opt_log_slow_slave_statements= FALSE;
1550+ }
1551+
1552 if (argc > 0)
1553 {
1554 fprintf(stderr, "%s: Too many arguments (first extra is '%s').\nUse --help to get a list of available options\n", my_progname, *argv);
6f73e838
ER		 1555diff -r 25523be1816e sql/set_var.cc
1556--- a/sql/set_var.cc Mon Dec 22 00:25:06 2008 -0800
1557+++ b/sql/set_var.cc Mon Dec 22 00:26:39 2008 -0800
dcc72bc6 1558@@ -217,9 +217,13 @@
833f2639
ER		 1559 sys_log_queries_not_using_indexes("log_queries_not_using_indexes",
1560 &opt_log_queries_not_using_indexes);
1561 sys_var_thd_ulong sys_log_warnings("log_warnings", &SV::log_warnings);
1562-sys_var_thd_ulong sys_long_query_time("long_query_time",
6f73e838 1563+sys_var_thd_microtime sys_long_query_time("long_query_time",
833f2639 1564 &SV::long_query_time);
dcc72bc6
ER		 1565+sys_var_bool_ptr sys_use_global_long_query_time("use_global_long_query_time",
1566+ &opt_use_global_long_query_time);
833f2639 1567 sys_var_bool_const_ptr sys_log_slow("log_slow_queries", &opt_slow_log);
6f73e838
ER		 1568+sys_var_log_slow sys_slow_query_log("slow_query_log", &opt_slow_log);
1569+sys_var_const_str_ptr sys_slow_query_log_file("slow_query_log_file", &opt_slow_logname);
833f2639 1570 sys_var_thd_bool sys_low_priority_updates("low_priority_updates",
6f73e838
ER		 1571 &SV::low_priority_updates,
1572 fix_low_priority_updates);
1573@@ -283,6 +285,8 @@
833f2639
ER		 1574 &SV::max_tmp_tables);
1575 sys_var_long_ptr sys_max_write_lock_count("max_write_lock_count",
1576 &max_write_lock_count);
1577+sys_var_thd_ulong sys_min_examined_row_limit("min_examined_row_limit",
1578+ &SV::min_examined_row_limit);
1579 sys_var_thd_ulong sys_multi_range_count("multi_range_count",
1580 &SV::multi_range_count);
1581 sys_var_long_ptr sys_myisam_data_pointer_size("myisam_data_pointer_size",
6f73e838 1582@@ -327,6 +331,20 @@
833f2639
ER		 1583 sys_var_bool_ptr sys_relay_log_purge("relay_log_purge",
1584 &relay_log_purge);
1585 #endif
1586+sys_var_thd_ulong sys_log_slow_rate_limit("log_slow_rate_limit",
1587+ &SV::log_slow_rate_limit);
1588+sys_var_thd_msl_flag sys_log_slow_filter("log_slow_filter",
1589+ &SV::log_slow_filter,
1590+ SLOG_F_NONE,
1591+ SLOG_F_NONE,
1592+ SLOG_F_INVALID,
1593+ slog_filter);
1594+sys_var_thd_msl_flag sys_log_slow_verbosity("log_slow_verbosity",
1595+ &SV::log_slow_verbosity,
1596+ SLOG_V_NONE,
1597+ SLOG_V_MICROTIME,
1598+ SLOG_V_INVALID,
1599+ slog_verb);
1600 sys_var_long_ptr sys_rpl_recovery_rank("rpl_recovery_rank",
1601 &rpl_recovery_rank);
1602 sys_var_long_ptr sys_query_cache_size("query_cache_size",
dcc72bc6 1603@@ -694,6 +712,10 @@
833f2639
ER		 1604 &sys_log_off,
1605 &sys_log_queries_not_using_indexes,
1606 &sys_log_slow,
1607+ &sys_log_slow_filter,
1608+ &sys_log_slow_rate_limit,
1609+ &sys_log_slow_verbosity,
dcc72bc6 1610+ &sys_use_global_long_query_time,
833f2639
ER		 1611 &sys_log_update,
1612 &sys_log_warnings,
1613 &sys_long_query_time,
6f73e838 1614@@ -717,6 +738,7 @@
833f2639
ER		 1615 &sys_max_tmp_tables,
1616 &sys_max_user_connections,
1617 &sys_max_write_lock_count,
1618+ &sys_min_examined_row_limit,
1619 &sys_multi_range_count,
1620 &sys_myisam_data_pointer_size,
1621 &sys_myisam_max_sort_file_size,
6f73e838
ER		 1622@@ -770,6 +792,8 @@
1623 &sys_slave_skip_counter,
1624 #endif
1625 &sys_slow_launch_time,
1626+ &sys_slow_query_log,
1627+ &sys_slow_query_log_file,
1628 &sys_sort_buffer,
1629 &sys_sql_big_tables,
1630 &sys_sql_low_priority_updates,
1631@@ -986,8 +1010,11 @@
833f2639
ER		 1632 {"log_slave_updates", (char*) &opt_log_slave_updates, SHOW_MY_BOOL},
1633 #endif
1634 {sys_log_slow.name, (char*) &sys_log_slow, SHOW_SYS},
1635+ {sys_log_slow_filter.name, (char*) &sys_log_slow_filter, SHOW_SYS},
6f73e838 1636+ {sys_log_slow_rate_limit.name, (char*) &sys_log_slow_rate_limit, SHOW_SYS},
833f2639
ER		 1637+ {sys_log_slow_verbosity.name, (char*) &sys_log_slow_verbosity, SHOW_SYS},
1638 {sys_log_warnings.name, (char*) &sys_log_warnings, SHOW_SYS},
6f73e838
ER		 1639- {sys_long_query_time.name, (char*) &sys_long_query_time, SHOW_SYS},
1640+ {sys_long_query_time.name, (char*) &sys_long_query_time, SHOW_MICROTIME},
833f2639 1641 {sys_low_priority_updates.name, (char*) &sys_low_priority_updates, SHOW_SYS},
6f73e838
ER		 1642 {"lower_case_file_system", (char*) &lower_case_file_system, SHOW_MY_BOOL},
1643 {"lower_case_table_names", (char*) &lower_case_table_names, SHOW_INT},
1644@@ -1014,6 +1041,7 @@
833f2639
ER		 1645 {sys_max_tmp_tables.name, (char*) &sys_max_tmp_tables, SHOW_SYS},
1646 {sys_max_user_connections.name,(char*) &sys_max_user_connections, SHOW_SYS},
1647 {sys_max_write_lock_count.name, (char*) &sys_max_write_lock_count,SHOW_SYS},
1648+ {sys_min_examined_row_limit.name, (char*) &sys_min_examined_row_limit, SHOW_SYS},
1649 {sys_multi_range_count.name, (char*) &sys_multi_range_count, SHOW_SYS},
1650 {sys_myisam_data_pointer_size.name, (char*) &sys_myisam_data_pointer_size, SHOW_SYS},
1651 {sys_myisam_max_sort_file_size.name, (char*) &sys_myisam_max_sort_file_size,
6f73e838
ER		 1652@@ -1101,6 +1129,8 @@
1653 {sys_slave_trans_retries.name,(char*) &sys_slave_trans_retries, SHOW_SYS},
1654 #endif
1655 {sys_slow_launch_time.name, (char*) &sys_slow_launch_time, SHOW_SYS},
1656+ {sys_slow_query_log.name, (char*) &sys_slow_query_log, SHOW_SYS},
1657+ {sys_slow_query_log_file.name,(char*) &sys_slow_query_log_file, SHOW_SYS},
1658 #ifdef HAVE_SYS_UN_H
1659 {"socket", (char*) &mysqld_unix_port, SHOW_CHAR_PTR},
1660 #endif
dcc72bc6
ER		 1661@@ -1141,6 +1171,7 @@
1662 {sys_tx_isolation.name, (char*) &sys_tx_isolation, SHOW_SYS},
1663 {sys_updatable_views_with_limit.name,
1664 (char*) &sys_updatable_views_with_limit,SHOW_SYS},
1665+ {sys_use_global_long_query_time.name, (char*) &sys_use_global_long_query_time, SHOW_SYS},
1666 {sys_version.name, (char*) &sys_version, SHOW_SYS},
1667 #ifdef HAVE_BERKELEY_DB
1668 {sys_version_bdb.name, (char*) &sys_version_bdb, SHOW_SYS},
6f73e838 1669@@ -1769,6 +1799,17 @@
833f2639
ER		 1670 }
1671
6f73e838 1672
833f2639
ER		 1673+bool sys_var_thd_microtime::check(THD *thd, set_var *var)
1674+{
1675+ if (var->value->result_type() == DECIMAL_RESULT)
1676+ var->save_result.ulonglong_value= (ulonglong)(var->value->val_real() * 1000000);
6f73e838
ER		 1677+ else
1678+ var->save_result.ulonglong_value= (ulonglong)(var->value->val_int() * 1000000);
1679+
833f2639
ER		 1680+ return 0;
1681+}
1682+
833f2639 1683+
6f73e838
ER		 1684 bool sys_var_thd_bool::update(THD *thd, set_var *var)
1685 {
1686 if (var->type == OPT_GLOBAL)
1687@@ -1924,6 +1965,19 @@
1688 value= *(longlong*) value_ptr(thd, var_type, base);
1689 pthread_mutex_unlock(&LOCK_global_system_variables);
1690 return new Item_int(value);
1691+ }
1692+ case SHOW_MICROTIME:
1693+ {
1694+ longlong value;
1695+ char buff[80];
1696+ int len;
833f2639 1697+
6f73e838
ER		 1698+ pthread_mutex_lock(&LOCK_global_system_variables);
1699+ value= *(longlong*) value_ptr(thd, var_type, base);
1700+ pthread_mutex_unlock(&LOCK_global_system_variables);
833f2639 1701+
6f73e838
ER		 1702+ len = snprintf(buff, 80, "%f", ((double) value) / 1000000.0);
1703+ return new Item_float(buff,len);
1704 }
1705 case SHOW_HA_ROWS:
1706 {
1707@@ -2757,6 +2811,30 @@
1708 }
1709
1710
1711+bool sys_var_log_slow::update(THD *thd, set_var *var)
1712+{
1713+ bool ret;
833f2639 1714+
6f73e838
ER		 1715+ pthread_mutex_lock(&LOCK_global_system_variables);
1716+ if (var->save_result.ulong_value)
833f2639 1717+ {
6f73e838
ER		 1718+ if(!mysql_slow_log.is_open())
1719+ {
1720+ mysql_slow_log.open_slow_log(opt_slow_logname);
1721+ }
833f2639 1722+ }
6f73e838 1723+ pthread_mutex_unlock(&LOCK_global_system_variables);
833f2639 1724+
6f73e838
ER		 1725+ ret = sys_var_bool_ptr::update(thd, var);
1726+
1727+#ifdef HAVE_INNOBASE_DB
1728+ innobase_update_var_slow_log();
1729+#endif
1730+
1731+ return(ret);
833f2639 1732+}
6f73e838
ER		 1733+
1734+
1735 #ifdef HAVE_REPLICATION
1736 bool sys_var_slave_skip_counter::check(THD *thd, set_var *var)
833f2639 1737 {
6f73e838 1738@@ -3519,6 +3597,191 @@
833f2639
ER		 1739 #endif
1740 }
1741
1742+/* Slow log stuff */
1743+
1744+ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len)
1745+{
1746+ ulong i;
1747+
1748+ for (i=0; opts[i].name; i++)
1749+ {
1750+ if (!my_strnncoll(&my_charset_latin1,
1751+ (const uchar *)name, len,
1752+ (const uchar *)opts[i].name, strlen(opts[i].name)))
1753+ return opts[i].val;
1754+ }
1755+ return opts[i].val;
1756+}
1757+
1758+ulong msl_flag_resolve_by_name(const struct msl_opts *opts, const char *names_list,
1759+ const ulong none_val, const ulong invalid_val)
1760+{
1761+ const char *p, *e;
1762+ ulong val= none_val;
1763+
1764+ if (!*names_list)
1765+ return val;
1766+
1767+ for (p= e= names_list; ; e++)
1768+ {
1769+ ulong i;
1770+
1771+ if (*e != ',' && *e)
1772+ continue;
1773+ for (i=0; opts[i].name; i++)
1774+ {
1775+ if (!my_strnncoll(&my_charset_latin1,
1776+ (const uchar *)p, e - p,
1777+ (const uchar *)opts[i].name, strlen(opts[i].name)))
1778+ {
1779+ val= val | opts[i].val;
1780+ break;
1781+ }
1782+ }
1783+ if (opts[i].val == invalid_val)
1784+ return invalid_val;
1785+ if (!*e)
1786+ break;
1787+ p= e + 1;
1788+ }
1789+ return val;
1790+}
1791+
1792+const char *msl_option_get_name(const struct msl_opts *opts, ulong val)
1793+{
1794+ for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1795+ {
1796+ if (opts[i].val == val)
1797+ return opts[i].name;
1798+ }
1799+ return "*INVALID*";
1800+}
1801+
1802+char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val)
1803+{
1804+ uint offset= 0;
1805+
1806+ *buf= '\0';
1807+ for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1808+ {
1809+ if (opts[i].val & val)
1810+ offset+= snprintf(buf+offset, STRING_BUFFER_USUAL_SIZE - offset - 1,
1811+ "%s%s", (offset ? "," : ""), opts[i].name);
1812+ }
1813+ return buf;
1814+}
1815+
1816+/****************************************************************************
1817+ Functions to handle log_slow_verbosity
1818+****************************************************************************/
1819+
1820+/* Based upon sys_var::check_enum() */
1821+
1822+bool sys_var_thd_msl_option::check(THD *thd, set_var *var)
1823+{
1824+ char buff[STRING_BUFFER_USUAL_SIZE];
1825+ String str(buff, sizeof(buff), &my_charset_latin1), *res;
1826+
1827+ if (var->value->result_type() == STRING_RESULT)
1828+ {
1829+ ulong verb= this->invalid_val;
1830+ if (!(res=var->value->val_str(&str)) ||
1831+ (var->save_result.ulong_value=
1832+ (ulong) (verb= msl_option_resolve_by_name(this->opts, res->ptr(), res->length()))) == this->invalid_val)
1833+ goto err;
1834+ return 0;
1835+ }
1836+
1837+err:
1838+ my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1839+ return 1;
1840+}
1841+
1842+byte *sys_var_thd_msl_option::value_ptr(THD *thd, enum_var_type type,
1843+ LEX_STRING *base)
1844+{
1845+ ulong val;
1846+ val= ((type == OPT_GLOBAL) ? global_system_variables.*offset :
1847+ thd->variables.*offset);
1848+ const char *verbosity= msl_option_get_name(this->opts, val);
1849+ return (byte *) verbosity;
1850+}
1851+
1852+
1853+void sys_var_thd_msl_option::set_default(THD *thd, enum_var_type type)
1854+{
1855+ if (type == OPT_GLOBAL)
1856+ global_system_variables.*offset= (ulong) this->default_val;
1857+ else
1858+ thd->variables.*offset= (ulong) (global_system_variables.*offset);
1859+}
1860+
1861+
1862+bool sys_var_thd_msl_option::update(THD *thd, set_var *var)
1863+{
1864+ if (var->type == OPT_GLOBAL)
1865+ global_system_variables.*offset= var->save_result.ulong_value;
1866+ else
1867+ thd->variables.*offset= var->save_result.ulong_value;
1868+ return 0;
1869+}
1870+
1871+/****************************************************************************
1872+ Functions to handle log_slow_filter
1873+****************************************************************************/
1874+
1875+/* Based upon sys_var::check_enum() */
1876+
1877+bool sys_var_thd_msl_flag::check(THD *thd, set_var *var)
1878+{
1879+ char buff[2 * STRING_BUFFER_USUAL_SIZE];
1880+ String str(buff, sizeof(buff), &my_charset_latin1), *res;
1881+
1882+ if (var->value->result_type() == STRING_RESULT)
1883+ {
1884+ ulong filter= this->none_val;
1885+ if (!(res=var->value->val_str(&str)) ||
1886+ (var->save_result.ulong_value=
1887+ (ulong) (filter= msl_flag_resolve_by_name(this->flags, res->ptr(), this->none_val,
1888+ this->invalid_val))) == this->invalid_val)
1889+ goto err;
1890+ return 0;
1891+ }
1892+
1893+err:
1894+ my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1895+ return 1;
1896+}
1897+
1898+byte *sys_var_thd_msl_flag::value_ptr(THD *thd, enum_var_type type,
1899+ LEX_STRING *base)
1900+{
1901+ ulong val;
1902+ val= ((type == OPT_GLOBAL) ? global_system_variables.*offset :
1903+ thd->variables.*offset);
1904+ msl_flag_get_name(this->flags, this->flags_string, val);
1905+ return (byte *) this->flags_string;
1906+}
1907+
1908+
1909+void sys_var_thd_msl_flag::set_default(THD *thd, enum_var_type type)
1910+{
1911+ if (type == OPT_GLOBAL)
1912+ global_system_variables.*offset= (ulong) this->default_val;
1913+ else
1914+ thd->variables.*offset= (ulong) (global_system_variables.*offset);
1915+}
1916+
1917+
1918+bool sys_var_thd_msl_flag::update(THD *thd, set_var *var)
1919+{
1920+ if (var->type == OPT_GLOBAL)
1921+ global_system_variables.*offset= var->save_result.ulong_value;
1922+ else
1923+ thd->variables.*offset= var->save_result.ulong_value;
1924+ return 0;
1925+}
1926+
1927 /****************************************************************************
1928 Functions to handle table_type
1929 ****************************************************************************/
6f73e838
ER		 1930diff -r 25523be1816e sql/set_var.h
1931--- a/sql/set_var.h Mon Dec 22 00:25:06 2008 -0800
1932+++ b/sql/set_var.h Mon Dec 22 00:26:39 2008 -0800
1933@@ -132,6 +132,7 @@
833f2639
ER		 1934 };
1935
1936
1937+
1938 class sys_var_ulonglong_ptr :public sys_var
1939 {
1940 public:
6f73e838
ER		 1941@@ -168,6 +169,13 @@
1942 bool check_update_type(Item_result type) { return 0; }
1943 };
1944
1945+class sys_var_log_slow :public sys_var_bool_ptr
1946+{
1947+public:
1948+ sys_var_log_slow(const char *name_arg, my_bool *value_arg)
1949+ :sys_var_bool_ptr(name_arg, value_arg) {}
1950+ bool update(THD *thd, set_var *var);
1951+};
1952
1953 class sys_var_bool_const_ptr : public sys_var
1954 {
1955@@ -340,7 +348,6 @@
833f2639
ER		 1956 }
1957 };
1958
1959-
1960 class sys_var_thd_ulong :public sys_var_thd
1961 {
1962 sys_check_func check_func;
6f73e838 1963@@ -360,7 +367,6 @@
833f2639
ER		 1964 byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1965 };
1966
6f73e838 1967-
833f2639
ER		 1968 class sys_var_thd_ha_rows :public sys_var_thd
1969 {
6f73e838
ER		 1970 public:
1971@@ -377,7 +383,6 @@
833f2639
ER		 1972 SHOW_TYPE show_type() { return SHOW_HA_ROWS; }
1973 byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1974 };
1975-
1976
1977 class sys_var_thd_ulonglong :public sys_var_thd
1978 {
6f73e838 1979@@ -407,6 +412,19 @@
833f2639
ER		 1980 }
1981 };
1982
6f73e838
ER		 1983+class sys_var_thd_microtime :public sys_var_thd_ulonglong
1984+{
1985+public:
1986+ sys_var_thd_microtime(const char *name_arg, ulonglong SV::*offset_arg)
1987+ :sys_var_thd_ulonglong(name_arg, offset_arg)
1988+ {}
1989+ SHOW_TYPE show_type() { return SHOW_MICROTIME; }
1990+ bool check(THD *thd, set_var *var);
1991+ bool check_update_type(Item_result type)
1992+ {
1993+ return type != INT_RESULT && type != DECIMAL_RESULT;
1994+ }
1995+};
1996
833f2639
ER		 1997 class sys_var_thd_bool :public sys_var_thd
1998 {
6f73e838 1999@@ -477,6 +495,66 @@
833f2639
ER		 2000 ulong *length);
2001 };
2002
2003+
2004+class sys_var_thd_msl_option :public sys_var_thd
2005+{
2006+protected:
2007+ ulong SV::*offset;
2008+ const ulong none_val;
2009+ const ulong default_val;
2010+ const ulong invalid_val;
2011+ const struct msl_opts *opts;
2012+public:
2013+ sys_var_thd_msl_option(const char *name_arg, ulong SV::*offset_arg,
2014+ const ulong none_val_arg,
2015+ const ulong default_val_arg,
2016+ const ulong invalid_val_arg,
2017+ const struct msl_opts *opts_arg)
2018+ :sys_var_thd(name_arg), offset(offset_arg), none_val(none_val_arg),
2019+ default_val(default_val_arg), invalid_val(invalid_val_arg),
2020+ opts(opts_arg)
2021+ {}
2022+ bool check(THD *thd, set_var *var);
2023+ SHOW_TYPE show_type() { return SHOW_CHAR; }
2024+ bool check_update_type(Item_result type)
2025+ {
2026+ return type != STRING_RESULT; /* Only accept strings */
2027+ }
2028+ void set_default(THD *thd, enum_var_type type);
2029+ bool update(THD *thd, set_var *var);
2030+ byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
2031+};
2032+
2033+
2034+class sys_var_thd_msl_flag :public sys_var_thd
2035+{
2036+protected:
2037+ char flags_string[2 * STRING_BUFFER_USUAL_SIZE];
2038+ ulong SV::*offset;
2039+ const ulong none_val;
2040+ const ulong default_val;
2041+ const ulong invalid_val;
2042+ const struct msl_opts *flags;
2043+public:
2044+ sys_var_thd_msl_flag(const char *name_arg, ulong SV::*offset_arg,
2045+ const ulong none_val_arg,
2046+ const ulong default_val_arg,
2047+ const ulong invalid_val_arg,
2048+ const struct msl_opts *flags_arg)
2049+ :sys_var_thd(name_arg), offset(offset_arg), none_val(none_val_arg),
2050+ default_val(default_val_arg), invalid_val(invalid_val_arg),
2051+ flags(flags_arg)
2052+ {}
2053+ bool check(THD *thd, set_var *var);
2054+ SHOW_TYPE show_type() { return SHOW_CHAR; }
2055+ bool check_update_type(Item_result type)
2056+ {
2057+ return type != STRING_RESULT; /* Only accept strings */
2058+ }
2059+ void set_default(THD *thd, enum_var_type type);
2060+ bool update(THD *thd, set_var *var);
2061+ byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
2062+};
2063
2064 class sys_var_thd_storage_engine :public sys_var_thd
2065 {
6f73e838 2066@@ -1087,3 +1165,11 @@
833f2639
ER		 2067 bool process_key_caches(int (* func) (const char *name, KEY_CACHE *));
2068 void delete_elements(I_List<NAMED_LIST> *list,
2069 void (*free_element)(const char*, gptr));
2070+
2071+/* Slow log functions */
2072+
2073+ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len);
2074+ulong msl_flag_resolve_by_name(const struct msl_opts *opts, const char *names_list,
2075+ const ulong none_val, const ulong invalid_val);
2076+const char *msl_option_get_name(const struct msl_opts *opts, ulong val);
2077+char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val);
6f73e838
ER		 2078diff -r 25523be1816e sql/slave.cc
2079--- a/sql/slave.cc Mon Dec 22 00:25:06 2008 -0800
2080+++ b/sql/slave.cc Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 2081@@ -2925,6 +2925,12 @@
2082 + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */
2083 thd->slave_thread = 1;
2084 set_slave_thread_options(thd);
2085+ if (opt_log_slow_slave_statements)
2086+ {
2087+ thd->enable_slow_log= TRUE;
2088+ /* Slave thread is excluded from rate limiting the slow log writes. */
2089+ thd->write_to_slow_log= TRUE;
2090+ }
2091 thd->client_capabilities = CLIENT_LOCAL_FILES;
2092 thd->real_id=pthread_self();
2093 pthread_mutex_lock(&LOCK_thread_count);
6f73e838
ER		 2094diff -r 25523be1816e sql/sql_cache.cc
2095--- a/sql/sql_cache.cc Mon Dec 22 00:25:06 2008 -0800
2096+++ b/sql/sql_cache.cc Mon Dec 22 00:26:39 2008 -0800
2097@@ -1341,6 +1341,7 @@
833f2639
ER		 2098
2099 thd->limit_found_rows = query->found_rows();
2100 thd->status_var.last_query_cost= 0.0;
2101+ thd->query_plan_flags|= QPLAN_QC;
2102
2103 BLOCK_UNLOCK_RD(query_block);
2104 DBUG_RETURN(1); // Result sent to client
6f73e838 2105@@ -1348,6 +1349,7 @@
833f2639
ER		 2106 err_unlock:
2107 STRUCT_UNLOCK(&structure_guard_mutex);
2108 err:
2109+ thd->query_plan_flags|= QPLAN_QC_NO;
2110 DBUG_RETURN(0); // Query was not cached
2111 }
2112
6f73e838
ER		 2113diff -r 25523be1816e sql/sql_class.cc
2114--- a/sql/sql_class.cc Mon Dec 22 00:25:06 2008 -0800
2115+++ b/sql/sql_class.cc Mon Dec 22 00:26:39 2008 -0800
2116@@ -188,7 +188,7 @@
833f2639
ER		 2117 lock_id(&main_lock_id),
2118 user_time(0), in_sub_stmt(0), global_read_lock(0), is_fatal_error(0),
2119 transaction_rollback_request(0), is_fatal_sub_stmt_error(0),
2120- rand_used(0), time_zone_used(0),
2121+ rand_used(0), time_zone_used(0), user_timer(0),
2122 last_insert_id_used(0), last_insert_id_used_bin_log(0), insert_id_used(0),
2123 clear_next_insert_id(0), in_lock_tables(0), bootstrap(0),
2124 derived_tables_processing(FALSE), spcont(NULL),
6f73e838 2125@@ -2224,6 +2224,12 @@
833f2639
ER		 2126 backup->cuted_fields= cuted_fields;
2127 backup->client_capabilities= client_capabilities;
2128 backup->savepoints= transaction.savepoints;
2129+ backup->innodb_io_reads= innodb_io_reads;
2130+ backup->innodb_io_read= innodb_io_read;
2131+ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
2132+ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
2133+ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
2134+ backup->innodb_page_access= innodb_page_access;
2135
2136 if (!lex->requires_prelocking() || is_update_query(lex->sql_command))
2137 options&= ~OPTION_BIN_LOG;
6f73e838 2138@@ -2240,7 +2246,13 @@
833f2639
ER		 2139 sent_row_count= 0;
2140 cuted_fields= 0;
2141 transaction.savepoints= 0;
2142-
2143+ innodb_io_reads= 0;
2144+ innodb_io_read= 0;
2145+ innodb_io_reads_wait_timer= 0;
2146+ innodb_lock_que_wait_timer= 0;
2147+ innodb_innodb_que_wait_timer= 0;
2148+ innodb_page_access= 0;
2149+
2150 /* Surpress OK packets in case if we will execute statements */
2151 net.no_send_ok= TRUE;
2152 }
6f73e838 2153@@ -2293,6 +2305,12 @@
833f2639
ER		 2154 */
2155 examined_row_count+= backup->examined_row_count;
2156 cuted_fields+= backup->cuted_fields;
2157+ innodb_io_reads+= backup->innodb_io_reads;
2158+ innodb_io_read+= backup->innodb_io_read;
2159+ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
2160+ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
2161+ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
2162+ innodb_page_access+= backup->innodb_page_access;
2163 }
2164
2165
dcc72bc6
ER		 2166diff -r 25523be1816e sql/sql_class.h
2167--- a/sql/sql_class.h Mon Dec 22 00:25:06 2008 -0800
2168+++ b/sql/sql_class.h Mon Dec 22 00:26:39 2008 -0800
6f73e838 2169@@ -43,6 +43,7 @@
833f2639
ER		 2170 extern char internal_table_name[2];
2171 extern char empty_c_string[1];
2172 extern const char **errmesg;
833f2639 2173+extern ulonglong frequency;
833f2639
ER		 2174
2175 #define TC_LOG_PAGE_SIZE 8192
2176 #define TC_LOG_MIN_SIZE (3*TC_LOG_PAGE_SIZE)
2177@@ -314,7 +321,7 @@
2178 bool write(THD *thd, enum enum_server_command command,
2179 const char *format, ...) ATTRIBUTE_FORMAT(printf, 4, 5);
2180 bool write(THD *thd, const char *query, uint query_length,
2181- time_t query_start=0);
2182+ time_t query_start=0, ulonglong query_start_timer=0);
2183 bool write(Log_event* event_info); // binary log write
2184 bool write(THD *thd, IO_CACHE *cache, Log_event *commit_event);
2185
2186@@ -520,13 +527,14 @@
2187 ulong auto_increment_increment, auto_increment_offset;
2188 ulong bulk_insert_buff_size;
2189 ulong join_buff_size;
2190- ulong long_query_time;
2191+ ulonglong long_query_time;
2192 ulong max_allowed_packet;
2193 ulong max_error_count;
2194 ulong max_length_for_sort_data;
2195 ulong max_sort_length;
2196 ulong max_tmp_tables;
2197 ulong max_insert_delayed_threads;
2198+ ulong min_examined_row_limit;
2199 ulong multi_range_count;
2200 ulong myisam_repair_threads;
2201 ulong myisam_sort_buff_size;
6f73e838 2202@@ -542,10 +550,13 @@
833f2639 2203 ulong preload_buff_size;
6f73e838 2204 ulong profiling_history_size;
833f2639
ER		 2205 ulong query_cache_type;
2206+ ulong log_slow_rate_limit;
2207 ulong read_buff_size;
2208 ulong read_rnd_buff_size;
2209 ulong div_precincrement;
2210 ulong sortbuff_size;
2211+ ulong log_slow_filter;
2212+ ulong log_slow_verbosity;
2213 ulong table_type;
2214 ulong tx_isolation;
2215 ulong completion_type;
6f73e838 2216@@ -1121,6 +1132,12 @@
833f2639
ER		 2217 uint in_sub_stmt;
2218 bool enable_slow_log, insert_id_used, clear_next_insert_id;
2219 bool last_insert_id_used;
2220+ ulong innodb_io_reads;
2221+ ulonglong innodb_io_read;
2222+ ulong innodb_io_reads_wait_timer;
2223+ ulong innodb_lock_que_wait_timer;
2224+ ulong innodb_innodb_que_wait_timer;
2225+ ulong innodb_page_access;
2226 my_bool no_send_ok;
2227 SAVEPOINT *savepoints;
2228 };
6f73e838 2229@@ -1177,6 +1194,11 @@
833f2639
ER		 2230 class THD :public Statement,
2231 public Open_tables_state
2232 {
2233+private:
2234+ inline ulonglong query_start_timer() { return start_timer; }
2235+ inline void set_timer() { if (user_timer) start_timer=timer_after_lock=user_timer; else timer_after_lock=my_timer(&start_timer, frequency); }
2236+ inline void end_timer() { my_timer(&start_timer, frequency); }
2237+ inline void lock_timer() { my_timer(&timer_after_lock, frequency); }
2238 public:
2239 /*
2240 Constant for THD::where initialization in the beginning of every query.
6f73e838 2241@@ -1285,10 +1307,24 @@
833f2639
ER		 2242 */
2243 const char *where;
2244 time_t start_time,time_after_lock,user_time;
2245+ ulonglong start_timer,timer_after_lock, user_timer;
2246 time_t connect_time,thr_create_time; // track down slow pthread_create
2247 thr_lock_type update_lock_default;
2248 Delayed_insert *di;
2249
2250+ bool write_to_slow_log;
2251+
2252+ bool innodb_was_used;
2253+ ulong innodb_io_reads;
2254+ ulonglong innodb_io_read;
2255+ ulong innodb_io_reads_wait_timer;
2256+ ulong innodb_lock_que_wait_timer;
2257+ ulong innodb_innodb_que_wait_timer;
2258+ ulong innodb_page_access;
2259+
2260+ ulong query_plan_flags;
2261+ ulong query_plan_fsort_passes;
2262+
2263 /* <> 0 if we are inside of trigger or stored function. */
2264 uint in_sub_stmt;
2265
6f73e838 2266@@ -1678,11 +1714,11 @@
833f2639
ER		 2267 sql_print_information("time() failed with %d", errno);
2268 }
2269
2270- inline time_t query_start() { query_start_used=1; return start_time; }
2271- inline void set_time() { if (user_time) start_time=time_after_lock=user_time; else { safe_time(&start_time); time_after_lock= start_time; }}
2272- inline void end_time() { safe_time(&start_time); }
2273- inline void set_time(time_t t) { time_after_lock=start_time=user_time=t; }
2274- inline void lock_time() { safe_time(&time_after_lock); }
2275+ inline time_t query_start() { query_start_timer(); query_start_used=1; return start_time; }
2276+ 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; }}
2277+ inline void end_time() { end_timer(); safe_time(&start_time); }
2278+ inline void set_time(time_t t) { set_timer(); time_after_lock=start_time=user_time=t; }
2279+ inline void lock_time() { lock_timer(); safe_time(&time_after_lock); }
2280 inline void insert_id(ulonglong id_arg)
2281 {
2282 last_insert_id= id_arg;
6f73e838
ER		 2283diff -r 25523be1816e sql/sql_parse.cc
2284--- a/sql/sql_parse.cc Mon Dec 22 00:25:06 2008 -0800
2285+++ b/sql/sql_parse.cc Mon Dec 22 00:26:39 2008 -0800
833f2639
ER		 2286@@ -20,6 +20,7 @@
2287 #include <m_ctype.h>
2288 #include <myisam.h>
2289 #include <my_dir.h>
2290+#include <my_time.h>
2291
2292 #ifdef HAVE_INNOBASE_DB
2293 #include "ha_innodb.h"
6f73e838 2294@@ -1227,6 +1228,15 @@
833f2639
ER		 2295 my_net_set_read_timeout(net, thd->variables.net_read_timeout);
2296 my_net_set_write_timeout(net, thd->variables.net_write_timeout);
2297
2298+ /*
2299+ If rate limiting of slow log writes is enabled, decide whether to log this
2300+ new thread's queries or not. Uses extremely simple algorithm. :)
2301+ */
2302+ thd->write_to_slow_log= FALSE;
2303+ if (thd->variables.log_slow_rate_limit <= 1 ||
2304+ (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
2305+ thd->write_to_slow_log= TRUE;
2306+
2307 while (!net->error && net->vio != 0 &&
2308 !(thd->killed == THD::KILL_CONNECTION))
2309 {
dcc72bc6 2310@@ -2353,27 +2363,55 @@
833f2639
ER		 2311 return; // Don't set time for sub stmt
2312
2313 start_of_query= thd->start_time;
2314+ ulonglong start_of_query_timer= thd->start_timer;
2315 thd->end_time(); // Set start time
2316+
2317+
2318+ /* Follow the slow log filter configuration. */
2319+ if (thd->variables.log_slow_filter != SLOG_F_NONE &&
2320+ (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
2321+ ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
2322+ (thd->query_plan_flags & QPLAN_QC))))
2323+ return;
2324+
2325+ /*
2326+ Low long_query_time value most likely means user is debugging stuff and even
2327+ though some thread's queries are not supposed to be logged b/c of the rate
2328+ limit, if one of them takes long enough (>= 1 second) it will be sensible
2329+ to make an exception and write to slow log anyway.
2330+ */
dcc72bc6
ER		 2331+ if (opt_use_global_long_query_time)
2332+ thd->variables.long_query_time = global_system_variables.long_query_time;
833f2639
ER		 2333+ if (thd->write_to_slow_log != TRUE && thd->variables.long_query_time < 1000000 &&
2334+ (ulong) (thd->start_timer - thd->timer_after_lock) >= 1000000)
2335+ thd->write_to_slow_log= TRUE;
2336+
2337+ /* Do not log this thread's queries due to rate limiting. */
2338+ if (thd->write_to_slow_log != TRUE)
2339+ return;
2340
2341 /*
2342 Do not log administrative statements unless the appropriate option is
2343 set; do not log into slow log if reading from backup.
2344 */
2345- if (thd->enable_slow_log && !thd->user_time)
2346+ if (thd->enable_slow_log &&
2347+ (!thd->user_time || (thd->slave_thread && opt_log_slow_slave_statements))
2348+ )
2349 {
6f73e838 2350 thd_proc_info(thd, "logging slow query");
833f2639
ER		 2351
2352- if ((ulong) (thd->start_time - thd->time_after_lock) >
2353- thd->variables.long_query_time ||
2354- (thd->server_status &
2355- (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
2356- opt_log_queries_not_using_indexes &&
2357- /* == SQLCOM_END unless this is a SHOW command */
2358- thd->lex->orig_sql_command == SQLCOM_END)
2359+ if (((ulong) (thd->start_timer - thd->timer_after_lock) >=
2360+ thd->variables.long_query_time ||
2361+ (thd->server_status &
2362+ (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
2363+ opt_log_queries_not_using_indexes &&
2364+ /* == SQLCOM_END unless this is a SHOW command */
2365+ thd->lex->orig_sql_command == SQLCOM_END) &&
2366+ thd->examined_row_count >= thd->variables.min_examined_row_limit)
2367 {
6f73e838 2368 thd_proc_info(thd, "logging slow query");
833f2639
ER		 2369 thd->status_var.long_query_count++;
2370- mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query);
2371+ mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query, start_of_query_timer);
2372 }
2373 }
2374 }
dcc72bc6
ER		 2375@@ -2664,6 +2702,8 @@
2376 context.resolve_in_table_list_only((TABLE_LIST*)select_lex->
2377 table_list.first);
2378
2379+ /* Reset the counter at all cases for the extended slow query log */
2380+ thd->row_count= 1;
2381 /*
2382 Reset warning count for each query that uses tables
2383 A better approach would be to reset this for any commands
6f73e838 2384@@ -6084,6 +6120,15 @@
833f2639
ER		 2385 thd->total_warn_count=0; // Warnings for this query
2386 thd->rand_used= 0;
2387 thd->sent_row_count= thd->examined_row_count= 0;
2388+ thd->innodb_was_used= FALSE;
2389+ thd->innodb_io_reads= 0;
2390+ thd->innodb_io_read= 0;
2391+ thd->innodb_io_reads_wait_timer= 0;
2392+ thd->innodb_lock_que_wait_timer= 0;
2393+ thd->innodb_innodb_que_wait_timer= 0;
2394+ thd->innodb_page_access= 0;
2395+ thd->query_plan_flags= QPLAN_NONE;
2396+ thd->query_plan_fsort_passes= 0;
2397 }
2398 DBUG_VOID_RETURN;
2399 }
6f73e838
ER		 2400diff -r 25523be1816e sql/sql_select.cc
2401--- a/sql/sql_select.cc Mon Dec 22 00:25:06 2008 -0800
2402+++ b/sql/sql_select.cc Mon Dec 22 00:26:39 2008 -0800
2403@@ -6221,8 +6221,11 @@
833f2639
ER		 2404 {
2405 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2406 if (statistics)
2407+ {
2408 statistic_increment(join->thd->status_var.select_scan_count,
2409 &LOCK_status);
2410+ join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
2411+ }
2412 }
2413 }
2414 else
6f73e838 2415@@ -6237,8 +6240,11 @@
833f2639
ER		 2416 {
2417 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2418 if (statistics)
2419+ {
2420 statistic_increment(join->thd->status_var.select_full_join_count,
2421 &LOCK_status);
2422+ join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
2423+ }
2424 }
2425 }
2426 if (!table->no_keyread)
6f73e838 2427@@ -9302,6 +9308,7 @@
833f2639
ER		 2428 (ulong) rows_limit,test(group)));
2429
2430 statistic_increment(thd->status_var.created_tmp_tables, &LOCK_status);
2431+ thd->query_plan_flags|= QPLAN_TMP_TABLE;
2432
2433 if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
2434 temp_pool_slot = bitmap_set_next(&temp_pool);
6f73e838 2435@@ -10162,6 +10169,7 @@
833f2639
ER		 2436 }
2437 statistic_increment(table->in_use->status_var.created_tmp_disk_tables,
2438 &LOCK_status);
2439+ table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
2440 table->s->db_record_offset= 1;
2441 DBUG_RETURN(0);
2442 err:
6f73e838
ER		 2443diff -r 25523be1816e sql/sql_show.cc
2444--- a/sql/sql_show.cc Mon Dec 22 00:25:06 2008 -0800
2445+++ b/sql/sql_show.cc Mon Dec 22 00:26:39 2008 -0800
2446@@ -1532,6 +1532,12 @@
833f2639
ER		 2447 value= ((char *) status_var + (ulonglong) value);
2448 case SHOW_LONGLONG:
2449 end= longlong10_to_str(*(longlong*) value, buff, 10);
2450+ break;
2451+ case SHOW_MICROTIME:
6f73e838
ER		 2452+ show_type= ((sys_var*) value)->show_type();
2453+ value= (char*) ((sys_var*) value)->value_ptr(thd, value_type,
2454+ &null_lex_str);
2455+ end= buff + sprintf(buff, "%f", (((double) (*(ulonglong*)value))) / 1000000.0);
833f2639
ER		 2456 break;
2457 case SHOW_HA_ROWS:
2458 end= longlong10_to_str((longlong) *(ha_rows*) value, buff, 10);
6f73e838
ER		 2459diff -r 25523be1816e sql/structs.h
2460--- a/sql/structs.h Mon Dec 22 00:25:06 2008 -0800
2461+++ b/sql/structs.h Mon Dec 22 00:26:39 2008 -0800
2462@@ -168,8 +168,8 @@
833f2639
ER		 2463 enum SHOW_TYPE
2464 {
2465 SHOW_UNDEF,
2466- SHOW_LONG, SHOW_LONGLONG, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
6f73e838 2467- SHOW_DOUBLE_STATUS,
990729de 2468+ SHOW_LONG, SHOW_LONGLONG, SHOW_MICROTIME, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
6f73e838 2469+ SHOW_DOUBLE_STATUS,
990729de 2470 SHOW_BOOL, SHOW_MY_BOOL, SHOW_OPENTABLES, SHOW_STARTTIME,
833f2639 2471 SHOW_LONG_CONST, SHOW_INT_CONST, SHOW_HAVE, SHOW_SYS, SHOW_HA_ROWS,
6f73e838 2472 SHOW_VARS,
MySQL: a very fast and reliable SQL database engine
This page took 0.341619 seconds and 4 git commands to generate.