| Bug #45387 | Information about statement id for prepared statements missed from general log | ||
|---|---|---|---|
| Submitted: | 9 Jun 10:04 | Modified: | 4 Sep 13:10 |
| Reporter: | Sveta Smirnova | ||
| Status: | Won't fix | ||
| Category: | Server | Severity: | S3 (Non-critical) |
| Version: | 5.1, 6.0 bzr | OS: | Any |
| Assigned to: | Staale Smedseng | Target Version: | 5.1+ |
| Tags: | regression | ||
| Triage: | Triaged: D3 (Medium) | ||
[9 Jun 10: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 14:46]
Sinisa Milivojevic
Sveta, In 5.1, nothing is missing. Thread ID is right there, after timestamp. The only thing missing is one blank ... ;o)
[9 Jun 14:51]
Sinisa Milivojevic
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 14:59]
Sinisa Milivojevic
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 16: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 17: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 22: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 22:36]
Sinisa Milivojevic
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 3: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 16: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 18: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 13: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 19:22]
Sinisa Milivojevic
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 13: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 15: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 15: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 15: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 18: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 13:10]
Staale Smedseng
Customer has requested associated support issue to be closed. A related feature request has been opened (Bug#45416).
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