mysql-profiling_slow.patch

   1 diff -ruN /dev/null b/patch_info/profiling_slow.info
   2 --- /dev/null   Thu Jan 01 00:00:00 1970 +0000
   3 +++ b/patch_info/profiling_slow.info    Fri Jul 03 15:40:29 2009 -0700
   4 @@ -0,0 +1,9 @@
   5 +File=profiling_slow.info
   6 +Name=profiling from SHOW PROFILE to slow.log
   7 +Version=1.0
   8 +Author=Percona <info@percona.com>
   9 +License=GPL
  10 +Comment=
  11 +Changelog
  12 +2009-05-18
  13 +Initial implementation
  14 diff -ruN a/sql/log.cc b/sql/log.cc
  15 --- a/sql/log.cc        Fri Jul 03 15:40:20 2009 -0700
  16 +++ b/sql/log.cc        Fri Jul 03 15:40:29 2009 -0700
  17 @@ -2404,6 +2404,11 @@
  18            tmp_errno=errno;
  19        }
  20      }
  21 +
  22 +#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
  23 +    thd->profiling.print_current(&log_file);
  24 +#endif
  25 +
  26      if (thd->db && strcmp(thd->db,db))
  27      {                                          // Database changed
  28        if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
  29 diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
  30 --- a/sql/mysqld.cc     Fri Jul 03 15:40:20 2009 -0700
  31 +++ b/sql/mysqld.cc     Fri Jul 03 15:40:29 2009 -0700
  32 @@ -5069,6 +5069,8 @@
  33    OPT_PORT_OPEN_TIMEOUT,
  34    OPT_MERGE,
  35    OPT_PROFILING,
  36 +  OPT_PROFILING_SERVER,
  37 +  OPT_PROFILING_USE_GETRUSAGE,
  38    OPT_SLOW_LOG,
  39    OPT_SLOW_QUERY_LOG_FILE,
  40    OPT_USE_GLOBAL_LONG_QUERY_TIME,
  41 @@ -5693,6 +5695,16 @@
  42     (gptr*) &global_system_variables.profiling_history_size,
  43     (gptr*) &max_system_variables.profiling_history_size,
  44     0, GET_ULONG, REQUIRED_ARG, 15, 0, 100, 0, 0, 0},
  45 +  {"profiling_server", OPT_PROFILING_SERVER,
  46 +   "Enable profiling of all threads",
  47 +   (gptr*) &global_system_variables.profiling_server,
  48 +   (gptr*) &max_system_variables.profiling_server, 0, GET_BOOL,
  49 +   OPT_ARG, 0, 0, 0, 0, 0, 0 },
  50 +  {"profiling_use_getrusage", OPT_PROFILING_USE_GETRUSAGE,
  51 +   "Enable getrusage function call for profiling",
  52 +   (gptr*) &global_system_variables.profiling_use_getrusage,
  53 +   (gptr*) &max_system_variables.profiling_use_getrusage, 0, GET_BOOL,
  54 +   OPT_ARG, 0, 0, 0, 0, 0, 0 },
  55  #endif
  56    {"relay-log", OPT_RELAY_LOG,
  57     "The location and name to use for relay logs.",
  58 diff -ruN a/sql/set_var.cc b/sql/set_var.cc
  59 --- a/sql/set_var.cc    Fri Jul 03 15:40:20 2009 -0700
  60 +++ b/sql/set_var.cc    Fri Jul 03 15:40:29 2009 -0700
  61 @@ -593,6 +593,10 @@
  62                                        ulonglong(OPTION_PROFILING));
  63  static sys_var_thd_ulong       sys_profiling_history_size("profiling_history_size",
  64                                               &SV::profiling_history_size);
  65 +static sys_var_thd_bool        sys_profiling_server("profiling_server",
  66 +                                             &SV::profiling_server);
  67 +static sys_var_thd_bool        sys_profiling_use_getrusage("profiling_use_getrusage",
  68 +                                             &SV::profiling_use_getrusage);
  69  #endif
  70
  71  /* Local state variables */
  72 @@ -770,6 +774,8 @@
  73  #if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
  74    &sys_profiling,
  75    &sys_profiling_history_size,
  76 +  &sys_profiling_server,
  77 +  &sys_profiling_use_getrusage,
  78  #endif
  79    &sys_pseudo_thread_id,
  80    &sys_query_alloc_block_size,
  81 @@ -1101,6 +1107,8 @@
  82  #if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
  83    {sys_profiling.name,        (char*) &sys_profiling,               SHOW_SYS},
  84    {sys_profiling_history_size.name, (char*) &sys_profiling_history_size, SHOW_SYS},
  85 +  {sys_profiling_server.name, (char*) &sys_profiling_server, SHOW_SYS},
  86 +  {sys_profiling_use_getrusage.name, (char*) &sys_profiling_use_getrusage, SHOW_SYS},
  87  #endif
  88    {"protocol_version",        (char*) &protocol_version,            SHOW_INT},
  89    {sys_query_alloc_block_size.name, (char*) &sys_query_alloc_block_size,
  90 diff -ruN a/sql/sql_class.h b/sql/sql_class.h
  91 --- a/sql/sql_class.h   Fri Jul 03 15:40:20 2009 -0700
  92 +++ b/sql/sql_class.h   Fri Jul 03 15:40:29 2009 -0700
  93 @@ -552,6 +552,8 @@
  94    ulong optimizer_search_depth;
  95    ulong preload_buff_size;
  96    ulong profiling_history_size;
  97 +  my_bool profiling_server;
  98 +  my_bool profiling_use_getrusage;
  99    ulong query_cache_type;
 100    ulong log_slow_rate_limit;
 101    ulong read_buff_size;
 102 diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc
 103 --- a/sql/sql_profile.cc        Fri Jul 03 15:40:20 2009 -0700
 104 +++ b/sql/sql_profile.cc        Fri Jul 03 15:40:29 2009 -0700
 105 @@ -221,9 +221,22 @@
 106  */
 107  void PROF_MEASUREMENT::collect()
 108  {
 109 +  struct timespec tp;
 110    time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
 111  #ifdef HAVE_GETRUSAGE
 112 -  getrusage(RUSAGE_SELF, &rusage);
 113 +  if ((profile->get_profiling())->enabled_getrusage())
 114 +    getrusage(RUSAGE_SELF, &rusage);
 115 +#endif
 116 +
 117 +#ifdef HAVE_CLOCK_GETTIME
 118 +  if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
 119 +  {
 120 +    cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;
 121 +  }
 122 +  else
 123 +  {
 124 +    cpu_time_usecs= 0;
 125 +  }
 126  #endif
 127  }
 128
 129 @@ -341,7 +354,7 @@
 130      finish_current_query();
 131    }
 132
 133 -  enabled= (((thd)->options & OPTION_PROFILING) != 0);
 134 +  enabled= (((thd)->options & OPTION_PROFILING) != 0) || ( thd->variables.profiling_server );
 135
 136    if (! enabled) DBUG_VOID_RETURN;
 137
 138 @@ -379,7 +392,8 @@
 139      status_change("ending", NULL, NULL, 0);
 140
 141      if ((enabled) &&                                    /* ON at start? */
 142 -        ((thd->options & OPTION_PROFILING) != 0) &&   /* and ON at end? */
 143 +        (((thd->options & OPTION_PROFILING) != 0) ||
 144 +          (thd->variables.profiling_server)) &&   /* and ON at end? */
 145          (current->query_source != NULL) &&
 146          (! current->entries.is_empty()))
 147      {
 148 @@ -480,6 +494,88 @@
 149    DBUG_VOID_RETURN;
 150  }
 151
 152 +bool PROFILING::enabled_getrusage()
 153 +{
 154 +  return thd->variables.profiling_use_getrusage;
 155 +}
 156 +
 157 +/**
 158 +  Print output for current query to file
 159 +*/
 160 +
 161 +int PROFILING::print_current(IO_CACHE *log_file)
 162 +{
 163 +  DBUG_ENTER("PROFILING::print_current");
 164 +  ulonglong row_number= 0;
 165 +  char query_time_buff[22+7];
 166 +  char query_cpu_time_buff[22+7];
 167 +
 168 +  QUERY_PROFILE *query;
 169 +  /* Get current query */
 170 +  if (current == NULL)
 171 +  {
 172 +    DBUG_RETURN(0);
 173 +  }
 174 +
 175 +  query= current;
 176 +
 177 +  my_b_printf(log_file, "# PROFILE_VALUES ");
 178 +
 179 +    void *entry_iterator;
 180 +    PROF_MEASUREMENT *entry, *previous= NULL, *first= NULL;
 181 +    /* ...and for each query, go through all its state-change steps. */
 182 +    for (entry_iterator= query->entries.new_iterator();
 183 +         entry_iterator != NULL;
 184 +         entry_iterator= query->entries.iterator_next(entry_iterator),
 185 +         previous=entry, row_number++)
 186 +    {
 187 +      entry= query->entries.iterator_value(entry_iterator);
 188 +
 189 +      /* Skip the first.  We count spans of fence, not fence-posts. */
 190 +      if (previous == NULL) {first= entry; continue;}
 191 +
 192 +      if (thd->lex->orig_sql_command == SQLCOM_SHOW_PROFILE)
 193 +      {
 194 +        /*
 195 +          We got here via a SHOW command.  That means that we stored
 196 +          information about the query we wish to show and that isn't
 197 +          in a WHERE clause at a higher level to filter out rows we
 198 +          wish to exclude.
 199 +
 200 +          Because that functionality isn't available in the server yet,
 201 +          we must filter here, at the wrong level.  Once one can con-
 202 +          struct where and having conditions at the SQL layer, then this
 203 +          condition should be ripped out.
 204 +        */
 205 +        if (thd->lex->profile_query_id == 0) /* 0 == show final query */
 206 +        {
 207 +          if (query != last)
 208 +            continue;
 209 +        }
 210 +        else
 211 +        {
 212 +          if (thd->lex->profile_query_id != query->profiling_query_id)
 213 +            continue;
 214 +        }
 215 +      }
 216 +
 217 +      snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", (entry->time_usecs-previous->time_usecs)/(1000.0*1000));
 218 +      snprintf(query_cpu_time_buff, sizeof(query_cpu_time_buff), "%.6f", (entry->cpu_time_usecs-previous->cpu_time_usecs)/(1000.0*1000*1000));
 219 +      my_b_printf(log_file, "%s: %s (cpu: %s), ", previous->status, query_time_buff, query_cpu_time_buff);
 220 +
 221 +    }
 222 +
 223 +    my_b_printf(log_file, "\n");
 224 +    if ((entry != NULL) && (first != NULL))
 225 +    {
 226 +      snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", (entry->time_usecs-first->time_usecs)/(1000.0*1000));
 227 +      snprintf(query_cpu_time_buff, sizeof(query_cpu_time_buff), "%.6f", (entry->cpu_time_usecs-first->cpu_time_usecs)/(1000.0*1000*1000));
 228 +      my_b_printf(log_file, "# PROFILE_TOTALS Total: %s (cpu: %s)\n", query_time_buff, query_cpu_time_buff);
 229 +    }
 230 +
 231 +  DBUG_RETURN(0);
 232 +}
 233 +
 234  /**
 235    Fill the information schema table, "query_profile", as defined in show.cc .
 236    There are two ways to get to this function:  Selecting from the information
 237 diff -ruN a/sql/sql_profile.h b/sql/sql_profile.h
 238 --- a/sql/sql_profile.h Fri Jul 03 15:40:20 2009 -0700
 239 +++ b/sql/sql_profile.h Fri Jul 03 15:40:29 2009 -0700
 240 @@ -193,6 +193,7 @@
 241    unsigned int line;
 242
 243    double time_usecs;
 244 +  double cpu_time_usecs;
 245    char *allocated_status_memory;
 246
 247    void set_label(const char *status_arg, const char *function_arg,
 248 @@ -243,6 +244,11 @@
 249
 250    /* Show this profile.  This is called by PROFILING. */
 251    bool show(uint options);
 252 +
 253 +public:
 254 +
 255 +  inline PROFILING * get_profiling() { return profiling; };
 256 +
 257  };
 258
 259
 260 @@ -288,9 +294,11 @@
 261
 262    /* SHOW PROFILES */
 263    bool show_profiles();
 264 +  bool enabled_getrusage();
 265
 266    /* ... from INFORMATION_SCHEMA.PROFILING ... */
 267    int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);
 268 +  int print_current(IO_CACHE *log_file);
 269  };
 270
 271  #  endif /* HAVE_PROFILING */