mysql-profiling_slow.patch

   1 # name       : profiling_slow.patch
   2 # introduced : 11 or before
   3 # maintainer : Yasufumi
   4 #
   5 #!!! notice !!!
   6 # Any small change to this file in the main branch
   7 # should be done or reviewed by the maintainer!
   8 --- /dev/null
   9 +++ b/mysql-test/r/percona_bug643149.result
  10 @@ -0,0 +1,21 @@
  11 +SET @old_slow_query_log_file=@@global.slow_query_log_file;
  12 +SET GLOBAL slow_query_log=on;
  13 +SET LOCAL profiling_server=on;
  14 +SET LOCAL long_query_time=0;
  15 +SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';;
  16 +SELECT 1;
  17 +1
  18 +1
  19 +# User@Host: root[root] @ localhost []
  20 +# Thread_id: X  Schema: test  Last_errno: X  Killed: X
  21 +# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
  22 +# Bytes_sent: X  Tmp_tables: X  Tmp_disk_tables: X  Tmp_table_sizes: X
  23 +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X
  24 +# Profile_total: X.X Profile_total_cpu: X.X
  25 +# User@Host: root[root] @ localhost []
  26 +# Thread_id: X  Schema: test  Last_errno: X  Killed: X
  27 +# Query_time: X.X  Lock_time: X.X  Rows_sent: X  Rows_examined: X  Rows_affected: X  Rows_read: X
  28 +# Bytes_sent: X  Tmp_tables: X  Tmp_disk_tables: X  Tmp_table_sizes: X
  29 +# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X
  30 +# Profile_total: X.X Profile_total_cpu: X.X
  31 +SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
  32 --- /dev/null
  33 +++ b/mysql-test/t/percona_bug643149.test
  34 @@ -0,0 +1,52 @@
  35 +#
  36 +# This test suffers from server
  37 +# Bug#38124 "general_log_file" variable silently unset when using expression
  38 +# In short:
  39 +#    SET GLOBAL general_log_file = @<whatever>
  40 +#    SET GLOBAL slow_query_log = @<whatever>
  41 +# cause that the value of these server system variables is set to default
  42 +# instead of the assigned values. There comes no error message or warning.
  43 +# If this bug is fixed please
  44 +# 1. try this test with "let $fixed_bug38124 = 0;"
  45 +# 2. remove all workarounds if 1. was successful.
  46 +let $fixed_bug38124 = 0;
  47 +
  48 +SET @old_slow_query_log_file=@@global.slow_query_log_file;
  49 +SET GLOBAL slow_query_log=on;
  50 +SET LOCAL profiling_server=on;
  51 +SET LOCAL long_query_time=0;
  52 +
  53 +let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log;
  54 +--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
  55 +--eval SET GLOBAL slow_query_log_file='$slogfile';
  56 +
  57 +--disable_ps_protocol
  58 +SELECT 1;
  59 +--enable_ps_protocol
  60 +
  61 +perl;
  62 +  $slogfile= $ENV{'slogfile'};
  63 +
  64 +  open(FILE, "$slogfile") or
  65 +    die("Unable to read slow query log file $slogfile: $!\n");
  66 +  while(<FILE>) {
  67 +    next if (!/^#/);
  68 +    next if (/^# Time:/);
  69 +    s/[0-9]+/X/g;
  70 +    print;
  71 +  }
  72 +
  73 +  close(FILE);
  74 +  open(FILE, '>', "$slogfile");
  75 +  close(FILE);
  76 +EOF
  77 +
  78 +SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
  79 +
  80 +if(!$fixed_bug38124)
  81 +{
  82 +  --disable_query_log
  83 +  let $my_var = `SELECT @old_slow_query_log_file`;
  84 +  eval SET @@global.slow_query_log_file = '$my_var';
  85 +  --enable_query_log
  86 +}
  87 --- /dev/null
  88 +++ b/patch_info/profiling_slow.info
  89 @@ -0,0 +1,9 @@
  90 +File=profiling_slow.info
  91 +Name=profiling from SHOW PROFILE to slow.log
  92 +Version=1.0
  93 +Author=Percona <info@percona.com>
  94 +License=GPL
  95 +Comment=
  96 +Changelog
  97 +2009-05-18
  98 +Initial implementation
  99 --- a/sql/log.cc
 100 +++ b/sql/log.cc
 101 @@ -2436,6 +2436,11 @@
 102            my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)
 103        tmp_errno= errno;
 104      }
 105 +
 106 +#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
 107 +    thd->profiling.print_current(&log_file);
 108 +#endif
 109 +
 110      if (thd->db && strcmp(thd->db, db))
 111      {                                          // Database changed
 112        if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
 113 --- a/sql/mysqld.cc
 114 +++ b/sql/mysqld.cc
 115 @@ -5809,6 +5809,8 @@
 116    OPT_LOG_OUTPUT,
 117    OPT_PORT_OPEN_TIMEOUT,
 118    OPT_PROFILING,
 119 +  OPT_PROFILING_SERVER,
 120 +  OPT_PROFILING_USE_GETRUSAGE,
 121    OPT_KEEP_FILES_ON_CREATE,
 122    OPT_GENERAL_LOG,
 123    OPT_SLOW_LOG,
 124 @@ -6424,6 +6426,16 @@
 125     &global_system_variables.profiling_history_size,
 126     &max_system_variables.profiling_history_size,
 127     0, GET_ULONG, REQUIRED_ARG, 15, 0, 100, 0, 0, 0},
 128 +  {"profiling_server", OPT_PROFILING_SERVER,
 129 +   "Enable profiling of all threads",
 130 +   (uchar**) &global_system_variables.profiling_server,
 131 +   (uchar**) &max_system_variables.profiling_server, 0, GET_BOOL,
 132 +   OPT_ARG, 0, 0, 0, 0, 0, 0 },
 133 +  {"profiling_use_getrusage", OPT_PROFILING_USE_GETRUSAGE,
 134 +   "Enable getrusage function call for profiling",
 135 +   (uchar**) &global_system_variables.profiling_use_getrusage,
 136 +   (uchar**) &max_system_variables.profiling_use_getrusage, 0, GET_BOOL,
 137 +   OPT_ARG, 0, 0, 0, 0, 0, 0 },
 138  #endif
 139    {"relay-log", OPT_RELAY_LOG,
 140     "The location and name to use for relay logs.",
 141 --- a/sql/set_var.cc
 142 +++ b/sql/set_var.cc
 143 @@ -860,6 +860,10 @@
 144                                        ulonglong(OPTION_PROFILING));
 145  static sys_var_thd_ulong       sys_profiling_history_size(&vars, "profiling_history_size",
 146                                               &SV::profiling_history_size);
 147 +static sys_var_thd_bool        sys_profiling_server(&vars, "profiling_server",
 148 +                                             &SV::profiling_server);
 149 +static sys_var_thd_bool        sys_profiling_use_getrusage(&vars, "profiling_use_getrusage",
 150 +                                             &SV::profiling_use_getrusage);
 151  #endif
 152
 153  /* Local state variables */
 154 --- a/sql/sql_class.h
 155 +++ b/sql/sql_class.h
 156 @@ -330,6 +330,8 @@
 157    ulong optimizer_switch;
 158    ulong preload_buff_size;
 159    ulong profiling_history_size;
 160 +  my_bool profiling_server;
 161 +  my_bool profiling_use_getrusage;
 162    ulong query_cache_type;
 163    ulong read_buff_size;
 164    ulong read_rnd_buff_size;
 165 --- a/sql/sql_profile.cc
 166 +++ b/sql/sql_profile.cc
 167 @@ -225,8 +225,22 @@
 168  {
 169    time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
 170  #ifdef HAVE_GETRUSAGE
 171 -  getrusage(RUSAGE_SELF, &rusage);
 172 +  if ((profile->get_profiling())->enabled_getrusage())
 173 +    getrusage(RUSAGE_SELF, &rusage);
 174  #endif
 175 +
 176 +#ifdef HAVE_CLOCK_GETTIME
 177 +  struct timespec tp;
 178 +
 179 +  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
 180 +  {
 181 +    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
 182 +  }
 183 +  else
 184 +#endif
 185 +  {
 186 +    cpu_time_usecs= 0;
 187 +  }
 188  }
 189
 190
 191 @@ -343,7 +357,7 @@
 192      finish_current_query();
 193    }
 194
 195 -  enabled= (((thd)->options & OPTION_PROFILING) != 0);
 196 +  enabled= (((thd)->options & OPTION_PROFILING) != 0) || ( thd->variables.profiling_server );
 197
 198    if (! enabled) DBUG_VOID_RETURN;
 199
 200 @@ -381,7 +395,8 @@
 201      status_change("ending", NULL, NULL, 0);
 202
 203      if ((enabled) &&                                    /* ON at start? */
 204 -        ((thd->options & OPTION_PROFILING) != 0) &&   /* and ON at end? */
 205 +        (((thd->options & OPTION_PROFILING) != 0) ||
 206 +          (thd->variables.profiling_server)) &&   /* and ON at end? */
 207          (current->query_source != NULL) &&
 208          (! current->entries.is_empty()))
 209      {
 210 @@ -482,6 +497,118 @@
 211    DBUG_VOID_RETURN;
 212  }
 213
 214 +bool PROFILING::enabled_getrusage()
 215 +{
 216 +  return thd->variables.profiling_use_getrusage;
 217 +}
 218 +
 219 +/**
 220 +   For a given profile entry specified by a name and 2 time measurements,
 221 +   print its normalized name (i.e. with all spaces replaced with underscores)
 222 +   along with its wall clock and CPU time.
 223 +*/
 224 +
 225 +static void my_b_print_status(IO_CACHE *log_file, const char *status,
 226 +                              PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)
 227 +{
 228 +  DBUG_ENTER("my_b_print_status");
 229 +  DBUG_ASSERT(log_file != NULL && status != NULL);
 230 +  char query_time_buff[22+7];
 231 +  const char *tmp;
 232 +
 233 +  my_b_printf(log_file, "Profile_");
 234 +  for (tmp= status; *tmp; tmp++)
 235 +    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
 236 +
 237 +  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
 238 +           (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));
 239 +  my_b_printf(log_file, ": %s ", query_time_buff);
 240 +
 241 +  my_b_printf(log_file, "Profile_");
 242 +  for (tmp= status; *tmp; tmp++)
 243 +    my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);
 244 +  my_b_printf(log_file, "_cpu: ");
 245 +
 246 +  snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",
 247 +           (stop->cpu_time_usecs - start->cpu_time_usecs) /
 248 +           (1000.0 * 1000 * 1000));
 249 +  my_b_printf(log_file, "%s ", query_time_buff);
 250 +
 251 +  DBUG_VOID_RETURN;
 252 +}
 253 +
 254 +/**
 255 +  Print output for current query to file
 256 +*/
 257 +
 258 +int PROFILING::print_current(IO_CACHE *log_file)
 259 +{
 260 +  DBUG_ENTER("PROFILING::print_current");
 261 +  ulonglong row_number= 0;
 262 +
 263 +  QUERY_PROFILE *query;
 264 +  /* Get current query */
 265 +  if (current == NULL)
 266 +  {
 267 +    DBUG_RETURN(0);
 268 +  }
 269 +
 270 +  query= current;
 271 +
 272 +  my_b_printf(log_file, "# ");
 273 +
 274 +    void *entry_iterator;
 275 +    PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;
 276 +    /* ...and for each query, go through all its state-change steps. */
 277 +    for (entry_iterator= query->entries.new_iterator();
 278 +         entry_iterator != NULL;
 279 +         entry_iterator= query->entries.iterator_next(entry_iterator),
 280 +         previous=entry, row_number++)
 281 +    {
 282 +      entry= query->entries.iterator_value(entry_iterator);
 283 +
 284 +      /* Skip the first.  We count spans of fence, not fence-posts. */
 285 +      if (previous == NULL) {first= entry; continue;}
 286 +
 287 +      if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
 288 +      {
 289 +        /*
 290 +          We got here via a SHOW command.  That means that we stored
 291 +          information about the query we wish to show and that isn't
 292 +          in a WHERE clause at a higher level to filter out rows we
 293 +          wish to exclude.
 294 +
 295 +          Because that functionality isn't available in the server yet,
 296 +          we must filter here, at the wrong level.  Once one can con-
 297 +          struct where and having conditions at the SQL layer, then this
 298 +          condition should be ripped out.
 299 +        */
 300 +        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
 301 +        {
 302 +          if (query != last)
 303 +            continue;
 304 +        }
 305 +        else
 306 +        {
 307 +          if (thd->lex->profile_query_id != query->profiling_query_id)
 308 +            continue;
 309 +        }
 310 +      }
 311 +
 312 +      my_b_print_status(log_file, previous->status, previous, entry);
 313 +    }
 314 +
 315 +    my_b_write_byte(log_file, '\n');
 316 +    if ((entry != NULL) && (first != NULL))
 317 +    {
 318 +      my_b_printf(log_file, "# ");
 319 +      my_b_print_status(log_file, "total", first, entry);
 320 +      my_b_write_byte(log_file, '\n');
 321 +    }
 322 +
 323 +  DBUG_RETURN(0);
 324 +}
 325 +
 326  /**
 327    Fill the information schema table, "query_profile", as defined in show.cc .
 328    There are two ways to get to this function:  Selecting from the information
 329 @@ -577,6 +704,8 @@
 330
 331  #ifdef HAVE_GETRUSAGE
 332
 333 +      if (enabled_getrusage())
 334 +      {
 335        my_decimal cpu_utime_decimal, cpu_stime_decimal;
 336
 337        double2my_decimal(E_DEC_FATAL_ERROR,
 338 @@ -647,6 +776,7 @@
 339        table->field[14]->store((uint32)(entry->rusage.ru_nswap -
 340                               previous->rusage.ru_nswap), true);
 341        table->field[14]->set_notnull();
 342 +      }
 343  #else
 344        /* TODO: Add swap info for non-BSD systems */
 345  #endif
 346 --- a/sql/sql_profile.h
 347 +++ b/sql/sql_profile.h
 348 @@ -168,11 +168,15 @@
 349  */
 350  class PROF_MEASUREMENT
 351  {
 352 -private:
 353 -  friend class QUERY_PROFILE;
 354 -  friend class PROFILING;
 355 -
 356    QUERY_PROFILE *profile;
 357 +
 358 +  char *allocated_status_memory;
 359 +
 360 +  void set_label(const char *status_arg, const char *function_arg,
 361 +                  const char *file_arg, unsigned int line_arg);
 362 +  void clean_up();
 363 +
 364 +public:
 365    char *status;
 366  #ifdef HAVE_GETRUSAGE
 367    struct rusage rusage;
 368 @@ -183,12 +187,7 @@
 369    unsigned int line;
 370
 371    double time_usecs;
 372 -  char *allocated_status_memory;
 373 -
 374 -  void set_label(const char *status_arg, const char *function_arg,
 375 -                  const char *file_arg, unsigned int line_arg);
 376 -  void clean_up();
 377 -
 378 +  double cpu_time_usecs;
 379    PROF_MEASUREMENT();
 380    PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
 381    PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
 382 @@ -233,6 +232,11 @@
 383
 384    /* Show this profile.  This is called by PROFILING. */
 385    bool show(uint options);
 386 +
 387 +public:
 388 +
 389 +  inline PROFILING * get_profiling() { return profiling; };
 390 +
 391  };
 392
 393
 394 @@ -278,9 +282,11 @@
 395
 396    /* SHOW PROFILES */
 397    bool show_profiles();
 398 +  bool enabled_getrusage();
 399
 400    /* ... from INFORMATION_SCHEMA.PROFILING ... */
 401    int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
 402 +  int print_current(IO_CACHE *log_file);
 403  };
 404
 405  #  endif /* HAVE_PROFILING */