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#14472648 | Frazer Clement | 14 Sep |
