[MDEV-24993] pymysql - executemany test failing - lock timeout - insert wait on non-indexed table Created: 2021-02-26  Updated: 2021-03-22  Resolved: 2021-03-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6
Fix Version/s: 10.6.0

Type: Bug Priority: Blocker
Reporter: Daniel Black Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: need_feedback, not-10.1, not-10.2, not-10.3, not-10.4, not-10.5

Issue Links:
Blocks
is blocked by MDEV-24818 Concurrent use of InnoDB table is imp... Closed
Problem/Incident
is caused by MDEV-515 innodb bulk insert Closed

 Description   

pymysql tests - as tested by https://buildbot.mariadb.org/#/builders/158 have been failing on 10.6 branch for a while.

This test is stable on all other branches.

Example failure: https://buildbot.mariadb.org/#/builders/158/builds/149

pymysql executemany test failure

_________________________ CursorTest.test_executemany __________________________
self = <pymysql.tests.test_cursor.CursorTest testMethod=test_executemany>
    def test_executemany(self):
        conn = self.test_connection
        cursor = conn.cursor(pymysql.cursors.Cursor)
    
        m = pymysql.cursors.RE_INSERT_VALUES.match(
            "INSERT INTO TEST (ID, NAME) VALUES (%s, %s)"
        )
        self.assertIsNotNone(m, "error parse %s")
        self.assertEqual(m.group(3), "", "group 3 not blank, bug in RE_INSERT_VALUES?")
    
        m = pymysql.cursors.RE_INSERT_VALUES.match(
            "INSERT INTO TEST (ID, NAME) VALUES (%(id)s, %(name)s)"
        )
        self.assertIsNotNone(m, "error parse %(name)s")
        self.assertEqual(m.group(3), "", "group 3 not blank, bug in RE_INSERT_VALUES?")
    
        m = pymysql.cursors.RE_INSERT_VALUES.match(
            "INSERT INTO TEST (ID, NAME) VALUES (%(id_name)s, %(name)s)"
        )
        self.assertIsNotNone(m, "error parse %(id_name)s")
        self.assertEqual(m.group(3), "", "group 3 not blank, bug in RE_INSERT_VALUES?")
    
        m = pymysql.cursors.RE_INSERT_VALUES.match(
            "INSERT INTO TEST (ID, NAME) VALUES (%(id_name)s, %(name)s) ON duplicate update"
        )
        self.assertIsNotNone(m, "error parse %(id_name)s")
        self.assertEqual(
            m.group(3),
            " ON duplicate update",
            "group 3 not ON duplicate update, bug in RE_INSERT_VALUES?",
        )
    
        # https://github.com/PyMySQL/PyMySQL/pull/597
        m = pymysql.cursors.RE_INSERT_VALUES.match(
            "INSERT INTO bloup(foo, bar)VALUES(%s, %s)"
        )
        assert m is not None
    
        # cursor._executed must bee "insert into test (data) values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9)"
        # list args
        data = range(10)
>       cursor.executemany("insert into test (data) values (%s)", data)
pymysql/tests/test_cursor.py:101: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
pymysql/cursors.py:187: in executemany
    return self._do_execute_many(
pymysql/cursors.py:225: in _do_execute_many
    rows += self.execute(sql + postfix)
pymysql/cursors.py:158: in execute
    result = self._query(query)
pymysql/cursors.py:325: in _query
    conn.query(q)
pymysql/connections.py:546: in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
pymysql/connections.py:775: in _read_query_result
    result.read()
pymysql/connections.py:1156: in read
    first_packet = self.connection._read_packet()
pymysql/connections.py:725: in _read_packet
    packet.raise_for_error()
pymysql/protocol.py:221: in raise_for_error
    err.raise_mysql_exception(self._data)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
data = b'\xff\xb5\x04#HY000Lock wait timeout exceeded; try restarting transaction'
    def raise_mysql_exception(data):
        errno = struct.unpack("<h", data[1:3])[0]
        errval = data[9:].decode("utf-8", "replace")
        errorclass = error_map.get(errno)
        if errorclass is None:
            errorclass = InternalError if errno < 1000 else OperationalError
>       raise errorclass(errno, errval)
E       pymysql.err.OperationalError: (1205, 'Lock wait timeout exceeded; try restarting transaction')
pymysql/err.py:143: OperationalError

https://github.com/PyMySQL/PyMySQL/blob/master/pymysql/tests/test_cursor.py#L101

git bisect log

git bisect start 'fail'
# good: [b76e5c66107d75d0161d8f8ab3cf05fc360c831e] MDEV-24765 fseg_free_extent fails to call buf_page_free() for the whole segment
git bisect good b76e5c66107d75d0161d8f8ab3cf05fc360c831e
# good: [b76e5c66107d75d0161d8f8ab3cf05fc360c831e] MDEV-24765 fseg_free_extent fails to call buf_page_free() for the whole segment
git bisect good b76e5c66107d75d0161d8f8ab3cf05fc360c831e
# bad: [786bc312b85e58857cb26a24ab6e997ba0fdfc32] Cleanup: Replace mysql_cond_t with pthread_cond_t
git bisect bad 786bc312b85e58857cb26a24ab6e997ba0fdfc32
# good: [260161fc9fb5b4885013d550e606681769b52019] MDEV-24167 fixup: Avoid hangs in SRW_LOCK_DUMMY
git bisect good 260161fc9fb5b4885013d550e606681769b52019
# good: [394fc71f4fa8f8b1b6d24adfead0ec45121d271e] MDEV-24569: Merge 10.5 into 10.6
git bisect good 394fc71f4fa8f8b1b6d24adfead0ec45121d271e
# bad: [3329f0ed0c3acdd47dedfa54aefadb1852eb7454] Cleanup: Remove LOCK_REC (which was mutually exclusive with LOCK_TABLE)
git bisect bad 3329f0ed0c3acdd47dedfa54aefadb1852eb7454
# bad: [3f871b339429441ad907ecf7dfabdc414797e664] MDEV-515 fixup: Cover dict_table_t::clear() during ADD INDEX
git bisect bad 3f871b339429441ad907ecf7dfabdc414797e664
# good: [0d7380fdac1add2be3fdb57519ccd8ac9c8e12bc] MDEV-24637 fts_slots is being accessed after it gets freed
git bisect good 0d7380fdac1add2be3fdb57519ccd8ac9c8e12bc
# good: [e9fc61053d64ee829e26ecf3bb1c521938e20543] Merge 10.5 into 10.6
git bisect good e9fc61053d64ee829e26ecf3bb1c521938e20543
# bad: [3cef4f8f0fc88ae5bfae4603d8d600ec84cc70a9] MDEV-515 Reduce InnoDB undo logging for insert into empty table
git bisect bad 3cef4f8f0fc88ae5bfae4603d8d600ec84cc70a9
# good: [7aed5eb76ffdec91637cb7a48bff89e4b4315f82] MDEV-24642 Assertion r->emplace... failed in sux_lock::s_lock_register()
git bisect good 7aed5eb76ffdec91637cb7a48bff89e4b4315f82
# first bad commit: [3cef4f8f0fc88ae5bfae4603d8d600ec84cc70a9] MDEV-515 Reduce InnoDB undo logging for insert into empty table

innodb processlist during test

MariaDB [(none)]> show processlist; show engine innodb status\G
 
Connection id:    6
Current database: *** NONE ***
 
+----+------+-----------+-------+---------+------+----------+------------------------------------------------------------------------+----------+
| Id | User | Host      | db    | Command | Time | State    | Info                                                                   | Progress |
+----+------+-----------+-------+---------+------+----------+------------------------------------------------------------------------+----------+
|  3 | root | localhost | test1 | Sleep   |    4 |          | NULL                                                                   |    0.000 |
|  4 | root | localhost | test1 | Sleep   |    4 |          | NULL                                                                   |    0.000 |
|  5 | root | localhost | test1 | Query   |    4 | Update   | insert into test (data) values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9) |    0.000 |
|  6 | dan  | localhost | NULL  | Query   |    0 | starting | show processlist                                                       |    0.000 |
+----+------+-----------+-------+---------+------+----------+------------------------------------------------------------------------+----------+
4 rows in set (0.003 sec)
 
*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
2021-02-26 17:36:22 0x7fd420d1a640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 7 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 7 srv_idle
srv_master_thread log flush and writes: 8
----------
SEMAPHORES
----------
------------
TRANSACTIONS
------------
Trx id counter 488
Purge done for trx's n:o < 487 undo n:o < 0 state: running
History list length 215
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 487, ACTIVE 5 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 1 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 5, OS thread handle 140549382817344, query id 8 localhost root Update
insert into test (data) values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9)
------- TRX HAS BEEN WAITING 5 SEC FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test1`.`test` trx id 487 lock mode IX waiting
------------------
---TRANSACTION 482, ACTIVE 5 sec
2 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 1
MySQL thread id 4, OS thread handle 140549383124544, query id 6 localhost root 
---TRANSACTION 422024369524888, not started
0 lock struct(s), heap size 1128, 0 row lock(s)

From: https://github.com/MariaDB/mariadb.org-tools/blob/master/buildbot.mariadb.org/dockerfiles/ecofiles/test-pymysql.sh

Create this test environment:

https://github.com/MariaDB/mariadb.org-tools/blob/master/buildbot.mariadb.org/dockerfiles/ecofiles/test-pymysql.sh#L21-L39

+ `set password for root@localhost = password('');`

+
https://github.com/MariaDB/mariadb.org-tools/blob/master/buildbot.mariadb.org/dockerfiles/ecofiles/test-pymysql.sh#L47-L52

runtest

 pytest -v pymysql/tests/test_cursor.py  -k  test_executemany 



 Comments   
Comment by Daniel Black [ 2021-02-26 ]

general log

sql/mysqld, Version: 10.6.0-MariaDB-log (Source distribution). started with:
Tcp port: 0  Unix socket: /tmp/build-mariadb-server-10.6.sock
Time		    Id Command	Argument
210226 17:58:24	     3 Connect	root@localhost on test1 using Socket
		     3 Query	SET AUTOCOMMIT = 0
		     3 Query	SHOW PLUGINS
		     4 Connect	root@localhost on test1 using Socket
		     4 Query	SET AUTOCOMMIT = 0
		     4 Query	drop table if exists `test`
		     4 Query	create table test (data varchar(10))
		     4 Query	insert into test (data) values ('row1'), ('row2'), ('row3'), ('row4'), ('row5')
		     5 Connect	root@localhost on test1 using Socket
		     5 Query	SET AUTOCOMMIT = 0
		     5 Query	insert into test (data) values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9)

Comment by Marko Mäkelä [ 2021-02-26 ]

This looks like a duplicate of MDEV-24818. To ensure that this ticket will not be accidentally closed without addressing the problem, I’m recording the relationship as ‘blocked by’.

Comment by Marko Mäkelä [ 2021-03-19 ]

danblack, was this addressed by MDEV-24818?

Comment by Daniel Black [ 2021-03-20 ]

Yes. Test now passes. No other regres

pymysql(master 6ccbecc1a0dfd04065b081950d2d35b1dac0aaa8), bb-10.6-MDEV-24818 (cbfa762c01961f6b8a9c15f6f09ea6836023f181), and 10.6-47c8896240593d197b25227e963dd3059f2b3936 (which includes 47c8896240593d197b25227e963dd3059f2b3936)

 
$  pytest -v pymysql/tests/test_cursor.py 
====================================================================== test session starts ======================================================================
platform linux -- Python 3.9.2, pytest-6.2.2, py-1.10.0, pluggy-0.13.1 -- /home/dan/.py3/bin/python
cachedir: .pytest_cache
rootdir: /home/dan/repos/PyMySQL
collected 3 items                                                                                                                                               
 
pymysql/tests/test_cursor.py::CursorTest::test_cleanup_rows_buffered PASSED                                                                               [ 33%]
pymysql/tests/test_cursor.py::CursorTest::test_cleanup_rows_unbuffered PASSED                                                                             [ 66%]
pymysql/tests/test_cursor.py::CursorTest::test_executemany PASSED                                                                                         [100%]

Comment by Marko Mäkelä [ 2021-03-22 ]

Thank you. This was essentially a duplicate of MDEV-24818, which was fixed.

Generated at Thu Feb 08 09:34:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.