MySQL Bugs: #52691: innodb_trx shows trx_query as NULL after lock_wait

Bug #52691	innodb_trx shows trx_query as NULL after lock_wait_timeout and in other cases
Submitted:	8 Apr 2010 13:32	Modified:	29 Jun 2011 23:02
Reporter:	Sergey Petrunya	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB Plugin storage engine	Severity:	S3 (Non-critical)
Version:	5.1.45, 5.5.12, 5.6.3	OS:	Any (linux)
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
information_schema.innodb_trx always shows trx_query as NULL after lock_wait_timeout has been exceeded.

How to repeat:
# Get MySQL 5.1.45, including innodb plugin that is shipped in the bundle.

# Start the server;
# Start client#1 and run:

create table ten(a int);
insert into ten values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
create table t1 (pk int, a int) engine=innodb;
insert into t1 select A.a+10*B.a+10*C.a, A.a+10*B.a+10*C.a from ten A, ten B, ten C;

MySQL [test2]> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

MySQL [test2]> select * from t1 where pk in (1,3,4) for update;
+------+------+
| pk   | a    |
+------+------+
|    1 |  120 |
|    3 |    3 |
|    4 |    4 |
+------+------+
3 rows in set (0.01 sec)

# Start client #2 and run:

MySQL [test2]> set innodb_lock_wait_timeout=30;
Query OK, 0 rows affected (0.00 sec)

# This will freeze: 

MySQL [test2]> update t1 set a=1230 where pk=1;

# While the above is frozen, start client #3 and run:

MySQL [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                       |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------+
| 83A02  | LOCK WAIT | 2010-04-08 17:26:20 | 83A02:0:60:2          | 2010-04-08 17:26:20 |          2 |                   2 | update t1 set a=1230 where pk=1 |
| 83A01  | RUNNING   | 2010-04-08 17:25:58 | NULL                  | NULL                |          4 |                   1 | NULL                            |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------+
2 rows in set (0.00 sec)

# So far everything is ok.
# Now, wait until client #2 times out:

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

# Then run the same statement in client #2 again:

MySQL [test2]> update t1 set a=1230 where pk=1;

# It will again freeze, and while it is frozen, switch into client #3 and run:

MySQL [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 |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+
| 83A03  | LOCK WAIT | 2010-04-08 17:28:02 | 83A03:0:60:2          | 2010-04-08 17:28:02 |          2 |                   2 | NULL      |
| 83A01  | RUNNING   | 2010-04-08 17:25:58 | NULL                  | NULL                |          4 |                   1 | NULL      |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+
2 rows in set (0.00 sec)

# And see that the trx_query is now NULL. I think it should not be NULL, but
# rather show the blocked query, like it has happened in the first attempt.

Suggested fix:
Make innodb_trx always show the query.

Thank you for the bug report.

C:\DBS>c:\dbs\5.1\bin\mysql -uroot --port=3306 --prompt="mysql 5.1 >"
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 6
Server version: 5.1.46-Win X64-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql 5.1 >use information_schema
Database changed
mysql 5.1 >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                       |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------+
| 8022   | LOCK WAIT | 2010-04-08 11:23:14 | 8022:0:1218:2         | 2010-04-08 11:23:14 |          2 |                   5 | update t1 set a=1230 where pk=1 |
| 8021   | RUNNING   | 2010-04-08 11:22:38 | NULL                  | NULL                |          4 |                   4 | NULL                            |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+---------------------------------+
2 rows in set (0.00 sec)

mysql 5.1 >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 |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+
| 8023   | LOCK WAIT | 2010-04-08 11:23:57 | 8023:0:1218:2         | 2010-04-08 11:23:57 |          2 |                   5 | NULL      |
| 8021   | RUNNING   | 2010-04-08 11:22:38 | NULL                  | NULL                |          4 |                   4 | NULL      |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+
2 rows in set (0.00 sec)

The relevant code from trx/trx0i_s.c is:

 462         if (trx->mysql_query_str != NULL && *trx->mysql_query_str != NULL) {
 463 
 464                 if (strlen(*trx->mysql_query_str)
 465                     > TRX_I_S_TRX_QUERY_MAX_LEN) {
 466 
 467                         char    query[TRX_I_S_TRX_QUERY_MAX_LEN + 1];
 468 
 469                         memcpy(query, *trx->mysql_query_str,
 470                                TRX_I_S_TRX_QUERY_MAX_LEN);
 471                         query[TRX_I_S_TRX_QUERY_MAX_LEN] = '\0';
 472 
 473                         row->trx_query = ha_storage_put_memlim(
 474                                 cache->storage, query,
 475                                 TRX_I_S_TRX_QUERY_MAX_LEN + 1,
 476                                 MAX_ALLOWED_FOR_STORAGE(cache));
 477                 } else {
 478 
 479                         row->trx_query = ha_storage_put_str_memlim(
 480                                 cache->storage, *trx->mysql_query_str,
 481                                 MAX_ALLOWED_FOR_STORAGE(cache));
 482                 }
 483 
 484                 if (row->trx_query == NULL) {
 485 
 486                         return(FALSE);
 487                 }
 488         } else {
 489 
 490                 row->trx_query = NULL;
 491         }

It seems lock_wait_timeout is not necessary to observe the effect. I also don't see the query text for LOAD DATA INFILE statement:

mysql> 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 |
+--------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+
| 30C    | RUNNING   | 2010-04-09 01:34:37 | NULL                  | NULL             |    1064611 |                   3 | NULL      |
+--------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+
1 row in set (0.00 sec)

mysql> show processlist;
+----+------+-----------+--------------------+---------+------+-------+--------------------------------------------------------------------------------------------------+
| Id | User | Host      | db                 | Command | Time | State | Info                                                                                             |
+----+------+-----------+--------------------+---------+------+-------+--------------------------------------------------------------------------------------------------+
|  2 | root | localhost | information_schema | Query   |    0 | NULL  | show processlist                                                                                 |
|  3 | root | localhost | dbt3sf10           | Query   |   45 | NULL  | LOAD DATA LOCAL INFILE '/home/psergey/partsupp.tbl' into table partsupp fields terminated by '|' |
+----+------+-----------+--------------------+---------+------+-------+--------------------------------------------------------------------------------------------------+

Hello, I cannot repeat this with latest 5.1/plugin or 5.5, I always get:

17:30:45 mysql> select trx_id, trx_state, trx_query from innodb_trx;
+--------+-----------+---------------------------------+
| trx_id | trx_state | trx_query                       |
+--------+-----------+---------------------------------+
| 5507   | LOCK WAIT | update t1 set a=1230 where pk=1 |
| 5505   | RUNNING   | NULL                            |
+--------+-----------+---------------------------------+
2 rows in set (0.01 sec)

I also cannot repeat with LOAD DATA INFILE in 5.1/plugin:

client1:
mysql> begin; select * from bug52691 for update;
Query OK, 0 rows affected (0.00 sec)

client2:
mysql> load data infile 'bug52691.txt' into table bug52691;
(hangs)

client3:
mysql> select trx_id, trx_state, trx_query from innodb_trx;
+--------+-----------+-----------------------------------------------------+
| trx_id | trx_state | trx_query                                           |
+--------+-----------+-----------------------------------------------------+
| 570D   | LOCK WAIT | load data infile 'bug52691.txt' into table bug52691 |
| 570C   | RUNNING   | NULL                                                |
+--------+-----------+-----------------------------------------------------+
2 rows in set (0.00 sec)

Vasil, Sergey, see this valgrind output during a generic dml test. can it be the cause here?

Attachment: bug52691_valgrind_5.6.3_innodb_trx.txt (text/plain), 7.80 KiB.

Shane, very useful analysis. I have committed a change in vasil.dimov@oracle.com-20110328083412-odusry0rkbeenhd1 (see http://lists.mysql.com/commits/133991) which will probably fix that valgrind warning.

Sergey, can you check whether it has also fixed this bug? Or if you can reproduce the bug at all because I couldn't last time I tried.

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

Shane,

could you please send us DML test which you used?

sveta: in my homedir on shella you can find zlibdml.php.  Run this in a few threads while repeatedly selecting from innodb_trx.  Run mysqld in valgrind if needed if needed.

Any insert/delete/update/select can be used, it doesn't really matter.

I managed to repeat valgrind warnings in version 5.1.56, but can not repeat them anymore with 5.1.57. I also noticed InnoDB takes less locks in 5.1.57.

Sergey, please check if issue which you reported solved as well. Thanks in advance.

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

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

I don't see anything in the 5.1.57 change history that might explain why this is not repeatable?

Still reproduce in 5.7.23

I'm encountering this issue on 8.0.20, which causes table locking and query backups on my database.  This is visible in an RDS instance by spikes in wait/io/table/sql/handler on Performance Insights.