]>
Commit | Line | Data |
---|---|---|
b4e1fa2c AM |
1 | # name : slow_extended.patch |
2 | # introduced : 11 or before | |
3 | # maintainer : Oleg | |
4 | # | |
5 | #!!! notice !!! | |
6 | # Any small change to this file in the main branch | |
7 | # should be done or reviewed by the maintainer! | |
db82db79 AM |
8 | --- a/include/mysql/plugin_audit.h.pp |
9 | +++ b/include/mysql/plugin_audit.h.pp | |
734d6226 | 10 | @@ -186,6 +186,16 @@ |
b4e1fa2c AM |
11 | char *thd_security_context(void* thd, char *buffer, unsigned int length, |
12 | unsigned int max_query_len); | |
13 | void thd_inc_row_count(void* thd); | |
14 | +void increment_thd_innodb_stats(void* thd, | |
15 | + unsigned long long trx_id, | |
16 | + long io_reads, | |
17 | + long long io_read, | |
18 | + long io_reads_wait_timer, | |
19 | + long lock_que_wait_timer, | |
20 | + long que_wait_timer, | |
21 | + long page_access); | |
22 | +unsigned long thd_log_slow_verbosity(const void* thd); | |
23 | +int thd_opt_slow_log(); | |
24 | int mysql_tmpfile(const char *prefix); | |
25 | int thd_killed(const void* thd); | |
26 | unsigned long thd_get_thread_id(const void* thd); | |
db82db79 AM |
27 | --- a/include/mysql/plugin_auth.h.pp |
28 | +++ b/include/mysql/plugin_auth.h.pp | |
734d6226 | 29 | @@ -186,6 +186,16 @@ |
b4e1fa2c AM |
30 | char *thd_security_context(void* thd, char *buffer, unsigned int length, |
31 | unsigned int max_query_len); | |
32 | void thd_inc_row_count(void* thd); | |
33 | +void increment_thd_innodb_stats(void* thd, | |
34 | + unsigned long long trx_id, | |
35 | + long io_reads, | |
36 | + long long io_read, | |
37 | + long io_reads_wait_timer, | |
38 | + long lock_que_wait_timer, | |
39 | + long que_wait_timer, | |
40 | + long page_access); | |
41 | +unsigned long thd_log_slow_verbosity(const void* thd); | |
42 | +int thd_opt_slow_log(); | |
43 | int mysql_tmpfile(const char *prefix); | |
44 | int thd_killed(const void* thd); | |
45 | unsigned long thd_get_thread_id(const void* thd); | |
db82db79 AM |
46 | --- a/include/mysql/plugin_ftparser.h.pp |
47 | +++ b/include/mysql/plugin_ftparser.h.pp | |
734d6226 | 48 | @@ -139,6 +139,16 @@ |
b4e1fa2c AM |
49 | char *thd_security_context(void* thd, char *buffer, unsigned int length, |
50 | unsigned int max_query_len); | |
51 | void thd_inc_row_count(void* thd); | |
52 | +void increment_thd_innodb_stats(void* thd, | |
53 | + unsigned long long trx_id, | |
54 | + long io_reads, | |
55 | + long long io_read, | |
56 | + long io_reads_wait_timer, | |
57 | + long lock_que_wait_timer, | |
58 | + long que_wait_timer, | |
59 | + long page_access); | |
60 | +unsigned long thd_log_slow_verbosity(const void* thd); | |
61 | +int thd_opt_slow_log(); | |
62 | int mysql_tmpfile(const char *prefix); | |
63 | int thd_killed(const void* thd); | |
64 | unsigned long thd_get_thread_id(const void* thd); | |
db82db79 AM |
65 | --- a/include/mysql/plugin.h |
66 | +++ b/include/mysql/plugin.h | |
734d6226 | 67 | @@ -545,6 +545,17 @@ |
b4e1fa2c AM |
68 | /* Increments the row counter, see THD::row_count */ |
69 | void thd_inc_row_count(MYSQL_THD thd); | |
70 | ||
71 | +void increment_thd_innodb_stats(MYSQL_THD thd, | |
72 | + unsigned long long trx_id, | |
73 | + long io_reads, | |
74 | + long long io_read, | |
75 | + long io_reads_wait_timer, | |
76 | + long lock_que_wait_timer, | |
77 | + long que_wait_timer, | |
78 | + long page_access); | |
79 | +unsigned long thd_log_slow_verbosity(const MYSQL_THD thd); | |
80 | +int thd_opt_slow_log(); | |
81 | +#define EXTENDED_SLOWLOG | |
82 | /** | |
83 | Create a temporary file. | |
84 | ||
db82db79 AM |
85 | --- /dev/null |
86 | +++ b/patch_info/slow_extended.info | |
b4e1fa2c AM |
87 | @@ -0,0 +1,25 @@ |
88 | +File=slow_extended.patch | |
89 | +Name=Extended statistics in slow.log (not InnoDB part) | |
90 | +Version=1.3 | |
91 | +Author=Percona <info@percona.com> | |
92 | +License=GPL | |
93 | +Comment= | |
94 | +Changelog | |
95 | +2008-11-26 | |
96 | +YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool). | |
97 | + | |
98 | +2008-11-07 | |
99 | +VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place | |
100 | + | |
101 | +2008-11 | |
102 | +Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au> | |
103 | + | |
104 | +2010-07 | |
105 | +1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged) | |
106 | +2) Control global slow feature merged (control_global_slow.patch merged) | |
107 | +3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged) | |
108 | +4) Now use_global_long_query_time and use_global_log_slow_control are synonims. Add value "all" for use_global_log_slow_control (contol-global_slow-2.patch merged) | |
109 | +5) Fix innodb_stats on replication (Bug 600684) | |
110 | +6) Change variable types (system/command-line) | |
a9ee80b9 | 111 | +2011-01 |
b4e1fa2c | 112 | +Patch profiling_slow.patch was merged |
db82db79 AM |
113 | --- a/scripts/mysqldumpslow.sh |
114 | +++ b/scripts/mysqldumpslow.sh | |
115 | @@ -102,8 +102,8 @@ | |
b4e1fa2c AM |
116 | s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//; |
117 | my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('',''); | |
118 | ||
119 | - s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//; | |
120 | - my ($t, $l, $r) = ($1, $2, $3); | |
121 | + s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//; | |
122 | + my ($t, $l, $r) = ($1, $3, $5); | |
123 | $t -= $l unless $opt{l}; | |
124 | ||
125 | # remove fluff that mysqld writes to log when it (re)starts: | |
db82db79 AM |
126 | --- a/sql/event_scheduler.cc |
127 | +++ b/sql/event_scheduler.cc | |
b4e1fa2c AM |
128 | @@ -195,6 +195,7 @@ |
129 | thd->client_capabilities|= CLIENT_MULTI_RESULTS; | |
130 | mysql_mutex_lock(&LOCK_thread_count); | |
131 | thd->thread_id= thd->variables.pseudo_thread_id= thread_id++; | |
1c82f14e | 132 | + thd->write_to_slow_log= true; |
b4e1fa2c AM |
133 | mysql_mutex_unlock(&LOCK_thread_count); |
134 | ||
135 | /* | |
db82db79 AM |
136 | --- a/sql/filesort.cc |
137 | +++ b/sql/filesort.cc | |
734d6226 | 138 | @@ -193,6 +193,7 @@ |
b4e1fa2c AM |
139 | { |
140 | status_var_increment(thd->status_var.filesort_scan_count); | |
141 | } | |
142 | + thd->query_plan_flags|= QPLAN_FILESORT; | |
143 | #ifdef CAN_TRUST_RANGE | |
144 | if (select && select->quick && select->quick->records > 0L) | |
145 | { | |
734d6226 AM |
146 | @@ -261,6 +262,7 @@ |
147 | /* filesort cannot handle zero-length records during merge. */ | |
148 | DBUG_ASSERT(param.sort_length != 0); | |
149 | ||
b4e1fa2c AM |
150 | + thd->query_plan_flags|= QPLAN_FILESORT_DISK; |
151 | if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer) | |
152 | { | |
153 | my_free(table_sort.buffpek); | |
734d6226 | 154 | @@ -1209,6 +1211,7 @@ |
b4e1fa2c AM |
155 | DBUG_ENTER("merge_buffers"); |
156 | ||
157 | status_var_increment(current_thd->status_var.filesort_merge_passes); | |
158 | + current_thd->query_plan_fsort_passes++; | |
159 | if (param->not_killable) | |
160 | { | |
161 | killed= ¬_killable; | |
db82db79 AM |
162 | --- a/sql/log.cc |
163 | +++ b/sql/log.cc | |
d8778560 | 164 | @@ -715,11 +715,13 @@ |
b4e1fa2c AM |
165 | */ |
166 | ||
167 | bool Log_to_csv_event_handler:: | |
168 | - log_slow(THD *thd, time_t current_time, time_t query_start_arg, | |
169 | + log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg, | |
170 | const char *user_host, uint user_host_len, | |
171 | ulonglong query_utime, ulonglong lock_utime, bool is_command, | |
172 | const char *sql_text, uint sql_text_len) | |
173 | { | |
174 | + time_t current_time= my_time_possible_from_micro(current_utime); | |
175 | + | |
176 | TABLE_LIST table_list; | |
177 | TABLE *table; | |
178 | bool result= TRUE; | |
d8778560 | 179 | @@ -935,14 +937,14 @@ |
b4e1fa2c AM |
180 | /** Wrapper around MYSQL_LOG::write() for slow log. */ |
181 | ||
182 | bool Log_to_file_event_handler:: | |
183 | - log_slow(THD *thd, time_t current_time, time_t query_start_arg, | |
184 | + log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg, | |
185 | const char *user_host, uint user_host_len, | |
186 | ulonglong query_utime, ulonglong lock_utime, bool is_command, | |
187 | const char *sql_text, uint sql_text_len) | |
188 | { | |
189 | Silence_log_table_errors error_handler; | |
190 | thd->push_internal_handler(&error_handler); | |
191 | - bool retval= mysql_slow_log.write(thd, current_time, query_start_arg, | |
192 | + bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg, | |
193 | user_host, user_host_len, | |
194 | query_utime, lock_utime, is_command, | |
195 | sql_text, sql_text_len); | |
13ceb006 AM |
196 | @@ -1200,8 +1202,6 @@ |
197 | ||
198 | if (*slow_log_handler_list) | |
199 | { | |
200 | - time_t current_time; | |
201 | - | |
202 | /* do not log slow queries from replication threads */ | |
203 | if (thd->slave_thread && !opt_log_slow_slave_statements) | |
204 | return 0; | |
205 | @@ -1216,16 +1216,29 @@ | |
b4e1fa2c AM |
206 | /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */ |
207 | user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE, | |
208 | sctx->priv_user ? sctx->priv_user : "", "[", | |
209 | - sctx->user ? sctx->user : "", "] @ ", | |
210 | + sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ", | |
211 | sctx->host ? sctx->host : "", " [", | |
212 | sctx->ip ? sctx->ip : "", "]", NullS) - | |
213 | user_host_buff); | |
13ceb006 AM |
214 | |
215 | - current_time= my_time_possible_from_micro(current_utime); | |
b4e1fa2c AM |
216 | if (thd->start_utime) |
217 | { | |
218 | - query_utime= (current_utime - thd->start_utime); | |
219 | - lock_utime= (thd->utime_after_lock - thd->start_utime); | |
220 | + if(current_utime < thd->start_utime) | |
221 | + { | |
222 | + query_utime= 0; | |
223 | + } | |
224 | + else | |
225 | + { | |
226 | + query_utime= (current_utime - thd->start_utime); | |
227 | + } | |
228 | + if(thd->utime_after_lock < thd->start_utime) | |
229 | + { | |
230 | + lock_utime= 0; | |
231 | + } | |
232 | + else | |
233 | + { | |
234 | + lock_utime= (thd->utime_after_lock - thd->start_utime); | |
235 | + } | |
236 | } | |
237 | else | |
238 | { | |
13ceb006 | 239 | @@ -1240,7 +1253,7 @@ |
b4e1fa2c AM |
240 | } |
241 | ||
b4e1fa2c AM |
242 | for (current_handler= slow_log_handler_list; *current_handler ;) |
243 | - error= (*current_handler++)->log_slow(thd, current_time, thd->start_time, | |
244 | + error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time, | |
245 | user_host_buff, user_host_len, | |
246 | query_utime, lock_utime, is_command, | |
247 | query, query_length) || error; | |
13ceb006 | 248 | @@ -2656,12 +2669,13 @@ |
b4e1fa2c AM |
249 | TRUE - error occured |
250 | */ | |
251 | ||
252 | -bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time, | |
253 | +bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime, | |
254 | time_t query_start_arg, const char *user_host, | |
255 | uint user_host_len, ulonglong query_utime, | |
256 | ulonglong lock_utime, bool is_command, | |
257 | const char *sql_text, uint sql_text_len) | |
258 | { | |
259 | + time_t current_time= my_time_possible_from_micro(current_utime); | |
260 | bool error= 0; | |
261 | DBUG_ENTER("MYSQL_QUERY_LOG::write"); | |
262 | ||
13ceb006 | 263 | @@ -2683,17 +2697,28 @@ |
b4e1fa2c AM |
264 | |
265 | if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT)) | |
266 | { | |
267 | - if (current_time != last_time) | |
a9ee80b9 | 268 | + if (opt_slow_query_log_timestamp_always || current_time != last_time) |
b4e1fa2c AM |
269 | { |
270 | last_time= current_time; | |
271 | struct tm start; | |
272 | localtime_r(¤t_time, &start); | |
273 | - | |
274 | - buff_len= my_snprintf(buff, sizeof buff, | |
275 | - "# Time: %02d%02d%02d %2d:%02d:%02d\n", | |
276 | - start.tm_year % 100, start.tm_mon + 1, | |
277 | - start.tm_mday, start.tm_hour, | |
278 | - start.tm_min, start.tm_sec); | |
a9ee80b9 | 279 | + if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND) |
b4e1fa2c AM |
280 | + { |
281 | + ulonglong microsecond = current_utime % (1000 * 1000); | |
282 | + buff_len= snprintf(buff, sizeof buff, | |
283 | + "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n", | |
284 | + start.tm_year % 100, start.tm_mon + 1, | |
285 | + start.tm_mday, start.tm_hour, | |
286 | + start.tm_min, start.tm_sec,microsecond); | |
287 | + } | |
288 | + else | |
289 | + { | |
290 | + buff_len= my_snprintf(buff, sizeof buff, | |
291 | + "# Time: %02d%02d%02d %2d:%02d:%02d\n", | |
292 | + start.tm_year % 100, start.tm_mon + 1, | |
293 | + start.tm_mday, start.tm_hour, | |
294 | + start.tm_min, start.tm_sec); | |
295 | + } | |
296 | ||
297 | /* Note that my_b_write() assumes it knows the length for this */ | |
298 | if (my_b_write(&log_file, (uchar*) buff, buff_len)) | |
13ceb006 | 299 | @@ -2710,13 +2735,71 @@ |
9dd04cbc | 300 | /* For slow query log */ |
b4e1fa2c AM |
301 | sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0); |
302 | sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0); | |
9dd04cbc | 303 | + DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno)); |
b4e1fa2c AM |
304 | if (my_b_printf(&log_file, |
305 | - "# Query_time: %s Lock_time: %s" | |
306 | - " Rows_sent: %lu Rows_examined: %lu\n", | |
307 | + "# Thread_id: %lu Schema: %s Last_errno: %u Killed: %u\n" \ | |
308 | + "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n" | |
309 | + "# Bytes_sent: %lu Tmp_tables: %lu Tmp_disk_tables: %lu Tmp_table_sizes: %lu\n", | |
310 | + (ulong) thd->thread_id, (thd->db ? thd->db : ""), | |
311 | + thd->last_errno, (uint) thd->killed, | |
312 | query_time_buff, lock_time_buff, | |
313 | (ulong) thd->sent_row_count, | |
314 | - (ulong) thd->examined_row_count) == (uint) -1) | |
315 | + (ulong) thd->examined_row_count, | |
316 | + ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0, | |
317 | + (ulong) thd->sent_row_count, | |
318 | + (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old), | |
319 | + (ulong) thd->tmp_tables_used, | |
320 | + (ulong) thd->tmp_tables_disk_used, | |
321 | + (ulong) thd->tmp_tables_size) == (uint) -1) | |
322 | tmp_errno= errno; | |
323 | + | |
324 | +#if defined(ENABLED_PROFILING) | |
325 | + thd->profiling.print_current(&log_file); | |
326 | +#endif | |
327 | + if (thd->innodb_was_used) | |
328 | + { | |
329 | + char buf[20]; | |
330 | + snprintf(buf, 20, "%llX", thd->innodb_trx_id); | |
331 | + if (my_b_printf(&log_file, | |
332 | + "# InnoDB_trx_id: %s\n", buf) == (uint) -1) | |
333 | + tmp_errno=errno; | |
334 | + } | |
335 | + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) && | |
336 | + my_b_printf(&log_file, | |
337 | + "# QC_Hit: %s Full_scan: %s Full_join: %s Tmp_table: %s Tmp_table_on_disk: %s\n" \ | |
338 | + "# Filesort: %s Filesort_on_disk: %s Merge_passes: %lu\n", | |
339 | + ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"), | |
340 | + ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"), | |
341 | + ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"), | |
342 | + ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"), | |
343 | + ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"), | |
344 | + ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"), | |
345 | + ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"), | |
346 | + thd->query_plan_fsort_passes) == (uint) -1) | |
347 | + tmp_errno=errno; | |
348 | + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used) | |
349 | + { | |
350 | + char buf[3][20]; | |
351 | + snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0); | |
352 | + snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0); | |
353 | + snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0); | |
354 | + if (my_b_printf(&log_file, | |
355 | + "# InnoDB_IO_r_ops: %lu InnoDB_IO_r_bytes: %lu InnoDB_IO_r_wait: %s\n" \ | |
356 | + "# InnoDB_rec_lock_wait: %s InnoDB_queue_wait: %s\n" \ | |
357 | + "# InnoDB_pages_distinct: %lu\n", | |
358 | + (ulong) thd->innodb_io_reads, | |
359 | + (ulong) thd->innodb_io_read, | |
360 | + buf[0], buf[1], buf[2], | |
361 | + (ulong) thd->innodb_page_access) == (uint) -1) | |
362 | + tmp_errno=errno; | |
363 | + } | |
364 | + else | |
365 | + { | |
366 | + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && | |
367 | + my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1) | |
368 | + tmp_errno=errno; | |
369 | + } | |
370 | + | |
371 | if (thd->db && strcmp(thd->db, db)) | |
372 | { // Database changed | |
373 | if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1) | |
db82db79 AM |
374 | --- a/sql/log.h |
375 | +++ b/sql/log.h | |
b4e1fa2c AM |
376 | @@ -242,7 +242,7 @@ |
377 | uint user_host_len, int thread_id, | |
378 | const char *command_type, uint command_type_len, | |
379 | const char *sql_text, uint sql_text_len); | |
380 | - bool write(THD *thd, time_t current_time, time_t query_start_arg, | |
381 | + bool write(THD *thd, ulonglong current_time, time_t query_start_arg, | |
382 | const char *user_host, uint user_host_len, | |
383 | ulonglong query_utime, ulonglong lock_utime, bool is_command, | |
384 | const char *sql_text, uint sql_text_len); | |
1bfc1981 | 385 | @@ -517,7 +517,7 @@ |
b4e1fa2c AM |
386 | virtual bool init()= 0; |
387 | virtual void cleanup()= 0; | |
388 | ||
389 | - virtual bool log_slow(THD *thd, time_t current_time, | |
390 | + virtual bool log_slow(THD *thd, ulonglong current_time, | |
391 | time_t query_start_arg, const char *user_host, | |
392 | uint user_host_len, ulonglong query_utime, | |
393 | ulonglong lock_utime, bool is_command, | |
1bfc1981 | 394 | @@ -546,7 +546,7 @@ |
b4e1fa2c AM |
395 | virtual bool init(); |
396 | virtual void cleanup(); | |
397 | ||
398 | - virtual bool log_slow(THD *thd, time_t current_time, | |
399 | + virtual bool log_slow(THD *thd, ulonglong current_utime, | |
400 | time_t query_start_arg, const char *user_host, | |
401 | uint user_host_len, ulonglong query_utime, | |
402 | ulonglong lock_utime, bool is_command, | |
1bfc1981 | 403 | @@ -578,7 +578,7 @@ |
b4e1fa2c AM |
404 | virtual bool init(); |
405 | virtual void cleanup(); | |
406 | ||
407 | - virtual bool log_slow(THD *thd, time_t current_time, | |
408 | + virtual bool log_slow(THD *thd, ulonglong current_utime, | |
409 | time_t query_start_arg, const char *user_host, | |
410 | uint user_host_len, ulonglong query_utime, | |
411 | ulonglong lock_utime, bool is_command, | |
db82db79 AM |
412 | --- a/sql/mysqld.cc |
413 | +++ b/sql/mysqld.cc | |
1c82f14e | 414 | @@ -421,6 +421,11 @@ |
b4e1fa2c AM |
415 | char* opt_secure_file_priv; |
416 | my_bool opt_log_slow_admin_statements= 0; | |
417 | my_bool opt_log_slow_slave_statements= 0; | |
418 | +my_bool opt_log_slow_sp_statements= 0; | |
a9ee80b9 ER |
419 | +my_bool opt_slow_query_log_timestamp_always= 0; |
420 | +ulonglong opt_slow_query_log_use_global_control= 0; | |
adf0fb13 | 421 | +ulong opt_slow_query_log_timestamp_precision= 0; |
1c82f14e | 422 | +ulong opt_slow_query_log_rate_type= 0; |
b4e1fa2c AM |
423 | my_bool lower_case_file_system= 0; |
424 | my_bool opt_large_pages= 0; | |
425 | my_bool opt_super_large_pages= 0; | |
1c82f14e | 426 | @@ -5892,14 +5897,10 @@ |
734d6226 AM |
427 | "Don't log extra information to update and slow-query logs.", |
428 | &opt_short_log_format, &opt_short_log_format, | |
429 | 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, | |
430 | - {"log-slow-admin-statements", 0, | |
431 | - "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to " | |
432 | - "the slow log if it is open.", &opt_log_slow_admin_statements, | |
433 | - &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, | |
b4e1fa2c AM |
434 | - {"log-slow-slave-statements", 0, |
435 | + /*{"log-slow-slave-statements", 0, | |
436 | "Log slow statements executed by slave thread to the slow log if it is open.", | |
437 | &opt_log_slow_slave_statements, &opt_log_slow_slave_statements, | |
438 | - 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, | |
439 | + 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/ | |
440 | {"log-slow-queries", OPT_SLOW_QUERY_LOG, | |
441 | "Log slow queries to a table or log file. Defaults logging to table " | |
442 | "mysql.slow_log or hostname-slow.log if --log-output=file is used. " | |
1c82f14e | 443 | @@ -7288,6 +7289,10 @@ |
b4e1fa2c AM |
444 | |
445 | C_MODE_END | |
446 | ||
447 | +/* defined in sys_vars.cc */ | |
448 | +extern void init_log_slow_verbosity(); | |
a9ee80b9 | 449 | +extern void init_slow_query_log_use_global_control(); |
b4e1fa2c AM |
450 | + |
451 | /** | |
452 | Get server options from the command line, | |
453 | and perform related server initializations. | |
1c82f14e | 454 | @@ -7437,6 +7442,8 @@ |
b4e1fa2c AM |
455 | global_system_variables.long_query_time= (ulonglong) |
456 | (global_system_variables.long_query_time_double * 1e6); | |
457 | ||
458 | + init_log_slow_verbosity(); | |
a9ee80b9 | 459 | + init_slow_query_log_use_global_control(); |
b4e1fa2c AM |
460 | if (opt_short_log_format) |
461 | opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT; | |
462 | ||
db82db79 AM |
463 | --- a/sql/mysqld.h |
464 | +++ b/sql/mysqld.h | |
1c82f14e | 465 | @@ -116,6 +116,11 @@ |
b4e1fa2c AM |
466 | extern char* opt_secure_backup_file_priv; |
467 | extern size_t opt_secure_backup_file_priv_len; | |
468 | extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements; | |
469 | +extern my_bool opt_log_slow_sp_statements; | |
a9ee80b9 ER |
470 | +extern my_bool opt_slow_query_log_timestamp_always; |
471 | +extern ulonglong opt_slow_query_log_use_global_control; | |
adf0fb13 | 472 | +extern ulong opt_slow_query_log_timestamp_precision; |
1c82f14e | 473 | +extern ulong opt_slow_query_log_rate_type; |
b4e1fa2c AM |
474 | extern my_bool sp_automatic_privileges, opt_noacl; |
475 | extern my_bool opt_old_style_user_limits, trust_function_creators; | |
476 | extern uint opt_crash_binlog_innodb; | |
db82db79 AM |
477 | --- a/sql/slave.cc |
478 | +++ b/sql/slave.cc | |
d8778560 | 479 | @@ -2038,6 +2038,7 @@ |
b4e1fa2c AM |
480 | + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */ |
481 | thd->slave_thread = 1; | |
482 | thd->enable_slow_log= opt_log_slow_slave_statements; | |
483 | + thd->write_to_slow_log= opt_log_slow_slave_statements; | |
484 | set_slave_thread_options(thd); | |
485 | thd->client_capabilities = CLIENT_LOCAL_FILES; | |
486 | mysql_mutex_lock(&LOCK_thread_count); | |
db82db79 AM |
487 | --- a/sql/sp_head.cc |
488 | +++ b/sql/sp_head.cc | |
1bfc1981 | 489 | @@ -2164,7 +2164,7 @@ |
b4e1fa2c AM |
490 | DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length, |
491 | m_name.str)); | |
492 | } | |
493 | - if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log) | |
494 | + if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log) | |
495 | { | |
496 | DBUG_PRINT("info", ("Disabling slow log for the execution")); | |
497 | save_enable_slow_log= true; | |
db82db79 AM |
498 | --- a/sql/sql_cache.cc |
499 | +++ b/sql/sql_cache.cc | |
1bfc1981 | 500 | @@ -1780,6 +1780,7 @@ |
b4e1fa2c AM |
501 | response, we can't handle it anyway. |
502 | */ | |
503 | (void) trans_commit_stmt(thd); | |
504 | + thd->query_plan_flags|= QPLAN_QC; | |
505 | if (!thd->stmt_da->is_set()) | |
506 | thd->stmt_da->disable_status(); | |
507 | ||
1bfc1981 | 508 | @@ -1790,6 +1791,7 @@ |
b4e1fa2c AM |
509 | err_unlock: |
510 | unlock(); | |
511 | err: | |
512 | + thd->query_plan_flags|= QPLAN_QC_NO; | |
513 | MYSQL_QUERY_CACHE_MISS(thd->query()); | |
514 | DBUG_RETURN(0); // Query was not cached | |
515 | } | |
db82db79 AM |
516 | --- a/sql/sql_class.cc |
517 | +++ b/sql/sql_class.cc | |
518 | @@ -616,6 +616,37 @@ | |
b4e1fa2c AM |
519 | thd->warning_info->inc_current_row_for_warning(); |
520 | } | |
521 | ||
522 | +extern "C" | |
523 | +void increment_thd_innodb_stats(THD* thd, | |
9dd04cbc AM |
524 | + unsigned long long trx_id, |
525 | + long io_reads, | |
526 | + long long io_read, | |
527 | + long io_reads_wait_timer, | |
528 | + long lock_que_wait_timer, | |
529 | + long que_wait_timer, | |
530 | + long page_access) | |
b4e1fa2c | 531 | +{ |
9dd04cbc AM |
532 | + thd->innodb_was_used= TRUE; |
533 | + thd->innodb_trx_id= trx_id; | |
534 | + thd->innodb_io_reads+= io_reads; | |
535 | + thd->innodb_io_read+= io_read; | |
536 | + thd->innodb_io_reads_wait_timer+= io_reads_wait_timer; | |
537 | + thd->innodb_lock_que_wait_timer+= lock_que_wait_timer; | |
538 | + thd->innodb_innodb_que_wait_timer+= que_wait_timer; | |
539 | + thd->innodb_page_access+= page_access; | |
b4e1fa2c AM |
540 | +} |
541 | + | |
542 | +extern "C" | |
543 | +unsigned long thd_log_slow_verbosity(const THD *thd) | |
544 | +{ | |
545 | + return (unsigned long) thd->variables.log_slow_verbosity; | |
546 | +} | |
547 | + | |
548 | +extern "C" | |
549 | +int thd_opt_slow_log() | |
550 | +{ | |
551 | + return (int) opt_slow_log; | |
552 | +} | |
553 | ||
554 | /** | |
555 | Dumps a text description of a thread, its security context | |
9dd04cbc | 556 | @@ -942,6 +973,8 @@ |
734d6226 AM |
557 | const char* msg, |
558 | MYSQL_ERROR ** cond_hdl) | |
559 | { | |
b4e1fa2c | 560 | + last_errno= sql_errno; |
734d6226 AM |
561 | + |
562 | if (!m_internal_handler) | |
563 | { | |
564 | *cond_hdl= NULL; | |
9dd04cbc AM |
565 | @@ -1236,6 +1269,8 @@ |
566 | /* Initialize the Debug Sync Facility. See debug_sync.cc. */ | |
567 | debug_sync_init_thread(this); | |
568 | #endif /* defined(ENABLED_DEBUG_SYNC) */ | |
569 | + | |
570 | + clear_slow_extended(); | |
571 | } | |
572 | ||
573 | ||
29ffd636 | 574 | @@ -3687,8 +3722,6 @@ |
9dd04cbc AM |
575 | backup->in_sub_stmt= in_sub_stmt; |
576 | backup->enable_slow_log= enable_slow_log; | |
577 | backup->limit_found_rows= limit_found_rows; | |
578 | - backup->examined_row_count= examined_row_count; | |
579 | - backup->sent_row_count= sent_row_count; | |
580 | backup->cuted_fields= cuted_fields; | |
581 | backup->client_capabilities= client_capabilities; | |
582 | backup->savepoints= transaction.savepoints; | |
29ffd636 | 583 | @@ -3696,6 +3729,7 @@ |
b4e1fa2c AM |
584 | first_successful_insert_id_in_prev_stmt; |
585 | backup->first_successful_insert_id_in_cur_stmt= | |
586 | first_successful_insert_id_in_cur_stmt; | |
9dd04cbc | 587 | + reset_sub_statement_state_slow_extended(backup); |
b4e1fa2c AM |
588 | |
589 | if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) && | |
590 | !is_current_stmt_binlog_format_row()) | |
29ffd636 | 591 | @@ -3711,13 +3745,74 @@ |
9dd04cbc AM |
592 | /* Disable result sets */ |
593 | client_capabilities &= ~CLIENT_MULTI_RESULTS; | |
594 | in_sub_stmt|= new_state; | |
595 | - examined_row_count= 0; | |
596 | - sent_row_count= 0; | |
b4e1fa2c AM |
597 | cuted_fields= 0; |
598 | transaction.savepoints= 0; | |
599 | first_successful_insert_id_in_cur_stmt= 0; | |
b4e1fa2c AM |
600 | } |
601 | ||
9dd04cbc AM |
602 | +void THD::clear_slow_extended() |
603 | +{ | |
604 | + DBUG_ENTER("THD::clear_slow_extended"); | |
605 | + sent_row_count= 0; | |
606 | + examined_row_count= 0; | |
607 | + bytes_sent_old= status_var.bytes_sent; | |
608 | + tmp_tables_used= 0; | |
609 | + tmp_tables_disk_used= 0; | |
610 | + tmp_tables_size= 0; | |
611 | + innodb_was_used= FALSE; | |
612 | + innodb_trx_id= 0; | |
613 | + innodb_io_reads= 0; | |
614 | + innodb_io_read= 0; | |
615 | + innodb_io_reads_wait_timer= 0; | |
616 | + innodb_lock_que_wait_timer= 0; | |
617 | + innodb_innodb_que_wait_timer= 0; | |
618 | + innodb_page_access= 0; | |
619 | + query_plan_flags= QPLAN_NONE; | |
620 | + query_plan_fsort_passes= 0; | |
621 | + last_errno= 0; | |
622 | + DBUG_VOID_RETURN; | |
623 | +} | |
624 | + | |
625 | +void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup) | |
626 | +{ | |
627 | + DBUG_ENTER("THD::reset_sub_statement_state_slow_extended"); | |
628 | + backup->sent_row_count= sent_row_count; | |
629 | + backup->examined_row_count= examined_row_count; | |
630 | + backup->tmp_tables_used= tmp_tables_used; | |
631 | + backup->tmp_tables_disk_used= tmp_tables_disk_used; | |
632 | + backup->tmp_tables_size= tmp_tables_size; | |
633 | + backup->innodb_was_used= innodb_was_used; | |
634 | + backup->innodb_io_reads= innodb_io_reads; | |
635 | + backup->innodb_io_read= innodb_io_read; | |
636 | + backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer; | |
637 | + backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer; | |
638 | + backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer; | |
639 | + backup->innodb_page_access= innodb_page_access; | |
640 | + backup->query_plan_flags= query_plan_flags; | |
641 | + backup->query_plan_fsort_passes= query_plan_fsort_passes; | |
642 | + clear_slow_extended(); | |
643 | + DBUG_VOID_RETURN; | |
644 | +} | |
645 | + | |
646 | +void THD::restore_sub_statement_state_slow_extended(const Sub_statement_state *backup) | |
647 | +{ | |
648 | + DBUG_ENTER("THD::restore_sub_statement_state_slow_extended"); | |
649 | + sent_row_count= backup->sent_row_count; | |
650 | + examined_row_count+= backup->examined_row_count; | |
651 | + tmp_tables_used+= backup->tmp_tables_used; | |
652 | + tmp_tables_disk_used+= backup->tmp_tables_disk_used; | |
653 | + tmp_tables_size+= backup->tmp_tables_size; | |
654 | + innodb_was_used= (innodb_was_used || backup->innodb_was_used); | |
655 | + innodb_io_reads+= backup->innodb_io_reads; | |
656 | + innodb_io_read+= backup->innodb_io_read; | |
657 | + innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer; | |
658 | + innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer; | |
659 | + innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer; | |
660 | + innodb_page_access+= backup->innodb_page_access; | |
661 | + query_plan_flags|= backup->query_plan_flags; | |
662 | + query_plan_fsort_passes+= backup->query_plan_fsort_passes; | |
663 | + DBUG_VOID_RETURN; | |
664 | +} | |
b4e1fa2c | 665 | |
9dd04cbc AM |
666 | void THD::restore_sub_statement_state(Sub_statement_state *backup) |
667 | { | |
29ffd636 | 668 | @@ -3758,7 +3853,6 @@ |
9dd04cbc AM |
669 | first_successful_insert_id_in_cur_stmt= |
670 | backup->first_successful_insert_id_in_cur_stmt; | |
671 | limit_found_rows= backup->limit_found_rows; | |
672 | - sent_row_count= backup->sent_row_count; | |
673 | client_capabilities= backup->client_capabilities; | |
674 | /* | |
675 | If we've left sub-statement mode, reset the fatal error flag. | |
29ffd636 | 676 | @@ -3776,8 +3870,8 @@ |
9dd04cbc AM |
677 | The following is added to the old values as we are interested in the |
678 | total complexity of the query | |
b4e1fa2c | 679 | */ |
9dd04cbc | 680 | - examined_row_count+= backup->examined_row_count; |
b4e1fa2c | 681 | cuted_fields+= backup->cuted_fields; |
9dd04cbc | 682 | + restore_sub_statement_state_slow_extended(backup); |
b4e1fa2c AM |
683 | DBUG_VOID_RETURN; |
684 | } | |
685 | ||
1c82f14e AM |
686 | @@ -3802,7 +3896,7 @@ |
687 | { | |
688 | mysql_mutex_lock(&LOCK_thd_data); | |
689 | set_query_inner(query_arg, query_length_arg, cs); | |
690 | - query_id= new_query_id; | |
691 | + do_set_query_id(new_query_id); | |
692 | mysql_mutex_unlock(&LOCK_thd_data); | |
693 | } | |
694 | ||
695 | @@ -3811,9 +3905,25 @@ | |
696 | void THD::set_query_id(query_id_t new_query_id) | |
697 | { | |
698 | mysql_mutex_lock(&LOCK_thd_data); | |
699 | - query_id= new_query_id; | |
700 | + do_set_query_id(new_query_id); | |
701 | mysql_mutex_unlock(&LOCK_thd_data); | |
702 | } | |
703 | +void THD::do_set_query_id(query_id_t new_query_id) | |
704 | +{ | |
705 | +#ifndef DBUG_OFF | |
706 | + if (variables.query_exec_id != 0 && | |
707 | + lex->sql_command != SQLCOM_SET_OPTION) | |
708 | + { | |
709 | + new_query_id= variables.query_exec_id; | |
710 | + } | |
711 | +#endif /* DBUG_OFF */ | |
712 | + query_id= new_query_id; | |
713 | + if (opt_slow_query_log_rate_type == SLOG_RT_QUERY) | |
714 | + { | |
715 | + const ulong& limit= variables.log_slow_rate_limit; | |
716 | + write_to_slow_log= limit == 0 || (query_id % limit) == 0; | |
717 | + } | |
718 | +} | |
719 | ||
720 | /** Assign a new value to thd->mysys_var. */ | |
721 | void THD::set_mysys_var(struct st_my_thread_var *new_mysys_var) | |
db82db79 AM |
722 | --- a/sql/sql_class.h |
723 | +++ b/sql/sql_class.h | |
1c82f14e | 724 | @@ -60,6 +60,36 @@ |
b4e1fa2c AM |
725 | enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE }; |
726 | enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON, | |
727 | DELAY_KEY_WRITE_ALL }; | |
a9ee80b9 ER |
728 | +enum enum_slow_query_log_use_global_control { |
729 | + SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT | |
730 | + , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME | |
731 | + , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL | |
732 | +}; | |
b4e1fa2c AM |
733 | +enum enum_log_slow_verbosity { |
734 | + SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB, | |
735 | + SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE, | |
736 | + SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL | |
737 | +}; | |
a9ee80b9 ER |
738 | +enum enum_slow_query_log_timestamp_precision { |
739 | + SLOG_SECOND, SLOG_MICROSECOND | |
740 | +}; | |
1c82f14e AM |
741 | +enum enum_slow_query_log_rate_type { |
742 | + SLOG_RT_SESSION, SLOG_RT_QUERY | |
743 | +}; | |
b4e1fa2c AM |
744 | +#define QPLAN_NONE 0 |
745 | +#define QPLAN_QC 1 << 0 | |
746 | +#define QPLAN_QC_NO 1 << 1 | |
747 | +#define QPLAN_FULL_SCAN 1 << 2 | |
748 | +#define QPLAN_FULL_JOIN 1 << 3 | |
749 | +#define QPLAN_TMP_TABLE 1 << 4 | |
750 | +#define QPLAN_TMP_DISK 1 << 5 | |
751 | +#define QPLAN_FILESORT 1 << 6 | |
752 | +#define QPLAN_FILESORT_DISK 1 << 7 | |
753 | +enum enum_log_slow_filter { | |
754 | + SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN, | |
755 | + SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT, | |
756 | + SLOG_F_FILESORT_DISK | |
757 | +}; | |
758 | enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT, | |
759 | SLAVE_EXEC_MODE_IDEMPOTENT, | |
760 | SLAVE_EXEC_MODE_LAST_BIT}; | |
1c82f14e | 761 | @@ -508,6 +538,22 @@ |
b4e1fa2c AM |
762 | |
763 | my_bool sysdate_is_now; | |
764 | ||
48b678b4 AM |
765 | +#ifndef DBUG_OFF |
766 | + ulonglong query_exec_time; | |
767 | + double query_exec_time_double; | |
1c82f14e | 768 | + ulong query_exec_id; |
48b678b4 | 769 | +#endif |
b4e1fa2c AM |
770 | + ulong log_slow_rate_limit; |
771 | + ulonglong log_slow_filter; | |
772 | + ulonglong log_slow_verbosity; | |
773 | + | |
774 | + ulong innodb_io_reads; | |
775 | + ulonglong innodb_io_read; | |
776 | + ulong innodb_io_reads_wait_timer; | |
777 | + ulong innodb_lock_que_wait_timer; | |
778 | + ulong innodb_innodb_que_wait_timer; | |
779 | + ulong innodb_page_access; | |
780 | + | |
781 | double long_query_time_double; | |
782 | ||
783 | } SV; | |
1c82f14e | 784 | @@ -1140,6 +1186,24 @@ |
b4e1fa2c AM |
785 | uint in_sub_stmt; |
786 | bool enable_slow_log; | |
787 | bool last_insert_id_used; | |
788 | + | |
9dd04cbc AM |
789 | + /*** Following variables used in slow_extended.patch ***/ |
790 | + ulong tmp_tables_used; | |
791 | + ulong tmp_tables_disk_used; | |
792 | + ulonglong tmp_tables_size; | |
793 | + | |
794 | + bool innodb_was_used; | |
b4e1fa2c AM |
795 | + ulong innodb_io_reads; |
796 | + ulonglong innodb_io_read; | |
797 | + ulong innodb_io_reads_wait_timer; | |
798 | + ulong innodb_lock_que_wait_timer; | |
799 | + ulong innodb_innodb_que_wait_timer; | |
800 | + ulong innodb_page_access; | |
9dd04cbc AM |
801 | + |
802 | + ulong query_plan_flags; | |
803 | + ulong query_plan_fsort_passes; | |
804 | + /*** The variables above used in slow_extended.patch ***/ | |
b4e1fa2c AM |
805 | + |
806 | SAVEPOINT *savepoints; | |
807 | enum enum_check_fields count_cuted_fields; | |
808 | }; | |
1c82f14e | 809 | @@ -1588,6 +1652,71 @@ |
b4e1fa2c AM |
810 | thr_lock_type update_lock_default; |
811 | Delayed_insert *di; | |
812 | ||
9dd04cbc AM |
813 | + /*** Following variables used in slow_extended.patch ***/ |
814 | + /* | |
815 | + Variable write_to_slow_log: | |
816 | + 1) initialized in | |
817 | + * sql_connect.cc (log_slow_rate_limit support) | |
818 | + * slave.cc (log_slow_slave_statements support) | |
819 | + 2) The variable is initialized on the thread startup and remains | |
820 | + constant afterwards. This will change when | |
821 | + LP #712396 ("log_slow_slave_statements not work on replication | |
822 | + threads without RESTART") is implemented. | |
823 | + 3) An implementation of LP #688646 ("Make query sampling possible by query") should use it. | |
824 | + */ | |
b4e1fa2c | 825 | + bool write_to_slow_log; |
9dd04cbc AM |
826 | + /* |
827 | + Variable bytes_send_old saves value of thd->status_var.bytes_sent | |
828 | + before query execution. | |
829 | + */ | |
b4e1fa2c | 830 | + ulonglong bytes_sent_old; |
9dd04cbc AM |
831 | + /* |
832 | + Variables tmp_tables_*** collect statistics about usage of temporary tables | |
833 | + */ | |
b4e1fa2c AM |
834 | + ulong tmp_tables_used; |
835 | + ulong tmp_tables_disk_used; | |
836 | + ulonglong tmp_tables_size; | |
9dd04cbc AM |
837 | + /* |
838 | + Variable innodb_was_used shows used or not InnoDB engine in current query. | |
839 | + */ | |
b4e1fa2c | 840 | + bool innodb_was_used; |
9dd04cbc AM |
841 | + /* |
842 | + Following Variables innodb_*** (is |should be) different from | |
843 | + default values only if (innodb_was_used==TRUE) | |
844 | + */ | |
b4e1fa2c AM |
845 | + ulonglong innodb_trx_id; |
846 | + ulong innodb_io_reads; | |
847 | + ulonglong innodb_io_read; | |
848 | + ulong innodb_io_reads_wait_timer; | |
849 | + ulong innodb_lock_que_wait_timer; | |
850 | + ulong innodb_innodb_que_wait_timer; | |
851 | + ulong innodb_page_access; | |
852 | + | |
9dd04cbc AM |
853 | + /* |
854 | + Variable query_plan_flags collects information about query plan entites | |
855 | + used on query execution. | |
856 | + */ | |
b4e1fa2c | 857 | + ulong query_plan_flags; |
9dd04cbc AM |
858 | + /* |
859 | + Variable query_plan_fsort_passes collects information about file sort passes | |
860 | + acquired during query execution. | |
861 | + */ | |
b4e1fa2c | 862 | + ulong query_plan_fsort_passes; |
9dd04cbc AM |
863 | + /* |
864 | + Query can generate several errors/warnings during execution | |
865 | + (see THD::handle_condition comment in sql_class.h) | |
866 | + Variable last_errno contains the last error/warning acquired during | |
867 | + query execution. | |
868 | + */ | |
b4e1fa2c | 869 | + uint last_errno; |
9dd04cbc AM |
870 | + /*** The variables above used in slow_extended.patch ***/ |
871 | + | |
872 | + /*** Following methods used in slow_extended.patch ***/ | |
873 | + void clear_slow_extended(); | |
874 | + void reset_sub_statement_state_slow_extended(Sub_statement_state *backup); | |
875 | + void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup); | |
876 | + /*** The methods above used in slow_extended.patch ***/ | |
b4e1fa2c AM |
877 | + |
878 | /* <> 0 if we are inside of trigger or stored function. */ | |
879 | uint in_sub_stmt; | |
880 | ||
1c82f14e AM |
881 | @@ -2784,6 +2913,9 @@ |
882 | void set_query_and_id(char *query_arg, uint32 query_length_arg, | |
883 | CHARSET_INFO *cs, query_id_t new_query_id); | |
884 | void set_query_id(query_id_t new_query_id); | |
885 | +private: | |
886 | + void do_set_query_id(query_id_t new_query_id); | |
887 | +public: | |
888 | void set_open_tables(TABLE *open_tables_arg) | |
889 | { | |
890 | mysql_mutex_lock(&LOCK_thd_data); | |
db82db79 AM |
891 | --- a/sql/sql_connect.cc |
892 | +++ b/sql/sql_connect.cc | |
1c82f14e | 893 | @@ -721,6 +721,14 @@ |
db82db79 AM |
894 | MYSQL_CONNECTION_START(thd->thread_id, &thd->security_ctx->priv_user[0], |
895 | (char *) thd->security_ctx->host_or_ip); | |
b4e1fa2c | 896 | |
1c82f14e AM |
897 | + /* |
898 | + If rate limiting of slow log writes is enabled, decide whether to log this | |
899 | + new thread's queries or not. Uses extremely simple algorithm. :) | |
900 | + */ | |
901 | + const ulong& limit= thd->variables.log_slow_rate_limit; | |
902 | + thd->write_to_slow_log= opt_slow_query_log_rate_type == SLOG_RT_SESSION && | |
903 | + (limit == 0 || (thd->thread_id % limit) == 0); | |
b4e1fa2c | 904 | + |
db82db79 AM |
905 | prepare_new_connection_state(thd); |
906 | return FALSE; | |
907 | } | |
908 | --- a/sql/sql_parse.cc | |
909 | +++ b/sql/sql_parse.cc | |
48b678b4 AM |
910 | @@ -114,6 +114,7 @@ |
911 | ||
912 | static bool execute_sqlcom_select(THD *thd, TABLE_LIST *all_tables); | |
913 | static void sql_kill(THD *thd, ulong id, bool only_kill_query); | |
914 | +static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime); | |
915 | ||
916 | const char *any_db="*any*"; // Special symbol for check_access | |
917 | ||
1bfc1981 | 918 | @@ -890,6 +891,7 @@ |
9dd04cbc AM |
919 | the slow log only if opt_log_slow_admin_statements is set. |
920 | */ | |
921 | thd->enable_slow_log= TRUE; | |
922 | + thd->clear_slow_extended(); | |
923 | thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */ | |
924 | thd->set_time(); | |
925 | if (!thd->is_valid_time()) | |
1bfc1981 | 926 | @@ -1440,6 +1442,60 @@ |
b4e1fa2c AM |
927 | DBUG_RETURN(error); |
928 | } | |
929 | ||
48b678b4 AM |
930 | +/** |
931 | + Calculate execution time for the current query. | |
932 | + | |
933 | + For debug builds, check the session value of query_exec_time | |
934 | + and if it is not zero, return it instead of the actual execution time. | |
935 | + | |
936 | + SET queries are ignored so that statements changing query_exec_time are not | |
937 | + affected by themselves. | |
938 | + | |
939 | + @param thd thread handle | |
940 | + @param lex current relative time in microseconds | |
941 | + | |
942 | + @return time in microseconds from utime_after_lock | |
943 | +*/ | |
944 | + | |
945 | +static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime) | |
946 | +{ | |
947 | + ulonglong res; | |
948 | +#ifndef DBUG_OFF | |
949 | + if (thd->variables.query_exec_time != 0) | |
950 | + res= thd->lex->sql_command != SQLCOM_SET_OPTION ? | |
951 | + thd->variables.query_exec_time : 0; | |
952 | + else | |
953 | +#endif | |
954 | + | |
955 | + res= cur_utime - thd->utime_after_lock; | |
956 | + | |
957 | + if (res > thd->variables.long_query_time) | |
958 | + thd->server_status|= SERVER_QUERY_WAS_SLOW; | |
959 | + else | |
960 | + thd->server_status&= ~SERVER_QUERY_WAS_SLOW; | |
961 | + | |
962 | + return res; | |
963 | +} | |
964 | + | |
965 | + | |
966 | +static inline void copy_global_to_session(THD *thd, ulong flag, | |
967 | + const ulong *val) | |
968 | +{ | |
969 | + my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables); | |
970 | + if (opt_slow_query_log_use_global_control & (1ULL << flag)) | |
971 | + *(ulong *)((char *) &thd->variables + offset) = *val; | |
972 | +} | |
973 | + | |
974 | + | |
975 | +static inline void copy_global_to_session(THD *thd, ulong flag, | |
976 | + const ulonglong *val) | |
977 | +{ | |
978 | + my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables); | |
979 | + if (opt_slow_query_log_use_global_control & (1ULL << flag)) | |
980 | + *(ulonglong *)((char *) &thd->variables + offset) = *val; | |
981 | +} | |
982 | + | |
983 | + | |
984 | ||
b4e1fa2c AM |
985 | void log_slow_statement(THD *thd) |
986 | { | |
1c82f14e | 987 | @@ -1453,13 +1509,47 @@ |
b4e1fa2c AM |
988 | if (unlikely(thd->in_sub_stmt)) |
989 | DBUG_VOID_RETURN; // Don't set time for sub stmt | |
990 | ||
991 | + /* Follow the slow log filter configuration. */ | |
992 | + if (thd->variables.log_slow_filter != 0 && | |
993 | + (!(thd->variables.log_slow_filter & thd->query_plan_flags) || | |
994 | + ((thd->variables.log_slow_filter & SLOG_F_QC_NO) && | |
995 | + (thd->query_plan_flags & QPLAN_QC)))) | |
996 | + DBUG_VOID_RETURN; | |
997 | + | |
48b678b4 AM |
998 | + ulonglong end_utime_of_query= thd->current_utime(); |
999 | + ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query); | |
1000 | + | |
b4e1fa2c AM |
1001 | + /* |
1002 | + Low long_query_time value most likely means user is debugging stuff and even | |
1003 | + though some thread's queries are not supposed to be logged b/c of the rate | |
1004 | + limit, if one of them takes long enough (>= 1 second) it will be sensible | |
1005 | + to make an exception and write to slow log anyway. | |
1006 | + */ | |
1007 | + | |
48b678b4 AM |
1008 | + system_variables const &g= global_system_variables; |
1009 | + copy_global_to_session(thd, SLOG_UG_LOG_SLOW_FILTER, | |
1010 | + &g.log_slow_filter); | |
1011 | + copy_global_to_session(thd, SLOG_UG_LOG_SLOW_RATE_LIMIT, | |
1012 | + &g.log_slow_rate_limit); | |
1013 | + copy_global_to_session(thd, SLOG_UG_LOG_SLOW_VERBOSITY, | |
1014 | + &g.log_slow_verbosity); | |
1015 | + copy_global_to_session(thd, SLOG_UG_LONG_QUERY_TIME, | |
1016 | + &g.long_query_time); | |
1017 | + copy_global_to_session(thd, SLOG_UG_MIN_EXAMINED_ROW_LIMIT, | |
1018 | + &g.min_examined_row_limit); | |
b4e1fa2c AM |
1019 | + |
1020 | + /* Do not log this thread's queries due to rate limiting. */ | |
1c82f14e AM |
1021 | + if (!thd->write_to_slow_log && (thd->variables.long_query_time >= 1000000 |
1022 | + || (ulong) query_exec_time < 1000000)) | |
b4e1fa2c AM |
1023 | + DBUG_VOID_RETURN; |
1024 | + | |
1025 | + | |
1026 | /* | |
1027 | Do not log administrative statements unless the appropriate option is | |
1028 | set. | |
48b678b4 AM |
1029 | */ |
1030 | if (thd->enable_slow_log) | |
1031 | { | |
1032 | - ulonglong end_utime_of_query= thd->current_utime(); | |
1033 | thd_proc_info(thd, "logging slow query"); | |
1034 | ||
1035 | if (((thd->server_status & SERVER_QUERY_WAS_SLOW) || | |
1bfc1981 | 1036 | @@ -5368,7 +5459,8 @@ |
9dd04cbc AM |
1037 | thd->stmt_da->reset_diagnostics_area(); |
1038 | thd->warning_info->reset_for_next_command(); | |
b4e1fa2c | 1039 | thd->rand_used= 0; |
9dd04cbc | 1040 | - thd->sent_row_count= thd->examined_row_count= 0; |
b4e1fa2c | 1041 | + |
9dd04cbc AM |
1042 | + thd->clear_slow_extended(); |
1043 | ||
b4e1fa2c AM |
1044 | thd->reset_current_stmt_binlog_format_row(); |
1045 | thd->binlog_unsafe_warning_flags= 0; | |
db82db79 AM |
1046 | --- a/sql/sql_select.cc |
1047 | +++ b/sql/sql_select.cc | |
1bfc1981 | 1048 | @@ -6912,7 +6912,10 @@ |
b4e1fa2c AM |
1049 | { |
1050 | join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED; | |
1051 | if (statistics) | |
1052 | + { | |
1053 | status_var_increment(join->thd->status_var.select_scan_count); | |
1054 | + join->thd->query_plan_flags|= QPLAN_FULL_SCAN; | |
1055 | + } | |
1056 | } | |
1057 | } | |
1058 | else | |
1bfc1981 | 1059 | @@ -6926,7 +6929,10 @@ |
b4e1fa2c AM |
1060 | { |
1061 | join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED; | |
1062 | if (statistics) | |
1063 | + { | |
1064 | status_var_increment(join->thd->status_var.select_full_join_count); | |
1065 | + join->thd->query_plan_flags|= QPLAN_FULL_JOIN; | |
1066 | + } | |
1067 | } | |
1068 | } | |
1069 | if (!table->no_keyread) | |
1bfc1981 | 1070 | @@ -10274,6 +10280,7 @@ |
b4e1fa2c AM |
1071 | (ulong) rows_limit,test(group))); |
1072 | ||
1073 | status_var_increment(thd->status_var.created_tmp_tables); | |
1074 | + thd->query_plan_flags|= QPLAN_TMP_TABLE; | |
1075 | ||
1076 | if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES)) | |
1077 | temp_pool_slot = bitmap_lock_set_next(&temp_pool); | |
1bfc1981 | 1078 | @@ -11175,6 +11182,7 @@ |
b4e1fa2c AM |
1079 | goto err; |
1080 | } | |
1081 | status_var_increment(table->in_use->status_var.created_tmp_disk_tables); | |
1082 | + table->in_use->query_plan_flags|= QPLAN_TMP_DISK; | |
1083 | share->db_record_offset= 1; | |
1084 | DBUG_RETURN(0); | |
1085 | err: | |
1bfc1981 | 1086 | @@ -11193,6 +11201,14 @@ |
b4e1fa2c AM |
1087 | save_proc_info=thd->proc_info; |
1088 | thd_proc_info(thd, "removing tmp table"); | |
1089 | ||
1090 | + thd->tmp_tables_used++; | |
1091 | + if (entry->file) | |
1092 | + { | |
1093 | + thd->tmp_tables_size += entry->file->stats.data_file_length; | |
1094 | + if (entry->file->ht->db_type != DB_TYPE_HEAP) | |
1095 | + thd->tmp_tables_disk_used++; | |
1096 | + } | |
1097 | + | |
1098 | // Release latches since this can take a long time | |
1099 | ha_release_temporary_latches(thd); | |
1100 | ||
db82db79 AM |
1101 | --- a/sql/sql_show.cc |
1102 | +++ b/sql/sql_show.cc | |
adf0fb13 | 1103 | @@ -1950,8 +1950,17 @@ |
b4e1fa2c AM |
1104 | table->field[4]->store(command_name[tmp->command].str, |
1105 | command_name[tmp->command].length, cs); | |
1106 | /* MYSQL_TIME */ | |
1107 | - table->field[5]->store((longlong)(tmp->start_time ? | |
1108 | - now - tmp->start_time : 0), FALSE); | |
1109 | + longlong value_in_time_column= 0; | |
1110 | + if(tmp->start_time) | |
1111 | + { | |
1112 | + value_in_time_column = (now - tmp->start_time); | |
1113 | + if(value_in_time_column > now) | |
1114 | + { | |
1115 | + value_in_time_column= 0; | |
1116 | + } | |
1117 | + } | |
1118 | + table->field[5]->store(value_in_time_column, FALSE); | |
1119 | + | |
1120 | /* STATE */ | |
1121 | if ((val= thread_state_info(tmp))) | |
1122 | { | |
db82db79 AM |
1123 | --- a/sql/sys_vars.cc |
1124 | +++ b/sql/sys_vars.cc | |
1c82f14e | 1125 | @@ -972,6 +972,36 @@ |
48b678b4 AM |
1126 | NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), |
1127 | ON_UPDATE(update_cached_long_query_time)); | |
1128 | ||
1129 | +#ifndef DBUG_OFF | |
1130 | +static bool update_cached_query_exec_time(sys_var *self, THD *thd, | |
1131 | + enum_var_type type) | |
1132 | +{ | |
1133 | + if (type == OPT_SESSION) | |
1134 | + thd->variables.query_exec_time= | |
1135 | + double2ulonglong(thd->variables.query_exec_time_double * 1e6); | |
1136 | + else | |
1137 | + global_system_variables.query_exec_time= | |
1138 | + double2ulonglong(global_system_variables.query_exec_time_double * 1e6); | |
1139 | + return false; | |
1140 | +} | |
1141 | + | |
1142 | +static Sys_var_double Sys_query_exec_time( | |
1143 | + "query_exec_time", | |
1144 | + "Pretend queries take this many seconds. When 0 (the default) use the " | |
1145 | + "actual execution time. Used only for debugging.", | |
1146 | + SESSION_VAR(query_exec_time_double), | |
1147 | + NO_CMD_LINE, VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(0), | |
1148 | + NO_MUTEX_GUARD, IN_BINLOG, ON_CHECK(0), | |
1149 | + ON_UPDATE(update_cached_query_exec_time)); | |
1c82f14e AM |
1150 | +static Sys_var_ulong sys_query_exec_id( |
1151 | + "query_exec_id", | |
1152 | + "Pretend queries take this query id. When 0 (the default) use the" | |
1153 | + "actual query id. Used only for debugging.", | |
1154 | + SESSION_VAR(query_exec_id), | |
1155 | + NO_CMD_LINE, VALID_RANGE(0, ULONG_MAX), DEFAULT(0), BLOCK_SIZE(1), | |
1156 | + NO_MUTEX_GUARD, IN_BINLOG); | |
48b678b4 AM |
1157 | +#endif |
1158 | + | |
1159 | static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type) | |
1160 | { | |
1161 | if (type == OPT_SESSION) | |
1c82f14e | 1162 | @@ -2898,6 +2928,134 @@ |
b4e1fa2c AM |
1163 | DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), |
1164 | ON_UPDATE(fix_log_state)); | |
1165 | ||
1166 | +const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join", | |
1167 | + "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0}; | |
1168 | +static Sys_var_set Sys_log_slow_filter( | |
1169 | + "log_slow_filter", | |
1170 | + "Log only the queries that followed certain execution plan. " | |
1171 | + "Multiple flags allowed in a comma-separated string. " | |
1172 | + "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, " | |
1173 | + "filesort, filesort_on_disk]", | |
1174 | + SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG), | |
1175 | + log_slow_filter_name, DEFAULT(0)); | |
1176 | +static Sys_var_ulong sys_log_slow_rate_limit( | |
1177 | + "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.", | |
1178 | + SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG), | |
1179 | + VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1)); | |
1180 | +const char* log_slow_verbosity_name[] = { | |
1181 | + "microtime", "query_plan", "innodb", | |
1182 | + "profiling", "profling_use_getrusage", | |
1183 | + "minimal", "standard", "full", 0 | |
1184 | +}; | |
1185 | +static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by) | |
1186 | +{ | |
1187 | + if((value & what) == what) | |
1188 | + { | |
1189 | + value = value & (~what); | |
1190 | + value = value | by; | |
1191 | + } | |
1192 | + return value; | |
1193 | +} | |
1194 | +void update_log_slow_verbosity(ulonglong* value_ptr) | |
1195 | +{ | |
1196 | + ulonglong &value = *value_ptr; | |
1197 | + ulonglong microtime= ULL(1) << SLOG_V_MICROTIME; | |
1198 | + ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN; | |
1199 | + ulonglong innodb= ULL(1) << SLOG_V_INNODB; | |
1200 | + ulonglong minimal= ULL(1) << SLOG_V_MINIMAL; | |
1201 | + ulonglong standard= ULL(1) << SLOG_V_STANDARD; | |
1202 | + ulonglong full= ULL(1) << SLOG_V_FULL; | |
1203 | + value= update_log_slow_verbosity_replace(value,minimal,microtime); | |
1204 | + value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan); | |
1205 | + value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb); | |
1206 | +} | |
1207 | +static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd, | |
1208 | + enum_var_type type) | |
1209 | +{ | |
1210 | + if(type == OPT_SESSION) | |
1211 | + { | |
1212 | + update_log_slow_verbosity(&(thd->variables.log_slow_verbosity)); | |
1213 | + } | |
1214 | + else | |
1215 | + { | |
1216 | + update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity)); | |
1217 | + } | |
1218 | + return false; | |
1219 | +} | |
a9ee80b9 | 1220 | +void init_slow_query_log_use_global_control() |
b4e1fa2c AM |
1221 | +{ |
1222 | + update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity)); | |
1223 | +} | |
1224 | +static Sys_var_set Sys_log_slow_verbosity( | |
1225 | + "log_slow_verbosity", | |
1226 | + "Choose how verbose the messages to your slow log will be. " | |
1227 | + "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]", | |
1228 | + SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG), | |
1229 | + log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME), | |
1230 | + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), | |
1231 | + ON_UPDATE(update_log_slow_verbosity_helper)); | |
1232 | +static Sys_var_mybool Sys_log_slow_slave_statements( | |
1233 | + "log_slow_slave_statements", | |
1234 | + "Log queries replayed be the slave SQL thread", | |
1235 | + GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG), | |
1236 | + DEFAULT(FALSE)); | |
734d6226 AM |
1237 | +static Sys_var_mybool Sys_log_slow_admin_statements( |
1238 | + "log_slow_admin_statements", | |
1239 | + "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements" | |
1240 | + " to the slow log if it is open.", | |
1241 | + GLOBAL_VAR(opt_log_slow_admin_statements), CMD_LINE(OPT_ARG), | |
1242 | + DEFAULT(FALSE)); | |
b4e1fa2c AM |
1243 | +static Sys_var_mybool Sys_log_slow_sp_statements( |
1244 | + "log_slow_sp_statements", | |
1245 | + "Log slow statements executed by stored procedure to the slow log if it is open.", | |
1246 | + GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG), | |
1247 | + DEFAULT(TRUE)); | |
a9ee80b9 ER |
1248 | +static Sys_var_mybool Sys_slow_query_log_timestamp_always( |
1249 | + "slow_query_log_timestamp_always", | |
b4e1fa2c | 1250 | + "Timestamp is printed for all records of the slow log even if they are same time.", |
a9ee80b9 | 1251 | + GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG), |
b4e1fa2c | 1252 | + DEFAULT(FALSE)); |
a9ee80b9 ER |
1253 | +const char *slow_query_log_use_global_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0}; |
1254 | +static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/, | |
b4e1fa2c AM |
1255 | + enum_var_type /*type*/) |
1256 | +{ | |
a9ee80b9 | 1257 | + if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL)) |
b4e1fa2c | 1258 | + { |
a9ee80b9 | 1259 | + opt_slow_query_log_use_global_control= |
b4e1fa2c AM |
1260 | + SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY | |
1261 | + SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT; | |
1262 | + } | |
1263 | + return false; | |
1264 | +} | |
1265 | +void init_log_slow_verbosity() | |
1266 | +{ | |
a9ee80b9 | 1267 | + update_slow_query_log_use_global_control(0,0,OPT_GLOBAL); |
b4e1fa2c | 1268 | +} |
a9ee80b9 ER |
1269 | +static Sys_var_set Sys_slow_query_log_use_global_control( |
1270 | + "slow_query_log_use_global_control", | |
b4e1fa2c | 1271 | + "Choose flags, wich always use the global variables. Multiple flags allowed in a comma-separated string. [none, log_slow_filter, log_slow_rate_limit, log_slow_verbosity, long_query_time, min_examined_row_limit, all]", |
a9ee80b9 ER |
1272 | + GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG), |
1273 | + slow_query_log_use_global_control_name, DEFAULT(0), | |
b4e1fa2c | 1274 | + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), |
a9ee80b9 ER |
1275 | + ON_UPDATE(update_slow_query_log_use_global_control)); |
1276 | +const char *slow_query_log_timestamp_precision_name[]= { "second", "microsecond", 0 }; | |
1277 | +static Sys_var_enum Sys_slow_query_log_timestamp_precision( | |
1278 | + "slow_query_log_timestamp_precision", | |
1279 | + "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]", | |
1280 | + GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG), | |
1281 | + slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND)); | |
1c82f14e AM |
1282 | + |
1283 | +const char* slow_query_log_rate_name[]= {"session", "query", 0}; | |
1284 | +static Sys_var_enum Sys_slow_query_log_rate_type( | |
1285 | + "log_slow_rate_type", | |
1286 | + "Choose the log_slow_rate_limit behavior: session or query. " | |
1287 | + "When you choose 'session' - every %log_slow_rate_limit connection " | |
1288 | + "will be processed to slow query log. " | |
1289 | + "When you choose 'query' - every %log_slow_rate_limit query " | |
1290 | + "will be processed to slow query log. " | |
1291 | + "[session, query]", | |
1292 | + GLOBAL_VAR(opt_slow_query_log_rate_type), CMD_LINE(REQUIRED_ARG), | |
1293 | + slow_query_log_rate_name, DEFAULT(SLOG_RT_SESSION)); | |
b4e1fa2c AM |
1294 | /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */ |
1295 | static Sys_var_mybool Sys_log_slow( | |
1296 | "log_slow_queries", | |
db82db79 AM |
1297 | --- a/sql/sql_profile.cc |
1298 | +++ b/sql/sql_profile.cc | |
b4e1fa2c AM |
1299 | @@ -243,7 +243,8 @@ |
1300 | { | |
1301 | time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */ | |
1302 | #ifdef HAVE_GETRUSAGE | |
1303 | - getrusage(RUSAGE_SELF, &rusage); | |
1304 | + if ((profile->get_profiling())->enabled_getrusage()) | |
1305 | + getrusage(RUSAGE_SELF, &rusage); | |
1306 | #elif defined(_WIN32) | |
1307 | FILETIME ftDummy; | |
1308 | // NOTE: Get{Process|Thread}Times has a granularity of the clock interval, | |
1309 | @@ -251,6 +252,19 @@ | |
1310 | // measurable by this function. | |
1311 | GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser); | |
1312 | #endif | |
1313 | + | |
1314 | +#ifdef HAVE_CLOCK_GETTIME | |
1315 | + struct timespec tp; | |
1316 | + | |
1317 | + if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp))) | |
1318 | + { | |
1319 | + cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec; | |
1320 | + } | |
1321 | + else | |
1322 | +#endif | |
1323 | + { | |
1324 | + cpu_time_usecs= 0; | |
1325 | + } | |
1326 | } | |
1327 | ||
1328 | ||
1329 | @@ -366,7 +380,8 @@ | |
1330 | finish_current_query(); | |
1331 | } | |
1332 | ||
1333 | - enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0); | |
1334 | + enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) || | |
1335 | + ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0); | |
1336 | ||
1337 | if (! enabled) DBUG_VOID_RETURN; | |
1338 | ||
1339 | @@ -404,7 +419,8 @@ | |
1340 | status_change("ending", NULL, NULL, 0); | |
1341 | ||
1342 | if ((enabled) && /* ON at start? */ | |
1343 | - ((thd->variables.option_bits & OPTION_PROFILING) != 0) && /* and ON at end? */ | |
1344 | + (((thd->variables.option_bits & OPTION_PROFILING) != 0) || | |
1345 | + ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) && /* and ON at end? */ | |
1346 | (current->query_source != NULL) && | |
1347 | (! current->entries.is_empty())) | |
1348 | { | |
1349 | @@ -505,6 +521,118 @@ | |
1350 | DBUG_VOID_RETURN; | |
1351 | } | |
1352 | ||
1353 | +bool PROFILING::enabled_getrusage() | |
1354 | +{ | |
1355 | + return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0); | |
1356 | +} | |
1357 | + | |
1358 | +/** | |
1359 | + For a given profile entry specified by a name and 2 time measurements, | |
1360 | + print its normalized name (i.e. with all spaces replaced with underscores) | |
1361 | + along with its wall clock and CPU time. | |
1362 | +*/ | |
1363 | + | |
1364 | +static void my_b_print_status(IO_CACHE *log_file, const char *status, | |
1365 | + PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop) | |
1366 | +{ | |
1367 | + DBUG_ENTER("my_b_print_status"); | |
1368 | + DBUG_ASSERT(log_file != NULL && status != NULL); | |
1369 | + char query_time_buff[22+7]; | |
1370 | + const char *tmp; | |
1371 | + | |
1372 | + my_b_printf(log_file, "Profile_"); | |
1373 | + for (tmp= status; *tmp; tmp++) | |
1374 | + my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp); | |
1375 | + | |
1376 | + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", | |
1377 | + (stop->time_usecs - start->time_usecs) / (1000.0 * 1000)); | |
1378 | + my_b_printf(log_file, ": %s ", query_time_buff); | |
1379 | + | |
1380 | + my_b_printf(log_file, "Profile_"); | |
1381 | + for (tmp= status; *tmp; tmp++) | |
1382 | + my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp); | |
1383 | + my_b_printf(log_file, "_cpu: "); | |
1384 | + | |
1385 | + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", | |
1386 | + (stop->cpu_time_usecs - start->cpu_time_usecs) / | |
1387 | + (1000.0 * 1000 * 1000)); | |
1388 | + my_b_printf(log_file, "%s ", query_time_buff); | |
1389 | + | |
1390 | + DBUG_VOID_RETURN; | |
1391 | +} | |
1392 | + | |
1393 | +/** | |
1394 | + Print output for current query to file | |
1395 | +*/ | |
1396 | + | |
1397 | +int PROFILING::print_current(IO_CACHE *log_file) | |
1398 | +{ | |
1399 | + DBUG_ENTER("PROFILING::print_current"); | |
1400 | + ulonglong row_number= 0; | |
1401 | + | |
1402 | + QUERY_PROFILE *query; | |
1403 | + /* Get current query */ | |
1404 | + if (current == NULL) | |
1405 | + { | |
1406 | + DBUG_RETURN(0); | |
1407 | + } | |
1408 | + | |
1409 | + query= current; | |
1410 | + | |
1411 | + my_b_printf(log_file, "# "); | |
1412 | + | |
1413 | + void *entry_iterator; | |
1414 | + PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL; | |
1415 | + /* ...and for each query, go through all its state-change steps. */ | |
1416 | + for (entry_iterator= query->entries.new_iterator(); | |
1417 | + entry_iterator != NULL; | |
1418 | + entry_iterator= query->entries.iterator_next(entry_iterator), | |
1419 | + previous=entry, row_number++) | |
1420 | + { | |
1421 | + entry= query->entries.iterator_value(entry_iterator); | |
1422 | + | |
1423 | + /* Skip the first. We count spans of fence, not fence-posts. */ | |
1424 | + if (previous == NULL) {first= entry; continue;} | |
1425 | + | |
1426 | + if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE) | |
1427 | + { | |
1428 | + /* | |
1429 | + We got here via a SHOW command. That means that we stored | |
1430 | + information about the query we wish to show and that isn't | |
1431 | + in a WHERE clause at a higher level to filter out rows we | |
1432 | + wish to exclude. | |
1433 | + | |
1434 | + Because that functionality isn't available in the server yet, | |
1435 | + we must filter here, at the wrong level. Once one can con- | |
1436 | + struct where and having conditions at the SQL layer, then this | |
1437 | + condition should be ripped out. | |
1438 | + */ | |
1439 | + if (thd->lex->profile_query_id == 0) /* 0 == show final query */ | |
1440 | + { | |
1441 | + if (query != last) | |
1442 | + continue; | |
1443 | + } | |
1444 | + else | |
1445 | + { | |
1446 | + if (thd->lex->profile_query_id != query->profiling_query_id) | |
1447 | + continue; | |
1448 | + } | |
1449 | + } | |
1450 | + | |
1451 | + my_b_print_status(log_file, previous->status, previous, entry); | |
1452 | + } | |
1453 | + | |
1454 | + my_b_write_byte(log_file, '\n'); | |
1455 | + if ((entry != NULL) && (first != NULL)) | |
1456 | + { | |
1457 | + my_b_printf(log_file, "# "); | |
1458 | + my_b_print_status(log_file, "total", first, entry); | |
1459 | + my_b_write_byte(log_file, '\n'); | |
1460 | + } | |
1461 | + | |
1462 | + DBUG_RETURN(0); | |
1463 | +} | |
1464 | + | |
1465 | /** | |
1466 | Fill the information schema table, "query_profile", as defined in show.cc . | |
1467 | There are two ways to get to this function: Selecting from the information | |
adf0fb13 AM |
1468 | @@ -600,6 +728,8 @@ |
1469 | ||
1470 | #ifdef HAVE_GETRUSAGE | |
1471 | ||
1472 | + if (enabled_getrusage()) | |
1473 | + { | |
1474 | my_decimal cpu_utime_decimal, cpu_stime_decimal; | |
1475 | ||
1476 | double2my_decimal(E_DEC_FATAL_ERROR, | |
1477 | @@ -687,6 +817,7 @@ | |
1478 | table->field[14]->store((uint32)(entry->rusage.ru_nswap - | |
1479 | previous->rusage.ru_nswap), true); | |
1480 | table->field[14]->set_notnull(); | |
1481 | + } | |
1482 | #else | |
1483 | /* TODO: Add swap info for non-BSD systems */ | |
1484 | #endif | |
db82db79 AM |
1485 | --- a/sql/sql_profile.h |
1486 | +++ b/sql/sql_profile.h | |
b4e1fa2c AM |
1487 | @@ -164,11 +164,15 @@ |
1488 | */ | |
1489 | class PROF_MEASUREMENT | |
1490 | { | |
1491 | -private: | |
1492 | - friend class QUERY_PROFILE; | |
1493 | - friend class PROFILING; | |
1494 | - | |
1495 | QUERY_PROFILE *profile; | |
1496 | + | |
1497 | + char *allocated_status_memory; | |
1498 | + | |
1499 | + void set_label(const char *status_arg, const char *function_arg, | |
1500 | + const char *file_arg, unsigned int line_arg); | |
1501 | + void clean_up(); | |
1502 | + | |
1503 | +public: | |
1504 | char *status; | |
1505 | #ifdef HAVE_GETRUSAGE | |
1506 | struct rusage rusage; | |
1507 | @@ -181,12 +185,7 @@ | |
1508 | unsigned int line; | |
1509 | ||
1510 | double time_usecs; | |
1511 | - char *allocated_status_memory; | |
1512 | - | |
1513 | - void set_label(const char *status_arg, const char *function_arg, | |
1514 | - const char *file_arg, unsigned int line_arg); | |
1515 | - void clean_up(); | |
1516 | - | |
1517 | + double cpu_time_usecs; | |
1518 | PROF_MEASUREMENT(); | |
1519 | PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg); | |
1520 | PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg, | |
1521 | @@ -231,6 +230,11 @@ | |
1522 | ||
1523 | /* Show this profile. This is called by PROFILING. */ | |
1524 | bool show(uint options); | |
1525 | + | |
1526 | +public: | |
1527 | + | |
1528 | + inline PROFILING * get_profiling() { return profiling; }; | |
1529 | + | |
1530 | }; | |
1531 | ||
1532 | ||
1533 | @@ -276,9 +280,11 @@ | |
1534 | ||
1535 | /* SHOW PROFILES */ | |
1536 | bool show_profiles(); | |
1537 | + bool enabled_getrusage(); | |
1538 | ||
1539 | /* ... from INFORMATION_SCHEMA.PROFILING ... */ | |
1540 | int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond); | |
1541 | + int print_current(IO_CACHE *log_file); | |
1542 | }; | |
1543 | ||
1544 | # endif /* HAVE_PROFILING */ | |
48b678b4 AM |
1545 | --- /dev/null |
1546 | +++ b/mysql-test/include/log_grep.inc | |
1c82f14e | 1547 | @@ -0,0 +1,41 @@ |
48b678b4 AM |
1548 | +--echo [log_grep.inc] file: $log_file pattern: $grep_pattern |
1549 | +perl; | |
1550 | + $log_file= $ENV{'log_file'}; | |
1551 | + $log_file_full_path= $ENV{'log_file_full_path'}; | |
1c82f14e | 1552 | + $log_slow_rate_test= $ENV{'log_slow_rate_test'}; |
48b678b4 AM |
1553 | + open(FILE, "$log_file_full_path") |
1554 | + or die("Cannot open file $log_file_full_path: $!\n"); | |
1555 | + | |
1c82f14e AM |
1556 | + if ($log_slow_rate_test) { |
1557 | + $one= 0; | |
1558 | + $two= 0; | |
1559 | + $three= 0; | |
1560 | + while(<FILE>) { | |
1561 | + $one++ if(/'connection_one'/); | |
1562 | + $two++ if(/'connection_two'/); | |
1563 | + $three++ if(/'connection_three'/); | |
1564 | + } | |
1565 | + $sum= $one + $two + $three; | |
1566 | + $zero= 0; | |
1567 | + if ($one == 0) { | |
1568 | + $zero++; | |
1569 | + } | |
1570 | + if ($two == 0) { | |
1571 | + $zero++; | |
1572 | + } | |
1573 | + if ($three == 0) { | |
1574 | + $zero++; | |
1575 | + } | |
1576 | + print "[log_grep.inc] sum: $sum\n"; | |
1577 | + print "[log_grep.inc] zero: $zero\n"; | |
1578 | + } | |
1579 | + else { | |
1580 | + $grep_pattern= $ENV{'grep_pattern'}; | |
1581 | + $lines= 0; | |
1582 | + while(<FILE>) { | |
1583 | + $lines++ if (/$grep_pattern/); | |
1584 | + } | |
1585 | + print "[log_grep.inc] lines: $lines\n"; | |
48b678b4 AM |
1586 | + } |
1587 | + close(FILE); | |
48b678b4 AM |
1588 | +EOF |
1589 | --- /dev/null | |
1590 | +++ b/mysql-test/include/log_start.inc | |
1591 | @@ -0,0 +1,16 @@ | |
1592 | +--disable_query_log | |
1593 | +--let log_file_full_path = $MYSQLTEST_VARDIR/$log_file | |
1594 | +SET @slow_query_log_old=@@slow_query_log; | |
1595 | +SET @slow_query_log_file_old= @@slow_query_log_file; | |
1596 | +SET GLOBAL slow_query_log=OFF; | |
1597 | +perl; | |
1598 | + $log_file_full_path= $ENV{'log_file_full_path'}; | |
1599 | + unlink $log_file_full_path; | |
1600 | + open(FILE, '>', $log_file_full_path) | |
1601 | + or die "Cannot create log file $log_file_full_path, reason: $!"; | |
1602 | + close(FILE); | |
1603 | +EOF | |
1604 | +--echo [log_start.inc] $log_file | |
1605 | +EVAL SET GLOBAL slow_query_log_file="$log_file_full_path"; | |
1606 | +SET GLOBAL slow_query_log=ON; | |
1607 | +--enable_query_log | |
48b678b4 AM |
1608 | --- /dev/null |
1609 | +++ b/mysql-test/include/log_stop.inc | |
1610 | @@ -0,0 +1,7 @@ | |
1611 | +--disable_query_log | |
1612 | +FLUSH LOGS; | |
1613 | +SET GLOBAL slow_query_log=OFF; | |
1614 | +--echo [log_stop.inc] $log_file | |
1615 | +SET GLOBAL slow_query_log_file= @slow_query_log_file_old; | |
1616 | +SET GLOBAL slow_query_log= @slow_query_log_old; | |
1617 | +--enable_query_log | |
1618 | --- /dev/null | |
1619 | +++ b/mysql-test/r/percona_bug643149.result | |
1620 | @@ -0,0 +1,21 @@ | |
1621 | +SET @old_slow_query_log_file=@@global.slow_query_log_file; | |
1622 | +SET GLOBAL slow_query_log=on; | |
1623 | +SET LOCAL log_slow_verbosity='profiling'; | |
1624 | +SET LOCAL long_query_time=0; | |
1625 | +SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';; | |
1626 | +SELECT 1; | |
1627 | +1 | |
1628 | +1 | |
1629 | +# User@Host: root[root] @ localhost [] | |
1630 | +# Thread_id: X Schema: test Last_errno: X Killed: X | |
1631 | +# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X | |
1632 | +# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X | |
1633 | +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X | |
1634 | +# Profile_total: X.X Profile_total_cpu: X.X | |
1635 | +# User@Host: root[root] @ localhost [] | |
1636 | +# Thread_id: X Schema: test Last_errno: X Killed: X | |
1637 | +# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X | |
1638 | +# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X | |
1639 | +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X | |
1640 | +# Profile_total: X.X Profile_total_cpu: X.X | |
1641 | +SET GLOBAL slow_query_log_file=@old_slow_query_log_file; | |
1642 | --- /dev/null | |
1643 | +++ b/mysql-test/r/percona_log_slow_filter-cl.result | |
1644 | @@ -0,0 +1,6 @@ | |
1645 | +SHOW VARIABLES LIKE 'log_slow_filter'; | |
1646 | +Variable_name Value | |
1647 | +log_slow_filter full_join | |
1648 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_filter'; | |
1649 | +Variable_name Value | |
1650 | +log_slow_filter full_join | |
1651 | --- /dev/null | |
1652 | +++ b/mysql-test/r/percona_log_slow_filter.result | |
1c82f14e | 1653 | @@ -0,0 +1,16 @@ |
48b678b4 AM |
1654 | +CREATE TABLE t(id INT PRIMARY KEY); |
1655 | +INSERT INTO t VALUES(1); | |
1656 | +INSERT INTO t VALUES(2); | |
1657 | +INSERT INTO t VALUES(3); | |
1658 | +SET long_query_time=1; | |
1659 | +SET log_slow_filter=full_join; | |
1660 | +[log_start.inc] percona.slow_extended.log_slow_filter | |
1661 | +SET query_exec_time = 1.1; | |
1662 | +SELECT * FROM t AS t1, t AS t2; | |
1663 | +SET query_exec_time = default; | |
1664 | +[log_stop.inc] percona.slow_extended.log_slow_filter | |
1665 | +SET log_slow_filter=default; | |
1666 | +SET long_query_time=default; | |
1667 | +[log_grep.inc] file: percona.slow_extended.log_slow_filter pattern: Query_time | |
1668 | +[log_grep.inc] lines: 1 | |
1c82f14e | 1669 | +DROP TABLE t; |
48b678b4 AM |
1670 | --- /dev/null |
1671 | +++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result | |
1672 | @@ -0,0 +1,6 @@ | |
1673 | +SHOW VARIABLES LIKE 'log_slow_slave_statements'; | |
1674 | +Variable_name Value | |
1675 | +log_slow_slave_statements ON | |
1676 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements'; | |
1677 | +Variable_name Value | |
1678 | +log_slow_slave_statements ON | |
1679 | --- /dev/null | |
1680 | +++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result | |
1c82f14e | 1681 | @@ -0,0 +1,19 @@ |
48b678b4 AM |
1682 | +include/master-slave.inc |
1683 | +[connection master] | |
1684 | +DROP TABLE IF EXISTS t; | |
1685 | +CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB; | |
1686 | +INSERT INTO t VALUES | |
1687 | +(1,"aaaaabbbbbcccccdddddeeeeefffff"), | |
1688 | +(2,"aaaaabbbbbcccccdddddeeeeefffff"), | |
1689 | +(3,"aaaaabbbbbcccccdddddeeeeefffff"), | |
1690 | +(4,"aaaaabbbbbcccccdddddeeeeefffff"), | |
1691 | +(5,"aaaaabbbbbcccccdddddeeeeefffff"); | |
1692 | +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; | |
1693 | +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; | |
1694 | +[log_start.inc] percona.slow_extended.log_slow_slave_statements-innodb | |
1695 | +INSERT INTO t SELECT t.id,t.data from t; | |
1696 | +[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb | |
1697 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops | |
1698 | +[log_grep.inc] lines: 1 | |
1c82f14e | 1699 | +DROP TABLE t; |
48b678b4 AM |
1700 | +include/rpl_end.inc |
1701 | --- /dev/null | |
1702 | +++ b/mysql-test/r/percona_log_slow_slave_statements.result | |
1c82f14e | 1703 | @@ -0,0 +1,45 @@ |
48b678b4 AM |
1704 | +include/master-slave.inc |
1705 | +[connection master] | |
1706 | +DROP TABLE IF EXISTS t; | |
1707 | +CREATE TABLE t(id INT); | |
1708 | +[log_start.inc] percona.slow_extended.log_slow_slave_statements | |
1709 | +LINE 1 | |
1710 | +LOG_SLOW_SLAVE_STATAMENTS is OFF | |
1711 | +LOG_SLOW_SLAVE_STATEMENTS=ON | |
1712 | +LOG_SLOW_SLAVE_STATAMENTS is ON | |
1713 | +LINE 2 | |
1714 | +include/restart_slave.inc | |
1715 | +LOG_SLOW_SLAVE_STATAMENTS is ON | |
1716 | +LINE 3 | |
1717 | +LOG_SLOW_SLAVE_STATAMENTS is ON | |
1718 | +LOG_SLOW_SLAVE_STATEMENTS=OFF | |
1719 | +LOG_SLOW_SLAVE_STATAMENTS is OFF | |
1720 | +LINE 4 | |
1721 | +include/restart_slave.inc | |
1722 | +LOG_SLOW_SLAVE_STATAMENTS is OFF | |
1723 | +LINE 5 | |
1724 | +LOG_SLOW_SLAVE_STATAMENTS is OFF | |
1725 | +LOG_SLOW_SLAVE_STATEMENTS=ON | |
1726 | +LOG_SLOW_SLAVE_STATAMENTS is ON | |
1727 | +LINE 6 | |
1728 | +include/restart_slave.inc | |
1729 | +LOG_SLOW_SLAVE_STATAMENTS is ON | |
1730 | +LINE 7 | |
1731 | +[log_stop.inc] percona.slow_extended.log_slow_slave_statements | |
1732 | +SET GLOBAL log_slow_slave_statements=default; | |
1733 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(1\) | |
1734 | +[log_grep.inc] lines: 0 | |
1735 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(2\) | |
1736 | +[log_grep.inc] lines: 0 | |
1737 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(3\) | |
1738 | +[log_grep.inc] lines: 1 | |
1739 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(4\) | |
1740 | +[log_grep.inc] lines: 0 | |
1741 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(5\) | |
1742 | +[log_grep.inc] lines: 0 | |
1743 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(6\) | |
1744 | +[log_grep.inc] lines: 0 | |
1745 | +[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(7\) | |
1746 | +[log_grep.inc] lines: 1 | |
1c82f14e | 1747 | +DROP TABLE t; |
48b678b4 AM |
1748 | +include/rpl_end.inc |
1749 | --- /dev/null | |
1750 | +++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result | |
1751 | @@ -0,0 +1,6 @@ | |
1752 | +SHOW VARIABLES LIKE 'log_slow_sp_statements'; | |
1753 | +Variable_name Value | |
1754 | +log_slow_sp_statements ON | |
1755 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements'; | |
1756 | +Variable_name Value | |
1757 | +log_slow_sp_statements ON | |
1758 | --- /dev/null | |
1759 | +++ b/mysql-test/r/percona_log_slow_sp_statements.result | |
1c82f14e | 1760 | @@ -0,0 +1,25 @@ |
48b678b4 AM |
1761 | +SET long_query_time=1; |
1762 | +SET GLOBAL log_slow_sp_statements=ON; | |
1763 | +SET SESSION query_exec_time=0.1; | |
1764 | +[log_start.inc] percona.slow_extended.log_slow_sp_statements | |
1765 | +CREATE PROCEDURE test_f() | |
1766 | +BEGIN | |
1767 | +SET SESSION query_exec_time=1.1; SELECT 1; | |
1768 | +SET SESSION query_exec_time=2.1; SELECT 1; | |
1769 | +SET SESSION query_exec_time=3.1; SELECT 1; | |
1770 | +SET SESSION query_exec_time=0.1; | |
1771 | +END^ | |
1772 | +CALL test_f(); | |
1773 | +1 | |
1774 | +1 | |
1775 | +1 | |
1776 | +1 | |
1777 | +1 | |
1778 | +1 | |
1779 | +[log_stop.inc] percona.slow_extended.log_slow_sp_statements | |
1780 | +SET SESSION query_exec_time=default; | |
1781 | +SET GLOBAL log_slow_sp_statements=default; | |
1782 | +SET long_query_time=default; | |
1783 | +[log_grep.inc] file: percona.slow_extended.log_slow_sp_statements pattern: Query_time | |
1784 | +[log_grep.inc] lines: 3 | |
1c82f14e | 1785 | +DROP PROCEDURE test_f; |
48b678b4 AM |
1786 | --- /dev/null |
1787 | +++ b/mysql-test/r/percona_log_slow_verbosity-cl.result | |
1788 | @@ -0,0 +1,6 @@ | |
1789 | +SHOW VARIABLES LIKE 'log_slow_verbosity'; | |
1790 | +Variable_name Value | |
1791 | +log_slow_verbosity microtime,query_plan,innodb | |
1792 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity'; | |
1793 | +Variable_name Value | |
1794 | +log_slow_verbosity microtime,query_plan,innodb | |
1795 | --- /dev/null | |
1796 | +++ b/mysql-test/r/percona_log_slow_verbosity.result | |
1797 | @@ -0,0 +1,16 @@ | |
1798 | +SET SESSION long_query_time=1; | |
1799 | +[log_start.inc] percona.slow_extended.log_slow_verbosity | |
1800 | +SET SESSION query_exec_time=2.1; | |
1801 | +SELECT 1; | |
1802 | +1 | |
1803 | +1 | |
1804 | +SET SESSION log_slow_verbosity=innodb; | |
1805 | +SELECT 1; | |
1806 | +1 | |
1807 | +1 | |
1808 | +SET SESSION query_exec_time=default; | |
1809 | +[log_stop.inc] percona.slow_extended.log_slow_verbosity | |
1810 | +SET log_slow_verbosity=default; | |
1811 | +SET long_query_time=default; | |
1812 | +[log_grep.inc] file: percona.slow_extended.log_slow_verbosity pattern: No InnoDB statistics available for this query | |
1813 | +[log_grep.inc] lines: 1 | |
1814 | --- /dev/null | |
1815 | +++ b/mysql-test/r/percona_long_query_time.result | |
1816 | @@ -0,0 +1,33 @@ | |
1817 | +SET long_query_time=2; | |
1818 | +[log_start.inc] percona.slow_extended.long_query_time | |
1819 | +SET SESSION query_exec_time=1.1; | |
1820 | +SELECT 1; | |
1821 | +1 | |
1822 | +1 | |
1823 | +SET SESSION query_exec_time=3.1; | |
1824 | +SELECT 1; | |
1825 | +1 | |
1826 | +1 | |
1827 | +SET SESSION query_exec_time=5.1; | |
1828 | +SELECT 1; | |
1829 | +1 | |
1830 | +1 | |
1831 | +SET long_query_time=4; | |
1832 | +SET SESSION query_exec_time=1.1; | |
1833 | +SELECT 1; | |
1834 | +1 | |
1835 | +1 | |
1836 | +SET SESSION query_exec_time=3.1; | |
1837 | +SELECT 1; | |
1838 | +1 | |
1839 | +1 | |
1840 | +SET SESSION query_exec_time=5.1; | |
1841 | +SELECT 1; | |
1842 | +1 | |
1843 | +1 | |
1844 | +SET SESSION query_exec_time=default; | |
1845 | +SET long_query_time=2; | |
1846 | +[log_stop.inc] percona.slow_extended.long_query_time | |
1847 | +SET long_query_time=default; | |
1848 | +[log_grep.inc] file: percona.slow_extended.long_query_time pattern: Query_time | |
1849 | +[log_grep.inc] lines: 3 | |
1850 | --- /dev/null | |
1851 | +++ b/mysql-test/r/percona_slow_query_log_timestamp_always-cl.result | |
1852 | @@ -0,0 +1,6 @@ | |
1853 | +SHOW VARIABLES LIKE 'slow_query_log_timestamp_always'; | |
1854 | +Variable_name Value | |
1855 | +slow_query_log_timestamp_always ON | |
1856 | +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always'; | |
1857 | +Variable_name Value | |
1858 | +slow_query_log_timestamp_always ON | |
1859 | --- /dev/null | |
1860 | +++ b/mysql-test/r/percona_slow_query_log_timestamp_always.result | |
1861 | @@ -0,0 +1,41 @@ | |
1862 | +SET long_query_time=2; | |
1863 | +SET GLOBAL slow_query_log_timestamp_always=ON; | |
1864 | +[log_start.inc] percona.slow_extended.slow_query_log_timestamp_always | |
1865 | +SET SESSION query_exec_time=2.1; | |
1866 | +SELECT 1; | |
1867 | +1 | |
1868 | +1 | |
1869 | +SELECT 1; | |
1870 | +1 | |
1871 | +1 | |
1872 | +SELECT 1; | |
1873 | +1 | |
1874 | +1 | |
1875 | +SET GLOBAL slow_query_log_timestamp_always=OFF; | |
1876 | +SET SESSION query_exec_time=2.1; | |
1877 | +SELECT 1; | |
1878 | +1 | |
1879 | +1 | |
1880 | +SELECT 1; | |
1881 | +1 | |
1882 | +1 | |
1883 | +SELECT 1; | |
1884 | +1 | |
1885 | +1 | |
1886 | +SET GLOBAL slow_query_log_timestamp_always=ON; | |
1887 | +SET SESSION query_exec_time=2.1; | |
1888 | +SELECT 1; | |
1889 | +1 | |
1890 | +1 | |
1891 | +SELECT 1; | |
1892 | +1 | |
1893 | +1 | |
1894 | +SELECT 1; | |
1895 | +1 | |
1896 | +1 | |
1897 | +SET SESSION query_exec_time=default; | |
1898 | +[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_always | |
1899 | +SET GLOBAL slow_query_log_timestamp_always=default; | |
1900 | +SET long_query_time=default; | |
1901 | +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_always pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ | |
1902 | +[log_grep.inc] lines: 6 | |
1903 | --- /dev/null | |
1904 | +++ b/mysql-test/r/percona_slow_query_log_timestamp_precision-cl.result | |
1905 | @@ -0,0 +1,6 @@ | |
1906 | +SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision'; | |
1907 | +Variable_name Value | |
1908 | +slow_query_log_timestamp_precision microsecond | |
1909 | +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision'; | |
1910 | +Variable_name Value | |
1911 | +slow_query_log_timestamp_precision microsecond | |
1912 | --- /dev/null | |
1913 | +++ b/mysql-test/r/percona_slow_query_log_timestamp_precision.result | |
1914 | @@ -0,0 +1,18 @@ | |
1915 | +SET long_query_time=2; | |
1916 | +[log_start.inc] percona.slow_extended.slow_query_log_timestamp_precision | |
1917 | +SET SESSION query_exec_time=2.1; | |
1918 | +SELECT 1; | |
1919 | +1 | |
1920 | +1 | |
1921 | +SET GLOBAL slow_query_log_timestamp_precision='microsecond'; | |
1922 | +SELECT 1; | |
1923 | +1 | |
1924 | +1 | |
1925 | +SET SESSION query_exec_time=default; | |
1926 | +[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_precision | |
1927 | +SET GLOBAL slow_query_log_timestamp_precision=default; | |
1928 | +SET long_query_time=default; | |
1929 | +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+ | |
1930 | +[log_grep.inc] lines: 1 | |
1931 | +[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ | |
1932 | +[log_grep.inc] lines: 2 | |
1933 | --- /dev/null | |
1934 | +++ b/mysql-test/r/percona_slow_query_log_use_global_control.result | |
1935 | @@ -0,0 +1,18 @@ | |
1936 | +SET GLOBAL long_query_time=1; | |
1937 | +[log_start.inc] percona.slow_extended.slow_query_log_use_global_control | |
1938 | +SET SESSION query_exec_time=1.1; | |
1939 | +SELECT 1; | |
1940 | +1 | |
1941 | +1 | |
1942 | +SET GLOBAL log_slow_verbosity=innodb; | |
1943 | +SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time"; | |
1944 | +SELECT 1; | |
1945 | +1 | |
1946 | +1 | |
1947 | +SET SESSION query_exec_time=default; | |
1948 | +[log_stop.inc] percona.slow_extended.slow_query_log_use_global_control | |
1949 | +SET GLOBAL slow_query_log_use_global_control=default; | |
1950 | +SET GLOBAL log_slow_verbosity=default; | |
1951 | +SET GLOBAL long_query_time=default; | |
1952 | +[log_grep.inc] file: percona.slow_extended.slow_query_log_use_global_control pattern: No InnoDB statistics available for this query | |
1953 | +[log_grep.inc] lines: 1 | |
1954 | --- /dev/null | |
1955 | +++ b/mysql-test/t/percona_bug643149.test | |
1956 | @@ -0,0 +1,49 @@ | |
1957 | +# | |
1958 | +# This test suffers from server | |
1959 | +# Bug#38124 "general_log_file" variable silently unset when using expression | |
1960 | +# In short: | |
1961 | +# SET GLOBAL general_log_file = @<whatever> | |
1962 | +# SET GLOBAL slow_query_log = @<whatever> | |
1963 | +# cause that the value of these server system variables is set to default | |
1964 | +# instead of the assigned values. There comes no error message or warning. | |
1965 | +# If this bug is fixed please | |
1966 | +# 1. try this test with "let $fixed_bug38124 = 0;" | |
1967 | +# 2. remove all workarounds if 1. was successful. | |
1968 | +--source include/have_profiling.inc | |
1969 | +let $fixed_bug38124 = 0; | |
1970 | + | |
1971 | +SET @old_slow_query_log_file=@@global.slow_query_log_file; | |
1972 | +SET GLOBAL slow_query_log=on; | |
1973 | +SET LOCAL log_slow_verbosity='profiling'; | |
1974 | +SET LOCAL long_query_time=0; | |
1975 | + | |
1976 | +let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log; | |
1977 | +--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR | |
1978 | +--eval SET GLOBAL slow_query_log_file='$slogfile'; | |
1979 | + | |
1980 | +SELECT 1; | |
1981 | + | |
1982 | +perl; | |
1983 | + $slogfile= $ENV{'slogfile'}; | |
1984 | + | |
1985 | + open(FILE, "$slogfile") or | |
1986 | + die("Unable to read slow query log file $slogfile: $!\n"); | |
1987 | + while(<FILE>) { | |
1988 | + next if (!/^#/); | |
1989 | + next if (/^# Time:/); | |
1990 | + s/[0-9]+/X/g; | |
1991 | + print; | |
1992 | + } | |
1993 | + | |
1994 | + close(FILE); | |
1995 | +EOF | |
1996 | + | |
1997 | +SET GLOBAL slow_query_log_file=@old_slow_query_log_file; | |
1998 | + | |
1999 | +if(!$fixed_bug38124) | |
2000 | +{ | |
2001 | + --disable_query_log | |
2002 | + let $my_var = `SELECT @old_slow_query_log_file`; | |
2003 | + eval SET @@global.slow_query_log_file = '$my_var'; | |
2004 | + --enable_query_log | |
2005 | +} | |
2006 | --- /dev/null | |
2007 | +++ b/mysql-test/t/percona_log_slow_filter-cl-master.opt | |
2008 | @@ -0,0 +1 @@ | |
2009 | +--log_slow_filter=full_join | |
2010 | --- /dev/null | |
2011 | +++ b/mysql-test/t/percona_log_slow_filter-cl.test | |
2012 | @@ -0,0 +1,2 @@ | |
2013 | +SHOW VARIABLES LIKE 'log_slow_filter'; | |
2014 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_filter'; | |
2015 | --- /dev/null | |
2016 | +++ b/mysql-test/t/percona_log_slow_filter.test | |
2017 | @@ -0,0 +1,26 @@ | |
2018 | +--source include/have_debug.inc | |
2019 | + | |
2020 | +CREATE TABLE t(id INT PRIMARY KEY); | |
2021 | +INSERT INTO t VALUES(1); | |
2022 | +INSERT INTO t VALUES(2); | |
2023 | +INSERT INTO t VALUES(3); | |
2024 | + | |
2025 | +SET long_query_time=1; | |
2026 | +SET log_slow_filter=full_join; | |
2027 | +--let log_file=percona.slow_extended.log_slow_filter | |
2028 | +--source include/log_start.inc | |
2029 | + | |
2030 | +SET query_exec_time = 1.1; | |
2031 | +--disable_result_log | |
2032 | +SELECT * FROM t AS t1, t AS t2; | |
2033 | +--enable_result_log | |
2034 | +SET query_exec_time = default; | |
2035 | + | |
2036 | +--source include/log_stop.inc | |
2037 | +SET log_slow_filter=default; | |
2038 | +SET long_query_time=default; | |
2039 | + | |
2040 | +--let grep_pattern = Query_time | |
2041 | +--source include/log_grep.inc | |
2042 | + | |
2043 | +DROP TABLE t; | |
2044 | --- /dev/null | |
2045 | +++ b/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt | |
2046 | @@ -0,0 +1 @@ | |
2047 | +--log_slow_slave_statements | |
2048 | \ No newline at end of file | |
2049 | --- /dev/null | |
2050 | +++ b/mysql-test/t/percona_log_slow_slave_statements-cl.test | |
2051 | @@ -0,0 +1,3 @@ | |
2052 | +SHOW VARIABLES LIKE 'log_slow_slave_statements'; | |
2053 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements'; | |
2054 | + | |
2055 | --- /dev/null | |
2056 | +++ b/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt | |
2057 | @@ -0,0 +1 @@ | |
2058 | +--long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb | |
2059 | \ No newline at end of file | |
2060 | --- /dev/null | |
2061 | +++ b/mysql-test/t/percona_log_slow_slave_statements-innodb.test | |
2062 | @@ -0,0 +1,42 @@ | |
2063 | +--source include/have_binlog_format_statement.inc | |
2064 | +--source include/master-slave.inc | |
2065 | +--source include/have_innodb.inc | |
2066 | +--let log_file=percona.slow_extended.log_slow_slave_statements-innodb | |
2067 | + | |
2068 | +connection master; | |
2069 | +-- disable_warnings | |
2070 | +DROP TABLE IF EXISTS t; | |
2071 | +-- enable_warnings | |
2072 | + | |
2073 | +CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB; | |
2074 | +INSERT INTO t VALUES | |
2075 | +(1,"aaaaabbbbbcccccdddddeeeeefffff"), | |
2076 | +(2,"aaaaabbbbbcccccdddddeeeeefffff"), | |
2077 | +(3,"aaaaabbbbbcccccdddddeeeeefffff"), | |
2078 | +(4,"aaaaabbbbbcccccdddddeeeeefffff"), | |
2079 | +(5,"aaaaabbbbbcccccdddddeeeeefffff"); | |
2080 | +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; | |
2081 | +INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2; | |
2082 | +sync_slave_with_master; | |
2083 | + | |
2084 | +connection slave; | |
2085 | +--source include/log_start.inc | |
2086 | + | |
2087 | +connection master; | |
2088 | +INSERT INTO t SELECT t.id,t.data from t; | |
2089 | +sync_slave_with_master; | |
2090 | + | |
2091 | +connection slave; | |
2092 | +--source include/log_stop.inc | |
2093 | + | |
2094 | +--enable_query_log | |
2095 | +--enable_result_log | |
2096 | + | |
2097 | +--let grep_pattern = InnoDB_IO_r_ops | |
2098 | +--source include/log_grep.inc | |
2099 | + | |
2100 | +connection master; | |
2101 | +DROP TABLE t; | |
2102 | +sync_slave_with_master; | |
2103 | + | |
2104 | +--source include/rpl_end.inc | |
2105 | --- /dev/null | |
2106 | +++ b/mysql-test/t/percona_log_slow_slave_statements-slave.opt | |
2107 | @@ -0,0 +1 @@ | |
2108 | +--long_query_time=0 | |
2109 | \ No newline at end of file | |
2110 | --- /dev/null | |
2111 | +++ b/mysql-test/t/percona_log_slow_slave_statements.test | |
2112 | @@ -0,0 +1,117 @@ | |
2113 | +-- source include/have_binlog_format_statement.inc | |
2114 | +-- source include/master-slave.inc | |
2115 | +--let log_file=percona.slow_extended.log_slow_slave_statements | |
2116 | +--let show=SELECT Variable_value FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name LIKE 'log_slow_slave_statements'; | |
2117 | + | |
2118 | +connection master; | |
2119 | +-- disable_warnings | |
2120 | +DROP TABLE IF EXISTS t; | |
2121 | +-- enable_warnings | |
2122 | + | |
2123 | +CREATE TABLE t(id INT); | |
2124 | +sync_slave_with_master; | |
2125 | + | |
2126 | +connection slave; | |
2127 | +--source include/log_start.inc | |
2128 | + | |
2129 | +--disable_query_log | |
2130 | +--disable_result_log | |
2131 | + | |
2132 | +--echo LINE 1 | |
2133 | +connection master; | |
2134 | +INSERT INTO t VALUES (1); | |
2135 | +sync_slave_with_master; | |
2136 | + | |
2137 | +connection slave; | |
2138 | +--let value=`$show` | |
2139 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2140 | +--echo LOG_SLOW_SLAVE_STATEMENTS=ON | |
2141 | +SET GLOBAL log_slow_slave_statements=ON; | |
2142 | +--let value=`$show` | |
2143 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2144 | + | |
2145 | +--echo LINE 2 | |
2146 | +connection master; | |
2147 | +INSERT INTO t VALUES (2); | |
2148 | +sync_slave_with_master; | |
2149 | + | |
2150 | +--source include/restart_slave_sql.inc | |
2151 | + | |
2152 | +connection slave; | |
2153 | +--let value=`$show` | |
2154 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2155 | + | |
2156 | +--echo LINE 3 | |
2157 | +connection master; | |
2158 | +INSERT INTO t VALUES (3); | |
2159 | +sync_slave_with_master; | |
2160 | + | |
2161 | +connection slave; | |
2162 | +--let value=`$show` | |
2163 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2164 | +--echo LOG_SLOW_SLAVE_STATEMENTS=OFF | |
2165 | +SET GLOBAL log_slow_slave_statements=OFF; | |
2166 | +--let value=`$show` | |
2167 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2168 | + | |
2169 | +--echo LINE 4 | |
2170 | +connection master; | |
2171 | +INSERT INTO t VALUES (4); | |
2172 | +sync_slave_with_master; | |
2173 | + | |
2174 | +--source include/restart_slave_sql.inc | |
2175 | + | |
2176 | +connection slave; | |
2177 | +--let value=`$show` | |
2178 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2179 | + | |
2180 | +--echo LINE 5 | |
2181 | +connection master; | |
2182 | +INSERT INTO t VALUES (5); | |
2183 | +sync_slave_with_master; | |
2184 | + | |
2185 | +connection slave; | |
2186 | +--let value=`$show` | |
2187 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2188 | +--echo LOG_SLOW_SLAVE_STATEMENTS=ON | |
2189 | +SET GLOBAL log_slow_slave_statements=ON; | |
2190 | +--let value=`$show` | |
2191 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2192 | + | |
2193 | +--echo LINE 6 | |
2194 | +connection master; | |
2195 | +INSERT INTO t VALUES (6); | |
2196 | +sync_slave_with_master; | |
2197 | + | |
2198 | +--source include/restart_slave_sql.inc | |
2199 | + | |
2200 | +connection slave; | |
2201 | +--let value=`$show` | |
2202 | +--echo LOG_SLOW_SLAVE_STATAMENTS is $value | |
2203 | + | |
2204 | +--echo LINE 7 | |
2205 | +connection master; | |
2206 | +INSERT INTO t VALUES (7); | |
2207 | +sync_slave_with_master; | |
2208 | + | |
2209 | +--enable_query_log | |
2210 | +--enable_result_log | |
2211 | + | |
2212 | +connection slave; | |
2213 | +--source include/log_stop.inc | |
2214 | +SET GLOBAL log_slow_slave_statements=default; | |
2215 | + | |
2216 | +connection slave; | |
2217 | +--let i=1 | |
2218 | +while($i < 8) | |
2219 | +{ | |
2220 | +--let grep_pattern= INSERT INTO t VALUES \($i\) | |
2221 | +--source include/log_grep.inc | |
2222 | + inc $i; | |
2223 | +} | |
2224 | + | |
2225 | +connection master; | |
2226 | +DROP TABLE t; | |
2227 | +sync_slave_with_master; | |
2228 | + | |
2229 | +--source include/rpl_end.inc | |
2230 | --- /dev/null | |
2231 | +++ b/mysql-test/t/percona_log_slow_sp_statements-cl-master.opt | |
2232 | @@ -0,0 +1 @@ | |
2233 | +--log_slow_sp_statements | |
2234 | --- /dev/null | |
2235 | +++ b/mysql-test/t/percona_log_slow_sp_statements-cl.test | |
2236 | @@ -0,0 +1,2 @@ | |
2237 | +SHOW VARIABLES LIKE 'log_slow_sp_statements'; | |
2238 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements'; | |
2239 | --- /dev/null | |
2240 | +++ b/mysql-test/t/percona_log_slow_sp_statements.test | |
2241 | @@ -0,0 +1,29 @@ | |
2242 | +--source include/have_debug.inc | |
2243 | + | |
2244 | +SET long_query_time=1; | |
2245 | +SET GLOBAL log_slow_sp_statements=ON; | |
2246 | +SET SESSION query_exec_time=0.1; | |
2247 | +--let log_file=percona.slow_extended.log_slow_sp_statements | |
2248 | +--source include/log_start.inc | |
2249 | + | |
2250 | +delimiter ^; | |
2251 | +CREATE PROCEDURE test_f() | |
2252 | +BEGIN | |
2253 | + SET SESSION query_exec_time=1.1; SELECT 1; | |
2254 | + SET SESSION query_exec_time=2.1; SELECT 1; | |
2255 | + SET SESSION query_exec_time=3.1; SELECT 1; | |
2256 | + SET SESSION query_exec_time=0.1; | |
2257 | +END^ | |
2258 | +delimiter ;^ | |
2259 | + | |
2260 | +CALL test_f(); | |
2261 | + | |
2262 | +--source include/log_stop.inc | |
2263 | +SET SESSION query_exec_time=default; | |
2264 | +SET GLOBAL log_slow_sp_statements=default; | |
2265 | +SET long_query_time=default; | |
2266 | + | |
2267 | +--let grep_pattern = Query_time | |
2268 | +--source include/log_grep.inc | |
2269 | + | |
2270 | +DROP PROCEDURE test_f; | |
2271 | --- /dev/null | |
2272 | +++ b/mysql-test/t/percona_log_slow_verbosity-cl-master.opt | |
2273 | @@ -0,0 +1 @@ | |
2274 | +--log_slow_verbosity="full" | |
2275 | --- /dev/null | |
2276 | +++ b/mysql-test/t/percona_log_slow_verbosity-cl.test | |
2277 | @@ -0,0 +1,2 @@ | |
2278 | +SHOW VARIABLES LIKE 'log_slow_verbosity'; | |
2279 | +SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity'; | |
2280 | --- /dev/null | |
2281 | +++ b/mysql-test/t/percona_log_slow_verbosity.test | |
2282 | @@ -0,0 +1,19 @@ | |
2283 | +--source include/have_innodb.inc | |
2284 | +--source include/have_debug.inc | |
2285 | + | |
2286 | +SET SESSION long_query_time=1; | |
2287 | +--let log_file=percona.slow_extended.log_slow_verbosity | |
2288 | +--source include/log_start.inc | |
2289 | + | |
2290 | +SET SESSION query_exec_time=2.1; | |
2291 | +SELECT 1; | |
2292 | +SET SESSION log_slow_verbosity=innodb; | |
2293 | +SELECT 1; | |
2294 | +SET SESSION query_exec_time=default; | |
2295 | + | |
2296 | +--source include/log_stop.inc | |
2297 | +SET log_slow_verbosity=default; | |
2298 | +SET long_query_time=default; | |
2299 | + | |
2300 | +--let grep_pattern = No InnoDB statistics available for this query | |
2301 | +--source include/log_grep.inc | |
2302 | --- /dev/null | |
2303 | +++ b/mysql-test/t/percona_long_query_time.test | |
2304 | @@ -0,0 +1,25 @@ | |
2305 | +--source include/have_debug.inc | |
2306 | + | |
2307 | +SET long_query_time=2; | |
2308 | +--let log_file=percona.slow_extended.long_query_time | |
2309 | +--source include/log_start.inc | |
2310 | + | |
2311 | +SET SESSION query_exec_time=1.1; SELECT 1; | |
2312 | +SET SESSION query_exec_time=3.1; SELECT 1; | |
2313 | +SET SESSION query_exec_time=5.1; SELECT 1; | |
2314 | + | |
2315 | +SET long_query_time=4; | |
2316 | + | |
2317 | +SET SESSION query_exec_time=1.1; SELECT 1; | |
2318 | +SET SESSION query_exec_time=3.1; SELECT 1; | |
2319 | +SET SESSION query_exec_time=5.1; SELECT 1; | |
2320 | + | |
2321 | +SET SESSION query_exec_time=default; | |
2322 | + | |
2323 | +SET long_query_time=2; | |
2324 | + | |
2325 | +--source include/log_stop.inc | |
2326 | +SET long_query_time=default; | |
2327 | + | |
2328 | +--let grep_pattern = Query_time | |
2329 | +--source include/log_grep.inc | |
2330 | --- /dev/null | |
2331 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl-master.opt | |
2332 | @@ -0,0 +1 @@ | |
2333 | +--slow_query_log_timestamp_always | |
2334 | \ No newline at end of file | |
2335 | --- /dev/null | |
2336 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl.test | |
2337 | @@ -0,0 +1,2 @@ | |
2338 | +SHOW VARIABLES LIKE 'slow_query_log_timestamp_always'; | |
2339 | +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always'; | |
2340 | --- /dev/null | |
2341 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_always.test | |
2342 | @@ -0,0 +1,34 @@ | |
2343 | +--source include/have_debug.inc | |
2344 | + | |
2345 | +SET long_query_time=2; | |
2346 | +SET GLOBAL slow_query_log_timestamp_always=ON; | |
2347 | +--let log_file=percona.slow_extended.slow_query_log_timestamp_always | |
2348 | +--source include/log_start.inc | |
2349 | + | |
2350 | +SET SESSION query_exec_time=2.1; | |
2351 | +SELECT 1; | |
2352 | +SELECT 1; | |
2353 | +SELECT 1; | |
2354 | + | |
2355 | +SET GLOBAL slow_query_log_timestamp_always=OFF; | |
2356 | + | |
2357 | +SET SESSION query_exec_time=2.1; | |
2358 | +SELECT 1; | |
2359 | +SELECT 1; | |
2360 | +SELECT 1; | |
2361 | + | |
2362 | +SET GLOBAL slow_query_log_timestamp_always=ON; | |
2363 | + | |
2364 | +SET SESSION query_exec_time=2.1; | |
2365 | +SELECT 1; | |
2366 | +SELECT 1; | |
2367 | +SELECT 1; | |
2368 | + | |
2369 | +SET SESSION query_exec_time=default; | |
2370 | + | |
2371 | +--source include/log_stop.inc | |
2372 | +SET GLOBAL slow_query_log_timestamp_always=default; | |
2373 | +SET long_query_time=default; | |
2374 | + | |
2375 | +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ | |
2376 | +--source include/log_grep.inc | |
2377 | --- /dev/null | |
2378 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl-master.opt | |
2379 | @@ -0,0 +1 @@ | |
2380 | +--slow_query_log_timestamp_precision='microsecond' | |
2381 | \ No newline at end of file | |
2382 | --- /dev/null | |
2383 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl.test | |
2384 | @@ -0,0 +1,2 @@ | |
2385 | +SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision'; | |
2386 | +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision'; | |
2387 | --- /dev/null | |
2388 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-master.opt | |
2389 | @@ -0,0 +1 @@ | |
2390 | +--slow_query_log_timestamp_always | |
2391 | \ No newline at end of file | |
2392 | --- /dev/null | |
2393 | +++ b/mysql-test/t/percona_slow_query_log_timestamp_precision.test | |
2394 | @@ -0,0 +1,25 @@ | |
2395 | +--source include/have_debug.inc | |
2396 | + | |
2397 | +SET long_query_time=2; | |
2398 | +--let log_file=percona.slow_extended.slow_query_log_timestamp_precision | |
2399 | +--source include/log_start.inc | |
2400 | + | |
2401 | +SET SESSION query_exec_time=2.1; | |
2402 | + | |
2403 | +SELECT 1; | |
2404 | + | |
2405 | +SET GLOBAL slow_query_log_timestamp_precision='microsecond'; | |
2406 | + | |
2407 | +SELECT 1; | |
2408 | + | |
2409 | +SET SESSION query_exec_time=default; | |
2410 | + | |
2411 | +--source include/log_stop.inc | |
2412 | +SET GLOBAL slow_query_log_timestamp_precision=default; | |
2413 | +SET long_query_time=default; | |
2414 | + | |
2415 | +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+ | |
2416 | +--source include/log_grep.inc | |
2417 | + | |
2418 | +--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+ | |
2419 | +--source include/log_grep.inc | |
2420 | --- /dev/null | |
2421 | +++ b/mysql-test/t/percona_slow_query_log_use_global_control.test | |
2422 | @@ -0,0 +1,28 @@ | |
2423 | +--source include/have_debug.inc | |
2424 | +--source include/have_innodb.inc | |
2425 | + | |
2426 | +SET GLOBAL long_query_time=1; | |
2427 | + | |
2428 | +--let log_file=percona.slow_extended.slow_query_log_use_global_control | |
2429 | +--source include/log_start.inc | |
2430 | + | |
2431 | +SET SESSION query_exec_time=1.1; | |
2432 | +SELECT 1; | |
2433 | + | |
2434 | +SET GLOBAL log_slow_verbosity=innodb; | |
2435 | +SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time"; | |
2436 | + | |
2437 | +SELECT 1; | |
2438 | + | |
2439 | +SET SESSION query_exec_time=default; | |
2440 | + | |
2441 | +--source include/log_stop.inc | |
2442 | + | |
2443 | + | |
2444 | +SET GLOBAL slow_query_log_use_global_control=default; | |
2445 | +SET GLOBAL log_slow_verbosity=default; | |
2446 | +SET GLOBAL long_query_time=default; | |
2447 | + | |
2448 | +--let grep_pattern = No InnoDB statistics available for this query | |
2449 | +--source include/log_grep.inc | |
2450 | + | |
2451 | --- /dev/null | |
2452 | +++ b/mysql-test/r/percona_slow_query_log_use_global_control-cl.result | |
2453 | @@ -0,0 +1,6 @@ | |
2454 | +SHOW VARIABLES LIKE 'slow_query_log_use_global_control'; | |
2455 | +Variable_name Value | |
2456 | +slow_query_log_use_global_control log_slow_verbosity,long_query_time | |
2457 | +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control'; | |
2458 | +Variable_name Value | |
2459 | +slow_query_log_use_global_control log_slow_verbosity,long_query_time | |
2460 | --- /dev/null | |
2461 | +++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl-master.opt | |
2462 | @@ -0,0 +1 @@ | |
2463 | +--slow_query_log_use_global_control="log_slow_verbosity,long_query_time" | |
2464 | --- /dev/null | |
2465 | +++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl.test | |
2466 | @@ -0,0 +1,2 @@ | |
2467 | +SHOW VARIABLES LIKE 'slow_query_log_use_global_control'; | |
2468 | +SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control'; | |
2469 | --- /dev/null | |
2470 | +++ b/mysql-test/r/percona_min_examined_row_limit.result | |
1c82f14e | 2471 | @@ -0,0 +1,35 @@ |
48b678b4 AM |
2472 | +drop table if exists t; |
2473 | +create table t(id INT PRIMARY KEY); | |
2474 | +insert into t values(1); | |
2475 | +insert into t values(2); | |
2476 | +insert into t values(3); | |
2477 | +SET GLOBAL long_query_time=2; | |
2478 | +SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit'; | |
2479 | +[log_start.inc] percona.slow_extended.min_examined_row_limit | |
2480 | +SET SESSION query_exec_time=2.1; | |
2481 | +SELECT 1; | |
2482 | +1 | |
2483 | +1 | |
2484 | +SET GLOBAL min_examined_row_limit=5; | |
2485 | +select * from t as t1, t as t2; | |
2486 | +id id | |
2487 | +1 1 | |
2488 | +2 1 | |
2489 | +3 1 | |
2490 | +1 2 | |
2491 | +2 2 | |
2492 | +3 2 | |
2493 | +1 3 | |
2494 | +2 3 | |
2495 | +3 3 | |
2496 | +SELECT 1; | |
2497 | +1 | |
2498 | +1 | |
2499 | +SET SESSION query_exec_time=default; | |
2500 | +[log_stop.inc] percona.slow_extended.min_examined_row_limit | |
2501 | +SET GLOBAL min_examined_row_limit=default; | |
2502 | +SET GLOBAL slow_query_log_use_global_control=default; | |
2503 | +SET GLOBAL long_query_time=default; | |
2504 | +[log_grep.inc] file: percona.slow_extended.min_examined_row_limit pattern: Query_time | |
2505 | +[log_grep.inc] lines: 1 | |
1c82f14e | 2506 | +DROP TABLE t; |
48b678b4 AM |
2507 | --- /dev/null |
2508 | +++ b/mysql-test/t/percona_min_examined_row_limit.test | |
2509 | @@ -0,0 +1,35 @@ | |
2510 | +--source include/have_debug.inc | |
2511 | + | |
2512 | +--disable_warnings | |
2513 | +drop table if exists t; | |
2514 | +--enable_warnings | |
2515 | + | |
2516 | +create table t(id INT PRIMARY KEY); | |
2517 | +insert into t values(1); | |
2518 | +insert into t values(2); | |
2519 | +insert into t values(3); | |
2520 | + | |
2521 | +SET GLOBAL long_query_time=2; | |
2522 | +SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit'; | |
2523 | +--let log_file=percona.slow_extended.min_examined_row_limit | |
2524 | +--source include/log_start.inc | |
2525 | + | |
2526 | +SET SESSION query_exec_time=2.1; | |
2527 | +SELECT 1; | |
2528 | + | |
2529 | +SET GLOBAL min_examined_row_limit=5; | |
2530 | + | |
2531 | +select * from t as t1, t as t2; | |
2532 | +SELECT 1; | |
2533 | + | |
2534 | +SET SESSION query_exec_time=default; | |
2535 | + | |
2536 | +--source include/log_stop.inc | |
2537 | +SET GLOBAL min_examined_row_limit=default; | |
2538 | +SET GLOBAL slow_query_log_use_global_control=default; | |
2539 | +SET GLOBAL long_query_time=default; | |
2540 | + | |
2541 | +--let grep_pattern = Query_time | |
2542 | +--source include/log_grep.inc | |
2543 | + | |
2544 | +DROP TABLE t; | |
2545 | --- a/sql/log_event.cc | |
2546 | +++ b/sql/log_event.cc | |
734d6226 | 2547 | @@ -2385,6 +2385,14 @@ |
48b678b4 AM |
2548 | start+= host.length; |
2549 | } | |
2550 | } | |
2551 | +#ifndef DBUG_OFF | |
2552 | + if (thd && thd->variables.query_exec_time > 0) | |
2553 | + { | |
2554 | + *start++= Q_QUERY_EXEC_TIME; | |
2555 | + int8store(start, thd->variables.query_exec_time); | |
2556 | + start+= 8; | |
2557 | + } | |
2558 | +#endif | |
2559 | /* | |
2560 | NOTE: When adding new status vars, please don't forget to update | |
2561 | the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update the function | |
734d6226 | 2562 | @@ -2871,6 +2879,17 @@ |
48b678b4 AM |
2563 | data_written= master_data_written= uint4korr(pos); |
2564 | pos+= 4; | |
2565 | break; | |
2566 | +#if !defined(DBUG_OFF) && !defined(MYSQL_CLIENT) | |
2567 | + case Q_QUERY_EXEC_TIME: | |
2568 | + { | |
2569 | + THD *thd= current_thd; | |
2570 | + CHECK_SPACE(pos, end, 8); | |
2571 | + if (thd) | |
2572 | + thd->variables.query_exec_time= uint8korr(pos); | |
2573 | + pos+= 8; | |
2574 | + break; | |
2575 | + } | |
2576 | +#endif | |
2577 | case Q_INVOKER: | |
2578 | { | |
2579 | CHECK_SPACE(pos, end, 1); | |
2580 | --- a/sql/log_event.h | |
2581 | +++ b/sql/log_event.h | |
1bfc1981 | 2582 | @@ -343,6 +343,10 @@ |
48b678b4 AM |
2583 | |
2584 | #define Q_INVOKER 11 | |
2585 | ||
2586 | +#ifndef DBUG_OFF | |
2587 | +#define Q_QUERY_EXEC_TIME 250 | |
2588 | +#endif | |
2589 | + | |
2590 | /* Intvar event post-header */ | |
2591 | ||
2592 | /* Intvar event data */ | |
2593 | --- /dev/null | |
2594 | +++ b/mysql-test/suite/sys_vars/r/query_exec_time_basic.result | |
2595 | @@ -0,0 +1,2 @@ | |
2596 | +SET GLOBAL query_exec_time=default; | |
2597 | +SET SESSION query_exec_time=default; | |
2598 | --- /dev/null | |
2599 | +++ b/mysql-test/suite/sys_vars/t/query_exec_time_basic.test | |
2600 | @@ -0,0 +1,4 @@ | |
2601 | +--source include/have_debug.inc | |
2602 | + | |
2603 | +SET GLOBAL query_exec_time=default; | |
2604 | +SET SESSION query_exec_time=default; | |
734d6226 AM |
2605 | --- /dev/null |
2606 | +++ b/mysql-test/r/percona_log_slow_global_control_default.result | |
2607 | @@ -0,0 +1 @@ | |
2608 | +SET GLOBAL slow_query_log_use_global_control=default; | |
2609 | --- /dev/null | |
2610 | +++ b/mysql-test/t/percona_log_slow_global_control_default.test | |
2611 | @@ -0,0 +1 @@ | |
2612 | +SET GLOBAL slow_query_log_use_global_control=default; | |
2613 | --- /dev/null | |
2614 | +++ b/mysql-test/r/percona_slow_extended_log_error.result | |
1c82f14e | 2615 | @@ -0,0 +1,10 @@ |
734d6226 AM |
2616 | +SET long_query_time=0; |
2617 | +DROP TABLE IF EXISTS t1; | |
2618 | +CREATE TABLE t(a INT); | |
2619 | +[log_start.inc] percona.slow_extended.log_error | |
2620 | +CREATE TABLE t(a INT); | |
2621 | +ERROR 42S01: Table 't' already exists | |
2622 | +[log_stop.inc] percona.slow_extended.log_error | |
2623 | +[log_grep.inc] file: percona.slow_extended.log_error pattern: Last_errno: 1050 | |
2624 | +[log_grep.inc] lines: 1 | |
1c82f14e | 2625 | +DROP TABLE t; |
734d6226 AM |
2626 | --- /dev/null |
2627 | +++ b/mysql-test/t/percona_slow_extended_log_error.test | |
2628 | @@ -0,0 +1,15 @@ | |
2629 | +--let log_file=percona.slow_extended.log_error | |
2630 | +SET long_query_time=0; | |
2631 | +--disable_warnings | |
2632 | +DROP TABLE IF EXISTS t1; | |
2633 | +--enable_warnings | |
2634 | +CREATE TABLE t(a INT); | |
2635 | +--source include/log_start.inc | |
2636 | + | |
2637 | +--error ER_TABLE_EXISTS_ERROR | |
2638 | +CREATE TABLE t(a INT); | |
2639 | + | |
2640 | +--source include/log_stop.inc | |
2641 | +--let grep_pattern = Last_errno: 1050 | |
2642 | +--source include/log_grep.inc | |
2643 | +DROP TABLE t; | |
2644 | --- /dev/null | |
2645 | +++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test | |
2646 | @@ -0,0 +1 @@ | |
2647 | +SELECT @@global.log_slow_admin_statements; | |
2648 | --- /dev/null | |
2649 | +++ b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_basic.result | |
2650 | @@ -0,0 +1,3 @@ | |
2651 | +SELECT @@global.log_slow_admin_statements; | |
2652 | +@@global.log_slow_admin_statements | |
2653 | +0 | |
2654 | --- /dev/null | |
2655 | +++ b/mysql-test/r/percona_log_slow_admin_statements.result | |
2656 | @@ -0,0 +1,35 @@ | |
2657 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2658 | +Variable_name Value | |
2659 | +log_slow_admin_statements OFF | |
2660 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2661 | +VARIABLE_NAME VARIABLE_VALUE | |
2662 | +LOG_SLOW_ADMIN_STATEMENTS OFF | |
2663 | +SET GLOBAL log_slow_admin_statements=true; | |
2664 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2665 | +Variable_name Value | |
2666 | +log_slow_admin_statements ON | |
2667 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2668 | +VARIABLE_NAME VARIABLE_VALUE | |
2669 | +LOG_SLOW_ADMIN_STATEMENTS ON | |
2670 | +SET GLOBAL log_slow_admin_statements=false; | |
2671 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2672 | +Variable_name Value | |
2673 | +log_slow_admin_statements OFF | |
2674 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2675 | +VARIABLE_NAME VARIABLE_VALUE | |
2676 | +LOG_SLOW_ADMIN_STATEMENTS OFF | |
2677 | +SET GLOBAL log_slow_admin_statements=foo; | |
2678 | +ERROR 42000: Variable 'log_slow_admin_statements' can't be set to the value of 'foo' | |
2679 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2680 | +Variable_name Value | |
2681 | +log_slow_admin_statements OFF | |
2682 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2683 | +VARIABLE_NAME VARIABLE_VALUE | |
2684 | +LOG_SLOW_ADMIN_STATEMENTS OFF | |
2685 | +SET GLOBAL log_slow_admin_statements=default; | |
2686 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2687 | +Variable_name Value | |
2688 | +log_slow_admin_statements OFF | |
2689 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2690 | +VARIABLE_NAME VARIABLE_VALUE | |
2691 | +LOG_SLOW_ADMIN_STATEMENTS OFF | |
2692 | --- /dev/null | |
2693 | +++ b/mysql-test/r/percona_log_slow_admin_statements-config_false.result | |
2694 | @@ -0,0 +1,6 @@ | |
2695 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2696 | +Variable_name Value | |
2697 | +log_slow_admin_statements OFF | |
2698 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2699 | +VARIABLE_NAME VARIABLE_VALUE | |
2700 | +LOG_SLOW_ADMIN_STATEMENTS OFF | |
2701 | --- /dev/null | |
2702 | +++ b/mysql-test/r/percona_log_slow_admin_statements-config_foo.result | |
2703 | @@ -0,0 +1,7 @@ | |
2704 | +call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF."); | |
2705 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2706 | +Variable_name Value | |
2707 | +log_slow_admin_statements OFF | |
2708 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2709 | +VARIABLE_NAME VARIABLE_VALUE | |
2710 | +LOG_SLOW_ADMIN_STATEMENTS OFF | |
2711 | --- /dev/null | |
2712 | +++ b/mysql-test/r/percona_log_slow_admin_statements-config_true.result | |
2713 | @@ -0,0 +1,6 @@ | |
2714 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2715 | +Variable_name Value | |
2716 | +log_slow_admin_statements ON | |
2717 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2718 | +VARIABLE_NAME VARIABLE_VALUE | |
2719 | +LOG_SLOW_ADMIN_STATEMENTS ON | |
2720 | --- /dev/null | |
2721 | +++ b/mysql-test/r/percona_log_slow_admin_statements-config.result | |
2722 | @@ -0,0 +1,6 @@ | |
2723 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2724 | +Variable_name Value | |
2725 | +log_slow_admin_statements ON | |
2726 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2727 | +VARIABLE_NAME VARIABLE_VALUE | |
2728 | +LOG_SLOW_ADMIN_STATEMENTS ON | |
2729 | --- /dev/null | |
2730 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.cnf | |
2731 | @@ -0,0 +1,2 @@ | |
2732 | +[mysqld.1] | |
2733 | +log-slow-admin-statements=false | |
2734 | --- /dev/null | |
2735 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.cnf | |
2736 | @@ -0,0 +1,2 @@ | |
2737 | +[mysqld.1] | |
2738 | +log-slow-admin-statements=foo | |
2739 | --- /dev/null | |
2740 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.cnf | |
2741 | @@ -0,0 +1,2 @@ | |
2742 | +[mysqld.1] | |
2743 | +log-slow-admin-statements=true | |
2744 | --- /dev/null | |
2745 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config.cnf | |
2746 | @@ -0,0 +1,2 @@ | |
2747 | +[mysqld.1] | |
2748 | +log-slow-admin-statements | |
2749 | --- /dev/null | |
2750 | +++ b/mysql-test/t/percona_log_slow_admin_statements.test | |
2751 | @@ -0,0 +1,20 @@ | |
2752 | +# default value | |
2753 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2754 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2755 | +# set value to 'true' | |
2756 | +SET GLOBAL log_slow_admin_statements=true; | |
2757 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2758 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2759 | +# set value to 'false' | |
2760 | +SET GLOBAL log_slow_admin_statements=false; | |
2761 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2762 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2763 | +# set value to 'foo' | |
2764 | +--error ER_WRONG_VALUE_FOR_VAR | |
2765 | +SET GLOBAL log_slow_admin_statements=foo; | |
2766 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2767 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2768 | +# set value to default | |
2769 | +SET GLOBAL log_slow_admin_statements=default; | |
2770 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2771 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2772 | --- /dev/null | |
2773 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.test | |
2774 | @@ -0,0 +1,2 @@ | |
2775 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2776 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2777 | --- /dev/null | |
2778 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.test | |
2779 | @@ -0,0 +1,3 @@ | |
2780 | +call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF."); | |
2781 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2782 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2783 | --- /dev/null | |
2784 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.test | |
2785 | @@ -0,0 +1,2 @@ | |
2786 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2787 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2788 | --- /dev/null | |
2789 | +++ b/mysql-test/t/percona_log_slow_admin_statements-config.test | |
2790 | @@ -0,0 +1,2 @@ | |
2791 | +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements'; | |
2792 | +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements'; | |
2793 | --- a/mysql-test/r/mysqld--help-notwin.result | |
2794 | +++ b/mysql-test/r/mysqld--help-notwin.result | |
1c82f14e | 2795 | @@ -250,15 +250,38 @@ |
734d6226 AM |
2796 | --log-slow-admin-statements |
2797 | Log slow OPTIMIZE, ANALYZE, ALTER and other | |
2798 | administrative statements to the slow log if it is open. | |
2799 | + --log-slow-filter=name | |
2800 | + Log only the queries that followed certain execution | |
2801 | + plan. Multiple flags allowed in a comma-separated string. | |
2802 | + [qc_miss, full_scan, full_join, tmp_table, | |
2803 | + tmp_table_on_disk, filesort, filesort_on_disk] | |
2804 | --log-slow-queries[=name] | |
2805 | Log slow queries to a table or log file. Defaults logging | |
2806 | to table mysql.slow_log or hostname-slow.log if | |
2807 | --log-output=file is used. Must be enabled to activate | |
2808 | other slow log options. Deprecated option, use | |
2809 | --slow-query-log/--slow-query-log-file instead. | |
2810 | + --log-slow-rate-limit=# | |
2811 | + Rate limit statement writes to slow log to only those | |
2812 | + from every (1/log_slow_rate_limit) session. | |
1c82f14e AM |
2813 | + --log-slow-rate-type=name |
2814 | + Choose the log_slow_rate_limit behavior: session or | |
2815 | + query. When you choose 'session' - every | |
2816 | + %log_slow_rate_limit connection will be processed to slow | |
2817 | + query log. When you choose 'query' - every | |
2818 | + %log_slow_rate_limit query will be processed to slow | |
2819 | + query log. [session, query] | |
734d6226 AM |
2820 | --log-slow-slave-statements |
2821 | - Log slow statements executed by slave thread to the slow | |
2822 | - log if it is open. | |
2823 | + Log queries replayed be the slave SQL thread | |
2824 | + --log-slow-sp-statements | |
2825 | + Log slow statements executed by stored procedure to the | |
2826 | + slow log if it is open. | |
2827 | + (Defaults to on; use --skip-log-slow-sp-statements to disable.) | |
2828 | + --log-slow-verbosity=name | |
2829 | + Choose how verbose the messages to your slow log will be. | |
2830 | + Multiple flags allowed in a comma-separated string. | |
2831 | + [microtime, query_plan, innodb, profiling, | |
2832 | + profiling_use_getrusage] | |
2833 | --log-tc=name Path to transaction coordinator log (used for | |
2834 | transactions that affect more than one storage engine, | |
2835 | when binary log is disabled). | |
1c82f14e | 2836 | @@ -660,6 +683,18 @@ |
734d6226 AM |
2837 | Log slow queries to given log file. Defaults logging to |
2838 | hostname-slow.log. Must be enabled to activate other slow | |
2839 | log options | |
2840 | + --slow-query-log-timestamp-always | |
2841 | + Timestamp is printed for all records of the slow log even | |
2842 | + if they are same time. | |
2843 | + --slow-query-log-timestamp-precision=name | |
2844 | + Log slow statements executed by stored procedure to the | |
2845 | + slow log if it is open. [second, microsecond] | |
2846 | + --slow-query-log-use-global-control=name | |
2847 | + Choose flags, wich always use the global variables. | |
2848 | + Multiple flags allowed in a comma-separated string. | |
2849 | + [none, log_slow_filter, log_slow_rate_limit, | |
2850 | + log_slow_verbosity, long_query_time, | |
2851 | + min_examined_row_limit, all] | |
2852 | --socket=name Socket file to use for connection | |
2853 | --sort-buffer-size=# | |
2854 | Each thread that needs to do a sort allocates a buffer of | |
1c82f14e | 2855 | @@ -817,7 +852,12 @@ |
734d6226 AM |
2856 | log-short-format FALSE |
2857 | log-slave-updates FALSE | |
2858 | log-slow-admin-statements FALSE | |
2859 | +log-slow-filter | |
2860 | +log-slow-rate-limit 1 | |
1c82f14e | 2861 | +log-slow-rate-type session |
734d6226 AM |
2862 | log-slow-slave-statements FALSE |
2863 | +log-slow-sp-statements TRUE | |
2864 | +log-slow-verbosity | |
2865 | log-tc tc.log | |
2866 | log-tc-size 24576 | |
2867 | log-warnings 1 | |
1c82f14e | 2868 | @@ -933,6 +973,9 @@ |
734d6226 AM |
2869 | slave-type-conversions |
2870 | slow-launch-time 2 | |
2871 | slow-query-log FALSE | |
2872 | +slow-query-log-timestamp-always FALSE | |
2873 | +slow-query-log-timestamp-precision second | |
2874 | +slow-query-log-use-global-control | |
2875 | sort-buffer-size 2097152 | |
2876 | sporadic-binlog-dump-fail FALSE | |
2877 | sql-mode | |
1c82f14e AM |
2878 | --- /dev/null |
2879 | +++ b/mysql-test/r/percona_slow_query_log_rate.result | |
2880 | @@ -0,0 +1,78 @@ | |
2881 | +SET GLOBAL long_query_time=1; | |
2882 | +SET GLOBAL log_slow_rate_type='session'; | |
2883 | +SET GLOBAL log_slow_rate_limit=3; | |
2884 | +[log_start.inc] percona.slow_extended.log_slow_rate_limit | |
2885 | +SET SESSION query_exec_time=1.1; | |
2886 | +SET SESSION query_exec_id=1; | |
2887 | +SELECT 'connection_one'; | |
2888 | +connection_one | |
2889 | +connection_one | |
2890 | +SET SESSION query_exec_time=1.1; | |
2891 | +SET SESSION query_exec_id=2; | |
2892 | +SELECT 'connection_two'; | |
2893 | +connection_two | |
2894 | +connection_two | |
2895 | +SET SESSION query_exec_time=1.1; | |
2896 | +SET SESSION query_exec_id=3; | |
2897 | +SELECT 'connection_three'; | |
2898 | +connection_three | |
2899 | +connection_three | |
2900 | +SET SESSION query_exec_time=1.1; | |
2901 | +SET SESSION query_exec_id=4; | |
2902 | +SELECT 'connection_one'; | |
2903 | +connection_one | |
2904 | +connection_one | |
2905 | +SET SESSION query_exec_time=1.1; | |
2906 | +SET SESSION query_exec_id=5; | |
2907 | +SELECT 'connection_two'; | |
2908 | +connection_two | |
2909 | +connection_two | |
2910 | +SET SESSION query_exec_time=1.1; | |
2911 | +SET SESSION query_exec_id=6; | |
2912 | +SELECT 'connection_three'; | |
2913 | +connection_three | |
2914 | +connection_three | |
2915 | +[log_stop.inc] percona.slow_extended.log_slow_rate_limit | |
2916 | +[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: | |
2917 | +[log_grep.inc] sum: 2 | |
2918 | +[log_grep.inc] zero: 2 | |
2919 | +SET GLOBAL log_slow_rate_type='query'; | |
2920 | +SET GLOBAL log_slow_rate_limit=2; | |
2921 | +[log_start.inc] percona.slow_extended.log_slow_rate_limit | |
2922 | +SET SESSION query_exec_time=1.1; | |
2923 | +SET SESSION query_exec_id=1; | |
2924 | +SELECT 'connection_one'; | |
2925 | +connection_one | |
2926 | +connection_one | |
2927 | +SET SESSION query_exec_time=1.1; | |
2928 | +SET SESSION query_exec_id=2; | |
2929 | +SELECT 'connection_two'; | |
2930 | +connection_two | |
2931 | +connection_two | |
2932 | +SET SESSION query_exec_time=1.1; | |
2933 | +SET SESSION query_exec_id=3; | |
2934 | +SELECT 'connection_three'; | |
2935 | +connection_three | |
2936 | +connection_three | |
2937 | +SET SESSION query_exec_time=1.1; | |
2938 | +SET SESSION query_exec_id=4; | |
2939 | +SELECT 'connection_one'; | |
2940 | +connection_one | |
2941 | +connection_one | |
2942 | +SET SESSION query_exec_time=1.1; | |
2943 | +SET SESSION query_exec_id=5; | |
2944 | +SELECT 'connection_two'; | |
2945 | +connection_two | |
2946 | +connection_two | |
2947 | +SET SESSION query_exec_time=1.1; | |
2948 | +SET SESSION query_exec_id=6; | |
2949 | +SELECT 'connection_three'; | |
2950 | +connection_three | |
2951 | +connection_three | |
2952 | +[log_stop.inc] percona.slow_extended.log_slow_rate_limit | |
2953 | +[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern: | |
2954 | +[log_grep.inc] sum: 3 | |
2955 | +[log_grep.inc] zero: 0 | |
2956 | +SET GLOBAL long_query_time=default; | |
2957 | +SET GLOBAL log_slow_rate_type=default; | |
2958 | +SET GLOBAL log_slow_rate_limit=default; | |
2959 | --- /dev/null | |
2960 | +++ b/mysql-test/t/percona_slow_query_log_rate.test | |
2961 | @@ -0,0 +1,16 @@ | |
2962 | +--source include/have_debug.inc | |
2963 | +--let log_file=percona.slow_extended.log_slow_rate_limit | |
2964 | + | |
2965 | +SET GLOBAL long_query_time=1; | |
2966 | + | |
2967 | +SET GLOBAL log_slow_rate_type='session'; | |
2968 | +SET GLOBAL log_slow_rate_limit=3; | |
2969 | +--source include/percona_slow_query_log_rate.inc | |
2970 | + | |
2971 | +SET GLOBAL log_slow_rate_type='query'; | |
2972 | +SET GLOBAL log_slow_rate_limit=2; | |
2973 | +--source include/percona_slow_query_log_rate.inc | |
2974 | + | |
2975 | +SET GLOBAL long_query_time=default; | |
2976 | +SET GLOBAL log_slow_rate_type=default; | |
2977 | +SET GLOBAL log_slow_rate_limit=default; | |
2978 | --- /dev/null | |
2979 | +++ b/mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test | |
2980 | @@ -0,0 +1 @@ | |
2981 | +SELECT @@global.log_slow_rate_limit; | |
2982 | --- /dev/null | |
2983 | +++ b/mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result | |
2984 | @@ -0,0 +1,3 @@ | |
2985 | +SELECT @@global.log_slow_rate_limit; | |
2986 | +@@global.log_slow_rate_limit | |
2987 | +1 | |
2988 | --- /dev/null | |
2989 | +++ b/mysql-test/suite/sys_vars/t/log_slow_rate_type_basic.test | |
2990 | @@ -0,0 +1 @@ | |
2991 | +SELECT @@global.log_slow_rate_type; | |
2992 | --- /dev/null | |
2993 | +++ b/mysql-test/suite/sys_vars/r/log_slow_rate_type_basic.result | |
2994 | @@ -0,0 +1,3 @@ | |
2995 | +SELECT @@global.log_slow_rate_type; | |
2996 | +@@global.log_slow_rate_type | |
2997 | +session | |
2998 | --- /dev/null | |
2999 | +++ b/mysql-test/include/percona_slow_query_log_rate.inc | |
3000 | @@ -0,0 +1,42 @@ | |
3001 | +--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST; | |
3002 | +--connection default | |
3003 | +--source include/log_start.inc | |
3004 | + | |
3005 | +--connect (connection_one,localhost,root,,) | |
3006 | +--connect (connection_two,localhost,root,,) | |
3007 | +--connect (connection_three,localhost,root,,) | |
3008 | + | |
3009 | +--let i=2 | |
3010 | +--let k=1 | |
3011 | + | |
3012 | +while($i) | |
3013 | +{ | |
3014 | +--connection connection_one | |
3015 | +SET SESSION query_exec_time=1.1; | |
3016 | +eval SET SESSION query_exec_id=$k; | |
3017 | +inc $k; | |
3018 | +SELECT 'connection_one'; | |
3019 | + | |
3020 | +--connection connection_two | |
3021 | +SET SESSION query_exec_time=1.1; | |
3022 | +eval SET SESSION query_exec_id=$k; | |
3023 | +inc $k; | |
3024 | +SELECT 'connection_two'; | |
3025 | + | |
3026 | +--connection connection_three | |
3027 | +SET SESSION query_exec_time=1.1; | |
3028 | +eval SET SESSION query_exec_id=$k; | |
3029 | +inc $k; | |
3030 | +SELECT 'connection_three'; | |
3031 | + | |
3032 | +dec $i; | |
3033 | +} | |
3034 | + | |
3035 | +--connection default | |
3036 | +--disconnect connection_one | |
3037 | +--disconnect connection_two | |
3038 | +--disconnect connection_three | |
3039 | +--source include/wait_condition.inc | |
3040 | +--source include/log_stop.inc | |
3041 | +--let log_slow_rate_test=1 | |
3042 | +--source include/log_grep.inc | |
3043 | --- /dev/null | |
3044 | +++ b/mysql-test/suite/sys_vars/r/query_exec_id_basic.result | |
3045 | @@ -0,0 +1,2 @@ | |
3046 | +SET GLOBAL query_exec_id=default; | |
3047 | +SET SESSION query_exec_id=default; | |
3048 | --- /dev/null | |
3049 | +++ b/mysql-test/suite/sys_vars/t/query_exec_id_basic.test | |
3050 | @@ -0,0 +1,4 @@ | |
3051 | +--source include/have_debug.inc | |
3052 | + | |
3053 | +SET GLOBAL query_exec_id=default; | |
3054 | +SET SESSION query_exec_id=default; |