#入库命令耗时日志

Junjie

2026-04-13 1f50c0fecf326680485aa393e7dee27d356ca154

#入库命令耗时日志

 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) {
@@ -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("站点路径总计算耗时较长，startStationId={}，endStationId={}，taskNo={}，mode={}，pathSource={}，pathLenFactor={}，candidateCount={}，resultPathLen={}，stepCosts={}，totalCost={}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("站点路径候选排序耗时较长，startStationId={}，endStationId={}，taskNo={}，pathLenFactor={}，candidateCount={}，filteredCandidateCount={}，metricsCount={}，orderedPathCount={}，skippedByLoopMergeGuard={}，skippedByOtherOutStation={}，stepCosts={}，totalCost={}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("站点路径候选生成耗时较长，startStationId={}，endStationId={}，lev={}，mode={}，rawCandidateCount={}，filteredCandidateCount={}，stepCosts={}，totalCost={}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()) {