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

[30 Sep 2006 21:11] Andrei Elkin
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.
[1 Oct 2006 5:23] Valeriy Kravchuk
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.
[1 Oct 2006 5:40] Valeriy Kravchuk
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.
[2 Oct 2006 9:22] Lars Thalmann
It is not a bug that the statement is logged as multiple log events.
This is common in row-based logging.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.054 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.