[MDEV-17481] mariadb service won't shutdown when it's running and the OS datetime updated backwards Created: 2018-10-17  Updated: 2020-08-25  Resolved: 2020-07-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.7, 10.5.2, 10.2, 10.3, 10.4
Fix Version/s: 10.2.33, 10.3.24, 10.4.14, 10.5.5

Type: Bug Priority: Critical
Reporter: Jossef Harush Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: hang, server, shutdown
Environment:

ubuntu 14.04.05

Attachments: File threads.trusty    
Issue Links:
Duplicate
duplicates MDEV-20078 When setting back the system time whi... Closed
is duplicated by MDEV-20598 Server slow to shutdown if system tim... Closed
is duplicated by MDEV-22789 MariaDB fails to stop on OS shutdown Closed
Relates
relates to MDEV-16526 Overhaul the InnoDB page flushing Closed

 Description   

When I update the OS datetime *backwards* while `mariadb` is running, it causes `mariadb` to hang when I command it's service to stop.
I've also noticed that this doesn't occur when I set the new OS datetime value to be grater than the current OS datetime, only backwards causes the hang.

—

Steps to reproduce: 

 
 
    sudo date --set="2018-10-04 20:00:00"
 
 
 
    sudo service mysql start
 
     * Starting MariaDB database server mysqld [ OK ]
 
 
 
    sudo service mysql stop
 
     * Stopping MariaDB database server mysqld [ OK ]
 
 
 
    sudo service mysql start
 
     * Starting MariaDB database server mysqld [ OK ]
 
 
 
    sudo date --set="2018-10-04 10:00:00"
 
 
 
    sudo service mysql stop
 
     * Stopping MariaDB database server mysqld

> setting the date, starting the service, resetting the date -10 hours, stopping the service => hang

 Comments   
Comment by Jossef Harush [ 2018-10-17 ]

also posted in StackExchange
https://dba.stackexchange.com/q/219291/36612

Why is it hangs and how can I avoid it?

Comment by Elena Stepanova [ 2018-12-29 ]

I can reproduce it reliably with the current 10.2/10.3 running on Trusty, but not on Stretch. I didn't try other OS flavors.

Service involvement or build specifics are irrelevant, reproducible with a debug server started and shut down manually, as well as with release binary tarballs and debian packages.

Not reproducible with 10.0/10.1.

10.3 ab4bc8442094a2be8cdb74bfcddfccede81ac03d

 
#0  0x00007f5333f79b9d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
 
#1  0x00007f533632b98b in os_thread_sleep (tm=100000) at /home/buildbot/mariadb-10.3.12/storage/innobase/os/os0thread.cc:225
 
#2  0x00007f53362fd750 in logs_empty_and_mark_files_at_shutdown () at /home/buildbot/mariadb-10.3.12/storage/innobase/log/log0log.cc:1821
 
#3  0x00007f533643058b in innodb_shutdown () at /home/buildbot/mariadb-10.3.12/storage/innobase/srv/srv0start.cc:2566
 
#4  0x00007f5336256d91 in innobase_end () at /home/buildbot/mariadb-10.3.12/storage/innobase/handler/ha_innodb.cc:4363
 
#5  0x00007f5335ffa71d in ha_finalize_handlerton (plugin=0x7f5339885078) at /home/buildbot/mariadb-10.3.12/sql/handler.cc:462
 
#6  0x00007f5335d0f4bc in plugin_deinitialize (plugin=0x7f5339885078, ref_check=true) at /home/buildbot/mariadb-10.3.12/sql/sql_plugin.cc:1235
 
#7  0x00007f5335d0f993 in reap_plugins () at /home/buildbot/mariadb-10.3.12/sql/sql_plugin.cc:1311
 
#8  0x00007f5335d11b8c in plugin_shutdown () at /home/buildbot/mariadb-10.3.12/sql/sql_plugin.cc:1977
 
#9  0x00007f5335bcf455 in clean_up (print_message=true) at /home/buildbot/mariadb-10.3.12/sql/mysqld.cc:2256
 
#10 0x00007f5335bcefc4 in unireg_end () at /home/buildbot/mariadb-10.3.12/sql/mysqld.cc:2124
 
#11 0x00007f5335bceeb5 in kill_server (sig_ptr=0x0) at /home/buildbot/mariadb-10.3.12/sql/mysqld.cc:2051
 
#12 0x00007f5335bcef03 in kill_server_thread (arg=0x7f53300a7e10) at /home/buildbot/mariadb-10.3.12/sql/mysqld.cc:2074
 
#13 0x00007f5333f72184 in start_thread (arg=0x7f531d892700) at pthread_create.c:312
 
#14 0x00007f533347f37d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
 
 
Thread 1 (Thread 0x7f5335622780 (LWP 19686)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
 
#1  0x00007f53367ab165 in safe_cond_wait (cond=0x7f5337476a00 <COND_thread_count>, mp=0x7f5337475600 <LOCK_thread_count>, file=0x7f533684a3e8 "/home/buildbot/mariadb-10.3.12/include/mysql/psi/mysql_thread.h", line=1178) at /home/buildbot/mariadb-10.3.12/mysys/thr_mutex.c:492
 
#2  0x00007f5335bcbdad in inline_mysql_cond_wait (that=0x7f5337476a00 <COND_thread_count>, mutex=0x7f5337475600 <LOCK_thread_count>, src_file=0x7f533684c340 "/home/buildbot/mariadb-10.3.12/sql/mysqld.cc", src_line=6217) at /home/buildbot/mariadb-10.3.12/include/mysql/psi/mysql_thread.h:1178
 
#3  0x00007f5335bd7731 in mysqld_main (argc=7, argv=0x7f533982b378) at /home/buildbot/mariadb-10.3.12/sql/mysqld.cc:6217
 
#4  0x00007f5335bcb515 in main (argc=7, argv=0x7fffe961eff8) at /home/buildbot/mariadb-10.3.12/sql/main.cc:25

All threads are attached as threads.trusty.

Also curiously, if I set the date back while it is hanging (or rather waiting for something), the shutdown proceeds to the successful finish. Note the timestamps:

2018-12-24 20:02:24 0 [Note] Added new Master_info '' to hash table
 
2018-12-24 20:02:24 0 [Note] /home/buildbot/mariadb-10.3.11-linux-x86_64/bin/mysqld: ready for connections.
 
Version: '10.3.11-MariaDB'  socket: '/tmp/mysql.sock'  port: 3306  MariaDB Server
 
2018-10-04 20:00:05 0 [Note] /home/buildbot/mariadb-10.3.11-linux-x86_64/bin/mysqld (initiated by: root[root] @ localhost [::1]): Normal shutdown
 
2018-10-04 20:00:05 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2018-10-04 20:00:05 0 [Note] InnoDB: FTS optimize thread exiting.
 
2018-10-04 20:00:06 0 [Note] InnoDB: Starting shutdown...
 
2018-10-04 20:00:06 0 [Note] InnoDB: Dumping buffer pool(s) to /home/buildbot/mariadb-10.3.11-linux-x86_64/data/ib_buffer_pool
 
2018-10-04 20:00:06 0 [Note] InnoDB: Buffer pool(s) dump completed at 181004 20:00:05
 
2018-10-04 20:01:06 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:02:06 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:03:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:04:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:05:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:06:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:07:07 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-10-04 20:08:08 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
2018-12-29 20:35:00 0 [Note] InnoDB: Shutdown completed; log sequence number 1630824; transaction id 22
 
2018-12-29 20:35:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2018-12-29 20:35:00 0 [Note] /home/buildbot/mariadb-10.3.11-linux-x86_64/bin/mysqld: Shutdown complete

Comment by Marko Mäkelä [ 2018-12-30 ]

At first sight, this looks like a design problem in os_event::timed_wait(). On Windows, it is using a delay in milliseconds; on POSIX systems, it invokes pthread_cond_timedwait() to wait until a specified absolute timestamp. If the system time is moved backwards after the creation of the timestamp, the wait could be much longer than anticipated.

In earlier versions of InnoDB, similar code is part of the function os_event_wait_time_low(). Maybe setting the system time backwards would cause a spurious wakeup and immediate return from pthread_cond_timedwait(). After all, spurious wakeups are documented to be possible.

The most likely cause for the hang seems to be the way how the page cleaner threads have been implemented in MySQL 5.7 and MariaDB 10.2. The function pc_sleep_if_needed() or its caller buf_flush_page_cleaner_coordinator() or the page cleaner subsystem could make the matter worse by storing absolute timestamps over extended periods of time. For example, page_cleaner_flush_pages_recommendation() is storing prev_time across calls, and pc_flush_slot() does not prevent the time differences list_tm and lru_tm from becoming negative.

Comment by Thirunarayanan Balathandayuthapani [ 2019-09-06 ]

The following patch solves this issue, but it causes a performance regression for idle server.

diff --git a/storage/innobase/buf/buf0flu.cc b/storage/innobase/buf/buf0flu.cc
 
index 74df5ee..2d8a9fe 100644
 
--- a/storage/innobase/buf/buf0flu.cc
 
+++ b/storage/innobase/buf/buf0flu.cc
 
@@ -3145,13 +3145,13 @@ DECLARE_THREAD(buf_flush_page_cleaner_coordinator)(void*)
 
        ulint   warn_interval = 1;
 
        ulint   warn_count = 0;
 
        int64_t sig_count = os_event_reset(buf_flush_event);
 
-       ulint   next_loop_time = ut_time_ms() + 1000;
 
+       ulint   next_loop_time = my_interval_timer() + 1000;
 
        ulint   n_flushed = 0;
 
        ulint   last_activity = srv_get_activity_count();
 
        ulint   last_pages = 0;
 
 
 
        while (srv_shutdown_state == SRV_SHUTDOWN_NONE) {
 
-               ulint   curr_time = ut_time_ms();
 
+               ulint   curr_time = my_interval_timer();
 
 
 
                /* The page_cleaner skips sleep if the server is
 
                idle and there are no pending IOs in the buffer pool

It should be fixable in mdev-16526

Comment by somak92 [ 2020-04-20 ]

HI~!
I have mariadb-10.2.19
How can I solve it in mariadb-10.2.19 ??
I would like to know how to solve this problem.
Please please.

Comment by Marko Mäkelä [ 2020-04-20 ]

Because this is repeatable with 10.5.2, MDEV-16264 did not magically fix this.

I think that we must run some tests to assess the performance impact of the proposed change, and we should actually fix this in the earliest affected major version (10.2).

Comment by Ivan Novak [ 2020-06-03 ]

I have a VPS that has its hwclock set 2 hours ahead of local time, and I can't get the provider to fix it. Then NTP client (chronyd) sets the time -2 hours every time after VPS start.
This is actually a big issue for me. After every reboot I need to first set the time 2 hours ahead, stop mariadb, run ntp client again to get correct time, and then start mariadb again.

Comment by Thirunarayanan Balathandayuthapani [ 2020-07-13 ]

__pthread_cond_timedwait() hangs if time moved backwards. Hack could be waking up the page cleaner thread in logs_empty_and_mark_files_at_shutdown().
But there is possibility that server could hang when server is running. So we need to call os_event_set(buf_flush_event) frequently. Master thread could
be the correct place to do. Need to evaluate the performance if we do that.

Comment by Marko Mäkelä [ 2020-07-13 ]

wlad, what do you think of this hack? Basically, we would intentionally trigger some ‘spurious wakeups’ to work around the problem. Ultimately we want to rewrite the page cleaner (MDEV-16526) and get rid of the problematic call, but that would be a way too big change in GA releases.

Comment by Vladislav Vaintroub [ 2020-07-13 ]

waking at shutdown seems fine, but do we really need it at other times, frequently? buf_flush_event is set here and there anyway, in different situations.

Comment by Vladislav Vaintroub [ 2020-07-13 ]

https://jira.mariadb.org/browse/MDEV-17481?focusedCommentId=133652&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-133652
probably causes a regression, because it uses nanoseconds timer my_interval_timer(), where previously milliseconds were used.

ulint next_loop_time = ut_time_ms() + 1000; vs ulint next_loop_time = my_interval_timer() + 1000;

is a big difference.

Comment by Marko Mäkelä [ 2020-07-14 ]

wlad, the old comment that you refer to is not part of the currently planned solution. We would not increase the use of my_interval_timer(), but instead basically just ensure that a call to os_event_set(buf_flush_event) will end the infinite wait here and there.

Comment by Marko Mäkelä [ 2020-07-22 ]

The work-around looks OK to me. We’d be waking up the page cleaner in logs_empty_and_mark_files_at_shutdown() and srv_master_do_idle_tasks().

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