This is an automated email from the ASF dual-hosted git repository. jackietien pushed a commit to branch IOTDB-3773 in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit 7660cec2bbad04bfb9fc1e57348350c6efa9df5f Author: JackieTien97 <[email protected]> AuthorDate: Wed Nov 2 14:02:47 2022 +0800 Make slow sql time cost more accurate --- .../org/apache/iotdb/db/mpp/plan/Coordinator.java | 21 +++++++++++++++++---- .../db/mpp/plan/execution/IQueryExecution.java | 4 ++++ .../iotdb/db/mpp/plan/execution/QueryExecution.java | 10 ++++++++++ .../mpp/plan/execution/config/ConfigExecution.java | 10 ++++++++++ .../service/thrift/impl/ClientRPCServiceImpl.java | 19 ------------------- 5 files changed, 41 insertions(+), 23 deletions(-) diff --git a/server/src/main/java/org/apache/iotdb/db/mpp/plan/Coordinator.java b/server/src/main/java/org/apache/iotdb/db/mpp/plan/Coordinator.java index 3095540a53..3a3002850e 100644 --- a/server/src/main/java/org/apache/iotdb/db/mpp/plan/Coordinator.java +++ b/server/src/main/java/org/apache/iotdb/db/mpp/plan/Coordinator.java @@ -22,6 +22,7 @@ import org.apache.iotdb.common.rpc.thrift.TEndPoint; import org.apache.iotdb.commons.client.IClientManager; import org.apache.iotdb.commons.client.sync.SyncDataNodeInternalServiceClient; import org.apache.iotdb.commons.concurrent.IoTDBThreadPoolFactory; +import org.apache.iotdb.commons.conf.IoTDBConstant; import org.apache.iotdb.db.client.DataNodeClientPoolFactory; import org.apache.iotdb.db.conf.IoTDBConfig; import org.apache.iotdb.db.conf.IoTDBDescriptor; @@ -59,7 +60,10 @@ public class Coordinator { private static final String COORDINATOR_WRITE_EXECUTOR_NAME = "MPPCoordinatorWrite"; private static final String COORDINATOR_SCHEDULED_EXECUTOR_NAME = "MPPCoordinatorScheduled"; private static final int COORDINATOR_SCHEDULED_EXECUTOR_SIZE = 10; - private static final IoTDBConfig config = IoTDBDescriptor.getInstance().getConfig(); + private static final IoTDBConfig CONFIG = IoTDBDescriptor.getInstance().getConfig(); + + private static final Logger SLOW_SQL_LOGGER = + LoggerFactory.getLogger(IoTDBConstant.SLOW_SQL_LOGGER_NAME); private static final IClientManager<TEndPoint, SyncDataNodeInternalServiceClient> INTERNAL_SERVICE_CLIENT_MANAGER = @@ -135,7 +139,7 @@ public class Coordinator { queryContext, partitionFetcher, schemaFetcher, - timeOut > 0 ? timeOut : config.getQueryTimeoutThreshold(), + timeOut > 0 ? timeOut : CONFIG.getQueryTimeoutThreshold(), startTime); if (execution.isQuery()) { queryExecutionMap.put(queryId, execution); @@ -168,13 +172,13 @@ public class Coordinator { // TODO: (xingtanzjr) need to redo once we have a concrete policy for the threadPool management private ExecutorService getQueryExecutor() { int coordinatorReadExecutorSize = - config.isClusterMode() ? config.getCoordinatorReadExecutorSize() : 1; + CONFIG.isClusterMode() ? CONFIG.getCoordinatorReadExecutorSize() : 1; return IoTDBThreadPoolFactory.newFixedThreadPool( coordinatorReadExecutorSize, COORDINATOR_EXECUTOR_NAME); } private ExecutorService getWriteExecutor() { - int coordinatorWriteExecutorSize = config.getCoordinatorWriteExecutorSize(); + int coordinatorWriteExecutorSize = CONFIG.getCoordinatorWriteExecutorSize(); return IoTDBThreadPoolFactory.newFixedThreadPool( coordinatorWriteExecutorSize, COORDINATOR_WRITE_EXECUTOR_NAME); } @@ -196,6 +200,15 @@ public class Coordinator { LOGGER.debug("[CleanUpQuery]]"); queryExecution.stopAndCleanup(); queryExecutionMap.remove(queryId); + if (queryExecution.isQuery()) { + long costTime = System.currentTimeMillis() - queryExecution.getStartExecutionTime(); + if (costTime >= CONFIG.getSlowQueryThreshold()) { + SLOW_SQL_LOGGER.info( + "Cost: {} ms, sql is {}", + costTime, + queryExecution.getExecuteSQL().orElse("UNKNOWN")); + } + } } } } diff --git a/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/IQueryExecution.java b/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/IQueryExecution.java index b89bc3c667..6c3f51c6d6 100644 --- a/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/IQueryExecution.java +++ b/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/IQueryExecution.java @@ -49,4 +49,8 @@ public interface IQueryExecution { boolean isQuery(); String getQueryId(); + + long getStartExecutionTime(); + + Optional<String> getExecuteSQL(); } diff --git a/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/QueryExecution.java b/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/QueryExecution.java index 88b954af7d..387f9d7258 100644 --- a/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/QueryExecution.java +++ b/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/QueryExecution.java @@ -579,6 +579,16 @@ public class QueryExecution implements IQueryExecution { return context.getQueryId().getId(); } + @Override + public long getStartExecutionTime() { + return context.getStartTime(); + } + + @Override + public Optional<String> getExecuteSQL() { + return Optional.ofNullable(context.getSql()); + } + public String toString() { return String.format("QueryExecution[%s]", context.getQueryId()); } diff --git a/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/config/ConfigExecution.java b/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/config/ConfigExecution.java index 7e379425fe..c18be1ecf5 100644 --- a/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/config/ConfigExecution.java +++ b/server/src/main/java/org/apache/iotdb/db/mpp/plan/execution/config/ConfigExecution.java @@ -219,4 +219,14 @@ public class ConfigExecution implements IQueryExecution { public String getQueryId() { return context.getQueryId().getId(); } + + @Override + public long getStartExecutionTime() { + return context.getStartTime(); + } + + @Override + public Optional<String> getExecuteSQL() { + return Optional.ofNullable(context.getSql()); + } } diff --git a/server/src/main/java/org/apache/iotdb/db/service/thrift/impl/ClientRPCServiceImpl.java b/server/src/main/java/org/apache/iotdb/db/service/thrift/impl/ClientRPCServiceImpl.java index e26c4e603f..0b8526bad2 100644 --- a/server/src/main/java/org/apache/iotdb/db/service/thrift/impl/ClientRPCServiceImpl.java +++ b/server/src/main/java/org/apache/iotdb/db/service/thrift/impl/ClientRPCServiceImpl.java @@ -127,11 +127,8 @@ import java.util.Map; import java.util.Optional; import static org.apache.iotdb.db.service.basic.ServiceProvider.AUDIT_LOGGER; -import static org.apache.iotdb.db.service.basic.ServiceProvider.CONFIG; import static org.apache.iotdb.db.service.basic.ServiceProvider.CURRENT_RPC_VERSION; import static org.apache.iotdb.db.service.basic.ServiceProvider.QUERY_FREQUENCY_RECORDER; -import static org.apache.iotdb.db.service.basic.ServiceProvider.SESSION_MANAGER; -import static org.apache.iotdb.db.service.basic.ServiceProvider.SLOW_SQL_LOGGER; import static org.apache.iotdb.db.utils.ErrorHandlingUtils.onIoTDBException; import static org.apache.iotdb.db.utils.ErrorHandlingUtils.onNPEOrUnexpectedException; import static org.apache.iotdb.db.utils.ErrorHandlingUtils.onQueryException; @@ -239,10 +236,6 @@ public class ClientRPCServiceImpl implements IClientRPCServiceWithHandler { onQueryException(e, "\"" + statement + "\". " + OperationType.EXECUTE_STATEMENT)); } finally { addOperationLatency(Operation.EXECUTE_QUERY, startTime); - long costTime = System.currentTimeMillis() - startTime; - if (costTime >= CONFIG.getSlowQueryThreshold()) { - SLOW_SQL_LOGGER.info("Cost: {} ms, sql is {}", costTime, statement); - } } } @@ -300,10 +293,6 @@ public class ClientRPCServiceImpl implements IClientRPCServiceWithHandler { onQueryException(e, "\"" + req + "\". " + OperationType.EXECUTE_RAW_DATA_QUERY)); } finally { addOperationLatency(Operation.EXECUTE_QUERY, startTime); - long costTime = System.currentTimeMillis() - startTime; - if (costTime >= CONFIG.getSlowQueryThreshold()) { - SLOW_SQL_LOGGER.info("Cost: {} ms, sql is {}", costTime, req); - } } } @@ -360,10 +349,6 @@ public class ClientRPCServiceImpl implements IClientRPCServiceWithHandler { onQueryException(e, "\"" + req + "\". " + OperationType.EXECUTE_LAST_DATA_QUERY)); } finally { addOperationLatency(Operation.EXECUTE_QUERY, startTime); - long costTime = System.currentTimeMillis() - startTime; - if (costTime >= CONFIG.getSlowQueryThreshold()) { - SLOW_SQL_LOGGER.info("Cost: {} ms, sql is {}", costTime, req); - } } } @@ -1516,10 +1501,6 @@ public class ClientRPCServiceImpl implements IClientRPCServiceWithHandler { return null; } finally { addOperationLatency(Operation.EXECUTE_QUERY, startTime); - long costTime = System.currentTimeMillis() - startTime; - if (costTime >= CONFIG.getSlowQueryThreshold()) { - SLOW_SQL_LOGGER.info("Cost: {} ms, sql is {}", costTime, statement); - } } }
