| Bug #96615 | mysql server cannot handle write operations after set system time to the past | ||
|---|---|---|---|
| Submitted: | 22 Aug 2019 10:23 | Modified: | 29 Aug 2019 13:03 |
| Reporter: | shangshang yu | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Logging | Severity: | S4 (Feature request) |
| Version: | 8.0.16 | OS: | CentOS |
| Assigned to: | CPU Architecture: | x86 | |
[22 Aug 2019 10:23]
shangshang yu
[23 Aug 2019 12:57]
MySQL Verification Team
Helo Mr. yu, Thank you for your bug report. What you are reporting is expected behaviour for the program `sysbench`. However, this program is not made, nor maintained by us, so you reported this to the wrong forum.
[25 Aug 2019 1:50]
shangshang yu
Hello, Sinisa, Thank you for your reply. However, I am disagree with you. Firstly, the sysbench just a tools is used for testing mysql, the write only mode of sysbench can do some write operations, such as INSERT, UPDATE, DELETE. The qps is 0 because of the operations was blocked, we can use "show processlist" to check it: mysql> show processlist; +----+-----------------+-----------------+--------+---------+--------+------------------------+------------------------------------------------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-----------------+-----------------+--------+---------+--------+------------------------+------------------------------------------------------------------------------------------------------+ | 4 | event_scheduler | localhost | NULL | Daemon | 145754 | Waiting on empty queue | NULL | | 41 | root | localhost | sbtest | Sleep | 846 | | NULL | | 42 | root | localhost:17059 | sbtest | Execute | 144 | updating | UPDATE sbtest23 SET k=k+1 WHERE id=1237 | | 43 | root | localhost:17062 | sbtest | Execute | 144 | updating | DELETE FROM sbtest7 WHERE id=1248 | | 44 | root | localhost:17060 | sbtest | Execute | 144 | updating | UPDATE sbtest11 SET k=k+1 WHERE id=1246 | | 45 | root | localhost:17058 | sbtest | Execute | 144 | updating | UPDATE sbtest1 SET k=k+1 WHERE id=1263 If we do some insert manually, the operation will blocked also. mysql> use sbtest Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql> insert into sbtest1(k,c,pad) values(1,'1','1'); Secondly, if I set the time to the past 10 minutes ago, and the qps will resume in 10 minutes: [ 1240s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1250s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1260s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1270s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1280s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1290s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1300s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1310s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 1320s ] thds: 32 tps: 119.90 qps: 719.48 (r/w/o: 0.00/479.28/240.19) lat (ms,95%): 81.48 err/s: 0.40 reconn/s: 0.00 [ 1330s ] thds: 32 tps: 605.62 qps: 3636.82 (r/w/o: 0.00/2425.48/1211.34) lat (ms,95%): 82.96 err/s: 0.10 reconn/s: 0.00 [ 1340s ] thds: 32 tps: 645.20 qps: 3868.57 (r/w/o: 0.00/2578.08/1290.49) lat (ms,95%): 77.19 err/s: 0.10 reconn/s: 0.00 [ 1350s ] thds: 32 tps: 580.18 qps: 3484.40 (r/w/o: 0.00/2323.93/1160.47) lat (ms,95%): 108.68 err/s: 0.10 reconn/s: 0.00 [ 1360s ] thds: 32 tps: 629.52 qps: 3777.11 (r/w/o: 0.00/2517.88/1259.24) lat (ms,95%): 81.48 err/s: 0.40 reconn/s: 0.00 [ 1370s ] thds: 32 tps: 640.40 qps: 3842.42 (r/w/o: 0.00/2561.41/1281.01) lat (ms,95%): 78.60 err/s: 0.00 reconn/s: 0.00 [ 1380s ] thds: 32 tps: 627.40 qps: 3765.19 (r/w/o: 0.00/2510.50/1254.70) lat (ms,95%): 81.48 err/s: 0.10 reconn/s: 0.00 [ 1390s ] thds: 32 tps: 608.20 qps: 3647.91 (r/w/o: 0.00/2431.31/1216.60) lat (ms,95%): 87.56 err/s: 0.10 reconn/s: 0.00 That means the mysql server can not resumed until reach the time point. Thirdly, I use sysbench test mysql server 5.7.x, the issue will not appear. In summary, I think the issue is a bug of mysql server, please pay more attention on this issue. Great Thanks.
[25 Aug 2019 1:52]
shangshang yu
change status
[26 Aug 2019 12:19]
MySQL Verification Team
Hi Mr. yu, I am afraid that you are wrong. If you change system time, you will affect how our server performs. You can also try kill -5 or -9 and you can also cause lots of problems. Try deleting data dictionary and server will be useless. On Unix , user `root` can do anything and we do not plan to make server oblivious to what ever somebody might invent. However, we are providing all the tools to help DBA to protect the server from any kind of unauthorised access.
[26 Aug 2019 13:58]
shangshang yu
Hello, Sinisa, Do you mean that mysql server 8.0.16 does not support to modify system time when runtime? However, the mysql server 5.7.x support the feature.
[27 Aug 2019 3:40]
shangshang yu
How to deal with the problem of Summer time？The system time may have one hour slower.
[27 Aug 2019 4:51]
MySQL Verification Team
think what reporter means is we should be using http://man7.org/linux/man-pages/man2/clock_nanosleep.2.html with CLOCK_MONOTONIC instead of nanosleep? Why should a sleep function care about the system time anyway.
[27 Aug 2019 12:17]
MySQL Verification Team
Hi, Daylight saving time is treated automatically by our server, provided you set a timezone correctly. That is one of the basic duties of the DBA. Or did you have something else in your mind, like using some other Linux clock settings ???? If the last case is true, can you be more specific ???
[27 Aug 2019 12:40]
shangshang yu
Hello, Sinisa, I just use 'date -s' to set system time. Could you repeat the issue? I have repeated in two environments.
[27 Aug 2019 12:40]
shangshang yu
Hello, Sinisa, I just use 'date -s' to set system time. Could you repeat the issue? I have repeated in two environments.
[27 Aug 2019 12:42]
MySQL Verification Team
Hi, Please, re-read all that I wrote to you .... Also, MySQL server's timezone is set on the server itself. You can check it whether it is correct or not. This is all explained in our Reference Manual.
[28 Aug 2019 1:27]
shangshang yu
Hello, Sinisa, I have re-read all that you wrote to me, but can notanswer my question. Let's put the time zone aside, focus on the issue. My qustion is why can't I manually set the Linux system time when mysql is running? Reseting system time is a very common operation，if mysql do not support the feature, would cause a lot of trouble. Now I describe the issue more specific. Firstly, I start do some write operations. The current time is # date Wed Aug 28 09:00:37 CST 2019 [ 10s ] thds: 32 tps: 574.33 qps: 3453.95 (r/w/o: 0.00/2302.10/1151.85) lat (ms,95%): 110.66 err/s: 0.00 reconn/s: 0.00 [ 20s ] thds: 32 tps: 550.42 qps: 3303.71 (r/w/o: 0.00/2202.87/1100.84) lat (ms,95%): 123.28 err/s: 0.00 reconn/s: 0.00 [ 30s ] thds: 32 tps: 580.80 qps: 3481.78 (r/w/o: 0.00/2320.19/1161.59) lat (ms,95%): 102.97 err/s: 0.00 reconn/s: 0.00 [ 40s ] thds: 32 tps: 576.60 qps: 3464.00 (r/w/o: 0.00/2310.80/1153.20) lat (ms,95%): 130.13 err/s: 0.00 reconn/s: 0.00 [ 50s ] thds: 32 tps: 434.50 qps: 2603.78 (r/w/o: 0.00/1734.68/869.09) lat (ms,95%): 99.33 err/s: 0.10 reconn/s: 0.00 Secondly, I set the system time one hour slower, and write operations were blocked. # date -s "2019-08-28 08:00:00" Wed Aug 28 08:00:00 CST 2019 [ 60s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 70s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 80s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 [ 90s ] thds: 32 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00 Here I set system time use 'hwclock -s', let system time up to date, and write operations were resumed. # date Wed Aug 28 09:01:56 CST 2019 [ 100s ] thds: 32 tps: 517.50 qps: 3109.60 (r/w/o: 0.00/2074.30/1035.30) lat (ms,95%): 110.66 err/s: 0.30 reconn/s: 0.00 [ 110s ] thds: 32 tps: 595.80 qps: 3574.32 (r/w/o: 0.00/2382.62/1191.71) lat (ms,95%): 110.66 err/s: 0.10 reconn/s: 0.00 [ 120s ] thds: 32 tps: 553.70 qps: 3320.30 (r/w/o: 0.00/2212.90/1107.40) lat (ms,95%): 132.49 err/s: 0.00 reconn/s: 0.00 [ 130s ] thds: 32 tps: 622.98 qps: 3736.70 (r/w/o: 0.00/2490.83/1245.87) lat (ms,95%): 94.10 err/s: 0.00 reconn/s: 0.00 How can we explain this scenario？
[28 Aug 2019 11:45]
MySQL Verification Team
No, it is not supported. Stop the server, change the time and restart server ....
[29 Aug 2019 8:17]
shangshang yu
Hello, Sinisa ,
I think that I have found the reason.
the function log_wait_for_space_in_log_recent_closed is wait for space of log.recent_closed, that is, waiting for advancing log.recent_closed.m_tail.
log.recent_closed.m_tail is advanced by log_closer thread.
void log_wait_for_space_in_log_recent_closed(log_t &log, lsn_t lsn) {
...
while (!log.recent_closed.has_space(lsn)) {
++wait_loops;
os_thread_sleep(20);
}
...
}
However, the log_closer thread was blocked.
#0 0x00002b69298f0d12 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000001ec1be5 in os_event::timed_wait (this=this@entry=0x2b6940383b38, abstime=abstime@entry=0x2b6953f0fab0) at /root/software/mysql-8.0.16/storage/innobase/os/os0event.cc:287
#2 0x0000000001ec1e41 in os_event::wait_time_low (this=this@entry=0x2b6940383b38, time_in_usec=time_in_usec@entry=1000, reset_sig_count=reset_sig_count@entry=1) at /root/software/mysql-8.0.16/storage/innobase/os/os0event.cc:410
#3 0x0000000001ec1efa in os_event_wait_time_low (event=event@entry=0x2b6940383b38, time_in_usec=time_in_usec@entry=1000, reset_sig_count=reset_sig_count@entry=1) at /root/software/mysql-8.0.16/storage/innobase/os/os0event.cc:509
#4 0x0000000001eacd2c in os_event_wait_for<log_closer(log_t*)::<lambda(bool)> > (condition=..., timeout=1000, spins_limit=<optimized out>, event=<synthetic pointer>) at /root/software/mysql-8.0.16/storage/innobase/include/os0event.ic:119
#5 wait<log_closer(log_t*)::<lambda(bool)> > (stop_condition=..., this=<synthetic pointer>) at /root/software/mysql-8.0.16/storage/innobase/log/log0write.cc:1011
#6 log_closer (log_ptr=<optimized out>) at /root/software/mysql-8.0.16/storage/innobase/log/log0write.cc:2524
#7 0x0000000001e88658 in __call<void, 0ul> (__args=<optimized out>, this=<synthetic pointer>) at /root/dbs/taurus-root/src/tools/gcc-5.4/include/c++/5.4.0/functional:1074
#8 operator()<, void> (this=<synthetic pointer>) at /root/dbs/taurus-root/src/tools/gcc-5.4/include/c++/5.4.0/functional:1133
#9 operator()<void (*)(log_t*), log_t*> (f=<unknown type in /root/install/mysql-8016/bin/mysqld, CU 0xed88fbe, DIE 0xedc57ac>, this=0x2b69408afcd8) at /root/software/mysql-8.0.16/storage/innobase/include/os0thread-create.h:91
#10 _M_invoke<0ul, 1ul> (this=0x2b69408afcc8) at /root/dbs/taurus-root/src/tools/gcc-5.4/include/c++/5.4.0/functional:1531
#11 operator() (this=0x2b69408afcc8) at /root/dbs/taurus-root/src/tools/gcc-5.4/include/c++/5.4.0/functional:1520
#12 std::thread::_Impl<std::_Bind_simple<Runnable (void (*)(log_t*), log_t*)> >::_M_run() (this=0x2b69408afcb0) at /root/dbs/taurus-root/src/tools/gcc-5.4/include/c++/5.4.0/thread:115
#13 0x00002b692acdb8e0 in std::execute_native_thread_routine (__p=<optimized out>) at ../../../../../gcc-5.4.0/libstdc++-v3/src/c++11/thread.cc:84
#14 0x00002b69298ecdd5 in start_thread () from /lib64/libpthread.so.0
#15 0x00002b692b5b6ead in clone () from /lib64/libc.so.6
storage/innobase/os/os0event.cc:287 ret = pthread_cond_timedwait(&cond_var, mutex, abstime);
pthread_cond_timedwait will make thread blocked until reach the abstime.
the abstime depends on system time, which is assigned in function os_event::wait_time_low.
Suggested fix:
We can use a timer that does not depend on system time, for example:
clock_gettime(CLOCK_MONOTONIC, &abstime);
A monotonic time since system started
[29 Aug 2019 8:58]
shangshang yu
This issue looks like to the Bug #93708 https://bugs.mysql.com/bug.php?id=93708
[29 Aug 2019 13:03]
MySQL Verification Team
Hi Mr. yu, As I wrote before, we do not support (currently) changing system time during the running of our server. However, it might be possible to introduce the correction that you suggest, but only on Linux OS. Hence, I am verifying this report as a feature request. This verified feature request shall be forwarded to those who make decisions on such matters. Thank you for your suggestion ......
[13 Apr 2022 1:23]
peng gao
affect 8.0.18. any fixed for this？ thanks
[13 Apr 2022 13:15]
MySQL Verification Team
Hi, MySQL Verification Team is not included in any decisions on the scheduling of the bug fixes or feature requests, so we are unable to give you any feedback. Those decisions are made at the much higher level. You can do the same thing that we do. With every new release, read the Release Notes (on dev.mysql.com) and see if anything relevant was changed. Beside, this is a low priority task, since the workaround is so simple and easy ......
[14 Apr 2022 7:23]
peng gao
Hi:
but i find 8.0.16..8.0.17 add funcition
+#ifndef _WIN32
+
+struct timespec os_event::get_wait_timelimit(ulint time_in_usec) {
+ /* We could get rid of this function if we switched to std::condition_variable
+ from the pthread_cond_. The std::condition_variable::wait_for relies on the
+ steady_clock internally and accepts timeout (not time increased by the
+ timeout). */
+ for (int i = 0;; i++) {
+ ut_a(i < 10);
+#ifdef HAVE_CLOCK_GETTIME
+ if (cond_attr_has_monotonic_clock) {
+ struct timespec tp;
+ if (clock_gettime(CLOCK_MONOTONIC, &tp) == -1) {
+ const auto errno_clock_gettime = errno;
+
os_event::wait_time_low abstime use CLOCK_MONOTONIC,but my version is 8.0.18,i don't kown thy log_closer is hang.
like this :
first monitor in errlog
Log written up to 20600471237
Log flushed up to 20600471237
Added dirty pages up to 20598368792
Pages flushed up to 20598368792
.....
last monitor in errlog
Log written up to 20600471237
Log flushed up to 20600471237
Added dirty pages up to 20598368792
Pages flushed up to 20598368792
then Semaphore page rw lock wait has lasted > 600 seconds and server restart. "Added dirty pages up to" is not change.
log_closer is not advance log.recent_closed.m_tail.
or nanosleep problem result log.recent_closed.m_tail have no info to advance。
I find 8.0.22 log_closer thread is remove.
Can i upgrade to 8.0.28 to solve this issue?
[14 Apr 2022 13:00]
MySQL Verification Team
Hi, Of course that you can upgrade to 8.0.28. Just make sure that datadir points to your current datadir and wait that 8.0.28 does its full upgrade process. After it is finished, you see how it works. If your problem is gone, let us know and we shall close this feature request.
[15 Apr 2022 1:33]
peng gao
thanks，i will feedback.
[15 Apr 2022 7:45]
peng gao
Hi: pstack result, log_closer can't broadcast by user theads。i don't kown why like： log_closer: Thread 37 (Thread 0x7eff64660700 (LWP 25714)): #0 0x00007f01c42014ed in __lll_lock_wait () from /lib64/libpthread.so.0 #1 0x00007f01c4203cdc in _L_cond_lock_847 () from /lib64/libpthread.so.0 #2 0x00007f01c4203b71 in __pthread_mutex_cond_lock () from /lib64/libpthread.so.0 #3 0x00007f01c41fede4 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #4 0x00000000020640b5 in os_event::timed_wait(timespec const*) () at ../../../mysql-8.0.18/storage/innobase/include/sync0types.h:541 #5 0x0000000002064c71 in os_event::wait_time_low (this=0x7f01a83797e8, time_in_usec=<optimized out>, reset_sig_count=12200193) at ../../../mysql-8.0.18/storage/innobase/os/os0event.cc:495 #6 0x000000000204bca9 in os_event_wait_for<log_closer(log_t*)::<lambda(bool)> > (condition=..., timeout=100000, spins_limit=<optimized out>, event=<synthetic pointer>) at ../../../mysql-8.0.18/storage/innobase/log/log0write.cc:2535 #7 wait<log_closer(log_t*)::<lambda(bool)> > (stop_condition=..., this=<synthetic pointer>) at ../../../mysql-8.0.18/storage/innobase/log/log0write.cc:1004 #8 log_closer (log_ptr=<optimized out>) at ../../../mysql-8.0.18/storage/innobase/log/log0write.cc:2540 some user thread: Thread 20 (Thread 0x7eff5bfff700 (LWP 25738)): #0 0x00007f01c41ff11e in pthread_cond_broadcast@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000002063e11 in broadcast (this=0x7f01a83797e8) at ../../../mysql-8.0.18/storage/innobase/os/os0event.cc:207 #2 set (this=0x7f01a83797e8) at ../../../mysql-8.0.18/storage/innobase/os/os0event.cc:92 #3 os_event_set (event=0x7f01a83797e8) at ../../../mysql-8.0.18/storage/innobase/os/os0event.cc:564 #4 0x00000000020153a7 in log_wait_for_space_in_log_recent_closed (log=..., lsn=20980968944) at ../../../mysql-8.0.18/storage/innobase/log/log0buf.cc:926 #5 0x0000000002054e12 in mtr_t::Command::execute (this=this@entry=0x7eff5bffa560) at ../../../mysql-8.0.18/storage/innobase/mtr/mtr0mtr.cc:651
[15 Apr 2022 8:56]
peng gao
this is bug? 8.0.22 commit
commit 9bfe6028224b6125c7e9104b7e91734e9b030952
Author: Yasufumi Kinoshita <yasufumi.kinoshita@oracle.com>
Date: Mon Apr 6 11:52:36 2020 +0900
Bug#30088404 : CONCURRENT LOG BUFFER OF 8.0 CAUSES REGRESSION OF CPU BOUND PERFORMANCE ON LOW-END ARCHITECTURE
- improved ut0link_buf.h and log_closer_thread was removed because not needed
- add variable to choose former style log_write_up_to for low-end servers cpu% bound
innodb_log_writer_threads=[ON|OFF]
- optimized checkpoint and sync_flush behavior
RB: 23457
Reviewed-by: Pawel Olchawa <pawel.olchawa@oracle.com>
remove log_closer, this issue can solve? thanks very much!!
[15 Apr 2022 9:24]
peng gao
this is like deadlock. i don't down why....
[15 Apr 2022 9:25]
peng gao
this is like deadlock. i don't kown why....
[15 Apr 2022 12:20]
MySQL Verification Team
Thank you Mr. yu, However, the problem is still with your time setting. You have set a time in the past, so these are expected consequences. It would require a thorough reorganisation of the code to handle these situations, which is why we do not recommend any changes in the time, other then those performed by the OS itself, due to summer / winter clock corrections.
[16 Apr 2022 2:39]
peng gao
crash stack
Attachment: pt-pmp.result (application/octet-stream, text), 14.46 KiB.
[16 Apr 2022 2:40]
peng gao
Hi 1、we not set time manual ,but use ntpdate command to sync clock every n sec. this version is 8.0.18 os_event::wait_time_low abstime use CLOCK_MONOTONIC 2、only one user thread broadcast and log closer thread can't get mutex to wake up,event is log.closer_event, #0 0x00007f01c42014ed in __lll_lock_wait () from /lib64/libpthread.so.0 #1 0x00007f01c4203cdc in _L_cond_lock_847 () from /lib64/libpthread.so.0 #2 0x00007f01c4203b71 in __pthread_mutex_cond_lock () from /lib64/libpthread.so.0 #3 0x00007f01c41fede4 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 pt-pmp result in attachment ,not kown why. 3、we will upgrade to 8.0.28，because frequently crash,each crash is log is log closer thread hang ,log closer is now remove. 4、Mr.gao . this is new issue in 8.0.18 crash , but like this issue. thanks.
[27 Apr 2022 12:59]
MySQL Verification Team
Hi Mr. yu, This is now a verified feature request. It is not considered a bug, so you have to wait until a decision is made on whether to implement it or not. Meanwhile, you can change system time only when the server is not running and even then by very small amounts. Setting time in the past is extremely dangerous and we do not support those changes. Our server is designed to handle day saving times, but not malfunctioning hardware or OS or administrative interventions with time, especially in the past.
