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