From 1f50c0fecf326680485aa393e7dee27d356ca154 Mon Sep 17 00:00:00 2001
From: Junjie <fallin.jie@qq.com>
Date: 星期一, 13 四月 2026 18:54:23 +0800
Subject: [PATCH] #入库命令耗时日志
---
src/main/java/com/zy/common/utils/NavigateUtils.java | 165 +++++++++++++++++++++++++++++++++++++++++++++++++++++-
1 files changed, 161 insertions(+), 4 deletions(-)
diff --git a/src/main/java/com/zy/common/utils/NavigateUtils.java b/src/main/java/com/zy/common/utils/NavigateUtils.java
index eeb8ad0..297ae7e 100644
--- a/src/main/java/com/zy/common/utils/NavigateUtils.java
+++ b/src/main/java/com/zy/common/utils/NavigateUtils.java
@@ -54,6 +54,7 @@
@Component
public class NavigateUtils {
+ private static final long STATION_PATH_SLOW_LOG_THRESHOLD_MS = 500L;
private static final double CONGESTION_BUSY_BASE = 1.0d;
private static final double CONGESTION_ISSUED_RESERVE_BASE = 0.75d;
private static final double CONGESTION_PENDING_QUEUE_BASE = 0.45d;
@@ -130,8 +131,17 @@
Integer currentTaskNo,
Double pathLenFactor,
StationPathCalcMode calcMode) {
+ long totalStartNs = System.nanoTime();
+ Map<String, Long> stepCostMap = new LinkedHashMap<>();
+ String pathSource = "fallback";
+ int candidateCount = 0;
+ List<NavigateNode> resultPath = new ArrayList<>();
+
+ long stepStartNs = System.nanoTime();
StationPathResolvedPolicy resolvedPolicy = resolveStationPathPolicy(startStationId, endStationId);
+ stepCostMap.put("resolvePolicy", elapsedMillis(stepStartNs));
if (calcMode != StationPathCalcMode.REROUTE) {
+ stepStartNs = System.nanoTime();
List<NavigateNode> directPath = findStationDirectPath(
startStationId,
endStationId,
@@ -140,24 +150,37 @@
calcMode,
resolvedPolicy
);
+ stepCostMap.put("directPath", elapsedMillis(stepStartNs));
if (!directPath.isEmpty()) {
- return normalizeStationPath(directPath);
+ pathSource = "direct";
+ resultPath = normalizeStationPath(directPath);
+ logStationPathCalcSlow(startStationId, endStationId, currentTaskNo, pathLenFactor, calcMode, pathSource, candidateCount, resultPath.size(), stepCostMap, totalStartNs);
+ return resultPath;
}
}
+ stepStartNs = System.nanoTime();
StationPathSearchContext context = buildStationPathSearchContext(
startStationId,
endStationId,
resolvedPolicy,
calcMode
);
+ stepCostMap.put("buildSearchContext", elapsedMillis(stepStartNs));
if (context.allList.isEmpty()) {
+ logStationPathCalcSlow(startStationId, endStationId, currentTaskNo, pathLenFactor, calcMode, "empty", candidateCount, 0, stepCostMap, totalStartNs);
return new ArrayList<>();
}
+ candidateCount = context.allList.size();
+ stepStartNs = System.nanoTime();
List<NavigateNode> list = calcMode == StationPathCalcMode.REACHABILITY
? findStationReachablePath(context.allList, context.resolvedPolicy, startStationId, endStationId)
: findStationBestPathTwoStage(context.allList, context.resolvedPolicy, currentTaskNo, pathLenFactor, startStationId, endStationId);
- return normalizeStationPath(list);
+ stepCostMap.put("selectBestPath", elapsedMillis(stepStartNs));
+ pathSource = calcMode == StationPathCalcMode.REACHABILITY ? "reachability" : "twoStage";
+ resultPath = normalizeStationPath(list);
+ logStationPathCalcSlow(startStationId, endStationId, currentTaskNo, pathLenFactor, calcMode, pathSource, candidateCount, resultPath.size(), stepCostMap, totalStartNs);
+ return resultPath;
}
public List<NavigateNode> calcByTrackSiteNo(int lev, Integer startTrackSiteNo, Integer endTrackSiteNo) {
@@ -724,7 +747,7 @@
StationPathResolvedPolicy resolvedPolicy) {
BasStation startStation = basStationService.getById(startStationId);
if (startStation == null) {
- throw new CoolException("鏈壘鍒拌 璧风偣 瀵瑰簲鐨勭珯鐐规暟鎹�");
+ throw new CoolException("鏈壘鍒拌 " + startStationId + "璧风偣 瀵瑰簲鐨勭珯鐐规暟鎹�");
}
NavigateSolution navigateSolution = new NavigateSolution();
@@ -732,7 +755,7 @@
NavigateNode startNode = navigateSolution.findStationNavigateNode(stationMap, startStationId);
NavigateNode endNode = navigateSolution.findStationNavigateNode(stationMap, endStationId);
if (startNode == null || endNode == null) {
- throw new CoolException("鏈壘鍒拌 璧风偣 鎴� 缁堢偣 瀵瑰簲鐨勮妭鐐�");
+ throw new CoolException("鏈壘鍒拌 " + startStationId + "璧风偣 鎴� " + endStationId + "缁堢偣 瀵瑰簲鐨勮妭鐐�");
}
DirectStationPathContext context = new DirectStationPathContext();
@@ -817,10 +840,13 @@
Double pathLenFactor,
Integer startStationId,
Integer endStationId) {
+ long totalStartNs = System.nanoTime();
+ Map<String, Long> stepCostMap = new LinkedHashMap<>();
if (allList == null || allList.isEmpty()) {
return new ArrayList<>();
}
+ long stepStartNs = System.nanoTime();
StationPathRuleConfig ruleConfig = resolvedPolicy.getRuleConfig() == null
? new StationPathRuleConfig()
: resolvedPolicy.getRuleConfig();
@@ -828,7 +854,9 @@
? StationPathProfileConfig.defaultConfig()
: resolvedPolicy.getProfileConfig();
PathGlobalPolicy globalPolicy = loadPathGlobalPolicy(profileConfig);
+ stepCostMap.put("loadPolicyConfig", elapsedMillis(stepStartNs));
+ stepStartNs = System.nanoTime();
List<List<NavigateNode>> filteredCandidates = applyRuleFilters(allList, ruleConfig, true);
if (filteredCandidates.isEmpty() && hasWaypoint(ruleConfig) && !strictWaypoint(ruleConfig)) {
filteredCandidates = applyRuleFilters(allList, ruleConfig, false);
@@ -851,16 +879,20 @@
}
filteredCandidates = allList;
}
+ stepCostMap.put("filterCandidates", elapsedMillis(stepStartNs));
+ stepStartNs = System.nanoTime();
Map<Integer, StationProtocol> statusMap = loadStationStatusMap();
Map<Integer, Double> stationLoopLoadMap = loadStationLoopLoadMap();
StationTrafficSnapshot trafficSnapshot = loadStationTrafficSnapshot(statusMap, currentTaskNo);
LoopMergeGuardContext loopMergeGuardContext = loadLoopMergeGuardContext();
Set<LoopMergeEntry> mandatoryLoopMergeEntrySet = resolveMandatoryLoopMergeEntrySet(filteredCandidates, loopMergeGuardContext);
Set<Integer> outStationIdSet = loadAllOutStationIdSet();
+ stepCostMap.put("loadDynamicContext", elapsedMillis(stepStartNs));
List<PathCandidateMetrics> metricsList = new ArrayList<>();
int skippedByOtherOutStation = 0;
int skippedByLoopMergeGuard = 0;
+ stepStartNs = System.nanoTime();
for (List<NavigateNode> path : filteredCandidates) {
if (path == null || path.isEmpty()) {
continue;
@@ -886,12 +918,15 @@
}
return new ArrayList<>();
}
+ stepCostMap.put("buildMetrics", elapsedMillis(stepStartNs));
+ stepStartNs = System.nanoTime();
applyPathLengthPreference(metricsList, profileConfig, globalPolicy, pathLenFactor);
metricsList.sort((a, b) -> compareStaticCandidateMetrics(a, b, pathLenFactor));
PathCandidateMetrics preferred = metricsList.get(0);
int maxLen = (int) Math.ceil(preferred.pathLen * safeDouble(profileConfig.getS1MaxLenRatio(), 1.15d));
int maxTurns = preferred.turnCount + safeInt(profileConfig.getS1MaxTurnDiff(), 1);
+ stepCostMap.put("stage1StaticSort", elapsedMillis(stepStartNs));
List<PathCandidateMetrics> stage1Selected = new ArrayList<>();
for (PathCandidateMetrics metrics : metricsList) {
@@ -911,6 +946,7 @@
primaryMetrics = new ArrayList<>(primaryMetrics.subList(0, topK));
}
+ stepStartNs = System.nanoTime();
primaryMetrics.sort((a, b) -> compareDynamicCandidateMetrics(a, b, pathLenFactor));
secondaryMetrics.sort((a, b) -> compareDynamicCandidateMetrics(a, b, pathLenFactor));
@@ -921,11 +957,26 @@
}
}
remainingMetrics.sort((a, b) -> compareDynamicCandidateMetrics(a, b, pathLenFactor));
+ stepCostMap.put("stage2DynamicSort", elapsedMillis(stepStartNs));
+ stepStartNs = System.nanoTime();
List<List<NavigateNode>> orderedPathList = new ArrayList<>();
appendCandidatePathList(orderedPathList, primaryMetrics);
appendCandidatePathList(orderedPathList, secondaryMetrics);
appendCandidatePathList(orderedPathList, remainingMetrics);
+ stepCostMap.put("buildOrderedPaths", elapsedMillis(stepStartNs));
+ logStationPathOrderSlow(startStationId,
+ endStationId,
+ currentTaskNo,
+ pathLenFactor,
+ allList.size(),
+ filteredCandidates.size(),
+ metricsList.size(),
+ orderedPathList.size(),
+ skippedByLoopMergeGuard,
+ skippedByOtherOutStation,
+ stepCostMap,
+ totalStartNs);
return orderedPathList;
}
@@ -2431,12 +2482,20 @@
Integer endStationId,
StationPathResolvedPolicy resolvedPolicy,
StationPathCalcMode calcMode) {
+ long totalStartNs = System.nanoTime();
+ Map<String, Long> stepCostMap = new LinkedHashMap<>();
+ int rawCandidateCount = 0;
+ int filteredCandidateCount = 0;
+
+ long stepStartNs = System.nanoTime();
BasStation startStation = basStationService.getById(startStationId);
if (startStation == null) {
throw new CoolException("鏈壘鍒拌 璧风偣 瀵瑰簲鐨勭珯鐐规暟鎹�");
}
Integer lev = startStation.getStationLev();
+ stepCostMap.put("loadStartStation", elapsedMillis(stepStartNs));
+ stepStartNs = System.nanoTime();
NavigateSolution navigateSolution = new NavigateSolution();
List<List<NavigateNode>> stationMap = navigateSolution.getStationMap(lev);
@@ -2449,10 +2508,13 @@
if (endNode == null) {
throw new CoolException("鏈壘鍒拌 缁堢偣 瀵瑰簲鐨勮妭鐐�");
}
+ stepCostMap.put("loadStationMapAndNode", elapsedMillis(stepStartNs));
+ stepStartNs = System.nanoTime();
StationPathProfileConfig profileConfig = resolvedPolicy.getProfileConfig() == null
? StationPathProfileConfig.defaultConfig()
: resolvedPolicy.getProfileConfig();
+ stepCostMap.put("loadProfileConfig", elapsedMillis(stepStartNs));
long startTime = System.currentTimeMillis();
News.info("[WCS Debug] 绔欑偣璺緞寮�濮嬭绠�,startStationId={},endStationId={},mode={}",
@@ -2463,6 +2525,7 @@
int calcMaxPaths = safeInt(profileConfig.getCalcMaxPaths(), 500);
int calcMaxCost = safeInt(profileConfig.getCalcMaxCost(), 300);
List<Integer> guideStationSequence = buildGuideStationSequence(startStationId, endStationId, resolvedPolicy.getRuleConfig());
+ stepStartNs = System.nanoTime();
List<List<NavigateNode>> allList = navigateSolution.allSimplePaths(
stationMap,
startNode,
@@ -2472,13 +2535,20 @@
calcMaxCost,
guideStationSequence
);
+ stepCostMap.put("allSimplePaths", elapsedMillis(stepStartNs));
+ rawCandidateCount = allList.size();
if (allList.isEmpty()) {
+ logStationPathSearchContextSlow(startStationId, endStationId, calcMode, lev, rawCandidateCount, filteredCandidateCount, stepCostMap, totalStartNs);
return StationPathSearchContext.empty(resolvedPolicy);
}
+ stepStartNs = System.nanoTime();
Map<Integer, StationProtocol> statusMap = loadStationStatusMap();
allList = filterNonAutoStationPaths(allList, statusMap);
+ stepCostMap.put("filterNonAutoStation", elapsedMillis(stepStartNs));
+ filteredCandidateCount = allList.size();
if (allList.isEmpty()) {
News.info("[WCS Debug] 绔欑偣璺緞鍊欓�夊叏閮ㄨ杩囨护锛屽瓨鍦ㄩ潪鑷姩绔欑偣,startStationId={},endStationId={}", startStationId, endStationId);
+ logStationPathSearchContextSlow(startStationId, endStationId, calcMode, lev, rawCandidateCount, filteredCandidateCount, stepCostMap, totalStartNs);
return StationPathSearchContext.empty(resolvedPolicy);
}
News.info("[WCS Debug] 绔欑偣璺緞璁＄畻瀹屾垚锛岃�楁椂锛歿}ms,startStationId={},endStationId={},mode={}",
@@ -2486,9 +2556,96 @@
startStationId,
endStationId,
calcMode == null ? "" : calcMode.name());
+ logStationPathSearchContextSlow(startStationId, endStationId, calcMode, lev, rawCandidateCount, filteredCandidateCount, stepCostMap, totalStartNs);
return new StationPathSearchContext(allList, resolvedPolicy);
}
+ private void logStationPathCalcSlow(Integer startStationId,
+ Integer endStationId,
+ Integer currentTaskNo,
+ Double pathLenFactor,
+ StationPathCalcMode calcMode,
+ String pathSource,
+ int candidateCount,
+ int resultPathLen,
+ Map<String, Long> stepCostMap,
+ long totalStartNs) {
+ long totalCostMs = elapsedMillis(totalStartNs);
+ if (totalCostMs < STATION_PATH_SLOW_LOG_THRESHOLD_MS) {
+ return;
+ }
+ News.warn("绔欑偣璺緞鎬昏绠楄�楁椂杈冮暱锛宻tartStationId={}锛宔ndStationId={}锛宼askNo={}锛宮ode={}锛宲athSource={}锛宲athLenFactor={}锛宑andidateCount={}锛宺esultPathLen={}锛宻tepCosts={}锛宼otalCost={}ms",
+ startStationId,
+ endStationId,
+ currentTaskNo,
+ calcMode == null ? "" : calcMode.name(),
+ pathSource,
+ pathLenFactor,
+ candidateCount,
+ resultPathLen,
+ JSON.toJSONString(stepCostMap),
+ totalCostMs);
+ }
+
+ private void logStationPathOrderSlow(Integer startStationId,
+ Integer endStationId,
+ Integer currentTaskNo,
+ Double pathLenFactor,
+ int candidateCount,
+ int filteredCandidateCount,
+ int metricsCount,
+ int orderedPathCount,
+ int skippedByLoopMergeGuard,
+ int skippedByOtherOutStation,
+ Map<String, Long> stepCostMap,
+ long totalStartNs) {
+ long totalCostMs = elapsedMillis(totalStartNs);
+ if (totalCostMs < STATION_PATH_SLOW_LOG_THRESHOLD_MS) {
+ return;
+ }
+ News.warn("绔欑偣璺緞鍊欓�夋帓搴忚�楁椂杈冮暱锛宻tartStationId={}锛宔ndStationId={}锛宼askNo={}锛宲athLenFactor={}锛宑andidateCount={}锛宖ilteredCandidateCount={}锛宮etricsCount={}锛宱rderedPathCount={}锛宻kippedByLoopMergeGuard={}锛宻kippedByOtherOutStation={}锛宻tepCosts={}锛宼otalCost={}ms",
+ startStationId,
+ endStationId,
+ currentTaskNo,
+ pathLenFactor,
+ candidateCount,
+ filteredCandidateCount,
+ metricsCount,
+ orderedPathCount,
+ skippedByLoopMergeGuard,
+ skippedByOtherOutStation,
+ JSON.toJSONString(stepCostMap),
+ totalCostMs);
+ }
+
+ private void logStationPathSearchContextSlow(Integer startStationId,
+ Integer endStationId,
+ StationPathCalcMode calcMode,
+ Integer lev,
+ int rawCandidateCount,
+ int filteredCandidateCount,
+ Map<String, Long> stepCostMap,
+ long totalStartNs) {
+ long totalCostMs = elapsedMillis(totalStartNs);
+ if (totalCostMs < STATION_PATH_SLOW_LOG_THRESHOLD_MS) {
+ return;
+ }
+ News.warn("绔欑偣璺緞鍊欓�夌敓鎴愯�楁椂杈冮暱锛宻tartStationId={}锛宔ndStationId={}锛宭ev={}锛宮ode={}锛宺awCandidateCount={}锛宖ilteredCandidateCount={}锛宻tepCosts={}锛宼otalCost={}ms",
+ startStationId,
+ endStationId,
+ lev,
+ calcMode == null ? "" : calcMode.name(),
+ rawCandidateCount,
+ filteredCandidateCount,
+ JSON.toJSONString(stepCostMap),
+ totalCostMs);
+ }
+
+ private long elapsedMillis(long startNs) {
+ long elapsedNs = System.nanoTime() - startNs;
+ return elapsedNs <= 0L ? 0L : elapsedNs / 1_000_000L;
+ }
+
private List<List<NavigateNode>> normalizeCandidatePaths(List<List<NavigateNode>> orderedPathList) {
List<List<NavigateNode>> result = new ArrayList<>();
if (orderedPathList == null || orderedPathList.isEmpty()) {
--
Gitblit v1.9.1