List:Commits« Previous MessageNext Message »
From:Frazer Clement Date:September 13 2012 8:49pm
Subject:bzr push into mysql-5.1-telco-6.3 branch (frazer.clement:3483 to 3484)
Bug#14472648
View as plain text  
 3484 Frazer Clement	2012-09-13
      Bug #14472648 	CONFIGURED DISKCHECKPOINTSPEED EXCEEDED WHEN BACKUPMAXWRITESIZE SET TO HIGH VALU
      
      The DiskCheckpointSpeed mechanism is implemented using 100 millisecond
      periods, which each have 1/10th of the configured quota available.
      
      A period is allowed to overflow its quota, with the excess being taken 
      from the next period's quota.
      
      However, this overflow was limited to the next period, after that, any
      further overflow was ignored.
      
      In cases where large overflows were possible, relative to the 1/10 
      DiskCheckPointSpeed quota, this could result in excessive disk writing,
      and CPU overhead as a result.
      
      Setting a larger-than standard MaxBackupWriteSize is the primary means
      of causing larger-than 2* quota overflows and triggering this bug.
      
      This bug is fixed by using as many subsequent periods as necessary to
      'pay off' the quota overflow.
      
      This will result in the data node staying within its quota.
      
      This fix may result in slower LCP in some systems, and reduced CPU usage
      during LCP.
      
      A testcase, and an internal DiskCheckPointSpeed verification mechanism
      are added to avoid future regressions.

    added:
      mysql-test/suite/ndb/r/ndb_backup_rate.result
      mysql-test/suite/ndb/t/ndb_backup_rate.cnf
      mysql-test/suite/ndb/t/ndb_backup_rate.test
    modified:
      storage/ndb/src/kernel/blocks/backup/Backup.cpp
      storage/ndb/src/kernel/blocks/backup/Backup.hpp
 3483 Frazer Clement	2012-09-12
      Bug #14386849 	SCAN RESOURCE LEAK WHEN TC KEYINFO DATA BUFFERS EXHAUSTED
      
      This patch fixes the scan resources leak when TC KeyInfo data buffers are exhausted.
      
      A testcase is added - one which causes a real leak, another which simulates it.
      
      Two new dump commands are added, to give visibility of the pool levels in TC and LQH.

    modified:
      storage/ndb/include/kernel/signaldata/DumpStateOrd.hpp
      storage/ndb/src/kernel/blocks/dblqh/DblqhMain.cpp
      storage/ndb/src/kernel/blocks/dbtc/Dbtc.hpp
      storage/ndb/src/kernel/blocks/dbtc/DbtcMain.cpp
      storage/ndb/src/ndbapi/ndberror.c
      storage/ndb/test/ndbapi/testScan.cpp
      storage/ndb/test/run-test/daily-basic-tests.txt
=== added file 'mysql-test/suite/ndb/r/ndb_backup_rate.result'
--- a/mysql-test/suite/ndb/r/ndb_backup_rate.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb/r/ndb_backup_rate.result	2012-09-13 20:18:47 +0000
@@ -0,0 +1,23 @@
+use test;
+create table t1 (a varchar(1024)) engine=ndb max_rows=100000000;
+insert into t1 values (repeat('I', 1024));
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1 limit 8192;
+insert into t1 select * from t1 limit 8192;
+insert into t1 select * from t1 limit 8192;
+Continuing insert/delete until redo is full
+Redo log full, waiting for redo log having space...
+Redo had space again.
+drop table t1;

=== added file 'mysql-test/suite/ndb/t/ndb_backup_rate.cnf'
--- a/mysql-test/suite/ndb/t/ndb_backup_rate.cnf	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb/t/ndb_backup_rate.cnf	2012-09-13 20:18:47 +0000
@@ -0,0 +1,9 @@
+!include ../my.cnf
+
+[cluster_config.1]
+DataMemory=80M
+BackupMemory=15M
+BackupDataBufferSize=11M
+BackupLogBufferSize = 3M
+BackupMaxWriteSize=10M
+DiskCheckpointSpeed=1M
\ No newline at end of file

=== added file 'mysql-test/suite/ndb/t/ndb_backup_rate.test'
--- a/mysql-test/suite/ndb/t/ndb_backup_rate.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb/t/ndb_backup_rate.test	2012-09-13 20:18:47 +0000
@@ -0,0 +1,88 @@
+-- source include/have_ndb.inc
+
+use test;
+create table t1 (a varchar(1024)) engine=ndb max_rows=100000000;
+insert into t1 values (repeat('I', 1024));
+
+# ~2kB : 1 row
+insert into t1 select * from t1;
+
+# ~64kB : 64 rows
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+
+# ~1M : 1024 rows
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+
+#~8M : 8192 rows
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+insert into t1 select * from t1;
+
+# ~32M 
+--error 0,1297
+insert into t1 select * from t1 limit 8192;
+--error 0,1297
+insert into t1 select * from t1 limit 8192;
+--error 0,1297
+insert into t1 select * from t1 limit 8192;
+
+--echo Continuing insert/delete until redo is full
+
+--disable_query_log
+--disable_result_log
+let $mysql_errno= 0;
+let $counter= 50;
+while (!$mysql_errno)
+{
+  --error 0,1297
+  insert into t1 select * from t1 limit 8192;
+
+  if (!$mysql_errno)
+  {
+    if (!$counter)
+    {
+      die Failed waiting for redo log full;
+    }
+    dec $counter;
+  }
+  --error 0,1297
+  delete from t1 limit 8192;
+}
+--enable_query_log
+--enable_result_log
+
+--echo Redo log full, waiting for redo log having space...
+
+--disable_query_log
+--disable_result_log
+
+let $mysql_errno= 1;
+let $counter= 600;
+while ($mysql_errno)
+{
+  --error 0,1297
+  insert into t1 select * from t1 limit 8192;
+
+  if ($mysql_errno)
+  {
+    if (!$counter)
+    {
+      die Failed waiting for redo log full;
+    }
+    dec $counter;
+    --sleep 0.1
+  }
+}
+--enable_query_log
+--enable_result_log
+
+--echo Redo had space again.
+  
+drop table t1;

=== modified file 'storage/ndb/src/kernel/blocks/backup/Backup.cpp'
--- a/storage/ndb/src/kernel/blocks/backup/Backup.cpp	2011-02-01 21:05:11 +0000
+++ b/storage/ndb/src/kernel/blocks/backup/Backup.cpp	2012-09-13 20:18:47 +0000
@@ -89,6 +89,8 @@ Backup::execSTTOR(Signal* signal)
 
   if (startphase == 1)
   {
+    m_monitor_words_written = 0;
+    m_monitor_snapshot_start = NdbTick_CurrentMillisecond();
     m_curr_disk_write_speed = c_defaults.m_disk_write_speed_sr;
     m_overflow_disk_write = 0;
     m_reset_disk_speed_time = NdbTick_CurrentMillisecond();
@@ -107,6 +109,8 @@ Backup::execSTTOR(Signal* signal)
 
   if (startphase == 7)
   {
+    m_monitor_words_written = 0;
+    m_monitor_snapshot_start = NdbTick_CurrentMillisecond();
     m_curr_disk_write_speed = c_defaults.m_disk_write_speed;
   }
 
@@ -190,6 +194,7 @@ Backup::execCONTINUEB(Signal* signal)
   switch(Tdata0) {
   case BackupContinueB::RESET_DISK_SPEED_COUNTER:
   {
+    jam();
     /*
       Adjust for upto 10 millisecond delay of this signal. Longer
       delays will not be handled, in this case the system is most
@@ -204,8 +209,40 @@ Backup::execCONTINUEB(Signal* signal)
     NDB_TICKS curr_time = NdbTick_CurrentMillisecond();
     int sig_delay = curr_time - m_reset_disk_speed_time;
 
-    m_words_written_this_period = m_overflow_disk_write;
-    m_overflow_disk_write = 0;
+    /* If we overflowed in the last period, count it in 
+     * this new period, potentially overflowing again into
+     * future periods...
+     */
+    /* How much overflow will we 'consume' this period?
+     * +1 to ensure that in the 'period full' case we
+     * do not write any more this period
+     */
+    Uint32 overflowThisPeriod = MIN(m_overflow_disk_write, 
+                                    m_curr_disk_write_speed + 1);
+    
+    /* How much overflow remains after this period? */
+    Uint32 remainingOverFlow = m_overflow_disk_write - overflowThisPeriod;
+    
+    if (overflowThisPeriod)
+    {
+      jam();
+#ifdef DEBUG_CHECKPOINTSPEED
+      ndbout_c("Overflow of %u bytes (max/period is %u bytes)",
+               overflowThisPeriod * 4, m_curr_disk_write_speed * 4);
+#endif
+      if (remainingOverFlow)
+      {
+        jam();
+#ifdef DEBUG_CHECKPOINTSPEED
+        ndbout_c("  Extra overflow : %u bytes, will take %u further periods to clear",
+                 remainingOverFlow * 4,
+                 remainingOverFlow / m_curr_disk_write_speed);
+#endif
+      }
+    }
+
+    m_words_written_this_period = overflowThisPeriod;
+    m_overflow_disk_write = remainingOverFlow;
     m_reset_disk_speed_time = curr_time;
 
     if (sig_delay > delay_time + 10)
@@ -217,6 +254,43 @@ Backup::execCONTINUEB(Signal* signal)
     m_reset_delay_used= delay_time;
     signal->theData[0] = BackupContinueB::RESET_DISK_SPEED_COUNTER;
     sendSignalWithDelay(BACKUP_REF, GSN_CONTINUEB, signal, delay_time, 1);
+
+    {
+      /* Independent check of DiskCheckpointSpeed.
+       * We check every second or so that we are roughly sticking
+       * to our diet.
+       */
+      if (curr_time >= m_monitor_snapshot_start + 1000)
+      {
+        jam();
+        const Uint64 millisPassed = curr_time - m_monitor_snapshot_start;
+        const Uint64 periodsPassed = (millisPassed / DISK_SPEED_CHECK_DELAY) + 1;
+        const Uint64 quotaWordsPerPeriod = m_curr_disk_write_speed;
+        const Uint64 maxOverFlowWords = c_defaults.m_maxWriteSize / 4;
+        const Uint64 maxExpectedWords = (periodsPassed * quotaWordsPerPeriod) + maxOverFlowWords;
+        
+        if (unlikely(m_monitor_words_written > maxExpectedWords))
+        {
+          jam();
+          /* In the last monitoring interval, we have written more words
+           * than allowed by the quota (DiskCheckpointSpeed), including
+           * transient spikes due to a single MaxBackupWriteSize write
+           */
+          ndbout << "Backup : Excessive Backup/LCP write rate in last monitoring period - recorded = "
+                 << (m_monitor_words_written * 4 * 1000) / millisPassed
+                 << " bytes/s, configured = "
+                 << m_curr_disk_write_speed * 4 * 10
+                 << " bytes/s" << endl;
+          ndbout << "Backup : Monitoring period : " << millisPassed
+                 << " millis. Bytes written : " << m_monitor_words_written
+                 << ".  Max allowed : " << maxExpectedWords << endl;
+          ndbassert(false);
+        }
+        /* Reset the monitor */
+        m_monitor_words_written = 0;
+        m_monitor_snapshot_start = curr_time;
+      }
+    }
 #if 0
     ndbout << "Signal delay was = " << sig_delay;
     ndbout << " Current time = " << curr_time << endl;
@@ -488,6 +562,15 @@ Backup::execDUMP_STATE_ORD(Signal* signa
               m_curr_disk_write_speed, m_words_written_this_period, m_overflow_disk_write);
     ndbout_c("m_reset_delay_used: %u  m_reset_disk_speed_time: %llu",
              m_reset_delay_used, (Uint64)m_reset_disk_speed_time);
+    /* Dump measured rate since last snapshot start */
+    NDB_TICKS now = NdbTick_CurrentMillisecond();
+    Uint64 millisPassed = now - m_monitor_snapshot_start;
+    Uint64 byteRate = (4000 * m_monitor_words_written) / (millisPassed + 1);
+    ndbout_c("m_monitor_words_written : %llu, duration : %llu millis, rate : %llu bytes/s : (%u pct of config)",
+             m_monitor_words_written, millisPassed, 
+             byteRate,
+             (Uint32) (100 * byteRate / (4 * 10)) / m_curr_disk_write_speed);
+
     for(c_backups.first(ptr); ptr.i != RNIL; c_backups.next(ptr))
     {
       ndbout_c("BackupRecord %u:  BackupId: %u  MasterRef: %x  ClientRef: %x",
@@ -4293,6 +4376,7 @@ Backup::ready_to_write(bool ready, Uint3
       completed by now.
     */
     int overflow;
+    m_monitor_words_written+= sz;
     m_words_written_this_period += sz;
     overflow = m_words_written_this_period - m_curr_disk_write_speed;
     if (overflow > 0)

=== modified file 'storage/ndb/src/kernel/blocks/backup/Backup.hpp'
--- a/storage/ndb/src/kernel/blocks/backup/Backup.hpp	2011-06-30 15:55:35 +0000
+++ b/storage/ndb/src/kernel/blocks/backup/Backup.hpp	2012-09-13 20:18:47 +0000
@@ -540,6 +540,9 @@ public:
   NDB_TICKS m_reset_disk_speed_time;
   static const int  DISK_SPEED_CHECK_DELAY = 100;
   
+  Uint64 m_monitor_words_written;
+  NDB_TICKS m_monitor_snapshot_start;
+
   STATIC_CONST(NO_OF_PAGES_META_FILE = 
 	       (2*MAX_WORDS_META_FILE + BACKUP_WORDS_PER_PAGE - 1) / 
 	       BACKUP_WORDS_PER_PAGE);

No bundle (reason: useless for push emails).
Thread
bzr push into mysql-5.1-telco-6.3 branch (frazer.clement:3483 to 3484)Bug#14472648Frazer Clement14 Sep