1 # name : slow_extended.patch
2 # introduced : 11 or before
6 # Any small change to this file in the main branch
7 # should be done or reviewed by the maintainer!
8 diff -ruN a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp
9 --- a/include/mysql/plugin_audit.h.pp 2010-11-03 01:01:11.000000000 +0300
10 +++ b/include/mysql/plugin_audit.h.pp 2010-12-16 04:27:46.000000000 +0300
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,
19 + long io_reads_wait_timer,
20 + long lock_que_wait_timer,
21 + long que_wait_timer,
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);
28 diff -ruN a/include/mysql/plugin_auth.h.pp b/include/mysql/plugin_auth.h.pp
29 --- a/include/mysql/plugin_auth.h.pp 2010-11-03 01:01:11.000000000 +0300
30 +++ b/include/mysql/plugin_auth.h.pp 2010-12-16 04:27:46.000000000 +0300
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,
39 + long io_reads_wait_timer,
40 + long lock_que_wait_timer,
41 + long que_wait_timer,
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);
48 diff -ruN a/include/mysql/plugin_ftparser.h.pp b/include/mysql/plugin_ftparser.h.pp
49 --- a/include/mysql/plugin_ftparser.h.pp 2010-11-03 01:01:11.000000000 +0300
50 +++ b/include/mysql/plugin_ftparser.h.pp 2010-12-16 04:27:46.000000000 +0300
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,
59 + long io_reads_wait_timer,
60 + long lock_que_wait_timer,
61 + long que_wait_timer,
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);
68 diff -ruN a/include/mysql/plugin.h b/include/mysql/plugin.h
69 --- a/include/mysql/plugin.h 2010-11-03 01:01:11.000000000 +0300
70 +++ b/include/mysql/plugin.h 2010-12-16 04:27:46.000000000 +0300
72 /* Increments the row counter, see THD::row_count */
73 void thd_inc_row_count(MYSQL_THD thd);
75 +void increment_thd_innodb_stats(MYSQL_THD thd,
76 + unsigned long long trx_id,
79 + long io_reads_wait_timer,
80 + long lock_que_wait_timer,
81 + long que_wait_timer,
83 +unsigned long thd_log_slow_verbosity(const MYSQL_THD thd);
84 +int thd_opt_slow_log();
85 +#define EXTENDED_SLOWLOG
87 Create a temporary file.
89 diff -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
91 +++ b/patch_info/slow_extended.info 2010-12-16 04:27:46.000000000 +0300
93 +File=slow_extended.patch
94 +Name=Extended statistics in slow.log (not InnoDB part)
96 +Author=Percona <info@percona.com>
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).
104 +VT: Moved log_slow_rate_limit in SHOW VARIABLE into right place
107 +Arjen Lentz: Fixups (backward compatibility) by Arjen Lentz <arjen@openquery.com.au>
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)
117 +Patch profiling_slow.patch was merged
118 diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh
119 --- a/scripts/mysqldumpslow.sh 2010-11-03 01:01:13.000000000 +0300
120 +++ b/scripts/mysqldumpslow.sh 2010-12-16 04:27:46.000000000 +0300
122 s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
123 my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
125 - s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
126 - my ($t, $l, $r) = ($1, $2, $3);
127 + s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//;
128 + my ($t, $l, $r) = ($1, $3, $5);
129 $t -= $l unless $opt{l};
131 # remove fluff that mysqld writes to log when it (re)starts:
132 diff -ruN a/sql/event_scheduler.cc b/sql/event_scheduler.cc
133 --- a/sql/event_scheduler.cc 2010-11-03 01:01:14.000000000 +0300
134 +++ b/sql/event_scheduler.cc 2010-12-16 04:27:46.000000000 +0300
136 thd->client_capabilities|= CLIENT_MULTI_RESULTS;
137 mysql_mutex_lock(&LOCK_thread_count);
138 thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
139 + thd->write_to_slow_log = TRUE;
140 mysql_mutex_unlock(&LOCK_thread_count);
143 diff -ruN a/sql/filesort.cc b/sql/filesort.cc
144 --- a/sql/filesort.cc 2010-11-03 01:01:14.000000000 +0300
145 +++ b/sql/filesort.cc 2010-12-16 04:27:46.000000000 +0300
148 status_var_increment(thd->status_var.filesort_scan_count);
150 + thd->query_plan_flags|= QPLAN_FILESORT;
151 #ifdef CAN_TRUST_RANGE
152 if (select && select->quick && select->quick->records > 0L)
158 + thd->query_plan_flags|= QPLAN_FILESORT_DISK;
159 if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
161 my_free(table_sort.buffpek);
162 @@ -1201,6 +1203,7 @@
163 DBUG_ENTER("merge_buffers");
165 status_var_increment(current_thd->status_var.filesort_merge_passes);
166 + current_thd->query_plan_fsort_passes++;
167 if (param->not_killable)
169 killed= ¬_killable;
170 diff -ruN a/sql/log.cc b/sql/log.cc
171 --- a/sql/log.cc 2010-11-03 07:01:14.000000000 +0900
172 +++ b/sql/log.cc 2010-12-02 19:28:31.337989417 +0900
173 @@ -630,11 +630,13 @@
176 bool Log_to_csv_event_handler::
177 - log_slow(THD *thd, time_t current_time, time_t query_start_arg,
178 + log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
179 const char *user_host, uint user_host_len,
180 ulonglong query_utime, ulonglong lock_utime, bool is_command,
181 const char *sql_text, uint sql_text_len)
183 + time_t current_time= my_time_possible_from_micro(current_utime);
185 TABLE_LIST table_list;
188 @@ -850,14 +852,14 @@
189 /** Wrapper around MYSQL_LOG::write() for slow log. */
191 bool Log_to_file_event_handler::
192 - log_slow(THD *thd, time_t current_time, time_t query_start_arg,
193 + log_slow(THD *thd, ulonglong current_utime, time_t query_start_arg,
194 const char *user_host, uint user_host_len,
195 ulonglong query_utime, ulonglong lock_utime, bool is_command,
196 const char *sql_text, uint sql_text_len)
198 Silence_log_table_errors error_handler;
199 thd->push_internal_handler(&error_handler);
200 - bool retval= mysql_slow_log.write(thd, current_time, query_start_arg,
201 + bool retval= mysql_slow_log.write(thd, current_utime, query_start_arg,
202 user_host, user_host_len,
203 query_utime, lock_utime, is_command,
204 sql_text, sql_text_len);
205 @@ -1131,7 +1133,7 @@
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) -
214 @@ -1139,8 +1141,22 @@
215 current_time= my_time_possible_from_micro(current_utime);
216 if (thd->start_utime)
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)
226 + query_utime= (current_utime - thd->start_utime);
228 + if(thd->utime_after_lock < thd->start_utime)
234 + lock_utime= (thd->utime_after_lock - thd->start_utime);
239 @@ -1154,8 +1170,20 @@
240 query_length= command_name[thd->command].length;
245 + thd->sent_row_count= thd->examined_row_count= 0;
246 + thd->sent_row_count= 0;
247 + thd->bytes_sent_old= thd->status_var.bytes_sent;
248 + thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
249 + thd->tmp_tables_size= 0;
250 + thd->innodb_was_used= FALSE;
251 + thd->query_plan_flags= QPLAN_NONE;
252 + thd->query_plan_fsort_passes= 0;
255 for (current_handler= slow_log_handler_list; *current_handler ;)
256 - error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
257 + error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
258 user_host_buff, user_host_len,
259 query_utime, lock_utime, is_command,
260 query, query_length) || error;
261 @@ -2539,12 +2567,13 @@
265 -bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
266 +bool MYSQL_QUERY_LOG::write(THD *thd, ulonglong current_utime,
267 time_t query_start_arg, const char *user_host,
268 uint user_host_len, ulonglong query_utime,
269 ulonglong lock_utime, bool is_command,
270 const char *sql_text, uint sql_text_len)
272 + time_t current_time= my_time_possible_from_micro(current_utime);
274 DBUG_ENTER("MYSQL_QUERY_LOG::write");
276 @@ -2566,17 +2595,28 @@
278 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
280 - if (current_time != last_time)
281 + if (opt_log_slow_timestamp_every || current_time != last_time)
283 last_time= current_time;
285 localtime_r(¤t_time, &start);
287 - buff_len= my_snprintf(buff, sizeof buff,
288 - "# Time: %02d%02d%02d %2d:%02d:%02d\n",
289 - start.tm_year % 100, start.tm_mon + 1,
290 - start.tm_mday, start.tm_hour,
291 - start.tm_min, start.tm_sec);
292 + if(opt_slow_query_log_microseconds_timestamp)
294 + ulonglong microsecond = current_utime % (1000 * 1000);
295 + buff_len= snprintf(buff, sizeof buff,
296 + "# Time: %02d%02d%02d %2d:%02d:%02d.%010lld\n",
297 + start.tm_year % 100, start.tm_mon + 1,
298 + start.tm_mday, start.tm_hour,
299 + start.tm_min, start.tm_sec,microsecond);
303 + buff_len= my_snprintf(buff, sizeof buff,
304 + "# Time: %02d%02d%02d %2d:%02d:%02d\n",
305 + start.tm_year % 100, start.tm_mon + 1,
306 + start.tm_mday, start.tm_hour,
307 + start.tm_min, start.tm_sec);
310 /* Note that my_b_write() assumes it knows the length for this */
311 if (my_b_write(&log_file, (uchar*) buff, buff_len))
312 @@ -2594,12 +2634,69 @@
313 sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
314 sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
315 if (my_b_printf(&log_file,
316 - "# Query_time: %s Lock_time: %s"
317 - " Rows_sent: %lu Rows_examined: %lu\n",
318 + "# Thread_id: %lu Schema: %s Last_errno: %u Killed: %u\n" \
319 + "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu Rows_affected: %lu Rows_read: %lu\n"
320 + "# Bytes_sent: %lu Tmp_tables: %lu Tmp_disk_tables: %lu Tmp_table_sizes: %lu\n",
321 + (ulong) thd->thread_id, (thd->db ? thd->db : ""),
322 + thd->last_errno, (uint) thd->killed,
323 query_time_buff, lock_time_buff,
324 (ulong) thd->sent_row_count,
325 - (ulong) thd->examined_row_count) == (uint) -1)
326 + (ulong) thd->examined_row_count,
327 + ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
328 + (ulong) thd->sent_row_count,
329 + (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
330 + (ulong) thd->tmp_tables_used,
331 + (ulong) thd->tmp_tables_disk_used,
332 + (ulong) thd->tmp_tables_size) == (uint) -1)
335 +#if defined(ENABLED_PROFILING)
336 + thd->profiling.print_current(&log_file);
338 + if (thd->innodb_was_used)
341 + snprintf(buf, 20, "%llX", thd->innodb_trx_id);
342 + if (my_b_printf(&log_file,
343 + "# InnoDB_trx_id: %s\n", buf) == (uint) -1)
346 + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_QUERY_PLAN)) &&
347 + my_b_printf(&log_file,
348 + "# QC_Hit: %s Full_scan: %s Full_join: %s Tmp_table: %s Tmp_table_on_disk: %s\n" \
349 + "# Filesort: %s Filesort_on_disk: %s Merge_passes: %lu\n",
350 + ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"),
351 + ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"),
352 + ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"),
353 + ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"),
354 + ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"),
355 + ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"),
356 + ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"),
357 + thd->query_plan_fsort_passes) == (uint) -1)
359 + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) && thd->innodb_was_used)
362 + snprintf(buf[0], 20, "%.6f", thd->innodb_io_reads_wait_timer / 1000000.0);
363 + snprintf(buf[1], 20, "%.6f", thd->innodb_lock_que_wait_timer / 1000000.0);
364 + snprintf(buf[2], 20, "%.6f", thd->innodb_innodb_que_wait_timer / 1000000.0);
365 + if (my_b_printf(&log_file,
366 + "# InnoDB_IO_r_ops: %lu InnoDB_IO_r_bytes: %lu InnoDB_IO_r_wait: %s\n" \
367 + "# InnoDB_rec_lock_wait: %s InnoDB_queue_wait: %s\n" \
368 + "# InnoDB_pages_distinct: %lu\n",
369 + (ulong) thd->innodb_io_reads,
370 + (ulong) thd->innodb_io_read,
371 + buf[0], buf[1], buf[2],
372 + (ulong) thd->innodb_page_access) == (uint) -1)
377 + if ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_INNODB)) &&
378 + my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
382 if (thd->db && strcmp(thd->db, db))
383 { // Database changed
384 if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
385 diff -ruN a/sql/log.h b/sql/log.h
386 --- a/sql/log.h 2010-11-03 01:01:14.000000000 +0300
387 +++ b/sql/log.h 2010-12-16 04:27:46.000000000 +0300
389 uint user_host_len, int thread_id,
390 const char *command_type, uint command_type_len,
391 const char *sql_text, uint sql_text_len);
392 - bool write(THD *thd, time_t current_time, time_t query_start_arg,
393 + bool write(THD *thd, ulonglong current_time, time_t query_start_arg,
394 const char *user_host, uint user_host_len,
395 ulonglong query_utime, ulonglong lock_utime, bool is_command,
396 const char *sql_text, uint sql_text_len);
398 virtual bool init()= 0;
399 virtual void cleanup()= 0;
401 - virtual bool log_slow(THD *thd, time_t current_time,
402 + virtual bool log_slow(THD *thd, ulonglong current_time,
403 time_t query_start_arg, const char *user_host,
404 uint user_host_len, ulonglong query_utime,
405 ulonglong lock_utime, bool is_command,
408 virtual void cleanup();
410 - virtual bool log_slow(THD *thd, time_t current_time,
411 + virtual bool log_slow(THD *thd, ulonglong current_utime,
412 time_t query_start_arg, const char *user_host,
413 uint user_host_len, ulonglong query_utime,
414 ulonglong lock_utime, bool is_command,
417 virtual void cleanup();
419 - virtual bool log_slow(THD *thd, time_t current_time,
420 + virtual bool log_slow(THD *thd, ulonglong current_utime,
421 time_t query_start_arg, const char *user_host,
422 uint user_host_len, ulonglong query_utime,
423 ulonglong lock_utime, bool is_command,
424 diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
425 --- a/sql/mysqld.cc 2010-12-16 04:27:10.000000000 +0300
426 +++ b/sql/mysqld.cc 2010-12-16 04:27:46.000000000 +0300
428 char* opt_secure_file_priv;
429 my_bool opt_log_slow_admin_statements= 0;
430 my_bool opt_log_slow_slave_statements= 0;
431 +my_bool opt_log_slow_sp_statements= 0;
432 +my_bool opt_log_slow_timestamp_every= 0;
433 +ulonglong opt_use_global_log_slow_control= 0;
434 +my_bool opt_slow_query_log_microseconds_timestamp= 0;
435 my_bool lower_case_file_system= 0;
436 my_bool opt_large_pages= 0;
437 my_bool opt_super_large_pages= 0;
438 @@ -5789,10 +5793,10 @@
439 "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
440 "the slow log if it is open.", &opt_log_slow_admin_statements,
441 &opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
442 - {"log-slow-slave-statements", 0,
443 + /*{"log-slow-slave-statements", 0,
444 "Log slow statements executed by slave thread to the slow log if it is open.",
445 &opt_log_slow_slave_statements, &opt_log_slow_slave_statements,
446 - 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
447 + 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},*/
448 {"log-slow-queries", OPT_SLOW_QUERY_LOG,
449 "Log slow queries to a table or log file. Defaults logging to table "
450 "mysql.slow_log or hostname-slow.log if --log-output=file is used. "
451 @@ -7182,6 +7186,10 @@
455 +/* defined in sys_vars.cc */
456 +extern void init_log_slow_verbosity();
457 +extern void init_use_global_log_slow_control();
460 Get server options from the command line,
461 and perform related server initializations.
462 @@ -7321,6 +7329,8 @@
463 global_system_variables.long_query_time= (ulonglong)
464 (global_system_variables.long_query_time_double * 1e6);
466 + init_log_slow_verbosity();
467 + init_use_global_log_slow_control();
468 if (opt_short_log_format)
469 opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
471 diff -ruN a/sql/mysqld.h b/sql/mysqld.h
472 --- a/sql/mysqld.h 2010-12-16 04:27:10.000000000 +0300
473 +++ b/sql/mysqld.h 2010-12-16 04:27:46.000000000 +0300
475 extern char* opt_secure_backup_file_priv;
476 extern size_t opt_secure_backup_file_priv_len;
477 extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
478 +extern my_bool opt_log_slow_sp_statements;
479 +extern my_bool opt_log_slow_timestamp_every;
480 +extern ulonglong opt_use_global_log_slow_control;
481 +extern my_bool opt_slow_query_log_microseconds_timestamp;
482 extern my_bool sp_automatic_privileges, opt_noacl;
483 extern my_bool opt_old_style_user_limits, trust_function_creators;
484 extern uint opt_crash_binlog_innodb;
485 diff -ruN a/sql/slave.cc b/sql/slave.cc
486 --- a/sql/slave.cc 2010-11-03 01:01:14.000000000 +0300
487 +++ b/sql/slave.cc 2010-12-16 04:27:46.000000000 +0300
488 @@ -2037,6 +2037,7 @@
489 + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */
490 thd->slave_thread = 1;
491 thd->enable_slow_log= opt_log_slow_slave_statements;
492 + thd->write_to_slow_log= opt_log_slow_slave_statements;
493 set_slave_thread_options(thd);
494 thd->client_capabilities = CLIENT_LOCAL_FILES;
495 mysql_mutex_lock(&LOCK_thread_count);
496 diff -ruN a/sql/sp_head.cc b/sql/sp_head.cc
497 --- a/sql/sp_head.cc 2010-12-16 04:27:10.000000000 +0300
498 +++ b/sql/sp_head.cc 2010-12-16 04:27:46.000000000 +0300
499 @@ -2151,7 +2151,7 @@
500 DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length,
503 - if (!(m_flags & LOG_SLOW_STATEMENTS) && thd->enable_slow_log)
504 + if (!(m_flags & LOG_SLOW_STATEMENTS || opt_log_slow_sp_statements) && thd->enable_slow_log)
506 DBUG_PRINT("info", ("Disabling slow log for the execution"));
507 save_enable_slow_log= true;
508 diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc
509 --- a/sql/sql_cache.cc 2010-11-03 01:01:14.000000000 +0300
510 +++ b/sql/sql_cache.cc 2010-12-16 04:27:46.000000000 +0300
511 @@ -1756,6 +1756,7 @@
512 response, we can't handle it anyway.
514 (void) trans_commit_stmt(thd);
515 + thd->query_plan_flags|= QPLAN_QC;
516 if (!thd->stmt_da->is_set())
517 thd->stmt_da->disable_status();
519 @@ -1766,6 +1767,7 @@
523 + thd->query_plan_flags|= QPLAN_QC_NO;
524 MYSQL_QUERY_CACHE_MISS(thd->query());
525 DBUG_RETURN(0); // Query was not cached
527 diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc
528 --- a/sql/sql_class.cc 2010-11-03 01:01:14.000000000 +0300
529 +++ b/sql/sql_class.cc 2010-12-16 04:27:46.000000000 +0300
531 thd->warning_info->inc_current_row_for_warning();
535 +void increment_thd_innodb_stats(THD* thd,
536 + unsigned long long trx_id,
539 + long io_reads_wait_timer,
540 + long lock_que_wait_timer,
541 + long que_wait_timer,
544 + thd->innodb_was_used = TRUE;
545 + thd->innodb_trx_id = trx_id;
546 + thd->innodb_io_reads += io_reads;
547 + thd->innodb_io_read += io_read;
548 + thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
549 + thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
550 + thd->innodb_innodb_que_wait_timer += que_wait_timer;
551 + thd->innodb_page_access += page_access;
555 +unsigned long thd_log_slow_verbosity(const THD *thd)
557 + return (unsigned long) thd->variables.log_slow_verbosity;
561 +int thd_opt_slow_log()
563 + return (int) opt_slow_log;
567 Dumps a text description of a thread, its security context
572 + last_errno= sql_errno;
574 for (Internal_error_handler *error_handler= m_internal_handler;
576 @@ -3355,6 +3387,12 @@
577 first_successful_insert_id_in_prev_stmt;
578 backup->first_successful_insert_id_in_cur_stmt=
579 first_successful_insert_id_in_cur_stmt;
580 + backup->innodb_io_reads= innodb_io_reads;
581 + backup->innodb_io_read= innodb_io_read;
582 + backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
583 + backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
584 + backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
585 + backup->innodb_page_access= innodb_page_access;
587 if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
588 !is_current_stmt_binlog_format_row())
589 @@ -3375,6 +3413,14 @@
591 transaction.savepoints= 0;
592 first_successful_insert_id_in_cur_stmt= 0;
595 + innodb_io_reads= 0;
597 + innodb_io_reads_wait_timer= 0;
598 + innodb_lock_que_wait_timer= 0;
599 + innodb_innodb_que_wait_timer= 0;
600 + innodb_page_access= 0;
604 @@ -3437,6 +3483,12 @@
606 examined_row_count+= backup->examined_row_count;
607 cuted_fields+= backup->cuted_fields;
608 + innodb_io_reads+= backup->innodb_io_reads;
609 + innodb_io_read+= backup->innodb_io_read;
610 + innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
611 + innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
612 + innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
613 + innodb_page_access+= backup->innodb_page_access;
617 diff -ruN a/sql/sql_class.h b/sql/sql_class.h
618 --- a/sql/sql_class.h 2010-12-16 04:27:10.000000000 +0300
619 +++ b/sql/sql_class.h 2010-12-16 04:27:46.000000000 +0300
621 enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
622 enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
623 DELAY_KEY_WRITE_ALL };
624 +enum enum_use_global_log_slow_control { SLOG_UG_LOG_SLOW_FILTER, SLOG_UG_LOG_SLOW_RATE_LIMIT, SLOG_UG_LOG_SLOW_VERBOSITY, SLOG_UG_LONG_QUERY_TIME, SLOG_UG_MIN_EXAMINED_ROW_LIMIT, SLOG_UG_ALL };
625 +enum enum_log_slow_verbosity {
626 + SLOG_V_MICROTIME, SLOG_V_QUERY_PLAN, SLOG_V_INNODB,
627 + SLOG_V_PROFILING, SLOG_V_PROFILING_USE_GETRUSAGE,
628 + SLOG_V_MINIMAL, SLOG_V_STANDARD, SLOG_V_FULL
630 +#define QPLAN_NONE 0
631 +#define QPLAN_QC 1 << 0
632 +#define QPLAN_QC_NO 1 << 1
633 +#define QPLAN_FULL_SCAN 1 << 2
634 +#define QPLAN_FULL_JOIN 1 << 3
635 +#define QPLAN_TMP_TABLE 1 << 4
636 +#define QPLAN_TMP_DISK 1 << 5
637 +#define QPLAN_FILESORT 1 << 6
638 +#define QPLAN_FILESORT_DISK 1 << 7
639 +enum enum_log_slow_filter {
640 + SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
641 + SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
642 + SLOG_F_FILESORT_DISK
644 enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
645 SLAVE_EXEC_MODE_IDEMPOTENT,
646 SLAVE_EXEC_MODE_LAST_BIT};
649 my_bool sysdate_is_now;
651 + ulong log_slow_rate_limit;
652 + ulonglong log_slow_filter;
653 + ulonglong log_slow_verbosity;
655 + ulong innodb_io_reads;
656 + ulonglong innodb_io_read;
657 + ulong innodb_io_reads_wait_timer;
658 + ulong innodb_lock_que_wait_timer;
659 + ulong innodb_innodb_que_wait_timer;
660 + ulong innodb_page_access;
662 double long_query_time_double;
665 @@ -1140,6 +1171,14 @@
667 bool enable_slow_log;
668 bool last_insert_id_used;
670 + ulong innodb_io_reads;
671 + ulonglong innodb_io_read;
672 + ulong innodb_io_reads_wait_timer;
673 + ulong innodb_lock_que_wait_timer;
674 + ulong innodb_innodb_que_wait_timer;
675 + ulong innodb_page_access;
677 SAVEPOINT *savepoints;
678 enum enum_check_fields count_cuted_fields;
680 @@ -1575,6 +1614,26 @@
681 thr_lock_type update_lock_default;
684 + bool write_to_slow_log;
686 + ulonglong bytes_sent_old;
687 + ulong tmp_tables_used;
688 + ulong tmp_tables_disk_used;
689 + ulonglong tmp_tables_size;
690 + bool innodb_was_used;
691 + ulonglong innodb_trx_id;
692 + ulong innodb_io_reads;
693 + ulonglong innodb_io_read;
694 + ulong innodb_io_reads_wait_timer;
695 + ulong innodb_lock_que_wait_timer;
696 + ulong innodb_innodb_que_wait_timer;
697 + ulong innodb_page_access;
699 + ulong query_plan_flags;
700 + ulong query_plan_fsort_passes;
704 /* <> 0 if we are inside of trigger or stored function. */
707 diff -ruN a/sql/sql_connect.cc b/sql/sql_connect.cc
708 --- a/sql/sql_connect.cc 2010-11-03 01:01:14.000000000 +0300
709 +++ b/sql/sql_connect.cc 2010-12-16 04:27:46.000000000 +0300
712 prepare_new_connection_state(thd);
715 + If rate limiting of slow log writes is enabled, decide whether to log this
716 + new thread's queries or not. Uses extremely simple algorithm. :)
718 + thd->write_to_slow_log= FALSE;
719 + if (thd->variables.log_slow_rate_limit <= 1 ||
720 + (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
721 + thd->write_to_slow_log= TRUE;
723 while (!net->error && net->vio != 0 &&
724 !(thd->killed == THD::KILL_CONNECTION))
726 diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc
727 --- a/sql/sql_parse.cc 2010-12-16 04:27:10.000000000 +0300
728 +++ b/sql/sql_parse.cc 2010-12-16 04:47:41.000000000 +0300
729 @@ -1424,7 +1424,6 @@
734 void log_slow_statement(THD *thd)
736 DBUG_ENTER("log_slow_statement");
737 @@ -1437,6 +1436,42 @@
738 if (unlikely(thd->in_sub_stmt))
739 DBUG_VOID_RETURN; // Don't set time for sub stmt
741 + /* Follow the slow log filter configuration. */
742 + if (thd->variables.log_slow_filter != 0 &&
743 + (!(thd->variables.log_slow_filter & thd->query_plan_flags) ||
744 + ((thd->variables.log_slow_filter & SLOG_F_QC_NO) &&
745 + (thd->query_plan_flags & QPLAN_QC))))
749 + Low long_query_time value most likely means user is debugging stuff and even
750 + though some thread's queries are not supposed to be logged b/c of the rate
751 + limit, if one of them takes long enough (>= 1 second) it will be sensible
752 + to make an exception and write to slow log anyway.
755 + ulonglong end_utime_of_query= thd->current_utime();
756 +#define USE_GLOBAL_UPDATE(variable_name,enum_value_name) \
757 + if (opt_use_global_log_slow_control & (ULL(1) << enum_value_name)) \
759 + thd->variables. variable_name= \
760 + global_system_variables. variable_name; \
762 + USE_GLOBAL_UPDATE(log_slow_filter,SLOG_UG_LOG_SLOW_FILTER);
763 + USE_GLOBAL_UPDATE(log_slow_rate_limit,SLOG_UG_LOG_SLOW_RATE_LIMIT);
764 + USE_GLOBAL_UPDATE(log_slow_verbosity,SLOG_UG_LOG_SLOW_VERBOSITY);
765 + USE_GLOBAL_UPDATE(long_query_time,SLOG_UG_LONG_QUERY_TIME);
766 + USE_GLOBAL_UPDATE(long_query_time_double,SLOG_UG_LONG_QUERY_TIME);
767 + USE_GLOBAL_UPDATE(min_examined_row_limit,SLOG_UG_MIN_EXAMINED_ROW_LIMIT);
768 +#undef USE_GLOBAL_UPDATE
770 + /* Do not log this thread's queries due to rate limiting. */
771 + if (thd->write_to_slow_log != TRUE
772 + && (thd->variables.long_query_time >= 1000000
773 + || (ulong) (end_utime_of_query - thd->utime_after_lock) < 1000000))
778 Do not log administrative statements unless the appropriate option is
780 @@ -1812,6 +1847,9 @@
781 context.resolve_in_table_list_only(select_lex->
784 + /* Reset the counter at all cases for the extended slow query log */
785 + thd->sent_row_count= 0;
788 Reset warning count for each query that uses tables
789 A better approach would be to reset this for any commands
790 @@ -5238,6 +5276,21 @@
792 thd->sent_row_count= thd->examined_row_count= 0;
794 + thd->bytes_sent_old= thd->status_var.bytes_sent;
795 + thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
796 + thd->tmp_tables_size= 0;
797 + thd->innodb_was_used= FALSE;
798 + thd->innodb_trx_id= 0;
799 + thd->innodb_io_reads= 0;
800 + thd->innodb_io_read= 0;
801 + thd->innodb_io_reads_wait_timer= 0;
802 + thd->innodb_lock_que_wait_timer= 0;
803 + thd->innodb_innodb_que_wait_timer= 0;
804 + thd->innodb_page_access= 0;
805 + thd->query_plan_flags= QPLAN_NONE;
806 + thd->query_plan_fsort_passes= 0;
807 + thd->last_errno= 0;
809 thd->reset_current_stmt_binlog_format_row();
810 thd->binlog_unsafe_warning_flags= 0;
812 diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc
813 --- a/sql/sql_select.cc 2010-12-16 04:27:10.000000000 +0300
814 +++ b/sql/sql_select.cc 2010-12-16 04:27:47.000000000 +0300
815 @@ -6870,7 +6870,10 @@
817 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
820 status_var_increment(join->thd->status_var.select_scan_count);
821 + join->thd->query_plan_flags|= QPLAN_FULL_SCAN;
826 @@ -6884,7 +6887,10 @@
828 join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
831 status_var_increment(join->thd->status_var.select_full_join_count);
832 + join->thd->query_plan_flags|= QPLAN_FULL_JOIN;
836 if (!table->no_keyread)
837 @@ -10210,6 +10216,7 @@
838 (ulong) rows_limit,test(group)));
840 status_var_increment(thd->status_var.created_tmp_tables);
841 + thd->query_plan_flags|= QPLAN_TMP_TABLE;
843 if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
844 temp_pool_slot = bitmap_lock_set_next(&temp_pool);
845 @@ -11107,6 +11114,7 @@
848 status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
849 + table->in_use->query_plan_flags|= QPLAN_TMP_DISK;
850 share->db_record_offset= 1;
853 @@ -11125,6 +11133,14 @@
854 save_proc_info=thd->proc_info;
855 thd_proc_info(thd, "removing tmp table");
857 + thd->tmp_tables_used++;
860 + thd->tmp_tables_size += entry->file->stats.data_file_length;
861 + if (entry->file->ht->db_type != DB_TYPE_HEAP)
862 + thd->tmp_tables_disk_used++;
865 // Release latches since this can take a long time
866 ha_release_temporary_latches(thd);
868 diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc
869 --- a/sql/sql_show.cc 2010-12-16 04:27:10.000000000 +0300
870 +++ b/sql/sql_show.cc 2010-12-16 04:27:47.000000000 +0300
871 @@ -1942,8 +1942,17 @@
872 table->field[4]->store(command_name[tmp->command].str,
873 command_name[tmp->command].length, cs);
875 - table->field[5]->store((longlong)(tmp->start_time ?
876 - now - tmp->start_time : 0), FALSE);
877 + longlong value_in_time_column= 0;
878 + if(tmp->start_time)
880 + value_in_time_column = (now - tmp->start_time);
881 + if(value_in_time_column > now)
883 + value_in_time_column= 0;
886 + table->field[5]->store(value_in_time_column, FALSE);
889 if ((val= thread_state_info(tmp)))
891 diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc
892 --- a/sql/sys_vars.cc 2010-12-16 04:27:10.000000000 +0300
893 +++ b/sql/sys_vars.cc 2010-12-16 04:36:12.000000000 +0300
894 @@ -2836,6 +2836,116 @@
895 DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
896 ON_UPDATE(fix_log_state));
898 +const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join",
899 + "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
900 +static Sys_var_set Sys_log_slow_filter(
902 + "Log only the queries that followed certain execution plan. "
903 + "Multiple flags allowed in a comma-separated string. "
904 + "[qc_miss, full_scan, full_join, tmp_table, tmp_table_on_disk, "
905 + "filesort, filesort_on_disk]",
906 + SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG),
907 + log_slow_filter_name, DEFAULT(0));
908 +static Sys_var_ulong sys_log_slow_rate_limit(
909 + "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
910 + SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
911 + VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
912 +const char* log_slow_verbosity_name[] = {
913 + "microtime", "query_plan", "innodb",
914 + "profiling", "profling_use_getrusage",
915 + "minimal", "standard", "full", 0
917 +static ulonglong update_log_slow_verbosity_replace(ulonglong value, ulonglong what, ulonglong by)
919 + if((value & what) == what)
921 + value = value & (~what);
922 + value = value | by;
926 +void update_log_slow_verbosity(ulonglong* value_ptr)
928 + ulonglong &value = *value_ptr;
929 + ulonglong microtime= ULL(1) << SLOG_V_MICROTIME;
930 + ulonglong query_plan= ULL(1) << SLOG_V_QUERY_PLAN;
931 + ulonglong innodb= ULL(1) << SLOG_V_INNODB;
932 + ulonglong minimal= ULL(1) << SLOG_V_MINIMAL;
933 + ulonglong standard= ULL(1) << SLOG_V_STANDARD;
934 + ulonglong full= ULL(1) << SLOG_V_FULL;
935 + value= update_log_slow_verbosity_replace(value,minimal,microtime);
936 + value= update_log_slow_verbosity_replace(value,standard,microtime | query_plan);
937 + value= update_log_slow_verbosity_replace(value,full,microtime | query_plan | innodb);
939 +static bool update_log_slow_verbosity_helper(sys_var */*self*/, THD *thd,
940 + enum_var_type type)
942 + if(type == OPT_SESSION)
944 + update_log_slow_verbosity(&(thd->variables.log_slow_verbosity));
948 + update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
952 +void init_use_global_log_slow_control()
954 + update_log_slow_verbosity(&(global_system_variables.log_slow_verbosity));
956 +static Sys_var_set Sys_log_slow_verbosity(
957 + "log_slow_verbosity",
958 + "Choose how verbose the messages to your slow log will be. "
959 + "Multiple flags allowed in a comma-separated string. [microtime, query_plan, innodb, profiling, profiling_use_getrusage]",
960 + SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
961 + log_slow_verbosity_name, DEFAULT(SLOG_V_MICROTIME),
962 + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
963 + ON_UPDATE(update_log_slow_verbosity_helper));
964 +static Sys_var_mybool Sys_log_slow_slave_statements(
965 + "log_slow_slave_statements",
966 + "Log queries replayed be the slave SQL thread",
967 + GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
969 +static Sys_var_mybool Sys_log_slow_sp_statements(
970 + "log_slow_sp_statements",
971 + "Log slow statements executed by stored procedure to the slow log if it is open.",
972 + GLOBAL_VAR(opt_log_slow_sp_statements), CMD_LINE(OPT_ARG),
974 +static Sys_var_mybool Sys_log_slow_timestamp_every(
975 + "log_slow_timestamp_every",
976 + "Timestamp is printed for all records of the slow log even if they are same time.",
977 + GLOBAL_VAR(opt_log_slow_timestamp_every), CMD_LINE(OPT_ARG),
979 +const char *use_global_log_slow_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0};
980 +static bool update_use_global_log_slow_control(sys_var */*self*/, THD */*thd*/,
981 + enum_var_type /*type*/)
983 + if(opt_use_global_log_slow_control & (ULL(1) << SLOG_UG_ALL))
985 + opt_use_global_log_slow_control=
986 + SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
987 + SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
991 +void init_log_slow_verbosity()
993 + update_use_global_log_slow_control(0,0,OPT_GLOBAL);
995 +static Sys_var_set Sys_use_global_log_slow_control(
996 + "use_global_log_slow_control",
997 + "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]",
998 + GLOBAL_VAR(opt_use_global_log_slow_control), CMD_LINE(REQUIRED_ARG),
999 + use_global_log_slow_control_name, DEFAULT(0),
1000 + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
1001 + ON_UPDATE(update_use_global_log_slow_control));
1002 +static Sys_var_mybool Sys_slow_query_log_microseconds_timestamp(
1003 + "slow_query_log_microseconds_timestamp",
1004 + "Log slow statements executed by stored procedure to the slow log if it is open.",
1005 + GLOBAL_VAR(opt_slow_query_log_microseconds_timestamp), CMD_LINE(OPT_ARG),
1008 /* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
1009 static Sys_var_mybool Sys_log_slow(
1011 diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc
1012 --- a/sql/sql_profile.cc 2010-11-03 07:01:14.000000000 +0900
1013 +++ b/sql/sql_profile.cc 2010-12-02 20:26:35.448357413 +0900
1016 time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
1017 #ifdef HAVE_GETRUSAGE
1018 - getrusage(RUSAGE_SELF, &rusage);
1019 + if ((profile->get_profiling())->enabled_getrusage())
1020 + getrusage(RUSAGE_SELF, &rusage);
1021 #elif defined(_WIN32)
1023 // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
1024 @@ -251,6 +252,19 @@
1025 // measurable by this function.
1026 GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
1029 +#ifdef HAVE_CLOCK_GETTIME
1030 + struct timespec tp;
1032 + if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
1034 + cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
1039 + cpu_time_usecs= 0;
1045 finish_current_query();
1048 - enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0);
1049 + enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1050 + ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0);
1052 if (! enabled) DBUG_VOID_RETURN;
1055 status_change("ending", NULL, NULL, 0);
1057 if ((enabled) && /* ON at start? */
1058 - ((thd->variables.option_bits & OPTION_PROFILING) != 0) && /* and ON at end? */
1059 + (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
1060 + ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING)) != 0)) && /* and ON at end? */
1061 (current->query_source != NULL) &&
1062 (! current->entries.is_empty()))
1064 @@ -505,6 +521,118 @@
1068 +bool PROFILING::enabled_getrusage()
1070 + return ((thd->variables.log_slow_verbosity & (ULL(1) << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
1074 + For a given profile entry specified by a name and 2 time measurements,
1075 + print its normalized name (i.e. with all spaces replaced with underscores)
1076 + along with its wall clock and CPU time.
1079 +static void my_b_print_status(IO_CACHE *log_file, const char *status,
1080 + PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
1082 + DBUG_ENTER("my_b_print_status");
1083 + DBUG_ASSERT(log_file != NULL && status != NULL);
1084 + char query_time_buff[22+7];
1087 + my_b_printf(log_file, "Profile_");
1088 + for (tmp= status; *tmp; tmp++)
1089 + my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1091 + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1092 + (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
1093 + my_b_printf(log_file, ": %s ", query_time_buff);
1095 + my_b_printf(log_file, "Profile_");
1096 + for (tmp= status; *tmp; tmp++)
1097 + my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
1098 + my_b_printf(log_file, "_cpu: ");
1100 + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
1101 + (stop->cpu_time_usecs - start->cpu_time_usecs) /
1102 + (1000.0 * 1000 * 1000));
1103 + my_b_printf(log_file, "%s ", query_time_buff);
1109 + Print output for current query to file
1112 +int PROFILING::print_current(IO_CACHE *log_file)
1114 + DBUG_ENTER("PROFILING::print_current");
1115 + ulonglong row_number= 0;
1117 + QUERY_PROFILE *query;
1118 + /* Get current query */
1119 + if (current == NULL)
1126 + my_b_printf(log_file, "# ");
1128 + void *entry_iterator;
1129 + PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
1130 + /* ...and for each query, go through all its state-change steps. */
1131 + for (entry_iterator= query->entries.new_iterator();
1132 + entry_iterator != NULL;
1133 + entry_iterator= query->entries.iterator_next(entry_iterator),
1134 + previous=entry, row_number++)
1136 + entry= query->entries.iterator_value(entry_iterator);
1138 + /* Skip the first. We count spans of fence, not fence-posts. */
1139 + if (previous == NULL) {first= entry; continue;}
1141 + if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
1144 + We got here via a SHOW command. That means that we stored
1145 + information about the query we wish to show and that isn't
1146 + in a WHERE clause at a higher level to filter out rows we
1149 + Because that functionality isn't available in the server yet,
1150 + we must filter here, at the wrong level. Once one can con-
1151 + struct where and having conditions at the SQL layer, then this
1152 + condition should be ripped out.
1154 + if (thd->lex->profile_query_id == 0) /* 0 == show final query */
1156 + if (query != last)
1161 + if (thd->lex->profile_query_id != query->profiling_query_id)
1166 + my_b_print_status(log_file, previous->status, previous, entry);
1169 + my_b_write_byte(log_file, '\n');
1170 + if ((entry != NULL) && (first != NULL))
1172 + my_b_printf(log_file, "# ");
1173 + my_b_print_status(log_file, "total", first, entry);
1174 + my_b_write_byte(log_file, '\n');
1181 Fill the information schema table, "query_profile", as defined in show.cc .
1182 There are two ways to get to this function: Selecting from the information
1183 diff -ruN a/sql/sql_profile.h b/sql/sql_profile.h
1184 --- a/sql/sql_profile.h 2010-11-03 07:01:14.000000000 +0900
1185 +++ b/sql/sql_profile.h 2010-12-02 19:23:07.823955510 +0900
1186 @@ -164,11 +164,15 @@
1188 class PROF_MEASUREMENT
1191 - friend class QUERY_PROFILE;
1192 - friend class PROFILING;
1194 QUERY_PROFILE *profile;
1196 + char *allocated_status_memory;
1198 + void set_label(const char *status_arg, const char *function_arg,
1199 + const char *file_arg, unsigned int line_arg);
1204 #ifdef HAVE_GETRUSAGE
1205 struct rusage rusage;
1206 @@ -181,12 +185,7 @@
1210 - char *allocated_status_memory;
1212 - void set_label(const char *status_arg, const char *function_arg,
1213 - const char *file_arg, unsigned int line_arg);
1216 + double cpu_time_usecs;
1218 PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
1219 PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
1220 @@ -231,6 +230,11 @@
1222 /* Show this profile. This is called by PROFILING. */
1223 bool show(uint options);
1227 + inline PROFILING * get_profiling() { return profiling; };
1232 @@ -276,9 +280,11 @@
1235 bool show_profiles();
1236 + bool enabled_getrusage();
1238 /* ... from INFORMATION_SCHEMA.PROFILING ... */
1239 int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
1240 + int print_current(IO_CACHE *log_file);
1243 # endif /* HAVE_PROFILING */