WL#12924: Disk data improvements

WL#8069: Ensure that the first LCP executes well after a long idle period
BUG#30276755: sync_lsn can wait forever

Reviewed-by: Mauritz Sundell <mauritz.sundell@oracle.com>

1) Add 3 ndbinfo tables:
  pgman_time_track_stats
    This table tracks latencies to perform get_page and read and write latencies
    of PGMAN disk accesses
  diskstat
    This table reports disk statistics when accessing PGMAN pages, it reports
    statistics for the last second
  diskstat_history
    Same as diskstat, but reports stats for last 20 seconds, one row per second

2) Add new configuration variable MaxDiskDataLatency
  Track mean latency of file operations, make it possible to set a maximum
  disk data latency that is acceptable in new config variable:
  MaxDiskDataLatency.
  If we pass this we will abort 20% of all disk accesses and if we pass
  2 times this value we will abort 2 out of 5 and so forth if it is
  X times this value we will abort X out of X + 1 disk access requests.
  If it passes 5 times this delay all disk accesses will be aborted.

  By default this configuration is 0 which means that we will not check
  for any maximum disk data latency.

  Add new configuration variable DiskDataUsingSameDisk.
  By default this is set to true. This means that we will by default try to
  balance the load from writing disk data checkpointing with the load created
  by writing in-memory checkpoints. If this configuration is set to 0 we
  will calculate the disk checkpoint speed independent of writes to
  in-memory checkpoints.

3) Fixed a bug in sync_lsn that caused log_waits to wait
   forever in some situations (BUG#30276755).

4) Report m_max_sync_req_lsn in DUMP command

5) Report duration of NDBFS requests in microseconds rather than millis
   in DUMP command

6) Improved latency of get_page requests in a number of different ways,
   particularly when WAL rule had to be applied

7) Started preparations to handle adaptive checkpoint speed also
   in PGMAN.
   - Keep track of number of dirty pages to assess current visible
     need for checkpointing
   - Keep track of number of pageouts in last LCP to give an estimate
     of normal checkpoint speed.
   - Provide information of how much time disk data uses compared to
     in memory pages.
   - Provide information of time it took with last LCP
8)
  First step to make it possible to perform LCP writes even when not requested
  to do so yet. The idea is the following.

  The next fragment to perform an LCP is the next in table id order and fragment
  order. Thus we can find the next fragment that will execute an LCP. By starting
  to write the pages in this fragment we are likely to make it much faster to run
  the LCP ones the request to perform the LCP in PGMAN arrives.

  We will at most write four fragments ahead of the current fragment being
  checkpointed. This is to strike a balance between staying ahead to get smooth
  checkpoint speed and avoiding to write too much that later is written again
  when writing the current checkpoint fragment.

9) Needed to track number of outstanding prepare LCP writes

10) Made it possible to run checkpointing also in normal operation
    during times when no disk data checkpoint has been requested.
    Calculates both IO parallelism and IO rate once every 100
    milliseconds. This in order to attempt to even out the IO
    load during checkpoints. Modern NVMe drives can write millions
    of IO operations per second, so it is very easy to overwhelm
    the disk drives with checkpoint flushes that makes it hard to
    perform normal disk IO for user operations. So we try to keep
    track of how fast we need to write disk data checkpoints and
    in-memory checkpoints to ensure an even IO load. It is also
    important to find a good balance between disk data checkpointing
    and in-memory checkpointing.

11) We invoked a lot of extra latency by putting the dirty pages first
    in dirty list. This led to writes of the most recently dirtied
    pages coming first. This led to a lot of unnecessary invocations
    of the WAL rule.

    Fixed this by inserting it last in list. In addition every time
    the page was made dirty (even when already dirty), we put the
    page last in its current dirty list to ensure that we minimise
    the risk of having to apply the WAL rule during LCP execution.

    In addition we ensured that we never attempted to write any
    pages that needed application of the WAL rule or that was ready
    to send a callback on a get page during prepare LCP phase.
    The prepare phase will mostly have enough work to do anyways.

    Finally we attempt to avoid writing pages in SL_CALLBACK list
    during LCP execution. We have to apply rules however to ensure
    that we make progress by not applying this rule for last
    page in dirty list. Also we don't apply the rule more than 32
    times to avoid breaking any rules for real-time execution.
    Finally we don't allow skipping two pages after each other that
    are in SL_CALLBACK list since that would put us at risk of
    looping on those two pages. We only move the page one step
    forward when skipping it to avoid giving it to high priority
    to skip the page.

12) The TSMAN had a major bottleneck in that it was protected by one single
    mutex. We held this mutex for quite some time during inserts and we also
    held it for some time preparing to page out and after completed page out
    and in a few more places. This is a serious bottleneck for disk data.

    The solution is to break up the protection in a few steps.
    The first step is that the Tablespace_client only takes a lock on one
    instance, its own instance. This means those Tablespace_client will
    not have problems with each other. When TSMAN needs to manipulate any
    data structures used by any Tablespace_client one can lock all
    instances. This is a rare operation only occurring when manipulating
    a tablespace to add more files, add a tablespace or when dropping a
    tablespace.

    Allocation and freeing extents requires a bit more protection given
    that we're working on a free list. Thus we use a allocate extent lock
    to protect these operations in addition to the instance lock.

    Finally to ensure that the instances don't bounce into each other we
    need to protect extent pages. We keep a fixed amount of mutexes per
    tablespace data file to protect these extent pages accesses from
    each other. We use a very simple hash function to decide which mutex
    to use for a specific extent page.

13) The extra PGMAN worker works differently in how LCPs are discovered
    to be started and ended. We need code to handle this as well in PGMAN.

14) Ensure that SYNC_EXTENT_PAGES_REQ is sent with FIRST_LCP also when no
    disk data tables present.

15) Handle case with completely empty LCP

16) Added more jam's around BUSY state in PGMAN
    Added rules to try to keep LCP speed down such that we at least
    take 10 seconds to run an LCP.

17) Fixed bug with respect to variable m_lcp_ongoing that wasn't properly handled for
    flushing of page cache for restarts.
    Reorganised debug printouts a bit and standardised on printing instance number in
    parenthesis at start of printout.

18) Need to avoid setting BUSY that would require lists to change for extent pages

19) Minor adaptions to decrease aggressiveness in writing LCPs for disk data

20) More fine-tuning of adaptive control parameters

21) Occasionally when running testRedo -n CheckLCPStartsAfterSR we
    move the REDO log so fast that we haven't finished opening the
    next file when starting to write into this next file. In this
    test case the REDO log size is set to 16 * 16 MB. I change to
    using 4 * 64 MB instead to minimise this risk.

22) Avoid trying to lock client locks when already holding those
    before calling execFSCLOSECONF.

23) New error code 1518 for overload when going beyond MaxDiskDataLatency

24) Slowed down the speed a bit more to increase lengths of LCPs in normal
    operation.

The aim of this worklog is to ensure that we balance the disk write rate for the
actual required disk write rate. This makes it possible to have very heavy write
rates also on disk data columns in NDB, particularly when using modern NVMe drives.
It has been tested heavily for large rows with YCSB on modern NVMe drives supporting
millions of IOPS and also tested on older SSD drives supporting at most 20.000 IOPS.
The worklog also adds ndbinfo tables to track the usage a bit more and debugging info
to track any problems in the new code. The worklog integrates the Adaptive Redo Control
algorithm for in-memory data with the checkpoint algorithm for disk data columns.

Author: Mikael Ronström

mysql-test/suite/ndb/r/ndbinfo.result

@@ -84,9 +84,12 @@ table_id	table_name	comment
 37	stored_tables	Information about stored tables
 38	processes	Process ID and Name information for connected nodes
 39	config_nodes	All nodes of current cluster configuration
+40	pgman_time_track_stats	Time tracking of reads and writes of disk data pages
+41	diskstat	Disk data statistics for last second
+42	diskstats_1sec	Disk data statistics history for last few seconds
 SELECT COUNT(*) FROM ndb$tables;
 COUNT(*)
-40
+43
 SELECT * FROM ndb$tables WHERE table_id = 2;
 table_id	table_name	comment
 2	test	for testing
@@ -126,6 +129,9 @@ table_id	table_name	comment
 37	stored_tables	Information about stored tables
 38	processes	Process ID and Name information for connected nodes
 39	config_nodes	All nodes of current cluster configuration
+40	pgman_time_track_stats	Time tracking of reads and writes of disk data pages
+41	diskstat	Disk data statistics for last second
+42	diskstats_1sec	Disk data statistics history for last few seconds
 SELECT * FROM ndb$tables WHERE table_name = 'LOGDESTINATION';
 table_id	table_name	comment
 SELECT COUNT(*) FROM ndb$tables t, ndb$columns c
@@ -156,6 +162,8 @@ table_id	table_name
 25	cpustat_50ms
 16	dict_obj_info
 10	diskpagebuffer
+41	diskstat
+42	diskstats_1sec
 19	disk_write_speed_aggregate
 18	disk_write_speed_base
 29	frag_locks
@@ -166,6 +174,7 @@ table_id	table_name
 15	membership
 9	nodes
 14	operations
+40	pgman_time_track_stats
 3	pools
 38	processes
 7	resources
@@ -260,6 +269,9 @@ table_id
 37
 38
 39
+40
+41
+42
 
 TRUNCATE ndb$tables;
 ERROR HY000: Table 'ndb$tables' is read only

scripts/mysql_system_tables.sql

@@ -690,6 +690,16 @@ PREPARE stmt FROM @str;
 EXECUTE stmt;
 DROP PREPARE stmt;
 
+SET @str=IF(@have_ndbinfo,'DROP VIEW IF EXISTS `ndbinfo`.`diskstat`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
+SET @str=IF(@have_ndbinfo,'DROP VIEW IF EXISTS `ndbinfo`.`diskstats_1sec`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
 SET @str=IF(@have_ndbinfo,'DROP VIEW IF EXISTS `ndbinfo`.`error_messages`','SET @dummy = 0');
 PREPARE stmt FROM @str;
 EXECUTE stmt;
@@ -735,6 +745,11 @@ PREPARE stmt FROM @str;
 EXECUTE stmt;
 DROP PREPARE stmt;
 
+SET @str=IF(@have_ndbinfo,'DROP VIEW IF EXISTS `ndbinfo`.`pgman_time_track_stats`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
 SET @str=IF(@have_ndbinfo,'DROP VIEW IF EXISTS `ndbinfo`.`processes`','SET @dummy = 0');
 PREPARE stmt FROM @str;
 EXECUTE stmt;
@@ -985,6 +1000,28 @@ PREPARE stmt FROM @str;
 EXECUTE stmt;
 DROP PREPARE stmt;
 
+# ndbinfo.ndb$diskstat
+SET @str=IF(@have_ndbinfo,'DROP TABLE IF EXISTS `ndbinfo`.`ndb$diskstat`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
+SET @str=IF(@have_ndbinfo,'CREATE TABLE `ndbinfo`.`ndb$diskstat` (`node_id` INT UNSIGNED COMMENT "node_id",`block_instance` INT UNSIGNED COMMENT "Block instance",`pages_made_dirty` INT UNSIGNED COMMENT "Pages made dirty last second",`reads_issued` INT UNSIGNED COMMENT "Reads issued last second",`reads_completed` INT UNSIGNED COMMENT "Reads completed last second",`writes_issued` INT UNSIGNED COMMENT "Writes issued last second",`writes_completed` INT UNSIGNED COMMENT "Writes completed last second",`log_writes_issued` INT UNSIGNED COMMENT "Log writes issued last second",`log_writes_completed` INT UNSIGNED COMMENT "Log writes completed last second",`get_page_calls_issued` INT UNSIGNED COMMENT "get_page calls issued last second",`get_page_reqs_issued` INT UNSIGNED COMMENT "get_page calls that triggered disk IO issued last second",`get_page_reqs_completed` INT UNSIGNED COMMENT "get_page calls that triggered disk IO completed last second") COMMENT="Disk data statistics for last second" ENGINE=NDBINFO CHARACTER SET latin1','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
+# ndbinfo.ndb$diskstats_1sec
+SET @str=IF(@have_ndbinfo,'DROP TABLE IF EXISTS `ndbinfo`.`ndb$diskstats_1sec`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
+SET @str=IF(@have_ndbinfo,'CREATE TABLE `ndbinfo`.`ndb$diskstats_1sec` (`node_id` INT UNSIGNED COMMENT "node_id",`block_instance` INT UNSIGNED COMMENT "Block instance",`pages_made_dirty` INT UNSIGNED COMMENT "Pages made dirty per second",`reads_issued` INT UNSIGNED COMMENT "Reads issued per second",`reads_completed` INT UNSIGNED COMMENT "Reads completed per second",`writes_issued` INT UNSIGNED COMMENT "Writes issued per second",`writes_completed` INT UNSIGNED COMMENT "Writes completed per second",`log_writes_issued` INT UNSIGNED COMMENT "Log writes issued per second",`log_writes_completed` INT UNSIGNED COMMENT "Log writes completed per second",`get_page_calls_issued` INT UNSIGNED COMMENT "get_page calls issued per second",`get_page_reqs_issued` INT UNSIGNED COMMENT "get_page calls that triggered disk IO issued per second",`get_page_reqs_completed` INT UNSIGNED COMMENT "get_page calls that triggered disk IO completed per second",`seconds_ago` INT UNSIGNED COMMENT "Seconds ago that this measurement was made") COMMENT="Disk data statistics history for last few seconds" ENGINE=NDBINFO CHARACTER SET latin1','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
 # ndbinfo.ndb$frag_locks
 SET @str=IF(@have_ndbinfo,'DROP TABLE IF EXISTS `ndbinfo`.`ndb$frag_locks`','SET @dummy = 0');
 PREPARE stmt FROM @str;
@@ -1073,6 +1110,17 @@ PREPARE stmt FROM @str;
 EXECUTE stmt;
 DROP PREPARE stmt;
 
+# ndbinfo.ndb$pgman_time_track_stats
+SET @str=IF(@have_ndbinfo,'DROP TABLE IF EXISTS `ndbinfo`.`ndb$pgman_time_track_stats`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
+SET @str=IF(@have_ndbinfo,'CREATE TABLE `ndbinfo`.`ndb$pgman_time_track_stats` (`node_id` INT UNSIGNED COMMENT "node_id",`block_number` INT UNSIGNED COMMENT "Block number",`block_instance` INT UNSIGNED COMMENT "Block instance",`upper_bound` INT UNSIGNED COMMENT "Upper bound in microseconds",`page_reads` BIGINT UNSIGNED COMMENT "Number of disk reads in this range",`page_writes` BIGINT UNSIGNED COMMENT "Number of disk writes in this range",`log_waits` BIGINT UNSIGNED COMMENT "Number of waits due to WAL rule in this range (log waits)",`get_page` BIGINT UNSIGNED COMMENT "Number of waits for get_page in this range") COMMENT="Time tracking of reads and writes of disk data pages" ENGINE=NDBINFO CHARACTER SET latin1','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
 # ndbinfo.ndb$pools
 SET @str=IF(@have_ndbinfo,'DROP TABLE IF EXISTS `ndbinfo`.`ndb$pools`','SET @dummy = 0');
 PREPARE stmt FROM @str;
@@ -1470,6 +1518,18 @@ PREPARE stmt FROM @str;
 EXECUTE stmt;
 DROP PREPARE stmt;
 
+# ndbinfo.diskstat
+SET @str=IF(@have_ndbinfo,'CREATE OR REPLACE DEFINER=`root`@`localhost` SQL SECURITY INVOKER VIEW `ndbinfo`.`diskstat` AS SELECT * FROM `ndbinfo`.`ndb$diskstat`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
+# ndbinfo.diskstats_1sec
+SET @str=IF(@have_ndbinfo,'CREATE OR REPLACE DEFINER=`root`@`localhost` SQL SECURITY INVOKER VIEW `ndbinfo`.`diskstats_1sec` AS SELECT * FROM `ndbinfo`.`ndb$diskstats_1sec`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
 # ndbinfo.error_messages
 SET @str=IF(@have_ndbinfo,'CREATE OR REPLACE DEFINER=`root`@`localhost` SQL SECURITY INVOKER VIEW `ndbinfo`.`error_messages` AS SELECT error_code, error_description, error_status, error_classification FROM `ndbinfo`.`ndb$error_messages`','SET @dummy = 0');
 PREPARE stmt FROM @str;
@@ -1524,6 +1584,12 @@ PREPARE stmt FROM @str;
 EXECUTE stmt;
 DROP PREPARE stmt;
 
+# ndbinfo.pgman_time_track_stats
+SET @str=IF(@have_ndbinfo,'CREATE OR REPLACE DEFINER=`root`@`localhost` SQL SECURITY INVOKER VIEW `ndbinfo`.`pgman_time_track_stats` AS SELECT * FROM `ndbinfo`.`ndb$pgman_time_track_stats`','SET @dummy = 0');
+PREPARE stmt FROM @str;
+EXECUTE stmt;
+DROP PREPARE stmt;
+
 # ndbinfo.processes
 SET @str=IF(@have_ndbinfo,'CREATE OR REPLACE DEFINER=`root`@`localhost` SQL SECURITY INVOKER VIEW `ndbinfo`.`processes` AS SELECT DISTINCT node_id, CASE node_type  WHEN 0 THEN "NDB"  WHEN 1 THEN "API"  WHEN 2 THEN "MGM"  ELSE NULL  END AS node_type,  node_version,  NULLIF(process_id, 0) AS process_id,  NULLIF(angel_process_id, 0) AS angel_process_id,  process_name, service_URI FROM `ndbinfo`.`ndb$processes` ORDER BY node_id','SET @dummy = 0');
 PREPARE stmt FROM @str;

storage/ndb/include/kernel/signaldata/LCP.hpp

@@ -256,8 +256,9 @@ struct SyncExtentPagesReq
   enum LcpOrder
   {
     FIRST_LCP = 0,
-    INTERMEDIATE_LCP = 1,
-    END_LCP = 2
+    END_LCP = 1,
+    RESTART_SYNC = 2,
+    FIRST_AND_END_LCP = 3
   };
   Uint32 senderData;
   Uint32 senderRef;

storage/ndb/include/kernel/signaldata/NextScan.hpp

@@ -1,5 +1,5 @@
 /*
-   Copyright (c) 2003, 2017, Oracle and/or its affiliates. All rights reserved.
+   Copyright (c) 2003, 2019, Oracle and/or its affiliates. All rights reserved.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License, version 2.0,
@@ -71,6 +71,7 @@ class NextScanConf {
 
 class NextScanRef {
   friend class Dbtux;
+  friend class Dbtup;
   friend class Dblqh;
 public:
   STATIC_CONST( SignalLength = 4 );

storage/ndb/include/kernel/signaldata/PgmanContinueB.hpp

@@ -1,5 +1,5 @@
 /*
-   Copyright (c) 2005, 2017, Oracle and/or its affiliates. All rights reserved.
+   Copyright (c) 2005, 2019, Oracle and/or its affiliates. All rights reserved.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License, version 2.0,
@@ -40,7 +40,9 @@ class PgmanContinueB {
     STATS_LOOP = 0,
     BUSY_LOOP = 1,
     CLEANUP_LOOP = 2,
-    LCP_LOOP = 3
+    LCP_LOOP = 3,
+    CALC_STATS_LOOP = 4,
+    TRACK_LCP_SPEED_LOOP = 5
   };
 };
 

storage/ndb/include/mgmapi/mgmapi_config_parameters.h

@@ -249,6 +249,8 @@
 #define CFG_DB_RESERVED_TRANS_BUFFER_MEM 666
 
 #define CFG_DB_TRANSACTION_MEM        667
+#define CFG_DB_MAX_DD_LATENCY         668
+#define CFG_DB_DD_USING_SAME_DISK     669
 
 #define CFG_NODE_ARBIT_RANK           200
 #define CFG_NODE_ARBIT_DELAY          201

storage/ndb/src/common/debugger/signaldata/IsolateOrd.cpp

@@ -50,7 +50,7 @@ printISOLATE_ORD(FILE * output, const Uint32 * theData, Uint32 len, Uint16 recei
   }
   else
   {
-    fprintf(output, " nodesToIsolate in signal section");
+    fprintf(output, " nodesToIsolate in signal section\n");
   }
   return true;
 }

storage/ndb/src/kernel/blocks/PgmanProxy.cpp

@@ -177,6 +177,20 @@ PgmanProxy::sendEND_LCPCONF(Signal* signal, Uint32 ssId)
  * thread is used.  These are extent pages.
  */
 
+void
+PgmanProxy::get_extent_page(Page_cache_client& caller,
+                            Signal* signal,
+                            Page_cache_client::Request& req,
+                            Uint32 flags)
+{
+  ndbrequire(blockToInstance(caller.m_block) == 0);
+  SimulatedBlock* block = globalData.getBlock(caller.m_block);
+  Pgman* worker = (Pgman*)workerBlock(c_workers - 1); // extraWorkerBlock();
+  Page_cache_client pgman(block, worker);
+  pgman.get_extent_page(signal, req, flags);
+  caller.m_ptr = pgman.m_ptr;
+}
+
 int
 PgmanProxy::get_page(Page_cache_client& caller,
                      Signal* signal,

storage/ndb/src/kernel/blocks/PgmanProxy.hpp

@@ -84,6 +84,11 @@ class PgmanProxy : public LocalProxy {
   int get_page(Page_cache_client& caller,
                Signal*, Page_cache_client::Request& req, Uint32 flags);
 
+  void get_extent_page(Page_cache_client& caller,
+                       Signal*,
+                       Page_cache_client::Request& req,
+                       Uint32 flags);
+
   void update_lsn(Signal *signal,
                   Page_cache_client& caller,
                   Local_key key, Uint64 lsn);