Repository: ignite Updated Branches: refs/heads/master a8378003b -> a727a4c71
IGNITE-8737 Improve checkpoint logging information - Fixes #4244. Signed-off-by: Ivan Rakov <ira...@apache.org> Project: http://git-wip-us.apache.org/repos/asf/ignite/repo Commit: http://git-wip-us.apache.org/repos/asf/ignite/commit/a727a4c7 Tree: http://git-wip-us.apache.org/repos/asf/ignite/tree/a727a4c7 Diff: http://git-wip-us.apache.org/repos/asf/ignite/diff/a727a4c7 Branch: refs/heads/master Commit: a727a4c7135e57415de0756e8fdc235ba191109a Parents: a837800 Author: AMedvedev <amedve...@gridgain.com> Authored: Thu Jul 5 13:19:23 2018 +0300 Committer: Ivan Rakov <ira...@apache.org> Committed: Thu Jul 5 13:19:23 2018 +0300 ---------------------------------------------------------------------- .../GridCacheDatabaseSharedManager.java | 13 ++- .../checkpoint/CheckpointHistory.java | 28 ++++- .../wal/FileWriteAheadLogManager.java | 12 +- .../wal/FsyncModeFileWriteAheadLogManager.java | 8 +- .../checkpoint/IgniteMassLoadSandboxTest.java | 110 ++++++++++++++++++- 5 files changed, 154 insertions(+), 17 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/ignite/blob/a727a4c7/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/GridCacheDatabaseSharedManager.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/GridCacheDatabaseSharedManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/GridCacheDatabaseSharedManager.java index 8d9f74c..55394ae 100755 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/GridCacheDatabaseSharedManager.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/GridCacheDatabaseSharedManager.java @@ -3193,12 +3193,13 @@ public class GridCacheDatabaseSharedManager extends IgniteCacheDatabaseSharedMan if (printCheckpointStats) { if (log.isInfoEnabled()) log.info(String.format("Checkpoint finished [cpId=%s, pages=%d, markPos=%s, " + - "walSegmentsCleared=%d, markDuration=%dms, pagesWrite=%dms, fsync=%dms, " + + "walSegmentsCleared=%d, walSegmentsCovered=%s, markDuration=%dms, pagesWrite=%dms, fsync=%dms, " + "total=%dms]", chp.cpEntry != null ? chp.cpEntry.checkpointId() : "", chp.pagesSize, chp.cpEntry != null ? chp.cpEntry.checkpointMark() : "", chp.walFilesDeleted, + chp.walSegmentsCovered, tracker.markDuration(), tracker.pagesWriteDuration(), tracker.fsyncDuration(), @@ -3870,6 +3871,9 @@ public class GridCacheDatabaseSharedManager extends IgniteCacheDatabaseSharedMan /** Number of deleted WAL files. */ private int walFilesDeleted; + /** WAL segments fully covered by this checkpoint. */ + private List<Long> walSegmentsCovered; + /** */ private final int pagesSize; @@ -3903,6 +3907,13 @@ public class GridCacheDatabaseSharedManager extends IgniteCacheDatabaseSharedMan public void walFilesDeleted(int walFilesDeleted) { this.walFilesDeleted = walFilesDeleted; } + + /** + * @param walSegmentsCovered WAL segments fully covered by this checkpoint. + */ + public void walSegmentsCovered(final List<Long> walSegmentsCovered) { + this.walSegmentsCovered = walSegmentsCovered; + } } /** http://git-wip-us.apache.org/repos/asf/ignite/blob/a727a4c7/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/checkpoint/CheckpointHistory.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/checkpoint/CheckpointHistory.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/checkpoint/CheckpointHistory.java index d6cc297..cef2093 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/checkpoint/CheckpointHistory.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/checkpoint/CheckpointHistory.java @@ -193,13 +193,39 @@ public class CheckpointHistory { } /** - * Clears checkpoint history after checkpoint finish. + * Logs and clears checkpoint history after checkpoint finish. * * @return List of checkpoints removed from history. */ public List<CheckpointEntry> onCheckpointFinished(GridCacheDatabaseSharedManager.Checkpoint chp, boolean truncateWal) { List<CheckpointEntry> removed = new ArrayList<>(); + final Map.Entry<Long, CheckpointEntry> lastEntry = histMap.lastEntry(); + + assert lastEntry != null; + + final Map.Entry<Long, CheckpointEntry> previousEntry = histMap.lowerEntry(lastEntry.getKey()); + + final WALPointer lastWALPointer = lastEntry.getValue().checkpointMark(); + + long lastIdx = 0; + + long prevIdx = 0; + + final ArrayList<Long> walSegmentsCovered = new ArrayList<>(); + + if (lastWALPointer instanceof FileWALPointer) { + lastIdx = ((FileWALPointer)lastWALPointer).index(); + + if (previousEntry != null) + prevIdx = ((FileWALPointer)previousEntry.getValue().checkpointMark()).index(); + } + + for (long walCovered = prevIdx; walCovered < lastIdx; walCovered++) + walSegmentsCovered.add(walCovered); + + chp.walSegmentsCovered(walSegmentsCovered); + int deleted = 0; while (histMap.size() > maxCpHistMemSize) { http://git-wip-us.apache.org/repos/asf/ignite/blob/a727a4c7/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FileWriteAheadLogManager.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FileWriteAheadLogManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FileWriteAheadLogManager.java index 3e06e15..457a59c 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FileWriteAheadLogManager.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FileWriteAheadLogManager.java @@ -744,8 +744,8 @@ public class FileWriteAheadLogManager extends GridCacheSharedManagerAdapter impl currWrHandle = rollOver(currWrHandle); - if (log != null && log.isDebugEnabled()) - log.debug("Rollover segment [" + idx + " to " + currWrHandle.idx + "], recordType=" + rec.type()); + if (log != null && log.isInfoEnabled()) + log.info("Rollover segment [" + idx + " to " + currWrHandle.idx + "], recordType=" + rec.type()); } WALPointer ptr = currWrHandle.addRecord(rec); @@ -1813,8 +1813,8 @@ public class FileWriteAheadLogManager extends GridCacheSharedManagerAdapter impl File dstFile = new File(walArchiveDir, name); - if (log.isDebugEnabled()) - log.debug("Starting to copy WAL segment [absIdx=" + absIdx + ", segIdx=" + segIdx + + if (log.isInfoEnabled()) + log.info("Starting to copy WAL segment [absIdx=" + absIdx + ", segIdx=" + segIdx + ", origFile=" + origFile.getAbsolutePath() + ", dstFile=" + dstFile.getAbsolutePath() + ']'); try { @@ -1836,8 +1836,8 @@ public class FileWriteAheadLogManager extends GridCacheSharedManagerAdapter impl ", dstFile=" + dstTmpFile.getAbsolutePath() + ']', e); } - if (log.isDebugEnabled()) - log.debug("Copied file [src=" + origFile.getAbsolutePath() + + if (log.isInfoEnabled()) + log.info("Copied file [src=" + origFile.getAbsolutePath() + ", dst=" + dstFile.getAbsolutePath() + ']'); return new SegmentArchiveResult(absIdx, origFile, dstFile); http://git-wip-us.apache.org/repos/asf/ignite/blob/a727a4c7/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FsyncModeFileWriteAheadLogManager.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FsyncModeFileWriteAheadLogManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FsyncModeFileWriteAheadLogManager.java index 45cb1a7..a75dd31 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FsyncModeFileWriteAheadLogManager.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/wal/FsyncModeFileWriteAheadLogManager.java @@ -1642,8 +1642,8 @@ public class FsyncModeFileWriteAheadLogManager extends GridCacheSharedManagerAda File dstFile = new File(walArchiveDir, name); - if (log.isDebugEnabled()) - log.debug("Starting to copy WAL segment [absIdx=" + absIdx + ", segIdx=" + segIdx + + if (log.isInfoEnabled()) + log.info("Starting to copy WAL segment [absIdx=" + absIdx + ", segIdx=" + segIdx + ", origFile=" + origFile.getAbsolutePath() + ", dstFile=" + dstFile.getAbsolutePath() + ']'); try { @@ -1665,8 +1665,8 @@ public class FsyncModeFileWriteAheadLogManager extends GridCacheSharedManagerAda ", dstFile=" + dstTmpFile.getAbsolutePath() + ']', e); } - if (log.isDebugEnabled()) - log.debug("Copied file [src=" + origFile.getAbsolutePath() + + if (log.isInfoEnabled()) + log.info("Copied file [src=" + origFile.getAbsolutePath() + ", dst=" + dstFile.getAbsolutePath() + ']'); return new SegmentArchiveResult(absIdx, origFile, dstFile); http://git-wip-us.apache.org/repos/asf/ignite/blob/a727a4c7/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/checkpoint/IgniteMassLoadSandboxTest.java ---------------------------------------------------------------------- diff --git a/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/checkpoint/IgniteMassLoadSandboxTest.java b/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/checkpoint/IgniteMassLoadSandboxTest.java index 76cd5bd..7fb277c 100644 --- a/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/checkpoint/IgniteMassLoadSandboxTest.java +++ b/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/checkpoint/IgniteMassLoadSandboxTest.java @@ -19,6 +19,7 @@ package org.apache.ignite.internal.processors.cache.persistence.db.checkpoint; import java.io.File; import java.util.ArrayList; +import java.util.Arrays; import java.util.Collection; import java.util.Map; import java.util.Random; @@ -29,6 +30,8 @@ import java.util.concurrent.Executors; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; +import java.util.regex.Matcher; +import java.util.regex.Pattern; import javax.cache.Cache; import junit.framework.TestCase; import org.apache.ignite.Ignite; @@ -47,9 +50,11 @@ import org.apache.ignite.configuration.IgniteConfiguration; import org.apache.ignite.configuration.WALMode; import org.apache.ignite.internal.IgniteEx; import org.apache.ignite.internal.processors.cache.persistence.wal.FileWriteAheadLogManager; +import org.apache.ignite.internal.util.typedef.G; import org.apache.ignite.internal.util.typedef.X; import org.apache.ignite.internal.util.typedef.internal.S; import org.apache.ignite.internal.util.typedef.internal.U; +import org.apache.ignite.testframework.GridStringLogger; import org.apache.ignite.testframework.GridTestUtils; import org.apache.ignite.testframework.junits.common.GridCommonAbstractTest; @@ -165,6 +170,7 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { /** * Runs multithreaded put scenario (no data streamer). Load is generated to page store and to WAL. + * * @throws Exception if failed. */ public void testContinuousPutMultithreaded() throws Exception { @@ -224,6 +230,7 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { /** * Runs multithreaded put scenario (no data streamer). Load is generated to page store and to WAL. + * * @throws Exception if failed. */ public void testDataStreamerContinuousPutMultithreaded() throws Exception { @@ -234,7 +241,6 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { System.setProperty(IgniteSystemProperties.IGNITE_OVERRIDE_WRITE_THROTTLING_ENABLED, "speed"); System.setProperty(IgniteSystemProperties.IGNITE_DELAYED_REPLACED_PAGE_WRITE, "true"); - setWalArchAndWorkToSameVal = true; customWalMode = WALMode.BACKGROUND; @@ -243,7 +249,8 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { ignite.active(true); - final int threads = 1; Runtime.getRuntime().availableProcessors(); + final int threads = 1; + Runtime.getRuntime().availableProcessors(); final int recsPerThread = CONTINUOUS_PUT_RECS_CNT / threads; @@ -297,6 +304,100 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { } } + /** + * Test that WAL segments that are fully covered by checkpoint are logged + * + * @throws Exception if failed. + */ + public void testCoveredWalLogged() throws Exception { + GridStringLogger log0 = null; + + try { + log0 = new GridStringLogger(); + + final IgniteConfiguration cfg = getConfiguration("testCoveredWalLogged"); + + cfg.setGridLogger(log0); + + cfg.getDataStorageConfiguration().setWalAutoArchiveAfterInactivity(10); + + final Ignite ignite = G.start(cfg); + + ignite.cluster().active(true); + + final IgniteCache<Object, Object> cache = ignite.cache(CACHE_NAME); + + cache.put(1, new byte[cfg.getDataStorageConfiguration().getWalSegmentSize() - 1024]); + + forceCheckpoint(); + + cache.put(1, new byte[cfg.getDataStorageConfiguration().getWalSegmentSize() - 1024]); + + forceCheckpoint(); + + cache.put(1, new byte[cfg.getDataStorageConfiguration().getWalSegmentSize() - 1024]); + + forceCheckpoint(); + + Thread.sleep(200); // needed by GridStringLogger + + final String log = log0.toString(); + + final String lines[] = log.split("\\r?\\n"); + + final Pattern chPtrn = Pattern.compile("Checkpoint finished"); + + final Pattern idxPtrn = Pattern.compile("idx=([0-9]+),"); + + final Pattern covererdPtrn = Pattern.compile("walSegmentsCovered=\\[(.+)\\], "); + + boolean hasCheckpoint = false; + + long nextCovered = 0; + + for (String line : lines) { + if (!chPtrn.matcher(line).find()) + continue; + + hasCheckpoint = true; + + final Matcher idxMatcher = idxPtrn.matcher(line); + + assertTrue(idxMatcher.find()); + + final long idx = Long.valueOf(idxMatcher.group(1)); + + final Matcher coveredMatcher = covererdPtrn.matcher(line); + + if (!coveredMatcher.find()) { // no wal segments are covered by checkpoint + assertEquals(nextCovered, idx); + continue; + } + + final String coveredMatcherGrp = coveredMatcher.group(1); + + final long[] covered = coveredMatcherGrp.length() > 0 ? + Arrays.stream(coveredMatcherGrp.split(",")).mapToLong(e -> Integer.valueOf(e.trim())).toArray() : + new long[0]; + + assertEquals(nextCovered, covered[0]); + + final long lastCovered = covered[covered.length - 1]; + + assertEquals(idx - 1, lastCovered); // current wal is excluded + + nextCovered = lastCovered + 1; + } + + assertTrue(hasCheckpoint); + + } + finally { + System.out.println(log0 != null ? log0.toString() : "Error initializing GridStringLogger"); + + stopAllGrids(); + } + } /** * Verifies data from storage. @@ -457,14 +558,13 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { } } - /** {@inheritDoc} */ @Override protected long getTestTimeout() { return TimeUnit.MINUTES.toMillis(20); } /** Object with additional 40 000 bytes of payload */ - public static class HugeIndexedObject { + public static class HugeIndexedObject { /** Data. */ private byte[] data; /** */ @@ -514,4 +614,4 @@ public class IgniteMassLoadSandboxTest extends GridCommonAbstractTest { return S.toString(HugeIndexedObject.class, this); } } -} \ No newline at end of file +}
