Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24993

pymysql - executemany test failing - lock timeout - insert wait on non-indexed table

Details

    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 
      
      

      Attachments

        Issue Links

          Activity

            danblack Daniel Black added a comment -

            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)
            

            danblack Daniel Black added a comment - 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)

            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’.

            marko Marko Mäkelä added a comment - 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’.

            danblack, was this addressed by MDEV-24818?

            marko Marko Mäkelä added a comment - danblack , was this addressed by MDEV-24818 ?
            danblack Daniel Black added a comment -

            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%]
            
            

            danblack Daniel Black added a comment - 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%]

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

            marko Marko Mäkelä added a comment - Thank you. This was essentially a duplicate of MDEV-24818 , which was fixed.

            People

              marko Marko Mäkelä
              danblack Daniel Black
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.