]> 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
- expire-logs-days sample
[packages/mysql.git] / mysql-microslow_innodb.patch
CommitLineData
89b96684
ER		 1diff -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
6f73e838
ER		 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
45532174 9+#define GET_MICROTIME 11
6f73e838
ER		 10+#define GET_DISABLED 12
11
12 #define GET_ASK_ADDR 128
13 #define GET_TYPE_MASK 127
89b96684
ER		 14diff -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
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_ */
89b96684
ER		 26diff -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
45532174 29@@ -37,6 +37,10 @@
833f2639
ER		 30 #include "log0log.h"
31 #include "trx0undo.h"
32 #include "srv0srv.h"
45532174 33+#include "trx0trx.h"
6f73e838
ER		 34+
35+/* prototypes for new functions added to ha_innodb.cc */
36+trx_t* innobase_get_trx();
833f2639
ER		 37
38 /*
39 IMPLEMENTATION OF THE BUFFER POOL
45532174 40@@ -1086,6 +1090,36 @@
833f2639
ER		 41 return(block);
42 }
43
44+inline void _increment_page_get_statistics(buf_block_t* block, trx_t* trx)
45+{
46+ ulint block_hash;
47+ ulint block_hash_byte;
48+ byte block_hash_offset;
49+
50+ ut_ad(block);
51+
6f73e838 52+ if (!srv_slow_log || !trx || !trx->take_stats)
833f2639
ER		 53+ return;
54+
6f73e838
ER		 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);
58+ }
59+
833f2639
ER		 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;
71+ return;
72+}
73+
74 /************************************************************************
75 This is the general function used to get access to a database page. */
76
45532174 77@@ -1108,6 +1142,11 @@
833f2639
ER		 78 ulint fix_type;
79 ibool success;
80 ibool must_read;
6f73e838 81+ trx_t* trx = NULL;
833f2639
ER		 82+ ulint sec;
83+ ulint ms;
84+ ib_longlong start_time;
85+ ib_longlong finish_time;
86
87 ut_ad(mtr);
88 ut_ad((rw_latch == RW_S_LATCH)
45532174 89@@ -1119,6 +1158,9 @@
833f2639
ER		 90 #ifndef UNIV_LOG_DEBUG
91 ut_ad(!ibuf_inside() || ibuf_page(space, offset));
92 #endif
6f73e838
ER		 93+ if (srv_slow_log) {
94+ trx = innobase_get_trx();
95+ }
833f2639
ER		 96 buf_pool->n_page_gets++;
97 loop:
98 block = NULL;
45532174 99@@ -1148,7 +1190,7 @@
833f2639
ER		 100 return(NULL);
101 }
102
103- buf_read_page(space, offset);
104+ buf_read_page(space, offset, trx);
105
106 #ifdef UNIV_DEBUG
107 buf_dbg_counter++;
45532174 108@@ -1261,6 +1303,11 @@
833f2639
ER		 109 /* Let us wait until the read operation
110 completes */
111
6f73e838 112+ if (srv_slow_log && trx && trx->take_stats)
833f2639
ER		 113+ {
114+ ut_usectime(&sec, &ms);
115+ start_time = (ib_longlong)sec * 1000000 + ms;
116+ }
117 for (;;) {
118 mutex_enter(&block->mutex);
119
45532174 120@@ -1276,6 +1323,12 @@
833f2639
ER		 121 break;
122 }
45532174 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);
45532174 129+ }
833f2639
ER		 130 }
131
45532174
ER		 132 fix_type = MTR_MEMO_BUF_FIX;
133@@ -1296,12 +1349,17 @@
833f2639
ER		 134 /* In the case of a first access, try to apply linear
135 read-ahead */
136
137- buf_read_ahead_linear(space, offset);
138+ buf_read_ahead_linear(space, offset, trx);
139 }
140
141 #ifdef UNIV_IBUF_DEBUG
142 ut_a(ibuf_count_get(block->space, block->offset) == 0);
143 #endif
144+
6f73e838
ER		 145+ if (srv_slow_log) {
146+ _increment_page_get_statistics(block, trx);
147+ }
833f2639
ER		 148+
149 return(block->frame);
150 }
151
45532174 152@@ -1326,6 +1384,7 @@
833f2639
ER		 153 ibool accessed;
154 ibool success;
155 ulint fix_type;
6f73e838 156+ trx_t* trx = NULL;
833f2639
ER		 157
158 ut_ad(mtr && block);
159 ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
45532174 160@@ -1440,7 +1499,7 @@
833f2639
ER		 161 read-ahead */
162
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);
166 }
167
168 #ifdef UNIV_IBUF_DEBUG
45532174 169@@ -1448,6 +1507,11 @@
833f2639
ER		 170 #endif
171 buf_pool->n_page_gets++;
45532174 172
6f73e838
ER		 173+ if (srv_slow_log) {
174+ trx = innobase_get_trx();
175+ _increment_page_get_statistics(block, trx);
176+ }
45532174 177+
833f2639
ER		 178 return(TRUE);
179 }
45532174
ER		 180
181@@ -1470,6 +1534,7 @@
833f2639
ER		 182 buf_block_t* block;
183 ibool success;
184 ulint fix_type;
6f73e838 185+ trx_t* trx = NULL;
833f2639
ER		 186
187 ut_ad(mtr);
188 ut_ad((rw_latch == RW_S_LATCH) || (rw_latch == RW_X_LATCH));
45532174 189@@ -1559,6 +1624,11 @@
833f2639
ER		 190 #endif
191 buf_pool->n_page_gets++;
45532174 192
6f73e838
ER		 193+ if (srv_slow_log) {
194+ trx = innobase_get_trx();
195+ _increment_page_get_statistics(block, trx);
196+ }
45532174 197+
833f2639
ER		 198 return(TRUE);
199 }
45532174 200
89b96684
ER		 201diff -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
833f2639
ER		 204@@ -70,7 +70,8 @@
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 */
210+ trx_t* trx)
211 {
212 buf_block_t* block;
213 ulint wake_later;
214@@ -140,10 +141,10 @@
215
216 ut_a(block->state == BUF_BLOCK_FILE_PAGE);
217
218- *err = fil_io(OS_FILE_READ | wake_later,
219+ *err = _fil_io(OS_FILE_READ | wake_later,
220 sync, space,
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);
225
226 if (sync) {
227@@ -174,8 +175,9 @@
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
233 wants to access */
234+ trx_t* trx)
235 {
236 ib_longlong tablespace_version;
237 buf_block_t* block;
238@@ -270,7 +272,7 @@
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);
246 fprintf(stderr,
247@@ -314,7 +316,8 @@
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 */
253+ trx_t* trx)
254 {
255 ib_longlong tablespace_version;
256 ulint count;
257@@ -323,13 +326,13 @@
258
259 tablespace_version = fil_space_get_version(space);
260
261- count = buf_read_ahead_random(space, offset);
262+ count = buf_read_ahead_random(space, offset, trx);
263
264 /* We do the i/o in the synchronous aio mode to save thread
265 switches: hence TRUE */
266
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);
273@@ -374,8 +377,9 @@
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) */
280+ trx_t* trx)
281 {
282 ib_longlong tablespace_version;
283 buf_block_t* block;
284@@ -556,7 +560,7 @@
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);
292 fprintf(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);
299 } else {
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);
303 }
304
305 if (err == DB_TABLESPACE_DELETED) {
306@@ -704,11 +708,11 @@
307
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);
312 } else {
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);
317 }
318 }
319
89b96684
ER		 320diff -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
833f2639
ER		 323@@ -3527,7 +3527,7 @@
324 node->name, node->handle, buf,
325 offset_low, offset_high,
326 UNIV_PAGE_SIZE * n_pages,
327- NULL, NULL);
328+ NULL, NULL, NULL);
329 #endif
330 if (success) {
331 node->size += n_pages;
332@@ -3851,7 +3851,7 @@
333 Reads or writes data. This operation is asynchronous (aio). */
334
335 ulint
336-fil_io(
337+_fil_io(
338 /*===*/
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 */
348+ trx_t* trx)
349 {
350 fil_system_t* system = fil_system;
351 ulint mode;
352@@ -4018,7 +4019,7 @@
353 #else
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);
358 #endif
359 ut_a(ret);
360
89b96684
ER		 361diff -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
833f2639
ER		 364@@ -10,6 +10,7 @@
365 #define buf0rea_h
366
367 #include "univ.i"
368+#include "trx0types.h"
369 #include "buf0types.h"
370
371 /************************************************************************
372@@ -25,7 +26,8 @@
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 */
378+ trx_t* trx);
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.
382@@ -55,8 +57,9 @@
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) */
389+ trx_t* trx);
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
89b96684
ER		 393diff -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
833f2639
ER		 396@@ -534,8 +534,11 @@
397 /************************************************************************
398 Reads or writes data. This operation is asynchronous (aio). */
399
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)
402+
403 ulint
404-fil_io(
405+_fil_io(
406 /*===*/
407 /* out: DB_SUCCESS, or DB_TABLESPACE_DELETED
408 if we are trying to do i/o on a tablespace
409@@ -561,8 +564,9 @@
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 */
416+ trx_t* trx);
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
89b96684
ER		 420diff -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
45532174 423@@ -11,6 +11,8 @@
833f2639
ER		 424
425 #include "univ.i"
833f2639 426
45532174
ER		 427+#include "trx0types.h"
428+
833f2639
ER		 429 #ifndef __WIN__
430 #include <dirent.h>
45532174 431 #include <sys/stat.h>
833f2639
ER		 432@@ -421,8 +423,11 @@
433 /***********************************************************************
434 Requests a synchronous read operation. */
435
436+#define os_file_read(file, buf, offset, offset_high, n) \
437+ _os_file_read(file, buf, offset, offset_high, n, NULL)
438+
439 ibool
440-os_file_read(
441+_os_file_read(
442 /*=========*/
443 /* out: TRUE if request was
444 successful, FALSE if fail */
445@@ -432,7 +437,8 @@
446 offset where to read */
447 ulint offset_high,/* in: most significant 32 bits of
448 offset */
449- ulint n); /* in: number of bytes to read */
450+ ulint n, /* in: number of bytes to read */
451+ trx_t* trx);
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
455@@ -584,7 +590,8 @@
456 can be used to identify a completed aio
457 operation); if mode is OS_AIO_SYNC, these
458 are ignored */
459- void* message2);
460+ void* message2,
461+ trx_t* trx);
462 /****************************************************************************
463 Wakes up all async i/o threads so that they know to exit themselves in
464 shutdown. */
89b96684
ER		 465diff -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
45532174 468@@ -27,6 +27,8 @@
6f73e838
ER		 469 #define SRV_AUTO_EXTEND_INCREMENT \
470 (srv_auto_extend_increment * ((1024 * 1024) / UNIV_PAGE_SIZE))
6f73e838 471
45532174
ER		 472+extern ibool srv_slow_log;
473+
6f73e838
ER		 474 /* This is set to TRUE if the MySQL user has set it in MySQL */
475 extern ibool srv_lower_case_table_names;
45532174 476
89b96684
ER		 477diff -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
833f2639
ER		 480@@ -668,6 +668,17 @@
481 /*------------------------------*/
482 char detailed_error[256]; /* detailed error message for last
483 error, or empty. */
484+ /*------------------------------*/
833f2639
ER		 485+ ulint io_reads;
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;
6f73e838 494+ ibool take_stats;
833f2639
ER		 495 };
496
497 #define TRX_MAX_N_THREADS 32 /* maximum number of concurrent
89b96684
ER		 498diff -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
833f2639
ER		 501@@ -1806,6 +1806,8 @@
502 {
503 lock_t* lock;
504 trx_t* trx;
505+ ulint sec;
506+ ulint ms;
507
508 #ifdef UNIV_SYNC_DEBUG
509 ut_ad(mutex_own(&kernel_mutex));
6f73e838 510@@ -1861,6 +1863,10 @@
833f2639
ER		 511 trx->que_state = TRX_QUE_LOCK_WAIT;
512 trx->was_chosen_as_deadlock_victim = FALSE;
513 trx->wait_started = time(NULL);
6f73e838
ER		 514+ if (srv_slow_log && trx->take_stats) {
515+ ut_usectime(&sec, &ms);
516+ trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
517+ }
833f2639
ER		 518
519 ut_a(que_thr_stop(thr));
520
6f73e838 521@@ -3514,7 +3520,9 @@
833f2639
ER		 522 {
523 lock_t* lock;
524 trx_t* trx;
525-
526+ ulint sec;
527+ ulint ms;
528+
529 #ifdef UNIV_SYNC_DEBUG
530 ut_ad(mutex_own(&kernel_mutex));
531 #endif /* UNIV_SYNC_DEBUG */
6f73e838 532@@ -3564,6 +3572,10 @@
833f2639
ER		 533 return(DB_SUCCESS);
534 }
6f73e838
ER		 535
536+ if (srv_slow_log && trx->take_stats) {
537+ ut_usectime(&sec, &ms);
538+ trx->lock_que_wait_ustarted = (ib_longlong)sec * 1000000 + ms;
539+ }
833f2639
ER		 540 trx->que_state = TRX_QUE_LOCK_WAIT;
541 trx->was_chosen_as_deadlock_victim = FALSE;
542 trx->wait_started = time(NULL);
89b96684
ER		 543diff -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
45532174 546@@ -14,6 +14,8 @@
833f2639
ER		 547 #include "srv0start.h"
548 #include "fil0fil.h"
549 #include "buf0buf.h"
550+#include "trx0sys.h"
45532174 551+#include "trx0trx.h"
833f2639
ER		 552
553 #if defined(UNIV_HOTBACKUP) && defined(__WIN__)
554 /* Add includes for the _stat() call to compile on Windows */
45532174 555@@ -1903,9 +1905,13 @@
833f2639
ER		 556 #ifndef __WIN__
557 /***********************************************************************
558 Does a synchronous read operation in Posix. */
559+
560+#define os_file_pread(file, buf, n, offset, offset_high) \
561+ _os_file_pread(file, buf, n, offset, offset_high, NULL);
562+
563 static
564 ssize_t
565-os_file_pread(
566+_os_file_pread(
567 /*==========*/
568 /* out: number of bytes read, -1 if error */
569 os_file_t file, /* in: handle to a file */
45532174 570@@ -1913,12 +1919,17 @@
833f2639
ER		 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
575- offset */
576+ ulint offset_high, /* in: most significant 32 bits of
577+ offset */
578+ trx_t* trx)
579 {
580 off_t offs;
581 ssize_t n_bytes;
582-
583+ ulint sec;
584+ ulint ms;
585+ ib_longlong start_time;
586+ ib_longlong finish_time;
587+
588 ut_a((offset & 0xFFFFFFFFUL) == offset);
589
590 /* If off_t is > 4 bytes in size, then we assume we can pass a
45532174 591@@ -1937,7 +1948,13 @@
833f2639
ER		 592 }
593
594 os_n_file_reads++;
595-
6f73e838 596+ if (srv_slow_log && trx && trx->take_stats)
833f2639
ER		 597+ {
598+ trx->io_reads++;
599+ trx->io_read += n;
600+ ut_usectime(&sec, &ms);
601+ start_time = (ib_longlong)sec * 1000000 + ms;
602+ }
603 #if defined(HAVE_PREAD) && !defined(HAVE_BROKEN_PREAD)
604 os_mutex_enter(os_file_count_mutex);
605 os_file_n_pending_preads++;
45532174 606@@ -1951,6 +1968,13 @@
833f2639
ER		 607 os_n_pending_reads--;
608 os_mutex_exit(os_file_count_mutex);
609
6f73e838 610+ if (srv_slow_log && trx && trx->take_stats && start_time)
833f2639
ER		 611+ {
612+ ut_usectime(&sec, &ms);
613+ finish_time = (ib_longlong)sec * 1000000 + ms;
614+ trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
615+ }
616+
617 return(n_bytes);
618 #else
619 {
45532174 620@@ -1981,6 +2005,13 @@
833f2639
ER		 621 os_n_pending_reads--;
622 os_mutex_exit(os_file_count_mutex);
45532174 623
6f73e838 624+ if (srv_slow_log && trx && trx->take_stats && start_time)
833f2639
ER		 625+ {
626+ ut_usectime(&sec, &ms);
627+ finish_time = (ib_longlong)sec * 1000000 + ms;
628+ trx->io_reads_wait_timer += (ulint)(finish_time - start_time);
629+ }
45532174 630+
833f2639
ER		 631 return(ret);
632 }
45532174
ER		 633 #endif
634@@ -2103,7 +2134,7 @@
833f2639
ER		 635 Requests a synchronous positioned read operation. */
636
637 ibool
638-os_file_read(
639+_os_file_read(
640 /*=========*/
641 /* out: TRUE if request was
642 successful, FALSE if fail */
45532174 643@@ -2113,7 +2144,8 @@
833f2639
ER		 644 offset where to read */
645 ulint offset_high, /* in: most significant 32 bits of
646 offset */
647- ulint n) /* in: number of bytes to read */
648+ ulint n, /* in: number of bytes to read */
649+ trx_t* trx)
650 {
651 #ifdef __WIN__
652 BOOL ret;
45532174 653@@ -2177,7 +2209,7 @@
833f2639
ER		 654 os_bytes_read_since_printout += n;
655
656 try_again:
657- ret = os_file_pread(file, buf, n, offset, offset_high);
658+ ret = _os_file_pread(file, buf, n, offset, offset_high, trx);
659
660 if ((ulint)ret == n) {
661
45532174 662@@ -3137,7 +3169,8 @@
833f2639
ER		 663 offset */
664 ulint offset_high, /* in: most significant 32 bits of
665 offset */
666- ulint len) /* in: length of the block to read or write */
667+ ulint len, /* in: length of the block to read or write */
668+ trx_t* trx)
669 {
670 os_aio_slot_t* slot;
671 #ifdef WIN_ASYNC_IO
45532174 672@@ -3390,7 +3423,8 @@
833f2639
ER		 673 can be used to identify a completed aio
674 operation); if mode is OS_AIO_SYNC, these
675 are ignored */
676- void* message2)
677+ void* message2,
678+ trx_t* trx)
679 {
680 os_aio_array_t* array;
681 os_aio_slot_t* slot;
45532174 682@@ -3429,8 +3463,8 @@
833f2639
ER		 683 wait in the Windows case. */
684
685 if (type == OS_FILE_READ) {
686- return(os_file_read(file, buf, offset,
687- offset_high, n));
688+ return(_os_file_read(file, buf, offset,
689+ offset_high, n, trx));
690 }
691
692 ut_a(type == OS_FILE_WRITE);
45532174 693@@ -3463,8 +3497,13 @@
833f2639
ER		 694 ut_error;
695 }
696
697+ if (trx && type == OS_FILE_READ)
698+ {
699+ trx->io_reads++;
700+ trx->io_read += n;
701+ }
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) {
707 #ifdef WIN_ASYNC_IO
89b96684
ER		 708diff -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
45532174 711@@ -48,6 +48,8 @@
6f73e838
ER		 712 #include "srv0start.h"
713 #include "row0mysql.h"
833f2639 714
45532174
ER		 715+ibool srv_slow_log = 0;
716+
6f73e838
ER		 717 /* This is set to TRUE if the MySQL user has set it in MySQL; currently
718 affects only FOREIGN KEY definition parsing */
45532174
ER		 719 ibool srv_lower_case_table_names = FALSE;
720@@ -1002,6 +1004,10 @@
833f2639
ER		 721 ibool has_slept = FALSE;
722 srv_conc_slot_t* slot = NULL;
723 ulint i;
724+ ib_longlong start_time = 0L;
725+ ib_longlong finish_time = 0L;
726+ ulint sec;
727+ ulint ms;
728
729 /* If trx has 'free tickets' to enter the engine left, then use one
730 such ticket */
45532174 731@@ -1060,6 +1066,7 @@
833f2639
ER		 732 if (SRV_THREAD_SLEEP_DELAY > 0)
733 {
734 os_thread_sleep(SRV_THREAD_SLEEP_DELAY);
735+ trx->innodb_que_wait_timer += SRV_THREAD_SLEEP_DELAY;
736 }
737
738 trx->op_info = "";
45532174 739@@ -1115,12 +1122,23 @@
833f2639
ER		 740 /* Go to wait for the event; when a thread leaves InnoDB it will
741 release this thread */
742
6f73e838
ER		 743+ if (srv_slow_log && trx->take_stats) {
744+ ut_usectime(&sec, &ms);
745+ start_time = (ib_longlong)sec * 1000000 + ms;
746+ }
833f2639
ER		 747+
748 trx->op_info = "waiting in InnoDB queue";
749
750 os_event_wait(slot->event);
751
752 trx->op_info = "";
45532174 753
6f73e838
ER		 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);
758+ }
45532174 759+
833f2639
ER		 760 os_fast_mutex_lock(&srv_conc_mutex);
761
45532174 762 srv_conc_n_waiting_threads--;
89b96684
ER		 763diff -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
6f73e838 766@@ -190,6 +190,15 @@
833f2639
ER		 767 trx->global_read_view_heap = mem_heap_create(256);
768 trx->global_read_view = NULL;
769 trx->read_view = NULL;
770+
771+ trx->io_reads = 0;
772+ trx->io_read = 0;
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;
6f73e838 778+ trx->take_stats = FALSE;
833f2639
ER		 779
780 /* Set X/Open XA transaction identification to NULL */
781 memset(&trx->xid, 0, sizeof(trx->xid));
6f73e838 782@@ -230,6 +239,11 @@
833f2639
ER		 783
784 trx->mysql_process_no = os_proc_get_number();
785
6f73e838
ER		 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);
789+ }
833f2639
ER		 790+
791 return(trx);
792 }
793
6f73e838 794@@ -366,6 +380,12 @@
833f2639
ER		 795 /*===============*/
796 trx_t* trx) /* in, own: trx object */
797 {
798+ if (trx->distinct_page_access_hash)
799+ {
800+ mem_free(trx->distinct_page_access_hash);
801+ trx->distinct_page_access_hash= NULL;
802+ }
803+
804 thr_local_free(trx->mysql_thread_id);
805
806 mutex_enter(&kernel_mutex);
6f73e838
ER		 807@@ -389,6 +409,12 @@
808 /*====================*/
809 trx_t* trx) /* in, own: trx object */
810 {
811+ if (trx->distinct_page_access_hash)
812+ {
813+ mem_free(trx->distinct_page_access_hash);
814+ trx->distinct_page_access_hash= NULL;
815+ }
816+
817 mutex_enter(&kernel_mutex);
818
819 trx_free(trx);
820@@ -1064,7 +1090,10 @@
833f2639
ER		 821 trx_t* trx) /* in: transaction */
822 {
823 que_thr_t* thr;
824-
825+ ulint sec;
826+ ulint ms;
827+ ib_longlong now;
828+
829 #ifdef UNIV_SYNC_DEBUG
830 ut_ad(mutex_own(&kernel_mutex));
831 #endif /* UNIV_SYNC_DEBUG */
6f73e838 832@@ -1080,6 +1109,11 @@
833f2639
ER		 833 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
834 }
835
6f73e838
ER		 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);
840+ }
833f2639
ER		 841 trx->que_state = TRX_QUE_RUNNING;
842 }
843
6f73e838 844@@ -1093,6 +1127,9 @@
833f2639
ER		 845 trx_t* trx) /* in: transaction in the TRX_QUE_LOCK_WAIT state */
846 {
847 que_thr_t* thr;
848+ ulint sec;
849+ ulint ms;
850+ ib_longlong now;
851
852 #ifdef UNIV_SYNC_DEBUG
853 ut_ad(mutex_own(&kernel_mutex));
6f73e838 854@@ -1109,6 +1146,11 @@
833f2639
ER		 855 thr = UT_LIST_GET_FIRST(trx->wait_thrs);
856 }
857
6f73e838
ER		 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);
862+ }
833f2639
ER		 863 trx->que_state = TRX_QUE_RUNNING;
864 }
865
89b96684
ER		 866diff -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
45532174
ER		 869@@ -827,7 +827,8 @@
870 #endif
871 break;
872 default:
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);
876 break;
877 }
878
89b96684 879@@ -1061,6 +1062,9 @@
6f73e838
ER		 880 case GET_ULONG:
881 printf("%lu\n", *((ulong*) value));
882 break;
45532174
ER		 883+ case GET_MICROTIME:
884+ printf("%6f\n", ((double)(*((longlong*) value))) / 1000000.0);
6f73e838
ER		 885+ break;
886 case GET_LL:
887 printf("%s\n", llstr(*((longlong*) value), buff));
888 break;
89b96684 889diff -r 1242d4575291 patch_info/microslow_innodb.info
833f2639 890--- /dev/null Thu Jan 01 00:00:00 1970 +0000
89b96684 891+++ b/patch_info/microslow_innodb.info Tue Jul 28 23:42:44 2009 -0700
6f73e838 892@@ -0,0 +1,15 @@
833f2639
ER		 893+File=microslow_innodb.patch
894+Name=Extended statistics in slow.log
dcc72bc6 895+Version=1.2
833f2639
ER		 896+Author=Percona <info@percona.com>
897+License=GPL
898+Comment=
6f73e838
ER		 899+Changelog
900+2008-11-26
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).
902+
903+2008-11-07
904+VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
905+
906+2008-11
907+Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
89b96684
ER		 908diff -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
833f2639
ER		 911@@ -83,8 +83,8 @@
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) : ('','');
914
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};
920
921 # remove fluff that mysqld writes to log when it (re)starts:
89b96684
ER		 922diff -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
45532174 925@@ -1253,3 +1253,37 @@
833f2639
ER		 926 return 0;
927 }
928
929+/*
930+ int my_timer(ulonglong *ltime, ulonglong frequency)
931+
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).
935+
936+ For windows platforms frequency value (obtained via
937+ QueryPerformanceFrequency) has to be specified. The global frequency
938+ value is set in mysqld.cc.
939+
940+ If Windows platform doesn't support QueryPerformanceFrequency we will
941+ obtain the time via GetClockCount, which supports microseconds only.
942+*/
943+
944+ulonglong my_timer(ulonglong *ltime, ulonglong frequency)
945+{
946+ ulonglong newtime= 0;
947+#ifdef __WIN__
948+ if (frequency)
949+ {
950+ QueryPerformanceCounter((LARGE_INTEGER *)&newtime);
951+ newtime/= (frequency * 1000000);
952+ } else
953+ newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */
954+#else
955+ struct timeval t;
dcc72bc6
ER		 956+ if (gettimeofday(&t, NULL) != -1)
957+ newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
833f2639
ER		 958+#endif
959+ if (ltime)
960+ *ltime= newtime;
961+ return newtime;
962+}
89b96684
ER		 963diff -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
833f2639
ER		 966@@ -180,6 +180,7 @@
967 {
968 statistic_increment(thd->status_var.filesort_scan_count, &LOCK_status);
969 }
970+ thd->query_plan_flags|= QPLAN_FILESORT;
971 #ifdef CAN_TRUST_RANGE
972 if (select && select->quick && select->quick->records > 0L)
973 {
974@@ -245,6 +246,7 @@
975 }
976 else
977 {
978+ thd->query_plan_flags|= QPLAN_FILESORT_DISK;
979 if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
980 {
981 x_free(table_sort.buffpek);
982@@ -1116,6 +1118,7 @@
983
984 statistic_increment(current_thd->status_var.filesort_merge_passes,
985 &LOCK_status);
986+ current_thd->query_plan_fsort_passes++;
987 if (param->not_killable)
988 {
989 killed= &not_killable;
89b96684
ER		 990diff -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
833f2639
ER		 993@@ -1,3 +1,4 @@
994+
995 /* Copyright (C) 2000-2005 MySQL AB & Innobase Oy
996
997 This program is free software; you can redistribute it and/or modify
45532174 998@@ -819,9 +820,34 @@
6f73e838
ER		 999 trx->check_unique_secondary = TRUE;
1000 }
1001
1002+ if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1003+ trx->take_stats = TRUE;
1004+ } else {
1005+ trx->take_stats = FALSE;
1006+ }
1007+
1008 return(trx);
1009 }
1010
1011+/*************************************************************************
1012+Gets current trx. */
1013+extern "C"
1014+trx_t*
1015+innobase_get_trx()
1016+{
1017+ THD *thd=current_thd;
1018+ if (likely(thd != 0)) {
1019+ return((trx_t*) thd->ha_data[innobase_hton.slot]);
1020+ } else {
1021+ return(NULL);
1022+ }
1023+}
1024+
1025+void
1026+innobase_update_var_slow_log()
1027+{
1028+ srv_slow_log = (ibool) opt_slow_log;
1029+}
1030
1031 /*************************************************************************
1032 Construct ha_innobase handler. */
45532174 1033@@ -1324,6 +1350,8 @@
6f73e838
ER		 1034
1035 /* -------------- Log files ---------------------------*/
6f73e838 1036
45532174
ER		 1037+ srv_slow_log = (ibool) opt_slow_log;
1038+
6f73e838
ER		 1039 /* The default dir for log files is the datadir of MySQL */
1040
45532174 1041 if (!innobase_log_group_home_dir) {
89b96684 1042@@ -4697,6 +4725,12 @@
6f73e838
ER		 1043 trx->check_unique_secondary = FALSE;
1044 }
1045
1046+ if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1047+ trx->take_stats = TRUE;
1048+ } else {
1049+ trx->take_stats = FALSE;
1050+ }
1051+
1052 if (lower_case_table_names) {
1053 srv_lower_case_table_names = TRUE;
1054 } else {
89b96684 1055@@ -4962,6 +4996,12 @@
6f73e838
ER		 1056 trx->check_unique_secondary = FALSE;
1057 }
1058
1059+ if (thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1060+ trx->take_stats = TRUE;
1061+ } else {
1062+ trx->take_stats = FALSE;
1063+ }
1064+
1065 name_len = strlen(name);
1066
1067 assert(name_len < 1000);
89b96684 1068@@ -5049,6 +5089,12 @@
6f73e838
ER		 1069 trx->check_foreigns = FALSE;
1070 }
1071
1072+ if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1073+ trx->take_stats = TRUE;
1074+ } else {
1075+ trx->take_stats = FALSE;
1076+ }
1077+
1078 error = row_drop_database_for_mysql(namebuf, trx);
1079 my_free(namebuf, MYF(0));
1080
89b96684 1081@@ -5115,6 +5161,12 @@
6f73e838 1082 trx->check_foreigns = FALSE;
45532174
ER		 1083 }
1084
6f73e838
ER		 1085+ if (current_thd->variables.log_slow_verbosity & SLOG_V_INNODB) {
1086+ trx->take_stats = TRUE;
1087+ } else {
1088+ trx->take_stats = FALSE;
45532174
ER		 1089+ }
1090+
6f73e838 1091 name_len1 = strlen(from);
45532174
ER		 1092 name_len2 = strlen(to);
1093
89b96684 1094@@ -6122,6 +6174,7 @@
833f2639
ER		 1095 {
1096 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
1097 trx_t* trx;
1098+ int i;
1099
1100 DBUG_ENTER("ha_innobase::external_lock");
1101 DBUG_PRINT("enter",("lock_type: %d", lock_type));
89b96684 1102@@ -6245,7 +6298,24 @@
833f2639
ER		 1103
1104 if (trx->n_mysql_tables_in_use == 0) {
1105
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;
1114+
1115+ trx->io_reads = 0;
1116+ trx->io_read = 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);
1123+
1124+ trx->mysql_n_tables_locked = 0;
1125 prebuilt->used_in_HANDLER = FALSE;
1126
1127 if (!(thd->options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN))) {
89b96684
ER		 1128diff -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
45532174 1131@@ -271,6 +271,8 @@
6f73e838
ER		 1132
1133 int innobase_start_trx_and_assign_read_view(THD* thd);
1134
1135+void innobase_update_var_slow_log();
1136+
1137 /***********************************************************************
1138 This function is used to prepare X/Open XA distributed transaction */
1139
89b96684
ER		 1140diff -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
45532174 1143@@ -2289,11 +2289,12 @@
833f2639
ER		 1144 */
1145
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)
1149 {
1150 bool error=0;
1151 time_t current_time;
6f73e838 1152- if (!is_open())
833f2639 1153+ ulonglong current_timer;
6f73e838 1154+ if (!opt_slow_log || !is_open())
833f2639
ER		 1155 return 0;
1156 DBUG_ENTER("MYSQL_LOG::write");
6f73e838 1157
45532174 1158@@ -2303,7 +2304,8 @@
833f2639
ER		 1159 int tmp_errno=0;
1160 char buff[80],*end;
1161 end=buff;
1162- if (!(thd->options & OPTION_UPDATE_LOG))
1163+ if (!(thd->options & OPTION_UPDATE_LOG) &&
1164+ !(thd->slave_thread && opt_log_slow_slave_statements))
1165 {
1166 VOID(pthread_mutex_unlock(&LOCK_log));
1167 DBUG_RETURN(0);
45532174 1168@@ -2333,22 +2335,72 @@
833f2639
ER		 1169 if (my_b_printf(&log_file, "# User@Host: %s[%s] @ %s [%s]\n",
1170 sctx->priv_user ?
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 : "") ==
1176 (uint) -1)
1177 tmp_errno=errno;
1178 }
1179- if (query_start_arg)
1180+ if (query_start_timer)
1181 {
1182+ char buf[5][20];
1183+ ulonglong current_timer= my_timer(&current_timer, frequency);
dcc72bc6
ER		 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);
833f2639
ER		 1186+ if (!query_length)
1187+ {
1188+ thd->sent_row_count= thd->examined_row_count= 0;
dcc72bc6 1189+ thd->row_count= 0;
833f2639
ER		 1190+ thd->innodb_was_used= FALSE;
1191+ thd->query_plan_flags= QPLAN_NONE;
1192+ thd->query_plan_fsort_passes= 0;
1193+ }
1194+
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" \
6f73e838 1201+ "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n",
833f2639
ER		 1202+ (ulong) thd->thread_id, (thd->db ? thd->db : ""),
1203+ buf[0], buf[1],
1204 (ulong) thd->sent_row_count,
6f73e838
ER		 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)
833f2639
ER		 1209 tmp_errno=errno;
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)
1222+ tmp_errno=errno;
1223+ if ((thd->variables.log_slow_verbosity & SLOG_V_INNODB) && thd->innodb_was_used)
1224+ {
dcc72bc6
ER		 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);
833f2639
ER		 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)
1236+ tmp_errno=errno;
1237+ }
1238+ else
1239+ {
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)
1242+ tmp_errno=errno;
1243+ }
1244 }
1245 if (thd->db && strcmp(thd->db,db))
1246 { // Database changed
89b96684
ER		 1247diff -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 @@
833f2639
ER		 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);
1255
1256 }
1257 else
89b96684
ER		 1258diff -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
45532174 1261@@ -507,6 +507,78 @@
833f2639
ER		 1262
1263 #define STRING_BUFFER_USUAL_SIZE 80
45532174 1264
833f2639
ER		 1265+/* Slow log */
1266+
1267+struct msl_opts
1268+{
1269+ ulong val;
1270+ const char *name;
1271+};
1272+
1273+#define SLOG_V_MICROTIME 1 << 0
1274+#define SLOG_V_QUERY_PLAN 1 << 1
1275+#define SLOG_V_INNODB 1 << 2
1276+/* ... */
1277+#define SLOG_V_INVALID 1 << 31
1278+#define SLOG_V_NONE SLOG_V_MICROTIME
1279+
1280+static const struct msl_opts slog_verb[]=
1281+{
1282+ /* Basic flags */
1283+
1284+ { SLOG_V_MICROTIME, "microtime" },
1285+ { SLOG_V_QUERY_PLAN, "query_plan" },
1286+ { SLOG_V_INNODB, "innodb" },
1287+
1288+ /* End of baisc flags */
1289+
1290+ { 0, "" },
1291+
1292+ /* Complex flags */
1293+
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" },
1297+
1298+ /* End of complex flags */
1299+
1300+ { SLOG_V_INVALID, (char *)0 }
1301+};
1302+
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
1312+/* ... */
1313+#define QPLAN_MAX 1 << 31
1314+
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
1324+
1325+static const struct msl_opts slog_filter[]=
1326+{
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 }
1335+};
45532174 1336+
833f2639
ER		 1337 enum enum_parsing_place
1338 {
45532174
ER		 1339 NO_MATTER,
1340@@ -1365,6 +1437,7 @@
6f73e838
ER		 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;
45532174 1348@@ -1376,7 +1449,8 @@
833f2639
ER		 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;
dcc72bc6 1354+extern my_bool opt_use_global_long_query_time;
833f2639
ER		 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;
89b96684
ER		 1358diff -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
45532174 1361@@ -176,7 +176,6 @@
833f2639
ER		 1362 static void getvolumeID(BYTE *volumeName);
1363 #endif /* __NETWARE__ */
833f2639 1364
45532174 1365-
833f2639
ER		 1366 #ifdef _AIX41
1367 int initgroups(const char *,unsigned int);
45532174
ER		 1368 #endif
1369@@ -411,10 +410,13 @@
833f2639
ER		 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;
dcc72bc6 1374+my_bool opt_use_global_long_query_time= 0;
833f2639
ER		 1375 my_bool lower_case_file_system= 0;
1376 my_bool opt_large_pages= 0;
1377 uint opt_large_page_size= 0;
6f73e838
ER		 1378 my_bool opt_old_style_user_limits= 0, trust_function_creators= 0;
1379+char* opt_slow_logname= 0;
1380 /*
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
45532174 1383@@ -509,6 +511,7 @@
833f2639
ER		 1384 Ge_creator ge_creator;
1385 Le_creator le_creator;
1386
1387+ulonglong frequency= 0;
1388
1389 FILE *bootstrap_file;
1390 int bootstrap_error;
45532174 1391@@ -588,7 +591,7 @@
6f73e838
ER		 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;
45532174 1400@@ -3697,6 +3700,8 @@
833f2639
ER		 1401 unireg_abort(1);
1402 }
1403 }
1404+ if (!QueryPerformanceFrequency((LARGE_INTEGER *)&frequency))
1405+ frequency= 0;
1406 #endif /* __WIN__ */
1407
1408 if (init_common_variables(MYSQL_CONFIG_NAME,
45532174 1409@@ -4947,7 +4952,7 @@
833f2639
ER		 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,
45532174 1418@@ -5038,11 +5043,18 @@
833f2639
ER		 1419 OPT_TIMED_MUTEXES,
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,
6f73e838 1427 OPT_PLUGIN_DIR,
833f2639
ER		 1428 OPT_PORT_OPEN_TIMEOUT,
1429 OPT_MERGE,
6f73e838
ER		 1430 OPT_PROFILING,
1431+ OPT_SLOW_LOG,
1432+ OPT_SLOW_QUERY_LOG_FILE,
dcc72bc6 1433+ OPT_USE_GLOBAL_LONG_QUERY_TIME,
6f73e838
ER		 1434 OPT_INNODB_ROLLBACK_ON_TIMEOUT,
1435 OPT_SECURE_FILE_PRIV,
1436 OPT_KEEP_FILES_ON_CREATE,
45532174 1437@@ -5441,10 +5453,19 @@
833f2639
ER		 1438 (gptr*) &opt_log_slow_admin_statements,
1439 (gptr*) &opt_log_slow_admin_statements,
6f73e838 1440 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
833f2639
ER		 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,
6f73e838 1445+ 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
833f2639
ER		 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.",
6f73e838
ER		 1448 (gptr*) &opt_slow_logname, (gptr*) &opt_slow_logname, 0, GET_STR, OPT_ARG,
1449 0, 0, 0, 0, 0, 0},
45532174
ER		 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},
6f73e838 1454 {"log-tc", OPT_LOG_TC,
45532174
ER		 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 @@
6f73e838
ER		 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},
1460 #endif
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},
45532174 1467@@ -6110,11 +6134,31 @@
833f2639
ER		 1468 (gptr*) 0,
1469 0, (GET_ULONG | GET_ASK_ADDR) , REQUIRED_ARG, 100,
1470 1, 100, 0, 1, 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_ULONG,
1475- REQUIRED_ARG, 10, 1, LONG_TIMEOUT, 0, 1, 0},
833f2639
ER		 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,
6f73e838 1483+ REQUIRED_ARG, 1, 1, LONG_MAX, 0, 1L, 0},
833f2639
ER		 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},
6f73e838
ER		 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,
45532174 1490+ (gptr*) &max_system_variables.long_query_time, 0, GET_MICROTIME,
833f2639
ER		 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,
6f73e838 1496+ REQUIRED_ARG, 0, 0, LONG_MAX, 0, 1L, 0},
dcc72bc6
ER		 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},
833f2639
ER		 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,
45532174 1504@@ -6893,7 +6937,11 @@
833f2639
ER		 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;
1508-
6f73e838
ER		 1509+ global_system_variables.long_query_time = 10000000;
1510+ max_system_variables.long_query_time = LONG_TIMEOUT * 1000000;
833f2639
ER		 1511+ global_system_variables.log_slow_verbosity= SLOG_V_MICROTIME;
1512+ global_system_variables.log_slow_filter= SLOG_F_NONE;
1513+
1514 /*
1515 Default behavior for 4.1 and 5.0 is to treat NULL values as unequal
1516 when collecting index statistics for MyISAM tables.
45532174 1517@@ -7364,6 +7412,35 @@
833f2639
ER		 1518 case OPT_BOOTSTRAP:
1519 opt_noacl=opt_bootstrap=1;
1520 break;
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)
1525+ {
6f73e838 1526+ fprintf(stderr,"Invalid argument in log_slow_filter: %s\n", argument);
833f2639
ER		 1527+ exit(1);
1528+ }
1529+ break;
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)
1534+ {
6f73e838
ER		 1535+ fprintf(stderr,"Invalid argument in log_slow_verbosity: %s\n", argument);
1536+ exit(1);
1537+ }
1538+ break;
1539+ case OPT_LONG_QUERY_TIME:
1540+ {
1541+ double doubleslow = strtod(argument,NULL);
1542+ if (doubleslow < 0 || doubleslow > (LONG_TIMEOUT))
1543+ {
1544+ fprintf(stderr,"Out of range long_query_time value: %s\n", argument);
833f2639
ER		 1545+ exit(1);
1546+ }
6f73e838 1547+ global_system_variables.long_query_time = (ulonglong) (doubleslow * 1000000);
833f2639 1548+ break;
6f73e838 1549+ }
833f2639
ER		 1550 case OPT_STORAGE_ENGINE:
1551 {
1552 if ((enum db_type)((global_system_variables.table_type=
45532174 1553@@ -7696,10 +7773,14 @@
833f2639
ER		 1554 if (opt_bdb)
1555 sql_print_warning("this binary does not contain BDB storage engine");
1556 #endif
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) &&
1560 !opt_slow_log)
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");
1562-
1563+ {
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;
1566+ }
1567+
1568 if (argc > 0)
1569 {
1570 fprintf(stderr, "%s: Too many arguments (first extra is '%s').\nUse --help to get a list of available options\n", my_progname, *argv);
89b96684
ER		 1571diff -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
dcc72bc6 1574@@ -217,9 +217,13 @@
833f2639
ER		 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",
6f73e838 1579+sys_var_thd_microtime sys_long_query_time("long_query_time",
833f2639 1580 &SV::long_query_time);
dcc72bc6
ER		 1581+sys_var_bool_ptr sys_use_global_long_query_time("use_global_long_query_time",
1582+ &opt_use_global_long_query_time);
833f2639 1583 sys_var_bool_const_ptr sys_log_slow("log_slow_queries", &opt_slow_log);
6f73e838
ER		 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);
833f2639 1586 sys_var_thd_bool sys_low_priority_updates("low_priority_updates",
6f73e838
ER		 1587 &SV::low_priority_updates,
1588 fix_low_priority_updates);
337bc045 1589@@ -283,6 +287,8 @@
833f2639
ER		 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",
337bc045 1598@@ -327,6 +333,20 @@
833f2639
ER		 1599 sys_var_bool_ptr sys_relay_log_purge("relay_log_purge",
1600 &relay_log_purge);
1601 #endif
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,
1606+ SLOG_F_NONE,
1607+ SLOG_F_NONE,
1608+ SLOG_F_INVALID,
1609+ slog_filter);
1610+sys_var_thd_msl_flag sys_log_slow_verbosity("log_slow_verbosity",
1611+ &SV::log_slow_verbosity,
1612+ SLOG_V_NONE,
1613+ SLOG_V_MICROTIME,
1614+ SLOG_V_INVALID,
1615+ slog_verb);
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",
45532174 1619@@ -697,6 +717,10 @@
833f2639
ER		 1620 &sys_log_off,
1621 &sys_log_queries_not_using_indexes,
1622 &sys_log_slow,
1623+ &sys_log_slow_filter,
1624+ &sys_log_slow_rate_limit,
1625+ &sys_log_slow_verbosity,
dcc72bc6 1626+ &sys_use_global_long_query_time,
833f2639
ER		 1627 &sys_log_update,
1628 &sys_log_warnings,
1629 &sys_long_query_time,
45532174 1630@@ -720,6 +744,7 @@
833f2639
ER		 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,
45532174 1638@@ -773,6 +798,8 @@
6f73e838
ER		 1639 &sys_slave_skip_counter,
1640 #endif
1641 &sys_slow_launch_time,
1642+ &sys_slow_query_log,
1643+ &sys_slow_query_log_file,
1644 &sys_sort_buffer,
1645 &sys_sql_big_tables,
1646 &sys_sql_low_priority_updates,
45532174 1647@@ -994,8 +1021,11 @@
833f2639
ER		 1648 {"log_slave_updates", (char*) &opt_log_slave_updates, SHOW_MY_BOOL},
1649 #endif
1650 {sys_log_slow.name, (char*) &sys_log_slow, SHOW_SYS},
1651+ {sys_log_slow_filter.name, (char*) &sys_log_slow_filter, SHOW_SYS},
6f73e838 1652+ {sys_log_slow_rate_limit.name, (char*) &sys_log_slow_rate_limit, SHOW_SYS},
833f2639
ER		 1653+ {sys_log_slow_verbosity.name, (char*) &sys_log_slow_verbosity, SHOW_SYS},
1654 {sys_log_warnings.name, (char*) &sys_log_warnings, SHOW_SYS},
6f73e838
ER		 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},
833f2639 1657 {sys_low_priority_updates.name, (char*) &sys_low_priority_updates, SHOW_SYS},
6f73e838
ER		 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},
45532174 1660@@ -1022,6 +1052,7 @@
833f2639
ER		 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,
45532174 1668@@ -1109,6 +1140,8 @@
6f73e838
ER		 1669 {sys_slave_trans_retries.name,(char*) &sys_slave_trans_retries, SHOW_SYS},
1670 #endif
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},
1676 #endif
45532174 1677@@ -1149,6 +1182,7 @@
dcc72bc6
ER		 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},
45532174 1685@@ -1777,6 +1811,17 @@
833f2639
ER		 1686 }
1687
6f73e838 1688
833f2639
ER		 1689+bool sys_var_thd_microtime::check(THD *thd, set_var *var)
1690+{
1691+ if (var->value->result_type() == DECIMAL_RESULT)
1692+ var->save_result.ulonglong_value= (ulonglong)(var->value->val_real() * 1000000);
6f73e838
ER		 1693+ else
1694+ var->save_result.ulonglong_value= (ulonglong)(var->value->val_int() * 1000000);
1695+
833f2639
ER		 1696+ return 0;
1697+}
1698+
833f2639 1699+
6f73e838
ER		 1700 bool sys_var_thd_bool::update(THD *thd, set_var *var)
1701 {
1702 if (var->type == OPT_GLOBAL)
45532174 1703@@ -1933,6 +1978,19 @@
6f73e838
ER		 1704 pthread_mutex_unlock(&LOCK_global_system_variables);
1705 return new Item_int(value);
45532174 1706 }
6f73e838
ER		 1707+ case SHOW_MICROTIME:
1708+ {
1709+ longlong value;
1710+ char buff[80];
1711+ int len;
833f2639 1712+
6f73e838
ER		 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);
833f2639 1716+
6f73e838
ER		 1717+ len = snprintf(buff, 80, "%f", ((double) value) / 1000000.0);
1718+ return new Item_float(buff,len);
45532174 1719+ }
6f73e838
ER		 1720 case SHOW_HA_ROWS:
1721 {
45532174
ER		 1722 ha_rows value;
1723@@ -2765,6 +2823,30 @@
6f73e838
ER		 1724 }
1725
1726
1727+bool sys_var_log_slow::update(THD *thd, set_var *var)
1728+{
1729+ bool ret;
833f2639 1730+
6f73e838
ER		 1731+ pthread_mutex_lock(&LOCK_global_system_variables);
1732+ if (var->save_result.ulong_value)
833f2639 1733+ {
6f73e838
ER		 1734+ if(!mysql_slow_log.is_open())
1735+ {
1736+ mysql_slow_log.open_slow_log(opt_slow_logname);
1737+ }
833f2639 1738+ }
6f73e838 1739+ pthread_mutex_unlock(&LOCK_global_system_variables);
833f2639 1740+
6f73e838
ER		 1741+ ret = sys_var_bool_ptr::update(thd, var);
1742+
1743+#ifdef HAVE_INNOBASE_DB
1744+ innobase_update_var_slow_log();
1745+#endif
1746+
1747+ return(ret);
833f2639 1748+}
6f73e838
ER		 1749+
1750+
1751 #ifdef HAVE_REPLICATION
1752 bool sys_var_slave_skip_counter::check(THD *thd, set_var *var)
833f2639 1753 {
89b96684 1754@@ -3549,6 +3631,191 @@
833f2639
ER		 1755 #endif
1756 }
1757
1758+/* Slow log stuff */
1759+
1760+ulong msl_option_resolve_by_name(const struct msl_opts *opts, const char *name, ulong len)
1761+{
1762+ ulong i;
1763+
1764+ for (i=0; opts[i].name; i++)
1765+ {
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;
1770+ }
1771+ return opts[i].val;
1772+}
1773+
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)
1776+{
1777+ const char *p, *e;
1778+ ulong val= none_val;
1779+
1780+ if (!*names_list)
1781+ return val;
1782+
1783+ for (p= e= names_list; ; e++)
1784+ {
1785+ ulong i;
1786+
1787+ if (*e != ',' && *e)
1788+ continue;
1789+ for (i=0; opts[i].name; i++)
1790+ {
1791+ if (!my_strnncoll(&my_charset_latin1,
1792+ (const uchar *)p, e - p,
1793+ (const uchar *)opts[i].name, strlen(opts[i].name)))
1794+ {
1795+ val= val | opts[i].val;
1796+ break;
1797+ }
1798+ }
1799+ if (opts[i].val == invalid_val)
1800+ return invalid_val;
1801+ if (!*e)
1802+ break;
1803+ p= e + 1;
1804+ }
1805+ return val;
1806+}
1807+
1808+const char *msl_option_get_name(const struct msl_opts *opts, ulong val)
1809+{
1810+ for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1811+ {
1812+ if (opts[i].val == val)
1813+ return opts[i].name;
1814+ }
1815+ return "*INVALID*";
1816+}
1817+
1818+char *msl_flag_get_name(const struct msl_opts *opts, char *buf, ulong val)
1819+{
1820+ uint offset= 0;
1821+
1822+ *buf= '\0';
1823+ for (ulong i=0; opts[i].name && opts[i].name[0]; i++)
1824+ {
1825+ if (opts[i].val & val)
1826+ offset+= snprintf(buf+offset, STRING_BUFFER_USUAL_SIZE - offset - 1,
1827+ "%s%s", (offset ? "," : ""), opts[i].name);
1828+ }
1829+ return buf;
1830+}
1831+
1832+/****************************************************************************
1833+ Functions to handle log_slow_verbosity
1834+****************************************************************************/
1835+
1836+/* Based upon sys_var::check_enum() */
1837+
1838+bool sys_var_thd_msl_option::check(THD *thd, set_var *var)
1839+{
1840+ char buff[STRING_BUFFER_USUAL_SIZE];
1841+ String str(buff, sizeof(buff), &my_charset_latin1), *res;
1842+
1843+ if (var->value->result_type() == STRING_RESULT)
1844+ {
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)
1849+ goto err;
1850+ return 0;
1851+ }
1852+
1853+err:
1854+ my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1855+ return 1;
1856+}
1857+
1858+byte *sys_var_thd_msl_option::value_ptr(THD *thd, enum_var_type type,
1859+ LEX_STRING *base)
1860+{
1861+ ulong val;
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;
1866+}
1867+
1868+
1869+void sys_var_thd_msl_option::set_default(THD *thd, enum_var_type type)
1870+{
1871+ if (type == OPT_GLOBAL)
1872+ global_system_variables.*offset= (ulong) this->default_val;
1873+ else
1874+ thd->variables.*offset= (ulong) (global_system_variables.*offset);
1875+}
1876+
1877+
1878+bool sys_var_thd_msl_option::update(THD *thd, set_var *var)
1879+{
1880+ if (var->type == OPT_GLOBAL)
1881+ global_system_variables.*offset= var->save_result.ulong_value;
1882+ else
1883+ thd->variables.*offset= var->save_result.ulong_value;
1884+ return 0;
1885+}
1886+
1887+/****************************************************************************
1888+ Functions to handle log_slow_filter
1889+****************************************************************************/
1890+
1891+/* Based upon sys_var::check_enum() */
1892+
1893+bool sys_var_thd_msl_flag::check(THD *thd, set_var *var)
1894+{
1895+ char buff[2 * STRING_BUFFER_USUAL_SIZE];
1896+ String str(buff, sizeof(buff), &my_charset_latin1), *res;
1897+
1898+ if (var->value->result_type() == STRING_RESULT)
1899+ {
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)
1905+ goto err;
1906+ return 0;
1907+ }
1908+
1909+err:
1910+ my_error(ER_WRONG_ARGUMENTS, MYF(0), var->var->name);
1911+ return 1;
1912+}
1913+
1914+byte *sys_var_thd_msl_flag::value_ptr(THD *thd, enum_var_type type,
1915+ LEX_STRING *base)
1916+{
1917+ ulong val;
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;
1922+}
1923+
1924+
1925+void sys_var_thd_msl_flag::set_default(THD *thd, enum_var_type type)
1926+{
1927+ if (type == OPT_GLOBAL)
1928+ global_system_variables.*offset= (ulong) this->default_val;
1929+ else
1930+ thd->variables.*offset= (ulong) (global_system_variables.*offset);
1931+}
1932+
1933+
1934+bool sys_var_thd_msl_flag::update(THD *thd, set_var *var)
1935+{
1936+ if (var->type == OPT_GLOBAL)
1937+ global_system_variables.*offset= var->save_result.ulong_value;
1938+ else
1939+ thd->variables.*offset= var->save_result.ulong_value;
1940+ return 0;
1941+}
1942+
1943 /****************************************************************************
1944 Functions to handle table_type
1945 ****************************************************************************/
89b96684
ER		 1946diff -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
6f73e838 1949@@ -132,6 +132,7 @@
833f2639
ER		 1950 };
1951
1952
1953+
1954 class sys_var_ulonglong_ptr :public sys_var
1955 {
1956 public:
6f73e838
ER		 1957@@ -168,6 +169,13 @@
1958 bool check_update_type(Item_result type) { return 0; }
1959 };
1960
1961+class sys_var_log_slow :public sys_var_bool_ptr
1962+{
1963+public:
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);
1967+};
1968
1969 class sys_var_bool_const_ptr : public sys_var
1970 {
1971@@ -340,7 +348,6 @@
833f2639
ER		 1972 }
1973 };
1974
1975-
1976 class sys_var_thd_ulong :public sys_var_thd
1977 {
1978 sys_check_func check_func;
6f73e838 1979@@ -360,7 +367,6 @@
833f2639
ER		 1980 byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1981 };
1982
6f73e838 1983-
833f2639
ER		 1984 class sys_var_thd_ha_rows :public sys_var_thd
1985 {
6f73e838 1986 public:
45532174 1987@@ -378,7 +384,6 @@
833f2639
ER		 1988 byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base);
1989 };
833f2639 1990
45532174 1991-
833f2639
ER		 1992 class sys_var_thd_ulonglong :public sys_var_thd
1993 {
45532174 1994 public:
6f73e838 1995@@ -407,6 +412,19 @@
833f2639
ER		 1996 }
1997 };
1998
6f73e838
ER		 1999+class sys_var_thd_microtime :public sys_var_thd_ulonglong
2000+{
2001+public:
2002+ sys_var_thd_microtime(const char *name_arg, ulonglong SV::*offset_arg)
2003+ :sys_var_thd_ulonglong(name_arg, offset_arg)
2004+ {}
2005+ SHOW_TYPE show_type() { return SHOW_MICROTIME; }
2006+ bool check(THD *thd, set_var *var);
2007+ bool check_update_type(Item_result type)
2008+ {
2009+ return type != INT_RESULT && type != DECIMAL_RESULT;
2010+ }
2011+};
2012
833f2639
ER		 2013 class sys_var_thd_bool :public sys_var_thd
2014 {
45532174 2015@@ -478,6 +496,66 @@
833f2639
ER		 2016 };
2017
45532174 2018
833f2639
ER		 2019+class sys_var_thd_msl_option :public sys_var_thd
2020+{
2021+protected:
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;
2027+public:
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),
2035+ opts(opts_arg)
2036+ {}
2037+ bool check(THD *thd, set_var *var);
2038+ SHOW_TYPE show_type() { return SHOW_CHAR; }
2039+ bool check_update_type(Item_result type)
2040+ {
2041+ return type != STRING_RESULT; /* Only accept strings */
2042+ }
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);
2046+};
2047+
2048+
2049+class sys_var_thd_msl_flag :public sys_var_thd
2050+{
2051+protected:
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;
2058+public:
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),
2066+ flags(flags_arg)
2067+ {}
2068+ bool check(THD *thd, set_var *var);
2069+ SHOW_TYPE show_type() { return SHOW_CHAR; }
2070+ bool check_update_type(Item_result type)
2071+ {
2072+ return type != STRING_RESULT; /* Only accept strings */
2073+ }
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);
2077+};
45532174 2078+
833f2639
ER		 2079 class sys_var_thd_storage_engine :public sys_var_thd
2080 {
45532174 2081 protected:
89b96684 2082@@ -1109,3 +1187,11 @@
833f2639
ER		 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));
2086+
2087+/* Slow log functions */
2088+
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);
89b96684
ER		 2094diff -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 @@
833f2639
ER		 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)
2102+ {
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;
2106+ }
2107 thd->client_capabilities = CLIENT_LOCAL_FILES;
2108 thd->real_id=pthread_self();
2109 pthread_mutex_lock(&LOCK_thread_count);
89b96684
ER		 2110diff -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
45532174 2113@@ -1402,6 +1402,7 @@
833f2639
ER		 2114
2115 thd->limit_found_rows = query->found_rows();
2116 thd->status_var.last_query_cost= 0.0;
2117+ thd->query_plan_flags|= QPLAN_QC;
2118
2119 BLOCK_UNLOCK_RD(query_block);
2120 DBUG_RETURN(1); // Result sent to client
45532174 2121@@ -1409,6 +1410,7 @@
833f2639
ER		 2122 err_unlock:
2123 STRUCT_UNLOCK(&structure_guard_mutex);
2124 err:
2125+ thd->query_plan_flags|= QPLAN_QC_NO;
2126 DBUG_RETURN(0); // Query was not cached
2127 }
2128
89b96684
ER		 2129diff -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
45532174
ER		 2132@@ -190,7 +190,7 @@
2133 table_map_for_update(0),
2134 global_read_lock(0), is_fatal_error(0),
833f2639
ER		 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),
45532174 2141@@ -2251,6 +2251,12 @@
833f2639
ER		 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;
2151
2152 if (!lex->requires_prelocking() || is_update_query(lex->sql_command))
2153 options&= ~OPTION_BIN_LOG;
45532174 2154@@ -2267,7 +2273,13 @@
833f2639
ER		 2155 sent_row_count= 0;
2156 cuted_fields= 0;
2157 transaction.savepoints= 0;
2158-
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;
2165+
2166 /* Surpress OK packets in case if we will execute statements */
2167 net.no_send_ok= TRUE;
2168 }
45532174 2169@@ -2320,6 +2332,12 @@
833f2639
ER		 2170 */
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;
2179 }
2180
2181
89b96684
ER		 2182diff -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
6f73e838 2185@@ -43,6 +43,7 @@
833f2639
ER		 2186 extern char internal_table_name[2];
2187 extern char empty_c_string[1];
2188 extern const char **errmesg;
833f2639 2189+extern ulonglong frequency;
833f2639
ER		 2190
2191 #define TC_LOG_PAGE_SIZE 8192
2192 #define TC_LOG_MIN_SIZE (3*TC_LOG_PAGE_SIZE)
337bc045 2193@@ -321,7 +322,7 @@
833f2639
ER		 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);
2201
337bc045 2202@@ -527,13 +528,14 @@
833f2639
ER		 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;
337bc045 2218@@ -549,10 +551,13 @@
833f2639 2219 ulong preload_buff_size;
6f73e838 2220 ulong profiling_history_size;
833f2639
ER		 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;
2229 ulong table_type;
2230 ulong tx_isolation;
2231 ulong completion_type;
45532174 2232@@ -1129,6 +1134,12 @@
833f2639
ER		 2233 uint in_sub_stmt;
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;
2242 my_bool no_send_ok;
2243 SAVEPOINT *savepoints;
2244 };
45532174 2245@@ -1185,6 +1196,11 @@
833f2639
ER		 2246 class THD :public Statement,
2247 public Open_tables_state
2248 {
2249+private:
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); }
2254 public:
2255 /*
2256 Constant for THD::where initialization in the beginning of every query.
45532174 2257@@ -1293,10 +1309,24 @@
833f2639
ER		 2258 */
2259 const char *where;
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;
2264 Delayed_insert *di;
2265
2266+ bool write_to_slow_log;
2267+
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;
2275+
2276+ ulong query_plan_flags;
2277+ ulong query_plan_fsort_passes;
2278+
2279 /* <> 0 if we are inside of trigger or stored function. */
2280 uint in_sub_stmt;
2281
45532174 2282@@ -1696,11 +1726,11 @@
833f2639
ER		 2283 sql_print_information("time() failed with %d", errno);
2284 }
2285
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)
2297 {
2298 last_insert_id= id_arg;
89b96684
ER		 2299diff -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
833f2639
ER		 2302@@ -20,6 +20,7 @@
2303 #include <m_ctype.h>
2304 #include <myisam.h>
2305 #include <my_dir.h>
2306+#include <my_time.h>
2307
2308 #ifdef HAVE_INNOBASE_DB
2309 #include "ha_innodb.h"
45532174 2310@@ -1227,6 +1228,15 @@
833f2639
ER		 2311 my_net_set_read_timeout(net, thd->variables.net_read_timeout);
2312 my_net_set_write_timeout(net, thd->variables.net_write_timeout);
2313
2314+ /*
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. :)
2317+ */
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;
2322+
2323 while (!net->error && net->vio != 0 &&
2324 !(thd->killed == THD::KILL_CONNECTION))
2325 {
89b96684 2326@@ -2353,28 +2363,57 @@
833f2639
ER		 2327 return; // Don't set time for sub stmt
2328
2329 start_of_query= thd->start_time;
45532174 2330- thd->end_time(); // Set start time
833f2639 2331+ ulonglong start_of_query_timer= thd->start_timer;
45532174
ER		 2332+ thd->end_time(); // Set start timea
2333+
833f2639
ER		 2334+
2335+ /* Follow the slow log filter configuration. */
45532174 2336+ if (thd->variables.log_slow_filter != SLOG_F_NONE &&
833f2639 2337+ (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
45532174 2338+ ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
833f2639
ER		 2339+ (thd->query_plan_flags & QPLAN_QC))))
2340+ return;
2341+
2342+ /*
45532174
ER		 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
833f2639
ER		 2346+ to make an exception and write to slow log anyway.
2347+ */
45532174 2348+
dcc72bc6
ER		 2349+ if (opt_use_global_long_query_time)
2350+ thd->variables.long_query_time = global_system_variables.long_query_time;
833f2639
ER		 2351+
2352+ /* Do not log this thread's queries due to rate limiting. */
45532174
ER		 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))
833f2639 2356+ return;
8d64228d 2357+
45532174 2358
833f2639
ER		 2359 /*
2360 Do not log administrative statements unless the appropriate option is
2361 set; do not log into slow log if reading from backup.
2362 */
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))
2366+ )
45532174 2367+
833f2639 2368 {
6f73e838 2369 thd_proc_info(thd, "logging slow query");
833f2639 2370
529deea8
AM		 2371- if ((thd->start_time > thd->time_after_lock &&
2372- (ulong) (thd->start_time - thd->time_after_lock) >
45532174 2373- thd->variables.long_query_time) ||
a709df28 2374- ((thd->server_status &
45532174
ER		 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 */
a709df28 2378- thd->lex->orig_sql_command == SQLCOM_END))
45532174
ER		 2379+ if (((ulong) (thd->start_timer - thd->timer_after_lock) >=
2380+ thd->variables.long_query_time ||
89b96684 2381+ (thd->server_status &
45532174
ER		 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 */
89b96684 2385+ thd->lex->orig_sql_command == SQLCOM_END) &&
45532174 2386+ thd->examined_row_count >= thd->variables.min_examined_row_limit)
833f2639 2387 {
6f73e838 2388 thd_proc_info(thd, "logging slow query");
833f2639
ER		 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);
2392 }
2393 }
2394 }
89b96684 2395@@ -2669,6 +2708,8 @@
45532174
ER		 2396 context.resolve_in_table_list_only((TABLE_LIST*)select_lex->
2397 table_list.first);
2398
2399+ /* Reset the counter at all cases for the extended slow query log */
2400+ thd->row_count= 1;
2401 /*
2402 Reset warning count for each query that uses tables
2403 A better approach would be to reset this for any commands
89b96684 2404@@ -6203,6 +6244,15 @@
45532174
ER		 2405 thd->total_warn_count=0; // Warnings for this query
2406 thd->rand_used= 0;
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;
2417 }
2418 DBUG_VOID_RETURN;
2419 }
89b96684
ER		 2420diff -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 @@
833f2639
ER		 2424 {
2425 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2426 if (statistics)
2427+ {
2428 statistic_increment(join->thd->status_var.select_scan_count,
2429 &LOCK_status);
2430+ join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
2431+ }
2432 }
2433 }
2434 else
89b96684 2435@@ -6288,8 +6291,11 @@
833f2639
ER		 2436 {
2437 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
2438 if (statistics)
2439+ {
2440 statistic_increment(join->thd->status_var.select_full_join_count,
2441 &LOCK_status);
2442+ join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
2443+ }
2444 }
2445 }
2446 if (!table->no_keyread)
89b96684 2447@@ -9350,6 +9356,7 @@
833f2639
ER		 2448 (ulong) rows_limit,test(group)));
2449
2450 statistic_increment(thd->status_var.created_tmp_tables, &LOCK_status);
2451+ thd->query_plan_flags|= QPLAN_TMP_TABLE;
2452
2453 if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
2454 temp_pool_slot = bitmap_set_next(&temp_pool);
89b96684 2455@@ -10210,6 +10217,7 @@
833f2639
ER		 2456 }
2457 statistic_increment(table->in_use->status_var.created_tmp_disk_tables,
2458 &LOCK_status);
2459+ table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
2460 table->s->db_record_offset= 1;
2461 DBUG_RETURN(0);
2462 err:
89b96684
ER		 2463diff -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
45532174 2466@@ -1560,6 +1560,12 @@
833f2639
ER		 2467 case SHOW_LONGLONG:
2468 end= longlong10_to_str(*(longlong*) value, buff, 10);
45532174 2469 break;
833f2639 2470+ case SHOW_MICROTIME:
6f73e838
ER		 2471+ show_type= ((sys_var*) value)->show_type();
2472+ value= (char*) ((sys_var*) value)->value_ptr(thd, value_type,
2473+ &null_lex_str);
2474+ end= buff + sprintf(buff, "%f", (((double) (*(ulonglong*)value))) / 1000000.0);
45532174 2475+ break;
833f2639
ER		 2476 case SHOW_HA_ROWS:
2477 end= longlong10_to_str((longlong) *(ha_rows*) value, buff, 10);
45532174 2478 break;
89b96684
ER		 2479diff -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
6f73e838 2482@@ -168,8 +168,8 @@
833f2639
ER		 2483 enum SHOW_TYPE
2484 {
2485 SHOW_UNDEF,
2486- SHOW_LONG, SHOW_LONGLONG, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
6f73e838 2487- SHOW_DOUBLE_STATUS,
990729de 2488+ SHOW_LONG, SHOW_LONGLONG, SHOW_MICROTIME, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR,
6f73e838 2489+ SHOW_DOUBLE_STATUS,
a1c5b050 2490 SHOW_BOOL, SHOW_MY_BOOL, SHOW_OPENTABLES, SHOW_STARTTIME, SHOW_QUERIES,
833f2639 2491 SHOW_LONG_CONST, SHOW_INT_CONST, SHOW_HAVE, SHOW_SYS, SHOW_HA_ROWS,
6f73e838 2492 SHOW_VARS,
MySQL: a very fast and reliable SQL database engine
This page took 0.371286 seconds and 4 git commands to generate.