Bug#800588: Same problem here since a long time...
Tim Ruehsen
tim.ruehsen at gmx.de
Tue Jun 7 09:57:17 BST 2016
I have the same problem on Debian SID (amd64) - daily updated - since a long
time. It only came up here on Reboot / Powerdown, but I wasn't aware it was
'mysqld'. Until the last systemd update... now it shows what it is waiting
for: (10min timeout on mysqld).
I just did a
# /etc/init.d/mysqld restart
[....] Restarting mysql (via systemctl): mysql.service
(Now waiting since a few minutes)
On a second console:
# systemctl status mysql.service
● mysql.service - MySQL Community Server
Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset:
enabled)
Active: deactivating (stop-sigterm) since Tue 2016-06-07 10:48:41 CEST; 16s
ago
Process: 1880 ExecStartPost=/usr/share/mysql/mysql-systemd-start post
(code=exited, status=0/SUCCESS)
Process: 1823 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre
(code=exited, status=0/SUCCESS)
Main PID: 1877 (mysqld_safe)
CGroup: /system.slice/mysql.service
├─1877 /bin/sh /usr/bin/mysqld_safe
├─5176 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --
plugin-dir=/usr/lib/mysql/plugin --pid-file=/var/run/mysqld/mysqld.p
└─5177 logger -t mysqld -p daemon error
Jun 07 10:48:42 blitz-lx mysqld[5177]: InnoDB: Last MySQL binlog file position
0 11039, file name /var/log/mysql/mysql-bin.000539
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] InnoDB:
128 rollback segment(s) are active.
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] InnoDB:
Waiting for purge to start
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] InnoDB:
5.6.30 started; log sequence number 5885519596
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] Server
hostname (bind-address): '127.0.0.1'; port: 3306
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] -
'127.0.0.1' resolves to '127.0.0.1';
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] Server
socket created on IP: '127.0.0.1'.
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] Event
Scheduler: Loaded 0 events
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note]
/usr/sbin/mysqld: ready for connections.
Jun 07 10:48:42 blitz-lx mysqld[5177]: Version: '5.6.30-1' socket:
'/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
# journalctl -u mysql.service
-- Logs begin at Tue 2016-06-07 10:41:14 CEST, end at Tue 2016-06-07 10:48:42
CEST. --
Jun 07 10:41:19 blitz-lx systemd[1]: Starting MySQL Community Server...
Jun 07 10:41:19 blitz-lx mysqld_safe[1877]: 160607 10:41:19 mysqld_safe
Logging to syslog.
Jun 07 10:41:20 blitz-lx mysqld_safe[1877]: 160607 10:41:20 mysqld_safe
Starting mysqld daemon with databases from /var/lib/mysql
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 0 [Warning] The
syntax 'pre-4.1 password hash' is deprecated and will be removed in a
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 0 [Warning] Using
unique option prefix key_buffer instead of key_buffer_size is deprec
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 0 [Warning] options
--log-slow-admin-statements, --log-queries-not-using-indexes and -
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 0 [Warning]
TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 0 [Note]
/usr/sbin/mysqld (mysqld 5.6.30-1) starting as process 2439 ...
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)
Jun 07 10:41:20 blitz-lx mysqld[2440]:
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Buffered warning: Changed limits: table_open_cache: 431 (requested 2000
Jun 07 10:41:20 blitz-lx mysqld[2440]:
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Using unique option prefix myisam-recover instead of myisam-recover-opt
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] Plugin
'FEDERATED' is disabled.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [ERROR]
Function 'innodb' already exists
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Couldn't load plugin named 'innodb' with soname 'ha_innodb.so'.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [ERROR]
Function 'federated' already exists
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Couldn't load plugin named 'federated' with soname 'ha_federated.so'.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [ERROR]
Function 'blackhole' already exists
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Couldn't load plugin named 'blackhole' with soname 'ha_blackhole.so'.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [ERROR]
Function 'archive' already exists
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Warning]
Couldn't load plugin named 'archive' with soname 'ha_archive.so'.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Using atomics to ref count buffer pool pages
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
The InnoDB memory heap is disabled
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Mutexes and rw_locks use GCC atomic builtins
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Memory barrier is not used
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Compressed tables use zlib 1.2.8
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Using Linux native AIO
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Using CPU crc32 instructions
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Initializing buffer pool, size = 128.0M
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Completed initialization of buffer pool
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Highest supported file format is Barracuda.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
The log sequence numbers 5885499610 and 5885499610 in ibdata files
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Database was not shutdown normally!
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Starting crash recovery.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Reading tablespace information from the .ibd files...
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Restoring possible half-written data pages
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
from the doublewrite buffer...
Jun 07 10:41:20 blitz-lx mysqld[2440]: InnoDB: Last MySQL binlog file position
0 11039, file name /var/log/mysql/mysql-bin.000539
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
128 rollback segment(s) are active.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
Waiting for purge to start
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] InnoDB:
5.6.30 started; log sequence number 5885519586
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] Server
hostname (bind-address): '127.0.0.1'; port: 3306
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] -
'127.0.0.1' resolves to '127.0.0.1';
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] Server
socket created on IP: '127.0.0.1'.
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note] Event
Scheduler: Loaded 0 events
Jun 07 10:41:20 blitz-lx mysqld[2440]: 2016-06-07 10:41:20 2439 [Note]
/usr/sbin/mysqld: ready for connections.
Jun 07 10:41:20 blitz-lx mysqld[2440]: Version: '5.6.30-1' socket:
'/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
Jun 07 10:41:20 blitz-lx systemd[1]: Started MySQL Community Server.
Jun 07 10:48:41 blitz-lx systemd[1]: Stopping MySQL Community Server...
Jun 07 10:48:41 blitz-lx mysqld_safe[1877]: Could not open required defaults
file: /etc/mysql/debian.cnf
Jun 07 10:48:41 blitz-lx mysqld_safe[1877]: Fatal error in defaults handling.
Program aborted
Jun 07 10:48:41 blitz-lx mysqld_safe[1877]: 160607 10:48:41 mysqld_safe Number
of processes running now: 1
Jun 07 10:48:41 blitz-lx mysqld_safe[1877]: 160607 10:48:41 mysqld_safe mysqld
process hanging, pid 2439 - killed
Jun 07 10:48:41 blitz-lx mysqld_safe[1877]: 160607 10:48:41 mysqld_safe mysqld
restarted
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 0 [Warning] The
syntax 'pre-4.1 password hash' is deprecated and will be removed in a
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 0 [Warning] Using
unique option prefix key_buffer instead of key_buffer_size is deprec
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 0 [Warning] options
--log-slow-admin-statements, --log-queries-not-using-indexes and -
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 0 [Warning]
TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 0 [Note]
/usr/sbin/mysqld (mysqld 5.6.30-1) starting as process 5176 ...
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)
Jun 07 10:48:41 blitz-lx mysqld[5177]:
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Buffered warning: Changed limits: table_open_cache: 431 (requested 2000
Jun 07 10:48:41 blitz-lx mysqld[5177]:
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Using unique option prefix myisam-recover instead of myisam-recover-opt
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] Plugin
'FEDERATED' is disabled.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [ERROR]
Function 'innodb' already exists
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Couldn't load plugin named 'innodb' with soname 'ha_innodb.so'.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [ERROR]
Function 'federated' already exists
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Couldn't load plugin named 'federated' with soname 'ha_federated.so'.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [ERROR]
Function 'blackhole' already exists
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Couldn't load plugin named 'blackhole' with soname 'ha_blackhole.so'.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [ERROR]
Function 'archive' already exists
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Warning]
Couldn't load plugin named 'archive' with soname 'ha_archive.so'.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Using atomics to ref count buffer pool pages
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
The InnoDB memory heap is disabled
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Mutexes and rw_locks use GCC atomic builtins
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Memory barrier is not used
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Compressed tables use zlib 1.2.8
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Using Linux native AIO
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Using CPU crc32 instructions
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Initializing buffer pool, size = 128.0M
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Completed initialization of buffer pool
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Highest supported file format is Barracuda.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
The log sequence numbers 5885499610 and 5885499610 in ibdata files
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Database was not shutdown normally!
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Starting crash recovery.
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Reading tablespace information from the .ibd files...
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
Restoring possible half-written data pages
Jun 07 10:48:41 blitz-lx mysqld[5177]: 2016-06-07 10:48:41 5176 [Note] InnoDB:
from the doublewrite buffer...
Jun 07 10:48:42 blitz-lx mysqld[5177]: InnoDB: Last MySQL binlog file position
0 11039, file name /var/log/mysql/mysql-bin.000539
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] InnoDB:
128 rollback segment(s) are active.
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] InnoDB:
Waiting for purge to start
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] InnoDB:
5.6.30 started; log sequence number 5885519596
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] Server
hostname (bind-address): '127.0.0.1'; port: 3306
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] -
'127.0.0.1' resolves to '127.0.0.1';
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] Server
socket created on IP: '127.0.0.1'.
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note] Event
Scheduler: Loaded 0 events
Jun 07 10:48:42 blitz-lx mysqld[5177]: 2016-06-07 10:48:42 5176 [Note]
/usr/sbin/mysqld: ready for connections.
Jun 07 10:48:42 blitz-lx mysqld[5177]: Version: '5.6.30-1' socket:
'/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
# date
Tue Jun 7 10:54:55 CEST 2016
Let me know if there is anything else you need. The problem is absolutely
reproducible / happens always.
BTW, how can one reduce the 10min to 1min ?
Best Regards
Tim Rühsen
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: This is a digitally signed message part.
URL: <http://lists.alioth.debian.org/pipermail/pkg-systemd-maintainers/attachments/20160607/4b5cb815/attachment-0001.sig>
More information about the Pkg-systemd-maintainers
mailing list