Ubuntu
mysql-5.7 package

Mysql server take 10 minutes to stop without message after time drift

Bug #1600164 reported by EOLE team on 2016-07-08
38
This bug affects 7 people
Affects Status Importance Assigned to Milestone
​ mysql-5.7 (Ubuntu)
Confirmed
Low
Norvald H. Ryeng
Also affects project (?) Also affects distribution/package Nominate for series

Bug Description

Hello,

I figure out an issue and it took time to understand what happened:

* hardware clock is 2 hours in future
* during system boot: mysql start at the same time than ntp
* ntp fix clock which does a drift of 2 hours in past

Now, stopping mysql with “service mysql stop”:

* take 10 minutes
* provides no no information of what's happening to the user
* process is killed by the way (no clean stop)

To solve this issue, mysql should be started after ntp.

Distributor ID: Ubuntu
Description: Ubuntu 16.04 LTS
Release: 16.04
Codename: xenial

Here are the logs:

root@xenial:~# LANG=C journalctl -u mysql.service
-- Logs begin at Fri 2016-07-08 14:33:07 CEST, end at Fri 2016-07-08 11:46:00 CEST. --
Jul 08 14:34:11 xenial systemd[1]: Starting MySQL Community Server...
Jul 08 14:34:12 xenial systemd[1]: Started MySQL Community Server.
Jul 08 11:36:00 xenial systemd[1]: Stopping MySQL Community Server...
Jul 08 11:46:00 xenial systemd[1]: mysql.service: State 'stop-sigterm' timed out. Killing.
Jul 08 11:46:00 xenial systemd[1]: mysql.service: Main process exited, code=killed, status=9/KILL
Jul 08 11:46:00 xenial systemd[1]: Stopped MySQL Community Server.
Jul 08 11:46:00 xenial systemd[1]: mysql.service: Unit entered failed state.
Jul 08 11:46:00 xenial systemd[1]: mysql.service: Failed with result 'signal'.

root@xenial:~# cat /var/log/mysql/error.log
2016-07-08T09:36:00.656993Z 0 [Note] Giving 0 client threads a chance to die gracefully
2016-07-08T09:36:00.657033Z 0 [Note] Shutting down slave threads
2016-07-08T09:36:00.657041Z 0 [Note] Forcefully disconnecting 0 remaining clients
2016-07-08T09:36:00.657049Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2016-07-08T09:36:00.657164Z 0 [Note] Binlog end
2016-07-08T09:36:00.657596Z 0 [Note] Shutting down plugin 'ngram'
2016-07-08T09:36:00.657609Z 0 [Note] Shutting down plugin 'ARCHIVE'
2016-07-08T09:36:00.657614Z 0 [Note] Shutting down plugin 'partition'
2016-07-08T09:36:00.657618Z 0 [Note] Shutting down plugin 'BLACKHOLE'
2016-07-08T09:36:00.657623Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
2016-07-08T09:36:00.657628Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2016-07-08T09:36:00.657631Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2016-07-08T09:36:00.657635Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2016-07-08T09:36:00.657639Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2016-07-08T09:36:00.657643Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2016-07-08T09:36:00.657646Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2016-07-08T09:36:00.657650Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2016-07-08T09:36:00.657653Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2016-07-08T09:36:00.657657Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2016-07-08T09:36:00.657660Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2016-07-08T09:36:00.657664Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2016-07-08T09:36:00.657667Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2016-07-08T09:36:00.657671Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2016-07-08T09:36:00.657674Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2016-07-08T09:36:00.657677Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2016-07-08T09:36:00.657681Z 0 [Note] Shutting down plugin 'INNODB_METRICS'
2016-07-08T09:36:00.657684Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
2016-07-08T09:36:00.657702Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2016-07-08T09:36:00.657706Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2016-07-08T09:36:00.657709Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2016-07-08T09:36:00.657713Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2016-07-08T09:36:00.657717Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2016-07-08T09:36:00.657720Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2016-07-08T09:36:00.657724Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
2016-07-08T09:36:00.657728Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2016-07-08T09:36:00.657731Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2016-07-08T09:36:00.657735Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2016-07-08T09:36:00.657739Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2016-07-08T09:36:00.657742Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2016-07-08T09:36:00.657746Z 0 [Note] Shutting down plugin 'InnoDB'
2016-07-08T09:36:00.657901Z 0 [Note] InnoDB: FTS optimize thread exiting.
2016-07-08T09:36:00.657993Z 0 [Note] InnoDB: Starting shutdown...
2016-07-08T09:36:00.758259Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2016-07-08T09:36:00.758430Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 160708 11:36:00
2016-07-08T09:37:01.641619Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:38:01.820902Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:39:02.008053Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:40:02.190355Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:41:02.368810Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:42:02.554637Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:43:02.738084Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:44:02.920082Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2016-07-08T09:45:03.103536Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool

Lars Tangvald (lars-tangvald) wrote :

I _think_ adding After=ntp.service would be safe (does not imply Requires), but need to learn more about the ordering and dependency system in systemd first.

Robie Basak (racb) wrote :

I'm not sure it's reasonable to adjust service startups. Following that logic, every package would have to start after ntp.service, and there should be a more general solution to that problem.

Can MySQL be adjusted to be a little more robust to the time changing when it is idle? I understand that in the general case this isn't really solvable though, which is exactly why ntp skews time. It is essential to have the system time on a server correct, and I don't think every case of things screwing up are reasonable to fix. It is reasonable to improve robustness if a fix is trivial, though.

Changed in mysql-5.7 (Ubuntu):
importance: Undecided → Low
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in mysql-5.7 (Ubuntu):
status: New → Confirmed
mateddy (mateddy) wrote :

I go this problem, however, adding After=ntp.service wouldn't fix it.

Robie Basak (racb) on 2017-01-06
Changed in mysql-5.7 (Ubuntu):
assignee: nobody → Norvald H. Ryeng (nryeng)
Clemens Fuchslocher (clemens-fuchslocher) wrote :

I also have this problem with Ubuntu 16.04.2 LTS:

| $ lsb_release --all
| No LSB modules are available.
| Distributor ID: Ubuntu
| Description: Ubuntu 16.04.2 LTS
| Release: 16.04
| Codename: xenial
|
| $ dmidecode -s system-product-name
| VirtualBox

After a reboot the activation time of MySQL is one hour ahead.

1. If I wait one hour after reboot, I can shutdown MySQL instantly:

| $ systemctl status mysql.service
| ...
| Active: active (running) since Fri 2017-02-10 18:20:08 CET; 59min left
| ...
|
| $ date
| Fri Feb 10 17:20:54 CET 2017
|
| $ sleep 60m
|
| $ date
| Fri Feb 10 18:21:02 CET 2017
|
| $ systemctl status mysql.service
| ...
| Active: active (running) since Fri 2017-02-10 18:20:08 CET; 57s ago
| ...
|
| $ time systemctl stop mysql.service
|
| real 0m4.928s
| user 0m0.028s
| sys 0m0.008s

2. If I try it earlier, the shutdown fails after 10 minutes and MySQL gets killed by systemd with SIGKILL.

3. If I increase the systemd timeout of MySQL to two hours, then the shutdown successfully ends after one hour. The attached error-20170210.log contains this case and also the time jump:

| 2017-02-10T15:22:26.962776Z 0 [Note] /usr/sbin/mysqld: ready for connections.
| ...
| 2017-02-10T14:23:52.465978Z 0 [Note] Giving 0 client threads a chance to die gracefully

4. As suggested, I tried to start MySQL after the ntp.service, but it didn't helped:

| $ apt-get install ntp
|
| $ grep ^After /lib/systemd/system/mysql.service
| After=ntp.service
|
| $ systemctl show mysql.service | grep ^After
| After=ntp.service basic.target system.slice systemd-journald.socket sysinit.target

5. I also tried to start MySQL after the systemd-timesyncd.service, but it also didn't helped:

| $ cat /lib/systemd/system/systemd-timesyncd.service.d/disable-with-time-daemon.conf
| ...
| ConditionFileIsExecutable=!/usr/sbin/ntpd
| ...
|
| $ dpkg --purge ntp
|
| $ grep ^After /lib/systemd/system/mysql.service
| After=systemd-timesyncd.service
|
| $ systemctl show mysql.service | grep ^After
| After=systemd-timesyncd.service system.slice basic.target systemd-journald.socket sysinit.target

6. Is there anything else I can try or do?

7. Maybe the importance of this issue should be raised, because killing MySQL during its shutdown with SIGKILL feels a bit risky.

Clemens Fuchslocher (clemens-fuchslocher) wrote :
Clemens Fuchslocher (clemens-fuchslocher) wrote :

I solved my above time jump problem by installing the VirtualBox guest additions as described here: https://www.virtualbox.org/manual/ch04.html

f10w (huudienkhue-le) wrote :

Any fix to this problem yet?

Robie Basak (racb) wrote :

I don't think there will be a fix to this problem in Ubuntu until it is fixed upstream. I suggest you ask there.

darek334 (darek334) wrote :

Confirmed, MySQL stops sometimes 10 minutes, there is no setting to change this ?

Kaijia Feng (fengkaijia) wrote :

Got the same issue, found a possible explanation: my cloud provider store time in local timezone (earlier than UTC); at startup MySQL boot first, then NTP, which updates the time to UTC; therefore, MySQL literally "started in the future" (sounds interesting).

I can hotfix this by setting the timezone to UTC:

dpkg-reconfigure tzdata

After that MySQL can be stopped immediately. Even after I switch timezone back to local time, it can still stop or restart without problems. After rebooting the server (a KVM), I have to do this again unless the NTP timezone issue is fixed.

BTW, @darek334:

> MySQL stops sometimes 10 minutes

10 minutes is the timeout period defined in system/multi-user.target.wants/mysql.service (TimeoutSec=600).

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.
Subscribing...

Other bug subscribers