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