[MDEV-9747] XtraDB thread never exits. Always in 'cleaning up' - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1.12, 10.0(EOL), 10.1(EOL)
Fix Version/s: 10.0.25
Component/s: Storage Engine - InnoDB, Storage Engine - OQGRAPH, Storage Engine - XtraDB
Labels:
None

Sprint:
10.0.25

Description

I've been having an issue with an instance of MariaDB 10.1.12 on a non-production machine which makes it never shutdown. It just hangs forever with "waiting for transaction".

This was odd as nothing was showing in "SHOW FULL PROCESSLIST"

I discovered a transaction thread never finishes.
This is the data collected. If you need more, let met know.

MariaDB [(none)]> show full processlist\G

*************************** 1. row ***************************

      Id: 80

    User: root

    Host: localhost

      db: NULL

 Command: Query

    Time: 0

   State: init

    Info: show full processlist

Progress: 0.000

1 row in set (0.00 sec)

MariaDB [(none)]> show engine innodb status\G

*************************** 1. row ***************************

  Type: InnoDB

  Name:

Status:

=====================================

2016-03-16 10:03:21 7ff7fc505700 INNODB MONITOR OUTPUT

=====================================

Per second averages calculated from the last 25 seconds

-----------------

BACKGROUND THREAD

-----------------

srv_master_thread loops: 50 srv_active, 0 srv_shutdown, 673746 srv_idle

srv_master_thread log flush and writes: 673567

----------

SEMAPHORES

----------

OS WAIT ARRAY INFO: reservation count 118

OS WAIT ARRAY INFO: signal count 120

Mutex spin waits 2904, rounds 3613, OS waits 53

RW-shared spins 68, rounds 1956, OS waits 64

RW-excl spins 3, rounds 50, OS waits 1

Spin rounds per wait: 1.24 mutex, 28.76 RW-shared, 16.67 RW-excl

------------

TRANSACTIONS

------------

Trx id counter 5443238

Purge done for trx's n:o < 5443232 undo n:o < 0 state: running but idle

History list length 541

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 0, not started

MySQL thread id 80, OS thread handle 0x7ff7fc505700, query id 2271 localhost root init

show engine innodb status

---TRANSACTION 0, not started

MySQL thread id 24, OS thread handle 0x7ff7ff267700, query id 174 cleaning up

--------

FILE I/O

--------

I/O thread 0 state: waiting for completed aio requests (insert buffer thread)

I/O thread 1 state: waiting for completed aio requests (log thread)

I/O thread 2 state: waiting for completed aio requests (read thread)

I/O thread 3 state: waiting for completed aio requests (read thread)

I/O thread 4 state: waiting for completed aio requests (read thread)

I/O thread 5 state: waiting for completed aio requests (read thread)

I/O thread 6 state: waiting for completed aio requests (write thread)

I/O thread 7 state: waiting for completed aio requests (write thread)

I/O thread 8 state: waiting for completed aio requests (write thread)

I/O thread 9 state: waiting for completed aio requests (write thread)

Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,

 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0

Pending flushes (fsync) log: 0; buffer pool: 0

2049 OS file reads, 621 OS file writes, 280 OS fsyncs

0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

-------------------------------------

INSERT BUFFER AND ADAPTIVE HASH INDEX

-------------------------------------

Ibuf: size 1, free list len 1842, seg size 1844, 0 merges

merged operations:

 insert 0, delete mark 0, delete 0

discarded operations:

 insert 0, delete mark 0, delete 0

0.00 hash searches/s, 0.00 non-hash searches/s

---

LOG

---

Log sequence number 225203203047

Log flushed up to   225203203047

Pages flushed up to 225203203047

Last checkpoint at  225203203047

Max checkpoint age    80354304

Checkpoint age target 77843232

Modified age          0

Checkpoint age        0

0 pending log writes, 0 pending chkp writes

201 log i/o's done, 0.00 log i/o's/second

----------------------

BUFFER POOL AND MEMORY

----------------------

Total memory allocated 138412032; in additional pool allocated 0

Total memory allocated by read views 200

Internal hash tables (constant factor + variable factor)

    Adaptive hash index 2561632         (2213368 + 348264)

    Page hash           139112 (buffer pool 0 only)

    Dictionary cache    2001389         (554768 + 1446621)

    File system         938224  (812272 + 125952)

    Lock system         333592  (332872 + 720)

    Recovery system     0       (0 + 0)

Dictionary memory allocated 1446621

Buffer pool size        8191

Buffer pool size, bytes 134201344

Free buffers            6575

Database pages          1595

Old database pages      607

Modified db pages       0

Percent of dirty pages(LRU & free pages): 0.000

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 0, not young 0

0.00 youngs/s, 0.00 non-youngs/s

Pages read 1572, created 23, written 369

0.00 reads/s, 0.00 creates/s, 0.00 writes/s

No buffer pool page gets since the last printout

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 1595, unzip_LRU len: 0

I/O sum[0]:cur[0], unzip sum[0]:cur[0]

--------------

ROW OPERATIONS

--------------

0 queries inside InnoDB, 0 queries in queue

0 read views open inside InnoDB

0 RW transactions active inside InnoDB

0 RO transactions active inside InnoDB

0 out of 1000 descriptors used

Main thread process no. 3914, id 140702637872896, state: sleeping

Number of rows inserted 157, updated 37, deleted 850, read 188280

0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Number of system rows inserted 0, updated 0, deleted 0, read 0

0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

----------------------------

END OF INNODB MONITOR OUTPUT

============================

1 row in set (0.00 sec)

MariaDB [(none)]>

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

my.cnf
5 kB
2016-03-17 15:10
mysqld.err
47 kB
2016-03-17 15:10
thread-trace.txt
57 kB
2016-03-16 14:12

Issue Links

is duplicated by

MDEV-8206 [PATCH] OQGraph crash caused by SELECT queries

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2016-03-17 14:12

grknight,
Where do you see "waiting for transaction"?
Does it also happen when you run without TokuDB?
Could you please attach the error log and the cnf file(s)?

Elena Stepanova added a comment - 2016-03-17 14:12 grknight , Where do you see "waiting for transaction"? Does it also happen when you run without TokuDB? Could you please attach the error log and the cnf file(s)?

Brian Evans added a comment - 2016-03-17 15:11

Added files requested. The Signal 6's are me doing SIGABRT to get the daemon to stop

Brian Evans added a comment - 2016-03-17 15:11 Added files requested. The Signal 6's are me doing SIGABRT to get the daemon to stop

Elena Stepanova added a comment - 2016-03-17 18:19 - edited

Thanks, I am able to reproduce the problem.

It happens between OQGRAPH and InnoDB. I'm not sure which one is to blame, so I'm assigning it to jplindst for now; Jan, if it turns out to be not an InnoDB problem, please reassign it back to me or directly to andymc73.

The described issue with shutdown happens on a non-debug build. Debug build goes down with an assertion failure earlier.

The MTR test case below is for manual reproducing/debugging only, please don't put it like this into the regression test suite (especially since it passes either way).

If it's run on a debug build, it fails on SELECT * FROM oq_graph (assertion failure is at the end of the comment). On a non-debug build, it does not crash, but returns an empty result set, which is already wrong, then the test proceeds to shutdown, hangs there until the timeout is exceeded (you'll see messages from the test), then kills the server, cleans up and exits.

MTR test case
--source include/have_innodb.inc
--enable_connect_log

install soname 'ha_oqgraph';

CREATE TABLE oq_backing (
origid INT UNSIGNED NOT NULL,
destid INT UNSIGNED NOT NULL,
PRIMARY KEY (origid, destid),
KEY (destid)
) ENGINE=InnoDB;

INSERT INTO oq_backing(origid, destid)
VALUES (1,2), (2,3), (3,4), (4,5), (2,6), (5,6);

CREATE TABLE oq_graph (
latch VARCHAR(32) NULL,
origid BIGINT UNSIGNED NULL,
destid BIGINT UNSIGNED NULL,
weight DOUBLE NULL,
seq BIGINT UNSIGNED NULL,
linkid BIGINT UNSIGNED NULL,
KEY (latch, origid, destid) USING HASH,
KEY (latch, destid, origid) USING HASH
)
ENGINE=OQGRAPH
data_table='oq_backing' origid='origid' destid='destid';

--enable_reconnect
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
--shutdown_server 10
--source include/wait_until_disconnected.inc

--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
--source include/wait_until_connected_again.inc

--connect (con1,localhost,root,,)
SELECT * FROM oq_graph;
--disconnect con1

--connect (con2,localhost,root,,)
--enable_reconnect

SELECT * FROM oq_graph;
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect

--echo
--echo #########################
--echo # If the test proceeds right away, then the bug was not reproduced.
--echo # If nothing happens for a long time, your are likely to have hit the problem,
--echo # wait for 70 sec until the timeout finishes and we'll check what the error log says...
--echo #########################
--echo

--shutdown_server 70

--exec sh -c "tail $MYSQLTEST_VARDIR/log/mysqld.1.err"

--echo
--echo #########################
--echo # MESSAGE FROM THE TEST:
--echo # If you see 'Waiting for X active transactions' in the error log above,
--echo # the problem was definitely reproduced.
--echo #########################
--echo

--source include/wait_until_disconnected.inc

--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
--source include/wait_until_connected_again.inc

--disable_query_log
drop table oq_graph, oq_backing;
uninstall soname 'ha_oqgraph';

Assertion failure on 10.0 commit 0125e588f3967bcaf01cf60b6a64e92758158ac4 debug build
mysqld: /src/10.0/sql/handler.cc:2473: THD* handler::ha_thd() const: Assertion `!table \|\| !table->in_use \|\| table->in_use == _current_thd()' failed.
160317 20:08:09 [ERROR] mysqld got signal 6 ;

#7 0x00007f78ce74d1d2 in __assert_fail () from /lib64/libc.so.6
#8 0x000000000086060a in handler::ha_thd (this=0x7f78bba79888) at /src/10.0/sql/handler.cc:2473
#9 0x00007f78c6f561ed in ha_innodb::extra (this=0x7f78bba79888, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at /src/10.0/storage/innobase/handler/ha_innodb.cc:12544
#10 0x00007f78c6bc95c3 in ha_oqgraph::extra (this=0x7f78bba5d888, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at /src/10.0/storage/oqgraph/ha_oqgraph.cc:1102
#11 0x00000000007ed36c in tc_acquire_table (thd=0x7f78c85716f0, share=0x7f78bba4b088) at /src/10.0/sql/table_cache.cc:342
#12 0x00000000007ee25b in tdc_acquire_share (thd=0x7f78c85716f0, db=0x7f78bb822868 "test", table_name=0x7f78bb822240 "oq_graph", key=0x7f78bb8226c9 "test", key_length=14, hash_value=3220223330, flags=3, out_table=0x7f78d07623e8) at /src/10.0/sql/table_cache.cc:765
#13 0x000000000060c249 in open_table (thd=0x7f78c85716f0, table_list=0x7f78bb822288, mem_root=0x7f78d07625f0, ot_ctx=0x7f78d07625b0) at /src/10.0/sql/sql_base.cc:2384
#14 0x000000000060ee71 in open_and_process_table (thd=0x7f78c85716f0, lex=0x7f78c8574f98, tables=0x7f78bb822288, counter=0x7f78d07626f4, flags=0, prelocking_strategy=0x7f78d0762730, has_prelocking_list=false, ot_ctx=0x7f78d07625b0, new_frm_mem=0x7f78d07625f0) at /src/10.0/sql/sql_base.cc:4045
#15 0x000000000060ff36 in open_tables (thd=0x7f78c85716f0, start=0x7f78d07626b0, counter=0x7f78d07626f4, flags=0, prelocking_strategy=0x7f78d0762730) at /src/10.0/sql/sql_base.cc:4579
#16 0x0000000000610f22 in open_and_lock_tables (thd=0x7f78c85716f0, tables=0x7f78bb822288, derived=true, flags=0, prelocking_strategy=0x7f78d0762730) at /src/10.0/sql/sql_base.cc:5222
#17 0x0000000000605313 in open_and_lock_tables (thd=0x7f78c85716f0, tables=0x7f78bb822288, derived=true, flags=0) at /src/10.0/sql/sql_base.h:489
#18 0x0000000000674664 in execute_sqlcom_select (thd=0x7f78c85716f0, all_tables=0x7f78bb822288) at /src/10.0/sql/sql_parse.cc:5249
#19 0x000000000066ccdb in mysql_execute_command (thd=0x7f78c85716f0) at /src/10.0/sql/sql_parse.cc:2562
#20 0x0000000000677479 in mysql_parse (thd=0x7f78c85716f0, rawbuf=0x7f78bb822088 "SELECT * FROM oq_graph", length=22, parser_state=0x7f78d0763650) at /src/10.0/sql/sql_parse.cc:6565
#21 0x0000000000669f45 in dispatch_command (command=COM_QUERY, thd=0x7f78c85716f0, packet=0x7f78c85784b1 "SELECT * FROM oq_graph", packet_length=22) at /src/10.0/sql/sql_parse.cc:1308
#22 0x0000000000669212 in do_command (thd=0x7f78c85716f0) at /src/10.0/sql/sql_parse.cc:998
#23 0x00000000007878a7 in do_handle_one_connection (thd_arg=0x7f78c85716f0) at /src/10.0/sql/sql_connect.cc:1377
#24 0x0000000000787619 in handle_one_connection (arg=0x7f78c85716f0) at /src/10.0/sql/sql_connect.cc:1292
#25 0x0000000000df4358 in pfs_spawn_thread (arg=0x7f78c84a0e70) at /src/10.0/storage/perfschema/pfs.cc:1860
#26 0x00007f78d04700a4 in start_thread () from /lib64/libpthread.so.0
#27 0x00007f78ce80404d in clone () from /lib64/libc.so.6

Elena Stepanova added a comment - 2016-03-17 18:19 - edited Thanks, I am able to reproduce the problem. It happens between OQGRAPH and InnoDB. I'm not sure which one is to blame, so I'm assigning it to jplindst for now; Jan, if it turns out to be not an InnoDB problem, please reassign it back to me or directly to andymc73 . The described issue with shutdown happens on a non-debug build. Debug build goes down with an assertion failure earlier. The MTR test case below is for manual reproducing/debugging only, please don't put it like this into the regression test suite (especially since it passes either way). If it's run on a debug build, it fails on SELECT * FROM oq_graph (assertion failure is at the end of the comment). On a non-debug build, it does not crash, but returns an empty result set, which is already wrong, then the test proceeds to shutdown, hangs there until the timeout is exceeded (you'll see messages from the test), then kills the server, cleans up and exits. MTR test case --source include/have_innodb.inc --enable_connect_log install soname 'ha_oqgraph' ; CREATE TABLE oq_backing ( origid INT UNSIGNED NOT NULL , destid INT UNSIGNED NOT NULL , PRIMARY KEY (origid, destid), KEY (destid) ) ENGINE=InnoDB; INSERT INTO oq_backing(origid, destid) VALUES (1,2), (2,3), (3,4), (4,5), (2,6), (5,6); CREATE TABLE oq_graph ( latch VARCHAR (32) NULL , origid BIGINT UNSIGNED NULL , destid BIGINT UNSIGNED NULL , weight DOUBLE NULL , seq BIGINT UNSIGNED NULL , linkid BIGINT UNSIGNED NULL , KEY (latch, origid, destid) USING HASH, KEY (latch, destid, origid) USING HASH ) ENGINE=OQGRAPH data_table= 'oq_backing' origid= 'origid' destid= 'destid' ; --enable_reconnect --exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect --shutdown_server 10 --source include/wait_until_disconnected.inc --exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect --source include/wait_until_connected_again.inc --connect (con1,localhost,root,,) SELECT * FROM oq_graph; --disconnect con1 --connect (con2,localhost,root,,) --enable_reconnect SELECT * FROM oq_graph; --exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect --echo --echo ######################### --echo # If the test proceeds right away, then the bug was not reproduced. --echo # If nothing happens for a long time, your are likely to have hit the problem, --echo # wait for 70 sec until the timeout finishes and we'll check what the error log says... --echo ######################### --echo --shutdown_server 70 --exec sh -c "tail $MYSQLTEST_VARDIR/log/mysqld.1.err" --echo --echo ######################### --echo # MESSAGE FROM THE TEST: --echo # If you see 'Waiting for X active transactions' in the error log above, --echo # the problem was definitely reproduced. --echo ######################### --echo --source include/wait_until_disconnected.inc --exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect --source include/wait_until_connected_again.inc --disable_query_log drop table oq_graph, oq_backing; uninstall soname 'ha_oqgraph'; Assertion failure on 10.0 commit 0125e588f3967bcaf01cf60b6a64e92758158ac4 debug build mysqld: /src/10.0/sql/handler.cc:2473: THD* handler::ha_thd() const: Assertion `!table || !table->in_use || table->in_use == _current_thd()' failed. 160317 20:08:09 [ERROR] mysqld got signal 6 ; #7 0x00007f78ce74d1d2 in __assert_fail () from /lib64/libc.so.6 #8 0x000000000086060a in handler::ha_thd (this=0x7f78bba79888) at /src/10.0/sql/handler.cc:2473 #9 0x00007f78c6f561ed in ha_innodb::extra (this=0x7f78bba79888, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at /src/10.0/storage/innobase/handler/ha_innodb.cc:12544 #10 0x00007f78c6bc95c3 in ha_oqgraph::extra (this=0x7f78bba5d888, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at /src/10.0/storage/oqgraph/ha_oqgraph.cc:1102 #11 0x00000000007ed36c in tc_acquire_table (thd=0x7f78c85716f0, share=0x7f78bba4b088) at /src/10.0/sql/table_cache.cc:342 #12 0x00000000007ee25b in tdc_acquire_share (thd=0x7f78c85716f0, db=0x7f78bb822868 "test", table_name=0x7f78bb822240 "oq_graph", key=0x7f78bb8226c9 "test", key_length=14, hash_value=3220223330, flags=3, out_table=0x7f78d07623e8) at /src/10.0/sql/table_cache.cc:765 #13 0x000000000060c249 in open_table (thd=0x7f78c85716f0, table_list=0x7f78bb822288, mem_root=0x7f78d07625f0, ot_ctx=0x7f78d07625b0) at /src/10.0/sql/sql_base.cc:2384 #14 0x000000000060ee71 in open_and_process_table (thd=0x7f78c85716f0, lex=0x7f78c8574f98, tables=0x7f78bb822288, counter=0x7f78d07626f4, flags=0, prelocking_strategy=0x7f78d0762730, has_prelocking_list=false, ot_ctx=0x7f78d07625b0, new_frm_mem=0x7f78d07625f0) at /src/10.0/sql/sql_base.cc:4045 #15 0x000000000060ff36 in open_tables (thd=0x7f78c85716f0, start=0x7f78d07626b0, counter=0x7f78d07626f4, flags=0, prelocking_strategy=0x7f78d0762730) at /src/10.0/sql/sql_base.cc:4579 #16 0x0000000000610f22 in open_and_lock_tables (thd=0x7f78c85716f0, tables=0x7f78bb822288, derived=true, flags=0, prelocking_strategy=0x7f78d0762730) at /src/10.0/sql/sql_base.cc:5222 #17 0x0000000000605313 in open_and_lock_tables (thd=0x7f78c85716f0, tables=0x7f78bb822288, derived=true, flags=0) at /src/10.0/sql/sql_base.h:489 #18 0x0000000000674664 in execute_sqlcom_select (thd=0x7f78c85716f0, all_tables=0x7f78bb822288) at /src/10.0/sql/sql_parse.cc:5249 #19 0x000000000066ccdb in mysql_execute_command (thd=0x7f78c85716f0) at /src/10.0/sql/sql_parse.cc:2562 #20 0x0000000000677479 in mysql_parse (thd=0x7f78c85716f0, rawbuf=0x7f78bb822088 "SELECT * FROM oq_graph", length=22, parser_state=0x7f78d0763650) at /src/10.0/sql/sql_parse.cc:6565 #21 0x0000000000669f45 in dispatch_command (command=COM_QUERY, thd=0x7f78c85716f0, packet=0x7f78c85784b1 "SELECT * FROM oq_graph", packet_length=22) at /src/10.0/sql/sql_parse.cc:1308 #22 0x0000000000669212 in do_command (thd=0x7f78c85716f0) at /src/10.0/sql/sql_parse.cc:998 #23 0x00000000007878a7 in do_handle_one_connection (thd_arg=0x7f78c85716f0) at /src/10.0/sql/sql_connect.cc:1377 #24 0x0000000000787619 in handle_one_connection (arg=0x7f78c85716f0) at /src/10.0/sql/sql_connect.cc:1292 #25 0x0000000000df4358 in pfs_spawn_thread (arg=0x7f78c84a0e70) at /src/10.0/storage/perfschema/pfs.cc:1860 #26 0x00007f78d04700a4 in start_thread () from /lib64/libpthread.so.0 #27 0x00007f78ce80404d in clone () from /lib64/libc.so.6

Jan Lindström (Inactive) added a comment - 2016-04-21 10:52 - edited

Problem is that oqgraph used incorrect thd, this leads to fact that transaction inside InnoDB is not committed/aborted leaving it active => xtradb log thread waits forever transaction to end. Fix in https://github.com/MariaDB/server/pull/153 for https://jira.mariadb.org/browse/MDEV-8206 fixes also both problems reported in this bug report.

Jan Lindström (Inactive) added a comment - 2016-04-21 10:52 - edited Problem is that oqgraph used incorrect thd, this leads to fact that transaction inside InnoDB is not committed/aborted leaving it active => xtradb log thread waits forever transaction to end. Fix in https://github.com/MariaDB/server/pull/153 for https://jira.mariadb.org/browse/MDEV-8206 fixes also both problems reported in this bug report.

Jan Lindström (Inactive) added a comment - 2016-04-26 13:01

Fixed by commits:
commit 23b1b69b101f8f22319a8e661ebe8b4587c435d4
Author: Andrew McDonnell <bugs@andrewmcdonnell.net>
Date: Sat Apr 9 22:39:22 2016 +0930

Comment from https://github.com/MariaDB/server/pull/153

commit 6651005e623e3a12ca0af6a645483a165941f8fe
Author: Andrew McDonnell <bugs@andrewmcdonnell.net>
Date: Fri Jan 22 21:13:33 2016 +1030

Fix for ~~MDEV-8206~~, as per Jira comments of 2015-11-16 and 2015-11-30

Jan Lindström (Inactive) added a comment - 2016-04-26 13:01 Fixed by commits: commit 23b1b69b101f8f22319a8e661ebe8b4587c435d4 Author: Andrew McDonnell <bugs@andrewmcdonnell.net> Date: Sat Apr 9 22:39:22 2016 +0930 Comment from https://github.com/MariaDB/server/pull/153 commit 6651005e623e3a12ca0af6a645483a165941f8fe Author: Andrew McDonnell <bugs@andrewmcdonnell.net> Date: Fri Jan 22 21:13:33 2016 +1030 Fix for MDEV-8206 , as per Jira comments of 2015-11-16 and 2015-11-30

Nilnandan Joshi added a comment - 2017-05-03 09:27

I can reproduce this issue with MariaDB 5.0.29, 5.1.21.
Simple login into mysql from three different sessions and check innodb status.

------------

TRANSACTIONS

------------

Trx id counter 2822

Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle

History list length 0

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 0, not started

MySQL thread id 3, OS thread handle 0x7f5a704ca700, query id 56 localhost root cleaning up

---TRANSACTION 0, not started

MySQL thread id 4, OS thread handle 0x7f5a70481700, query id 22 localhost root cleaning up

---TRANSACTION 2821, not started

MySQL thread id 2, OS thread handle 0x7f5a70513700, query id 58 localhost root init

show engine innodb status

Nilnandan Joshi added a comment - 2017-05-03 09:27 I can reproduce this issue with MariaDB 5.0.29, 5.1.21. Simple login into mysql from three different sessions and check innodb status. ------------ TRANSACTIONS ------------ Trx id counter 2822 Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle History list length 0 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0, not started MySQL thread id 3, OS thread handle 0x7f5a704ca700, query id 56 localhost root cleaning up ---TRANSACTION 0, not started MySQL thread id 4, OS thread handle 0x7f5a70481700, query id 22 localhost root cleaning up ---TRANSACTION 2821, not started MySQL thread id 2, OS thread handle 0x7f5a70513700, query id 58 localhost root init show engine innodb status

Marko Mäkelä added a comment - 2017-05-03 10:39

The output lines "MySQL thread id" are emitted by thd_get_error_context_description(), which is called by innobase_mysql_print_thd(), called by trx_print_low() which displays the line "TRANSACTION 0, not started".

From the InnoDB point of view, the 2 transactions are not active. The trx objects should be cached objects that only exist in the handler interface and in trx_sys->mysql_trx_list. The objects should be freed when the connection is closed. Maybe these connections did access InnoDB in the past, but no transaction is active any more?

There only is one transaction allocated for the SHOW ENGINE INNODB STATUS.

Do the "cleaning up" entries go away when the two connections are disconnected?
I do not know where the "cleaning up" message is coming from. One possibility is PSI_stage_info stage_cleaning_up defined in mysqld.cc.

Marko Mäkelä added a comment - 2017-05-03 10:39 The output lines "MySQL thread id" are emitted by thd_get_error_context_description(), which is called by innobase_mysql_print_thd(), called by trx_print_low() which displays the line "TRANSACTION 0, not started". From the InnoDB point of view, the 2 transactions are not active. The trx objects should be cached objects that only exist in the handler interface and in trx_sys->mysql_trx_list. The objects should be freed when the connection is closed. Maybe these connections did access InnoDB in the past, but no transaction is active any more? There only is one transaction allocated for the SHOW ENGINE INNODB STATUS. Do the "cleaning up" entries go away when the two connections are disconnected? I do not know where the "cleaning up" message is coming from. One possibility is PSI_stage_info stage_cleaning_up defined in mysqld.cc.

People

Assignee:: Jan Lindström (Inactive)

Reporter:: Brian Evans

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 2016-03-16 14:13

Updated:: 2017-05-03 10:39

Resolved:: 2016-04-26 13:01

Git Integration

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

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration