Uploaded image for project: 'Percona Server'
  1. Percona Server
  2. PS-5221

Page Cleaner will sleep for long time if clock changes

    Details

    • Type: Bug
    • Status: Done
    • Priority: Medium
    • Resolution: Fixed
    • Affects Version/s: 8.0, 5.7.24-26, 5.6.43-84.3
    • Fix Version/s: 8.0.15-5, 5.6.44-85.0, 5.7.26-29
    • Component/s: None
    • Labels:

      Description

      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

       

        Smart Checklist

          Attachments

            Activity

              People

              • Assignee:
                george.lorch George Lorch
                Reporter:
                marcelo.altmann Marcelo Altmann
              • Votes:
                1 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - Not Specified
                  Not Specified
                  Logged:
                  Time Spent - 3 days, 5 hours, 34 minutes
                  3d 5h 34m