List:Commits« Previous MessageNext Message »
From:Tatiana Azundris Nurnberg Date:January 6 2011 12:27pm
Subject:bzr commit into mysql-trunk branch (azundris:3349) Bug#53630
View as plain text  
#At file:///Users/tnurnberg/forest/53630/56-53630/ based on revid:tor.didriksen@stripped

 3349 Tatiana Azundris Nurnberg	2011-01-06
      Bug#53630: include the connection ID in the slow query log
      
      Include thread_ID in both file and table forms of slow query log.
      Add new column to upgrade and 1st_install paths (CREATE/ALTER TABLE
      slow_log). Add integrity check for Slow Query Log Table.
     @ mysql-test/suite/sys_vars/r/slow_query_log_func.result
        nominally test for thread_id column
     @ mysql-test/suite/sys_vars/t/slow_query_log_func.test
        pro forma test, not that we needed one -- we don't test for the other
        columns either, and pretty much any integer is a good integer, though
        sanity should dictate that the last SLEEP() is from our connection.
     @ scripts/mysql_system_tables.sql
        if creating slow_log from scratch, have thread_id in there
     @ scripts/mysql_system_tables_fix.sql
        when upgrading an existing slow_log, add thread_id to slow_log if not already present
     @ scripts/mysqldumpslow.sh
        parse out thread_ID if it exists. not useful in itself, more something to
        build additional filters on.
     @ sql/log.cc
        add thread_ID to slow_log, both the file and the table variants.
        the table is what gets replicated if and when, no extra code required.
        add integrity check for Slow Query Log Table.
     @ sql/log.h
        enum Slow Query Log Table fields, for clarity and checks

    modified:
      mysql-test/suite/sys_vars/r/slow_query_log_func.result
      mysql-test/suite/sys_vars/t/slow_query_log_func.test
      scripts/mysql_system_tables.sql
      scripts/mysql_system_tables_fix.sql
      scripts/mysqldumpslow.sh
      sql/log.cc
      sql/log.h
=== modified file 'mysql-test/suite/sys_vars/r/slow_query_log_func.result'
--- a/mysql-test/suite/sys_vars/r/slow_query_log_func.result	2010-08-30 06:38:09 +0000
+++ b/mysql-test/suite/sys_vars/r/slow_query_log_func.result	2011-01-06 12:26:47 +0000
@@ -14,12 +14,17 @@ count(*)
 '----When slow_query_log = ON-----'
 SET @@global.slow_query_log = ON;
 TRUNCATE mysql.slow_log;
-SELECT sleep(2);
-sleep(2)
+SELECT sleep(2) AS bug53630;
+bug53630
 0
-SELECT count(*) > 0 FROM mysql.slow_log;
+SELECT count(*) > 0 FROM mysql.slow_log WHERE sql_text LIKE '% bug53630';
 count(*) > 0
 1
+SELECT thread_id - connection_id() FROM mysql.slow_log
+WHERE sql_text LIKE '% bug53630'
+                                   ORDER BY start_time DESC LIMIT 1;
+thread_id - connection_id()
+0
 'Bug#47905 stored procedures not logged correctly to slow query log'
 TRUNCATE mysql.slow_log;
 CREATE PROCEDURE p_test() 

=== modified file 'mysql-test/suite/sys_vars/t/slow_query_log_func.test'
--- a/mysql-test/suite/sys_vars/t/slow_query_log_func.test	2010-06-08 08:58:19 +0000
+++ b/mysql-test/suite/sys_vars/t/slow_query_log_func.test	2011-01-06 12:26:47 +0000
@@ -27,10 +27,12 @@ SELECT count(*) FROM mysql.slow_log;
 SET @@global.slow_query_log = ON;
 TRUNCATE mysql.slow_log;
 # The sleep is the slow query
-SELECT sleep(2);
-
-SELECT count(*) > 0 FROM mysql.slow_log;
+SELECT sleep(2) AS bug53630;
 
+SELECT count(*) > 0 FROM mysql.slow_log WHERE sql_text LIKE '% bug53630';
+SELECT thread_id - connection_id() FROM mysql.slow_log
+                                   WHERE sql_text LIKE '% bug53630'
+                                   ORDER BY start_time DESC LIMIT 1;
 
 #==========================================================================
 --echo 'Bug#47905 stored procedures not logged correctly to slow query log'

=== modified file 'scripts/mysql_system_tables.sql'
--- a/scripts/mysql_system_tables.sql	2010-11-09 08:16:50 +0000
+++ b/scripts/mysql_system_tables.sql	2011-01-06 12:26:47 +0000
@@ -89,7 +89,7 @@ DROP PREPARE stmt;
 
 -- Create slow_log if CSV is enabled.
 
-SET @str = IF (@have_csv = 'YES', 'CREATE TABLE IF NOT EXISTS slow_log (start_time TIMESTAMP NOT NULL, user_host MEDIUMTEXT NOT NULL, query_time TIME NOT NULL, lock_time TIME NOT NULL, rows_sent INTEGER NOT NULL, rows_examined INTEGER NOT NULL, db VARCHAR(512) NOT NULL, last_insert_id INTEGER NOT NULL, insert_id INTEGER NOT NULL, server_id INTEGER UNSIGNED NOT NULL, sql_text MEDIUMTEXT NOT NULL) engine=CSV CHARACTER SET utf8 comment="Slow log"', 'SET @dummy = 0');
+SET @str = IF (@have_csv = 'YES', 'CREATE TABLE IF NOT EXISTS slow_log (start_time TIMESTAMP NOT NULL, user_host MEDIUMTEXT NOT NULL, query_time TIME NOT NULL, lock_time TIME NOT NULL, rows_sent INTEGER NOT NULL, rows_examined INTEGER NOT NULL, db VARCHAR(512) NOT NULL, last_insert_id INTEGER NOT NULL, insert_id INTEGER NOT NULL, server_id INTEGER UNSIGNED NOT NULL, sql_text MEDIUMTEXT NOT NULL, thread_id INTEGER NOT NULL) engine=CSV CHARACTER SET utf8 comment="Slow log"', 'SET @dummy = 0');
 
 PREPARE stmt FROM @str;
 EXECUTE stmt;

=== modified file 'scripts/mysql_system_tables_fix.sql'
--- a/scripts/mysql_system_tables_fix.sql	2010-11-03 11:51:15 +0000
+++ b/scripts/mysql_system_tables_fix.sql	2011-01-06 12:26:47 +0000
@@ -255,6 +255,8 @@ ALTER TABLE slow_log
   MODIFY insert_id INTEGER NOT NULL,
   MODIFY server_id INTEGER UNSIGNED NOT NULL,
   MODIFY sql_text MEDIUMTEXT NOT NULL;
+ALTER TABLE slow_log
+  ADD COLUMN thread_id INTEGER NOT NULL AFTER sql_text;
 SET GLOBAL slow_query_log = @old_log_state;
 
 ALTER TABLE plugin

=== modified file 'scripts/mysqldumpslow.sh'
--- a/scripts/mysqldumpslow.sh	2009-05-07 17:40:00 +0000
+++ b/scripts/mysqldumpslow.sh	2011-01-06 12:26:47 +0000
@@ -81,7 +81,7 @@ while ( defined($_ = shift @pending) or 
     }
 
     s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
-    my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
+    my ($user,$host,$dummy,$thread_id) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+)\s+\S+(\s+Id:\s+(\d+))?.*\n// ? ($1,$2,$3,$4) : ('','','','','');
 
     s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
     my ($t, $l, $r) = ($1, $2, $3);

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2010-11-16 12:38:17 +0000
+++ b/sql/log.cc	2011-01-06 12:26:47 +0000
@@ -47,6 +47,89 @@
 #define MAX_LOG_BUFFER_SIZE 1024
 #define MAX_TIME_SIZE 32
 
+static
+const TABLE_FIELD_TYPE slow_query_log_table_fields[SQLT_FIELD_COUNT] =
+{
+  {
+    { C_STRING_WITH_LEN("start_time") },
+    { C_STRING_WITH_LEN("timestamp") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("user_host") },
+    { C_STRING_WITH_LEN("mediumtext") },
+    { C_STRING_WITH_LEN("utf8") }
+  },
+  {
+    { C_STRING_WITH_LEN("query_time") },
+    { C_STRING_WITH_LEN("time") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("lock_time") },
+    { C_STRING_WITH_LEN("time") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("rows_sent") },
+    { C_STRING_WITH_LEN("int(11)") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("rows_examined") },
+    { C_STRING_WITH_LEN("int(11)") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("db") },
+    { C_STRING_WITH_LEN("varchar(512)") },
+    { C_STRING_WITH_LEN("utf8") }
+  },
+  {
+    { C_STRING_WITH_LEN("last_insert_id") },
+    { C_STRING_WITH_LEN("int(11)") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("insert_id") },
+    { C_STRING_WITH_LEN("int(11)") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("server_id") },
+    { C_STRING_WITH_LEN("int(10) unsigned") },
+    { NULL, 0 }
+  },
+  {
+    { C_STRING_WITH_LEN("sql_text") },
+    { C_STRING_WITH_LEN("mediumtext") },
+    { C_STRING_WITH_LEN("utf8") }
+  },
+  {
+    { C_STRING_WITH_LEN("thread_id") },
+    { C_STRING_WITH_LEN("int(11)") },
+    { NULL, 0 }
+  }
+};
+
+static const TABLE_FIELD_DEF
+  event_table_def= {SQLT_FIELD_COUNT, slow_query_log_table_fields};
+
+class Slow_query_log_table_intact : public Table_check_intact
+{
+protected:
+  void report_error(uint, const char *fmt, ...)
+  {
+    va_list args;
+    va_start(args, fmt);
+    error_log_print(ERROR_LEVEL, fmt, args);
+    va_end(args);
+  }
+};
+
+/** In case of an error, a message is printed to the error log. */
+static Slow_query_log_table_intact sqlt_intact;
+
 LOGGER logger;
 
 static bool test_if_number(const char *str,
@@ -438,6 +521,9 @@ bool Log_to_csv_event_handler::
 
   need_close= TRUE;
 
+  if (sqlt_intact.check(table_list.table, &event_table_def))
+    goto err;
+
   if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||
       table->file->ha_rnd_init(0))
     goto err;
@@ -449,15 +535,12 @@ bool Log_to_csv_event_handler::
 
   restore_record(table, s->default_values);    // Get empty record
 
-  /* check that all columns exist */
-  if (table->s->fields < 11)
-    goto err;
-
   /* store the time and user values */
-  DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);
-  ((Field_timestamp*) table->field[0])->store_timestamp((my_time_t)
-                                                        current_time);
-  if (table->field[1]->store(user_host, user_host_len, client_cs))
+  DBUG_ASSERT(table->field[SQLT_FIELD_START_TIME]->type() == MYSQL_TYPE_TIMESTAMP);
+  ((Field_timestamp*) table->field[SQLT_FIELD_START_TIME])->store_timestamp(
+      (my_time_t) current_time);
+  if (table->field[SQLT_FIELD_USER_HOST]->store(user_host, user_host_len,
+                                                client_cs))
     goto err;
 
   if (query_start_arg)
@@ -474,42 +557,43 @@ bool Log_to_csv_event_handler::
 
     /* fill in query_time field */
     calc_time_from_sec(&t, (long) min(query_time, (longlong) TIME_MAX_VALUE_SECONDS), 0);
-    if (table->field[2]->store_time(&t, MYSQL_TIMESTAMP_TIME))
+    if (table->field[SQLT_FIELD_QUERY_TIME]->store_time(&t, MYSQL_TIMESTAMP_TIME))
       goto err;
     /* lock_time */
     calc_time_from_sec(&t, (long) min(lock_time, (longlong) TIME_MAX_VALUE_SECONDS), 0);
-    if (table->field[3]->store_time(&t, MYSQL_TIMESTAMP_TIME))
+    if (table->field[SQLT_FIELD_LOCK_TIME]->store_time(&t, MYSQL_TIMESTAMP_TIME))
       goto err;
     /* rows_sent */
-    if (table->field[4]->store((longlong) thd->sent_row_count, TRUE))
+    if (table->field[SQLT_FIELD_ROWS_SENT]->store((longlong) thd->sent_row_count, TRUE))
       goto err;
     /* rows_examined */
-    if (table->field[5]->store((longlong) thd->examined_row_count, TRUE))
+    if (table->field[SQLT_FIELD_ROWS_EXAMINED]->store((longlong) thd->examined_row_count, TRUE))
       goto err;
   }
   else
   {
-    table->field[2]->set_null();
-    table->field[3]->set_null();
-    table->field[4]->set_null();
-    table->field[5]->set_null();
+    table->field[SQLT_FIELD_QUERY_TIME]->set_null();
+    table->field[SQLT_FIELD_LOCK_TIME]->set_null();
+    table->field[SQLT_FIELD_ROWS_SENT]->set_null();
+    table->field[SQLT_FIELD_ROWS_EXAMINED]->set_null();
   }
   /* fill database field */
   if (thd->db)
   {
-    if (table->field[6]->store(thd->db, thd->db_length, client_cs))
+    if (table->field[SQLT_FIELD_DATABASE]->store(thd->db, thd->db_length,
+                                                 client_cs))
       goto err;
-    table->field[6]->set_notnull();
+    table->field[SQLT_FIELD_DATABASE]->set_notnull();
   }
 
   if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt)
   {
     if (table->
-        field[7]->store((longlong)
+        field[SQLT_FIELD_LAST_INSERT_ID]->store((longlong)
                         thd->first_successful_insert_id_in_prev_stmt_for_binlog,
                         TRUE))
       goto err;
-    table->field[7]->set_notnull();
+    table->field[SQLT_FIELD_LAST_INSERT_ID]->set_notnull();
   }
 
   /*
@@ -521,22 +605,27 @@ bool Log_to_csv_event_handler::
   if (thd->auto_inc_intervals_in_cur_stmt_for_binlog.nb_elements() > 0)
   {
     if (table->
-        field[8]->store((longlong)
+        field[SQLT_FIELD_INSERT_ID]->store((longlong)
           thd->auto_inc_intervals_in_cur_stmt_for_binlog.minimum(), TRUE))
       goto err;
-    table->field[8]->set_notnull();
+    table->field[SQLT_FIELD_INSERT_ID]->set_notnull();
   }
 
-  if (table->field[9]->store((longlong) server_id, TRUE))
+  if (table->field[SQLT_FIELD_SERVER_ID]->store((longlong) server_id, TRUE))
     goto err;
-  table->field[9]->set_notnull();
+  table->field[SQLT_FIELD_SERVER_ID]->set_notnull();
 
   /*
     Column sql_text.
     A positive return value in store() means truncation.
     Still logging a message in the log in this case.
   */
-  if (table->field[10]->store(sql_text, sql_text_len, client_cs) < 0)
+  if (table->field[SQLT_FIELD_SQL_TEXT]->store(sql_text, sql_text_len,
+                                               client_cs) < 0)
+    goto err;
+
+  if (table->field[SQLT_FIELD_THREAD_ID]->store((longlong) thd->thread_id,
+                                                TRUE))
     goto err;
 
   /* log table entries are not replicated */
@@ -1764,12 +1853,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, ti
         if (my_b_write(&log_file, (uchar*) buff, buff_len))
           tmp_errno= errno;
       }
-      const uchar uh[]= "# User@Host: ";
-      if (my_b_write(&log_file, uh, sizeof(uh) - 1))
-        tmp_errno= errno;
-      if (my_b_write(&log_file, (uchar*) user_host, user_host_len))
-        tmp_errno= errno;
-      if (my_b_write(&log_file, (uchar*) "\n", 1))
+      buff_len= my_snprintf(buff, 14, "  Id: %5ld\n", (long) thd->thread_id);
+      if (my_b_printf(&log_file, "# User@Host: %s  Id: %s\n", user_host, buff))
         tmp_errno= errno;
     }
     /* For slow query log */

=== modified file 'sql/log.h'
--- a/sql/log.h	2010-11-16 12:38:17 +0000
+++ b/sql/log.h	2011-01-06 12:26:47 +0000
@@ -216,6 +216,25 @@ public:
 #endif
 };
 
+
+enum enum_slow_query_log_table_field
+{
+  SQLT_FIELD_START_TIME = 0,
+  SQLT_FIELD_USER_HOST,
+  SQLT_FIELD_QUERY_TIME,
+  SQLT_FIELD_LOCK_TIME,
+  SQLT_FIELD_ROWS_SENT,
+  SQLT_FIELD_ROWS_EXAMINED,
+  SQLT_FIELD_DATABASE,
+  SQLT_FIELD_LAST_INSERT_ID,
+  SQLT_FIELD_INSERT_ID,
+  SQLT_FIELD_SERVER_ID,
+  SQLT_FIELD_SQL_TEXT,
+  SQLT_FIELD_THREAD_ID,
+  SQLT_FIELD_COUNT
+};
+
+
 class MYSQL_QUERY_LOG: public MYSQL_LOG
 {
 public:


Attachment: [text/bzr-bundle] bzr/azundris@sun.com-20110106122647-nkfdrjr6asnr5do5.bundle
Thread
bzr commit into mysql-trunk branch (azundris:3349) Bug#53630Tatiana Azundris Nurnberg6 Jan