MySQL Bugs: #62540: Table locks within stored functions are back in 5.5 with MIXED and ROW binlog

Bug #62540	Table locks within stored functions are back in 5.5 with MIXED and ROW binlog
Submitted:	26 Sep 2011 8:30	Modified:	31 Jul 2012 2:00
Reporter:	Alexander Keremidarski	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.5.16, 5.6.4	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
Hello,

This could be the old bug http://bugs.mysql.com/bug.php?id=18077 which was fixed in 5.0 and 5.1 and later introduced again in 5.5.

With MIXED and ROW binlog format:

* MySQL 5.5 sets table locks for table from which Stored Function SELECTs. 
* MySQL 5.1 does not set any locks with same Stored Function
* Same SELECT running from within Stored Procedure doesn't set any locks with both 5.1 and 5.5
* With STATEMENT binlog format no locks are set by 5.1 or 5.5
* innodb_locks_unsafe_for_binlog does not have any effect on the above.

How to repeat:
CREATE TABLE test (
  id int(10) unsigned NOT NULL,
  x char(3) DEFAULT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO test VALUES(1,'foo'),(2,'bar');

DELIMITER //

CREATE FUNCTION `test_f`(x CHAR(8)) RETURNS INT
  READS SQL DATA
BEGIN 
  DECLARE output INT DEFAULT NULL; 
  SELECT t.id FROM test t WHERE t.x =x INTO output; 
  RETURN output; 
END //

CREATE PROCEDURE `test_p`(IN x CHAR(8), OUT output INT)
  READS SQL DATA
BEGIN 
  SELECT id FROM test t WHERE t.x = x INTO output; 
END //

DELIMITER ;

CREATE TABLE innodb_monitor(x INT);
CREATE TABLE innodb_lock_monitor(x INT);

START TRANSACTION; SELECT test_f('foo');

# From another session:
SHOW ENGINE INNODB STATUS;

# observe locks reported by innodb_lock_monitor like:
---TRANSACTION 9C08, ACTIVE 2 sec
2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 1, OS thread handle 0x7f4d206ba700, query id 63 localhost root
TABLE LOCK table `bugs`.`test` trx id 9C08 lock mode IS
RECORD LOCKS space id 0 page no 147489 n bits 72 index `PRIMARY` of table `bugs`.`test` trx id 9C08 lock mode S locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 00000001; asc     ;;
 1: len 6; hex 000000009a06; asc       ;;
 2: len 7; hex 8500017b9f0110; asc    {   ;;
 3: len 3; hex 666f6f; asc foo;;

# with procedure no locks are set
START TRANSACRION; SET @x:=0; CALL test_p('foo', @x); SELECT @x;

# SHOW ENGINE INNODB STATUS doesn't show any locks and the rows can be locked manually from another transaction. For example with:

START TRANSACRION; SET @x:=0; CALL test_p('foo', @x); SELECT @x;
# from another session:
SELECT id FROM test WHERE x = 'bar' FOR UPDATE; -- returns immediately

# with
START TRANSACTION; SELECT test_f('foo');
# from another session:
SELECT id FROM test WHERE x = 'bar' FOR UPDATE; -- waits

Hello Mr. Keremidarski,

It is evident from your reported bug that you are not a beginner with both SQL and our product.

But, before we proceed to check your claim(s), could you try running your test case but without typos. You have used "START TRANSACRION" in several places.

Also, please, let us know if you have started a server with '--log-bin' option and whether you have set binlog_format option on the global or session level. You could also inform us about the format in which statements got written, when binlog_format is MIXED. For your information, in order to check that, you will have to COMMIT your transaction(s) first.

Many thanks in advance.

I already provided all the required information. The stored function definition and CREATE TABLE are enough as the bug can be reproduced with any data and any statement that calls the stored function. Provided that someone cares to attempt reproducing it indeed. 

Asking nonsensical questions like in what format SELECT func(); is logged in binlog does not help anyone. 

This is regression in MySQL 5.5 compared to 5.1. Such locks existed in early 5.0, but were removed later accordind to bug http://bugs.mysql.com/bug.php?id=18077

Do I understand it correct that Oracle refuses to accept this bug report because of a typo outside of the test case and within statement irrelevant to reproducing the bug?

I can not repeat this with 5.5.16 on Windows XP with the following settings:

mysql> show variables like '%bin%';
+-----------------------------------------+----------------------+
| Variable_name                           | Value                |
+-----------------------------------------+----------------------+
| binlog_cache_size                       | 32768                |
| binlog_direct_non_transactional_updates | OFF                  |
| binlog_format                           | ROW                  |
| binlog_stmt_cache_size                  | 32768                |
| innodb_locks_unsafe_for_binlog          | OFF                  |
| log_bin                                 | ON                   |
| log_bin_trust_function_creators         | OFF                  |
| max_binlog_cache_size                   | 18446744073709547520 |
| max_binlog_size                         | 1073741824           |
| max_binlog_stmt_cache_size              | 18446744073709547520 |
| sql_log_bin                             | ON                   |
| sync_binlog                             | 0                    |
+-----------------------------------------+----------------------+
12 rows in set (0.00 sec)

No locks are reported:

------------
TRANSACTIONS
------------
Trx id counter 270D
Purge done for trx's n:o < 2706 undo n:o < 0
History list length 36
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 270C, not started
MySQL thread id 5, OS thread handle 0x474, query id 41 localhost 127.0.0.1 root
---TRANSACTION 270B, ACTIVE 89 sec, thread declared inside InnoDB 498
mysql tables in use 1, locked 0
MySQL thread id 4, OS thread handle 0x26c4, query id 34 localhost 127.0.0.1 root
 User sleep
SELECT test_f('foo'), sleep(120)
Trx read view will not see trx with id >= 270C, sees < 270C
--------

and concurrent SELECT ... FOR UPDATE is not blocked.

Probably I miss something. I wonder what are the values of the variables listed above in your case.

Now it becomes interesting. I am testing under Linux and I really hope it is not OS dependant issue. My binlog settings I use are pretty much the defaults as you can see below. I tried changing binlog_format, innodb_locks_unsafe_for_binlog and log_bin_trust_function_creators and log_bin. With log_bin=OFF no locks are set as expected. More on my config at the end: 

mysql> show variables like "%bin%";
+-----------------------------------------+----------------------+
| Variable_name                           | Value                |
+-----------------------------------------+----------------------+
| binlog_cache_size                       | 32768                |
| binlog_direct_non_transactional_updates | OFF                  |
| binlog_format                           | ROW                  |
| binlog_stmt_cache_size                  | 32768                |
| innodb_locks_unsafe_for_binlog          | OFF                  |
| log_bin                                 | ON                   |
| log_bin_trust_function_creators         | OFF                  |
| max_binlog_cache_size                   | 18446744073709547520 |
| max_binlog_size                         | 1073741824           |
| max_binlog_stmt_cache_size              | 18446744073709547520 |
| sql_log_bin                             | ON                   |
| sync_binlog                             | 0                    |
+-----------------------------------------+----------------------+

I tried with fresh install using:

* MySQL-server-5.5.16-1.linux2.6.x86_64.rpm
* empty datadir
* my.cnf with single line in [mysqld]
cat /etc/my.cnf 
[mysqld]
log_bin=1

Upon first start of mysqld and executing the test case as described (up until SHOW ENGINE INNODB STATUS;) I see exactly the same table locks. When running  SHOW ENGINE INNODB STATUS before the statement with function call:

------------
TRANSACTIONS
------------
Trx id counter 305
Purge done for trx's n:o < 0 undo n:o < 0
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2, OS thread handle 0x7fd1985e8700, query id 9 localhost root
show engine innodb status
---TRANSACTION 302, not started
MySQL thread id 1, OS thread handle 0x7fd185276700, query id 7 localhost root

Then from another connection: 
START TRANSACTION; SELECT test_f('foo');

and SHOW ENGINE INNODB STATUS from the other connection now shows:

------------
TRANSACTIONS
------------
Trx id counter 306
Purge done for trx's n:o < 0 undo n:o < 0
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2, OS thread handle 0x7fd1985e8700, query id 15 localhost root
show engine innodb status
---TRANSACTION 305, ACTIVE 9 sec
2 lock struct(s), heap size 376, 3 row lock(s)
MySQL thread id 1, OS thread handle 0x7fd185276700, query id 11 localhost root
TABLE LOCK table `test`.`test` trx id 305 lock mode IS
RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`test` trx id 305 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 00000001; asc     ;;
 1: len 6; hex 000000000302; asc       ;;
 2: len 7; hex 83000001340110; asc     4  ;;
 3: len 3; hex 666f6f; asc foo;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 00000002; asc     ;;
 1: len 6; hex 000000000302; asc       ;;
 2: len 7; hex 8300000134011c; asc     4  ;;
 3: len 3; hex 626172; asc bar;;

See http://bugs.mysql.com/bug.php?id=37578 also...

I wonder what transaction isolation level do you use?

I was able to get exactly the same locks as in your case, but only after setting:

set transaction isolation level serializable;

before START TRANSACTION...

But for SERIALIZABLE isolation level locking read is expected and, thus, IS table level lock is also expected.

Once again I use fresh install with all the default startup parameters which I ensure by /etc/my.cnf file containing single log-bin=ON line. There are no other my.cnf files which this mysqld will potentially read. Hence the isolation level is REPEATABLE-READ.

Out of curiosity I tested with all four isolation levels: READ UNCOMMITTED, READ COMMITTED, REPEATABLE READ and SERIALIZABLE. The result is always the same. I get table lock displayed by InnoDB status for the stored function while stored procedure acquires this lock only for SERIALIZABLE which is more or less expected. The table lock for SP in SERIALIZABLE doesn't make much sense, but let's suppose it does. 

What is funny is that with SERIALIZABLE running the SELECT statement alone outside of stored routine does not set any locks! Neighter table lock (it shouldn't) nor row locks which it should set according to the manual: "InnoDB implicitly converts all plain SELECT statements to SELECT ... LOCK IN SHARE MODE if autocommit is disabled." That would be different bug though.

Thank you for the feedback.

Verified as described using debug build of mysql-trunk (5.6.4)

I was debugging to find the source of the bug, and it seems that is here

bool DML_prelocking_strategy::
handle_routine(THD *thd, Query_tables_list *prelocking_ctx,
               Sroutine_hash_entry *rt, sp_head *sp, bool *need_prelocking)
{
  /*
    We assume that for any "CALL proc(...)" statement sroutines_list will
    have 'proc' as first element (it may have several, consider e.g.
    "proc(sp_func(...)))". This property is currently guaranted by the
    parser.
  */

  if (rt != (Sroutine_hash_entry*)prelocking_ctx->sroutines_list.first ||
      rt->mdl_request.key.mdl_namespace() != MDL_key::PROCEDURE)
  {
    *need_prelocking= TRUE;
    sp_update_stmt_used_routines(thd, prelocking_ctx, &sp->m_sroutines,
                                 rt->belong_to_view);
    (void)sp->add_used_tables_to_table_list(thd,
                                            &prelocking_ctx->query_tables_last,
                                            rt->belong_to_view);
  }
  sp->propagate_attributes(prelocking_ctx);
  return FALSE;
}

need_prelocking becomes true for all functions

sorry, the location of the routine of my previous comment is sql_base.cc lines 5063 to 5086

Noted in 5.6.7, 5.7.0 changelogs.

With statement-based binary logging, stored routines that accessed
but did not modify tables took too strong a lock for the tables,
unnecessarily blocking other statements that also accessed those 
tables.

Hi,

This is really a show stopper for anyone using stored functions and non-RBR binlog_format. Is there any chance of the bug fix to be back ported to 5.5 series? Currently, the only workaround seems to be to either use binlog_format=ROW or rewrite the stored function to a stored procedure with an OUT param.

I would like to make this correction to the bug description.

Instead of the following:
With MIXED and ROW binlog format:
* MySQL 5.5 sets table locks for table from which Stored Function SELECTs. 
* With STATEMENT binlog format no locks are set by 5.1 or 5.5

The correct description should be:
With MIXED and STATEMENT binlog format:
* MySQL 5.5 sets table locks for table from which Stored Function SELECTs. 
* With any binlog format no locks are set by 5.1
* With ROW binlog format no locks are set by 5.5

Will this bug be fixed in 5.5 ? It is very annoying.