Bug #47179 Lock mode S placed on join
Submitted: 7 Sep 2009 18:12 Modified: 3 Nov 2009 10:00
Reporter: Athanasios Alekizoglou Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:5.1.35, 5.1.38 OS:Windows
Assigned to: CPU Architecture:Any

[7 Sep 2009 18:12] Athanasios Alekizoglou
Description:
I am experiencing an S lock mode on running a SELECT with JOIN. Previous version was 5.1.30 and the same SELECT was running fine.

How to repeat:
Table is:

CREATE TABLE `users` (
  `iUserID` int(11) unsigned NOT NULL DEFAULT '0',
  `strFName` varchar(25) DEFAULT NULL,
  `strLName` varchar(25) DEFAULT NULL,
  `strLoginName` varchar(15) NOT NULL DEFAULT '',
  `strPassword` varchar(100) DEFAULT NULL,
  `bLogged` tinyint(1) DEFAULT NULL,
  `bRemote` tinyint(1) DEFAULT NULL,
  `iRemoteKeys` int(11) unsigned DEFAULT NULL,
  `dLastLogin` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  `strUserName` varchar(15) NOT NULL DEFAULT '',
  `dTimeStamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `bGroup` tinyint(1) NOT NULL DEFAULT '0',
  `iGroupID` int(11) DEFAULT NULL,
  `strRunningVersion` varchar(20) DEFAULT NULL,
  PRIMARY KEY (`iUserID`),
  UNIQUE KEY `iUserID` (`iUserID`),
  UNIQUE KEY `strLoginName` (`strLoginName`)
) ENGINE=InnoDB; 

Data:
INSERT INTO `users` (`iUserID`, `strFName`, `strLName`, `strLoginName`, `strPassword`, `bLogged`, `bRemote`, `iRemoteKeys`, `dLastLogin`, `strUserName`, `dTimeStamp`, `bGroup`, `iGroupID`, `strRunningVersion`) VALUES 
  (1, '', 'Nasos', 'Nasos', '', 0, NULL, NULL, '2009-07-02 10:17:09', 'qualisys', '2009-09-07 20:38:02', 0, NULL, '2.5.31.1742'),
  (2, NULL, 'Administrator', 'Administrator', '', 0, NULL, NULL, '2008-12-11 16:03:40', 'qualisys', '2008-12-11 16:04:02', 0, 10001, '2.5.20.1644'),
  (3, NULL, 'User', 'User', '', 1, NULL, NULL, '2009-09-07 20:16:50', '.GADMINISTRATOR', '2009-09-07 20:15:42', 0, 10001, '2.5.37.1774'),
  (10001, NULL, 'Administrators Group', '.GADMINISTRATOR', '', 0, 0, NULL, '2009-02-18 09:22:10', 'qualisys', '2008-12-11 16:03:18', 1, NULL, '2.5.21.1678');

On first connection I run:

select strFormName,
       strFieldKey,
       strCharacteristic,
       strValue,
       bExistInDB,
       bPreserve
from

(
SELECT 	b.strFormName,
	b.strFieldKey,
	b.strCharacteristic,
	b.strValue	,
        1 as bExistInDB,
        0 as bPreserve
FROM   	usersettings AS b
WHERE	b.strUserName = 'Nasos'

UNION

SELECT 	c.strFormName,
	c.strFieldKey,
	c.strCharacteristic,
	c.strValue	,
        0 as bExistInDB,
        1 as bPreserve
FROM   	usersettings AS c
WHERE	c.strUserName = (SELECT u.strLoginName
                         FROM users AS u
			 WHERE iUserID = 1)

)

AS d

GROUP BY strFormName,
	strFieldKey,
	strCharacteristic

and i can see in SHOW INNODB STATUS 

---TRANSACTION 0 17446, ACTIVE 183 sec, OS thread id 1560
2 lock struct(s), heap size 320, 1 row lock(s)
MySQL thread id 42, query id 235 dvlp.qualisys.local 172.20.1.94 root
Trx read view will not see trx with id >= 0 17447, sees < 0 17447
TABLE LOCK table `etime`.`users` trx id 0 17446 lock mode IS
RECORD LOCKS space id 0 page no 61 n bits 80 index `PRIMARY` of table `etime`.`users` trx id 0 17446 lock mode S locks rec but not gap
Record lock, heap no 8 PHYSICAL RECORD: n_fields 16; compact format; info bits 0
 0: len 4; hex 00000001; asc     ;; 1: len 6; hex 00000000441c; asc     D ;; 2: len 7; hex 00000001e505b0; asc        ;; 3: len 0; hex ; asc ;; 4: len 8; hex 5175616c69737973; asc Qualisys;; 5: len 8; hex 5175616c69737973; asc Qualisys;; 6: len 0; hex ; asc ;; 7: len 1; hex 80; asc  ;; 8: SQL NULL; 9: SQL NULL; 10: len 8; hex 80001245bb297ccd; asc    E )| ;; 11: len 8; hex 7175616c69737973; asc qualisys;; 12: len 4; hex 4aa544fa; asc J D ;; 13: len 1; hex 80; asc  ;; 14: SQL NULL; 15: len 11; hex 322e352e33312e31373432; asc 2.5.31.1742;;

So, if i run on another connection

update users 
set strFName = 'Q'
WHERE iUserID = 1

I get a lock wait timeout since the second connection cannot get an S lock on the same row.

Possible solution:

Issue a statement

SELECT *
FROM users
WHERE iUserID = 1
LOCK IN SHARE MODE;

and the do the update.

Suggested fix:
This was not the case for versions up to 5.1.30.
[8 Sep 2009 5:42] Sveta Smirnova
Thank you for the report.

Please provide output of SHOW CREATE TABLE usersettings
[8 Sep 2009 6:11] Athanasios Alekizoglou
Table usersettings:

CREATE TABLE `usersettings` (
  `strFormName` varchar(70) NOT NULL,
  `strFieldKey` varchar(70) NOT NULL,
  `strCharacteristic` varchar(70) NOT NULL,
  `strUserName` varchar(15) NOT NULL DEFAULT '',
  `strValue` varchar(255) NOT NULL,
  PRIMARY KEY (`strUserName`,`strFormName`,`strFieldKey`,`strCharacteristic`),
  KEY `strUserName` (`strUserName`),
  CONSTRAINT `usersettings_strUserName_fk` FOREIGN KEY (`strUserName`) REFERENCES `users` (`strLoginName`) ON DELETE CASCADE ON UPDATE CASCADE
) ENGINE=InnoDB;

Also I checked against 5.1.37 and found that it does the same. Finally I checked with 5.1.38 and the problem DOES NOT exists.
[8 Sep 2009 6:46] Sveta Smirnova
Thank you for the feedback.

Closing as "Can't repeat" because last comment and because I can not repeat the problem with test data as well.
[8 Sep 2009 18:59] Athanasios Alekizoglou
Re-open the case, since I found the same bug in 5.1.38, but not 5.1.30. Let me know what other information and/or SQL schema, data, etc should I sent in order to reproduce.
[8 Sep 2009 21:44] Sveta Smirnova
Thank you for the feedback.

Please provide minimal dump problem is repeatable with.
[9 Sep 2009 6:39] Athanasios Alekizoglou
Dump Database

Attachment: LOCKDUMP.SQL (application/octet-stream, text), 2.02 KiB.

[9 Sep 2009 6:47] Athanasios Alekizoglou
After you create the DB with the dump I provided you run

drop table if exists innodb_monitor;
create table innodb_monitor(a int)engine=innodb;
drop table if exists innodb_table_monitor;
create table innodb_table_monitor(a int)engine=innodb;
drop table if exists innodb_tablespace_monitor;
create table innodb_tablespace_monitor(a int)engine=innodb;
drop table if exists innodb_lock_monitor;
create table innodb_lock_monitor(a int)engine=innodb;

as described in the manual to enabled INNODB monitors.

then execute

select strFormName,
       strFieldKey,
       strCharacteristic,
       strValue,
       bExistInDB,
       bPreserve
from
(
SELECT 	b.strFormName,
	b.strFieldKey,
	b.strCharacteristic,
	b.strValue	,
        1 as bExistInDB,
        0 as bPreserve
FROM   	usersettings AS b
WHERE	b.strUserName = 'TEST1'

UNION

SELECT 	c.strFormName,
	c.strFieldKey,
	c.strCharacteristic,
	c.strValue	,
        0 as bExistInDB,
        1 as bPreserve
FROM   	usersettings AS c
WHERE	c.strUserName = (SELECT u.strLoginName
                         FROM users AS u
			 WHERE iUserID = 1000)
)
AS d
GROUP BY strFormName,
	strFieldKey,
	strCharacteristic

and after than if you do

SHOW INNODB STATUS you will get

------------
TRANSACTIONS
------------
Trx id counter 0 17546
Purge done for trx's n:o < 0 17542 undo n:o < 0 0
History list length 1
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, OS thread id 3952
MySQL thread id 126, query id 736 dvlp.qualisys.local 172.20.1.94 root
SHOW INNODB STATUS
---TRANSACTION 0 17524, not started, OS thread id 2564
MySQL thread id 113, query id 675 dvlp.qualisys.local 172.20.1.94 root
---TRANSACTION 0 0, not started, OS thread id 2800
MySQL thread id 114, query id 709 dvlp.qualisys.local 172.20.1.94 root
---TRANSACTION 0 0, not started, OS thread id 3888
MySQL thread id 109, query id 660 dvlp.qualisys.local 172.20.1.94 root
---TRANSACTION 0 17545, ACTIVE 4 sec, OS thread id 1200
2 lock struct(s), heap size 320, 1 row lock(s)
MySQL thread id 125, query id 732 dvlp.qualisys.local 172.20.1.94 root
Trx read view will not see trx with id >= 0 17546, sees < 0 17536
TABLE LOCK table `dblock`.`users` trx id 0 17545 lock mode IS
RECORD LOCKS space id 0 page no 497 n bits 80 index `PRIMARY` of table `dblock`.`users` trx id 0 17545 lock mode S locks rec but not gap
Record lock, heap no 6 PHYSICAL RECORD: n_fields 9; compact format; info bits 0
 0: len 4; hex 000003e8; asc     ;; 1: len 6; hex 00000000447d; asc     D};; 2: len 7; hex 00000001f50e30; asc       0;; 3: len 7; hex 2e47524f555031; asc .GROUP1;; 4: len 0; hex ; asc ;; 5: len 4; hex 4aa74cbe; asc J L ;; 6: len 1; hex 81; asc  ;; 7: SQL NULL; 8: SQL NULL;

after that go on another session and try

UPDATE users
SET strUserName = 'TEST'
WHERE iUserID = 1;

and you will get the lock wait timeout since there cannot be a new X lock on that record. Of course if you do a 

SELECT * 
FROM users 
WHERE iUserID = 1
LOCK IN SHARE MODE;

you will get the S lock first and then the update will go on.

I've tried those on Windows:

5.1.30 - working fine
5.1.35 - locking as above
5.1.37 - locking as above
5.1.38 - locking as above
[10 Sep 2009 9:50] Sveta Smirnova
Thank you for the feedback.

I still can not repeat described behavior and even similar TRANSACTIONS output. Please send us also your configuration file, output of SHOW PROCESSLIST and full output of SHOW ENGINE INNODB STATUS: I want to check if there are other active transactions.
[10 Sep 2009 9:55] Sveta Smirnova
Please ignore SHOW ENGINE INNODB STATUS request
[17 Sep 2009 11:18] Athanasios Alekizoglou
MySQL Configuration Files

Attachment: my.ini (application/octet-stream, text), 8.74 KiB.

[17 Sep 2009 11:24] Athanasios Alekizoglou
SHOW PROCESSLIST

Attachment: SHOW PROCESSLIST.txt (text/plain), 469 bytes.

[28 Sep 2009 13:14] Athanasios Alekizoglou
Any news on this issue?

I still cannot find an explanation on what's going on, and of course cannot upgrade to 5.1.38
[3 Oct 2009 10:00] Sveta Smirnova
Thank you for the feedback.

I still can not repeat described behavior. Probably other transactions affect this.

Please temporarily turn general query log to on, output to table, then get lock, issue SHOW PROCESSLIST and SHOW ENGINE INNODB STATUS, then get queries:

select * from mysql.general_log where  thread_id in (LIST OF MYSQL THREAD IDs YOU GOT FROM SHOW PROCESSLISTand SHOW ENGINE INNODB STATUS) order by  event_time;
[4 Nov 2009 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".