9

My not-so-big table hangs on an ALTER command. What could it be?

Only 150k rows, 42 fields 142 MByte total. InnoDB storage engine and Server version: 5.5.44-MariaDB MariaDB Server. 1 field, 'slotindex', is primary key: bigint(20) and BTREE type.

The command:

    MariaDB [mydb]> ALTER TABLE `runs` CHANGE `p_w_trans_x` `p_w_tran_x` FLOAT NOT NULL;
    Stage: 1 of 2 'copy to tmp table'   65.7% of stage done
    Stage: 2 of 2 'Enabling keys'      0% of stage done

Will completely hang forever in this stage 2.

The processlist is then as follows:

MariaDB [(none)]> show full processlist;
+--------+------+-----------------+-----------+---------+-------+---------------------------------+---------------------------------------------------------------------+----------+
| Id     | User | Host            | db        | Command | Time  | State                           | Info                                                                | Progress |
+--------+------+-----------------+-----------+---------+-------+---------------------------------+---------------------------------------------------------------------+----------+
| 274226 | root | localhost:45423 | edc_proxy | Sleep   | 16043 |                                 | NULL                                                                |    0.000 |
| 274319 | root | localhost       | myDB      | Query   |    99 | Waiting for table metadata lock | ALTER TABLE `runs` CHANGE `p_w_trans_x` `p_w_tran_x` FLOAT NOT NULL |    0.000 |
| 274416 | root | localhost       | NULL      | Query   |     0 | NULL                            | show full processlist                                               |    0.000 |
+--------+------+-----------------+-----------+---------+-------+---------------------------------+---------------------------------------------------------------------+----------+

This answer suggests checking the information_schema tables, not much there:

MariaDB [INFORMATION_SCHEMA]> SELECT * FROM INNODB_LOCK_WAITS;
Empty set (0.00 sec)

MariaDB [INFORMATION_SCHEMA]> SELECT * FROM INNODB_LOCKS ;
Empty set (0.00 sec)

MariaDB [INFORMATION_SCHEMA]> SELECT * FROM INNODB_TRX;
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+
| trx_id   | trx_state | trx_started         | trx_requested_lock_id | trx_wait_started | trx_weight | trx_mysql_thread_id | trx_query | trx_operation_state | trx_tables_in_use | trx_tables_locked | trx_lock_structs | trx_lock_memory_bytes | trx_rows_locked | trx_rows_modified | trx_concurrency_tickets | trx_isolation_level | trx_unique_checks | trx_foreign_key_checks | trx_last_foreign_key_error | trx_adaptive_hash_latched | trx_adaptive_hash_timeout |
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+
| 83A8B36E | RUNNING   | 2016-12-08 11:13:02 | NULL                  | NULL             |          0 |              274226 | NULL      | NULL                |                 0 |                 0 |                0 |                   376 |               0 |                 0 |                       0 | REPEATABLE READ     |                 1 |                      1 | NULL                       |                         0 |                     10000 |
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+
1 row in set (0.00 sec)

And the section on transactions from show engine innodb status;:

------------
TRANSACTIONS
------------
Trx id counter 83A8F071
Purge done for trx's n:o < 83A8CA86 undo n:o < 0
History list length 1490
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 274543, OS thread handle 0x7fbb863e6700, query id 85356480 localhost root
show engine innodb status
---TRANSACTION 83A8EB07, not started
mysql tables in use 1, locked 2
MySQL thread id 274542, OS thread handle 0x7fbb843f6700, query id 85354935 localhost root Waiting for table metadata lock
ALTER TABLE `runs` CHANGE `p_w_trans_x` `p_w_tran_x` FLOAT NOT NULL
---TRANSACTION 83A8B36E, ACTIVE 24627 sec
MySQL thread id 274226, OS thread handle 0x7fbb845f5700, query id 85337236 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 83A8B36F, sees < 83A8B36D
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Any pointers for further investigation, for circumventing the problem and for solving are appreciated!

Community
  • 1
  • 1
Bastiaan
  • 4,451
  • 4
  • 22
  • 33
  • See http://stackoverflow.com/a/13155778/166339 – Asaph Dec 09 '16 at 00:37
  • I'm not positive about MariaDB, but I know MySQL has to recreate the entire table when you do most `ALTER`s; indexes won't matter. If something else is accessing the table, or holding a lock on it, such as an uncommitted transaction, what Asaph has linked above should help you find it. – Uueerdo Dec 09 '16 at 00:43
  • @Asaph @Uueerdo Thanks for your comments, I edited the question to include those suggestions. No other processes are running or locking the table, `show process list;` reflects that too, or could they be hidden somewhere else? – Bastiaan Dec 09 '16 at 02:09
  • can you show us the table description? what keys are there? `DESC runs;` – Mr.P Dec 09 '16 at 02:19
  • Your thread 274226 holds a read lock on table `runs`. That's why the `ALTER` could proceed to the stage 2, but now it needs to override table and cannot acquire the metadata lock. Commit the transaction in that thread or kill the thread if you can afford it, `ALTER` should finish after that. – elenst Dec 09 '16 at 02:26
  • Please provide `SHOW CREATE TABLE` (not `DESC`) before the alter. – Rick James Dec 09 '16 at 05:49
  • Is 99 seconds (as per processlist) what you call "hang forever"? If it is running on spinning disk drives, it will take longer than a few minutes to shovel 0.142GB around a couple of times. – Rick James Dec 09 '16 at 05:51
  • @elenst How do you know it has a lock on `runs`? Its supposedly running on a different DB. Also, what could this sleep command be? I didn't ask for it. – Bastiaan Dec 09 '16 at 07:36
  • @RickJames Output of SHOW CREATE TABLE runs is added to the question. Thank you! I have restarted and killed the command a few times, this output was copy pasted 99 seconds after starting. Last night it took 6:30 hour to complete (successfully). But I have more changes and don't want to wait again. – Bastiaan Dec 09 '16 at 07:47
  • @Mr.P Output of SHOW CREATE is added to the question. Thank you! – Bastiaan Dec 09 '16 at 07:48
  • Mysql is notoriously slow when altering tables. I have seen a add column command take 8 hours to complete on a medium-to-large table – Bohemian Dec 09 '16 at 07:49
  • 1
    @Bastiaan Both the processlist and InnoDB status agree there are only 3 threads running, no strays. Connection which runs `SHOW PROCESSLIST` / `STATUS` is apparently transient, so there are only two. `ALTER` stopped at exact moment when it would stop if it couldn't acquire a metadata lock on the table, which is confirmed both by the `State` in processlist and `Stage` in the progress report. If the `ALTER` was just slow, there would have been a different `State` at least, even if progress report doesn't work. So, the only reasonable explanation is that another transaction/thread holds the lock. – elenst Dec 09 '16 at 08:42
  • @elenst you turn out to be right. What I didn't get at first is that the process appears to be running in a different DB and therefore should be completely independent of my problem. But what probably happend is that I connect to the edc_proxy database and the run a query on `myDB.runs`. The query really has nothing to do with the edc_procy DB. Question remains why it does succeed after so many hours of waiting? The sleep expires? Is there a way to get more info about the sleep process (what happend, who initiated)? – Bastiaan Dec 09 '16 at 17:39
  • @Bastiaan `Sleep` just means inactivity. If `ALTER` succeeded after several hours, that's because the other thread aborted due to inactivity after connection timeout (default 28800 seconds, 8 hours), thus releasing locks. Even though it has an open transaction, it will still expire if it doesn't do things. If the thread hadn't been idle, `ALTER` could have waited forever -- default lock wait timeout is 31536000 (1 year). And that's right, the database in the processlist doesn't have anything to do with actual tables in use, it's just the default database set by the connection at the moment. – elenst Dec 09 '16 at 19:10

2 Answers2

6

A metadata lock is an implicit (from the user perspective) lock that prevents DDL against the table because something else needs the table to remain in its current form. In this case, it's a transaction that has been left running.

Task 1: Your alter will succeed if you kill the connection on thread 274226.

mysql> KILL 274226;

The problem here, as indicated by information_schema.innodb_trx, is that this thread has left a transaction running for several hours and we can infer that this table has been referenced by that transaction. A table can't be altered until no transactioms still have an MVCC view or any locks involving the table. This transaction holds a view, which we can again infer could impact this table, as shown in the last line:

--TRANSACTION 83A8B36E, ACTIVE 24627 sec
MySQL thread id 274226, OS thread handle 0x7fbb845f5700, query id 85337236 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 83A8B36F, sees < 83A8B36D

Note that Sleep is not a real command, in this context, it's just the placeholder status for any idle connection. All connections are doing something, and in this case the "something" is sleeping -- in other words, idle and waiting for another query. But an idle connection is still a connection, and if your code (or query browser tool) leaves a transaction running, it just keeps running.

Task 2: find the bug or mistake that left that transaction running. In a live application, leaving transactions running potentially make a much bigger mess.

Michael - sqlbot
  • 169,571
  • 25
  • 353
  • 427
0

I was having a very similar issue with table lock, but it ended up being MySQL Workbench out of all things. Any RENAME TABLE or ALTER TABLE command in MySQL Workbench would just sit claiming a meta lock. I logged onto the server and was able to execute those types of queries no problem. Current version of Workbench is 8.0.22.

I had sifted through all these queries and was totally stumped when they showed no issues:

SHOW OPEN TABLES;

SHOW ENGINE inndodb STATUS;

SELECT * FROM INNODB_LOCK_WAITS;

SELECT * FROM INNODB_LOCKS;

SELECT * FROM INNODB_TRX;

SHOW FULL PROCESSLIST;

Gwi7d31
  • 1,652
  • 2
  • 12
  • 10