From 05d27f51fb18105671aafb9b871bd0ae2356c9e1 Mon Sep 17 00:00:00 2001 From: brinn <brinn> Date: Tue, 13 Mar 2012 17:56:56 +0000 Subject: [PATCH] Improve logging of eager shuffling (including some timing information so the performance can be assessed). SVN: 24707 --- .../shared/utils/SegmentedStoreUtils.java | 22 +++++-- .../SegmentedStoreShufflingTaskTest.java | 59 +++++++++++++------ .../plugins/SimpleShufflingTest.java | 5 ++ .../EagerShufflingTaskTest.java | 5 ++ .../PostRegistrationMaintenanceTaskTest.java | 4 -- .../plugins/standard/RsyncArchiverTest.java | 24 ++++---- .../shared/utils/SegmentedStoreUtilsTest.java | 58 ++++++++++-------- 7 files changed, 116 insertions(+), 61 deletions(-) diff --git a/datastore_server/source/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtils.java b/datastore_server/source/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtils.java index 231a3c0578c..a29a0e50a0d 100644 --- a/datastore_server/source/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtils.java +++ b/datastore_server/source/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtils.java @@ -176,6 +176,7 @@ public class SegmentedStoreUtils Set<String> incomingShares, IFreeSpaceProvider freeSpaceProvider, IEncapsulatedOpenBISService service, ISimpleLogger log) { + final long start = System.currentTimeMillis(); List<Share> shares = getDataSetsPerShare(storeRoot, dataStoreCode, freeSpaceProvider, service, log, SystemTimeProvider.SYSTEM_TIME_PROVIDER); @@ -183,6 +184,9 @@ public class SegmentedStoreUtils { share.setIncoming(incomingShares.contains(share.getShareId())); } + log.log(LogLevel.INFO, + String.format("Obtained the list of all datasets in all shares in %.2f s.", + (System.currentTimeMillis() - start) / 1000.0)); return shares; } @@ -282,7 +286,7 @@ public class SegmentedStoreUtils } File dataSetDirInNewShare = new File(share, relativePath); dataSetDirInNewShare.mkdirs(); - copyToShare(dataSetDirInStore, dataSetDirInNewShare); + copyToShare(dataSetDirInStore, dataSetDirInNewShare, logger); long size = assertEqualSizeAndChildren(dataSetDirInStore, dataSetDirInNewShare); String shareId = share.getName(); service.updateShareIdAndSize(dataSetCode, shareId, size); @@ -345,10 +349,16 @@ public class SegmentedStoreUtils deleteDataSet(dataSetCode, new File(shareFolder, location), shareIdManager, logger); } - private static void copyToShare(File file, File share) + private static void copyToShare(File file, File share, ISimpleLogger logger) { - RsyncCopier copier = new RsyncCopier(OSUtilities.findExecutable(RSYNC_EXEC)); + final long start = System.currentTimeMillis(); + logger.log(LogLevel.INFO, String.format("Start moving directory '%s' to new share '%s'", + file.getPath(), share.getPath())); + final RsyncCopier copier = new RsyncCopier(OSUtilities.findExecutable(RSYNC_EXEC)); copier.copyContent(file, share); + logger.log(LogLevel.INFO, String.format( + "Finished moving directory '%s' to new share '%s' in %.2f s", file.getPath(), + share.getPath(), (System.currentTimeMillis() - start) / 1000.0)); } private static long assertEqualSizeAndChildren(File source, File destination) @@ -402,12 +412,12 @@ public class SegmentedStoreUtils { throw new EnvironmentFailureException("Destination file '" + destination.getAbsolutePath() + "' has checksum " + destinationChecksum - + " but source file '" + source.getAbsolutePath() + "' has checksum " + sourceChecksum - + "."); + + " but source file '" + source.getAbsolutePath() + "' has checksum " + + sourceChecksum + "."); } return sourceSize; } - + private static long calculateCRC(File file) { try diff --git a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SegmentedStoreShufflingTaskTest.java b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SegmentedStoreShufflingTaskTest.java index 0675f573083..7eb335f827b 100644 --- a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SegmentedStoreShufflingTaskTest.java +++ b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SegmentedStoreShufflingTaskTest.java @@ -28,6 +28,7 @@ import java.util.List; import java.util.Properties; import org.apache.log4j.Level; +import org.hamcrest.Matchers; import org.jmock.Expectations; import org.jmock.Mockery; import org.jmock.Sequence; @@ -50,35 +51,41 @@ import ch.systemsx.cisd.openbis.dss.generic.shared.utils.ShareFactory; import ch.systemsx.cisd.openbis.generic.shared.dto.SimpleDataSetInformationDTO; /** - * - * * @author Franz-Josef Elmer */ -@Friend(toClasses={ShareFactory.class, SegmentedStoreShufflingTask.class}) +@Friend(toClasses = + { ShareFactory.class, SegmentedStoreShufflingTask.class }) public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase { private static final String DATA_STORE_CODE = "DATA-STORE-1"; private static void prepareAsWithdrawShare(File share) { - FileUtilities.writeToFile(new File(share, SHARE_PROPS_FILE), WITHDRAW_SHARE_PROP + " = true"); + FileUtilities.writeToFile(new File(share, SHARE_PROPS_FILE), WITHDRAW_SHARE_PROP + + " = true"); } - + public static final class MockShuffling implements ISegmentedStoreShuffling { private final Properties properties; + private boolean initialized; + private List<Share> sourceShares; + private List<Share> targetShares; + private IEncapsulatedOpenBISService service; + private IDataSetMover dataSetMover; + private ISimpleLogger logger; - + public MockShuffling(Properties properties) { this.properties = properties; } - + public void init(ISimpleLogger l) { initialized = true; @@ -95,14 +102,21 @@ public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase logger = simpleLogger; } } - + private BufferedAppender logRecorder; + private Mockery context; + private IEncapsulatedOpenBISService service; + private IFreeSpaceProvider spaceProvider; + private IDataSetMover dataSetMover; + private ISimpleLogger logger; + private SegmentedStoreShufflingTask balancerTask; + private File storeRoot; @BeforeMethod @@ -121,7 +135,7 @@ public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase storeRoot = new File(workingDirectory, "store"); storeRoot.mkdirs(); } - + @AfterMethod public void afterMethod() { @@ -170,7 +184,7 @@ public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase ds3.setDataStoreCode("other data store"); will(returnValue(Arrays.asList(ds1, ds2, ds3))); inSequence(sequence1); - + SimpleDataSetInformationDTO ds1b = new SimpleDataSetInformationDTO(); ds1b.setDataStoreCode(DATA_STORE_CODE); ds1b.setDataSetCode("ds1"); @@ -180,15 +194,20 @@ public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase one(service).listDataSets(); will(returnValue(Arrays.asList(ds1b, ds2))); inSequence(sequence1); - + one(logger).log(with(LogLevel.WARN), with(logMessageRecordingMatcher)); + allowing(logger).log( + with(LogLevel.INFO), + with(Matchers.startsWith("Obtained the list of all " + + "datasets in all shares"))); } }); logRecorder.resetLogContent(); - + balancerTask.execute(); - - MockShuffling balancer = (SegmentedStoreShufflingTaskTest.MockShuffling) balancerTask.shuffling; + + MockShuffling balancer = + (SegmentedStoreShufflingTaskTest.MockShuffling) balancerTask.shuffling; assertEquals("{class=" + balancer.getClass().getName() + "}", balancer.properties.toString()); assertEquals("1", balancer.sourceShares.get(0).getShareId()); @@ -208,8 +227,8 @@ public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase + "INFO NOTIFY.SegmentedStoreShufflingTask - " + "The following shares were emptied by shuffling: [1]", logRecorder.getLogContent()); - assertEquals("Data set ds1 no longer exists in share 2.", - logMessageRecordingMatcher.recordedObject().toString()); + assertEquals("Data set ds1 no longer exists in share 2.", logMessageRecordingMatcher + .recordedObject().toString()); context.assertIsSatisfied(); } @@ -225,13 +244,17 @@ public class SegmentedStoreShufflingTaskTest extends AbstractFileSystemTestCase { exactly(2).of(service).listDataSets(); will(returnValue(Arrays.asList())); - + one(logger).log(LogLevel.INFO, "Data Store Shares:"); + allowing(logger).log( + with(LogLevel.INFO), + with(Matchers.startsWith("Obtained the list of all " + + "datasets in all shares"))); } }); balancerTask.execute(); - + context.assertIsSatisfied(); } } diff --git a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SimpleShufflingTest.java b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SimpleShufflingTest.java index 7ef3bd2d3d4..688a0a43130 100644 --- a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SimpleShufflingTest.java +++ b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/plugins/SimpleShufflingTest.java @@ -31,6 +31,7 @@ import java.util.Map.Entry; import java.util.Properties; import java.util.Set; +import org.hamcrest.Matchers; import org.jmock.Expectations; import org.jmock.Mockery; import org.testng.annotations.AfterMethod; @@ -251,6 +252,10 @@ public class SimpleShufflingTest extends AbstractFileSystemTestCase "Data set ds2 successfully moved from share 1 to 4."); one(logger).log(LogLevel.WARN, "No share found for shuffling data set ds4."); + allowing(logger).log( + with(LogLevel.INFO), + with(Matchers.startsWith("Obtained the list of all " + + "datasets in all shares"))); } }); diff --git a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/EagerShufflingTaskTest.java b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/EagerShufflingTaskTest.java index 2da9e8de8c1..e16bc37be39 100644 --- a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/EagerShufflingTaskTest.java +++ b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/EagerShufflingTaskTest.java @@ -26,6 +26,7 @@ import java.util.Properties; import org.apache.commons.io.FileUtils; import org.apache.log4j.Level; +import org.hamcrest.Matchers; import org.jmock.Expectations; import org.jmock.Mockery; import org.testng.annotations.AfterMethod; @@ -287,6 +288,10 @@ public class EagerShufflingTaskTest extends AbstractFileSystemTestCase { one(service).listDataSets(); will(returnValue(Arrays.asList(dataSet("1", DATA_SET_CODE1)))); + one(logger).log( + with(LogLevel.INFO), + with(Matchers.startsWith("Obtained the list of all " + + "datasets in all shares"))); } }); } diff --git a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/PostRegistrationMaintenanceTaskTest.java b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/PostRegistrationMaintenanceTaskTest.java index 613f614a420..d90bc1f9046 100644 --- a/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/PostRegistrationMaintenanceTaskTest.java +++ b/datastore_server/sourceTest/java/ch/systemsx/cisd/etlserver/postregistration/PostRegistrationMaintenanceTaskTest.java @@ -50,10 +50,8 @@ import ch.systemsx.cisd.common.filesystem.FileUtilities; import ch.systemsx.cisd.common.logging.BufferedAppender; import ch.systemsx.cisd.common.logging.ISimpleLogger; import ch.systemsx.cisd.common.test.AssertionUtil; -import ch.systemsx.cisd.common.test.RecordingMatcher; import ch.systemsx.cisd.openbis.dss.generic.shared.IEncapsulatedOpenBISService; import ch.systemsx.cisd.openbis.dss.generic.shared.ServiceProviderTestWrapper; -import ch.systemsx.cisd.openbis.generic.shared.basic.dto.TrackingDataSetCriteria; import ch.systemsx.cisd.openbis.generic.shared.basic.dto.builders.DataSetBuilder; /** @@ -259,8 +257,6 @@ public class PostRegistrationMaintenanceTaskTest extends AbstractFileSystemTestC { Properties properties = createDefaultProperties(); - final Sequence sequence = context.sequence("tasks"); - // when there is lastSeenDataSetFile it means, that the marking of the dataset has not // succeeded. // Before proceeding, the dataset which code is in this file will have to marked as diff --git a/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/RsyncArchiverTest.java b/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/RsyncArchiverTest.java index 97828d6a81f..c9de75fc10b 100644 --- a/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/RsyncArchiverTest.java +++ b/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/RsyncArchiverTest.java @@ -342,9 +342,13 @@ public class RsyncArchiverTest extends AbstractFileSystemTestCase ProcessingStatus status = archiver.unarchive(Arrays.asList(ds1), archiverTaskContext); - assertEquals("INFO OPERATION.AbstractDatastorePlugin - " - + "Unarchiving of the following datasets has been requested: [Dataset 'ds1']", - logRecorder.getLogContent()); + assertTrue( + logRecorder.getLogContent(), + logRecorder + .getLogContent() + .startsWith( + "INFO OPERATION.AbstractDatastorePlugin - " + + "Unarchiving of the following datasets has been requested: [Dataset 'ds1']")); assertEquals("[]", status.getErrorStatuses().toString()); assertEquals("{class=" + ShareFinder.class.getName() + "\np1=property 1}", ShareFinder.properties.toString()); @@ -454,20 +458,20 @@ public class RsyncArchiverTest extends AbstractFileSystemTestCase archiver = new RsyncArchiver(properties, store, fileOperationsManager); archiver.deleteFromArchive(Arrays.asList(datasetLocation)); } - + @Test public void testDeleteFromArchiveOnlyMarkAsDeleted() { final DatasetLocation datasetLocation = new DatasetLocation(); datasetLocation.setDataSetLocation("my-location"); context.checking(new Expectations() - { { - one(fileOperationsManager).markAsDeleted(datasetLocation); - will(returnValue(Status.OK)); - } - }); - + { + one(fileOperationsManager).markAsDeleted(datasetLocation); + will(returnValue(Status.OK)); + } + }); + archiver = new RsyncArchiver(properties, store, fileOperationsManager); archiver.deleteFromArchive(Arrays.asList(datasetLocation)); } diff --git a/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtilsTest.java b/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtilsTest.java index 2983269bbeb..d34705faf73 100644 --- a/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtilsTest.java +++ b/datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/shared/utils/SegmentedStoreUtilsTest.java @@ -44,24 +44,27 @@ import ch.systemsx.cisd.openbis.generic.shared.basic.dto.DataSet; import ch.systemsx.cisd.openbis.generic.shared.dto.SimpleDataSetInformationDTO; /** - * - * * @author Franz-Josef Elmer */ -@Friend(toClasses=SegmentedStoreUtils.class) +@Friend(toClasses = SegmentedStoreUtils.class) public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase { private static final String DATA_STORE_CODE = "ds-code"; - + private Mockery context; + private IEncapsulatedOpenBISService service; + private IShareIdManager shareIdManager; + private MockLogger log; + private IFreeSpaceProvider freeSpaceProvider; + private ITimeProvider timeProvider; private File store; - + @BeforeMethod public void beforeMethod() { @@ -96,7 +99,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase throw new Error(method.getName() + "() : ", t); } } - + @Test public void testGetDataSetsPerShare() { @@ -130,9 +133,9 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase { one(service).listDataSets(); will(returnValue(Arrays.asList(ds1, ds2, ds3, ds4, ds5))); - + one(service).updateShareIdAndSize("ds-1", "1", 10L); - + try { one(freeSpaceProvider).freeSpaceKb(with(fileMatcher)); @@ -143,13 +146,13 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase } } }); - + List<Share> shares = SegmentedStoreUtils.getDataSetsPerShare(store, DATA_STORE_CODE, freeSpaceProvider, service, log, timeProvider); Share share1 = shares.get(0); long freeSpace = share1.calculateFreeSpace(); - + assertEquals("WARN: Speed file " + speedFile2 + " doesn't contain a number: not a number\n" + "INFO: Calculating size of " + ds1File + "\n" + "INFO: " + ds1File + " contains 10 bytes (calculated in 0 msec)\n" @@ -168,7 +171,8 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase assertEquals(new File(store, "2").toString(), shares.get(1).getShare().toString()); assertEquals("2", shares.get(1).getShareId()); assertSame(ds3, shares.get(1).getDataSetsOrderedBySize().get(0)); - assertEquals(123456789L, shares.get(1).getDataSetsOrderedBySize().get(0).getDataSetSize().longValue()); + assertEquals(123456789L, shares.get(1).getDataSetsOrderedBySize().get(0).getDataSetSize() + .longValue()); assertEquals(1, shares.get(1).getDataSetsOrderedBySize().size()); assertEquals(Math.abs(Constants.DEFAULT_SPEED_HINT), shares.get(1).getSpeed()); assertEquals(123456789L, shares.get(1).getTotalSizeOfDataSets()); @@ -198,7 +202,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase { one(service).tryGetDataSet("ds-1"); will(returnValue(new DataSet())); - + one(service).updateShareIdAndSize("ds-1", "2", 11L); one(shareIdManager).setShareId("ds-1", "2"); one(shareIdManager).await("ds-1"); @@ -206,10 +210,18 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase }); assertEquals(true, dataSetDirInStore.exists()); assertFileNames(share2uuid01, "22"); - + SegmentedStoreUtils.moveDataSetToAnotherShare(dataSetDirInStore, share2, service, shareIdManager, log); + log.assertNextLogMessage("Start moving directory 'targets/unit-test-wd/ch.systemsx.cisd." + + "openbis.dss.generic.shared.utils.SegmentedStoreUtilsTest/store/1/uuid/01/02/03/ds-1' " + + "to new share 'targets/unit-test-wd/ch.systemsx.cisd.openbis.dss.generic.shared.utils." + + "SegmentedStoreUtilsTest/store/2/uuid/01/02/03/ds-1'"); + log.assertNextLogMessageContains("Finished moving directory 'targets/unit-test-wd/ch.systemsx.cisd." + + "openbis.dss.generic.shared.utils.SegmentedStoreUtilsTest/store/1/uuid/01/02/03/ds-1'" + + " to new share 'targets/unit-test-wd/ch.systemsx.cisd.openbis.dss.generic.shared.utils." + + "SegmentedStoreUtilsTest/store/2/uuid/01/02/03/ds-1'"); log.assertNextLogMessage("Await for data set ds-1 to be unlocked."); log.assertNextLogMessage("Start deleting data set ds-1 at " + share1 + "/uuid/01/02/03/ds-1"); @@ -221,7 +233,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase FileUtilities.loadToString(new File(share2uuid01, "02/03/ds-1/original/hello.txt"))); log.assertNoMoreLogMessages(); } - + @Test public void testCleanupOld() { @@ -233,13 +245,13 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase { one(shareIdManager).getShareId("ds-1"); will(returnValue("2")); - + one(shareIdManager).await("ds-1"); } }); - + SegmentedStoreUtils.cleanUp(dataSet, store, "2", shareIdManager, log); - + assertEquals(false, ds1In1.exists()); assertEquals(true, ds1In2.exists()); log.assertNextLogMessage("Await for data set ds-1 to be unlocked."); @@ -272,7 +284,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase log.assertNextLogMessage("Deletion of data set ds-1 at " + ds1In2 + " failed."); log.assertNoMoreLogMessages(); } - + @Test public void testFindIncomingShare() { @@ -281,9 +293,9 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase File share1 = new File(store, "1"); share1.mkdirs(); FileUtilities.writeToFile(new File(share1, "share.properties"), "withdraw-share = true"); - + String share = SegmentedStoreUtils.findIncomingShare(incomingFolder, store, log); - + assertEquals("1", share); assertEquals( "WARN: Incoming folder [targets/unit-test-wd/" @@ -291,7 +303,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase + "/incoming] can not be assigned to share 1 because its property " + "withdraw-share is set to true.\n", log.toString()); } - + private File dataSetFile(String shareId, boolean empty) { File share = new File(store, shareId); @@ -304,7 +316,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase FileUtilities.writeToFile(new File(dataSetFile, "read.me"), "do nothing"); return dataSetFile; } - + private void assertFileNames(File file, String... names) { File[] files = file.listFiles(); @@ -316,7 +328,7 @@ public class SegmentedStoreUtilsTest extends AbstractFileSystemTestCase } assertEquals(Arrays.asList(names).toString(), actualNames.toString()); } - + private SimpleDataSetInformationDTO dataSet(File dataSetFile, String dataStoreCode, Long size) { SimpleDataSetInformationDTO dataSet = new SimpleDataSetInformationDTO(); -- GitLab