![\"\"](\"http:\/\/www.nivas.hr\/blog\/wp-content\/uploads\/2017\/08\/programming-knock-knock.jpg\")
<\/a><\/p>\nMy first thought was that improvements which were introduced in MySQL 5.7. regarding GET_LOCK() broke something.<\/p>\n
Test script:<\/p>\n
\r\n<?php\r\n\r\n$host = 'DB_HOST';\r\n$db = 'DB_NAME';\r\n$user = 'DB_USER';\r\n$pass = 'DB_PASSWD';\r\n$charset = 'utf8mb4';\r\n\r\n$dsn = "mysql:host=$host;dbname=$db;charset=$charset";\r\n$opt = [\r\n PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION,\r\n PDO::ATTR_DEFAULT_FETCH_MODE => PDO::FETCH_ASSOC,\r\n PDO::ATTR_EMULATE_PREPARES => false,\r\n\tPDO::ATTR_PERSISTENT => false\r\n];\r\n$pdo = new PDO($dsn, $user, $pass, $opt);\r\n\r\necho "<pre>";\r\necho "pid=(".getmypid().")\\n";\r\n\r\n$stmt = $pdo->query('SELECT GET_LOCK("foobar", 15)');\r\n$row = $stmt->fetch();\r\n\r\nvar_dump($row);\r\necho "\\n";\r\n\r\necho "Sleep for 50s\\n";\r\nsleep(50);\r\n\r\necho "<\/pre>";\r\n?>\r\n<\/pre>\nLock timeout is 15s and script executes (and hold lock) for 50s so I could have time to start both scripts in parallel and monitor MySQL performance_schema.<\/p>\n
Result from the first tab:<\/p>\n
\r\npid=(14769)\r\narray(1) {\r\n ["GET_LOCK("foobar", 15)"]=>\r\n int(1)\r\n}\r\n\r\nSleep for 50s\r\n<\/pre>\nResult from the second tab:<\/p>\n
\r\npid=(14769)\r\narray(1) {\r\n ["GET_LOCK("foobar", 15)"]=>\r\n int(1)\r\n}\r\n\r\nSleep for 50s\r\n<\/pre>\nOutput is not as expected. GET_LOCK() from the second tab should return 0, not 1.<\/p>\n
I executed the script again, but from the command line, again in parallel. Second one was executed 1-2s after the first one.<\/p>\n
Result from the first (cmd line):<\/p>\n
\r\n$ php -q locktest_1.php \r\n\r\n<pre>pid=(16328)\r\narray(1) {\r\n ["GET_LOCK("foobar", 15)"]=>\r\n int(1)\r\n}\r\n\r\nSleep for 50s\r\n<\/pre>\nResult from the second (cmd line):<\/p>\n
\r\n$ php -q locktest_1.php \r\n\r\n<pre>pid=(16382)\r\narray(1) {\r\n ["GET_LOCK("foobar", 15)"]=>\r\n int(0)\r\n}\r\n\r\nSleep for 50s\r\n<\/pre>\nAnd everything was working as expected. First script obtained the lock, and second didn’t.<\/p>\n
With helpful comments from StackOverflow community I continued with my investigation.<\/p>\n
Put the performance_schema to good use<\/h2>\n
In order to see what is happening with my locks it is necessary to monitor performance_schema.threads and performance_schema.metadata_locks closely. To learn more about it check the MySQL documentation<\/a>.<\/p>\nI added connection_id()<\/a> in php test script in order to match running php script with entries in the performance_schema.threads and performance_schema.metadata_locks tables.<\/p>\nSecond round of tests<\/h2>\n
Now, armed with all this data, second round of test can begin.<\/p>\n
After running the test scripts I quickly executed these sql queries:<\/p>\n
\r\nselect * from performance_schema.threads;\r\n<\/pre>\n\r\nselect * from performance_schema.metadata_locks;\r\n<\/pre>\nYou will see active threads and locks and their status (GRANTED, PENDING).<\/p>\n
First one returned:<\/p>\n
\r\npid=(14773)\r\nCONNECTION_ID()=(71)\r\narray(1) {\r\n ["GET_LOCK("foobar", 15)"]=>\r\n int(1)\r\n}\r\nSleep for 50s\r\n<\/pre>\nSecond one returned:<\/p>\n
\r\npid=(14773)\r\nCONNECTION_ID()=(72)\r\narray(1) {\r\n ["GET_LOCK("foobar", 15)"]=>\r\n int(1)\r\n}\r\nSleep for 50s\r\n<\/pre>\nAlso in performance_schema.threads there was at any point in time only one entry related to the test script.
\nFirst it showed:<\/p>\n
![\"\"](\"http:\/\/www.nivas.hr\/blog\/wp-content\/uploads\/2017\/08\/01_blog_post_processlist_id_71_Selection_042-450x51.jpg\")
<\/a><\/p>\nPlease note row with PROCESSLIST_ID = 71 (matching the output from the first script)<\/p>\n
I kept refreshing performance_schema.threads and noticed that one thread related to the test script was replaced with another one. They were not running in parallel like they do when I start test script from cmd line.<\/p>\n
![\"\"](\"http:\/\/www.nivas.hr\/blog\/wp-content\/uploads\/2017\/08\/02_blog_post_proccesslist_id_72_Selection_043-450x49.jpg\")
<\/a><\/p>\nPlease note row with PROCESSLIST_ID = 72 (matching the output from the second script)
\nAlso performance_schema.metadata_locks showed only one lock at any point in time (not one GRANTED and one PENDING):<\/p>\n