Optimizer trace.

By me:
WL#5257	 	Create a first API for the Optimizer trace
By Jorgen Loland:
WL#5594	 	Add optimizer traces to the range optimizer
WL#5741	 	Ensure optimizer tracing for subqueries works without JSON syntax errors
WL#5581	 	Add --opt-trace-protocol to MTR.
Summary below.
* This feature produces a trace for any SELECT/INSERT/UPDATE/DELETE/DO/SET/CALL,
which contains information about decisions taken by the optimizer during
the optimization phase (choice of table access method, various costs,
transformations, etc). It should help understand the logic followed by the
optimizer for a particular query. Trace is session-local, controlled by the
@@optimizer_trace variable and other new variables, and readable by selecting
from information_schema.optimizer_trace. See the doxygen comments in opt_trace.h
for more info.
* By default the tracing code is compiled in, but not enabled
at runtime; set @@optimizer_trace to enable it.
* Changes to test results: unless otherwise noted they are due to those changes:
** The query printed by EXPLAIN EXTENDED now shows the id of each SELECT,
to help interpret the "id" column.
** EXPLAIN EXTENDED now prints triggered conditions as:
    trigcond_if(outer_field_is_not_null, <is_not_null_test>(`test`.`t2`.`s1`), true)
instead of:
    trigcond(<is_not_null_test>(`test`.`t2`.`s1`).
* @@optimizer_trace_offset is a signed variable, so I had to add support for
this in MySQL (so far all integer system variables were unsigned, it was impossible
to set a system variable to a negative value, it would be rounded to 0).

Author: Guilhem Bichot

.bzrignore

@@ -3116,6 +3116,7 @@ libmysqld/transaction.cc
 libmysqld/sys_vars.cc
 libmysqld/keycaches.cc
 client/dtoa.c
+libmysqld/opt_trace.cc
 libmysqld/sql_audit.cc
 storage/archive/archive_performance
 storage/archive/concurrency_test

CMakeLists.txt

@@ -186,6 +186,8 @@ MARK_AS_ADVANCED(ENABLED_LOCAL_INFILE)
 OPTION(WITH_FAST_MUTEXES "Compile with fast mutexes" OFF)
 MARK_AS_ADVANCED(WITH_FAST_MUTEXES)
 
+OPTION(OPTIMIZER_TRACE "Support tracing of Optimizer" ON)
+
 # Set DBUG_OFF and other optional release-only flags for non-debug project types
 FOREACH(BUILD_TYPE RELEASE RELWITHDEBINFO MINSIZEREL)
   FOREACH(LANG C CXX)

client/mysqltest.cc

@@ -90,7 +90,8 @@ enum {
   OPT_PS_PROTOCOL=OPT_MAX_CLIENT_OPTION, OPT_SP_PROTOCOL,
   OPT_CURSOR_PROTOCOL, OPT_VIEW_PROTOCOL, OPT_MAX_CONNECT_RETRIES,
   OPT_MAX_CONNECTIONS, OPT_MARK_PROGRESS, OPT_LOG_DIR,
-  OPT_TAIL_LINES, OPT_RESULT_FORMAT_VERSION, OPT_EXPLAIN_PROTOCOL
+  OPT_TAIL_LINES, OPT_RESULT_FORMAT_VERSION, OPT_TRACE_PROTOCOL,
+  OPT_EXPLAIN_PROTOCOL
 };
 
 static int record= 0, opt_sleep= -1;
@@ -110,6 +111,7 @@ static my_bool opt_mark_progress= 0;
 static my_bool ps_protocol= 0, ps_protocol_enabled= 0;
 static my_bool sp_protocol= 0, sp_protocol_enabled= 0;
 static my_bool view_protocol= 0, view_protocol_enabled= 0;
+static my_bool opt_trace_protocol= 0, opt_trace_protocol_enabled= 0;
 static my_bool explain_protocol= 0, explain_protocol_enabled= 0;
 static my_bool cursor_protocol= 0, cursor_protocol_enabled= 0;
 static my_bool parsing_disabled= 0;
@@ -201,6 +203,8 @@ static char *opt_plugin_dir= 0;
 static my_regex_t ps_re;     /* the query can be run using PS protocol */
 static my_regex_t sp_re;     /* the query can be run as a SP */
 static my_regex_t view_re;   /* the query can be run as a view*/
+/* the query can be traced with optimizer trace*/
+static my_regex_t opt_trace_re;
 static my_regex_t explain_re;/* the query can be converted to EXPLAIN */
 
 static void init_re(void);
@@ -6392,6 +6396,10 @@ static struct my_option my_long_options[] =
   {"view-protocol", OPT_VIEW_PROTOCOL, "Use views for select.",
    &view_protocol, &view_protocol, 0,
    GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
+  {"opt-trace-protocol", OPT_TRACE_PROTOCOL,
+   "Trace DML statements with optimizer trace",
+   &opt_trace_protocol, &opt_trace_protocol, 0,
+   GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
   {"explain-protocol", OPT_EXPLAIN_PROTOCOL,
    "Explain all SELECT/INSERT/REPLACE/UPDATE/DELETE statements",
    &explain_protocol, &explain_protocol, 0,
@@ -7879,6 +7887,40 @@ void run_query(struct st_connection *cn, struct st_command *command, int flags)
   DBUG_VOID_RETURN;
 }
 
+/**
+   Display the optimizer trace produced by the last executed statement.
+ */
+void display_opt_trace(struct st_connection *cn,
+                       struct st_command *command,
+                       int flags)
+{
+  if (!disable_query_log &&
+      opt_trace_protocol_enabled &&
+      !command->expected_errors.count &&
+      match_re(&opt_trace_re, command->query))
+  {
+    st_command save_command= *command;
+    DYNAMIC_STRING query_str;
+    init_dynamic_string(&query_str,
+                        "SELECT trace FROM information_schema.optimizer_trace"
+                        " /* injected by --opt-trace-protocol */",
+                        128, 128);
+
+    command->query= query_str.str;
+    command->query_len= query_str.length;
+    command->end= strend(command->query);
+
+    /* sorted trace is not readable at all*/
+    my_bool save_display_result_sorted= display_result_sorted;
+    display_result_sorted= FALSE;
+    run_query(cn, command, flags);
+    display_result_sorted= save_display_result_sorted;
+
+    dynstr_free(&query_str);
+    *command= save_command;
+  }
+}
+
 
 void run_explain(struct st_connection *cn, struct st_command *command, int flags)
 {
@@ -7968,6 +8010,13 @@ void init_re(void)
     "^("
     "[[:space:]]*SELECT[[:space:]])";
 
+  const char *opt_trace_re_str =
+    "^("
+    "[[:space:]]*INSERT[[:space:]]|"
+    "[[:space:]]*UPDATE[[:space:]]|"
+    "[[:space:]]*DELETE[[:space:]]|"
+    "[[:space:]]*EXPLAIN[[:space:]]|"
+    "[[:space:]]*SELECT[[:space:]])";
 
   /* Filter for queries that can be converted to EXPLAIN */
   const char *explain_re_str =
@@ -7977,6 +8026,7 @@ void init_re(void)
   init_re_comp(&ps_re, ps_re_str);
   init_re_comp(&sp_re, sp_re_str);
   init_re_comp(&view_re, view_re_str);
+  init_re_comp(&opt_trace_re, opt_trace_re_str);
   init_re_comp(&explain_re, explain_re_str);
 }
 
@@ -8014,6 +8064,7 @@ void free_re(void)
   my_regfree(&ps_re);
   my_regfree(&sp_re);
   my_regfree(&view_re);
+  my_regfree(&opt_trace_re);
   my_regex_end();
 }
 
@@ -8327,6 +8378,7 @@ int main(int argc, char **argv)
   var_set_int("$PS_PROTOCOL", ps_protocol);
   var_set_int("$SP_PROTOCOL", sp_protocol);
   var_set_int("$VIEW_PROTOCOL", view_protocol);
+  var_set_int("$OPT_TRACE_PROTOCOL", opt_trace_protocol);
   var_set_int("$EXPLAIN_PROTOCOL", explain_protocol);
   var_set_int("$CURSOR_PROTOCOL", cursor_protocol);
 
@@ -8363,6 +8415,7 @@ int main(int argc, char **argv)
   ps_protocol_enabled= ps_protocol;
   sp_protocol_enabled= sp_protocol;
   view_protocol_enabled= view_protocol;
+  opt_trace_protocol_enabled= opt_trace_protocol;
   explain_protocol_enabled= explain_protocol;
   cursor_protocol_enabled= cursor_protocol;
 
@@ -8649,6 +8702,7 @@ int main(int argc, char **argv)
         */
 	run_explain(cur_con, command, flags);
 	run_query(cur_con, command, flags);
+	display_opt_trace(cur_con, command, flags);
 	command_executed++;
         command->last_argument= command->end;
 

config.h.cmake

@@ -511,6 +511,7 @@
 #cmakedefine EXTRA_DEBUG 1
 #cmakedefine BACKUP_TEST 1
 #cmakedefine CYBOZU 1
+#cmakedefine OPTIMIZER_TRACE 1
 #cmakedefine USE_SYMDIR 1
 
 /* Character sets and collations */

dbug/dbug.c

@@ -1412,7 +1412,7 @@ static struct link *ListAddDel(struct link *head, const char *ctlp,
         }
         else
         {
-          (*cur)->flags&=~(EXCLUDE & SUBDIR);
+          (*cur)->flags&=~(EXCLUDE | SUBDIR);
           (*cur)->flags|=INCLUDE | subdir;
         }
         goto next;

include/my_getopt.h

@@ -116,6 +116,7 @@ longlong getopt_ll_limit_value(longlong, const struct my_option *,
 double getopt_double_limit_value(double num, const struct my_option *optp,
                                  my_bool *fix);
 my_bool getopt_compare_strings(const char *s, const char *t, uint length);
+ulonglong max_of_int_range(int var_type);
 
 C_MODE_END
 

include/my_sys.h

@@ -158,7 +158,22 @@ extern void *my_memdup(const void *from,size_t length,myf MyFlags);
 extern char *my_strdup(const char *from,myf MyFlags);
 extern char *my_strndup(const char *from, size_t length,
 				   myf MyFlags);
-#define TRASH(A,B) do{MEM_CHECK_ADDRESSABLE(A,B);MEM_UNDEFINED(A,B);} while (0)
+#if !defined(DBUG_OFF) || defined(HAVE_VALGRIND)
+/**
+  Put bad content in memory to be sure it will segfault if dereferenced.
+  With Valgrind, verify that memory is addressable, and mark it undefined.
+  We cache value of B because if B is expression which depends on A, memset()
+  trashes value of B.
+*/
+#define TRASH(A,B) do {                                                 \
+    const size_t l= (B);                                                \
+    MEM_CHECK_ADDRESSABLE(A, l);                                        \
+    memset(A, 0x8F, l);                                                 \
+    MEM_UNDEFINED(A, l);                                                \
+  } while (0)
+#else
+#define TRASH(A,B) do {} while(0)
+#endif
 #if defined(ENABLED_DEBUG_SYNC)
 extern void (*debug_sync_C_callback_ptr)(const char *, size_t);
 #define DEBUG_SYNC_C(_sync_point_name_) do {                            \
@@ -763,16 +778,16 @@ extern my_bool init_dynamic_array2(DYNAMIC_ARRAY *array, uint element_size,
 extern my_bool init_dynamic_array(DYNAMIC_ARRAY *array, uint element_size,
                                   uint init_alloc, uint alloc_increment);
 extern my_bool insert_dynamic(DYNAMIC_ARRAY *array, const void *element);
-extern uchar *alloc_dynamic(DYNAMIC_ARRAY *array);
-extern uchar *pop_dynamic(DYNAMIC_ARRAY*);
+extern void *alloc_dynamic(DYNAMIC_ARRAY *array);
+extern void *pop_dynamic(DYNAMIC_ARRAY*);
 extern my_bool set_dynamic(DYNAMIC_ARRAY *array, const void *element,
                            uint array_index);
 extern my_bool allocate_dynamic(DYNAMIC_ARRAY *array, uint max_elements);
-extern void get_dynamic(DYNAMIC_ARRAY *array,uchar * element,uint array_index);
+extern void get_dynamic(DYNAMIC_ARRAY *array, void *element,
+                        uint array_index);
 extern void delete_dynamic(DYNAMIC_ARRAY *array);
 extern void delete_dynamic_element(DYNAMIC_ARRAY *array, uint array_index);
 extern void freeze_size(DYNAMIC_ARRAY *array);
-extern int  get_index_dynamic(DYNAMIC_ARRAY *array, uchar * element);
 #define dynamic_array_ptr(array,array_index) ((array)->buffer+(array_index)*(array)->size_of_element)
 #define dynamic_element(array,array_index,type) ((type)((array)->buffer) +(array_index))
 #define push_dynamic(A,B) insert_dynamic((A),(B))

include/mysql/plugin.h

@@ -124,13 +124,16 @@ __MYSQL_DECLARE_PLUGIN(NAME, \
 
 #define mysql_declare_plugin_end ,{0,0,0,0,0,0,0,0,0,0,0,0}}
 
-/*
+/**
   declarations for SHOW STATUS support in plugins
 */
 enum enum_mysql_show_type
 {
-  SHOW_UNDEF, SHOW_BOOL, SHOW_INT, SHOW_LONG,
-  SHOW_LONGLONG, SHOW_CHAR, SHOW_CHAR_PTR,
+  SHOW_UNDEF, SHOW_BOOL,
+  SHOW_INT,        ///< shown as _unsigned_ int
+  SHOW_LONG,       ///< shown as _unsigned_ long
+  SHOW_LONGLONG,   ///< shown as _unsigned_ longlong
+  SHOW_CHAR, SHOW_CHAR_PTR,
   SHOW_ARRAY, SHOW_FUNC, SHOW_DOUBLE,
   SHOW_always_last
 };

include/mysql/plugin_audit.h.pp

@@ -82,8 +82,11 @@
 typedef struct st_mysql_xid MYSQL_XID;
 enum enum_mysql_show_type
 {
-  SHOW_UNDEF, SHOW_BOOL, SHOW_INT, SHOW_LONG,
-  SHOW_LONGLONG, SHOW_CHAR, SHOW_CHAR_PTR,
+  SHOW_UNDEF, SHOW_BOOL,
+  SHOW_INT,
+  SHOW_LONG,
+  SHOW_LONGLONG,
+  SHOW_CHAR, SHOW_CHAR_PTR,
   SHOW_ARRAY, SHOW_FUNC, SHOW_DOUBLE,
   SHOW_always_last
 };

include/mysql/plugin_auth.h.pp

@@ -82,8 +82,11 @@
 typedef struct st_mysql_xid MYSQL_XID;
 enum enum_mysql_show_type
 {
-  SHOW_UNDEF, SHOW_BOOL, SHOW_INT, SHOW_LONG,
-  SHOW_LONGLONG, SHOW_CHAR, SHOW_CHAR_PTR,
+  SHOW_UNDEF, SHOW_BOOL,
+  SHOW_INT,
+  SHOW_LONG,
+  SHOW_LONGLONG,
+  SHOW_CHAR, SHOW_CHAR_PTR,
   SHOW_ARRAY, SHOW_FUNC, SHOW_DOUBLE,
   SHOW_always_last
 };

include/mysql/plugin_ftparser.h.pp

@@ -82,8 +82,11 @@
 typedef struct st_mysql_xid MYSQL_XID;
 enum enum_mysql_show_type
 {
-  SHOW_UNDEF, SHOW_BOOL, SHOW_INT, SHOW_LONG,
-  SHOW_LONGLONG, SHOW_CHAR, SHOW_CHAR_PTR,
+  SHOW_UNDEF, SHOW_BOOL,
+  SHOW_INT,
+  SHOW_LONG,
+  SHOW_LONGLONG,
+  SHOW_CHAR, SHOW_CHAR_PTR,
   SHOW_ARRAY, SHOW_FUNC, SHOW_DOUBLE,
   SHOW_always_last
 };

mysql-test/collections/default.experimental

@@ -11,6 +11,8 @@ main.mysqlslap @windows                  # Bug#11761520 2010-08-10 alik mysqlsla
 main.signal_demo3 @solaris               # Bug#11755949 2010-01-20 alik Several test cases fail on Solaris with error Thread stack overrun
 main.sp @solaris                         # Bug#11755949 2010-01-20 alik Several test cases fail on Solaris with error Thread stack overrun
 main.subquery_sj_none @solaris          # Bug#11755949 2010-01-20 alik Several test cases fail on Solaris with error Thread stack overrun
+main.subquery_sj_none_jcl6 @solaris          # Bug#11755949 2010-01-20 alik Several test cases fail on Solaris with error Thread stack overrun
+main.subquery_sj_none_jcl7 @solaris          # Bug#11755949 2010-01-20 alik Several test cases fail on Solaris with error Thread stack overrun
 main.wait_timeout @solaris               # Bug#11758972 2010-04-26 alik wait_timeout fails on OpenSolaris
 
 rpl.rpl_delayed_slave                    # BUG#11764654 rpl_delayed_slave fails sporadically in pb

mysql-test/include/have_optimizer_trace.inc

@@ -0,0 +1,9 @@
+--disable_query_log
+
+# Check if variable optimizer_trace exists
+let $have_var = `select TRUE from information_schema.session_variables where variable_name="optimizer_trace"`;
+if (!$have_var)
+{
+  skip requires optimizer trace support;
+}
+--enable_query_log

mysql-test/mysql-test-run.pl

@@ -163,7 +163,7 @@ END
 
 # If you add a new suite, please check TEST_DIRS in Makefile.am.
 #
-my $DEFAULT_SUITES= "main,sys_vars,binlog,federated,rpl,innodb,perfschema,funcs_1";
+my $DEFAULT_SUITES= "main,sys_vars,binlog,federated,rpl,innodb,perfschema,funcs_1,optimizer_trace";
 my $opt_suites;
 
 our $opt_verbose= 0;  # Verbose output, enable with --verbose
@@ -189,6 +189,7 @@ END
 my $opt_sp_protocol;
 my $opt_cursor_protocol;
 my $opt_view_protocol;
+my $opt_trace_protocol;
 my $opt_explain_protocol;
 
 our $opt_debug;
@@ -1043,6 +1044,7 @@ sub command_line_setup {
              'ps-protocol'              => \$opt_ps_protocol,
              'sp-protocol'              => \$opt_sp_protocol,
              'view-protocol'            => \$opt_view_protocol,
+             'opt-trace-protocol'       => \$opt_trace_protocol,
              'explain-protocol'         => \$opt_explain_protocol,
              'cursor-protocol'          => \$opt_cursor_protocol,
              'ssl|with-openssl'         => \$opt_ssl,
@@ -1682,6 +1684,13 @@ sub command_line_setup {
       unless @valgrind_args;
   }
 
+  if ( $opt_trace_protocol )
+  {
+    push(@opt_extra_mysqld_opt, "--optimizer_trace=enabled=on,one_line=off");
+    # some queries yield big traces:
+    push(@opt_extra_mysqld_opt, "--optimizer-trace-max-mem-size=1000000");
+  }
+
   if ( $opt_valgrind )
   {
     # Set valgrind_options to default unless already defined
@@ -5456,6 +5465,11 @@ ($)
     mtr_add_arg($args, "--view-protocol");
   }
 
+  if ( $opt_trace_protocol )
+  {
+    mtr_add_arg($args, "--opt-trace-protocol");
+  }
+
   if ( $opt_cursor_protocol )
   {
     mtr_add_arg($args, "--cursor-protocol");
@@ -5961,6 +5975,7 @@ ($)
   cursor-protocol       Use the cursor protocol between client and server
                         (implies --ps-protocol)
   view-protocol         Create a view to execute all non updating queries
+  opt-trace-protocol    Print optimizer trace
   explain-protocol      Run 'EXPLAIN EXTENDED' on all SELECT queries
   sp-protocol           Create a stored procedure to execute all queries
   compress              Use the compressed protocol between client and server
@@ -6062,7 +6077,9 @@ ($)
   ddd                   Start mysqld in ddd
   debug                 Dump trace output for all servers and client programs
   debug-common          Same as debug, but sets 'd' debug flags to
-                        "query,info,error,enter,exit"
+                        "query,info,error,enter,exit"; you need this if you
+                        want both to see debug printouts and to use
+                        DBUG_EXECUTE_IF.
   debug-server          Use debug version of server, but without turning on
                         tracing
   debugger=NAME         Start mysqld in the selected debugger