1 /* Copyright (c) 2007, 2021, Oracle and/or its affiliates.
2
3 This program is free software; you can redistribute it and/or modify
4 it under the terms of the GNU General Public License, version 2.0,
5 as published by the Free Software Foundation.
6
7 This program is also distributed with certain software (including
8 but not limited to OpenSSL) that is licensed under separate terms,
9 as designated in a particular file or component or in included license
10 documentation. The authors of MySQL hereby grant you an additional
11 permission to link the program and your derivative works with the
12 separately licensed software that they have included with MySQL.
13
14 This program is distributed in the hope that it will be useful,
15 but WITHOUT ANY WARRANTY; without even the implied warranty of
16 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
17 GNU General Public License, version 2.0, for more details.
18
19 You should have received a copy of the GNU General Public License
20 along with this program; if not, write to the Free Software Foundation,
21 51 Franklin Street, Suite 500, Boston, MA 02110-1335 USA */
22
23
24 /**
25 @file
26
27 Implement query profiling as as list of metaphorical fences, with one fence
28 per query, and each fencepost a change of thd->proc_info state (with a
29 snapshot of system statistics). When asked, we can then iterate over the
30 fenceposts and calculate the distance between them, to inform the user what
31 happened during a particular query or thd->proc_info state.
32
33 User variables that inform profiling behavior:
34 - "profiling", boolean, session only, "Are queries profiled?"
35 - "profiling_history_size", integer, session + global, "Num queries stored?"
36 */
37
38
39 #include "sql_profile.h"
40 #include "my_sys.h"
41 #include "sql_show.h" // schema_table_store_record
42 #include "sql_class.h" // THD
43 #include "log.h"
44
45 #include <algorithm>
46
47 using std::min;
48 using std::max;
49
50 #define TIME_FLOAT_DIGITS 9
51 /** two vals encoded: (dec*100)+len */
52 #define TIME_I_S_DECIMAL_SIZE (TIME_FLOAT_DIGITS*100)+(TIME_FLOAT_DIGITS-3)
53
54 static const size_t MAX_QUERY_LENGTH= 300;
55 #define MAX_QUERY_HISTORY 101U
56
57 /**
58 Connects Information_Schema and Profiling.
59 */
fill_query_profile_statistics_info(THD * thd,TABLE_LIST * tables,Item * cond)60 int fill_query_profile_statistics_info(THD *thd, TABLE_LIST *tables,
61 Item *cond)
62 {
63 #if defined(ENABLED_PROFILING)
64 const char *old= thd->lex->sql_command == SQLCOM_SHOW_PROFILE ?
65 "SHOW PROFILE" : "INFORMATION_SCHEMA.PROFILING";
66
67 assert(thd->lex->sql_command != SQLCOM_SHOW_PROFILES);
68
69 push_deprecated_warn(thd, old, "Performance Schema");
70 return(thd->profiling.fill_statistics_info(thd, tables, cond));
71 #else
72 my_error(ER_FEATURE_DISABLED, MYF(0), "SHOW PROFILE", "enable-profiling");
73 return(1);
74 #endif
75 }
76
77 ST_FIELD_INFO query_profile_statistics_info[]=
78 {
79 /* name, length, type, value, maybe_null, old_name, open_method */
80 {"QUERY_ID", 20, MYSQL_TYPE_LONG, 0, false, "Query_id", SKIP_OPEN_TABLE},
81 {"SEQ", 20, MYSQL_TYPE_LONG, 0, false, "Seq", SKIP_OPEN_TABLE},
82 {"STATE", 30, MYSQL_TYPE_STRING, 0, false, "Status", SKIP_OPEN_TABLE},
83 {"DURATION", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, false, "Duration", SKIP_OPEN_TABLE},
84 {"CPU_USER", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, true, "CPU_user", SKIP_OPEN_TABLE},
85 {"CPU_SYSTEM", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, true, "CPU_system", SKIP_OPEN_TABLE},
86 {"CONTEXT_VOLUNTARY", 20, MYSQL_TYPE_LONG, 0, true, "Context_voluntary", SKIP_OPEN_TABLE},
87 {"CONTEXT_INVOLUNTARY", 20, MYSQL_TYPE_LONG, 0, true, "Context_involuntary", SKIP_OPEN_TABLE},
88 {"BLOCK_OPS_IN", 20, MYSQL_TYPE_LONG, 0, true, "Block_ops_in", SKIP_OPEN_TABLE},
89 {"BLOCK_OPS_OUT", 20, MYSQL_TYPE_LONG, 0, true, "Block_ops_out", SKIP_OPEN_TABLE},
90 {"MESSAGES_SENT", 20, MYSQL_TYPE_LONG, 0, true, "Messages_sent", SKIP_OPEN_TABLE},
91 {"MESSAGES_RECEIVED", 20, MYSQL_TYPE_LONG, 0, true, "Messages_received", SKIP_OPEN_TABLE},
92 {"PAGE_FAULTS_MAJOR", 20, MYSQL_TYPE_LONG, 0, true, "Page_faults_major", SKIP_OPEN_TABLE},
93 {"PAGE_FAULTS_MINOR", 20, MYSQL_TYPE_LONG, 0, true, "Page_faults_minor", SKIP_OPEN_TABLE},
94 {"SWAPS", 20, MYSQL_TYPE_LONG, 0, true, "Swaps", SKIP_OPEN_TABLE},
95 {"SOURCE_FUNCTION", 30, MYSQL_TYPE_STRING, 0, true, "Source_function", SKIP_OPEN_TABLE},
96 {"SOURCE_FILE", 20, MYSQL_TYPE_STRING, 0, true, "Source_file", SKIP_OPEN_TABLE},
97 {"SOURCE_LINE", 20, MYSQL_TYPE_LONG, 0, true, "Source_line", SKIP_OPEN_TABLE},
98 {NULL, 0, MYSQL_TYPE_STRING, 0, true, NULL, 0}
99 };
100
101
make_profile_table_for_show(THD * thd,ST_SCHEMA_TABLE * schema_table)102 int make_profile_table_for_show(THD *thd, ST_SCHEMA_TABLE *schema_table)
103 {
104 uint profile_options = thd->lex->profile_options;
105 uint fields_include_condition_truth_values[]= {
106 FALSE, /* Query_id */
107 FALSE, /* Seq */
108 TRUE, /* Status */
109 TRUE, /* Duration */
110 profile_options & PROFILE_CPU, /* CPU_user */
111 profile_options & PROFILE_CPU, /* CPU_system */
112 profile_options & PROFILE_CONTEXT, /* Context_voluntary */
113 profile_options & PROFILE_CONTEXT, /* Context_involuntary */
114 profile_options & PROFILE_BLOCK_IO, /* Block_ops_in */
115 profile_options & PROFILE_BLOCK_IO, /* Block_ops_out */
116 profile_options & PROFILE_IPC, /* Messages_sent */
117 profile_options & PROFILE_IPC, /* Messages_received */
118 profile_options & PROFILE_PAGE_FAULTS, /* Page_faults_major */
119 profile_options & PROFILE_PAGE_FAULTS, /* Page_faults_minor */
120 profile_options & PROFILE_SWAPS, /* Swaps */
121 profile_options & PROFILE_SOURCE, /* Source_function */
122 profile_options & PROFILE_SOURCE, /* Source_file */
123 profile_options & PROFILE_SOURCE, /* Source_line */
124 };
125
126 ST_FIELD_INFO *field_info;
127 Name_resolution_context *context= &thd->lex->select_lex->context;
128 int i;
129
130 for (i= 0; schema_table->fields_info[i].field_name != NULL; i++)
131 {
132 if (! fields_include_condition_truth_values[i])
133 continue;
134
135 field_info= &schema_table->fields_info[i];
136 Item_field *field= new Item_field(context,
137 NullS, NullS, field_info->field_name);
138 if (field)
139 {
140 field->item_name.copy(field_info->old_name);
141 if (add_item_to_list(thd, field))
142 return 1;
143 }
144 }
145 return 0;
146 }
147
148
149 #if defined(ENABLED_PROFILING)
150
151 #define RUSAGE_USEC(tv) ((tv).tv_sec*1000*1000 + (tv).tv_usec)
152 #define RUSAGE_DIFF_USEC(tv1, tv2) (RUSAGE_USEC((tv1))-RUSAGE_USEC((tv2)))
153
154 #ifdef _WIN32
FileTimeToQuadWord(FILETIME * ft)155 static ULONGLONG FileTimeToQuadWord(FILETIME *ft)
156 {
157 // Overlay FILETIME onto a ULONGLONG.
158 union {
159 ULONGLONG qwTime;
160 FILETIME ft;
161 } u;
162
163 u.ft = *ft;
164 return u.qwTime;
165 }
166
167
168 // Get time difference between to FILETIME objects in seconds.
GetTimeDiffInSeconds(FILETIME * a,FILETIME * b)169 static double GetTimeDiffInSeconds(FILETIME *a, FILETIME *b)
170 {
171 return ((FileTimeToQuadWord(a) - FileTimeToQuadWord(b)) / 1e7);
172 }
173 #endif
174
PROF_MEASUREMENT(QUERY_PROFILE * profile_arg,const char * status_arg)175 PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char
176 *status_arg)
177 :profile(profile_arg)
178 {
179 collect();
180 set_label(status_arg, NULL, NULL, 0);
181 }
182
PROF_MEASUREMENT(QUERY_PROFILE * profile_arg,const char * status_arg,const char * function_arg,const char * file_arg,unsigned int line_arg)183 PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg,
184 const char *status_arg,
185 const char *function_arg,
186 const char *file_arg,
187 unsigned int line_arg)
188 :profile(profile_arg)
189 {
190 collect();
191 set_label(status_arg, function_arg, file_arg, line_arg);
192 }
193
~PROF_MEASUREMENT()194 PROF_MEASUREMENT::~PROF_MEASUREMENT()
195 {
196 my_free(allocated_status_memory);
197 status= function= file= NULL;
198 }
199
set_label(const char * status_arg,const char * function_arg,const char * file_arg,unsigned int line_arg)200 void PROF_MEASUREMENT::set_label(const char *status_arg,
201 const char *function_arg,
202 const char *file_arg, unsigned int line_arg)
203 {
204 size_t sizes[3]; /* 3 == status+function+file */
205 char *cursor;
206
207 /*
208 Compute all the space we'll need to allocate one block for everything
209 we'll need, instead of N mallocs.
210 */
211 sizes[0]= (status_arg == NULL) ? 0 : strlen(status_arg) + 1;
212 sizes[1]= (function_arg == NULL) ? 0 : strlen(function_arg) + 1;
213 sizes[2]= (file_arg == NULL) ? 0 : strlen(file_arg) + 1;
214
215 allocated_status_memory= (char *) my_malloc(key_memory_PROFILE,
216 sizes[0] + sizes[1] + sizes[2], MYF(0));
217 assert(allocated_status_memory != NULL);
218
219 cursor= allocated_status_memory;
220
221 if (status_arg != NULL)
222 {
223 strcpy(cursor, status_arg);
224 status= cursor;
225 cursor+= sizes[0];
226 }
227 else
228 status= NULL;
229
230 if (function_arg != NULL)
231 {
232 strcpy(cursor, function_arg);
233 function= cursor;
234 cursor+= sizes[1];
235 }
236 else
237 function= NULL;
238
239 if (file_arg != NULL)
240 {
241 strcpy(cursor, file_arg);
242 file= cursor;
243 cursor+= sizes[2];
244 }
245 else
246 file= NULL;
247
248 line= line_arg;
249 }
250
251 /**
252 This updates the statistics for this moment of time. It captures the state
253 of the running system, so later we can compare points in time and infer what
254 happened in the mean time. It should only be called immediately upon
255 instantiation of this PROF_MEASUREMENT.
256
257 @todo Implement resource capture for OSes not like BSD.
258 */
collect()259 void PROF_MEASUREMENT::collect()
260 {
261 time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
262 #ifdef HAVE_GETRUSAGE
263 if ((profile->get_profiling())->enabled_getrusage())
264 {
265 #ifdef RUSAGE_THREAD
266 getrusage(RUSAGE_THREAD, &rusage);
267 #else
268 getrusage(RUSAGE_SELF, &rusage);
269 #endif
270 }
271 #elif defined(_WIN32)
272 FILETIME ftDummy;
273 // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
274 // which is typically ~15ms. So intervals shorter than that will not be
275 // measurable by this function.
276 GetProcessTimes(GetCurrentProcess(), &ftDummy, &ftDummy, &ftKernel, &ftUser);
277 #endif
278
279 #ifdef HAVE_CLOCK_GETTIME
280 struct timespec tp;
281
282 if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
283 {
284 cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
285 }
286 else
287 #endif
288 {
289 cpu_time_usecs= 0;
290 }
291 }
292
293
QUERY_PROFILE(PROFILING * profiling_arg,const char * status_arg)294 QUERY_PROFILE::QUERY_PROFILE(PROFILING *profiling_arg, const char *status_arg)
295 :profiling(profiling_arg), profiling_query_id(0), m_query_source(NULL_STR)
296 {
297 m_seq_counter= 1;
298 PROF_MEASUREMENT *prof= new PROF_MEASUREMENT(this, status_arg);
299 prof->m_seq= m_seq_counter++;
300 m_start_time_usecs= prof->time_usecs;
301 m_end_time_usecs= m_start_time_usecs;
302 entries.push_back(prof);
303 }
304
~QUERY_PROFILE()305 QUERY_PROFILE::~QUERY_PROFILE()
306 {
307 while (! entries.is_empty())
308 delete entries.pop();
309
310 my_free(m_query_source.str);
311 }
312
313 /**
314 @todo Provide a way to include the full text, as in SHOW PROCESSLIST.
315 */
set_query_source(const char * query_source_arg,size_t query_length_arg)316 void QUERY_PROFILE::set_query_source(const char *query_source_arg,
317 size_t query_length_arg)
318 {
319 /* Truncate to avoid DoS attacks. */
320 size_t length= min(MAX_QUERY_LENGTH, query_length_arg);
321
322 assert(m_query_source.str == NULL); /* we don't leak memory */
323 if (query_source_arg != NULL)
324 {
325 m_query_source.str= my_strndup(key_memory_PROFILE,
326 query_source_arg, length, MYF(0));
327 m_query_source.length= length;
328 }
329 }
330
new_status(const char * status_arg,const char * function_arg,const char * file_arg,unsigned int line_arg)331 void QUERY_PROFILE::new_status(const char *status_arg,
332 const char *function_arg, const char *file_arg,
333 unsigned int line_arg)
334 {
335 PROF_MEASUREMENT *prof;
336 DBUG_ENTER("QUERY_PROFILE::status");
337
338 assert(status_arg != NULL);
339
340 if ((function_arg != NULL) && (file_arg != NULL))
341 prof= new PROF_MEASUREMENT(this, status_arg, function_arg, base_name(file_arg), line_arg);
342 else
343 prof= new PROF_MEASUREMENT(this, status_arg);
344
345 prof->m_seq= m_seq_counter++;
346 m_end_time_usecs= prof->time_usecs;
347 entries.push_back(prof);
348
349 /* Maintain the query history size. */
350 while (entries.elements > MAX_QUERY_HISTORY)
351 delete entries.pop();
352
353 DBUG_VOID_RETURN;
354 }
355
356
357
PROFILING()358 PROFILING::PROFILING()
359 :profile_id_counter(1), current(NULL), last(NULL)
360 {
361 }
362
~PROFILING()363 PROFILING::~PROFILING()
364 {
365 while (! history.is_empty())
366 delete history.pop();
367
368 if (current != NULL)
369 delete current;
370 }
371
372 /**
373 A new state is given, and that signals the profiler to start a new
374 timed step for the current query's profile.
375
376 @param status_arg name of this step
377 @param function_arg calling function (usually supplied from compiler)
378 @param function_arg calling file (usually supplied from compiler)
379 @param function_arg calling line number (usually supplied from compiler)
380 */
status_change(const char * status_arg,const char * function_arg,const char * file_arg,unsigned int line_arg)381 void PROFILING::status_change(const char *status_arg,
382 const char *function_arg,
383 const char *file_arg, unsigned int line_arg)
384 {
385 DBUG_ENTER("PROFILING::status_change");
386
387 if (status_arg == NULL) /* We don't know how to handle that */
388 DBUG_VOID_RETURN;
389
390 if (current == NULL) /* This profile was already discarded. */
391 DBUG_VOID_RETURN;
392
393 if (unlikely(enabled))
394 current->new_status(status_arg, function_arg, file_arg, line_arg);
395
396 DBUG_VOID_RETURN;
397 }
398
399 /**
400 Prepare to start processing a new query. It is an error to do this
401 if there's a query already in process; nesting is not supported.
402
403 @param initial_state (optional) name of period before first state change
404 */
start_new_query(const char * initial_state)405 void PROFILING::start_new_query(const char *initial_state)
406 {
407 DBUG_ENTER("PROFILING::start_new_query");
408
409 /* This should never happen unless the server is radically altered. */
410 if (unlikely(current != NULL))
411 {
412 DBUG_PRINT("warning", ("profiling code was asked to start a new query "
413 "before the old query was finished. This is "
414 "probably a bug."));
415 finish_current_query();
416 }
417
418 enabled= ((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
419 ((thd->variables.log_slow_verbosity
420 & (1ULL << SLOG_V_PROFILING)) != 0);
421
422 if (! enabled) DBUG_VOID_RETURN;
423
424 assert(current == NULL);
425 current= new QUERY_PROFILE(this, initial_state);
426
427 DBUG_VOID_RETURN;
428 }
429
430 /**
431 Throw away the current profile, because it's useless or unwanted
432 or corrupted.
433 */
discard_current_query()434 void PROFILING::discard_current_query()
435 {
436 DBUG_ENTER("PROFILING::discard_current_profile");
437
438 delete current;
439 current= NULL;
440
441 DBUG_VOID_RETURN;
442 }
443
444 /**
445 Try to save the current profile entry, clean up the data if it shouldn't be
446 saved, and maintain the profile history size. Naturally, this may not
447 succeed if the profile was previously discarded, and that's expected.
448 */
finish_current_query()449 void PROFILING::finish_current_query()
450 {
451 DBUG_ENTER("PROFILING::finish_current_profile");
452 if (current != NULL)
453 {
454 /* The last fence-post, so we can support the span before this. */
455 status_change("ending", NULL, NULL, 0);
456
457 if ((enabled) && /* ON at start? */
458 (((thd->variables.option_bits & OPTION_PROFILING) != 0) ||
459 ((thd->variables.log_slow_verbosity & (1ULL << SLOG_V_PROFILING))
460 != 0)) && /* and ON at end? */
461 (current->m_query_source.str != NULL) &&
462 (! current->entries.is_empty()))
463 {
464 current->profiling_query_id= next_profile_id(); /* assign an id */
465
466 history.push_back(current);
467 last= current; /* never contains something that is not in the history. */
468 current= NULL;
469 }
470 else
471 {
472 delete current;
473 current= NULL;
474 }
475 }
476
477 /* Maintain the history size. */
478 while (history.elements > thd->variables.profiling_history_size)
479 delete history.pop();
480
481 DBUG_VOID_RETURN;
482 }
483
show_profiles()484 bool PROFILING::show_profiles()
485 {
486 DBUG_ENTER("PROFILING::show_profiles");
487 QUERY_PROFILE *prof;
488 List<Item> field_list;
489
490 field_list.push_back(new Item_return_int("Query_ID", 10,
491 MYSQL_TYPE_LONG));
492 field_list.push_back(new Item_return_int("Duration", TIME_FLOAT_DIGITS-1,
493 MYSQL_TYPE_DOUBLE));
494 field_list.push_back(new Item_empty_string("Query", 40));
495
496 if (thd->send_result_metadata(&field_list,
497 Protocol::SEND_NUM_ROWS | Protocol::SEND_EOF))
498 DBUG_RETURN(TRUE);
499
500 SELECT_LEX *sel= thd->lex->select_lex;
501 SELECT_LEX_UNIT *unit= thd->lex->unit;
502 ha_rows idx= 0;
503 Protocol *protocol= thd->get_protocol();
504
505 unit->set_limit(sel);
506
507 void *iterator;
508 for (iterator= history.new_iterator();
509 iterator != NULL;
510 iterator= history.iterator_next(iterator))
511 {
512 prof= history.iterator_value(iterator);
513
514 String elapsed;
515
516 double query_time_usecs= prof->m_end_time_usecs - prof->m_start_time_usecs;
517
518 if (++idx <= unit->offset_limit_cnt)
519 continue;
520 if (idx > unit->select_limit_cnt)
521 break;
522
523 protocol->start_row();
524 protocol->store((uint32)(prof->profiling_query_id));
525 protocol->store((double)(query_time_usecs/(1000.0*1000)),
526 (uint32) TIME_FLOAT_DIGITS-1, &elapsed);
527 if (prof->m_query_source.str != NULL)
528 protocol->store(prof->m_query_source.str, prof->m_query_source.length,
529 system_charset_info);
530 else
531 protocol->store_null();
532
533 if (protocol->end_row())
534 DBUG_RETURN(TRUE);
535 }
536 my_eof(thd);
537 DBUG_RETURN(FALSE);
538 }
539
540 /**
541 At a point in execution where we know the query source, save the text
542 of it in the query profile.
543
544 This must be called exactly once per descrete statement.
545 */
set_query_source(const char * query_source_arg,size_t query_length_arg)546 void PROFILING::set_query_source(const char *query_source_arg, size_t query_length_arg)
547 {
548 DBUG_ENTER("PROFILING::set_query_source");
549
550 if (! enabled)
551 DBUG_VOID_RETURN;
552
553 if (current != NULL)
554 current->set_query_source(query_source_arg, query_length_arg);
555 else
556 DBUG_PRINT("info", ("no current profile to send query source to"));
557 DBUG_VOID_RETURN;
558 }
559
enabled_getrusage() const560 bool PROFILING::enabled_getrusage() const
561 {
562 return ((thd->variables.log_slow_verbosity
563 & (1ULL << SLOG_V_PROFILING_USE_GETRUSAGE)) != 0);
564 }
565
566 /**
567 For a given profile entry specified by a name and 2 time measurements,
568 print its normalized name (i.e. with all spaces replaced with underscores)
569 along with its wall clock and CPU time.
570 */
571
my_b_print_status(IO_CACHE * log_file,const char * status,PROF_MEASUREMENT * start,PROF_MEASUREMENT * stop)572 static void my_b_print_status(IO_CACHE *log_file, const char *status,
573 PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
574 {
575 DBUG_ENTER("my_b_print_status");
576 assert(log_file != NULL);
577 assert(status != NULL);
578 char query_time_buff[22+7];
579 const char *tmp;
580
581 my_b_printf(log_file, "Profile_");
582 for (tmp= status; *tmp; tmp++)
583 my_b_printf(log_file, "%c", *tmp == ' ' ? '_' : *tmp);
584
585 snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
586 (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
587 my_b_printf(log_file, ": %s ", query_time_buff);
588
589 my_b_printf(log_file, "Profile_");
590 for (tmp= status; *tmp; tmp++)
591 my_b_printf(log_file, "%c", *tmp == ' ' ? '_' : *tmp);
592 my_b_printf(log_file, "_cpu: ");
593
594 snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
595 (stop->cpu_time_usecs - start->cpu_time_usecs) /
596 (1000.0 * 1000 * 1000));
597 my_b_printf(log_file, "%s ", query_time_buff);
598
599 DBUG_VOID_RETURN;
600 }
601
602 /**
603 Print output for current query to file
604 */
605
print_current(IO_CACHE * log_file) const606 int PROFILING::print_current(IO_CACHE *log_file) const
607 {
608 DBUG_ENTER("PROFILING::print_current");
609 ulonglong row_number= 0;
610
611 QUERY_PROFILE *query;
612 /* Get current query */
613 if (current == NULL)
614 {
615 DBUG_RETURN(0);
616 }
617
618 query= current;
619
620 my_b_printf(log_file, "# ");
621
622 void *entry_iterator;
623 PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
624 /* ...and for each query, go through all its state-change steps. */
625 for (entry_iterator= query->entries.new_iterator();
626 entry_iterator != NULL;
627 entry_iterator= query->entries.iterator_next(entry_iterator),
628 previous=entry, row_number++)
629 {
630 entry= query->entries.iterator_value(entry_iterator);
631
632 /* Skip the first. We count spans of fence, not fence-posts. */
633 if (previous == NULL) {first= entry; continue;}
634
635 if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
636 {
637 /*
638 We got here via a SHOW command. That means that we stored
639 information about the query we wish to show and that isn't
640 in a WHERE clause at a higher level to filter out rows we
641 wish to exclude.
642
643 Because that functionality isn't available in the server yet,
644 we must filter here, at the wrong level. Once one can con-
645 struct where and having conditions at the SQL layer, then this
646 condition should be ripped out.
647 */
648 if (thd->lex->query_id == 0) /* 0 == show final query */
649 {
650 if (query != last)
651 continue;
652 }
653 else
654 {
655 if (thd->lex->query_id != query->profiling_query_id)
656 continue;
657 }
658 }
659
660 my_b_print_status(log_file, previous->status, previous, entry);
661 }
662
663 my_b_printf(log_file, "\n");
664 if ((entry != NULL) && (first != NULL))
665 {
666 my_b_printf(log_file, "# ");
667 my_b_print_status(log_file, "total", first, entry);
668 my_b_printf(log_file, "\n");
669 }
670
671 DBUG_RETURN(0);
672 }
673
674 /**
675 Fill the information schema table, "query_profile", as defined in show.cc .
676 There are two ways to get to this function: Selecting from the information
677 schema, and a SHOW command.
678 */
fill_statistics_info(THD * thd_arg,TABLE_LIST * tables,Item * cond)679 int PROFILING::fill_statistics_info(THD *thd_arg, TABLE_LIST *tables, Item *cond)
680 {
681 DBUG_ENTER("PROFILING::fill_statistics_info");
682 TABLE *table= tables->table;
683 ulonglong row_number= 0;
684
685 QUERY_PROFILE *query;
686 /* Go through each query in this thread's stored history... */
687 void *history_iterator;
688 for (history_iterator= history.new_iterator();
689 history_iterator != NULL;
690 history_iterator= history.iterator_next(history_iterator))
691 {
692 query= history.iterator_value(history_iterator);
693
694 /*
695 Because we put all profiling info into a table that may be reordered, let
696 us also include a numbering of each state per query. The query_id and
697 the "seq" together are unique.
698 */
699 ulong seq;
700
701 void *entry_iterator;
702 PROF_MEASUREMENT *entry, *previous= NULL;
703 /* ...and for each query, go through all its state-change steps. */
704 for (entry_iterator= query->entries.new_iterator();
705 entry_iterator != NULL;
706 entry_iterator= query->entries.iterator_next(entry_iterator),
707 previous=entry, row_number++)
708 {
709 entry= query->entries.iterator_value(entry_iterator);
710 seq= entry->m_seq;
711
712 /* Skip the first. We count spans of fence, not fence-posts. */
713 if (previous == NULL) continue;
714
715 if (thd_arg->lex->sql_command == SQLCOM_SHOW_PROFILE)
716 {
717 /*
718 We got here via a SHOW command. That means that we stored
719 information about the query we wish to show and that isn't
720 in a WHERE clause at a higher level to filter out rows we
721 wish to exclude.
722
723 Because that functionality isn't available in the server yet,
724 we must filter here, at the wrong level. Once one can con-
725 struct where and having conditions at the SQL layer, then this
726 condition should be ripped out.
727 */
728 if (thd_arg->lex->query_id == 0) /* 0 == show final query */
729 {
730 if (query != last)
731 continue;
732 }
733 else
734 {
735 if (thd_arg->lex->query_id != query->profiling_query_id)
736 continue;
737 }
738 }
739
740 /* Set default values for this row. */
741 restore_record(table, s->default_values);
742
743 /*
744 The order of these fields is set by the query_profile_statistics_info
745 array.
746 */
747 table->field[0]->store((ulonglong) query->profiling_query_id, TRUE);
748 table->field[1]->store((ulonglong) seq, TRUE); /* the step in the sequence */
749 /*
750 This entry, n, has a point in time, T(n), and a status phrase, S(n).
751 The status phrase S(n) describes the period of time that begins at
752 T(n). The previous status phrase S(n-1) describes the period of time
753 that starts at T(n-1) and ends at T(n). Since we want to describe the
754 time that a status phrase took T(n)-T(n-1), this line must describe the
755 previous status.
756 */
757 table->field[2]->store(previous->status, strlen(previous->status),
758 system_charset_info);
759
760 my_decimal duration_decimal;
761 double2my_decimal(E_DEC_FATAL_ERROR,
762 (entry->time_usecs-previous->time_usecs)/(1000.0*1000),
763 &duration_decimal);
764
765 table->field[3]->store_decimal(&duration_decimal);
766
767
768 #ifdef HAVE_GETRUSAGE
769
770 if (enabled_getrusage())
771 {
772 my_decimal cpu_utime_decimal, cpu_stime_decimal;
773
774 double2my_decimal(E_DEC_FATAL_ERROR,
775 RUSAGE_DIFF_USEC(entry->rusage.ru_utime,
776 previous->rusage.ru_utime) /
777 (1000.0*1000),
778 &cpu_utime_decimal);
779
780 double2my_decimal(E_DEC_FATAL_ERROR,
781 RUSAGE_DIFF_USEC(entry->rusage.ru_stime,
782 previous->rusage.ru_stime) /
783 (1000.0*1000),
784 &cpu_stime_decimal);
785
786 table->field[4]->store_decimal(&cpu_utime_decimal);
787 table->field[5]->store_decimal(&cpu_stime_decimal);
788 table->field[4]->set_notnull();
789 table->field[5]->set_notnull();
790 #elif defined(_WIN32)
791 my_decimal cpu_utime_decimal, cpu_stime_decimal;
792
793 double2my_decimal(E_DEC_FATAL_ERROR,
794 GetTimeDiffInSeconds(&entry->ftUser,
795 &previous->ftUser),
796 &cpu_utime_decimal);
797 double2my_decimal(E_DEC_FATAL_ERROR,
798 GetTimeDiffInSeconds(&entry->ftKernel,
799 &previous->ftKernel),
800 &cpu_stime_decimal);
801
802 // Store the result.
803 table->field[4]->store_decimal(&cpu_utime_decimal);
804 table->field[5]->store_decimal(&cpu_stime_decimal);
805 table->field[4]->set_notnull();
806 table->field[5]->set_notnull();
807 #else
808 /* TODO: Add CPU-usage info for non-BSD systems */
809 #endif
810
811 #ifdef HAVE_GETRUSAGE
812 table->field[6]->store((uint32)(entry->rusage.ru_nvcsw -
813 previous->rusage.ru_nvcsw));
814 table->field[6]->set_notnull();
815 table->field[7]->store((uint32)(entry->rusage.ru_nivcsw -
816 previous->rusage.ru_nivcsw));
817 table->field[7]->set_notnull();
818 #else
819 /* TODO: Add context switch info for non-BSD systems */
820 #endif
821
822 #ifdef HAVE_GETRUSAGE
823 table->field[8]->store((uint32)(entry->rusage.ru_inblock -
824 previous->rusage.ru_inblock));
825 table->field[8]->set_notnull();
826 table->field[9]->store((uint32)(entry->rusage.ru_oublock -
827 previous->rusage.ru_oublock));
828 table->field[9]->set_notnull();
829 #else
830 /* TODO: Add block IO info for non-BSD systems */
831 #endif
832
833 #ifdef HAVE_GETRUSAGE
834 table->field[10]->store((uint32)(entry->rusage.ru_msgsnd -
835 previous->rusage.ru_msgsnd), true);
836 table->field[10]->set_notnull();
837 table->field[11]->store((uint32)(entry->rusage.ru_msgrcv -
838 previous->rusage.ru_msgrcv), true);
839 table->field[11]->set_notnull();
840 #else
841 /* TODO: Add message info for non-BSD systems */
842 #endif
843
844 #ifdef HAVE_GETRUSAGE
845 table->field[12]->store((uint32)(entry->rusage.ru_majflt -
846 previous->rusage.ru_majflt), true);
847 table->field[12]->set_notnull();
848 table->field[13]->store((uint32)(entry->rusage.ru_minflt -
849 previous->rusage.ru_minflt), true);
850 table->field[13]->set_notnull();
851 #else
852 /* TODO: Add page fault info for non-BSD systems */
853 #endif
854
855 #ifdef HAVE_GETRUSAGE
856 table->field[14]->store((uint32)(entry->rusage.ru_nswap -
857 previous->rusage.ru_nswap), true);
858 table->field[14]->set_notnull();
859 }
860 #else
861 /* TODO: Add swap info for non-BSD systems */
862 #endif
863
864 /* Emit the location that started this step, not that ended it. */
865 if ((previous->function != NULL) && (previous->file != NULL))
866 {
867 table->field[15]->store(previous->function, strlen(previous->function),
868 system_charset_info);
869 table->field[15]->set_notnull();
870 table->field[16]->store(previous->file, strlen(previous->file), system_charset_info);
871 table->field[16]->set_notnull();
872 table->field[17]->store(previous->line, true);
873 table->field[17]->set_notnull();
874 }
875
876 if (schema_table_store_record(thd_arg, table))
877 DBUG_RETURN(1);
878
879 }
880 }
881
882 DBUG_RETURN(0);
883 }
884 /**
885 Clear all the profiling information.
886 */
cleanup()887 void PROFILING::cleanup()
888 {
889 while (!history.is_empty())
890 delete history.pop();
891 delete current;
892 current= NULL;
893 }
894
895 #endif /* ENABLED_PROFILING */
896