新增组件拉取处理日志记录

cf-module-prod-plan/cf-module-prod-plan-biz/src/main/java/com/cf/imes/module/plan/service/orderImport/factory/ProducingOrderImportFactory.java

@@ -180,6 +180,23 @@ public class ProducingOrderImportFactory {
     private List<OrderComponentDO> orderComponentDOS = new ArrayList<>();
     private List<SystemConfigSealEdgeRespDTO> sealEdgeConfigList;
 
+    // 板件阶段明细耗时，仅用于一次导入请求内的性能定位。
+    private long plateObjectBuildNanos;
+    private long customPlateNoNanos;
+    private long plateModelBuildNanos;
+    private long plateModelJsonNanos;
+    private long plateRelationBuildNanos;
+    private long plateBatchNanos;
+    private long plateModelCompressionNanos;
+    private long itemBatchNanos;
+    private long partBatchNanos;
+    private int plateBatchCount;
+    private int plateBatchRows;
+    private int itemBatchCount;
+    private int itemBatchRows;
+    private int partBatchCount;
+    private int partBatchRows;
+
     private static final String PART_CATEGORY_ONE = "封边条";
     private static final String PART_CATEGORY_TWO = "五金";
     private static final String PART_CATEGORY_THREE = "组件";
@@ -310,14 +327,26 @@ public class ProducingOrderImportFactory {
             // 解析板件列表
             stageStartedAt = System.nanoTime();
             analyzeBlockList(producingImportData.getBlocks());
+            long platesElapsedNanos = System.nanoTime() - stageStartedAt;
             logStage("plates", stageStartedAt);
+            logPlatePerformanceDetail(platesElapsedNanos);
             log.debug("====================【cad拆单解析板件结束】====================");
 
             log.debug("====================【cad拆单解析配件开始】====================");
             // 解析配件列表
+            long itemBatchBeforeParts = itemBatchNanos;
+            long partBatchBeforeParts = partBatchNanos;
+            int itemRowsBeforeParts = itemBatchRows;
+            int partRowsBeforeParts = partBatchRows;
             stageStartedAt = System.nanoTime();
             analyzeParts(producingImportData.getParts());
+            long partsElapsedNanos = System.nanoTime() - stageStartedAt;
             logStage("parts", stageStartedAt);
+            logPartsPerformanceDetail(partsElapsedNanos,
+                    itemBatchNanos - itemBatchBeforeParts,
+                    partBatchNanos - partBatchBeforeParts,
+                    itemBatchRows - itemRowsBeforeParts,
+                    partBatchRows - partRowsBeforeParts);
             log.debug("====================【cad拆单解析配件结束】====================");
 
             // 部件入库
@@ -328,6 +357,7 @@ public class ProducingOrderImportFactory {
             stageStartedAt = System.nanoTime();
             orderItemBatchInsertWithinThreshold(orderItemDOS, true);
             logStage("item-insert", stageStartedAt);
+            logBatchPerformanceSummary();
             log.debug("====================【cad拆单全局保存开始】====================");
 
             // 保存数据柜体、加工组
@@ -389,6 +419,72 @@ public class ProducingOrderImportFactory {
         return (System.nanoTime() - startedAt) / 1_000_000;
     }
 
+    /**
+     * 输出板件阶段的纯计算和批量写库累计耗时，避免逐板打印日志。
+     */
+    private void logPlatePerformanceDetail(long platesElapsedNanos) {
+        long plateBatchWithoutCompression =
+                Math.max(0L, plateBatchNanos - plateModelCompressionNanos);
+        long accountedNanos = plateObjectBuildNanos + customPlateNoNanos
+                + plateModelBuildNanos + plateModelJsonNanos + plateRelationBuildNanos
+                + plateBatchNanos + itemBatchNanos;
+        log.info("[producing-import-plate-detail] orderId={} totalMs={} otherMs={} "
+                        + "plateRows={} plateBatches={} "
+                        + "objectBuildMs={} customPlateNoMs={} modelBuildMs={} modelJsonMs={} "
+                        + "relationBuildMs={} modelCompressMs={} plateDbAndBindMs={} "
+                        + "itemBatchMs={} itemBatchRows={} itemBatches={}",
+                orderId, nanosToMillis(platesElapsedNanos),
+                nanosToMillis(Math.max(0L, platesElapsedNanos - accountedNanos)),
+                plateBatchRows, plateBatchCount,
+                nanosToMillis(plateObjectBuildNanos),
+                nanosToMillis(customPlateNoNanos),
+                nanosToMillis(plateModelBuildNanos),
+                nanosToMillis(plateModelJsonNanos),
+                nanosToMillis(plateRelationBuildNanos),
+                nanosToMillis(plateModelCompressionNanos),
+                nanosToMillis(plateBatchWithoutCompression),
+                nanosToMillis(itemBatchNanos), itemBatchRows, itemBatchCount);
+    }
+
+    /**
+     * 输出配件阶段中纯计算与批量写库的拆分耗时。
+     */
+    private void logPartsPerformanceDetail(long partsElapsedNanos,
+                                           long itemBatchElapsedNanos,
+                                           long partBatchElapsedNanos,
+                                           int itemRows,
+                                           int partRows) {
+        long computeNanos = Math.max(0L,
+                partsElapsedNanos - itemBatchElapsedNanos - partBatchElapsedNanos);
+        log.info("[producing-import-part-detail] orderId={} totalMs={} computeMs={} "
+                        + "itemBatchMs={} itemRows={} partBatchMs={} partRows={}",
+                orderId, nanosToMillis(partsElapsedNanos), nanosToMillis(computeNanos),
+                nanosToMillis(itemBatchElapsedNanos), itemRows,
+                nanosToMillis(partBatchElapsedNanos), partRows);
+    }
+
+    /**
+     * 输出本次导入各张明细表的批量写入总量和总耗时。
+     */
+    private void logBatchPerformanceSummary() {
+        log.info("[producing-import-batch-summary] orderId={} "
+                        + "plateRows={} plateBatches={} plateBatchMs={} modelCompressMs={} "
+                        + "itemRows={} itemBatches={} itemBatchMs={} "
+                        + "partRows={} partBatches={} partBatchMs={}",
+                orderId,
+                plateBatchRows, plateBatchCount, nanosToMillis(plateBatchNanos),
+                nanosToMillis(plateModelCompressionNanos),
+                itemBatchRows, itemBatchCount, nanosToMillis(itemBatchNanos),
+                partBatchRows, partBatchCount, nanosToMillis(partBatchNanos));
+    }
+
+    /**
+     * 将累计纳秒转换为毫秒。
+     */
+    private long nanosToMillis(long nanos) {
+        return nanos / 1_000_000;
+    }
+
     /**
      * 获取组织封边条对应配置
      */
@@ -612,8 +708,10 @@ public class ProducingOrderImportFactory {
             return;
         }
         // 1、构建树 + 生成结构hash
+        long detailStartedAt = System.nanoTime();
         List<OrderComponentTreeCompareVO> roots =
                 buildTree(componentGroupReqVOS);
+        logStage("components-build-tree", detailStartedAt);
 
         // 2、查询装配配置
         List<String> names = roots.stream()
@@ -622,8 +720,10 @@ public class ProducingOrderImportFactory {
                 .toList();
 
 
+        detailStartedAt = System.nanoTime();
         CommonResult<List<AssemblyConfigRespDTO>> configResult =
                 assemblyConfigApi.getNotProcessAssemblyConfigByPartNameList(names);
+        logStage("components-config-query", detailStartedAt);
 
         if (configResult.isError()) {
             throw new ServiceException(
@@ -632,11 +732,15 @@ public class ProducingOrderImportFactory {
         }
 
         // 3、刷新组件状态
+        detailStartedAt = System.nanoTime();
         refreshComponentStatus(roots, configResult.getData());
+        logStage("components-refresh-status", detailStartedAt);
 
+        detailStartedAt = System.nanoTime();
         for (OrderComponentTreeCompareVO root : roots) {
             createAndCacheComponent(root, null, null, 0);
         }
+        logStage("components-cache", detailStartedAt);
     }
 
     /**
@@ -936,10 +1040,13 @@ public class ProducingOrderImportFactory {
             return;
         }
         // 获取自定义板编号配置
+        long detailStartedAt = System.nanoTime();
         plateNoGenerateConfigVO = customPlateNoGenerateService.getPlateNoGenerateConfig(orderId);
+        logStage("plates-custom-no-config", detailStartedAt);
 
         // 一次性查询目标订单的全部已有房间，供板件和配件导入共同复用。
         // 配件可能位于本次板件数据未包含的房间，因此这里不能只按本次报文房间名查询。
+        detailStartedAt = System.nanoTime();
         existRoomIdMap = orderBodyMapper.selectMaps(
                         new QueryWrapper<OrderBodyDO>()
                                 .select("room_name,MIN(room_id) as room_id")
@@ -951,6 +1058,7 @@ public class ProducingOrderImportFactory {
                         m -> String.valueOf(m.get(ROOM_NAME_FIELD)),
                         m -> ((Number) m.get("room_id")).longValue()
                 ));
+        logStage("plates-existing-rooms", detailStartedAt);
 
         for (ProducingImportRoomTree room : douleRoomTree) {
             // 房间名
@@ -1042,6 +1150,7 @@ public class ProducingOrderImportFactory {
      * @param block
      */
     private void createPlate(OrderBodyDO orderBodyDO, ProducingImportBlock block) {
+        long objectBuildStartedAt = System.nanoTime();
         // 是否异形
         Boolean isSpecialShape = block.isSpecialShape();
         // 是否侧面造型
@@ -1145,6 +1254,7 @@ public class ProducingOrderImportFactory {
         plateDO.setUpdater(operatorName);
         plateDO.setCreateTime(now);
         plateDO.setUpdateTime(now);
+        plateObjectBuildNanos += System.nanoTime() - objectBuildStartedAt;
 
         //批量保存板件
         // 达到板件数量阈值，停止入库，更新全局参数停止后续入库
@@ -1157,22 +1267,33 @@ public class ProducingOrderImportFactory {
         // 生成自定义板编号
         plateDO.setRoomName(orderBodyDO.getRoomName());
         plateDO.setBodyName(orderBodyDO.getName());
+        long customPlateNoStartedAt = System.nanoTime();
         generateCustomPlateNo(plateDO, block.getCustBlockNo());
+        customPlateNoNanos += System.nanoTime() - customPlateNoStartedAt;
 
         // 更新房间下板件和异形的数量
         orderBodyDO.setPlateNum(orderBodyDO.getPlateNum() + 1);
         orderBodyDO.setUnregularNum(orderBodyDO.getUnregularNum() + BooleanUtil.toInt(isSpecialShape));
 
         // 创建造型数据
+        long modelBuildStartedAt = System.nanoTime();
         OrderModelDO orderModelDO = createModel(plateDO, block, plateRemark);
+        plateModelBuildNanos += System.nanoTime() - modelBuildStartedAt;
+        long modelJsonStartedAt = System.nanoTime();
         plateDO.setModelData(JsonUtils.toJsonString(orderModelDO));
+        plateModelJsonNanos += System.nanoTime() - modelJsonStartedAt;
 
         plateDOS.add(plateDO);
         blockSerialNoMap.put(block.getSourceBlockItemId(), plateDO.getPlateNo());
         orderPlateBatchInsertWithinThreshold(plateDOS, false);
 
         // 遍历加工组信息，生成对应的加工组和item
+        long relationStartedAt = System.nanoTime();
+        long itemBatchBefore = itemBatchNanos;
         analyzeBlockProcessGroup(orderBodyDO, block, plateId);
+        long relationElapsed = System.nanoTime() - relationStartedAt;
+        plateRelationBuildNanos += Math.max(0L,
+                relationElapsed - (itemBatchNanos - itemBatchBefore));
     }
 
     /**
@@ -2268,6 +2389,9 @@ public class ProducingOrderImportFactory {
     private void orderPlateBatchInsertWithinThreshold(List<PlateDO> list, boolean isLast) {
         // 达到批量的阈值就做一次插入
         if (CollUtil.isNotEmpty(list) && (list.size() >= BATCH_THRESHOLD_NUMBER || isLast)) {
+            int batchRows = list.size();
+            long batchStartedAt = System.nanoTime();
+            long[] compressionNanos = {0L};
             String sql = "INSERT INTO order_plate  (id,organ_id,order_id,name,plate_no,type,goods_id,width,height,thickness,split_width,split_height,split_thickness,seal_left,seal_right,seal_up,seal_down,area,texture,hole_face,hole_arrange,unregular_point_count,front_hole_count,back_hole_count,side_hole_count,front_model_count,back_model_count,is_door,open_door_type,offset_x,offset_y,is_arc_across,module_type_id,is_special_shaped,is_sculpt,is_side_sculpt,is_2v,is_side_2v,is_row_hole,is_optimized,is_cutted,filter_type,remark,is_cancel,deleted,custom_plate_no,create_time,update_time,creator,updater, cad_plate_no, model_data, reserved_edge_left, reserved_edge_right, reserved_edge_up, reserved_edge_down, source_block_item_id) VALUES    (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)";
             jdbcTemplate.batchUpdate(sql, new BatchPreparedStatementSetter() {
                 /** {@inheritDoc} */
@@ -2328,7 +2452,9 @@ public class ProducingOrderImportFactory {
 
                     String modelData = item.getModelData();
                     if (StringUtils.isNotEmpty(modelData)) {
+                        long compressionStartedAt = System.nanoTime();
                         ps.setString(52, JsonUtils.zipString(modelData));
+                        compressionNanos[0] += System.nanoTime() - compressionStartedAt;
                     } else {
                         ps.setNull(52, Types.BLOB);
                     }
@@ -2345,6 +2471,17 @@ public class ProducingOrderImportFactory {
                     return list.size();
                 }
             });
+            long batchElapsed = System.nanoTime() - batchStartedAt;
+            plateBatchNanos += batchElapsed;
+            plateModelCompressionNanos += compressionNanos[0];
+            plateBatchCount++;
+            plateBatchRows += batchRows;
+            log.info("[producing-import-batch] orderId={} table=order_plate batch={} rows={} "
+                            + "elapsedMs={} modelCompressMs={} dbAndBindMs={}",
+                    orderId, plateBatchCount, batchRows,
+                    nanosToMillis(batchElapsed),
+                    nanosToMillis(compressionNanos[0]),
+                    nanosToMillis(Math.max(0L, batchElapsed - compressionNanos[0])));
 
 
             if (!isLast) {
@@ -2370,6 +2507,8 @@ public class ProducingOrderImportFactory {
     private void orderItemBatchInsertWithinThreshold(List<OrderItemDO> list, boolean isLast) {
         // 达到批量的阈值就做一次插入
         if (CollUtil.isNotEmpty(list) && (list.size() >= BATCH_THRESHOLD_NUMBER || isLast)) {
+            int batchRows = list.size();
+            long batchStartedAt = System.nanoTime();
 
             String sql = "INSERT INTO order_item (id,order_id,type,room_id,body_id,package_id,group_id,plate_id,parts_id,num,organ_id,comp_id,cad_view_id,source_parts_item_id) VALUES    (?,?,?,?,?,?,?,?,?,?,?,?,?,?)";
             jdbcTemplate.batchUpdate(sql, new BatchPreparedStatementSetter() {
@@ -2415,6 +2554,12 @@ public class ProducingOrderImportFactory {
                     return list.size();
                 }
             });
+            long batchElapsed = System.nanoTime() - batchStartedAt;
+            itemBatchNanos += batchElapsed;
+            itemBatchCount++;
+            itemBatchRows += batchRows;
+            log.info("[producing-import-batch] orderId={} table=order_item batch={} rows={} elapsedMs={}",
+                    orderId, itemBatchCount, batchRows, nanosToMillis(batchElapsed));
 
 
             if (!isLast) {
@@ -2440,6 +2585,8 @@ public class ProducingOrderImportFactory {
     private void orderPartBatchInsertWithinThreshold(List<OrderPartsDO> list, boolean isLast) {
         // 达到批量的阈值就做一次插入
         if (CollUtil.isNotEmpty(list) && (list.size() >= BATCH_THRESHOLD_NUMBER || isLast)) {
+            int batchRows = list.size();
+            long batchStartedAt = System.nanoTime();
 
             String sql = "INSERT INTO order_parts (id,organ_id,order_id,goods_id,name,color,material,category,type,width,length,thickness,model,spec,brand,factory,unit,price,is_composite,subparts,remark,deleted,create_time,update_time,creator,updater) VALUES    (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)";
             jdbcTemplate.batchUpdate(sql, new BatchPreparedStatementSetter() {
@@ -2481,6 +2628,12 @@ public class ProducingOrderImportFactory {
                     return list.size();
                 }
             });
+            long batchElapsed = System.nanoTime() - batchStartedAt;
+            partBatchNanos += batchElapsed;
+            partBatchCount++;
+            partBatchRows += batchRows;
+            log.info("[producing-import-batch] orderId={} table=order_parts batch={} rows={} elapsedMs={}",
+                    orderId, partBatchCount, batchRows, nanosToMillis(batchElapsed));
 
 
             if (!isLast) {