This is an automated email from the ASF dual-hosted git repository.
xingtanzjr pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/iotdb.git
The following commit(s) were added to refs/heads/master by this push:
new e094b3649f5 add time cost for datanode start (#11498)
e094b3649f5 is described below
commit e094b3649f5b2e439858d55605c2a5f0112bbd2e
Author: Zhijia Cao <[email protected]>
AuthorDate: Thu Nov 9 15:57:58 2023 +0800
add time cost for datanode start (#11498)
---
.../org/apache/iotdb/db/conf/IoTDBStartCheck.java | 5 ++
.../iotdb/db/protocol/client/ConfigNodeInfo.java | 14 ++++-
.../java/org/apache/iotdb/db/service/DataNode.java | 62 ++++++++++++++++------
.../db/storageengine/rescon/disk/TierManager.java | 3 ++
.../iotdb/commons/service/RegisterManager.java | 6 +++
5 files changed, 72 insertions(+), 18 deletions(-)
diff --git
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/conf/IoTDBStartCheck.java
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/conf/IoTDBStartCheck.java
index 287b966645e..024e02ba483 100644
---
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/conf/IoTDBStartCheck.java
+++
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/conf/IoTDBStartCheck.java
@@ -408,6 +408,7 @@ public class IoTDBStartCheck {
}
public void serializeMutableSystemPropertiesIfNecessary() throws IOException
{
+ long startTime = System.currentTimeMillis();
boolean needsSerialize = false;
for (String param : variableParamValueTable.keySet()) {
if (!(properties.getProperty(param).equals(getVal(param)))) {
@@ -421,5 +422,9 @@ public class IoTDBStartCheck {
properties.store(outputStream, SYSTEM_PROPERTIES_STRING);
}
}
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "Serialize mutable system properties successfully, which takes {} ms.",
+ (endTime - startTime));
}
}
diff --git
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/client/ConfigNodeInfo.java
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/client/ConfigNodeInfo.java
index c34ae9013b6..b0088d96719 100644
---
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/client/ConfigNodeInfo.java
+++
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/client/ConfigNodeInfo.java
@@ -69,6 +69,7 @@ public class ConfigNodeInfo {
/** Update ConfigNodeList both in memory and system.properties file */
public void updateConfigNodeList(List<TEndPoint> latestConfigNodes) {
+ long startTime = System.currentTimeMillis();
// Check whether the config nodes are latest or not
configNodeInfoReadWriteLock.readLock().lock();
try {
@@ -86,8 +87,11 @@ public class ConfigNodeInfo {
onlineConfigNodes.clear();
onlineConfigNodes.addAll(latestConfigNodes);
storeConfigNode();
-
- logger.info("Successfully update ConfigNode: {}.", onlineConfigNodes);
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "Update ConfigNode Successfully: {}, which takes {} ms.",
+ onlineConfigNodes,
+ (endTime - startTime));
} catch (IOException e) {
logger.error("Update ConfigNode failed.", e);
} finally {
@@ -113,6 +117,7 @@ public class ConfigNodeInfo {
}
public void loadConfigNodeList() {
+ long startTime = System.currentTimeMillis();
// properties contain CONFIG_NODE_LIST only when start as Data node
try {
configNodeInfoReadWriteLock.writeLock().lock();
@@ -128,6 +133,11 @@ public class ConfigNodeInfo {
onlineConfigNodes.addAll(
NodeUrlUtils.parseTEndPointUrls(properties.getProperty(CONFIG_NODE_LIST)));
}
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "Load ConfigNode successfully: {}, which takes {} ms.",
+ onlineConfigNodes,
+ (endTime - startTime));
} catch (BadNodeUrlException e) {
logger.error("Cannot parse config node list in system.properties");
} finally {
diff --git
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/service/DataNode.java
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/service/DataNode.java
index 3d6bc5b0c68..3e988256269 100644
---
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/service/DataNode.java
+++
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/service/DataNode.java
@@ -217,6 +217,7 @@ public class DataNode implements DataNodeMBean {
/** Prepare cluster IoTDB-DataNode */
private boolean prepareDataNode() throws StartupException, IOException {
+ long startTime = System.currentTimeMillis();
// Set cluster mode
config.setClusterMode(true);
@@ -231,6 +232,8 @@ public class DataNode implements DataNodeMBean {
// Startup checks
DataNodeStartupCheck checks = new
DataNodeStartupCheck(IoTDBConstant.DN_ROLE, config);
checks.startUpCheck();
+ long endTime = System.currentTimeMillis();
+ logger.info("The DataNode is prepared successfully, which takes {} ms",
(endTime - startTime));
return isFirstStart;
}
@@ -247,7 +250,7 @@ public class DataNode implements DataNodeMBean {
*/
private void pullAndCheckSystemConfigurations() throws StartupException {
logger.info("Pulling system configurations from the ConfigNode-leader...");
-
+ long startTime = System.currentTimeMillis();
/* Pull system configurations */
int retry = DEFAULT_RETRY;
TSystemConfigurationResp configurationResp = null;
@@ -312,8 +315,10 @@ public class DataNode implements DataNodeMBean {
} catch (Exception e) {
throw new StartupException(e.getMessage());
}
-
- logger.info("Successfully pull system configurations from
ConfigNode-leader.");
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "Successfully pull system configurations from ConfigNode-leader, which
takes {} ms",
+ (endTime - startTime));
}
/**
@@ -365,7 +370,7 @@ public class DataNode implements DataNodeMBean {
*/
private void sendRegisterRequestToConfigNode() throws StartupException,
IOException {
logger.info("Sending register request to ConfigNode-leader...");
-
+ long startTime = System.currentTimeMillis();
/* Send register request */
int retry = DEFAULT_RETRY;
TDataNodeRegisterReq req = new TDataNodeRegisterReq();
@@ -411,8 +416,11 @@ public class DataNode implements DataNodeMBean {
storeRuntimeConfigurations(
dataNodeRegisterResp.getConfigNodeList(),
dataNodeRegisterResp.getRuntimeConfiguration());
-
- logger.info("Successfully register to the cluster: {}",
config.getClusterName());
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "Successfully register to the cluster: {} , which takes {} ms.",
+ config.getClusterName(),
+ (endTime - startTime));
} else {
/* Throw exception when register failed */
logger.error(dataNodeRegisterResp.getStatus().getMessage());
@@ -422,7 +430,7 @@ public class DataNode implements DataNodeMBean {
private void sendRestartRequestToConfigNode() throws StartupException {
logger.info("Sending restart request to ConfigNode-leader...");
-
+ long startTime = System.currentTimeMillis();
/* Send restart request */
int retry = DEFAULT_RETRY;
TDataNodeRestartReq req = new TDataNodeRestartReq();
@@ -464,7 +472,11 @@ public class DataNode implements DataNodeMBean {
/* Store runtime configurations when restart request is accepted */
storeRuntimeConfigurations(
dataNodeRestartResp.getConfigNodeList(),
dataNodeRestartResp.getRuntimeConfiguration());
- logger.info("Restart request to cluster: {} is accepted.",
config.getClusterName());
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "Restart request to cluster: {} is accepted, which takes {} ms.",
+ config.getClusterName(),
+ (endTime - startTime));
} else {
/* Throw exception when restart is rejected */
throw new StartupException(dataNodeRestartResp.getStatus().getMessage());
@@ -493,9 +505,18 @@ public class DataNode implements DataNodeMBean {
logger.info("IoTDB DataNode has started.");
try {
+ long startTime = System.currentTimeMillis();
SchemaRegionConsensusImpl.getInstance().start();
+ long schemaRegionEndTime = System.currentTimeMillis();
+ logger.info(
+ "SchemaRegion consensus start successfully, which takes {} ms.",
+ (schemaRegionEndTime - startTime));
schemaRegionConsensusStarted = true;
DataRegionConsensusImpl.getInstance().start();
+ long dataRegionEndTime = System.currentTimeMillis();
+ logger.info(
+ "DataRegion consensus start successfully, which takes {} ms.",
+ (dataRegionEndTime - schemaRegionEndTime));
dataRegionConsensusStarted = true;
} catch (IOException e) {
throw new StartupException(e);
@@ -541,7 +562,7 @@ public class DataNode implements DataNodeMBean {
logger.info(
"IoTDB DataNode is setting up, some databases may not be ready now,
please wait several seconds...");
-
+ long startTime = System.currentTimeMillis();
while (!StorageEngine.getInstance().isAllSgReady()) {
try {
TimeUnit.MILLISECONDS.sleep(1000);
@@ -551,7 +572,8 @@ public class DataNode implements DataNodeMBean {
return;
}
}
-
+ long endTime = System.currentTimeMillis();
+ logger.info("Wait for all databases ready, which takes {} ms.", (endTime -
startTime));
// Must init after SchemaEngine and StorageEngine prepared well
DataNodeRegionManager.getInstance().init();
@@ -646,6 +668,7 @@ public class DataNode implements DataNodeMBean {
}
private void prepareUDFResources() throws StartupException {
+ long startTime = System.currentTimeMillis();
initUDFRelatedInstance();
if (resourcesInformationHolder.getUDFInformationList() == null
|| resourcesInformationHolder.getUDFInformationList().isEmpty()) {
@@ -675,8 +698,8 @@ public class DataNode implements DataNodeMBean {
} catch (Exception e) {
throw new StartupException(e);
}
-
- logger.debug("successfully registered all the UDFs");
+ long endTime = System.currentTimeMillis();
+ logger.debug("successfully registered all the UDFs, which takes {} ms.",
(endTime - startTime));
if (logger.isDebugEnabled()) {
for (UDFInformation udfInformation :
UDFManagementService.getInstance().getAllUDFInformation()) {
@@ -749,6 +772,7 @@ public class DataNode implements DataNodeMBean {
}
private void prepareTriggerResources() throws StartupException {
+ long startTime = System.currentTimeMillis();
initTriggerRelatedInstance();
if (resourcesInformationHolder.getTriggerInformationList() == null
|| resourcesInformationHolder.getTriggerInformationList().isEmpty()) {
@@ -779,7 +803,7 @@ public class DataNode implements DataNodeMBean {
} catch (Exception e) {
throw new StartupException(e);
}
- logger.debug("successfully registered all the triggers");
+
if (logger.isDebugEnabled()) {
for (TriggerInformation triggerInformation :
TriggerManagementService.getInstance().getAllTriggerInformationInTriggerTable())
{
@@ -793,6 +817,9 @@ public class DataNode implements DataNodeMBean {
}
// Start TriggerInformationUpdater
triggerInformationUpdater.startTriggerInformationUpdater();
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "successfully registered all the triggers, which takes {} ms.",
(endTime - startTime));
}
private void getJarOfTriggers(List<TriggerInformation>
triggerInformationList)
@@ -854,7 +881,10 @@ public class DataNode implements DataNodeMBean {
}
private void preparePipeResources() throws StartupException {
+ long startTime = System.currentTimeMillis();
PipeAgent.runtime().preparePipeResources(resourcesInformationHolder);
+ long endTime = System.currentTimeMillis();
+ logger.info("Prepare pipe resources successfully, which takes {} ms.",
(endTime - startTime));
}
private void getPipeInformationList(List<ByteBuffer> allPipeInformation) {
@@ -868,10 +898,10 @@ public class DataNode implements DataNodeMBean {
}
private void initSchemaEngine() {
- long time = System.currentTimeMillis();
+ long startTime = System.currentTimeMillis();
SchemaEngine.getInstance().init();
- long end = System.currentTimeMillis() - time;
- logger.info("Spent {}ms to recover schema.", end);
+ long endTime = System.currentTimeMillis();
+ logger.info("Recover schema successfully, which takes {} ms.", (endTime -
startTime));
}
public void stop() {
diff --git
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/rescon/disk/TierManager.java
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/rescon/disk/TierManager.java
index 8b1ca4a3712..927d22ba9ac 100644
---
a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/rescon/disk/TierManager.java
+++
b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/rescon/disk/TierManager.java
@@ -153,12 +153,15 @@ public class TierManager {
}
public synchronized void resetFolders() {
+ long startTime = System.currentTimeMillis();
seqTiers.clear();
unSeqTiers.clear();
seqDir2TierLevel.clear();
unSeqDir2TierLevel.clear();
initFolders();
+ long endTime = System.currentTimeMillis();
+ logger.info("The folders is reset successfully, which takes {} ms.",
(endTime - startTime));
}
private void mkDataDirs(List<String> folders) {
diff --git
a/iotdb-core/node-commons/src/main/java/org/apache/iotdb/commons/service/RegisterManager.java
b/iotdb-core/node-commons/src/main/java/org/apache/iotdb/commons/service/RegisterManager.java
index f0b139689ed..9b979f74831 100644
---
a/iotdb-core/node-commons/src/main/java/org/apache/iotdb/commons/service/RegisterManager.java
+++
b/iotdb-core/node-commons/src/main/java/org/apache/iotdb/commons/service/RegisterManager.java
@@ -48,7 +48,13 @@ public class RegisterManager {
}
}
iServices.add(service);
+ long startTime = System.currentTimeMillis();
service.start();
+ long endTime = System.currentTimeMillis();
+ logger.info(
+ "The {} service is started successfully, which takes {} ms.",
+ service.getID().getName(),
+ (endTime - startTime));
}
/** stop all service and clear iService list. */
