]> 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
- todo
[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!
8diff -ruN a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp
a9ee80b9
ER		 9--- a/include/mysql/plugin_audit.h.pp 2011-01-20 00:37:08.000000000 +0200
10+++ b/include/mysql/plugin_audit.h.pp 2011-02-21 22:57:48.816765777 +0200
b4e1fa2c
AM		 11@@ -178,6 +178,16 @@
12 char *thd_security_context(void* thd, char *buffer, unsigned int length,
13 unsigned int max_query_len);
14 void thd_inc_row_count(void* thd);
15+void increment_thd_innodb_stats(void* thd,
16+ unsigned long long trx_id,
17+ long io_reads,
18+ long long io_read,
19+ long io_reads_wait_timer,
20+ long lock_que_wait_timer,
21+ long que_wait_timer,
22+ long page_access);
23+unsigned long thd_log_slow_verbosity(const void* thd);
24+int thd_opt_slow_log();
25 int mysql_tmpfile(const char *prefix);
26 int thd_killed(const void* thd);
27 unsigned long thd_get_thread_id(const void* thd);
28diff -ruN a/include/mysql/plugin_auth.h.pp b/include/mysql/plugin_auth.h.pp
a9ee80b9
ER		 29--- a/include/mysql/plugin_auth.h.pp 2011-01-20 00:37:08.000000000 +0200
30+++ b/include/mysql/plugin_auth.h.pp 2011-02-21 22:57:48.816765777 +0200
b4e1fa2c
AM		 31@@ -178,6 +178,16 @@
32 char *thd_security_context(void* thd, char *buffer, unsigned int length,
33 unsigned int max_query_len);
34 void thd_inc_row_count(void* thd);
35+void increment_thd_innodb_stats(void* thd,
36+ unsigned long long trx_id,
37+ long io_reads,
38+ long long io_read,
39+ long io_reads_wait_timer,
40+ long lock_que_wait_timer,
41+ long que_wait_timer,
42+ long page_access);
43+unsigned long thd_log_slow_verbosity(const void* thd);
44+int thd_opt_slow_log();
45 int mysql_tmpfile(const char *prefix);
46 int thd_killed(const void* thd);
47 unsigned long thd_get_thread_id(const void* thd);
48diff -ruN a/include/mysql/plugin_ftparser.h.pp b/include/mysql/plugin_ftparser.h.pp
a9ee80b9
ER		 49--- a/include/mysql/plugin_ftparser.h.pp 2011-01-20 00:37:08.000000000 +0200
50+++ b/include/mysql/plugin_ftparser.h.pp 2011-02-21 22:57:48.816765777 +0200
b4e1fa2c
AM		 51@@ -131,6 +131,16 @@
52 char *thd_security_context(void* thd, char *buffer, unsigned int length,
53 unsigned int max_query_len);
54 void thd_inc_row_count(void* thd);
55+void increment_thd_innodb_stats(void* thd,
56+ unsigned long long trx_id,
57+ long io_reads,
58+ long long io_read,
59+ long io_reads_wait_timer,
60+ long lock_que_wait_timer,
61+ long que_wait_timer,
62+ long page_access);
63+unsigned long thd_log_slow_verbosity(const void* thd);
64+int thd_opt_slow_log();
65 int mysql_tmpfile(const char *prefix);
66 int thd_killed(const void* thd);
67 unsigned long thd_get_thread_id(const void* thd);
68diff -ruN a/include/mysql/plugin.h b/include/mysql/plugin.h
a9ee80b9
ER		 69--- a/include/mysql/plugin.h 2011-01-20 00:37:08.000000000 +0200
70+++ b/include/mysql/plugin.h 2011-02-21 22:57:48.817765600 +0200
b4e1fa2c
AM		 71@@ -536,6 +536,17 @@
72 /* Increments the row counter, see THD::row_count */
73 void thd_inc_row_count(MYSQL_THD thd);
74
75+void increment_thd_innodb_stats(MYSQL_THD thd,
76+ unsigned long long trx_id,
77+ long io_reads,
78+ long long io_read,
79+ long io_reads_wait_timer,
80+ long lock_que_wait_timer,
81+ long que_wait_timer,
82+ long page_access);
83+unsigned long thd_log_slow_verbosity(const MYSQL_THD thd);
84+int thd_opt_slow_log();
85+#define EXTENDED_SLOWLOG
86 /**
87 Create a temporary file.
88
89diff -ruN a/patch_info/slow_extended.info b/patch_info/slow_extended.info
90--- a/patch_info/slow_extended.info 1970-01-01 03:00:00.000000000 +0300
a9ee80b9 91+++ b/patch_info/slow_extended.info 2011-02-21 22:57:48.818765423 +0200
b4e1fa2c
AM		 92@@ -0,0 +1,25 @@
93+File=slow_extended.patch
94+Name=Extended statistics in slow.log (not InnoDB part)
95+Version=1.3
96+Author=Percona <info@percona.com>
97+License=GPL
98+Comment=
99+Changelog
100+2008-11-26
101+YK: Fix inefficient determination of trx, Make not to call useless gettimeofday when don't use slow log. Make log_slow_queries dynamic (bool).
102+
103+2008-11-07
104+VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
105+
106+2008-11
107+Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
108+
109+2010-07
110+1) Fix overflow of query time and lock time (Bug 600360) (slow_extended_fix_overflow.patch merged)
111+2) Control global slow feature merged (control_global_slow.patch merged)
112+3) Microseconds in slow query log merged (microseconds_in_slow_query_log.patch merged)
113+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)
114+5) Fix innodb_stats on replication (Bug 600684)
115+6) Change variable types (system/command-line)
a9ee80b9 116+2011-01
b4e1fa2c 117+Patch profiling_slow.patch was merged
a9ee80b9
ER		 118+2011-02
119+Rename variables:
120+LOG_SLOW_TIMESTAMP_EVERY => SLOW_QUERY_LOG_TIMESTAMP_ALWAYS
121+LOG_WARNINGS_SILENCE => LOG_WARNINGS_SUPPRESS
122+SLOW_QUERY_LOG_MICROSECONDS_TIMESTAMP => SLOW_QUERY_LOG_TIMESTAMP_PRECISION=(SECOND,MICROSECOND)
123+USE_GLOBAL_LOG_SLOW_CONTROL => SLOW_QUERY_LOG_USE_GLOBAL_CONTROL
b4e1fa2c 124diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh
a9ee80b9
ER		 125--- a/scripts/mysqldumpslow.sh 2011-01-20 00:37:09.000000000 +0200
126+++ b/scripts/mysqldumpslow.sh 2011-02-21 22:57:48.818765423 +0200
d8778560 127@@ -101,8 +101,8 @@
b4e1fa2c
AM		 128 s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
129 my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
130
131- s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
132- my ($t, $l, $r) = ($1, $2, $3);
133+ s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//;
134+ my ($t, $l, $r) = ($1, $3, $5);
135 $t -= $l unless $opt{l};
136
137 # remove fluff that mysqld writes to log when it (re)starts:
138diff -ruN a/sql/event_scheduler.cc b/sql/event_scheduler.cc
a9ee80b9
ER		 139--- a/sql/event_scheduler.cc 2011-01-20 00:37:09.000000000 +0200
140+++ b/sql/event_scheduler.cc 2011-02-21 22:57:48.819765246 +0200
b4e1fa2c
AM		 141@@ -195,6 +195,7 @@
142 thd->client_capabilities|= CLIENT_MULTI_RESULTS;
143 mysql_mutex_lock(&LOCK_thread_count);
144 thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
145+ thd->write_to_slow_log = TRUE;
146 mysql_mutex_unlock(&LOCK_thread_count);
147
148 /*
149diff -ruN a/sql/filesort.cc b/sql/filesort.cc
a9ee80b9
ER		 150--- a/sql/filesort.cc 2011-01-20 00:37:09.000000000 +0200
151+++ b/sql/filesort.cc 2011-02-21 22:57:48.821764892 +0200
d8778560 152@@ -193,6 +193,7 @@
b4e1fa2c
AM		 153 {
154 status_var_increment(thd->status_var.filesort_scan_count);
155 }
156+ thd->query_plan_flags|= QPLAN_FILESORT;
157 #ifdef CAN_TRUST_RANGE
158 if (select && select->quick && select->quick->records > 0L)
159 {
d8778560 160@@ -258,6 +259,7 @@
b4e1fa2c
AM		 161 }
162 else
163 {
164+ thd->query_plan_flags|= QPLAN_FILESORT_DISK;
165 if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
166 {
167 my_free(table_sort.buffpek);
d8778560 168@@ -1197,6 +1199,7 @@
b4e1fa2c
AM		 169 DBUG_ENTER("merge_buffers");
170
171 status_var_increment(current_thd->status_var.filesort_merge_passes);
172+ current_thd->query_plan_fsort_passes++;
173 if (param->not_killable)
174 {
175 killed= &not_killable;
176diff -ruN a/sql/log.cc b/sql/log.cc
a9ee80b9
ER		 177--- a/sql/log.cc 2011-01-20 00:37:09.000000000 +0200
178+++ b/sql/log.cc 2011-02-21 23:14:33.973714581 +0200
d8778560 179@@ -715,11 +715,13 @@
b4e1fa2c
AM		 180 */
181
182 bool Log_to_csv_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+ time_t current_time= my_time_possible_from_micro(current_utime);
190+
191 TABLE_LIST table_list;
192 TABLE *table;
193 bool result= TRUE;
d8778560 194@@ -935,14 +937,14 @@
b4e1fa2c
AM		 195 /** Wrapper around MYSQL_LOG::write() for slow log. */
196
197 bool Log_to_file_event_handler::
198- log_slow(THD *thd, time_t current_time, time_t query_start_arg,
199+ log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
200 const char *user_host, uint user_host_len,
201 ulonglong query_utime, ulonglong lock_utime, bool is_command,
202 const char *sql_text, uint sql_text_len)
203 {
204 Silence_log_table_errors error_handler;
205 thd->push_internal_handler(&error_handler);
206- bool retval= mysql_slow_log.write(thd, current_time, query_start_arg,
207+ bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg,
208 user_host, user_host_len,
209 query_utime, lock_utime, is_command,
210 sql_text, sql_text_len);
d8778560 211@@ -1216,7 +1218,7 @@
b4e1fa2c
AM		 212 /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
213 user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
214 sctx->priv_user ? sctx->priv_user : "", "[",
215- sctx->user ? sctx->user : "", "] @ ",
216+ sctx->user ? sctx->user : (thd->slave_thread ? "SQL_SLAVE" : ""), "] @ ",
217 sctx->host ? sctx->host : "", " [",
218 sctx->ip ? sctx->ip : "", "]", NullS) -
219 user_host_buff);
d8778560 220@@ -1224,8 +1226,22 @@
b4e1fa2c
AM		 221 current_time= my_time_possible_from_micro(current_utime);
222 if (thd->start_utime)
223 {
224- query_utime= (current_utime - thd->start_utime);
225- lock_utime= (thd->utime_after_lock - thd->start_utime);
226+ if(current_utime < thd->start_utime)
227+ {
228+ query_utime= 0;
229+ }
230+ else
231+ {
232+ query_utime= (current_utime - thd->start_utime);
233+ }
234+ if(thd->utime_after_lock < thd->start_utime)
235+ {
236+ lock_utime= 0;
237+ }
238+ else
239+ {
240+ lock_utime= (thd->utime_after_lock - thd->start_utime);
241+ }
242 }
243 else
244 {
d8778560 245@@ -1239,8 +1255,20 @@
b4e1fa2c
AM		 246 query_length= command_name[thd->command].length;
247 }
248
249+ if (!query_length)
250+ {
251+ thd->sent_row_count= thd->examined_row_count= 0;
252+ thd->sent_row_count= 0;
253+ thd->bytes_sent_old= thd->status_var.bytes_sent;
254+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
255+ thd->tmp_tables_size= 0;
256+ thd->innodb_was_used= FALSE;
257+ thd->query_plan_flags= QPLAN_NONE;
258+ thd->query_plan_fsort_passes= 0;
259+ }
260+
261 for (current_handler= slow_log_handler_list; *current_handler ;)
262- error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
263+ error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
264 user_host_buff, user_host_len,
265 query_utime, lock_utime, is_command,
266 query, query_length) || error;
d8778560 267@@ -2656,12 +2684,13 @@
b4e1fa2c
AM		 268 TRUE - error occured
269 */
270
271-bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
272+bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
273 time_t query_start_arg, const char *user_host,
274 uint user_host_len, ulonglong query_utime,
275 ulonglong lock_utime, bool is_command,
276 const char *sql_text, uint sql_text_len)
277 {
278+ time_t current_time= my_time_possible_from_micro(current_utime);
279 bool error= 0;
280 DBUG_ENTER("MYSQL_QUERY_LOG::write");
281
d8778560 282@@ -2683,17 +2712,28 @@
b4e1fa2c
AM		 283
284 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
285 {
286- if (current_time != last_time)
a9ee80b9 287+ if (opt_slow_query_log_timestamp_always || current_time != last_time)
b4e1fa2c
AM		 288 {
289 last_time= current_time;
290 struct tm start;
291 localtime_r(&current_time, &start);
292-
293- buff_len= my_snprintf(buff, sizeof buff,
294- "# Time: %02d%02d%02d %2d:%02d:%02d\n",
295- start.tm_year % 100, start.tm_mon + 1,
296- start.tm_mday, start.tm_hour,
297- start.tm_min, start.tm_sec);
a9ee80b9 298+ if(opt_slow_query_log_timestamp_precision & SLOG_MICROSECOND)
b4e1fa2c
AM		 299+ {
300+ ulonglong microsecond = current_utime % (1000 * 1000);
301+ buff_len= snprintf(buff, sizeof buff,
302+ "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
303+ start.tm_year % 100, start.tm_mon + 1,
304+ start.tm_mday, start.tm_hour,
305+ start.tm_min, start.tm_sec,microsecond);
306+ }
307+ else
308+ {
309+ buff_len= my_snprintf(buff, sizeof buff,
310+ "# Time: %02d%02d%02d %2d:%02d:%02d\n",
311+ start.tm_year % 100, start.tm_mon + 1,
312+ start.tm_mday, start.tm_hour,
313+ start.tm_min, start.tm_sec);
314+ }
315
316 /* Note that my_b_write() assumes it knows the length for this */
317 if (my_b_write(&log_file, (uchar*) buff, buff_len))
a9ee80b9 318@@ -2711,12 +2752,69 @@
b4e1fa2c
AM		 319 sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
320 sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
321 if (my_b_printf(&log_file,
322- "# Query_time: %s Lock_time: %s"
323- " Rows_sent: %lu Rows_examined: %lu\n",
324+ "# Thread_id: %lu Schema: %s Last_errno: %u Killed: %u\n" \
325+ "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n"
326+ "# Bytes_sent: %lu Tmp_tables: %lu Tmp_disk_tables: %lu Tmp_table_sizes: %lu\n",
327+ (ulong) thd->thread_id, (thd->db ? thd->db : ""),
328+ thd->last_errno, (uint) thd->killed,
329 query_time_buff, lock_time_buff,
330 (ulong) thd->sent_row_count,
331- (ulong) thd->examined_row_count) == (uint) -1)
332+ (ulong) thd->examined_row_count,
333+ ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
334+ (ulong) thd->sent_row_count,
335+ (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
336+ (ulong) thd->tmp_tables_used,
337+ (ulong) thd->tmp_tables_disk_used,
338+ (ulong) thd->tmp_tables_size) == (uint) -1)
339 tmp_errno= errno;
340+
341+#if defined(ENABLED_PROFILING)
342+ thd->profiling.print_current(&log_file);
343+#endif
344+ if (thd->innodb_was_used)
345+ {
346+ char buf[20];
347+ snprintf(buf, 20, "%llX", thd->innodb_trx_id);
348+ if (my_b_printf(&log_file,
349+ "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
350+ tmp_errno=errno;
351+ }
352+ if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
353+ my_b_printf(&log_file,
354+ "# QC_Hit: %s Full_scan: %s Full_join: %s Tmp_table: %s Tmp_table_on_disk: %s\n" \
355+ "# Filesort: %s Filesort_on_disk: %s Merge_passes: %lu\n",
356+ ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
357+ ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
358+ ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
359+ ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
360+ ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
361+ ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
362+ ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
363+ thd->query_plan_fsort_passes) == (uint) -1)
364+ tmp_errno=errno;
365+ if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
366+ {
367+ char buf[3][20];
368+ snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
369+ snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
370+ snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
371+ if (my_b_printf(&log_file,
372+ "# InnoDB_IO_r_ops: %lu InnoDB_IO_r_bytes: %lu InnoDB_IO_r_wait: %s\n" \
373+ "# InnoDB_rec_lock_wait: %s InnoDB_queue_wait: %s\n" \
374+ "# InnoDB_pages_distinct: %lu\n",
375+ (ulong) thd->innodb_io_reads,
376+ (ulong) thd->innodb_io_read,
377+ buf[0], buf[1], buf[2],
378+ (ulong) thd->innodb_page_access) == (uint) -1)
379+ tmp_errno=errno;
380+ }
381+ else
382+ {
383+ if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
384+ my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
385+ tmp_errno=errno;
386+ }
387+
388 if (thd->db && strcmp(thd->db, db))
389 { // Database changed
390 if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
391diff -ruN a/sql/log.h b/sql/log.h
a9ee80b9
ER		 392--- a/sql/log.h 2011-01-20 00:37:09.000000000 +0200
393+++ b/sql/log.h 2011-02-21 22:57:48.826764006 +0200
b4e1fa2c
AM		 394@@ -242,7 +242,7 @@
395 uint user_host_len, int thread_id,
396 const char *command_type, uint command_type_len,
397 const char *sql_text, uint sql_text_len);
398- bool write(THD *thd, time_t current_time, time_t query_start_arg,
399+ bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
400 const char *user_host, uint user_host_len,
401 ulonglong query_utime, ulonglong lock_utime, bool is_command,
402 const char *sql_text, uint sql_text_len);
403@@ -492,7 +492,7 @@
404 virtual bool init()= 0;
405 virtual void cleanup()= 0;
406
407- virtual bool log_slow(THD *thd, time_t current_time,
408+ virtual bool log_slow(THD *thd, ulonglong current_time,
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,
412@@ -521,7 +521,7 @@
413 virtual bool init();
414 virtual void cleanup();
415
416- virtual bool log_slow(THD *thd, time_t current_time,
417+ virtual bool log_slow(THD *thd, ulonglong current_utime,
418 time_t query_start_arg, const char *user_host,
419 uint user_host_len, ulonglong query_utime,
420 ulonglong lock_utime, bool is_command,
421@@ -553,7 +553,7 @@
422 virtual bool init();
423 virtual void cleanup();
424
425- virtual bool log_slow(THD *thd, time_t current_time,
426+ virtual bool log_slow(THD *thd, ulonglong current_utime,
427 time_t query_start_arg, const char *user_host,
428 uint user_host_len, ulonglong query_utime,
429 ulonglong lock_utime, bool is_command,
430diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
a9ee80b9
ER		 431--- a/sql/mysqld.cc 2011-02-21 22:57:24.442081625 +0200
432+++ b/sql/mysqld.cc 2011-02-21 22:59:30.845699981 +0200
b4e1fa2c
AM		 433@@ -418,6 +418,10 @@
434 char* opt_secure_file_priv;
435 my_bool opt_log_slow_admin_statements= 0;
436 my_bool opt_log_slow_slave_statements= 0;
437+my_bool opt_log_slow_sp_statements= 0;
a9ee80b9
ER		 438+my_bool opt_slow_query_log_timestamp_always= 0;
439+ulonglong opt_slow_query_log_use_global_control= 0;
440+ulonglong opt_slow_query_log_timestamp_precision= 0;
b4e1fa2c
AM		 441 my_bool lower_case_file_system= 0;
442 my_bool opt_large_pages= 0;
443 my_bool opt_super_large_pages= 0;
d8778560 444@@ -5784,10 +5788,10 @@
b4e1fa2c
AM		 445 "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
446 "the slow log if it is open.", &opt_log_slow_admin_statements,
447 &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
448- {"log-slow-slave-statements", 0,
449+ /*{"log-slow-slave-statements", 0,
450 "Log slow statements executed by slave thread to the slow log if it is open.",
451 &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
452- 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
453+ 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
454 {"log-slow-queries", OPT_SLOW_QUERY_LOG,
455 "Log slow queries to a table or log file. Defaults logging to table "
456 "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
d8778560 457@@ -7179,6 +7183,10 @@
b4e1fa2c
AM		 458
459 C_MODE_END
460
461+/* defined in sys_vars.cc */
462+extern void init_log_slow_verbosity();
a9ee80b9 463+extern void init_slow_query_log_use_global_control();
b4e1fa2c
AM		 464+
465 /**
466 Get server options from the command line,
467 and perform related server initializations.
d8778560 468@@ -7318,6 +7326,8 @@
b4e1fa2c
AM		 469 global_system_variables.long_query_time= (ulonglong)
470 (global_system_variables.long_query_time_double * 1e6);
471
472+ init_log_slow_verbosity();
a9ee80b9 473+ init_slow_query_log_use_global_control();
b4e1fa2c
AM		 474 if (opt_short_log_format)
475 opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
476
477diff -ruN a/sql/mysqld.h b/sql/mysqld.h
a9ee80b9
ER		 478--- a/sql/mysqld.h 2011-02-21 22:57:24.398089415 +0200
479+++ b/sql/mysqld.h 2011-02-21 23:01:50.079045873 +0200
b4e1fa2c
AM		 480@@ -116,6 +116,10 @@
481 extern char* opt_secure_backup_file_priv;
482 extern size_t opt_secure_backup_file_priv_len;
483 extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
484+extern my_bool opt_log_slow_sp_statements;
a9ee80b9
ER		 485+extern my_bool opt_slow_query_log_timestamp_always;
486+extern ulonglong opt_slow_query_log_use_global_control;
487+extern ulonglong opt_slow_query_log_timestamp_precision;
b4e1fa2c
AM		 488 extern my_bool sp_automatic_privileges, opt_noacl;
489 extern my_bool opt_old_style_user_limits, trust_function_creators;
490 extern uint opt_crash_binlog_innodb;
491diff -ruN a/sql/slave.cc b/sql/slave.cc
a9ee80b9
ER		 492--- a/sql/slave.cc 2011-01-20 00:37:09.000000000 +0200
493+++ b/sql/slave.cc 2011-02-21 22:57:48.834762590 +0200
d8778560 494@@ -2038,6 +2038,7 @@
b4e1fa2c
AM		 495 + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */
496 thd->slave_thread = 1;
497 thd->enable_slow_log= opt_log_slow_slave_statements;
498+ thd->write_to_slow_log= opt_log_slow_slave_statements;
499 set_slave_thread_options(thd);
500 thd->client_capabilities = CLIENT_LOCAL_FILES;
501 mysql_mutex_lock(&LOCK_thread_count);
502diff -ruN a/sql/sp_head.cc b/sql/sp_head.cc
a9ee80b9
ER		 503--- a/sql/sp_head.cc 2011-01-20 00:37:09.000000000 +0200
504+++ b/sql/sp_head.cc 2011-02-21 22:57:48.837762059 +0200
b4e1fa2c
AM		 505@@ -2151,7 +2151,7 @@
506 DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length,
507 m_name.str));
508 }
509- if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
510+ if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
511 {
512 DBUG_PRINT("info", ("Disabling slow log for the execution"));
513 save_enable_slow_log= true;
514diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc
a9ee80b9
ER		 515--- a/sql/sql_cache.cc 2011-01-20 00:37:09.000000000 +0200
516+++ b/sql/sql_cache.cc 2011-02-21 22:57:48.840761528 +0200
b4e1fa2c
AM		 517@@ -1756,6 +1756,7 @@
518 response, we can't handle it anyway.
519 */
520 (void) trans_commit_stmt(thd);
521+ thd->query_plan_flags|= QPLAN_QC;
522 if (!thd->stmt_da->is_set())
523 thd->stmt_da->disable_status();
524
525@@ -1766,6 +1767,7 @@
526 err_unlock:
527 unlock();
528 err:
529+ thd->query_plan_flags|= QPLAN_QC_NO;
530 MYSQL_QUERY_CACHE_MISS(thd->query());
531 DBUG_RETURN(0); // Query was not cached
532 }
533diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc
a9ee80b9
ER		 534--- a/sql/sql_class.cc 2011-01-20 00:37:09.000000000 +0200
535+++ b/sql/sql_class.cc 2011-02-21 22:57:48.843760997 +0200
b4e1fa2c
AM		 536@@ -367,6 +367,37 @@
537 thd->warning_info->inc_current_row_for_warning();
538 }
539
540+extern "C"
541+void increment_thd_innodb_stats(THD* thd,
542+ unsigned long long trx_id,
543+ long io_reads,
544+ long long io_read,
545+ long io_reads_wait_timer,
546+ long lock_que_wait_timer,
547+ long que_wait_timer,
548+ long page_access)
549+{
550+ thd->innodb_was_used = TRUE;
551+ thd->innodb_trx_id = trx_id;
552+ thd->innodb_io_reads += io_reads;
553+ thd->innodb_io_read += io_read;
554+ thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
555+ thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
556+ thd->innodb_innodb_que_wait_timer += que_wait_timer;
557+ thd->innodb_page_access += page_access;
558+}
559+
560+extern "C"
561+unsigned long thd_log_slow_verbosity(const THD *thd)
562+{
563+ return (unsigned long) thd->variables.log_slow_verbosity;
564+}
565+
566+extern "C"
567+int thd_opt_slow_log()
568+{
569+ return (int) opt_slow_log;
570+}
571
572 /**
573 Dumps a text description of a thread, its security context
574@@ -661,6 +692,7 @@
575 *cond_hdl= NULL;
576 return FALSE;
577 }
578+ last_errno= sql_errno;
579
580 for (Internal_error_handler *error_handler= m_internal_handler;
581 error_handler;
d8778560 582@@ -3389,6 +3421,12 @@
b4e1fa2c
AM		 583 first_successful_insert_id_in_prev_stmt;
584 backup->first_successful_insert_id_in_cur_stmt=
585 first_successful_insert_id_in_cur_stmt;
586+ backup->innodb_io_reads= innodb_io_reads;
587+ backup->innodb_io_read= innodb_io_read;
588+ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
589+ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
590+ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
591+ backup->innodb_page_access= innodb_page_access;
592
593 if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
594 !is_current_stmt_binlog_format_row())
d8778560 595@@ -3409,6 +3447,14 @@
b4e1fa2c
AM		 596 cuted_fields= 0;
597 transaction.savepoints= 0;
598 first_successful_insert_id_in_cur_stmt= 0;
599+ last_errno= 0;
600+ innodb_trx_id= 0;
601+ innodb_io_reads= 0;
602+ innodb_io_read= 0;
603+ innodb_io_reads_wait_timer= 0;
604+ innodb_lock_que_wait_timer= 0;
605+ innodb_innodb_que_wait_timer= 0;
606+ innodb_page_access= 0;
607 }
608
609
d8778560 610@@ -3471,6 +3517,12 @@
b4e1fa2c
AM		 611 */
612 examined_row_count+= backup->examined_row_count;
613 cuted_fields+= backup->cuted_fields;
614+ innodb_io_reads+= backup->innodb_io_reads;
615+ innodb_io_read+= backup->innodb_io_read;
616+ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
617+ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
618+ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
619+ innodb_page_access+= backup->innodb_page_access;
620 DBUG_VOID_RETURN;
621 }
622
623diff -ruN a/sql/sql_class.h b/sql/sql_class.h
a9ee80b9
ER		 624--- a/sql/sql_class.h 2011-02-21 22:57:24.423084989 +0200
625+++ b/sql/sql_class.h 2011-02-21 23:06:24.869371276 +0200
626@@ -60,6 +60,33 @@
b4e1fa2c
AM		 627 enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
628 enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
629 DELAY_KEY_WRITE_ALL };
a9ee80b9
ER		 630+enum enum_slow_query_log_use_global_control {
631+ SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT
632+ , SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME
633+ , SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL
634+};
b4e1fa2c
AM		 635+enum enum_log_slow_verbosity {
636+ SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB,
637+ SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
638+ SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
639+};
a9ee80b9
ER		 640+enum enum_slow_query_log_timestamp_precision {
641+ SLOG_SECOND, SLOG_MICROSECOND
642+};
b4e1fa2c
AM		 643+#define QPLAN_NONE 0
644+#define QPLAN_QC 1 << 0
645+#define QPLAN_QC_NO 1 << 1
646+#define QPLAN_FULL_SCAN 1 << 2
647+#define QPLAN_FULL_JOIN 1 << 3
648+#define QPLAN_TMP_TABLE 1 << 4
649+#define QPLAN_TMP_DISK 1 << 5
650+#define QPLAN_FILESORT 1 << 6
651+#define QPLAN_FILESORT_DISK 1 << 7
652+enum enum_log_slow_filter {
653+ SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
654+ SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
655+ SLOG_F_FILESORT_DISK
656+};
657 enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
658 SLAVE_EXEC_MODE_IDEMPOTENT,
659 SLAVE_EXEC_MODE_LAST_BIT};
a9ee80b9 660@@ -508,6 +535,17 @@
b4e1fa2c
AM		 661
662 my_bool sysdate_is_now;
663
664+ ulong log_slow_rate_limit;
665+ ulonglong log_slow_filter;
666+ ulonglong log_slow_verbosity;
667+
668+ ulong innodb_io_reads;
669+ ulonglong innodb_io_read;
670+ ulong innodb_io_reads_wait_timer;
671+ ulong innodb_lock_que_wait_timer;
672+ ulong innodb_innodb_que_wait_timer;
673+ ulong innodb_page_access;
674+
675 double long_query_time_double;
676
677 } SV;
a9ee80b9 678@@ -1140,6 +1178,14 @@
b4e1fa2c
AM		 679 uint in_sub_stmt;
680 bool enable_slow_log;
681 bool last_insert_id_used;
682+
683+ ulong innodb_io_reads;
684+ ulonglong innodb_io_read;
685+ ulong innodb_io_reads_wait_timer;
686+ ulong innodb_lock_que_wait_timer;
687+ ulong innodb_innodb_que_wait_timer;
688+ ulong innodb_page_access;
689+
690 SAVEPOINT *savepoints;
691 enum enum_check_fields count_cuted_fields;
692 };
a9ee80b9 693@@ -1575,6 +1621,26 @@
b4e1fa2c
AM		 694 thr_lock_type update_lock_default;
695 Delayed_insert *di;
696
697+ bool write_to_slow_log;
698+
699+ ulonglong bytes_sent_old;
700+ ulong tmp_tables_used;
701+ ulong tmp_tables_disk_used;
702+ ulonglong tmp_tables_size;
703+ bool innodb_was_used;
704+ ulonglong innodb_trx_id;
705+ ulong innodb_io_reads;
706+ ulonglong innodb_io_read;
707+ ulong innodb_io_reads_wait_timer;
708+ ulong innodb_lock_que_wait_timer;
709+ ulong innodb_innodb_que_wait_timer;
710+ ulong innodb_page_access;
711+
712+ ulong query_plan_flags;
713+ ulong query_plan_fsort_passes;
714+
715+ uint last_errno;
716+
717 /* <> 0 if we are inside of trigger or stored function. */
718 uint in_sub_stmt;
719
720diff -ruN a/sql/sql_connect.cc b/sql/sql_connect.cc
a9ee80b9
ER		 721--- a/sql/sql_connect.cc 2011-01-20 00:37:09.000000000 +0200
722+++ b/sql/sql_connect.cc 2011-02-21 22:57:48.848760112 +0200
d8778560 723@@ -741,6 +741,15 @@
b4e1fa2c
AM		 724
725 prepare_new_connection_state(thd);
726
727+ /*
728+ If rate limiting of slow log writes is enabled, decide whether to log this
729+ new thread's queries or not. Uses extremely simple algorithm. :)
730+ */
731+ thd->write_to_slow_log= FALSE;
732+ if (thd->variables.log_slow_rate_limit <= 1 ||
733+ (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
734+ thd->write_to_slow_log= TRUE;
735+
736 while (!net->error && net->vio != 0 &&
737 !(thd->killed == THD::KILL_CONNECTION))
738 {
739diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc
a9ee80b9
ER		 740--- a/sql/sql_parse.cc 2011-02-21 22:57:24.451080031 +0200
741+++ b/sql/sql_parse.cc 2011-02-21 22:57:48.852759404 +0200
d8778560 742@@ -1431,7 +1431,6 @@
b4e1fa2c
AM		 743 DBUG_RETURN(error);
744 }
745
746-
747 void log_slow_statement(THD *thd)
748 {
749 DBUG_ENTER("log_slow_statement");
d8778560 750@@ -1444,6 +1443,42 @@
b4e1fa2c
AM		 751 if (unlikely(thd->in_sub_stmt))
752 DBUG_VOID_RETURN; // Don't set time for sub stmt
753
754+ /* Follow the slow log filter configuration. */
755+ if (thd->variables.log_slow_filter != 0 &&
756+ (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
757+ ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
758+ (thd->query_plan_flags & QPLAN_QC))))
759+ DBUG_VOID_RETURN;
760+
761+ /*
762+ Low long_query_time value most likely means user is debugging stuff and even
763+ though some thread's queries are not supposed to be logged b/c of the rate
764+ limit, if one of them takes long enough (>= 1 second) it will be sensible
765+ to make an exception and write to slow log anyway.
766+ */
767+
768+ ulonglong end_utime_of_query= thd->current_utime();
769+#define USE_GLOBAL_UPDATE(variable_name,enum_value_name) \
a9ee80b9 770+ if (opt_slow_query_log_use_global_control & (ULL(1) << enum_value_name)) \
b4e1fa2c
AM		 771+ { \
772+ thd->variables. variable_name= \
773+ global_system_variables. variable_name; \
774+ }
775+ USE_GLOBAL_UPDATE(log_slow_filter,SLOG_UG_LOG_SLOW_FILTER);
776+ USE_GLOBAL_UPDATE(log_slow_rate_limit,SLOG_UG_LOG_SLOW_RATE_LIMIT);
777+ USE_GLOBAL_UPDATE(log_slow_verbosity,SLOG_UG_LOG_SLOW_VERBOSITY);
778+ USE_GLOBAL_UPDATE(long_query_time,SLOG_UG_LONG_QUERY_TIME);
779+ USE_GLOBAL_UPDATE(long_query_time_double,SLOG_UG_LONG_QUERY_TIME);
780+ USE_GLOBAL_UPDATE(min_examined_row_limit,SLOG_UG_MIN_EXAMINED_ROW_LIMIT);
781+#undef USE_GLOBAL_UPDATE
782+
783+ /* Do not log this thread's queries due to rate limiting. */
784+ if (thd->write_to_slow_log != TRUE
785+ && (thd->variables.long_query_time >= 1000000
786+ || (ulong) (end_utime_of_query - thd->utime_after_lock) < 1000000))
787+ DBUG_VOID_RETURN;
788+
789+
790 /*
791 Do not log administrative statements unless the appropriate option is
792 set.
d8778560 793@@ -1819,6 +1854,9 @@
b4e1fa2c
AM		 794 context.resolve_in_table_list_only(select_lex->
795 table_list.first);
796
797+ /* Reset the counter at all cases for the extended slow query log */
798+ thd->sent_row_count= 0;
799+
800 /*
801 Reset warning count for each query that uses tables
802 A better approach would be to reset this for any commands
d8778560 803@@ -5258,6 +5296,21 @@
b4e1fa2c
AM		 804 thd->rand_used= 0;
805 thd->sent_row_count= thd->examined_row_count= 0;
806
807+ thd->bytes_sent_old= thd->status_var.bytes_sent;
808+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
809+ thd->tmp_tables_size= 0;
810+ thd->innodb_was_used= FALSE;
811+ thd->innodb_trx_id= 0;
812+ thd->innodb_io_reads= 0;
813+ thd->innodb_io_read= 0;
814+ thd->innodb_io_reads_wait_timer= 0;
815+ thd->innodb_lock_que_wait_timer= 0;
816+ thd->innodb_innodb_que_wait_timer= 0;
817+ thd->innodb_page_access= 0;
818+ thd->query_plan_flags= QPLAN_NONE;
819+ thd->query_plan_fsort_passes= 0;
820+ thd->last_errno= 0;
821+
822 thd->reset_current_stmt_binlog_format_row();
823 thd->binlog_unsafe_warning_flags= 0;
824
825diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc
a9ee80b9
ER		 826--- a/sql/sql_select.cc 2011-02-21 22:57:24.411087114 +0200
827+++ b/sql/sql_select.cc 2011-02-21 22:57:48.867756749 +0200
d8778560 828@@ -6872,7 +6872,10 @@
b4e1fa2c
AM		 829 {
830 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
831 if (statistics)
832+ {
833 status_var_increment(join->thd->status_var.select_scan_count);
834+ join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
835+ }
836 }
837 }
838 else
d8778560 839@@ -6886,7 +6889,10 @@
b4e1fa2c
AM		 840 {
841 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
842 if (statistics)
843+ {
844 status_var_increment(join->thd->status_var.select_full_join_count);
845+ join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
846+ }
847 }
848 }
849 if (!table->no_keyread)
d8778560 850@@ -10217,6 +10223,7 @@
b4e1fa2c
AM		 851 (ulong) rows_limit,test(group)));
852
853 status_var_increment(thd->status_var.created_tmp_tables);
854+ thd->query_plan_flags|= QPLAN_TMP_TABLE;
855
856 if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
857 temp_pool_slot = bitmap_lock_set_next(&temp_pool);
d8778560 858@@ -11115,6 +11122,7 @@
b4e1fa2c
AM		 859 goto err;
860 }
861 status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
862+ table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
863 share->db_record_offset= 1;
864 DBUG_RETURN(0);
865 err:
d8778560 866@@ -11133,6 +11141,14 @@
b4e1fa2c
AM		 867 save_proc_info=thd->proc_info;
868 thd_proc_info(thd, "removing tmp table");
869
870+ thd->tmp_tables_used++;
871+ if (entry->file)
872+ {
873+ thd->tmp_tables_size += entry->file->stats.data_file_length;
874+ if (entry->file->ht->db_type != DB_TYPE_HEAP)
875+ thd->tmp_tables_disk_used++;
876+ }
877+
878 // Release latches since this can take a long time
879 ha_release_temporary_latches(thd);
880
881diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc
a9ee80b9
ER		 882--- a/sql/sql_show.cc 2011-02-21 22:57:24.456079146 +0200
883+++ b/sql/sql_show.cc 2011-02-21 22:57:48.873755686 +0200
b4e1fa2c
AM		 884@@ -1942,8 +1942,17 @@
885 table->field[4]->store(command_name[tmp->command].str,
886 command_name[tmp->command].length, cs);
887 /* MYSQL_TIME */
888- table->field[5]->store((longlong)(tmp->start_time ?
889- now - tmp->start_time : 0), FALSE);
890+ longlong value_in_time_column= 0;
891+ if(tmp->start_time)
892+ {
893+ value_in_time_column = (now - tmp->start_time);
894+ if(value_in_time_column > now)
895+ {
896+ value_in_time_column= 0;
897+ }
898+ }
899+ table->field[5]->store(value_in_time_column, FALSE);
900+
901 /* STATE */
902 if ((val= thread_state_info(tmp)))
903 {
904diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc
a9ee80b9
ER		 905--- a/sql/sys_vars.cc 2011-02-21 22:57:24.435082865 +0200
906+++ b/sql/sys_vars.cc 2011-02-21 23:10:51.177188840 +0200
907@@ -2852,6 +2852,117 @@
b4e1fa2c
AM		 908 DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
909 ON_UPDATE(fix_log_state));
910
911+const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
912+ "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
913+static Sys_var_set Sys_log_slow_filter(
914+ "log_slow_filter",
915+ "Log only the queries that followed certain execution plan. "
916+ "Multiple flags allowed in a comma-separated string. "
917+ "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
918+ "filesort, filesort_on_disk]",
919+ SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
920+ log_slow_filter_name, DEFAULT(0));
921+static Sys_var_ulong sys_log_slow_rate_limit(
922+ "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
923+ SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
924+ VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
925+const char* log_slow_verbosity_name[] = {
926+ "microtime", "query_plan", "innodb",
927+ "profiling", "profling_use_getrusage",
928+ "minimal", "standard", "full", 0
929+};
930+static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
931+{
932+ if((value & what) == what)
933+ {
934+ value = value & (~what);
935+ value = value | by;
936+ }
937+ return value;
938+}
939+void update_log_slow_verbosity(ulonglong* value_ptr)
940+{
941+ ulonglong &value = *value_ptr;
942+ ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
943+ ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
944+ ulonglong innodb= ULL(1) << SLOG_V_INNODB;
945+ ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
946+ ulonglong standard= ULL(1) << SLOG_V_STANDARD;
947+ ulonglong full= ULL(1) << SLOG_V_FULL;
948+ value= update_log_slow_verbosity_replace(value,minimal,microtime);
949+ value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
950+ value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
951+}
952+static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
953+ enum_var_type type)
954+{
955+ if(type == OPT_SESSION)
956+ {
957+ update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
958+ }
959+ else
960+ {
961+ update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
962+ }
963+ return false;
964+}
a9ee80b9 965+void init_slow_query_log_use_global_control()
b4e1fa2c
AM		 966+{
967+ update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
968+}
969+static Sys_var_set Sys_log_slow_verbosity(
970+ "log_slow_verbosity",
971+ "Choose how verbose the messages to your slow log will be. "
972+ "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
973+ SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
974+ log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
975+ NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
976+ ON_UPDATE(update_log_slow_verbosity_helper));
977+static Sys_var_mybool Sys_log_slow_slave_statements(
978+ "log_slow_slave_statements",
979+ "Log queries replayed be the slave SQL thread",
980+ GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
981+ DEFAULT(FALSE));
982+static Sys_var_mybool Sys_log_slow_sp_statements(
983+ "log_slow_sp_statements",
984+ "Log slow statements executed by stored procedure to the slow log if it is open.",
985+ GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
986+ DEFAULT(TRUE));
a9ee80b9
ER		 987+static Sys_var_mybool Sys_slow_query_log_timestamp_always(
988+ "slow_query_log_timestamp_always",
b4e1fa2c 989+ "Timestamp is printed for all records of the slow log even if they are same time.",
a9ee80b9 990+ GLOBAL_VAR(opt_slow_query_log_timestamp_always), CMD_LINE(OPT_ARG),
b4e1fa2c 991+ DEFAULT(FALSE));
a9ee80b9
ER		 992+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};
993+static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/,
b4e1fa2c
AM		 994+ enum_var_type /*type*/)
995+{
a9ee80b9 996+ if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
b4e1fa2c 997+ {
a9ee80b9 998+ opt_slow_query_log_use_global_control=
b4e1fa2c
AM		 999+ SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
1000+ SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
1001+ }
1002+ return false;
1003+}
1004+void init_log_slow_verbosity()
1005+{
a9ee80b9 1006+ update_slow_query_log_use_global_control(0,0,OPT_GLOBAL);
b4e1fa2c 1007+}
a9ee80b9
ER		 1008+static Sys_var_set Sys_slow_query_log_use_global_control(
1009+ "slow_query_log_use_global_control",
b4e1fa2c 1010+ "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		 1011+ GLOBAL_VAR(opt_slow_query_log_use_global_control), CMD_LINE(REQUIRED_ARG),
1012+ slow_query_log_use_global_control_name, DEFAULT(0),
b4e1fa2c 1013+ NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
a9ee80b9
ER		 1014+ ON_UPDATE(update_slow_query_log_use_global_control));
1015+const char *slow_query_log_timestamp_precision_name[]= { "second", "microsecond", 0 };
1016+static Sys_var_enum Sys_slow_query_log_timestamp_precision(
1017+ "slow_query_log_timestamp_precision",
1018+ "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]",
1019+ GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
1020+ slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
b4e1fa2c
AM		 1021+
1022 /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
1023 static Sys_var_mybool Sys_log_slow(
1024 "log_slow_queries",
1025diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc
a9ee80b9
ER		 1026--- a/sql/sql_profile.cc 2011-01-20 00:37:09.000000000 +0200
1027+++ b/sql/sql_profile.cc 2011-02-21 22:57:48.877754978 +0200
b4e1fa2c
AM		 1028@@ -243,7 +243,8 @@
1029 {
1030 time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
1031 #ifdef HAVE_GETRUSAGE
1032- getrusage(RUSAGE_SELF, &rusage);
1033+ if ((profile->get_profiling())->enabled_getrusage())
1034+ getrusage(RUSAGE_SELF, &rusage);
1035 #elif defined(_WIN32)
1036 FILETIME ftDummy;
1037 // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
1038@@ -251,6 +252,19 @@
1039 // measurable by this function.
1040 GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
1041 #endif
1042+
1043+#ifdef HAVE_CLOCK_GETTIME
1044+ struct timespec tp;
1045+
1046+ if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
1047+ {
1048+ cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
1049+ }
1050+ else
1051+#endif
1052+ {
1053+ cpu_time_usecs= 0;
1054+ }
1055 }
1056
1057
1058@@ -366,7 +380,8 @@
1059 finish_current_query();
1060 }
1061
1062- enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
1063+ enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1064+ ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
1065
1066 if (! enabled) DBUG_VOID_RETURN;
1067
1068@@ -404,7 +419,8 @@
1069 status_change("ending", NULL, NULL, 0);
1070
1071 if ((enabled) && /* ON at start? */
1072- ((thd->variables.option_bits & OPTION_PROFILING) != 0) && /* and ON at end? */
1073+ (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1074+ ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) && /* and ON at end? */
1075 (current->query_source != NULL) &&
1076 (! current->entries.is_empty()))
1077 {
1078@@ -505,6 +521,118 @@
1079 DBUG_VOID_RETURN;
1080 }
1081
1082+bool PROFILING::enabled_getrusage()
1083+{
1084+ return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
1085+}
1086+
1087+/**
1088+ For a given profile entry specified by a name and 2 time measurements,
1089+ print its normalized name (i.e. with all spaces replaced with underscores)
1090+ along with its wall clock and CPU time.
1091+*/
1092+
1093+static void my_b_print_status(IO_CACHE *log_file, const char *status,
1094+ PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
1095+{
1096+ DBUG_ENTER("my_b_print_status");
1097+ DBUG_ASSERT(log_file != NULL && status != NULL);
1098+ char query_time_buff[22+7];
1099+ const char *tmp;
1100+
1101+ my_b_printf(log_file, "Profile_");
1102+ for (tmp= status; *tmp; tmp++)
1103+ my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1104+
1105+ snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1106+ (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
1107+ my_b_printf(log_file, ": %s ", query_time_buff);
1108+
1109+ my_b_printf(log_file, "Profile_");
1110+ for (tmp= status; *tmp; tmp++)
1111+ my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1112+ my_b_printf(log_file, "_cpu: ");
1113+
1114+ snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1115+ (stop->cpu_time_usecs - start->cpu_time_usecs) /
1116+ (1000.0 * 1000 * 1000));
1117+ my_b_printf(log_file, "%s ", query_time_buff);
1118+
1119+ DBUG_VOID_RETURN;
1120+}
1121+
1122+/**
1123+ Print output for current query to file
1124+*/
1125+
1126+int PROFILING::print_current(IO_CACHE *log_file)
1127+{
1128+ DBUG_ENTER("PROFILING::print_current");
1129+ ulonglong row_number= 0;
1130+
1131+ QUERY_PROFILE *query;
1132+ /* Get current query */
1133+ if (current == NULL)
1134+ {
1135+ DBUG_RETURN(0);
1136+ }
1137+
1138+ query= current;
1139+
1140+ my_b_printf(log_file, "# ");
1141+
1142+ void *entry_iterator;
1143+ PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
1144+ /* ...and for each query, go through all its state-change steps. */
1145+ for (entry_iterator= query->entries.new_iterator();
1146+ entry_iterator != NULL;
1147+ entry_iterator= query->entries.iterator_next(entry_iterator),
1148+ previous=entry, row_number++)
1149+ {
1150+ entry= query->entries.iterator_value(entry_iterator);
1151+
1152+ /* Skip the first. We count spans of fence, not fence-posts. */
1153+ if (previous == NULL) {first= entry; continue;}
1154+
1155+ if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
1156+ {
1157+ /*
1158+ We got here via a SHOW command. That means that we stored
1159+ information about the query we wish to show and that isn't
1160+ in a WHERE clause at a higher level to filter out rows we
1161+ wish to exclude.
1162+
1163+ Because that functionality isn't available in the server yet,
1164+ we must filter here, at the wrong level. Once one can con-
1165+ struct where and having conditions at the SQL layer, then this
1166+ condition should be ripped out.
1167+ */
1168+ if (thd->lex->profile_query_id == 0) /* 0 == show final query */
1169+ {
1170+ if (query != last)
1171+ continue;
1172+ }
1173+ else
1174+ {
1175+ if (thd->lex->profile_query_id != query->profiling_query_id)
1176+ continue;
1177+ }
1178+ }
1179+
1180+ my_b_print_status(log_file, previous->status, previous, entry);
1181+ }
1182+
1183+ my_b_write_byte(log_file, '\n');
1184+ if ((entry != NULL) && (first != NULL))
1185+ {
1186+ my_b_printf(log_file, "# ");
1187+ my_b_print_status(log_file, "total", first, entry);
1188+ my_b_write_byte(log_file, '\n');
1189+ }
1190+
1191+ DBUG_RETURN(0);
1192+}
1193+
1194 /**
1195 Fill the information schema table, "query_profile", as defined in show.cc .
1196 There are two ways to get to this function: Selecting from the information
1197diff -ruN a/sql/sql_profile.h b/sql/sql_profile.h
a9ee80b9
ER		 1198--- a/sql/sql_profile.h 2011-01-20 00:37:09.000000000 +0200
1199+++ b/sql/sql_profile.h 2011-02-21 22:57:48.878754801 +0200
b4e1fa2c
AM		 1200@@ -164,11 +164,15 @@
1201 */
1202 class PROF_MEASUREMENT
1203 {
1204-private:
1205- friend class QUERY_PROFILE;
1206- friend class PROFILING;
1207-
1208 QUERY_PROFILE *profile;
1209+
1210+ char *allocated_status_memory;
1211+
1212+ void set_label(const char *status_arg, const char *function_arg,
1213+ const char *file_arg, unsigned int line_arg);
1214+ void clean_up();
1215+
1216+public:
1217 char *status;
1218 #ifdef HAVE_GETRUSAGE
1219 struct rusage rusage;
1220@@ -181,12 +185,7 @@
1221 unsigned int line;
1222
1223 double time_usecs;
1224- char *allocated_status_memory;
1225-
1226- void set_label(const char *status_arg, const char *function_arg,
1227- const char *file_arg, unsigned int line_arg);
1228- void clean_up();
1229-
1230+ double cpu_time_usecs;
1231 PROF_MEASUREMENT();
1232 PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
1233 PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
1234@@ -231,6 +230,11 @@
1235
1236 /* Show this profile. This is called by PROFILING. */
1237 bool show(uint options);
1238+
1239+public:
1240+
1241+ inline PROFILING * get_profiling() { return profiling; };
1242+
1243 };
1244
1245
1246@@ -276,9 +280,11 @@
1247
1248 /* SHOW PROFILES */
1249 bool show_profiles();
1250+ bool enabled_getrusage();
1251
1252 /* ... from INFORMATION_SCHEMA.PROFILING ... */
1253 int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
1254+ int print_current(IO_CACHE *log_file);
1255 };
1256
1257 # endif /* HAVE_PROFILING */
MySQL: a very fast and reliable SQL database engine
This page took 0.193596 seconds and 4 git commands to generate.