[哈工大] Apulis 每50个step 训练阻塞，导致训练速度过慢

Environment
Environment(Ascend/GPU/CPU):
-- ascend 910
-- Apulis

Software Environment:
-- Python 3.7.5
-- GCC 7.5.0

代码写法：
```
    init = tf.global_variables_initializer()

config = tf.ConfigProto()
    custom_op = config.graph_options.rewrite_options.custom_optimizers.add()
    custom_op.name = "NpuOptimizer"
    custom_op.parameter_map["use_off_line"].b = True  # 在昇腾AI处理器执行训练
    config.graph_options.rewrite_options.remapping = RewriterConfig.OFF  # 关闭remap开关

with tf.Session(config=config) as sess:
        train_data_generator = train_loader
        val_data_generator = val_loader
        if args.model_checkpoint_path is not None:
            saver.restore(sess, args.model_checkpoint_path)
            print("load model from {}".format(args.model_checkpoint_path))
        else:
            sess.run(init)
        write = tf.summary.FileWriter(train_logs_dir, sess.graph)
        for step in range(args.TRAIN_MAX_STEPS):

template_batch, search_batch, label_cls_batch, label_loc_batch, label_loc_weight_batch, \
            label_mask_batch, label_mask_weight_batch = next(train_data_generator)

train_feed_dict = {template: template_batch,
                               search: search_batch,
                               label_cls: label_cls_batch,
                               label_loc: label_loc_batch,
                               label_loc_weight: label_loc_weight_batch,
                               label_mask: label_mask_batch,
                               label_mask_weight: label_mask_weight_batch
                               }

summery, loss_val, rpn_cls_loss_val, rpn_loc_loss_val, rpn_mask_loss_val, train_op_val = sess.run(
                [merged, loss, rpn_cls_loss, rpn_loc_loss, rpn_mask_loss, train_op],
                feed_dict=train_feed_dict)
            print(
                "step : {} >>>>>>>>>>>>loss_val : {}， rpn_cls_loss : {}， rpn_loc_loss : {}，rpn_mask_loss : {}".format(
                    step,
                    loss_val,
                    rpn_cls_loss_val,
                    rpn_loc_loss_val,
                    rpn_mask_loss_val,
                ))
       
            write.add_summary(summery, step)
            if step % 1000 == 0:
                saver.save(sess, os.path.join(args.CHECKPOINTS_OUTPUT_DIR,
       
```

运行现象：代码当中没有50相关的代码，但是每50个step就会阻塞，停下来报tf_adapter/kernels/geop_npu.cc，训练50个step的时间是2S左右，但是停下来报tf_adapter/kernels/geop_npu.cc的时间可能超过20分钟，相关日志如下：
```
2020-12-16 06:10:30.977578: I tf_adapter/kernels/geop_npu.cc:76] BuildOutputTensorInfo, num_outputs:8
2020-12-16 06:10:30.977764: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:0, total_bytes:4, shape:, tensor_ptr:281431438791680, output281431438839104
2020-12-16 06:10:30.977805: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:1, total_bytes:4, shape:, tensor_ptr:281431438791872, output281429572058992
2020-12-16 06:10:30.977829: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:2, total_bytes:4, shape:, tensor_ptr:281431438792000, output281431438838240
2020-12-16 06:10:30.977855: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:3, total_bytes:4, shape:, tensor_ptr:281431438840768, output281431438837376
2020-12-16 06:10:30.977876: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:4, total_bytes:4, shape:, tensor_ptr:281431438840832, output281431438837696
2020-12-16 06:10:30.977898: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:5, total_bytes:4, shape:, tensor_ptr:281431438841024, output281431438838720
2020-12-16 06:10:30.977918: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:6, total_bytes:4, shape:, tensor_ptr:281431438841152, output281431438837568
2020-12-16 06:10:30.977945: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:7, total_bytes:4, shape:, tensor_ptr:281431438841344, output281431438840544
2020-12-16 06:10:30.977971: I tf_adapter/kernels/geop_npu.cc:573] [GEOP] RunGraphAsync callback, status:0, kernel_name:GeOp3_0[ 27947404us]
》》》》》》》》》》》》上面是上一次报的tf_adapter/kernels/geop_npu.cc

step : 852 >>>>>>>>>>>>loss_val : 15.878068923950195， rpn_cls_loss : 0.756157398223877， rpn_loc_loss : 0.7279908657073975，rpn_mask_loss : 0.39578673243522644
step : 853 >>>>>>>>>>>>loss_val : 13.455028533935547， rpn_cls_loss : 0.6305966377258301， rpn_loc_loss : 0.32987886667251587，rpn_mask_loss : 0.34523826837539673

.
. 重复打印训练结果
.

step : 900 >>>>>>>>>>>>loss_val : 14.225655555725098， rpn_cls_loss : 0.6576089859008789， rpn_loc_loss : 0.3688529133796692，rpn_mask_loss : 0.36459508538246155
step : 901 >>>>>>>>>>>>loss_val : 14.359504699707031， rpn_cls_loss : 0.7054455280303955， rpn_loc_loss : 0.49630972743034363，rpn_mask_loss : 0.36273574829101562020-12-16 06:10:32.375333: I

》》》》》》》》》》》》下面是接着报的tf_adapter/kernels/geop_npu.cc

tf_adapter/kernels/geop_npu.cc:388] [GEOP] Begin GeOp::ComputeAsync, kernel_name:GeOp3_0, num_inputs:7, num_outputs:8
2020-12-16 06:10:32.375544: I tf_adapter/kernels/geop_npu.cc:260] [GEOP] tf session direct795b320e370623a6, graph id: 11 no need to rebuild
2020-12-16 06:10:32.375943: I tf_adapter/kernels/geop_npu.cc:580] [GEOP] Call ge session RunGraphAsync, kernel_name:GeOp3_0 ,tf session: direct795b320e370623a6 ,graph id: 11
2020-12-16 06:10:32.376108: I tf_adapter/kernels/geop_npu.cc:593] [GEOP] End GeOp::ComputeAsync, kernel_name:GeOp3_0, ret_status:success ,tf session: direct795b320e370623a6 ,graph id: 11 [0 ms]
2020-12-16 06:11:00.323856: I tf_adapter/kernels/geop_npu.cc:76] BuildOutputTensorInfo, num_outputs:8
2020-12-16 06:11:00.323973: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:0, total_bytes:4, shape:, tensor_ptr:281431438841984, output281431438840256
2020-12-16 06:11:00.323992: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:1, total_bytes:4, shape:, tensor_ptr:281431438842112, output281461175288176
2020-12-16 06:11:00.324003: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:2, total_bytes:4, shape:, tensor_ptr:281431438842304, output281431438839392
2020-12-16 06:11:00.324015: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:3, total_bytes:4, shape:, tensor_ptr:281431438842368, output281431438839872
2020-12-16 06:11:00.324025: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:4, total_bytes:4, shape:, tensor_ptr:281431438842560, output281431438838528
2020-12-16 06:11:00.324036: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:5, total_bytes:4, shape:, tensor_ptr:281431438842688, output281431438839680
2020-12-16 06:11:00.324050: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:6, total_bytes:4, shape:, tensor_ptr:281431438842880, output281431438840000
2020-12-16 06:11:00.324060: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:7, total_bytes:4, shape:, tensor_ptr:281431438842944, output281431438841120
2020-12-16 06:11:00.324076: I tf_adapter/kernels/geop_npu.cc:573] [GEOP] RunGraphAsync callback, status:0, kernel_name:GeOp3_0[ 27948382us]
2020-12-16 06:11:01.636396: I tf_adapter/kernels/geop_npu.cc:388] [GEOP] Begin GeOp::ComputeAsync, kernel_name:GeOp3_0, num_inputs:7, num_outputs:8
2020-12-16 06:11:01.636624: I tf_adapter/kernels/geop_npu.cc:260] [GEOP] tf session direct795b320e370623a6, graph id: 11 no need to rebuild
2020-12-16 06:11:01.637015: I tf_adapter/kernels/geop_npu.cc:580] [GEOP] Call ge session RunGraphAsync, kernel_name:GeOp3_0 ,tf session: direct795b320e370623a6 ,graph id: 11
2020-12-16 06:11:01.637194: I tf_adapter/kernels/geop_npu.cc:593] [GEOP] End GeOp::ComputeAsync, kernel_name:GeOp3_0, ret_status:success ,tf session: direct795b320e370623a6 ,graph id: 11 [0 ms]
2020-12-16 06:11:29.568243: I tf_adapter/kernels/geop_npu.cc:76] BuildOutputTensorInfo, num_outputs:8
2020-12-16 06:11:29.568421: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:0, total_bytes:4, shape:, tensor_ptr:281431438843136, output281431438837568
2020-12-16 06:11:29.568458: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:1, total_bytes:4, shape:, tensor_ptr:281431438843264, output281429423151760
2020-12-16 06:11:29.568481: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:2, total_bytes:4, shape:, tensor_ptr:281431438843456, output281431438838720
2020-12-16 06:11:29.568502: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:3, total_bytes:4, shape:, tensor_ptr:281431438843520, output281431438840544
2020-12-16 06:11:29.568524: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:4, total_bytes:4, shape:, tensor_ptr:281431438843712, output281431438841024
2020-12-16 06:11:29.568589: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:5, total_bytes:4, shape:, tensor_ptr:281431438843840, output281431438830208
2020-12-16 06:11:29.568615: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:6, total_bytes:4, shape:, tensor_ptr:281431438844032, output281431438791872
2020-12-16 06:11:29.568635: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:7, total_bytes:4, shape:, tensor_ptr:281431438844096, output281431438842656
2020-12-16 06:11:29.568660: I tf_adapter/kernels/geop_npu.cc:573] [GEOP] RunGraphAsync callback, status:0, kernel_name:GeOp3_0[ 27931890us]
2020-12-16 06:11:31.163086: I tf_adapter/kernels/geop_npu.cc:388] [GEOP] Begin GeOp::ComputeAsync, kernel_name:GeOp3_0, num_inputs:7, num_outputs:8
2020-12-16 06:11:31.163335: I tf_adapter/kernels/geop_npu.cc:260] [GEOP] tf session direct795b320e370623a6, graph id: 11 no need to rebuild
2020-12-16 06:11:31.163734: I tf_adapter/kernels/geop_npu.cc:580] [GEOP] Call ge session RunGraphAsync, kernel_name:GeOp3_0 ,tf session: direct795b320e370623a6 ,graph id: 11
2020-12-16 06:11:31.163900: I tf_adapter/kernels/geop_npu.cc:593] [GEOP] End GeOp::ComputeAsync, kernel_name:GeOp3_0, ret_status:success ,tf session: direct795b320e370623a6 ,graph id: 11 [0 ms]

.
.重复打印tf_adapter/kernels/geop_npu.cc
.

2020-12-16 06:35:01.233119: I tf_adapter/kernels/geop_npu.cc:76] BuildOutputTensorInfo, num_outputs:8
2020-12-16 06:35:01.233275: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:0, total_bytes:4, shape:, tensor_ptr:281431438898624, output281431438895840
2020-12-16 06:35:01.233303: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:1, total_bytes:4, shape:, tensor_ptr:281431438898752, output281429423151760
2020-12-16 06:35:01.233319: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:2, total_bytes:4, shape:, tensor_ptr:281431438898944, output281431438894400
2020-12-16 06:35:01.233334: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:3, total_bytes:4, shape:, tensor_ptr:281431438899008, output281431438897024
2020-12-16 06:35:01.233348: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:4, total_bytes:4, shape:, tensor_ptr:281431438899200, output281431438896896
2020-12-16 06:35:01.233363: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:5, total_bytes:4, shape:, tensor_ptr:281431438899328, output281431438896704
2020-12-16 06:35:01.233377: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:6, total_bytes:4, shape:, tensor_ptr:281431438899520, output281431438896448
2020-12-16 06:35:01.233391: I tf_adapter/kernels/geop_npu.cc:103] BuildOutputTensorInfo, output index:7, total_bytes:4, shape:, tensor_ptr:281431438899584, output281431438898144
2020-12-16 06:35:01.233410: I tf_adapter/kernels/geop_npu.cc:573] [GEOP] RunGraphAsync callback, status:0, kernel_name:GeOp3_0[ 27940952us]

step : 902 >>>>>>>>>>>>loss_val : 13.80793285369873， rpn_cls_loss : 0.7042933106422424， rpn_loc_loss : 0.2955395579338074，rpn_mask_loss : 0.35413867235183716
step : 903 >>>>>>>>>>>>loss_val : 14.42981243133545， rpn_cls_loss : 0.6335854530334473， rpn_loc_loss : 0.32963234186172485，rpn_mask_loss : 0.3722407817840576

```

Ascend/modelzoo
暂停

内容风险标识

评论 (25)

Ascend/modelzoo暂停 .gitee-modal { width: 500px !important; }

内容风险标识