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

[EOLE team]

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)]

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)]

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.

[Launchpad Janitor (janitor)]

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

[mateddy (mateddy)]

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

[Clemens Fuchslocher (clemens-fuchslocher)]

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)]

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)]

Any fix to this problem yet?

[Robie Basak (racb)]

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)]

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

[Kaijia Feng (fengkaijia)]

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).

[JakubPisarczyk (jpisarczyk)]

Hi,
Same happening on ubuntu server 18.04. Fresh install , just apache and mysql without ntp. Machine is a VM in esxi 6.5. During restart “A stop job is running to for Mysql Community Server” and 10 min of waiting.

I was trying tzdata reconfigure and ntp service, but it's not permanent.

Any solution soon ?
Best regards

[EOLE team (eole-team)]

I think the problem can be solved with:

* recent systemd fixes https://github.com/systemd/systemd/issues/5097 (with a workaround for older versions)
* fixing mysql.service to use After=time-sync.target and Wants=time-sync.target

Regards.

[Robie Basak (racb)]

> * fixing mysql.service to use After=time-sync.target and Wants=time-sync.target

As far as I understand this is unsuitable to be done by default since not all systems will necessarily ever reach "time synced", for example if they're intentionally being used offline.

But this does seem like a reasonable workaround for sysadmins to use locally when using MySQL in broken environments. In this case, you can override packaged service behaviour locally in /etc (see systemd-system.conf(5)).

[EOLE team (eole-team)]

I just made the test to be sure: using Wants= does not prevent MySQL to start event if the system never reaches “time-sync.target”.

I added an ntpdate.service:

  # /etc/systemd/system/ntpdate.service
  [Unit]
  Description=Force synchronisation of time
  ConditionPathExists=/etc/default/ntpdate
  DefaultDependencies=no
  Conflicts=shutdown.target
  After=network-online.target
  Before=time-sync.target shutdown.target
  Wants=network-online.target time-sync.target

  [Service]
  Type=oneshot
  Environment="NTPSERVERS=pool.ntp.org"
  EnvironmentFile=/etc/default/ntpdate
  ExecStart=/usr/sbin/ntpdate -v $NTPSERVERS
  RemainAfterExit=yes

  [Install]
  WantedBy=sysinit.target

And an override for MySQL:

  # /etc/systemd/system/mysql.service.d/override.conf
  [Unit]
  After=network-online.target time-sync.target
  Wants=network-online.target time-sync.target

ntpdate.service is failed:

  systemctl status ntpdate.service
  ● ntpdate.service - Force synchronisation of time
     Loaded: loaded (/etc/systemd/system/ntpdate.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Mon 2018-10-15 16:51:25 CEST; 40s ago
    Process: 1129 ExecStart=/usr/sbin/ntpdate -v $NTPSERVERS (code=exited, status=1/FAILURE)
   Main PID: 1129 (code=exited, status=1/FAILURE)

But MySQL is started:

  systemctl status mysql.service
  ● mysql.service - MySQL Community Server
     Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mysql.service.d
             └─override.conf
     Active: active (running) since Mon 2018-10-15 16:51:27 CEST; 3min 17s ago
    Process: 1600 ExecStart=/usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid (code=exited, status=0/SUCCESS)
    Process: 1550 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
   Main PID: 1602 (mysqld)
      Tasks: 30 (limit: 4915)
     CGroup: /system.slice/mysql.service
             └─1602 /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid

Regards.

[Robie Basak (racb)]

I'm just going by https://github.com/systemd/systemd/issues/5097#issuecomment-276787961

[EOLE team (eole-team)]

Yes, it will delay the start of MySQL server but the consequence of going backward in time after MySQL is started are important enough to me.

Regards.

[Arkadiusz Miśkiewicz (arekm)]

https://bugs.mysql.com/bug.php?id=93708

[Rafael David Tinoco (rafaeldtinoco)]

" Fixed as of the upcoming 5.7.27, 8.0.17 release, and here's the changelog entry "

So, judging by:

 mysql-server | 5.7.31-0ubuntu0.18.04.1 | bionic-updates | all

and

 mysql-server | 8.0.20-0ubuntu0.19.10.1 | eoan-updates | all

and

 mysql-server | 8.0.21-0ubuntu0.20.04.3 | focal-updates | all

this is Fix Released in all 3 of them.