This is an automated email from the ASF dual-hosted git repository. rong pushed a commit to branch 1.2-slow-startup in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit 07eb593e2267f338e5b1e468d3001d3921481f21 Author: Steve Yurong Su <[email protected]> AuthorDate: Mon Jun 26 21:40:56 2023 +0800 add log for slow startup --- .../db/pipe/agent/runtime/PipeAgentLauncher.java | 17 ++++++++++++++ .../db/pipe/agent/runtime/PipeRuntimeAgent.java | 26 ++++++++++++++++++++++ .../file/PipeHardlinkFileDirStartupCleaner.java | 5 +++++ .../java/org/apache/iotdb/db/service/DataNode.java | 9 ++++++++ 4 files changed, 57 insertions(+) diff --git a/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeAgentLauncher.java b/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeAgentLauncher.java index 69786989982..1da5cd57d9d 100644 --- a/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeAgentLauncher.java +++ b/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeAgentLauncher.java @@ -60,17 +60,29 @@ class PipeAgentLauncher { public static synchronized void launchPipePluginAgent( ResourcesInformationHolder resourcesInformationHolder) throws StartupException { + long time = System.currentTimeMillis(); + LOGGER.info("Start to launch pipe plugin agent"); + initPipePluginRelatedInstances(); + LOGGER.info( + "Finish to init pipe plugin related instances, cost {} ms", + System.currentTimeMillis() - time); if (resourcesInformationHolder.getPipePluginMetaList() == null || resourcesInformationHolder.getPipePluginMetaList().isEmpty()) { return; } + time = System.currentTimeMillis(); final List<PipePluginMeta> uninstalledOrConflictedPipePluginMetaList = getUninstalledOrConflictedPipePluginMetaList(resourcesInformationHolder); + LOGGER.info( + "Finish to get uninstalled or conflicted pipe plugin meta list, cost {} ms", + System.currentTimeMillis() - time); + int index = 0; while (index < uninstalledOrConflictedPipePluginMetaList.size()) { + time = System.currentTimeMillis(); List<PipePluginMeta> curList = new ArrayList<>(); int offset = 0; while (offset < ResourcesInformationHolder.getJarNumOfOneRpc() @@ -80,16 +92,21 @@ class PipeAgentLauncher { } index += (offset + 1); fetchAndSavePipePluginJars(curList); + LOGGER.info( + "Finish to fetch and save pipe plugin jars, cost {} ms", + System.currentTimeMillis() - time); } // create instances of pipe plugins and do registration try { + time = System.currentTimeMillis(); for (PipePluginMeta meta : resourcesInformationHolder.getPipePluginMetaList()) { if (meta.isBuiltin()) { continue; } PipeAgent.plugin().doRegister(meta); } + LOGGER.info("Finish to register pipe plugin, cost {} ms", System.currentTimeMillis() - time); } catch (Exception e) { throw new StartupException(e); } diff --git a/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeRuntimeAgent.java b/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeRuntimeAgent.java index afc899854d0..d9055001a6d 100644 --- a/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeRuntimeAgent.java +++ b/server/src/main/java/org/apache/iotdb/db/pipe/agent/runtime/PipeRuntimeAgent.java @@ -51,17 +51,38 @@ public class PipeRuntimeAgent implements IService { public synchronized void preparePipeResources( ResourcesInformationHolder resourcesInformationHolder) throws StartupException { + long startTs = System.currentTimeMillis(); + LOGGER.info("PipeHardlinkFileDirStartupCleaner.clean started"); PipeHardlinkFileDirStartupCleaner.clean(); + LOGGER.info( + "PipeHardlinkFileDirStartupCleaner finished, cost: {}ms", + System.currentTimeMillis() - startTs); + + startTs = System.currentTimeMillis(); + LOGGER.info("PipeAgentLauncher.launchPipePluginAgent started"); PipeAgentLauncher.launchPipePluginAgent(resourcesInformationHolder); + LOGGER.info( + "PipeAgentLauncher.launchPipePluginAgent finished, cost: {}ms", + System.currentTimeMillis() - startTs); + + startTs = System.currentTimeMillis(); + LOGGER.info("PipeAgentLauncher.launchPipeTaskAgent started"); simpleConsensusProgressIndexAssigner.start(); + LOGGER.info( + "PipeAgentLauncher.launchPipeTaskAgent finished, cost: {}ms", + System.currentTimeMillis() - startTs); } @Override public synchronized void start() throws StartupException { + long startTs = System.currentTimeMillis(); + PipeConfig.getInstance().printAllConfigs(); PipeAgentLauncher.launchPipeTaskAgent(); isShutdown.set(false); + + LOGGER.info("PipeRuntimeAgent started in {}ms", System.currentTimeMillis() - startTs); } @Override @@ -92,10 +113,15 @@ public class PipeRuntimeAgent implements IService { ////////////////////// Recover ProgressIndex Assigner ////////////////////// public void assignRecoverProgressIndexForTsFileRecovery(TsFileResource tsFileResource) { + long startTs = System.currentTimeMillis(); tsFileResource.updateProgressIndex( new RecoverProgressIndex( DATA_NODE_ID, simpleConsensusProgressIndexAssigner.getSimpleProgressIndexForTsFileRecovery())); + LOGGER.info( + "Assign RecoverProgressIndex for TsFileRecovery, tsFileResource: {}, cost: {}ms", + tsFileResource, + System.currentTimeMillis() - startTs); } //////////////////////////// Runtime Exception Handlers //////////////////////////// diff --git a/server/src/main/java/org/apache/iotdb/db/pipe/resource/file/PipeHardlinkFileDirStartupCleaner.java b/server/src/main/java/org/apache/iotdb/db/pipe/resource/file/PipeHardlinkFileDirStartupCleaner.java index 1acadceb5fd..179135e5c6f 100644 --- a/server/src/main/java/org/apache/iotdb/db/pipe/resource/file/PipeHardlinkFileDirStartupCleaner.java +++ b/server/src/main/java/org/apache/iotdb/db/pipe/resource/file/PipeHardlinkFileDirStartupCleaner.java @@ -40,6 +40,8 @@ public class PipeHardlinkFileDirStartupCleaner { */ public static void clean() { for (String dataDir : IoTDBDescriptor.getInstance().getConfig().getDataDirs()) { + long startTs = System.currentTimeMillis(); + LOGGER.info("PipeHardlinkFileDirStartupCleaner.clean started, dataDir: {}", dataDir); for (File file : FileUtils.listFilesAndDirs( new File(dataDir), DirectoryFileFilter.INSTANCE, DirectoryFileFilter.INSTANCE)) { @@ -51,6 +53,9 @@ public class PipeHardlinkFileDirStartupCleaner { FileUtils.deleteQuietly(file)); } } + LOGGER.info( + "PipeHardlinkFileDirStartupCleaner finished, cost: {}ms", + System.currentTimeMillis() - startTs); } } diff --git a/server/src/main/java/org/apache/iotdb/db/service/DataNode.java b/server/src/main/java/org/apache/iotdb/db/service/DataNode.java index 5ae417d3a29..abaa9fa1dea 100644 --- a/server/src/main/java/org/apache/iotdb/db/service/DataNode.java +++ b/server/src/main/java/org/apache/iotdb/db/service/DataNode.java @@ -457,8 +457,14 @@ public class DataNode implements DataNodeMBean { } private void prepareResources() throws StartupException { + long startTime = System.currentTimeMillis(); prepareUDFResources(); + logger.info("Prepare UDF resources cost {} ms.", System.currentTimeMillis() - startTime); + + startTime = System.currentTimeMillis(); prepareTriggerResources(); + logger.info("Prepare trigger resources cost {} ms.", System.currentTimeMillis() - startTime); + preparePipeResources(); } @@ -836,7 +842,10 @@ public class DataNode implements DataNodeMBean { } private void preparePipeResources() throws StartupException { + logger.info("!!! start to prepare pipe resources ..."); + final long currentTime = System.currentTimeMillis(); PipeAgent.runtime().preparePipeResources(resourcesInformationHolder); + logger.info("!!! prepare pipe resources cost {}ms", System.currentTimeMillis() - currentTime); } private void getPipeInformationList(List<ByteBuffer> allPipeInformation) {
