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