diff --git a/modules/core/src/main/java/org/apache/ignite/internal/pagemem/FullPageId.java b/modules/core/src/main/java/org/apache/ignite/internal/pagemem/FullPageId.java index 5dad8a37b0fc1..b39aaf160b2ad 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/pagemem/FullPageId.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/pagemem/FullPageId.java @@ -122,6 +122,13 @@ public long pageId() { return pageId; } + /** + * @return Effective page ID. + */ + public long effectivePageId() { + return effectivePageId; + } + /** * @return Cache group ID. */ 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 0252d654daace..b9514813d05f4 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 @@ -97,7 +97,6 @@ import org.apache.ignite.internal.metric.IoStatisticsHolderNoOp; import org.apache.ignite.internal.pagemem.FullPageId; import org.apache.ignite.internal.pagemem.PageIdAllocator; -import org.apache.ignite.internal.pagemem.PageIdUtils; import org.apache.ignite.internal.pagemem.PageMemory; import org.apache.ignite.internal.pagemem.PageUtils; import org.apache.ignite.internal.pagemem.store.IgnitePageStoreManager; @@ -3698,9 +3697,18 @@ private void waitCompleted() throws IgniteCheckedException { @SuppressWarnings("NakedNotify") public class Checkpointer extends GridWorker { /** Checkpoint started log message format. */ - private static final String CHECKPOINT_STARTED_LOG_FORMAT = "Checkpoint started [checkpointId=%s, startPtr=%s," + - " checkpointBeforeLockTime=%dms, checkpointLockWait=%dms, checkpointListenersExecuteTime=%dms, " + - "checkpointLockHoldTime=%dms, walCpRecordFsyncDuration=%dms, %s pages=%d, reason='%s']"; + private static final String CHECKPOINT_STARTED_LOG_FORMAT = "Checkpoint started [" + + "checkpointId=%s, " + + "startPtr=%s, " + + "checkpointBeforeLockTime=%dms, " + + "checkpointLockWait=%dms, " + + "checkpointListenersExecuteTime=%dms, " + + "checkpointLockHoldTime=%dms, " + + "walCpRecordFsyncDuration=%dms, " + + "writeCheckpointEntryDuration=%dms, " + + "splitAndSortCpPagesDuration=%dms, " + + "%s pages=%d, " + + "reason='%s']"; /** Temporary write buffer. */ private final ByteBuffer tmpWriteBuf; @@ -4374,9 +4382,13 @@ private Checkpoint markCheckpointBegin(CheckpointMetricsTracker tracker) throws curr.transitTo(MARKER_STORED_TO_DISK); + tracker.onSplitAndSortCpPagesStart(); + GridMultiCollectionWrapper cpPages = splitAndSortCpPagesIfNeeded( cpPagesTuple, persistenceCfg.getCheckpointThreads()); + tracker.onSplitAndSortCpPagesEnd(); + if (printCheckpointStats && log.isInfoEnabled()) { long possibleJvmPauseDur = possibleLongJvmPauseDuration(tracker); @@ -4391,6 +4403,8 @@ private Checkpoint markCheckpointBegin(CheckpointMetricsTracker tracker) throws tracker.listenersExecuteDuration(), tracker.lockHoldDuration(), tracker.walCpRecordFsyncDuration(), + tracker.writeCheckpointEntryDuration(), + tracker.splitAndSortCpPagesDuration(), possibleJvmPauseDur > 0 ? "possibleJvmPauseDuration=" + possibleJvmPauseDur + "ms," : "", cpPages.size(), curr.reason @@ -4848,8 +4862,7 @@ private GridMultiCollectionWrapper splitAndSortCpPagesIfNeeded( if (cmp != 0) return cmp; - return Long.compare(PageIdUtils.effectivePageId(o1.pageId()), - PageIdUtils.effectivePageId(o2.pageId())); + return Long.compare(o1.effectivePageId(), o2.effectivePageId()); } }; diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/CheckpointMetricsTracker.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/CheckpointMetricsTracker.java index 9bdbc60a313c8..210b47973b186 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/CheckpointMetricsTracker.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/CheckpointMetricsTracker.java @@ -16,8 +16,12 @@ package org.apache.ignite.internal.processors.cache.persistence.pagemem; +import java.nio.ByteBuffer; import java.util.concurrent.atomic.AtomicIntegerFieldUpdater; import org.apache.ignite.internal.pagemem.wal.record.CheckpointRecord; +import org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager; +import org.apache.ignite.internal.processors.cache.persistence.checkpoint.CheckpointEntry; +import org.apache.ignite.internal.processors.cache.persistence.checkpoint.CheckpointEntryType; /** * Tracks various checkpoint phases and stats. @@ -75,6 +79,12 @@ public class CheckpointMetricsTracker { /** */ private long walCpRecordFsyncEnd; + /** */ + private long splitAndSortCpPagesStart; + + /** */ + private long splitAndSortCpPagesEnd; + /** */ private long listenersExecEnd; @@ -162,6 +172,20 @@ public void onWalCpRecordFsyncStart() { walCpRecordFsyncStart = System.currentTimeMillis(); } + /** + * + */ + public void onSplitAndSortCpPagesStart() { + splitAndSortCpPagesStart = System.currentTimeMillis(); + } + + /** + * + */ + public void onSplitAndSortCpPagesEnd() { + splitAndSortCpPagesEnd = System.currentTimeMillis(); + } + /** * */ @@ -232,6 +256,22 @@ public long walCpRecordFsyncDuration() { return walCpRecordFsyncEnd - walCpRecordFsyncStart; } + /** + * @return Duration of checkpoint entry buffer writing to file. + * + * @see GridCacheDatabaseSharedManager#writeCheckpointEntry(ByteBuffer, CheckpointEntry, CheckpointEntryType) + */ + public long writeCheckpointEntryDuration() { + return splitAndSortCpPagesStart - walCpRecordFsyncEnd; + } + + /** + * @return Duration of splitting and sorting checkpoint pages. + */ + public long splitAndSortCpPagesDuration() { + return splitAndSortCpPagesEnd - splitAndSortCpPagesStart; + } + /** * @return Checkpoint start time. */ diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/PageMemoryImpl.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/PageMemoryImpl.java index f1c1352a21304..6cead2d04f2bc 100755 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/PageMemoryImpl.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/persistence/pagemem/PageMemoryImpl.java @@ -1253,7 +1253,7 @@ private boolean isThrottlingEnabled() { relPtr = refreshOutdatedPage( seg, fullId.groupId(), - PageIdUtils.effectivePageId(fullId.pageId()), + fullId.effectivePageId(), true ); @@ -1413,7 +1413,7 @@ private int generationTag(Segment seg, FullPageId fullId) { private long resolveRelativePointer(Segment seg, FullPageId fullId, int reqVer) { return seg.loadedPages.get( fullId.groupId(), - PageIdUtils.effectivePageId(fullId.pageId()), + fullId.effectivePageId(), reqVer, INVALID_REL_PTR, OUTDATED_REL_PTR @@ -1543,7 +1543,7 @@ public long acquiredPages() { */ public boolean hasLoadedPage(FullPageId fullPageId) { int grpId = fullPageId.groupId(); - long pageId = PageIdUtils.effectivePageId(fullPageId.pageId()); + long pageId = fullPageId.effectivePageId(); int partId = PageIdUtils.partId(pageId); Segment seg = segment(grpId, pageId); @@ -2517,7 +2517,7 @@ else if (dirtyAddr != INVALID_REL_PTR) loadedPages.remove( fullPageId.groupId(), - PageIdUtils.effectivePageId(fullPageId.pageId()) + fullPageId.effectivePageId() ); return relRmvAddr; @@ -2590,7 +2590,7 @@ private long tryToFindSequentially(int cap, PageStoreWriter saveDirtyPage) throw if (preparePageRemoval(fullPageId, absEvictAddr, saveDirtyPage)) { loadedPages.remove( fullPageId.groupId(), - PageIdUtils.effectivePageId(fullPageId.pageId()) + fullPageId.effectivePageId() ); return addr; diff --git a/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/CheckpointBufferDeadlockTest.java b/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/CheckpointBufferDeadlockTest.java index 3465704d568fe..1d362317001e0 100644 --- a/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/CheckpointBufferDeadlockTest.java +++ b/modules/core/src/test/java/org/apache/ignite/internal/processors/cache/persistence/db/CheckpointBufferDeadlockTest.java @@ -233,11 +233,11 @@ private void runDeadlockScenario() throws Exception { pickedPages.sort(new Comparator() { @Override public int compare(FullPageId o1, FullPageId o2) { int cmp = Long.compare(o1.groupId(), o2.groupId()); + if (cmp != 0) return cmp; - return Long.compare(PageIdUtils.effectivePageId(o1.pageId()), - PageIdUtils.effectivePageId(o2.pageId())); + return Long.compare(o1.effectivePageId(), o2.effectivePageId()); } }); diff --git a/modules/core/src/test/java/org/apache/ignite/spi/checkpoint/cache/CheckCheckpointStartLoggingTest.java b/modules/core/src/test/java/org/apache/ignite/spi/checkpoint/cache/CheckCheckpointStartLoggingTest.java new file mode 100644 index 0000000000000..7bb9881db7ba6 --- /dev/null +++ b/modules/core/src/test/java/org/apache/ignite/spi/checkpoint/cache/CheckCheckpointStartLoggingTest.java @@ -0,0 +1,100 @@ +/* + * Copyright 2019 GridGain Systems, Inc. and Contributors. + * + * Licensed under the GridGain Community Edition License (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.gridgain.com/products/software/community-edition/gridgain-community-edition-license + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.ignite.spi.checkpoint.cache; + +import java.util.regex.Pattern; +import org.apache.ignite.Ignite; +import org.apache.ignite.IgniteCache; +import org.apache.ignite.configuration.DataRegionConfiguration; +import org.apache.ignite.configuration.DataStorageConfiguration; +import org.apache.ignite.configuration.IgniteConfiguration; +import org.apache.ignite.testframework.ListeningTestLogger; +import org.apache.ignite.testframework.LogListener; +import org.apache.ignite.testframework.junits.common.GridCommonAbstractTest; +import org.junit.Test; + +/** + * Checks correct checkpoint times logging + */ +public class CheckCheckpointStartLoggingTest extends GridCommonAbstractTest { + /** */ + private static final String VALID_MS_PATTERN = "[0-9]*ms"; + + /** */ + private static final String CHECKPOINT_STARTED_LOG_FORMAT = "Checkpoint started .*" + + "checkpointBeforeLockTime=" + VALID_MS_PATTERN + ", " + + "checkpointLockWait=" + VALID_MS_PATTERN + ", " + + "checkpointListenersExecuteTime="+ VALID_MS_PATTERN +", " + + "checkpointLockHoldTime="+ VALID_MS_PATTERN + ", " + + "walCpRecordFsyncDuration="+ VALID_MS_PATTERN +", " + + "writeCheckpointEntryDuration="+ VALID_MS_PATTERN +", " + + "splitAndSortCpPagesDuration="+ VALID_MS_PATTERN +", " + + ".* pages=[1-9][0-9]*, " + + "reason=.*"; + + /** */ + private ListeningTestLogger testLogger = new ListeningTestLogger(false, log); + + /** {@inheritDoc} */ + @Override protected IgniteConfiguration getConfiguration(String igniteInstanceName) throws Exception { + IgniteConfiguration cfg = super.getConfiguration(igniteInstanceName); + + DataStorageConfiguration memCfg = new DataStorageConfiguration() + .setDefaultDataRegionConfiguration( + new DataRegionConfiguration() + .setMaxSize(10 * 1024 * 1024) + .setPersistenceEnabled(true)); + + cfg.setDataStorageConfiguration(memCfg); + + cfg.setGridLogger(testLogger); + + return cfg; + } + + /** {@inheritDoc} */ + @Override protected void afterTest() throws Exception { + stopAllGrids(); + + cleanPersistenceDir(); + + super.afterTest(); + } + + /** + * @throws Exception if failed. + */ + @Test + public void testCheckpointLogging() throws Exception { + LogListener lsnr = LogListener.matches(Pattern.compile(CHECKPOINT_STARTED_LOG_FORMAT)).build(); + + testLogger.registerListener(lsnr); + + Ignite ignite = startGrid(); + + ignite.cluster().active(true); + + IgniteCache cache = ignite.getOrCreateCache(DEFAULT_CACHE_NAME); + + for (int i = 0; i < 1000; i++) + cache.put(i, i); + + forceCheckpoint(); + + assertTrue(lsnr.check()); + } +} diff --git a/modules/core/src/test/java/org/apache/ignite/testsuites/IgniteSpiCheckpointSelfTestSuite.java b/modules/core/src/test/java/org/apache/ignite/testsuites/IgniteSpiCheckpointSelfTestSuite.java index 61836813b8922..2c8cef4e15b89 100644 --- a/modules/core/src/test/java/org/apache/ignite/testsuites/IgniteSpiCheckpointSelfTestSuite.java +++ b/modules/core/src/test/java/org/apache/ignite/testsuites/IgniteSpiCheckpointSelfTestSuite.java @@ -20,6 +20,7 @@ import org.apache.ignite.spi.checkpoint.cache.CacheCheckpointSpiSecondCacheSelfTest; import org.apache.ignite.spi.checkpoint.cache.CacheCheckpointSpiSelfTest; import org.apache.ignite.spi.checkpoint.cache.CacheCheckpointSpiStartStopSelfTest; +import org.apache.ignite.spi.checkpoint.cache.CheckCheckpointStartLoggingTest; import org.apache.ignite.spi.checkpoint.jdbc.JdbcCheckpointSpiConfigSelfTest; import org.apache.ignite.spi.checkpoint.jdbc.JdbcCheckpointSpiCustomConfigSelfTest; import org.apache.ignite.spi.checkpoint.jdbc.JdbcCheckpointSpiDefaultConfigSelfTest; @@ -40,6 +41,7 @@ CacheCheckpointSpiSelfTest.class, CacheCheckpointSpiStartStopSelfTest.class, CacheCheckpointSpiSecondCacheSelfTest.class, + CheckCheckpointStartLoggingTest.class, // JDBC. JdbcCheckpointSpiConfigSelfTest.class,