-
Type:
Bug
-
Status: Done
-
Priority:
Medium
-
Resolution: Fixed
-
Affects Version/s: 5.7.24-26, 5.6.43-84.3, 8.0.x
-
Fix Version/s: 8.0.15-5, 5.6.44-85.0, 5.7.26-29
-
Component/s: None
-
Labels:
-
Upstream Bug URL:
Page cleaner will sleep for a long time in case you adjust your clock backward, for example, if ntp adjusts the clock or when you exit summer time.
Error log:
2018-12-20T15:26:28.981196Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2018-12-20T15:26:28.981951Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 181220 15:26:28
2018-12-20T15:26:29.181297Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:27:29.412452Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:28:29.636237Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:29:31.497178Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:30:34.856757Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:31:38.337117Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:32:41.654854Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:33:45.085653Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:34:48.594154Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:35:52.294568Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:36:55.932855Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:37:59.590748Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:39:03.387422Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:40:07.109075Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:41:10.742600Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:42:14.363348Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:43:18.191026Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:44:21.817929Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-20T15:45:25.487459Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
Thread stack:
[Switching to thread 3 (Thread 0x7f1dd2897700 (LWP 3570))]
#0 0x00007f1decbb8d42 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) bt
#0 0x00007f1decbb8d42 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000fce162 in os_event::timed_wait (this=this@entry=0x393e528, abstime=abstime@entry=0x7f1dd2896b70) at /export/home/pb2/build/sb_0-30854123-1538633024.42/rpm/BUILD/mysql-5.7.24/mysql-5.7.24/storage/innobase/os/os0event.cc:285
#2 0x0000000000fce391 in os_event::wait_time_low (this=0x393e528, time_in_usec=<optimized out>, reset_sig_count=<optimized out>, reset_sig_count@entry=2)
at /export/home/pb2/build/sb_0-30854123-1538633024.42/rpm/BUILD/mysql-5.7.24/mysql-5.7.24/storage/innobase/os/os0event.cc:412
#3 0x0000000000fce5fa in os_event_wait_time_low (event=<optimized out>, time_in_usec=<optimized out>, reset_sig_count=reset_sig_count@entry=2) at /export/home/pb2/build/sb_0-30854123-1538633024.42/rpm/BUILD/mysql-5.7.24/mysql-5.7.24/storage/innobase/os/os0event.cc:517
#4 0x000000000113b19f in pc_sleep_if_needed (sig_count=2, next_loop_time=1545320288739) at /export/home/pb2/build/sb_0-30854123-1538633024.42/rpm/BUILD/mysql-5.7.24/mysql-5.7.24/storage/innobase/buf/buf0flu.cc:2690
#5 buf_flush_page_cleaner_coordinator (arg=<optimized out>) at /export/home/pb2/build/sb_0-30854123-1538633024.42/rpm/BUILD/mysql-5.7.24/mysql-5.7.24/storage/innobase/buf/buf0flu.cc:3191
#6 0x00007f1decbb4e25 in start_thread () from /lib64/libpthread.so.0
#7 0x00007f1deb66ebad in clone () from /lib64/libc.so.6
Looks like os_event_wait_time_low->os_event::wait_time_low->ut_gettimeofday is returning previous saved time (in the future).
This affects page cleaner in general, as it won't flush any pages while coordinator is in os_event::timed_wait->pthread_cond_timedwait()
When talking about os_event_wait_time_low, looks like there are other 10 places where it can be potentially affected by the same issue:
1 buf0flu.cc pc_sleep_if_needed 2689 return(os_event_wait_time_low(buf_flush_event,
2 os0event.h os_event_wait_time 133 #define os_event_wait_time(e, t) os_event_wait_time_low((e), (t), 0)
3 lock0wait.cc DECLARE_THREAD 501 os_event_wait_time_low(event, 1000000, sig_count);
4 os0event.cc os_event_wait_time_low 507 os_event_wait_time_low(
5 row0merge.cc row_merge_read_clustered_index 2574 os_event_wait_time_low(fts_parallel_sort_event,
6 row0merge.cc row_merge_build_indexes 4473 os_event_wait_time_low(
7 srv0srv.cc DECLARE_THREAD 1585 os_event_wait_time_low(srv_monitor_event, 5000000, sig_count);
8 srv0srv.cc DECLARE_THREAD 1751 os_event_wait_time_low(srv_error_event, 1000000, sig_count);
9 srv0srv.cc srv_purge_coordinator_suspend 2679 ret = os_event_wait_time_low(
a ut0wqueue.cc ib_wqueue_timedwait 158 error = os_event_wait_time_low(wq->event,
How to repeat:
1. Start MySQL
2. Change time: date $(date +%m%d%H%M%Y.%S -d '50 min ago')
3. Stop MySQL