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