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