#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#53630 | Tatiana Azundris Nurnberg | 6 Jan |
