[MKL-DNN] Advice on runtime context related crash in Transformer

[jczaja]

When test_analyzer_transformer.profile_mkldnn is run with "--test_all_data" option there is a crash (matmul inputs has mismatch of dims). Problem is that when MKL-DNN is used (any op)
then starting from third iteration (when Input data shapes will differ from Warmup and first iteration) then wrong Tensor is chosen for op to work.

Problem is that runtime context is having a Variables pointing to tensors "scale_0.tmp_0" that
comes from previous iterations when shape of those Tensors was diffrent. At the same time
scope does contain "scale_0_tmp_0" of good proper dims.
As a test/workround I forced paddle to recreate runtime context each time. With this hack crash goes away (it all pass). Code I'm refering to (that was disabled to force recreate of runtime context):

Paddle/paddle/fluid/framework/operator.cc

Line 897 in 4267a81

if (!runtime_ctx_ || pre_scope_ != cur_scope) {

@luotao1 Could you please advice/suggest on how to fix this problem?

[luotao1]

When use the latest develop branch. I can run it normally without MKLDNN

./paddle/fluid/inference/tests/api/test_analyzer_transformer --gtest_filter=Analyzer_Transformer.profile --infer_model=third_party/inference_demo/transformer/model --infer_data=third_party/inference_demo/transformer/data.txt --paddle_num_threads=8 --repeat=1 --batch_size=8 --test_all_data
Note: Google Test filter = Analyzer_Transformer.profile
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from Analyzer_Transformer
[ RUN      ] Analyzer_Transformer.profile
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0414 19:27:37.383009 26581 analyzer_transformer_tester.cc:176] The number of samples to be test: 200
I0414 19:27:37.523564 26581 tester_helper.h:85] AnalysisConfig {
  NativeConfig {
    PaddlePredictor::Config {
      model_dir:
    }
    use_gpu: 0
    device: 0
    fraction_of_gpu_memory: 0
    specify_input_name: 1
    cpu_num_threads: 1
  }
  prog_file: third_party/inference_demo/transformer/model/model
  param_file: third_party/inference_demo/transformer/model/params
  enable_ir_optim: 1
  enable_ir_optim: 1
  use_feed_fetch_ops: 1
  use_tensorrt: 0
  use_mkldnn: 0
}
--- Running analysis [ir_graph_build_pass]
--- Running analysis [ir_analysis_pass]
--- Running IR pass [infer_clean_graph_pass]
--- Running IR pass [runtime_context_cache_pass]
--- Running IR pass [attention_lstm_fuse_pass]
--- Running IR pass [seqconv_eltadd_relu_fuse_pass]
--- Running IR pass [fc_lstm_fuse_pass]
--- Running IR pass [mul_lstm_fuse_pass]
--- Running IR pass [fc_gru_fuse_pass]
--- Running IR pass [mul_gru_fuse_pass]
--- Running IR pass [seq_concat_fc_fuse_pass]
--- Running IR pass [fc_fuse_pass]
---  detected 12 subgraphs
--- Running IR pass [repeated_fc_relu_fuse_pass]
--- Running IR pass [squared_mat_sub_fuse_pass]
--- Running IR pass [conv_bn_fuse_pass]
--- Running IR pass [conv_eltwiseadd_bn_fuse_pass]
--- Running IR pass [is_test_pass]
--- Running IR pass [expected_kernel_cache_pass]
--- Running analysis [ir_params_sync_among_devices_pass]
--- Running analysis [ir_graph_to_program_pass]
I0414 19:27:39.150509 26581 analysis_predictor.cc:432] == optimize end ==
I0414 19:27:39.152670 26581 tester_helper.h:327] Thread 0, number of threads 1, run 1 times...
I0414 19:35:05.154572 26581 helper.h:273] ====== threads: 1, thread id: 0 ======
I0414 19:35:05.154955 26581 helper.h:275] ====== batch_size: 8, iterations: 25, repetitions: 1 ======
I0414 19:35:05.154970 26581 helper.h:277] ====== batch latency: 17840.1ms, number of samples: 200, sample latency: 2230.01ms, fps: 0.448429 ======
[       OK ] Analyzer_Transformer.profile (450498 ms)
[----------] 1 test from Analyzer_Transformer (450498 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (450499 ms total)
[  PASSED  ] 1 test.

For MKLDNN, the error is

./paddle/fluid/inference/tests/api/test_analyzer_transformer --gtest_filter=Analyzer_Transformer.profile_mkldnn --infer_model=third_party/inference_demo/transformer/model --infer_data=third_party/inference_demo/transformer/data.txt --paddle_num_threads=8 --repeat=1 --batch_size=8 --test_all_data
Note: Google Test filter = Analyzer_Transformer.profile_mkldnn
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from Analyzer_Transformer
[ RUN      ] Analyzer_Transformer.profile_mkldnn
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0414 19:36:31.854957  4578 analyzer_transformer_tester.cc:176] The number of samples to be test: 200
I0414 19:36:32.037312  4578 tester_helper.h:85] AnalysisConfig {
  NativeConfig {
    PaddlePredictor::Config {
      model_dir:
    }
    use_gpu: 0
    device: 0
    fraction_of_gpu_memory: 0
    specify_input_name: 1
    cpu_num_threads: 1
  }
  prog_file: third_party/inference_demo/transformer/model/model
  param_file: third_party/inference_demo/transformer/model/params
  enable_ir_optim: 1
  enable_ir_optim: 1
  use_feed_fetch_ops: 1
  use_tensorrt: 0
  use_mkldnn: 1
}
I0414 19:36:32.052160  4578 analysis_predictor.cc:396] MKLDNN is enabled
--- Running analysis [ir_graph_build_pass]
--- Running analysis [ir_analysis_pass]
--- Running IR pass [mkldnn_placement_pass]
--- Running IR pass [infer_clean_graph_pass]
--- Running IR pass [runtime_context_cache_pass]
--- Running IR pass [attention_lstm_fuse_pass]
--- Running IR pass [seqconv_eltadd_relu_fuse_pass]
--- Running IR pass [fc_lstm_fuse_pass]
--- Running IR pass [mul_lstm_fuse_pass]
--- Running IR pass [fc_gru_fuse_pass]
--- Running IR pass [mul_gru_fuse_pass]
--- Running IR pass [seq_concat_fc_fuse_pass]
--- Running IR pass [fc_fuse_pass]
---  detected 12 subgraphs
--- Running IR pass [repeated_fc_relu_fuse_pass]
--- Running IR pass [squared_mat_sub_fuse_pass]
--- Running IR pass [conv_bn_fuse_pass]
--- Running IR pass [conv_eltwiseadd_bn_fuse_pass]
--- Running IR pass [is_test_pass]
--- Running IR pass [expected_kernel_cache_pass]
--- Running IR pass [depthwise_conv_mkldnn_pass]
--- Running IR pass [conv_bn_fuse_pass]
--- Running IR pass [conv_eltwiseadd_bn_fuse_pass]
--- Running IR pass [conv_bias_mkldnn_fuse_pass]
--- Running IR pass [conv3d_bias_mkldnn_fuse_pass]
--- Running IR pass [conv_elementwise_add_mkldnn_fuse_pass]
Fused graph 0
--- Running IR pass [conv_relu_mkldnn_fuse_pass]
--- Running analysis [ir_params_sync_among_devices_pass]
--- Running analysis [ir_graph_to_program_pass]
I0414 19:36:36.069097  4578 analysis_predictor.cc:432] == optimize end ==
I0414 19:36:36.072036  4578 tester_helper.h:327] Thread 0, number of threads 1, run 1 times...
unknown file: Failure
C++ exception with description "Enforce failed. Expected x_dims[i + axis] == y_dims[i], but received x_dims[i + axis]:39 != y_dims[i]:66.
Broadcast dimension mismatch. at [/home/luotao/Paddle/paddle/fluid/operators/elementwise/elementwise_op_function.h:63]
PaddlePaddle Call Stacks:
0             0xc4b0d0p void paddle::platform::EnforceNotMet::Init<std::string>(std::string, char const*, int) + 384
1             0xc4b7e7p paddle::platform::EnforceNotMet::EnforceNotMet(std::string const&, char const*, int) + 87
2            0x1081fa7p paddle::operators::get_mid_dims(paddle::framework::DDim const&, paddle::framework::DDim const&, int, int*, int*, int*) + 359
3            0x17142cap void paddle::operators::ElementwiseComputeEx<paddle::operators::AddFunctor<float>, paddle::platform::CPUDeviceContext, float, float>(paddle::framework::ExecutionContext const&, paddle::framework::Tensor const*, paddle::framework::Tensor const*, int, paddle::operators::AddFunctor<float>, paddle::framework::Tensor*) + 810
4            0x1717db9p paddle::operators::ElementwiseAddKernel<paddle::platform::CPUDeviceContext, float>::Compute(paddle::framework::ExecutionContext const&) const + 473
5            0x17182a3p std::_Function_handler<void (paddle::framework::ExecutionContext const&), paddle::framework::OpKernelRegistrarFunctor<paddle::platform::CPUPlace, false, 0ul, paddle::operators::ElementwiseAddKernel<paddle::platform::CPUDeviceContext, float>, paddle::operators::ElementwiseAddKernel<paddle::platform::CPUDeviceContext, double>, paddle::operators::ElementwiseAddKernel<paddle::platform::CPUDeviceContext, int>, paddle::operators::ElementwiseAddKernel<paddle::platform::CPUDeviceContext, long> >::operator()(char const*, char const*, int) const::{lambda(paddle::framework::ExecutionContext const&)#1}>::_M_invoke(std::_Any_data const&, paddle::framework::ExecutionContext const&) + 35
6            0x1a6e630p paddle::framework::OperatorWithKernel::RunImpl(paddle::framework::Scope const&, boost::variant<paddle::platform::CUDAPlace, paddle::platform::CPUPlace, paddle::platform::CUDAPinnedPlace, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const&, paddle::framework::RuntimeContext*) const + 368
7            0x1a6eda1p paddle::framework::OperatorWithKernel::RunImpl(paddle::framework::Scope const&, boost::variant<paddle::platform::CUDAPlace, paddle::platform::CPUPlace, paddle::platform::CUDAPinnedPlace, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const&) const + 545
8            0x1a6ccdbp paddle::framework::OperatorBase::Run(paddle::framework::Scope const&, boost::variant<paddle::platform::CUDAPlace, paddle::platform::CPUPlace, paddle::platform::CUDAPinnedPlace, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const&) + 267
9             0xcd573ep paddle::framework::Executor::RunPreparedContext(paddle::framework::ExecutorPrepareContext*, paddle::framework::Scope*, bool, bool, bool) + 158
10           0x1849e26p paddle::operators::WhileOp::RunImpl(paddle::framework::Scope const&, boost::variant<paddle::platform::CUDAPlace, paddle::platform::CPUPlace, paddle::platform::CUDAPinnedPlace, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const&) const + 1590
11           0x1a6ccdbp paddle::framework::OperatorBase::Run(paddle::framework::Scope const&, boost::variant<paddle::platform::CUDAPlace, paddle::platform::CPUPlace, paddle::platform::CUDAPinnedPlace, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const&) + 267
12           0x1a0ad38p paddle::framework::NaiveExecutor::Run() + 216
13            0xc8d52cp paddle::AnalysisPredictor::Run(std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> > const&, std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> >*, int) + 268
14            0xc411ffp paddle::inference::PredictionRun(paddle::PaddlePredictor*, std::vector<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> >, std::allocator<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> > > > const&, std::vector<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> >, std::allocator<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> > > >*, int, int) + 959
15            0xc41520p paddle::inference::TestOneThreadPrediction(paddle::PaddlePredictor::Config const*, std::vector<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> >, std::allocator<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> > > > const&, std::vector<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> >, std::allocator<std::vector<paddle::PaddleTensor, std::allocator<paddle::PaddleTensor> > > >*, bool) + 96
16            0xc46d61p paddle::inference::profile(bool) + 625
17            0xcc1fc3p void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) + 51
18            0xcb52d7p testing::Test::Run() + 183
19            0xcb537ep testing::TestInfo::Run() + 158
20            0xcb5bbdp testing::TestCase::Run() + 173
21            0xcb99a5p testing::internal::UnitTestImpl::RunAllTests() + 565
22            0xcb9c50p testing::UnitTest::Run() + 80
23            0xc002d7p main + 935
24      0x7f24764abbd5p __libc_start_main + 245
25            0xc3da45p
" thrown in the test body.
[  FAILED  ] Analyzer_Transformer.profile_mkldnn (21417 ms)
[----------] 1 test from Analyzer_Transformer (21417 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (21418 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] Analyzer_Transformer.profile_mkldnn

Is the error same with you?

[jczaja]

@luotao1 Yes, This is the same error. And Yes it works properly without mkl-dnn. The problem with runtime context I'm seeing is just when mkl-dnn is used. So if you could suggest if condition on recreating runtime context should be updated somehow for mkl-dnn then it would be helpful . any other advice is also welcomed.

[luotao1]

So if you could suggest if condition on recreating runtime context should be updated somehow for mkl-dnn then it would be helpful

analyzer_int8_image_classification_tester.cc is successful for both runtime_context_cache_pass and mkldnn_placement_pass. I will investigate this issue, and you can remove this pass when profiling the transformer model at first.

[jczaja]

@luotao1 Great! With disabled runtime_context it worked for me (transformer . profile_mkldnn with --test_all_data). I think that analyzer_int8_image_classification may be different as input images are probably the same size while in Transformer we have input data of various sizes. Anyway, if you have any observations/suggestions based on your investigation then please share

Thanks @luotao1 . Cache was introduced to save context creation time but cache will definitely bring in risk for inconsistency (remember the last random CI failure caused by Chunwei's data transfer scope cache?)

[luotao1]

@jczaja @jianhang-liu I fix it in #17048, you can have a try.

[jczaja]

@luotao1 I have tested changes from #17048 and crash in Transformer is gone (tested both profile_mkldnn and compare_mkldnn with --test_all_data). But I have a question,
"expected_kernel_cache_pass", //
"runtime_context_cache_pass"
are to be as final passes, but MKL-DNN passes are still executed later on. For example log from transformer:
--- Running analysis [ir_graph_build_pass]
--- Running analysis [ir_analysis_pass]
--- Running IR pass [mkldnn_placement_pass]
--- Running IR pass [infer_clean_graph_pass]
--- Running IR pass [attention_lstm_fuse_pass]
--- Running IR pass [seqconv_eltadd_relu_fuse_pass]
--- Running IR pass [fc_lstm_fuse_pass]
--- Running IR pass [mul_lstm_fuse_pass]
--- Running IR pass [fc_gru_fuse_pass]
--- Running IR pass [mul_gru_fuse_pass]
--- Running IR pass [seq_concat_fc_fuse_pass]
--- Running IR pass [fc_fuse_pass]
--- detected 12 subgraphs
--- Running IR pass [repeated_fc_relu_fuse_pass]
--- Running IR pass [squared_mat_sub_fuse_pass]
--- Running IR pass [conv_bn_fuse_pass]
--- Running IR pass [conv_eltwiseadd_bn_fuse_pass]
--- Running IR pass [is_test_pass]
--- Running IR pass [expected_kernel_cache_pass]
--- Running IR pass [runtime_context_cache_pass]
--- Running IR pass [depthwise_conv_mkldnn_pass]
--- Running IR pass [conv_bn_fuse_pass]
--- Running IR pass [conv_eltwiseadd_bn_fuse_pass]
--- Running IR pass [conv_bias_mkldnn_fuse_pass]
--- Running IR pass [conv3d_bias_mkldnn_fuse_pass]
--- Running IR pass [conv_elementwise_add_mkldnn_fuse_pass]
Fused graph 0
--- Running IR pass [conv_relu_mkldnn_fuse_pass]

shouldn't :
"expected_kernel_cache_pass",
"runtime_context_cache_pass"

be executed after MKL-DNN passes?

[luotao1]

shouldn't :
"expected_kernel_cache_pass",
"runtime_context_cache_pass"
be executed after MKL-DNN passes?

Yes, it should be executed after MKL-DNN passes. We plan to remove expected_kernel_cache_pass which could be enabled default. And how about re-add runtime_context_cache_pass again after MKL-DNN passes? Or do you have any good suggestion?