| Bug #45387 | Information about statement id for prepared statements missed from general log | ||
|---|---|---|---|
| Submitted: | 9 Jun 2009 8:04 | Modified: | 4 Sep 2009 11:10 |
| Reporter: | Sveta Smirnova | Email Updates: | |
| Status: | Won't fix | Impact on me: | |
| Category: | MySQL Server | Severity: | S3 (Non-critical) |
| Version: | 5.1, 6.0 bzr | OS: | Any |
| Assigned to: | Staale Smedseng | CPU Architecture: | Any |
| Tags: | regression | ||
[9 Jun 2009 8:14]
Sveta Smirnova
Test case for the testsuite: --let $MYSQLD_LOG=`select @@general_log_file` prepare p2 from 'select ?'; set @a=1; execute p2 using @a; --exec cat $MYSQLD_LOG
[9 Jun 2009 12:46]
MySQL Verification Team
Sveta, In 5.1, nothing is missing. Thread ID is right there, after timestamp. The only thing missing is one blank ... ;o)
[9 Jun 2009 12:51]
MySQL Verification Team
This is an extremely easy fix for this "bug" ...
=== modified file 'sql/log.cc'
--- sql/log.cc 2009-04-09 15:25:25 +0000
+++ sql/log.cc 2009-06-09 12:52:27 +0000
@@ -2086,7 +2086,7 @@
goto err;
/* command_type, thread_id */
- length= my_snprintf(buff, 32, "%5ld ", (long) thread_id);
+ length= my_snprintf(buff, 32, " %5ld ", (long) thread_id);
if (my_b_write(&log_file, (uchar*) buff, length))
goto err;
[9 Jun 2009 12:59]
MySQL Verification Team
Better fix for thread_id:
=== modified file 'sql/log.cc'
--- sql/log.cc 2009-04-09 15:25:25 +0000
+++ sql/log.cc 2009-06-09 13:02:02 +0000
@@ -2073,7 +2073,7 @@
localtime_r(&event_time, &start);
time_buff_len= my_snprintf(local_time_buff, MAX_TIME_SIZE,
- "%02d%02d%02d %2d:%02d:%02d",
+ "%02d%02d%02d %2d:%02d:%02d\t",
start.tm_year % 100, start.tm_mon + 1,
start.tm_mday, start.tm_hour,
start.tm_min, start.tm_sec);
[11 Jun 2009 14:09]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/76128 2935 Staale Smedseng 2009-06-11 Bug #45387 Information about statement id for prepared statements missed from general log Insufficient separation between timetag and ID in the log file causes the ID to become intelligible. Separation is added, and a testcase is supplied which logs a few statements to file and parses and compares the actual and expected IDs. @ mysql-test/t/log_state.test A small Perl script is embedded to parse the output to the given log file, extracting the ID and comparing to the expected value.
[11 Jun 2009 15:09]
Davi Arnaut
Although the Thread ID together with the Timestamp is a bug, Sveta is complaining about the lack of the Statement ID: In 5.0: 7 Execute [2] insert into a values(1,2,5) In 5.1: 13067 Execute insert into a values(1,2,3) The value within bracket is the Statement Id. Sveta, As part of fix for Bug#21557, we had to change the log format of prepared statements to avoid truncation. Perhaps we should now investigate whether we can pass prepared statement information down the log call stack.
[11 Jun 2009 20:35]
Sveta Smirnova
Output of patch for statement id:
prepare p2 from 'select ?';
set @a=1;
execute p2 using @a;
?
1
/users/ssmirnova/src/mysql-5.1/sql/mysqld, Version: 5.1.36-debug-log (Source distribution). started with:
Tcp port: 13000 Unix socket: /users/ssmirnova/src/mysql-5.1/mysql-test/var/tmp/mysqld.1.sock
Time Id Command Argument
090611 23:32:07 1 Connect root@localhost on
090611 23:32:08 1 Query call mtr.check_testcase()
1 Quit
2 Connect root@localhost on test
2 Query select @@general_log_file
2 Query prepare p2 from 'select ?'
2 Prepare [1] select ?
2 Query set @a=1
2 Query execute p2 using @a
2 Execute [1] select 1
[11 Jun 2009 20:36]
MySQL Verification Team
This is a second part of the patch:
=== modified file 'sql/sql_prepare.cc'
--- sql/sql_prepare.cc 2009-02-13 16:41:47 +0000
+++ sql/sql_prepare.cc 2009-06-11 17:57:29 +0000
@@ -3106,7 +3106,13 @@
the general log.
*/
if (thd->spcont == NULL)
- general_log_write(thd, COM_STMT_PREPARE, query, query_length);
+ {
+ const char *format= "[%lu] %.*b";
+ general_log_print(thd, COM_STMT_PREPARE, format, id,
+ query_length, query);
+
+ }
+
}
DBUG_RETURN(error);
}
@@ -3610,7 +3616,11 @@
the general log.
*/
if (error == 0 && thd->spcont == NULL)
- general_log_write(thd, COM_STMT_EXECUTE, thd->query, thd->query_length);
+ {
+ const char *format= "[%lu] %.*b";
+ general_log_print(thd, COM_STMT_EXECUTE, format, id,
+ thd->query_length, thd->query);
+ }
error:
flags&= ~ (uint) IS_IN_USE;
[12 Jun 2009 1:47]
Davi Arnaut
Sveta, We still don't have a patch for the Statement Id problem -- I noted this on the reply to the patch. The one that was committed only addresses the Thread Id. We still need to investigate whether a solution for the statement id problem is feasible. Sinisa, We should aim for something better then reverting changes made in Bug#21557.
[12 Jun 2009 14:28]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/76204 2939 Staale Smedseng 2009-06-12 Bug #45387 Information about statement id for prepared statements missed from general log A refinement of the test in the previous patch to avoid using sleep as a means to ensure that timestamps are added to the log entries. @ mysql-test/t/log_tables_debug.test New test file. A debug feature is used to ensure that log entries are prefixed with a timestamp. @ sql/log.cc A debug feature is implemented to ensure that log entries are prefixed with a timestamp.
[15 Jun 2009 16:06]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/76315 2943 Staale Smedseng 2009-06-15 Bug #45387 Information about statement id for prepared statements missed from general log A FLUSH LOGS is added to ensure that the log info hits the file before attempting to process. @ mysql-test/t/log_tables_debug.test A FLUSH LOGS is added, and in the event that a match is not found, <FILE> is reset and the contents of the log file is dumped for debugging purposes.
[16 Jun 2009 11:04]
Bugs System
Pushed into 5.1.36 (revid:joro@sun.com-20090616102155-3zhezogudt4uxdyn) (version source revid:staale.smedseng@sun.com-20090615160325-miaxz8z9rjgm78h4) (merge vers: 5.1.36) (pib:6)
[24 Jun 2009 17:22]
MySQL Verification Team
Davi, I did not know about bug #21557, so I did not intentionally intend to revert back the changes ... Can you tell me in short (in private note if you wish), what is a problem in providing info on the `id`. As far as I have seen while debugging, this info is available, so please tell me what is the crux of the problem. Thanks.
[10 Jul 2009 11:21]
Bugs System
Pushed into 5.4.4-alpha (revid:anozdrin@bk-internal.mysql.com-20090710111017-bnh2cau84ug1hvei) (version source revid:staale.smedseng@sun.com-20090615160439-hoxfi2ie4knij4eh) (merge vers: 5.4.4-alpha) (pib:11)
[26 Aug 2009 13:46]
Bugs System
Pushed into 5.1.37-ndb-7.0.8 (revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[26 Aug 2009 13:46]
Bugs System
Pushed into 5.1.37-ndb-6.3.27 (revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (version source revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (merge vers: 5.1.37-ndb-6.3.27) (pib:11)
[26 Aug 2009 13:48]
Bugs System
Pushed into 5.1.37-ndb-6.2.19 (revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (version source revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (merge vers: 5.1.37-ndb-6.2.19) (pib:11)
[27 Aug 2009 16:33]
Bugs System
Pushed into 5.1.35-ndb-7.1.0 (revid:magnus.blaudd@sun.com-20090827163030-6o3kk6r2oua159hr) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[4 Sep 2009 11:10]
Staale Smedseng
Customer has requested associated support issue to be closed. A related feature request has been opened (Bug#45416).
[15 Feb 2010 15:54]
Paul DuBois
Noted in 5.1.36 changelog. A separator was added between the time tag and the thread ID in the general query log file.
Description: In version 5.0 we had in general log following information: 090609 11:41:32 7 Query prepare p1 from 'insert into a values(?,?,?)' 7 Prepare [2] insert into a values(?,?,?) 090609 11:41:35 7 Query execute p1 using @id, @b, @c 090609 11:41:36 8 Connect Access denied for user 'MySQL_Instance_M'@'localhost' (using password: YES) 090609 11:41:41 7 Query set @id=1, @b=2, @c=5 090609 11:41:43 7 Query execute p1 using @id, @b, @c 7 Execute [2] insert into a values(1,2,5) 090609 11:41:45 7 Query set @id=1, @b=2, @c=6 090609 11:41:47 7 Query execute p1 using @id, @b, @c 7 Execute [2] insert into a values(1,2,6) 090609 11:41:56 9 Connect Access denied for user 'MySQL_Instance_M'@'localhost' (using password: YES) 090609 11:41:59 7 Query prepare p2 from 'select ?' 7 Prepare [3] select ? 090609 11:42:03 7 Query set @a=1 090609 11:42:12 7 Query execute p2 using @a 7 Execute [3] select 1 090609 11:42:13 7 Query execute p2 using @a 7 Execute [3] select 1 090609 11:42:14 7 Query execute p2 using @a 7 Execute [3] select 1 7 Query execute p2 using @a 7 Execute [3] select 1 090609 11:42:15 7 Quit While in 5.1 part of such information is missed: 13067 Prepare insert into a values(?,?,?) 090609 11:32:4113067 Query set @id=1, @b=2, @c=3 090609 11:32:5413067 Query execute p1 using @id, @b, @c 13067 Execute insert into a values(1,2,3) 090609 11:32:5713067 Quit How to repeat: prepare p2 from 'select ?' set @a=1 execute p2 using @a Examine general query log Suggested fix: Print this information