MySQL Bugs: #37091: Binlog filename and position saved in InnoDB might be inconsistent

Bug #37091	Binlog filename and position saved in InnoDB might be inconsistent
Submitted:	30 May 2008 7:28	Modified:	20 Aug 2008 22:33
Reporter:	Zhenxing He	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.1, 6.0	OS:	Any
Assigned to:	Inaam Rana	CPU Architecture:	Any

Description:
Innodb storage engine saved binlog filename and position in its transaction log, but the code to get the filename and position of binlog is not protected by the global lock of binlog, it is only protected by the `prepare_commit_mutex', which can only protect other innodb transactions to update the binlog file. Transactions of other storage engine can still commit and update binlog file. 

Lets consider the following scenario:
  th1> innodb transaction write to binlog; start commit( before get the binlog filename and position)
  th2> myiasm transaction commit, write to binlog;
  th1> get the binlog filename and position and continue commit

The binlog filename and position would be the filename and position of the myiasm transaction. What's more serious is if the call to get filename and get position is interrupted and there is a binlog rotate,  then the filename and position would be completely invalid: 
  th1> innodb transaction write to binlog; start commit; 
  th1> get the binlog filename; (before get the position)
  th2> myiasm transaction commit, write to binlog and cause a rotate;
  th1> get log position and continue commit

How to repeat:
No able to repeat directly, but we can examine this by adding some debugging code before or after read the filename and position of binlog in `innobase_commit' function of file ha_innodb.cc

Suggested fix:
I don't know how the information of binlog filename and position in innodb transaction log is used, if only the order is important, then we only need to prevent the second scenario to happen, i.e  protect with binlog global lock when get the filename and position.  If the information must be correct, then we have to prevent the first scenario two.

One way to examine this is applying the follow patch to storage/innobase/handler/ha_innodb.cc:

--- storage/innobase/handler/ha_innodb.cc	2008-04-14 10:15:04 +0000
+++ storage/innobase/handler/ha_innodb.cc	2008-05-30 07:33:36 +0000
@@ -1884,6 +1884,8 @@
 
 		trx->mysql_log_file_name = mysql_bin_log_file_name();
 		trx->mysql_log_offset = (ib_longlong) mysql_bin_log_file_pos();
+		while (trx->mysql_log_offset == (ib_longlong) mysql_bin_log_file_pos())
+		  sleep(1);
 
 		innobase_commit_low(trx);

compile and start the server with log-bin, then run the following in one client:

    create table t1 (a int) engine=INNODB;
    insert into t1 values (1);

This would hang  until do the following in another client:

  create table t2 (b int) engine=MyISAM;
  insert into t2 values (1);

Which means the binlog file position can be updated by transaction of other engines.

I think it is "work as design". If you want to guarantee the consistency, you have to use transactional engines with XA turned on. There was an innodb_safe_binlog setting prior to 5.0.3, but removed as part of XA implementation. Please see:

http://bugs.mysql.com/bug.php?id=28714

Hi Calvin

innodb_support_xa is enabled, and what I mean is not the inconsistence of innodb transaction and binlog, it is the binlog filename and position stored in innodb transaction log can be wrong.

It is correct that they may be entries in the binlog that do not belong to InnoDB tables. That is not serious.

A more serious thing is that since the read of the binlog file name and the position is not protected my any mutex, we may read an inconsistent position if MyISAM operations are concurrently running.

Assigning this to Inaam. Please study if in 6.0 we can protect the following with some MySQL binlog mutex:

                trx->mysql_log_file_name = mysql_bin_log_file_name();
                trx->mysql_log_offset = (ib_longlong) mysql_bin_log_file_pos();

Please see also bug#38501 "hold times on prepare_commit_mutex limit read/write scalability" which relates to this issue.

Set to verified according to Heikki comment.

There are two issues raised here.

1) Entries in binary log coming from other storage engines than InnoDB. This, as Heikki mentioned, is not an issue.

2) Possible rotation of binary log file between the read of log file name and its position.

There is enough protection in MySQL code to avoid this. If there is a trx in prepared state, the binary log rotation will wait until that trx is committed.

I tried it in the debugger and get the following stack:

#0  0xb7f582a1 in pthread_cond_wait@@GLIBC_2.3.2 () from /usr/lib/debug/libpthread.so.0
#1  0x08650935 in safe_cond_wait (cond=0x88f3760, mp=0x88f371c, file=0x874fb20 "log.cc", 
    line=3413) at thr_mutex.c:249
#2  0x08317c6e in MYSQL_BIN_LOG::new_file_impl (this=0x88f32a0, need_lock=false)
    at log.cc:3413
#3  0x08317f31 in MYSQL_BIN_LOG::new_file_without_locking (this=0x88f32a0) at log.cc:3367
#4  0x08317fed in MYSQL_BIN_LOG::rotate_and_purge (this=0x88f32a0, flags=1)
    at log.cc:4103
#5  0x0831959e in MYSQL_BIN_LOG::write (this=0x88f32a0, event_info=0x8ac52c28)
    at log.cc:4004
#6  0x082312e1 in THD::binlog_query (this=0xa576288, qtype=THD::ROW_QUERY_TYPE, 
    query_arg=0xa58e010 "INSERT INTO t_0 VALUES    ( 7022, 7023, 7024, 66358 )", 
    query_len=53, is_trans=false, suppress_use=false, killed_status_arg=THD::NOT_KILLED)
    at sql_class.cc:3686
#7  0x082f41f0 in mysql_insert (thd=0xa576288, table_list=0xa58e0f0, fields=@0xa57793c, 
    values_list=@0xa577960, update_fields=@0xa577954, update_values=@0xa577948, 
    duplic=DUP_ERROR, ignore=false) at sql_insert.cc:915
#8  0x082604b1 in mysql_execute_command (thd=0xa576288) at sql_parse.cc:2950
#9  0x08267231 in mysql_parse (thd=0xa576288, 
    inBuf=0xa58e010 "INSERT INTO t_0 VALUES    ( 7022, 7023, 7024, 66358 )", length=53, 
    found_semicolon=0x8ac53fb8) at sql_parse.cc:5811
#10 0x08267e0c in dispatch_command (command=COM_QUERY, thd=0xa576288, 
    packet=0xa585fb1 "INSERT INTO t_0 VALUES    ( 7022, 7023, 7024, 66358 )", 
    packet_length=53) at sql_parse.cc:1051
#11 0x0826939e in do_command (thd=0xa576288) at sql_parse.cc:724
#12 0x082560c6 in handle_one_connection (arg=0xa576288) at sql_connect.cc:1153
#13 0xb7f53fba in start_thread (arg=0x8ac54b90) at pthread_create.c:296
#14 0xb7d4c3fe in clone () from /usr/lib/debug/libc.so.6

This happens when another thread is in the middle of trying to commit an InnoDB trx.

Thread 12 (Thread -1966584944 (LWP 24586)):
#0  MYSQL_BIN_LOG::unlog (this=0x88f32a0, cookie=1, xid=3) at log.cc:5421
#1  0x08382fb8 in ha_commit_trans (thd=0xa548658, all=false) at handler.cc:1149
#2  0x08383137 in ha_autocommit_or_rollback (thd=0xa548658, error=0) at handler.cc:1303
#3  0x08268df8 in dispatch_command (command=COM_QUERY, thd=0xa548658, 
    packet=0xa56fef1 "insert into t1 values (1)", packet_length=25) at sql_parse.cc:1408
#4  0x0826939e in do_command (thd=0xa548658) at sql_parse.cc:724
#5  0x082560c6 in handle_one_connection (arg=0xa548658) at sql_connect.cc:1153
---Type <return> to continue, or q <return> to quit---
#6  0xb7f53fba in start_thread (arg=0x8ac84b90) at pthread_create.c:296
#7  0xb7d4c3fe in clone () from /usr/lib/debug/libc.so.6

Hence I am closing it as 'Not a Bug'.

regards,
inaam