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:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.1, 6.0 bzr OS:Any
Assigned to: Staale Smedseng CPU Architecture:Any
Tags: regression
Triage: Triaged: D3 (Medium)

[9 Jun 2009 8:04] Sveta Smirnova
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
[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] 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 2009 12: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 2009 12: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 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] 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 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] 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 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.