#入库命令耗时日志

Junjie

2026-04-13 f7009ef55b73941d904f57e642bbe30b86421634

#入库命令耗时日志

 src/main/java/com/zy/common/service/CommonService.java

@@ -33,6 +33,11 @@
public class CommonService {

    private static final long OUT_STATION_ROUTE_CACHE_SECONDS = 60 * 60 * 24 * 7;
    /**
     * 入库目标站的拓扑变化频率很低，允许使用 24h 缓存减少重复可达路径搜索。
     */
    private static final long IN_STATION_ROUTE_CACHE_SECONDS = 60 * 60 * 24;
    private static final long IN_STATION_ROUTE_SLOW_LOG_THRESHOLD_MS = 200L;

    @Autowired
    private WrkMastService wrkMastService;
@@ -677,27 +682,42 @@
    }

    public Integer findInStationId(FindCrnNoResult findCrnNoResult, Integer sourceStationId) {
        return resolveInStationId(findCrnNoResult, sourceStationId).getTargetStationId();
    }

    public InStationResolveResult resolveInStationId(FindCrnNoResult findCrnNoResult, Integer sourceStationId) {
        long resolveStartNs = System.nanoTime();
        if (findCrnNoResult == null || findCrnNoResult.getCrnType() == null
                || findCrnNoResult.getCrnNo() == null || sourceStationId == null) {
            return InStationResolveResult.empty(false, nanosToMillis(resolveStartNs));
        }
        List<StationObjModel> stationList = new ArrayList<>();
        Integer crnNo = findCrnNoResult.getCrnNo();
        if (findCrnNoResult.getCrnType().equals(SlaveType.Crn)) {
            BasCrnp basCrnp = basCrnpService.getOne(new QueryWrapper<BasCrnp>().eq("crn_no", crnNo));
            if(basCrnp == null) {
                return null;
                return InStationResolveResult.empty(false, nanosToMillis(resolveStartNs));
            }
            stationList = basCrnp.getInStationList$();
        } else if (findCrnNoResult.getCrnType().equals(SlaveType.DualCrn)) {
            BasDualCrnp basDualCrnp = basDualCrnpService.getOne(new QueryWrapper<BasDualCrnp>().eq("crn_no", crnNo));
            if(basDualCrnp == null) {
                return null;
                return InStationResolveResult.empty(false, nanosToMillis(resolveStartNs));
            }
            stationList = basDualCrnp.getInStationList$();
        }

        Integer cachedTargetStationId = resolveCachedInStationId(findCrnNoResult, sourceStationId, stationList);
        if (cachedTargetStationId != null) {
            return cachedTargetStationId;
            long totalCostMs = nanosToMillis(resolveStartNs);
            if (totalCostMs >= IN_STATION_ROUTE_SLOW_LOG_THRESHOLD_MS) {
                log.info("入库目标站缓存命中耗时较长，sourceStationId={}，crnNo={}，targetStationId={}，totalCost={}ms",
                        sourceStationId, crnNo, cachedTargetStationId, totalCostMs);
            }
            return InStationResolveResult.cacheHit(cachedTargetStationId, totalCostMs);
        }

        long searchStartNs = System.nanoTime();
        Integer targetStationId = null;
        for (StationObjModel stationObjModel : stationList) {
            try {
@@ -711,7 +731,11 @@
//                e.printStackTrace();
            }
        }
        return targetStationId;
        long searchCostMs = nanosToMillis(searchStartNs);
        long totalCostMs = nanosToMillis(resolveStartNs);
        log.info("入库目标站缓存未命中，sourceStationId={}，crnNo={}，targetStationId={}，searchCost={}ms，totalCost={}ms",
                sourceStationId, crnNo, targetStationId, searchCostMs, totalCostMs);
        return InStationResolveResult.searchResult(targetStationId, totalCostMs, searchCostMs);
    }

    public Integer findOutStationId(FindCrnNoResult findCrnNoResult, Integer targetStationId) {
@@ -792,7 +816,7 @@
        }
        redisUtil.set(buildInStationRouteCacheKey(findCrnNoResult, sourceStationId),
                targetStationId,
                OUT_STATION_ROUTE_CACHE_SECONDS);
                IN_STATION_ROUTE_CACHE_SECONDS);
    }

    private String buildInStationRouteCacheKey(FindCrnNoResult findCrnNoResult, Integer sourceStationId) {
@@ -873,4 +897,54 @@
        }
    }

    private long nanosToMillis(long startNs) {
        long elapsedNs = System.nanoTime() - startNs;
        return elapsedNs <= 0L ? 0L : elapsedNs / 1_000_000L;
    }

    public static class InStationResolveResult {
        private final Integer targetStationId;
        private final boolean cacheHit;
        private final long totalCostMs;
        private final long searchCostMs;

        private InStationResolveResult(Integer targetStationId,
                                       boolean cacheHit,
                                       long totalCostMs,
                                       long searchCostMs) {
            this.targetStationId = targetStationId;
            this.cacheHit = cacheHit;
            this.totalCostMs = totalCostMs;
            this.searchCostMs = searchCostMs;
        }

        public static InStationResolveResult cacheHit(Integer targetStationId, long totalCostMs) {
            return new InStationResolveResult(targetStationId, true, totalCostMs, 0L);
        }

        public static InStationResolveResult searchResult(Integer targetStationId, long totalCostMs, long searchCostMs) {
            return new InStationResolveResult(targetStationId, false, totalCostMs, searchCostMs);
        }

        public static InStationResolveResult empty(boolean cacheHit, long totalCostMs) {
            return new InStationResolveResult(null, cacheHit, totalCostMs, 0L);
        }

        public Integer getTargetStationId() {
            return targetStationId;
        }

        public boolean isCacheHit() {
            return cacheHit;
        }

        public long getTotalCostMs() {
            return totalCostMs;
        }

        public long getSearchCostMs() {
            return searchCostMs;
        }
    }

}

 src/main/java/com/zy/core/thread/impl/ZyStationV5Thread.java

@@ -50,6 +50,7 @@
    private static final int EXECUTOR_QUEUE_WARN_THRESHOLD = 20;
    private static final int EXECUTOR_ACTIVE_WARN_THRESHOLD = 48;
    private static final long SEGMENT_EXECUTE_WARN_MS = 10_000L;
    private static final long COMMAND_BUILD_WARN_MS = 500L;
    private static final int QUEUE_DRAIN_BATCH_SIZE = 32;
    private static final long QUEUE_IDLE_SLEEP_MS = 20L;

@@ -254,8 +255,25 @@
        stationCommand.setCommandType(commandType);

        if (commandType == StationCommandType.MOVE && !stationId.equals(targetStationId)) {
            long startNs = System.nanoTime();
            long calcPathStartNs = startNs;
            List<NavigateNode> nodes = calcPathNavigateNodes(taskNo, stationId, targetStationId, pathLenFactor);
            return fillMoveCommandPath(stationCommand, nodes, taskNo, stationId, targetStationId);
            long calcPathCostMs = nanosToMillis(System.nanoTime() - calcPathStartNs);
            long fillCommandStartNs = System.nanoTime();
            StationCommand builtCommand = fillMoveCommandPath(stationCommand, nodes, taskNo, stationId, targetStationId);
            long fillCommandCostMs = nanosToMillis(System.nanoTime() - fillCommandStartNs);
            long totalCostMs = nanosToMillis(System.nanoTime() - startNs);
            if (totalCostMs >= COMMAND_BUILD_WARN_MS) {
                log.warn("V5输送命令生成耗时较长，deviceNo={}, taskNo={}, stationId={}, targetStaNo={}, calcPath={}ms, fillCommand={}ms, total={}ms",
                        deviceConfig == null ? null : deviceConfig.getDeviceNo(),
                        taskNo,
                        stationId,
                        targetStationId,
                        calcPathCostMs,
                        fillCommandCostMs,
                        totalCostMs);
            }
            return builtCommand;
        }
        return stationCommand;
    }

 src/main/java/com/zy/core/utils/station/StationDispatchLoadSupport.java

@@ -24,6 +24,7 @@
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;

import java.util.ArrayList;
import java.util.List;
import java.util.Locale;
import java.util.Map;
@@ -143,27 +144,49 @@
            List<NavigateNode> nodes = wrkMast == null
                    ? navigateUtils.calcOptimalPathByStationId(sourceStationId, targetStationId, null, null)
                    : calcOutboundNavigatePath(wrkMast, sourceStationId, targetStationId, pathLenFactor);
            if (nodes == null || nodes.isEmpty()) {
                return LoopHitResult.noHit();
            }

            for (NavigateNode node : nodes) {
                Integer stationId = getStationIdFromNode(node);
                if (stationId == null) {
                    continue;
                }
                Integer loopNo = loadGuardState.getStationLoopNoMap().get(stationId);
                if (loopNo != null) {
                    return new LoopHitResult(true, loopNo, stationId);
                }
            }
            return findPathLoopHitByNavigateNodes(nodes, loadGuardState);
        } catch (Exception ignore) {
            return LoopHitResult.noHit();
        }
    }

    public LoopHitResult findPathLoopHitByNavigatePath(List<Integer> navigatePath,
                                                       LoadGuardState loadGuardState) {
        if (navigatePath == null || navigatePath.isEmpty()) {
            return LoopHitResult.noHit();
        }
        if (loadGuardState == null || loadGuardState.getStationLoopNoMap().isEmpty()) {
            return LoopHitResult.noHit();
        }

        for (Integer stationId : navigatePath) {
            if (stationId == null) {
                continue;
            }
            Integer loopNo = loadGuardState.getStationLoopNoMap().get(stationId);
            if (loopNo != null) {
                return new LoopHitResult(true, loopNo, stationId);
            }
        }
        return LoopHitResult.noHit();
    }

    public LoopHitResult findPathLoopHitByNavigateNodes(List<NavigateNode> nodes,
                                                        LoadGuardState loadGuardState) {
        if (nodes == null || nodes.isEmpty()) {
            return LoopHitResult.noHit();
        }

        List<Integer> navigatePath = new ArrayList<>();
        for (NavigateNode node : nodes) {
            Integer stationId = getStationIdFromNode(node);
            if (stationId != null) {
                navigatePath.add(stationId);
            }
        }
        return findPathLoopHitByNavigatePath(navigatePath, loadGuardState);
    }

    public void saveLoopLoadReserve(Integer wrkNo, LoopHitResult loopHitResult) {
        if (wrkNo == null || wrkNo <= 0 || loopHitResult == null || !loopHitResult.isThroughLoop()) {
            return;

 src/main/java/com/zy/core/utils/station/StationRegularDispatchProcessor.java

@@ -25,7 +25,6 @@
import com.zy.core.model.StationObjModel;
import com.zy.core.model.command.StationCommand;
import com.zy.core.model.protocol.StationProtocol;
import com.zy.core.model.protocol.StationTaskBufferItem;
import com.zy.core.move.StationMoveCoordinator;
import com.zy.core.thread.StationThread;
import com.zy.core.utils.station.model.DispatchLimitConfig;
@@ -41,6 +40,8 @@

@Component
public class StationRegularDispatchProcessor {

    private static final long STATION_IN_SLOW_LOG_THRESHOLD_MS = 500L;

    @Autowired
    private BasDevpService basDevpService;
@@ -265,86 +266,125 @@
        ) {
            return;
        }

        WrkMast wrkMast = wrkMastService.getOne(new QueryWrapper<WrkMast>().eq("barcode", stationProtocol.getBarcode()));
        if (wrkMast == null || !Objects.equals(wrkMast.getWrkSts(), WrkStsType.NEW_INBOUND.sts)) {
            return;
        }

        Integer crnNo = wrkMast.getCrnNo();
        BasCrnp basCrnp = basCrnpService.getOne(new QueryWrapper<BasCrnp>().eq("crn_no", crnNo));
        if (basCrnp == null) {
            News.taskInfo(wrkMast.getWrkNo(), "{}工作,未找到堆垛机数据", wrkMast.getWrkNo());
            return;
        }

        int maxInTask = 3;
        if (basCrnp.getMaxInTask() != null) {
            maxInTask = basCrnp.getMaxInTask();
        }

        long count = wrkMastService.count(new QueryWrapper<WrkMast>().eq("crn_no", crnNo).eq("wrk_sts", WrkStsType.INBOUND_STATION_RUN.sts));
        if(count >=  maxInTask) {
            News.taskInfo(wrkMast.getWrkNo(), "{}工作,堆垛机到达任务上限，稍后执行", wrkMast.getWrkNo());
            stationProtocol.setSystemWarning(wrkMast.getWrkNo() + "工作," + crnNo + "号堆垛机到达任务上限，稍后执行");
            return;
        }

        String locNo = wrkMast.getLocNo();
        FindCrnNoResult findCrnNoResult = commonService.findCrnNoByLocNo(locNo);
        if (findCrnNoResult == null) {
            News.taskInfo(wrkMast.getWrkNo(), "{}工作,未匹配到堆垛机", wrkMast.getWrkNo());
            return;
        }

        Integer targetStationId = commonService.findInStationId(findCrnNoResult, stationId);
        if (targetStationId == null) {
            News.taskInfo(wrkMast.getWrkNo(), "{}站点,搜索入库站点失败", stationId);
            return;
        }

        DispatchLimitConfig limitConfig = stationDispatchLoadSupport.getDispatchLimitConfig(stationProtocol.getStationId(), targetStationId);
        int currentStationTaskCount = stationDispatchLoadSupport.countCurrentStationTask();
        LoadGuardState loadGuardState = stationDispatchLoadSupport.buildLoadGuardState(limitConfig);
        LoopHitResult loopHitResult = stationDispatchLoadSupport.findPathLoopHit(
                limitConfig,
                stationProtocol.getStationId(),
                targetStationId,
                loadGuardState
        );
        if (stationDispatchLoadSupport.isDispatchBlocked(limitConfig, currentStationTaskCount, loadGuardState, loopHitResult.isThroughLoop())) {
            return;
        }

        StationCommand command = stationThread.getCommand(StationCommandType.MOVE, wrkMast.getWrkNo(), stationId, targetStationId, 0);
        if (command == null) {
            News.taskInfo(wrkMast.getWrkNo(), "{}工作,获取输送线命令失败", wrkMast.getWrkNo());
            return;
        }

        Date now = new Date();
        wrkMast.setWrkSts(WrkStsType.INBOUND_STATION_RUN.sts);
        wrkMast.setSourceStaNo(stationProtocol.getStationId());
        wrkMast.setStaNo(targetStationId);
        wrkMast.setSystemMsg("");
        wrkMast.setIoTime(now);
        wrkMast.setModiTime(now);
        if (wrkMastService.updateById(wrkMast)) {
            wrkAnalysisService.markInboundStationStart(wrkMast, now);
            boolean offered = offerDevpCommandWithDedup(basDevp.getDevpNo(), command, "stationInExecute");
            if (offered && stationMoveCoordinator != null) {
                stationMoveCoordinator.recordDispatch(
                        wrkMast.getWrkNo(),
                        stationProtocol.getStationId(),
                        "stationInExecute",
                        command,
                        false
                );
        long totalStartNs = System.nanoTime();
        Map<String, Long> stepCostMap = new java.util.LinkedHashMap<>();
        WrkMast wrkMast = null;
        Integer targetStationId = null;
        String targetSource = "unknown";
        String locNo = null;
        try {
            long stepStartNs = System.nanoTime();
            wrkMast = wrkMastService.getOne(new QueryWrapper<WrkMast>().eq("barcode", stationProtocol.getBarcode()));
            stepCostMap.put("loadWrkByBarcode", elapsedMillis(stepStartNs));
            if (wrkMast == null || !Objects.equals(wrkMast.getWrkSts(), WrkStsType.NEW_INBOUND.sts)) {
                return;
            }
            News.info("输送站点入库命令下发成功，站点号={}，工作号={}，命令数据={}", stationId, wrkMast.getWrkNo(), JSON.toJSONString(command));
            redisUtil.set(RedisKeyType.STATION_IN_EXECUTE_LIMIT.key + stationId, "lock", 5);
            loadGuardState.reserveLoopTask(loopHitResult.getLoopNo());
            stationDispatchLoadSupport.saveLoopLoadReserve(wrkMast.getWrkNo(), loopHitResult);

            Integer crnNo = wrkMast.getCrnNo();
            BasCrnp basCrnp = basCrnpService.getOne(new QueryWrapper<BasCrnp>().eq("crn_no", crnNo));
            if (basCrnp == null) {
                News.taskInfo(wrkMast.getWrkNo(), "{}工作,未找到堆垛机数据", wrkMast.getWrkNo());
                return;
            }

            int maxInTask = 3;
            if (basCrnp.getMaxInTask() != null) {
                maxInTask = basCrnp.getMaxInTask();
            }

            stepStartNs = System.nanoTime();
            long count = wrkMastService.count(new QueryWrapper<WrkMast>().eq("crn_no", crnNo).eq("wrk_sts", WrkStsType.INBOUND_STATION_RUN.sts));
            stepCostMap.put("countCrnInboundRunTask", elapsedMillis(stepStartNs));
            if(count >=  maxInTask) {
                News.taskInfo(wrkMast.getWrkNo(), "{}工作,堆垛机到达任务上限，稍后执行", wrkMast.getWrkNo());
                stationProtocol.setSystemWarning(wrkMast.getWrkNo() + "工作," + crnNo + "号堆垛机到达任务上限，稍后执行");
                return;
            }

            locNo = wrkMast.getLocNo();
            stepStartNs = System.nanoTime();
            FindCrnNoResult findCrnNoResult = commonService.findCrnNoByLocNo(locNo);
            stepCostMap.put("resolveCrnByLocNo", elapsedMillis(stepStartNs));
            if (findCrnNoResult == null) {
                News.taskInfo(wrkMast.getWrkNo(), "{}工作,未匹配到堆垛机", wrkMast.getWrkNo());
                return;
            }

            stepStartNs = System.nanoTime();
            CommonService.InStationResolveResult resolveResult = commonService.resolveInStationId(findCrnNoResult, stationId);
            stepCostMap.put("resolveInboundTargetStation", elapsedMillis(stepStartNs));
            targetStationId = resolveResult == null ? null : resolveResult.getTargetStationId();
            targetSource = resolveResult == null ? "unknown" : (resolveResult.isCacheHit() ? "cache" : "search");
            if (targetStationId == null) {
                News.taskInfo(wrkMast.getWrkNo(), "{}站点,搜索入库站点失败", stationId);
                return;
            }

            stepStartNs = System.nanoTime();
            DispatchLimitConfig limitConfig = stationDispatchLoadSupport.getDispatchLimitConfig(stationProtocol.getStationId(), targetStationId);
            int currentStationTaskCount = stationDispatchLoadSupport.countCurrentStationTask();
            LoadGuardState loadGuardState = stationDispatchLoadSupport.buildLoadGuardState(limitConfig);
            stepCostMap.put("buildLoopGuardState", elapsedMillis(stepStartNs));

            stepStartNs = System.nanoTime();
            StationCommand command = stationThread.getCommand(StationCommandType.MOVE, wrkMast.getWrkNo(), stationId, targetStationId, 0);
            stepCostMap.put("buildMoveCommand", elapsedMillis(stepStartNs));
            if (command == null) {
                News.taskInfo(wrkMast.getWrkNo(), "{}工作,获取输送线命令失败", wrkMast.getWrkNo());
                return;
            }

            stepStartNs = System.nanoTime();
            LoopHitResult loopHitResult = stationDispatchLoadSupport.findPathLoopHitByNavigatePath(command.getNavigatePath(), loadGuardState);
            stepCostMap.put("evaluateLoopPath", elapsedMillis(stepStartNs));
            if (stationDispatchLoadSupport.isDispatchBlocked(limitConfig, currentStationTaskCount, loadGuardState, loopHitResult.isThroughLoop())) {
                return;
            }

            stepStartNs = System.nanoTime();
            Date now = new Date();
            wrkMast.setWrkSts(WrkStsType.INBOUND_STATION_RUN.sts);
            wrkMast.setSourceStaNo(stationProtocol.getStationId());
            wrkMast.setStaNo(targetStationId);
            wrkMast.setSystemMsg("");
            wrkMast.setIoTime(now);
            wrkMast.setModiTime(now);
            if (wrkMastService.updateById(wrkMast)) {
                wrkAnalysisService.markInboundStationStart(wrkMast, now);
                boolean offered = offerDevpCommandWithDedup(basDevp.getDevpNo(), command, "stationInExecute");
                if (offered && stationMoveCoordinator != null) {
                    stationMoveCoordinator.recordDispatch(
                            wrkMast.getWrkNo(),
                            stationProtocol.getStationId(),
                            "stationInExecute",
                            command,
                            false
                    );
                }
                News.info("输送站点入库命令下发成功，站点号={}，工作号={}，命令数据={}", stationId, wrkMast.getWrkNo(), JSON.toJSONString(command));
                redisUtil.set(RedisKeyType.STATION_IN_EXECUTE_LIMIT.key + stationId, "lock", 5);
                loadGuardState.reserveLoopTask(loopHitResult.getLoopNo());
                stationDispatchLoadSupport.saveLoopLoadReserve(wrkMast.getWrkNo(), loopHitResult);
            }
            stepCostMap.put("updateWrkAndDispatch", elapsedMillis(stepStartNs));
        } finally {
            long totalCostMs = elapsedMillis(totalStartNs);
            if (totalCostMs >= STATION_IN_SLOW_LOG_THRESHOLD_MS) {
                News.warn("stationInExecute耗时较长，stationId={}，barcode={}，wrkNo={}，locNo={}，targetStaNo={}，targetSource={}，stepCosts={}，totalCost={}ms",
                        stationId,
                        stationProtocol.getBarcode(),
                        wrkMast == null ? null : wrkMast.getWrkNo(),
                        locNo,
                        targetStationId,
                        targetSource,
                        JSON.toJSONString(stepCostMap),
                        totalCostMs);
            }
        }
    }

    private long elapsedMillis(long startNs) {
        long elapsedNs = System.nanoTime() - startNs;
        return elapsedNs <= 0L ? 0L : elapsedNs / 1_000_000L;
    }
}