MySQL Bugs: #22866: CREATE ... SELECT is logged extraneously surrounded with BEGIN

Bug #22866	CREATE ... SELECT is logged extraneously surrounded with BEGIN - COMMIT
Submitted:	30 Sep 2006 21:11	Modified:	2 Oct 2006 9:22
Reporter:	Andrei Elkin	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S3 (Non-critical)
Version:	5.1.12	OS:	Linux (linux)
Assigned to:	Lars Thalmann	CPU Architecture:	Any

Description:
Because of CREATE .. SELECT commits implicitly, it should be logged as a single
statement. no need to construct a transaction from it for the log. 
Currently a record in binlog it is recored as 3 queries

| master | 102 | Query       |         1 |         170 | use `test`; BEGIN                                        |
| master  | 170 | Query       |         1 |         159 | use `test`; CREATE TABLE `t` (
  `a` int(11) DEFAULT NULL,
  `b` int(1) NOT NULL DEFAULT '0'
) ENGINE=MyISAM |
| master | 329 | Table_map   |       -hkigw8-fe  1 |         198 | table_id: 130 (test.t)                                        |
| master | 368 | Write_rows  |         1 |         236 | table_id: 130 flags: STMT_END_F                                        |
| master | 406 | Query       |         1 |         475 | use `test`; COMMIT 
 
This applies to both myisam and innodb regardless of autocommit status.

How to repeat:
drop table if exists t; reset master; 
create table t (a int) select (1) as b;
show binlog events;

Suggested fix:
Remove extaneous parts of logging.

Thank you for a problem report. Sorry, but I was not able to repeat the behaviour described:

openxs@suse:~/dbs/5.1> bin/mysqld_safe --log-bin --binlog-format=row &
[1] 6448
openxs@suse:~/dbs/5.1> Starting mysqld daemon with databases from /home/openxs/d
bs/5.1/var

openxs@suse:~/dbs/5.1> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 5.1.12-beta-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> drop table if exists t; reset master;
Query OK, 0 rows affected (0.01 sec)

Query OK, 0 rows affected (0.02 sec)

mysql> create table t (a int) select (1) as b;
Query OK, 1 row affected (0.03 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql> show binlog events;
+-----------------+-----+-------------+-----------+-------------+------------------------------------------------------------------------------------------------+
| Log_name        | Pos | Event_type  | Server_id | End_log_pos | Info
 |
+-----------------+-----+-------------+-----------+-------------+------------------------------------------------------------------------------------------------+
| suse-bin.000001 |   4 | Format_desc |         1 |         102 | Server ver: 5.1.12-beta-debug-log, Binlog ver: 4 |
| suse-bin.000001 | 102 | Query       |         1 |         145 | use `test`; CREATE TABLE `t` (
  `a` int(11) DEFAULT NULL,
  `b` int(1) NOT NULL DEFAULT '0'
) |
| suse-bin.000001 | 247 | Table_map   |         1 |         184 | table_id: 31 (test.t) |
| suse-bin.000001 | 286 | Write_rows  |         1 |         222 | table_id: 31 flags: STMT_END_F |
+-----------------+-----+-------------+-----------+-------------+------------------------------------------------------------------------------------------------+
4 rows in set (0.01 sec)

on ChangeSet@1.2328.1.2, 2006-09-28 11:25:02-07:00.

Previous test was performed with autocommit=1 (by default). Let us see what happens with autocommit=0:

openxs@suse:~/dbs/5.1> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 5.1.12-beta-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> drop table if exists t; reset master;
Query OK, 0 rows affected (0.03 sec)

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> create table t (a int) engine=innodb select (1) as b;
Query OK, 1 row affected (0.02 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql> show binlog events;
+-----------------+-----+-------------+-----------+-------------+---------------
-----------------------------------+
| Log_name        | Pos | Event_type  | Server_id | End_log_pos | Info
                                   |
+-----------------+-----+-------------+-----------+-------------+---------------
-----------------------------------+
| suse-bin.000001 |   4 | Format_desc |         1 |         102 | Server ver: 5.
1.12-beta-debug-log, Binlog ver: 4 |
+-----------------+-----+-------------+-----------+-------------+---------------
-----------------------------------+
1 row in set (0.00 sec)

The above is a BUG. We should have this statement in the binary log, as it should be committed implicitely in any case (as any DDL).

mysql> commit;
Query OK, 0 rows affected (0.00 sec)

mysql> show binlog events;
+-----------------+-----+-------------+-----------+-------------+---------------
--------------------------------------------------------------------------------
---------------+
| Log_name        | Pos | Event_type  | Server_id | End_log_pos | Info

               |
+-----------------+-----+-------------+-----------+-------------+---------------
--------------------------------------------------------------------------------
---------------+
| suse-bin.000001 |   4 | Format_desc |         1 |         102 | Server ver: 5.
1.12-beta-debug-log, Binlog ver: 4
               |
| suse-bin.000001 | 102 | Query       |         1 |         170 | use `test`; BE
GIN
               |
| suse-bin.000001 | 170 | Query       |         1 |         159 | use `test`; CR
EATE TABLE `t` (
  `a` int(11) DEFAULT NULL,
  `b` int(1) NOT NULL DEFAULT '0'
) ENGINE=InnoDB |
| suse-bin.000001 | 329 | Table_map   |         1 |         198 | table_id: 31 (
test.t)
               |
| suse-bin.000001 | 368 | Write_rows  |         1 |         236 | table_id: 31 f
lags: STMT_END_F
               |
| suse-bin.000001 | 406 | Xid         |         1 |         433 | COMMIT /* xid=
23 */
               |
+-----------------+-----+-------------+-----------+-------------+---------------
--------------------------------------------------------------------------------
---------------+
6 rows in set (0.00 sec)

Now we have something similar to the initial report.

It is not a bug that the statement is logged as multiple log events.
This is common in row-based logging.