[MDEV-20319] Unable to stop or restart mariadb.service (timeouts) Created: 2019-08-11  Updated: 2022-04-13  Resolved: 2019-08-15

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.4.7
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: acsfer Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: timeout
Environment:

Ubuntu 18.04.3, Kernel 5.0.0-25-generic

Issue Links:
Duplicate
is duplicated by MDEV-20115 10.4 crash after upgrade from 10.3 ( ... Closed

 Description   

Server is member of a Master-Master using GTID replication.
Server has been upgraded from latest GA 10.3.

systemctl stop mariadb outputs nothing, but service remains active.

# # systemctl status mariadb
 
â mariadb.service - MariaDB 10.4.7 database server
 
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
 
  Drop-In: /etc/systemd/system/mariadb.service.d
 
           ââMY_SPECIAL.conf, migrated-from-my.cnf-settings.conf, override.conf
 
   Active: failed (Result: timeout) since Sun 2019-08-11 18:21:15 CEST; 40s ago
 
     Docs: man:mysqld(8)
 
           https://mariadb.com/kb/en/library/systemd/
 
 Main PID: 2269
 
   Status: "Shutdown in progress"
 
    Tasks: 27 (limit: 4533)
 
   CGroup: /system.slice/mariadb.service
 
           ââ2269 /usr/sbin/mysqld
 
 
 
Aug 11 18:15:44 srv-nur mysqld[2269]: 2019-08-11 18:15:44 0 [Note] /usr/sbin/mysqld (mysqld 10.4.7-MariaDB-1:10.4.7+maria~bionic-log) starting as process 2269 ...
 
Aug 11 18:15:47 srv-nur /etc/mysql/debian-start[2315]: /usr/bin/mysql_upgrade: the '--basedir' option is always ignored
 
Aug 11 18:15:47 srv-nur /etc/mysql/debian-start[2315]: Looking for 'mysql' as: /usr/bin/mysql
 
Aug 11 18:15:47 srv-nur /etc/mysql/debian-start[2315]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
 
Aug 11 18:15:47 srv-nur /etc/mysql/debian-start[2315]: This installation of MariaDB is already upgraded to 10.4.7-MariaDB, use --force if you still need to run mysql_upgrade
 
Aug 11 18:19:44 srv-nur systemd[1]: mariadb.service: State 'stop-sigterm' timed out. Skipping SIGKILL.
 
Aug 11 18:21:15 srv-nur systemd[1]: mariadb.service: State 'stop-final-sigterm' timed out. Skipping SIGKILL. Entering failed mode.
 
Aug 11 18:21:15 srv-nur systemd[1]: mariadb.service: Failed with result 'timeout'.

and from error.log:

2019-08-11 18:18:14 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
 
2019-08-11 18:18:14 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2019-08-11 18:18:14 11 [Note] Error reading relay log event: slave SQL thread was killed
 
2019-08-11 18:18:14 0 [Note] InnoDB: FTS optimize thread exiting.
 
2019-08-11 18:18:14 11 [Note] Slave SQL thread exiting, replication stopped in log 'cluster-bin.000050' at position 3135870; GTID position '0-1-87716,1-1-11383278,2-2-3302009'
 
2019-08-11 18:18:14 10 [Note] Slave I/O thread exiting, read up to log 'cluster-bin.000050', position 3355631; GTID position 1-1-11383278,0-1-87716,2-2-3302520
 
2019-08-11 18:18:34 0 [Warning] /usr/sbin/mysqld: Thread 15 (user : '') did not exit
 
2019-08-11 18:18:34 0 [Warning] /usr/sbin/mysqld: Thread 14 (user : '') did not exit
 
2019-08-11 18:18:34 0 [Warning] /usr/sbin/mysqld: Thread 13 (user : '') did not exit
 
2019-08-11 18:18:34 0 [Warning] /usr/sbin/mysqld: Thread 12 (user : '') did not exit

Only solution to bring server back is to kill -9 the process and restart the server.

 Comments   
Comment by acsfer [ 2019-08-11 ]

If it seems a duplicate of MDEV-20115 feel free to close it.

Comment by acsfer [ 2019-08-11 ]

Same behavior on the 2nd server. Can't stop server without manually kill the process.

Comment by Alice Sherepa [ 2019-08-12 ]

probably the same issue as MDEV-20247(MDEV-20288). as a temporary workaround please try setting innodb_thread_concurrency=0

Comment by acsfer [ 2019-08-13 ]

This is already the value:

MariaDB [(none)]> SHOW GLOBAL VARIABLES LIKE 'innodb_thread_concurrency';
 
+---------------------------+-------+
 
| Variable_name             | Value |
 
+---------------------------+-------+
 
| innodb_thread_concurrency | 0     |
 
+---------------------------+-------+
 
1 row in set (0.001 sec)

Comment by acsfer [ 2019-08-14 ]

Restart also fails, see errors bellow:

2019-08-14 13:33:57 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
 
2019-08-14 13:33:57 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2019-08-14 13:33:57 9135 [Note] Error reading relay log event: slave SQL thread was killed
 
2019-08-14 13:33:57 9135 [Note] Slave SQL thread exiting, replication stopped in log 'managedstack-bin.000083' at position 25734953; GTID position '0-1-87716,1-1-11514325,2-2-3571446'
 
2019-08-14 13:33:57 0 [Note] InnoDB: FTS optimize thread exiting.
 
2019-08-14 13:33:57 9134 [Note] Slave I/O thread exiting, read up to log 'managedstack-bin.000083', position 25734953; GTID position 1-1-11514325,0-1-87716,2-2-3571446
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9143 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9142 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9140 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9141 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9139 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9138 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9137 (user : '') did not exit
 
2019-08-14 13:34:17 0 [Warning] /usr/sbin/mysqld: Thread 9136 (user : '') did not exit
 
2019-08-14 13:36:58 0 [ERROR] mysqld: Can't lock aria control file '/var/lib/mysql/aria_log_control' for exclusive use, error: 11. Will retry for 30 seconds
 
2019-08-14 13:37:29 0 [ERROR] mysqld: Got error 'Could not get an exclusive lock; file is probably in use by another process' when trying to use aria control file '/var/lib/mysql/aria_log_control'
 
2019-08-14 13:37:29 0 [ERROR] Plugin 'Aria' init function returned error.
 
2019-08-14 13:37:29 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
 
2019-08-14 13:37:29 0 [Note] InnoDB: Using Linux native AIO
 
2019-08-14 13:37:29 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2019-08-14 13:37:29 0 [Note] InnoDB: Uses event mutexes
 
2019-08-14 13:37:29 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2019-08-14 13:37:29 0 [Note] InnoDB: Number of pools: 1
 
2019-08-14 13:37:29 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2019-08-14 13:37:29 0 [Note] mysqld: O_TMPFILE is not supported on /mnt/ramdisk (disabling future attempts)
 
2019-08-14 13:37:29 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 1, chunk size = 128M
 
2019-08-14 13:37:29 0 [Note] InnoDB: Completed initialization of buffer pool
 
2019-08-14 13:37:29 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2019-08-14 13:37:29 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:29 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:29 0 [Note] InnoDB: Retrying to lock the first data file
 
2019-08-14 13:37:30 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:30 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:31 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:31 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:32 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:32 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:33 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:33 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:34 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:34 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:35 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:35 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:36 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:36 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:37 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:37 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:38 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:38 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
2019-08-14 13:37:39 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11
 
2019-08-14 13:37:39 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
 
 
 
2019-08-14 13:39:09 0 [Note] InnoDB: Unable to open the first data file
 
2019-08-14 13:39:09 0 [ERROR] InnoDB: Operating system error number 11 in a file operation.
 
2019-08-14 13:39:09 0 [ERROR] InnoDB: Error number 11 means 'Resource temporarily unavailable'
 
2019-08-14 13:39:09 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
 
2019-08-14 13:39:09 0 [ERROR] InnoDB: Cannot open datafile './ibdata1'
 
2019-08-14 13:39:09 0 [ERROR] InnoDB: Could not open or create the system tablespace. If you tried to add new data files to the system tablespace, and it failed here, you should now edit innodb_data_file_path in my.cnf back to what it was, and remove the new ibdata files InnoDB created in this failed attempt. InnoDB only wrote those files full of zeros, but did not yet use them in any way. But be careful: do not remove old data files which contain your precious data!
 
2019-08-14 13:39:09 0 [ERROR] InnoDB: Plugin initialization aborted with error Cannot open a file
 
2019-08-14 13:39:09 0 [Note] InnoDB: Starting shutdown...
 
2019-08-14 13:39:10 0 [ERROR] Plugin 'InnoDB' init function returned error.
 
2019-08-14 13:39:10 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2019-08-14 13:39:10 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2019-08-14 13:39:10 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
 
2019-08-14 13:39:10 0 [ERROR] Failed to initialize plugins.
 
2019-08-14 13:39:10 0 [ERROR] Aborting

Only solution, in both cases, is to kill -9 the process and then start the server.

Once process killed, servers starts normally:

2019-08-14 13:41:23 0 [Note] InnoDB: Using Linux native AIO
 
2019-08-14 13:41:23 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2019-08-14 13:41:23 0 [Note] InnoDB: Uses event mutexes
 
2019-08-14 13:41:23 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2019-08-14 13:41:23 0 [Note] InnoDB: Number of pools: 1
 
2019-08-14 13:41:23 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2019-08-14 13:41:23 0 [Note] mysqld: O_TMPFILE is not supported on /mnt/ramdisk (disabling future attempts)
 
2019-08-14 13:41:23 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 1, chunk size = 128M
 
2019-08-14 13:41:23 0 [Note] InnoDB: Completed initialization of buffer pool
 
2019-08-14 13:41:23 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2019-08-14 13:41:23 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=23793753349
 
2019-08-14 13:41:23 0 [Note] InnoDB: Last binlog file './managedstack-bin.000058', position 53049690
 
2019-08-14 13:41:25 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2019-08-14 13:41:25 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2019-08-14 13:41:25 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2019-08-14 13:41:25 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2019-08-14 13:41:25 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2019-08-14 13:41:25 0 [Note] InnoDB: Waiting for purge to start
 
2019-08-14 13:41:25 0 [Note] InnoDB: 10.4.7 started; log sequence number 23793753358; transaction id 37923374
 
2019-08-14 13:41:25 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2019-08-14 13:41:25 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2019-08-14 13:41:25 0 [Note] Recovering after a crash using managedstack-bin
 
2019-08-14 13:41:26 0 [Note] Starting crash recovery...
 
2019-08-14 13:41:26 0 [Note] Crash recovery finished.
 
2019-08-14 13:41:26 0 [Note] Server socket created on IP: '0.0.0.0'.
 
2019-08-14 13:41:26 0 [Note] Reading of all Master_info entries succeeded
 
2019-08-14 13:41:26 0 [Note] Added new Master_info '' to hash table
 
2019-08-14 13:41:26 10 [Note] Slave I/O thread: Start asynchronous replication to master 'replication@10.0.0.2:3306' in log 'managedstack-bin.000083' at position 25734953
 
2019-08-14 13:41:26 11 [Note] Slave SQL thread initialized, starting replication in log 'managedstack-bin.000083' at position 25734953, relay log './managedstack-relay-bin.000001' position: 4; GTID position '0-1-87716,1-1-11514325,2-2-3571446'
 
2019-08-14 13:41:26 0 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.4.7-MariaDB-1:10.4.7+maria~bionic-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
2019-08-14 13:41:26 10 [Note] Slave I/O thread: connected to master 'replication@10.0.0.2:3306',replication starts at GTID position '1-1-11514325,0-1-87716,2-2-3571446'
 
2019-08-14 13:41:26 16 [Note] Start binlog_dump to slave_server(1), pos(managedstack-bin.000058, 53049690)

Comment by Elena Stepanova [ 2019-08-15 ]

Let's keep tracking it in MDEV-20115, as acs-ferreira suggested.

Comment by Andrei Petrov [ 2020-07-23 ]

Hi All,

unfortunately stepped on the same rake when I began to deploy a powerds server on debian10.3 with mariadb 10.4.13. Everything was fine before replication started but after that when I tried to restart mariadb with the command 'service mysql restart' it hung up and I could see the timeout messages. I could not even reboot the DO droplet because mariadb could not stop and i had to switch off/switch on the droplet first. I tried to to google about this issue and got here. Added the option innodb_thread_concurrency = 0 but it did not help. Next i began to read the config my.cnf carefully and i decided to enable general_log option to look at the usual logs:

  1. Both location gets rotated by the cronjob.
  2. Be aware that this log type is a performance killer.
  3. As of 5.1 you can enable the log at runtime!
    general_log_file = /var/log/mysql/mysql.log
    general_log = 1

and after that the issue disappeared and mariadb restarts smoothly now. I have small db about 1mb and i dont think i will lose the perfomance with enabling general_log, but i hope you may fix it further and it may be possible to switch off general_log once.

Comment by Michael Widenius [ 2022-04-13 ]

If this happens again, it would be of great help to know what the server is doing when it hangs.

To know this, you can try one of the following commands:

strace -p 'pid of mysqld process'

Or try to use gdb to get a full stack trace:

gdb /usr/sbin/mariadbd
attach 'pid of mysqld process'
set logging on
set pagination off
set print frame-arguments all
thread apply all bt full
set logging off
quit

The output can be found in the file gdb.txt. Please attach it to this bug report

Comment by Michael Widenius [ 2022-04-13 ]

Please also provide information about the cpu you are using

Generated at Thu Feb 08 08:58:33 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.