Details
-
Bug
-
Status: Open (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.11.11
Description
from https://github.com/MariaDB/server/pull/4182#issuecomment-3088926726
tested distro f42 with systemd configuration for the 10.11.11 MariaDB Service:
TimeoutStartUSec=40s
TimeoutStopUSec=40s
InnoDB - innodb_buffer_pool_size=innodb_log_file_size=10G
to validate the operation of extend timeout.
|
session1 |
SHOW CREATE TABLE t\G
|
CREATE TABLE `t` (
|
`seq` bigint(20) unsigned NOT NULL
|
) ENGINE=InnoDB DEFAULT CHARSET=latin1 COLLATE=latin1_swedish_ci
|
CREATE TABLE `t` (
|
`seq` bigint(20) unsigned NOT NULL
|
) ENGINE=InnoDB DEFAULT CHARSET=latin1 COLLATE=latin1_swedish_ci
|
|
|
MariaDB [test]> insert into t select seq from seq_1_to_300000000;
|
|
session 2 |
MariaDB [test]> set global innodb_fast_shutdown=3;
|
Query OK, 0 rows affected (0.000 sec)
|
|
|
(and approx 5 min+ mins later whie query still running)
|
MariaDB [test]> SHUTDOWN;
|
Query OK, 0 rows affected (0.000 sec)
|
Jul 21 13:51:23 bark mariadbd[19738]: 2025-07-21 13:51:23 0 [Note] /usr/libexec/mariadbd: ready for connections.
|
Jul 21 13:51:23 bark mariadbd[19738]: Version: '10.11.11-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server
|
Jul 21 13:51:23 bark systemd[1]: Started mariadb.service - MariaDB 10.11 database server.
|
Jul 21 13:59:12 bark mariadbd[19738]: 2025-07-21 13:59:12 0 [Warning] InnoDB: Could not free any blocks in the buffer pool! 648960 blocks are in use and 0 free. Consider increasing innodb_buffer_pool_size.
|
Jul 21 13:59:29 bark mariadbd[19738]: 2025-07-21 13:59:29 0 [Note] /usr/libexec/mariadbd (initiated by: root[root] @ localhost []): Normal shutdown
|
Jul 21 13:59:49 bark mariadbd[19738]: 2025-07-21 13:59:49 0 [Warning] /usr/libexec/mariadbd: Thread 3 (user : 'root') did not exit
|
Jul 21 14:00:09 bark systemd[1]: mariadb.service: State 'stop-sigterm' timed out. Aborting.
|
Jul 21 14:00:09 bark systemd[1]: mariadb.service: Killing process 19738 (mariadbd) with signal SIGABRT.
|
After shutdown:
MariaDB [test]> insert into t select seq from seq_1_to_300000000;
|
ERROR 2013 (HY000): Lost connection to MySQL server during query
|
and because the shutdown ran out of time:
Thread 3 (Thread 0x7fdef01296c0 (LWP 19921)):
|
#0 row_undo_step (thr=0x7fdc40056a38) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/innobase/row/row0undo.cc:420
|
#1 0x000055e16ddee1ff in que_thr_step (thr=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/innobase/que/que0que.cc:551
|
#2 que_run_threads_low (thr=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/innobase/que/que0que.cc:609
|
#3 que_run_threads (thr=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/innobase/que/que0que.cc:629
|
#4 0x000055e16de548ab in trx_t::rollback_low (this=0x7fdef01c0b80, savept=0x0) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/innobase/trx/trx0roll.cc:116
|
#5 0x000055e16dd67d30 in innobase_rollback (thd=<optimized out>, rollback_trx=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/innobase/handler/ha_innodb.cc:4751
|
#6 0x000055e16da8ace5 in ha_rollback_trans (thd=0x7fdc40000c68, all=false) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/handler.cc:2282
|
#7 0x000055e16d9590c9 in trans_rollback_stmt (thd=0x7fdc40000c68) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/transaction.cc:570
|
#8 0x000055e16d7c6d2c in mysql_execute_command (thd=0x7fdc40000c68, is_called_from_prepared_stmt=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.--Type <RET> for more, q to quit, c to continue without paging--
|
fc42.x86_64/sql/sql_parse.cc:6219
|
#9 0x000055e16d7d3249 in mysql_parse (thd=0x7fdc40000c68, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/sql_parse.cc:8188
|
#10 0x000055e16d7c473e in dispatch_command (command=COM_QUERY, thd=0x7fdc40000c68, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/sql_parse.cc:1905
|
#11 0x000055e16d7b9ac8 in do_command (thd=0x7fdc40000c68, blocking=true) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/sql_parse.cc:1418
|
#12 0x000055e16d953fed in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55e195d04678, put_in_cache=put_in_cache@entry=true) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/sql_connect.cc:1386
|
#13 0x000055e16d9544bf in handle_one_connection (arg=arg@entry=0x55e195d04678) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/sql/sql_connect.cc:1298
|
#14 0x000055e16dcd2921 in pfs_spawn_thread (arg=0x55e195c90298) at /usr/src/debug/mariadb10.11-10.11.11-6.fc42.x86_64/storage/perfschema/pfs.cc:2201
|
#15 0x00007fdf0547f1d4 in start_thread () from /lib64/libc.so.6
|
#16 0x00007fdf05501cec in __clone3 () from /lib64/libc.so.6
|
So it appears SHUTDOWN killed all thread and resulted in the rollback regardless of the global variable innodb_fast_shutdown=3.
(non?)Problem 1:
innodb_fast_shutdown=3 has no obvious effect from connection issued current SQL commands.
Implemented in row_undo_step where trx->error_state = DB_INTERRUPTED
Problem 2:
No timeout extensions in innobase_rollback
Problem 3: (trivial)
End of rollback doesn't reset MariaDB systemd service status to something indicating the completion.
Status: "To roll back: 1 transactions, 2006379 rows"
|
Tasks: 15 (limit: 250919)
|
Memory: 10.1G (peak: 10.1G)
|
CPU: 8min 48.995s
|
CGroup: /system.slice/mariadb.service
|
└─23510 /usr/libexec/mariadbd --basedir=/usr
|
|
|
Jul 21 14:37:49 bark mariadbd[23510]: 2025-07-21 14:37:49 0 [Note] InnoDB: To roll back: 1 transactions, 19668953 rows
|
Jul 21 14:37:49 bark systemd[1]: mariadb.service: Got notification message from PID 23510: STATUS=To roll back: 1 transactions, 19668953 rows, EXTEND_TIMEOU>
|
Jul 21 14:38:04 bark mariadbd[23510]: 2025-07-21 14:38:04 0 [Note] InnoDB: To roll back: 1 transactions, 14178368 rows
|
Jul 21 14:38:04 bark systemd[1]: mariadb.service: Got notification message from PID 23510: STATUS=To roll back: 1 transactions, 14178368 rows, EXTEND_TIMEOU>
|
Jul 21 14:38:19 bark mariadbd[23510]: 2025-07-21 14:38:19 0 [Note] InnoDB: To roll back: 1 transactions, 8255513 rows
|
Jul 21 14:38:19 bark systemd[1]: mariadb.service: Got notification message from PID 23510: STATUS=To roll back: 1 transactions, 8255513 rows, EXTEND_TIMEOUT>
|
Jul 21 14:38:34 bark mariadbd[23510]: 2025-07-21 14:38:34 0 [Note] InnoDB: To roll back: 1 transactions, 2006379 rows
|
Jul 21 14:38:34 bark systemd[1]: mariadb.service: Got notification message from PID 23510: STATUS=To roll back: 1 transactions, 2006379 rows, EXTEND_TIMEOUT>
|
Jul 21 14:38:38 bark mariadbd[23510]: 2025-07-21 14:38:38 0 [Note] InnoDB: Rolled back recovered transaction 71
|
Jul 21 14:38:38 bark mariadbd[23510]: 2025-07-21 14:38:38 0 [Note] InnoDB: Rollback of non-prepared transactions completed
|
Attachments
Issue Links
- relates to
-
MDEV-14705 systemd: EXTEND_TIMEOUT_USEC= to avoid startup and shutdown timeouts
-
- Closed
-
- links to