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