1
/* Copyright (C) 2007 MySQL AB
3
This program is free software; you can redistribute it and/or modify
4
it under the terms of the GNU General Public License as published by
5
the Free Software Foundation; version 2 of the License.
7
This program is distributed in the hope that it will be useful,
8
but WITHOUT ANY WARRANTY; without even the implied warranty of
9
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
10
GNU General Public License for more details.
12
You should have received a copy of the GNU General Public License
13
along with this program; if not, write to the Free Software
14
Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA */
20
Implement query profiling as as list of metaphorical fences, with one fence
21
per query, and each fencepost a change of thd->proc_info state (with a
22
snapshot of system statistics). When asked, we can then iterate over the
23
fenceposts and calculate the distance between them, to inform the user what
24
happened during a particular query or thd->proc_info state.
26
User variables that inform profiling behavior:
27
- "profiling", boolean, session only, "Are queries profiled?"
28
- "profiling_history_size", integer, session + global, "Num queries stored?"
32
#include "mysql_priv.h"
35
#define TIME_FLOAT_DIGITS 9
36
/** two vals encoded: (dec*100)+len */
37
#define TIME_I_S_DECIMAL_SIZE (TIME_FLOAT_DIGITS*100)+(TIME_FLOAT_DIGITS-3)
39
#define MAX_QUERY_LENGTH 300
41
/* Reserved for systems that can't record the function name in source. */
42
const char * const _unknown_func_ = "<unknown>";
45
Connects Information_Schema and Profiling.
47
int fill_query_profile_statistics_info(THD *thd, TABLE_LIST *tables,
50
#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
51
return(thd->profiling.fill_statistics_info(thd, tables, cond));
53
my_error(ER_FEATURE_DISABLED, MYF(0), "SHOW PROFILE", "enable-profiling");
58
ST_FIELD_INFO query_profile_statistics_info[]=
60
/* name, length, type, value, maybe_null, old_name, open_method */
61
{"QUERY_ID", 20, MYSQL_TYPE_LONG, 0, false, "Query_id", SKIP_OPEN_TABLE},
62
{"SEQ", 20, MYSQL_TYPE_LONG, 0, false, "Seq", SKIP_OPEN_TABLE},
63
{"STATE", 30, MYSQL_TYPE_STRING, 0, false, "Status", SKIP_OPEN_TABLE},
64
{"DURATION", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, false, "Duration", SKIP_OPEN_TABLE},
65
{"CPU_USER", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, true, "CPU_user", SKIP_OPEN_TABLE},
66
{"CPU_SYSTEM", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, true, "CPU_system", SKIP_OPEN_TABLE},
67
{"CONTEXT_VOLUNTARY", 20, MYSQL_TYPE_LONG, 0, true, "Context_voluntary", SKIP_OPEN_TABLE},
68
{"CONTEXT_INVOLUNTARY", 20, MYSQL_TYPE_LONG, 0, true, "Context_involuntary", SKIP_OPEN_TABLE},
69
{"BLOCK_OPS_IN", 20, MYSQL_TYPE_LONG, 0, true, "Block_ops_in", SKIP_OPEN_TABLE},
70
{"BLOCK_OPS_OUT", 20, MYSQL_TYPE_LONG, 0, true, "Block_ops_out", SKIP_OPEN_TABLE},
71
{"MESSAGES_SENT", 20, MYSQL_TYPE_LONG, 0, true, "Messages_sent", SKIP_OPEN_TABLE},
72
{"MESSAGES_RECEIVED", 20, MYSQL_TYPE_LONG, 0, true, "Messages_received", SKIP_OPEN_TABLE},
73
{"PAGE_FAULTS_MAJOR", 20, MYSQL_TYPE_LONG, 0, true, "Page_faults_major", SKIP_OPEN_TABLE},
74
{"PAGE_FAULTS_MINOR", 20, MYSQL_TYPE_LONG, 0, true, "Page_faults_minor", SKIP_OPEN_TABLE},
75
{"SWAPS", 20, MYSQL_TYPE_LONG, 0, true, "Swaps", SKIP_OPEN_TABLE},
76
{"SOURCE_FUNCTION", 30, MYSQL_TYPE_STRING, 0, true, "Source_function", SKIP_OPEN_TABLE},
77
{"SOURCE_FILE", 20, MYSQL_TYPE_STRING, 0, true, "Source_file", SKIP_OPEN_TABLE},
78
{"SOURCE_LINE", 20, MYSQL_TYPE_LONG, 0, true, "Source_line", SKIP_OPEN_TABLE},
79
{NULL, 0, MYSQL_TYPE_STRING, 0, true, NULL, 0}
83
int make_profile_table_for_show(THD *thd, ST_SCHEMA_TABLE *schema_table)
85
int profile_options = thd->lex->profile_options;
86
int fields_include_condition_truth_values[]= {
91
profile_options & PROFILE_CPU, /* CPU_user */
92
profile_options & PROFILE_CPU, /* CPU_system */
93
profile_options & PROFILE_CONTEXT, /* Context_voluntary */
94
profile_options & PROFILE_CONTEXT, /* Context_involuntary */
95
profile_options & PROFILE_BLOCK_IO, /* Block_ops_in */
96
profile_options & PROFILE_BLOCK_IO, /* Block_ops_out */
97
profile_options & PROFILE_IPC, /* Messages_sent */
98
profile_options & PROFILE_IPC, /* Messages_received */
99
profile_options & PROFILE_PAGE_FAULTS, /* Page_faults_major */
100
profile_options & PROFILE_PAGE_FAULTS, /* Page_faults_minor */
101
profile_options & PROFILE_SWAPS, /* Swaps */
102
profile_options & PROFILE_SOURCE, /* Source_function */
103
profile_options & PROFILE_SOURCE, /* Source_file */
104
profile_options & PROFILE_SOURCE, /* Source_line */
107
ST_FIELD_INFO *field_info;
108
Name_resolution_context *context= &thd->lex->select_lex.context;
111
for (i= 0; schema_table->fields_info[i].field_name != NULL; i++)
113
if (! fields_include_condition_truth_values[i])
116
field_info= &schema_table->fields_info[i];
117
Item_field *field= new Item_field(context,
118
NullS, NullS, field_info->field_name);
121
field->set_name(field_info->old_name,
122
(uint) strlen(field_info->old_name),
123
system_charset_info);
124
if (add_item_to_list(thd, field))
132
#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
134
#define RUSAGE_USEC(tv) ((tv).tv_sec*1000*1000 + (tv).tv_usec)
135
#define RUSAGE_DIFF_USEC(tv1, tv2) (RUSAGE_USEC((tv1))-RUSAGE_USEC((tv2)))
138
PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char
140
:profile(profile_arg)
143
set_label(status_arg, NULL, NULL, 0);
146
PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg,
147
const char *status_arg,
148
const char *function_arg,
149
const char *file_arg,
150
unsigned int line_arg)
151
:profile(profile_arg)
154
set_label(status_arg, function_arg, file_arg, line_arg);
157
PROF_MEASUREMENT::~PROF_MEASUREMENT()
159
if (allocated_status_memory != NULL)
160
my_free(allocated_status_memory, MYF(0));
161
status= function= file= NULL;
164
void PROF_MEASUREMENT::set_label(const char *status_arg,
165
const char *function_arg,
166
const char *file_arg, unsigned int line_arg)
168
size_t sizes[3]; /* 3 == status+function+file */
172
Compute all the space we'll need to allocate one block for everything
173
we'll need, instead of N mallocs.
175
sizes[0]= (status_arg == NULL) ? 0 : strlen(status_arg) + 1;
176
sizes[1]= (function_arg == NULL) ? 0 : strlen(function_arg) + 1;
177
sizes[2]= (file_arg == NULL) ? 0 : strlen(file_arg) + 1;
179
allocated_status_memory= (char *) my_malloc(sizes[0] + sizes[1] + sizes[2], MYF(0));
180
DBUG_ASSERT(allocated_status_memory != NULL);
182
cursor= allocated_status_memory;
184
if (status_arg != NULL)
186
strcpy(cursor, status_arg);
193
if (function_arg != NULL)
195
strcpy(cursor, function_arg);
202
if (file_arg != NULL)
204
strcpy(cursor, file_arg);
215
This updates the statistics for this moment of time. It captures the state
216
of the running system, so later we can compare points in time and infer what
217
happened in the mean time. It should only be called immediately upon
218
instantiation of this PROF_MEASUREMENT.
220
@todo Implement resource capture for OSes not like BSD.
222
void PROF_MEASUREMENT::collect()
224
time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
225
#ifdef HAVE_GETRUSAGE
226
getrusage(RUSAGE_SELF, &rusage);
231
QUERY_PROFILE::QUERY_PROFILE(PROFILING *profiling_arg, const char *status_arg)
232
:profiling(profiling_arg), profiling_query_id(0), query_source(NULL)
234
profile_start= new PROF_MEASUREMENT(this, status_arg);
235
entries.push_back(profile_start);
236
profile_end= profile_start;
239
QUERY_PROFILE::~QUERY_PROFILE()
241
while (! entries.is_empty())
242
delete entries.pop();
244
if (query_source != NULL)
245
my_free(query_source, MYF(0));
249
@todo Provide a way to include the full text, as in SHOW PROCESSLIST.
251
void QUERY_PROFILE::set_query_source(char *query_source_arg,
252
uint query_length_arg)
254
/* Truncate to avoid DoS attacks. */
255
uint length= min(MAX_QUERY_LENGTH, query_length_arg);
257
DBUG_ASSERT(query_source == NULL); /* we don't leak memory */
258
if (query_source_arg != NULL)
259
query_source= my_strndup(query_source_arg, length, MYF(0));
262
void QUERY_PROFILE::new_status(const char *status_arg,
263
const char *function_arg, const char *file_arg,
264
unsigned int line_arg)
266
PROF_MEASUREMENT *prof;
267
DBUG_ENTER("QUERY_PROFILE::status");
269
DBUG_ASSERT(status_arg != NULL);
271
if ((function_arg != NULL) && (file_arg != NULL))
272
prof= new PROF_MEASUREMENT(this, status_arg, function_arg, file_arg, line_arg);
274
prof= new PROF_MEASUREMENT(this, status_arg);
277
entries.push_back(prof);
284
PROFILING::PROFILING()
285
:profile_id_counter(1), current(NULL), last(NULL)
289
PROFILING::~PROFILING()
291
while (! history.is_empty())
292
delete history.pop();
299
A new state is given, and that signals the profiler to start a new
300
timed step for the current query's profile.
302
@param status_arg name of this step
303
@param function_arg calling function (usually supplied from compiler)
304
@param function_arg calling file (usually supplied from compiler)
305
@param function_arg calling line number (usually supplied from compiler)
307
void PROFILING::status_change(const char *status_arg,
308
const char *function_arg,
309
const char *file_arg, unsigned int line_arg)
311
DBUG_ENTER("PROFILING::status_change");
313
if (status_arg == NULL) /* We don't know how to handle that */
316
if (current == NULL) /* This profile was already discarded. */
319
if (unlikely(enabled))
320
current->new_status(status_arg, function_arg, file_arg, line_arg);
326
Prepare to start processing a new query. It is an error to do this
327
if there's a query already in process; nesting is not supported.
329
@param initial_state (optional) name of period before first state change
331
void PROFILING::start_new_query(const char *initial_state)
333
DBUG_ENTER("PROFILING::start_new_query");
335
/* This should never happen unless the server is radically altered. */
336
if (unlikely(current != NULL))
338
DBUG_PRINT("warning", ("profiling code was asked to start a new query "
339
"before the old query was finished. This is "
341
finish_current_query();
344
enabled= (((thd)->options & OPTION_PROFILING) != 0);
346
if (! enabled) DBUG_VOID_RETURN;
348
DBUG_ASSERT(current == NULL);
349
current= new QUERY_PROFILE(this, initial_state);
355
Throw away the current profile, because it's useless or unwanted
358
void PROFILING::discard_current_query()
360
DBUG_ENTER("PROFILING::discard_current_profile");
369
Try to save the current profile entry, clean up the data if it shouldn't be
370
saved, and maintain the profile history size. Naturally, this may not
371
succeed if the profile was previously discarded, and that's expected.
373
void PROFILING::finish_current_query()
375
DBUG_ENTER("PROFILING::finish_current_profile");
378
/* The last fence-post, so we can support the span before this. */
379
status_change("ending", NULL, NULL, 0);
381
if ((enabled) && /* ON at start? */
382
((thd->options & OPTION_PROFILING) != 0) && /* and ON at end? */
383
(current->query_source != NULL) &&
384
(! current->entries.is_empty()))
386
current->profiling_query_id= next_profile_id(); /* assign an id */
388
history.push_back(current);
389
last= current; /* never contains something that is not in the history. */
399
/* Maintain the history size. */
400
while (history.elements > thd->variables.profiling_history_size)
401
delete history.pop();
406
bool PROFILING::show_profiles()
408
DBUG_ENTER("PROFILING::show_profiles");
410
List<Item> field_list;
412
field_list.push_back(new Item_return_int("Query_ID", 10,
414
field_list.push_back(new Item_return_int("Duration", TIME_FLOAT_DIGITS-1,
416
field_list.push_back(new Item_empty_string("Query", 40));
418
if (thd->protocol->send_fields(&field_list,
419
Protocol::SEND_NUM_ROWS | Protocol::SEND_EOF))
422
SELECT_LEX *sel= &thd->lex->select_lex;
423
SELECT_LEX_UNIT *unit= &thd->lex->unit;
425
Protocol *protocol= thd->protocol;
427
unit->set_limit(sel);
430
for (iterator= history.new_iterator();
432
iterator= history.iterator_next(iterator))
434
prof= history.iterator_value(iterator);
438
PROF_MEASUREMENT *ps= prof->profile_start;
439
PROF_MEASUREMENT *pe= prof->profile_end;
441
if (++idx <= unit->offset_limit_cnt)
443
if (idx > unit->select_limit_cnt)
446
protocol->prepare_for_resend();
447
protocol->store((uint32)(prof->profiling_query_id));
448
protocol->store((double)(pe->time_usecs - ps->time_usecs)/(1000.0*1000),
449
(uint32) TIME_FLOAT_DIGITS-1, &elapsed);
450
if (prof->query_source != NULL)
451
protocol->store(prof->query_source, strlen(prof->query_source),
452
system_charset_info);
454
protocol->store_null();
456
if (protocol->write())
464
At a point in execution where we know the query source, save the text
465
of it in the query profile.
467
This must be called exactly once per descrete statement.
469
void PROFILING::set_query_source(char *query_source_arg, uint query_length_arg)
471
DBUG_ENTER("PROFILING::set_query_source");
477
current->set_query_source(query_source_arg, query_length_arg);
479
DBUG_PRINT("info", ("no current profile to send query source to"));
484
Fill the information schema table, "query_profile", as defined in show.cc .
485
There are two ways to get to this function: Selecting from the information
486
schema, and a SHOW command.
488
int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond)
490
DBUG_ENTER("PROFILING::fill_statistics_info");
491
TABLE *table= tables->table;
492
ulonglong row_number= 0;
494
QUERY_PROFILE *query;
495
/* Go through each query in this thread's stored history... */
496
void *history_iterator;
497
for (history_iterator= history.new_iterator();
498
history_iterator != NULL;
499
history_iterator= history.iterator_next(history_iterator))
501
query= history.iterator_value(history_iterator);
504
Because we put all profiling info into a table that may be reordered, let
505
us also include a numbering of each state per query. The query_id and
506
the "seq" together are unique.
510
void *entry_iterator;
511
PROF_MEASUREMENT *entry, *previous= NULL;
512
/* ...and for each query, go through all its state-change steps. */
513
for (seq= 0, entry_iterator= query->entries.new_iterator();
514
entry_iterator != NULL;
515
entry_iterator= query->entries.iterator_next(entry_iterator),
516
seq++, previous=entry, row_number++)
518
entry= query->entries.iterator_value(entry_iterator);
520
/* Skip the first. We count spans of fence, not fence-posts. */
521
if (previous == NULL) continue;
523
if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
526
We got here via a SHOW command. That means that we stored
527
information about the query we wish to show and that isn't
528
in a WHERE clause at a higher level to filter out rows we
531
Because that functionality isn't available in the server yet,
532
we must filter here, at the wrong level. Once one can con-
533
struct where and having conditions at the SQL layer, then this
534
condition should be ripped out.
536
if (thd->lex->profile_query_id == 0) /* 0 == show final query */
543
if (thd->lex->profile_query_id != query->profiling_query_id)
548
/* Set default values for this row. */
549
restore_record(table, s->default_values);
552
The order of these fields is set by the query_profile_statistics_info
555
table->field[0]->store((ulonglong) query->profiling_query_id, TRUE);
556
table->field[1]->store((ulonglong) seq, TRUE); /* the step in the sequence */
558
This entry, n, has a point in time, T(n), and a status phrase, S(n).
559
The status phrase S(n) describes the period of time that begins at
560
T(n). The previous status phrase S(n-1) describes the period of time
561
that starts at T(n-1) and ends at T(n). Since we want to describe the
562
time that a status phrase took T(n)-T(n-1), this line must describe the
565
table->field[2]->store(previous->status, strlen(previous->status),
566
system_charset_info);
568
my_decimal duration_decimal;
569
double2my_decimal(E_DEC_FATAL_ERROR,
570
(entry->time_usecs-previous->time_usecs)/(1000.0*1000),
573
table->field[3]->store_decimal(&duration_decimal);
576
#ifdef HAVE_GETRUSAGE
578
my_decimal cpu_utime_decimal, cpu_stime_decimal;
580
double2my_decimal(E_DEC_FATAL_ERROR,
581
RUSAGE_DIFF_USEC(entry->rusage.ru_utime,
582
previous->rusage.ru_utime) /
586
double2my_decimal(E_DEC_FATAL_ERROR,
587
RUSAGE_DIFF_USEC(entry->rusage.ru_stime,
588
previous->rusage.ru_stime) /
592
table->field[4]->store_decimal(&cpu_utime_decimal);
593
table->field[5]->store_decimal(&cpu_stime_decimal);
594
table->field[4]->set_notnull();
595
table->field[5]->set_notnull();
597
/* TODO: Add CPU-usage info for non-BSD systems */
600
#ifdef HAVE_GETRUSAGE
601
table->field[6]->store((uint32)(entry->rusage.ru_nvcsw -
602
previous->rusage.ru_nvcsw));
603
table->field[6]->set_notnull();
604
table->field[7]->store((uint32)(entry->rusage.ru_nivcsw -
605
previous->rusage.ru_nivcsw));
606
table->field[7]->set_notnull();
608
/* TODO: Add context switch info for non-BSD systems */
611
#ifdef HAVE_GETRUSAGE
612
table->field[8]->store((uint32)(entry->rusage.ru_inblock -
613
previous->rusage.ru_inblock));
614
table->field[8]->set_notnull();
615
table->field[9]->store((uint32)(entry->rusage.ru_oublock -
616
previous->rusage.ru_oublock));
617
table->field[9]->set_notnull();
619
/* TODO: Add block IO info for non-BSD systems */
622
#ifdef HAVE_GETRUSAGE
623
table->field[10]->store((uint32)(entry->rusage.ru_msgsnd -
624
previous->rusage.ru_msgsnd), true);
625
table->field[10]->set_notnull();
626
table->field[11]->store((uint32)(entry->rusage.ru_msgrcv -
627
previous->rusage.ru_msgrcv), true);
628
table->field[11]->set_notnull();
630
/* TODO: Add message info for non-BSD systems */
633
#ifdef HAVE_GETRUSAGE
634
table->field[12]->store((uint32)(entry->rusage.ru_majflt -
635
previous->rusage.ru_majflt), true);
636
table->field[12]->set_notnull();
637
table->field[13]->store((uint32)(entry->rusage.ru_minflt -
638
previous->rusage.ru_minflt), true);
639
table->field[13]->set_notnull();
641
/* TODO: Add page fault info for non-BSD systems */
644
#ifdef HAVE_GETRUSAGE
645
table->field[14]->store((uint32)(entry->rusage.ru_nswap -
646
previous->rusage.ru_nswap), true);
647
table->field[14]->set_notnull();
649
/* TODO: Add swap info for non-BSD systems */
652
/* Emit the location that started this step, not that ended it. */
653
if ((previous->function != NULL) && (previous->file != NULL))
655
table->field[15]->store(previous->function, strlen(previous->function),
656
system_charset_info);
657
table->field[15]->set_notnull();
658
table->field[16]->store(previous->file, strlen(previous->file), system_charset_info);
659
table->field[16]->set_notnull();
660
table->field[17]->store(previous->line, true);
661
table->field[17]->set_notnull();
664
if (schema_table_store_record(thd, table))
672
#endif /* ENABLED_PROFILING */
added
removed
sql/sql_profile.cc
