TVM's get_output function is time-consuming with Mali openCL on RK3399

Questions
#1

I encounter the issue of huge time processing for get_output function when i deploy mobinet_ssd’s model on RK3399 board with target openCL. Here is the part of my script:

m = graph_runtime.create(graph, lib, ctx)
m.set_input(**params)

begin = time.time()
m.set_input(‘data’, tvm.nd.array(x.astype(dtype)))
m.run()
end = time.time()
print('Run time: '+str(end-begin))

_, outshape = nnvm.compiler.graph_util.infer_shape(graph, shape={“data”: dshape})

begin2 = time.time()
tvm_output_0 = m.get_output(0, tvm.nd.empty(tuple(outshape[0]),‘float32’)) # shape: (1, 21, 1917)
tvm_output_1 = m.get_output(1, tvm.nd.empty(tuple(outshape[1]),‘float32’)) #shape: (1, 7668)
tvm_output_2 = m.get_output(2, tvm.nd.empty(tuple(outshape[2]),‘float32’)) # shape: (1, 1917, 4)
end4 = time.time()
print('get output time: '+str(end4-begin2))
begin5 = time.time()
final_output = get_multibox_detection_output_tvm(tvm_output_0, tvm_output_1, tvm_output_2, 1, num_anchor, 21)
end5 = time.time()
print('get get_multibox_detection_output_tvm: '+str(end5-begin5))

And the output:

  • runtime:0.02s
  • get output time: 1.95s
  • get_multibox_detection_output_tvm time: 1s

This was reported here 979. Is there any update for this issue or any other way to get result from TVM?

#2

OpenCL kernels are lazy exectued. So the your time evaluation of run tells you nothing.
We will sync the stream when calling get_output

To make time evaluation correct, we have to time both run, get_output and do some warm up runs

2 Likes
#3

Actually i tested with multiple images, and it was the result after several loop.
i also tested this code in my PC with nvidia-GTX1080, the get output time after several loops is only 0.0007s

#4

I believe that mobilenet ssd cannot run in 50ms on RK3399. You should time both run and get_output. This is the real time cost, which is 0.05 + 1.95s in your case.

BTW, if you use RPC, you should also remove time cost due to network.

#5

i checked again and actually the run time is about 0.02. Please note that this run time doesn’t include multibox_detection part- which run on cpu. So the real time cost is: run time + get_output time + multibox_detection time You can check my full script here

#6

0.02s is impossible. You can see my benchmark result here https://github.com/dmlc/tvm/wiki/Benchmark#mobile-gpu. Mobilenet with highly tuned kernels takes about 80ms on rk3399 board.
So we are sure that the run is lazily executed.

In your script, you use ‘opencl’ as target. Then tvm will use the kernels optimized for cuda backend.
For mali GPU, you should use "opencl -device=mali" as target. We have different kernel implementation optimized for mali. Finally, to get the best performance, you have to follow the auto tuning tutorial (https://docs.tvm.ai/tutorials/autotvm/tune_nnvm_mobile_gpu.html)

1 Like
#7

sorry, this script for running on my PC. I use “target=tvm.target.mali, ctx = tvm.cl(0)” when deploy in RK3399. I changed target=“opencl -device=mali” but the time is the same. You can see the log here:

model compiled.

[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…
[11:11:47] /home/firefly/tvm_openCL_support_priorBox/src/pass/vectorize_loop.cc:303: Detect vector condition in Vectorized Loop, scalarizing…

=======================================================

=======================================================
[11:11:54] /home/firefly/tvm_openCL_support_priorBox/src/runtime/opencl/opencl_device_api.cc:242: Initialize OpenCL platform ‘ARM Platform’
[11:11:54] /home/firefly/tvm_openCL_support_priorBox/src/runtime/opencl/opencl_device_api.cc:251: No OpenCL device any device matched given the options: accelerator mode
[11:11:54] /home/firefly/tvm_openCL_support_priorBox/src/runtime/opencl/opencl_device_api.cc:269: opencl(0)=‘Mali-T860’ cl_device_id=0x7f93d40dd8
run time: 46.999, getout_time: 2.03895, detection_time: 0.687, total time: 49.725
run time: 0.018, getout_time: 1.91659, detection_time: 1.128, total time: 3.063
run time: 0.02, getout_time: 1.93148, detection_time: 1.118, total time: 3.069
run time: 0.02, getout_time: 1.91593, detection_time: 1.093, total time: 3.029
run time: 0.019, getout_time: 1.93582, detection_time: 1.14, total time: 3.095
run time: 0.018, getout_time: 1.93465, detection_time: 1.119, total time: 3.072
run time: 0.018, getout_time: 1.97412, detection_time: 1.143, total time: 3.135
run time: 0.019, getout_time: 1.92758, detection_time: 1.077, total time: 3.024
run time: 0.019, getout_time: 1.92943, detection_time: 1.156, total time: 3.104
run time: 0.019, getout_time: 1.9279, detection_time: 1.135, total time: 3.082
run time: 0.02, getout_time: 1.93719, detection_time: 1.136, total time: 3.093
run time: 0.019, getout_time: 1.97357, detection_time: 1.145, total time: 3.138
run time: 0.018, getout_time: 1.92685, detection_time: 1.138, total time: 3.083
run time: 0.02, getout_time: 1.96257, detection_time: 1.133, total time: 3.116
run time: 0.019, getout_time: 1.95402, detection_time: 1.134, total time: 3.107
run time: 0.019, getout_time: 1.92661, detection_time: 1.147, total time: 3.093
run time: 0.02, getout_time: 1.9345, detection_time: 1.141, total time: 3.095
run time: 0.018, getout_time: 1.92304, detection_time: 1.135, total time: 3.076
run time: 0.018, getout_time: 1.9267, detection_time: 1.139, total time: 3.084
run time: 0.018, getout_time: 1.92407, detection_time: 1.135, total time: 3.077
run time: 0.02, getout_time: 1.93869, detection_time: 1.116, total time: 3.075
run time: 0.018, getout_time: 1.91643, detection_time: 1.153, total time: 3.087
run time: 0.019, getout_time: 1.92286, detection_time: 1.101, total time: 3.043
run time: 0.019, getout_time: 1.95793, detection_time: 1.113, total time: 3.09
run time: 0.018, getout_time: 1.92309, detection_time: 1.074, total time: 3.015
run time: 0.019, getout_time: 1.91833, detection_time: 1.079, total time: 3.016
run time: 0.02, getout_time: 1.92622, detection_time: 1.097, total time: 3.043
run time: 0.018, getout_time: 1.93256, detection_time: 1.096, total time: 3.047
run time: 0.018, getout_time: 1.91949, detection_time: 1.086, total time: 3.023
run time: 0.018, getout_time: 1.94478, detection_time: 1.083, total time: 3.046
run time: 0.018, getout_time: 1.96931, detection_time: 1.076, total time: 3.063
run time: 0.021, getout_time: 1.91958, detection_time: 1.111, total time: 3.052
run time: 0.018, getout_time: 1.99231, detection_time: 1.07, total time: 3.08
run time: 0.019, getout_time: 1.92992, detection_time: 1.071, total time: 3.02
run time: 0.018, getout_time: 2.04414, detection_time: 1.067, total time: 3.129
run time: 0.018, getout_time: 1.92568, detection_time: 1.083, total time: 3.027
run time: 0.018, getout_time: 1.9227, detection_time: 1.082, total time: 3.023
run time: 0.019, getout_time: 1.92214, detection_time: 1.095, total time: 3.036
run time: 0.018, getout_time: 1.95153, detection_time: 1.066, total time: 3.036
run time: 0.019, getout_time: 1.92528, detection_time: 1.075, total time: 3.019
run time: 0.019, getout_time: 1.93487, detection_time: 1.062, total time: 3.016
run time: 0.02, getout_time: 1.92637, detection_time: 1.077, total time: 3.023
run time: 0.02, getout_time: 1.93431, detection_time: 1.066, total time: 3.02
run time: 0.02, getout_time: 1.93129, detection_time: 1.054, total time: 3.005
run time: 0.022, getout_time: 1.93616, detection_time: 1.064, total time: 3.022
run time: 0.022, getout_time: 1.90587, detection_time: 1.088, total time: 3.016
run time: 0.019, getout_time: 1.92704, detection_time: 1.078, total time: 3.024
run time: 0.021, getout_time: 1.97368, detection_time: 1.069, total time: 3.064
run time: 0.019, getout_time: 1.9386, detection_time: 1.087, total time: 3.045
run time: 0.02, getout_time: 1.91252, detection_time: 1.051, total time: 2.984
run time: 0.018, getout_time: 1.94096, detection_time: 1.061, total time: 3.02
run time: 0.02, getout_time: 1.93779, detection_time: 1.053, total time: 3.011
run time: 0.019, getout_time: 1.97773, detection_time: 1.07, total time: 3.067
run time: 0.02, getout_time: 1.93013, detection_time: 1.069, total time: 3.019
run time: 0.018, getout_time: 1.94176, detection_time: 1.101, total time: 3.061
run time: 0.019, getout_time: 1.92462, detection_time: 1.079, total time: 3.023
run time: 0.022, getout_time: 1.9222, detection_time: 1.076, total time: 3.02
run time: 0.021, getout_time: 1.91133, detection_time: 1.048, total time: 2.98
run time: 0.019, getout_time: 1.91965, detection_time: 1.067, total time: 3.006
run time: 0.021, getout_time: 1.92235, detection_time: 1.105, total time: 3.048
run time: 0.021, getout_time: 1.92866, detection_time: 1.161, total time: 3.111
run time: 0.019, getout_time: 1.91241, detection_time: 1.086, total time: 3.017
run time: 0.02, getout_time: 1.93633, detection_time: 1.052, total time: 3.008
run time: 0.019, getout_time: 1.91661, detection_time: 1.073, total time: 3.009
run time: 0.019, getout_time: 1.90531, detection_time: 1.059, total time: 2.983
run time: 0.021, getout_time: 1.92044, detection_time: 1.067, total time: 3.008
run time: 0.038, getout_time: 1.92036, detection_time: 1.042, total time: 3.0
run time: 0.018, getout_time: 1.91986, detection_time: 1.055, total time: 2.993
run time: 0.019, getout_time: 1.95779, detection_time: 1.087, total time: 3.064
run time: 0.019, getout_time: 1.92522, detection_time: 1.068, total time: 3.012
run time: 0.02, getout_time: 1.93092, detection_time: 1.045, total time: 2.996
run time: 0.02, getout_time: 1.91828, detection_time: 1.059, total time: 2.997
run time: 0.019, getout_time: 1.9287, detection_time: 1.081, total time: 3.029
run time: 0.02, getout_time: 1.92668, detection_time: 1.068, total time: 3.015
run time: 0.02, getout_time: 1.94282, detection_time: 1.109, total time: 3.072
run time: 0.02, getout_time: 1.92563, detection_time: 1.064, total time: 3.01
run time: 0.038, getout_time: 1.92589, detection_time: 1.049, total time: 3.013
run time: 0.034, getout_time: 1.92938, detection_time: 1.051, total time: 3.014
run time: 0.018, getout_time: 1.977, detection_time: 1.078, total time: 3.073
run time: 0.018, getout_time: 1.931, detection_time: 1.053, total time: 3.002
run time: 0.02, getout_time: 1.93045, detection_time: 1.049, total time: 2.999
run time: 0.019, getout_time: 1.91125, detection_time: 1.068, total time: 2.998
run time: 0.018, getout_time: 1.93437, detection_time: 1.049, total time: 3.001
run time: 0.031, getout_time: 1.91328, detection_time: 1.065, total time: 3.009
run time: 0.019, getout_time: 1.9211, detection_time: 1.049, total time: 2.989
run time: 0.041, getout_time: 1.90842, detection_time: 1.058, total time: 3.007
run time: 0.036, getout_time: 1.92608, detection_time: 1.055, total time: 3.017
run time: 0.022, getout_time: 1.92604, detection_time: 1.047, total time: 2.995
run time: 0.045, getout_time: 1.92545, detection_time: 1.043, total time: 3.013
run time: 0.035, getout_time: 1.91599, detection_time: 1.026, total time: 2.977
run time: 0.021, getout_time: 1.96068, detection_time: 1.067, total time: 3.049
run time: 0.028, getout_time: 1.92769, detection_time: 1.066, total time: 3.022
run time: 0.035, getout_time: 1.94109, detection_time: 1.036, total time: 3.012
run time: 0.019, getout_time: 1.92071, detection_time: 1.051, total time: 2.991
run time: 0.019, getout_time: 1.92616, detection_time: 1.084, total time: 3.029
run time: 0.028, getout_time: 1.92764, detection_time: 1.061, total time: 3.017
run time: 0.018, getout_time: 1.93644, detection_time: 1.068, total time: 3.022
run time: 0.02, getout_time: 1.95426, detection_time: 1.045, total time: 3.019
run time: 0.045, getout_time: 1.91813, detection_time: 1.029, total time: 2.992
run time: 0.018, getout_time: 1.92311, detection_time: 1.041, total time: 2.982
run time: 0.018, getout_time: 1.91577, detection_time: 1.046, total time: 2.98
run time: 0.038, getout_time: 1.92422, detection_time: 1.048, total time: 3.01
run time: 0.021, getout_time: 1.97752, detection_time: 1.072, total time: 3.071
run time: 0.018, getout_time: 1.9339, detection_time: 1.045, total time: 2.997
run time: 0.02, getout_time: 1.93187, detection_time: 1.046, total time: 2.998
run time: 0.019, getout_time: 1.92066, detection_time: 1.075, total time: 3.015
run time: 0.019, getout_time: 1.92475, detection_time: 1.055, total time: 2.999
run time: 0.043, getout_time: 1.90995, detection_time: 1.047, total time: 3.0
run time: 0.03, getout_time: 1.91711, detection_time: 1.097, total time: 3.044
run time: 0.045, getout_time: 1.9019, detection_time: 1.061, total time: 3.008
run time: 0.037, getout_time: 1.91884, detection_time: 1.081, total time: 3.037
run time: 0.021, getout_time: 1.89945, detection_time: 1.075, total time: 2.995
run time: 0.036, getout_time: 1.92068, detection_time: 1.048, total time: 3.005
run time: 0.029, getout_time: 1.9183, detection_time: 1.053, total time: 3.0
run time: 0.019, getout_time: 1.94357, detection_time: 1.08, total time: 3.043
run time: 0.018, getout_time: 1.90703, detection_time: 1.04, total time: 2.965
run time: 0.018, getout_time: 1.95019, detection_time: 1.06, total time: 3.028
run time: 0.019, getout_time: 1.92096, detection_time: 1.078, total time: 3.018
run time: 0.019, getout_time: 1.92293, detection_time: 1.084, total time: 3.026
run time: 0.02, getout_time: 1.92731, detection_time: 1.099, total time: 3.046
run time: 0.018, getout_time: 1.96959, detection_time: 1.075, total time: 3.063
run time: 0.019, getout_time: 1.92001, detection_time: 1.088, total time: 3.027
run time: 0.018, getout_time: 1.97402, detection_time: 1.12, total time: 3.112
run time: 0.019, getout_time: 1.9416, detection_time: 1.05, total time: 3.011
run time: 0.021, getout_time: 1.92424, detection_time: 1.124, total time: 3.069

according to the output, the run time is mostly stable from second loop and ~0.02s. What is the input size of your mobilenet model? @merrymercy

#8

"tvm.target.mali" is okay. It is the same as "opencl -device=mali".

As the contributor of mali backend, I am pretty sure you are wrong…

run only launches kernels but does not sync the stream.
We only sync the stream when we want to get some data from GPU to CPU. (i.e. get_output to cpu tvm array or call asnumpy on gpu tvm array)

1 Like
#9

Yes. I know you are big contributor of TVM. I already referenced your documents and scripts. Something went wrong here…
You can measure yourself with my script? i already uploaded my models here
Anyway, What is the input size of your mobilenet model?

#10

The output of your script is correct and reasonable.
But the time of run does not mean the time cost of running all opencl kernels.
So your conclusion get_output is time-consuming is not correct.

When you call ‘run’, the CPU puts kernels into a queue but does not wait them to finish.
In the meanwhile GPU fetch commands from the queue and execute them.
When you want to get results back from GPU (where you call get_output), you wait until all commands in that queue finish. So the correct measurement should include run + get_output. In this way we measure the running cost of all kernels.

The benchmark uses 224x224x3 imagenet input

2 Likes
#11

try adding ctx.sync() after run()

#12

Thanks for your clear answer!
@masahi i add this, now the run time is about 1.95s and get_output time is 0.005s

#13

Out of curiosity, is there a reason time evaluator is not being used here?

That is the typical way we usually do performance measurement, as it allows for customizing the number of trials/repetitions and also uses high precision timers.

1 Like
#14

@eqy Yes! Time_evaluator is exactly what i need. Thank you!

#15

@merrymercy Can we sync stream before transferring data from GPU to CPU? This seems necessary for heterogeneous execution. Thanks.

#16

Can ctx.sync() work for you?

#17

I deployed my model (mobilenet_ssd_300x300) with RPC on RK3399 but the processing time is still too bad (1884.47ms, std dev=6.09ms) compare to the recorded result (78.39 ms , std dev=1.33ms). Do you know the reason? @merrymercy

#18
  1. First make sure you can reproduce our benchmark results
    We lock the frequency of mali gpu and close gui by
sudo /etc/init.d/lightdm stop
sudo -i
echo performance > /sys/class/misc/mali0/device/devfreq/ff9a0000.gpu/governor
  1. Then you need auto-tuning for your own network.
1 Like
#19

@merrymercy Yes. I successfully reproduced your benchmark result (84.47ms for mobilenet and 181.75ms for resnet-18)
The model that i deployed here doesn’t include multibox_detection part. I removed multibox_prior part of this model and the result seemed to be more reasonable (230.95ms, std dev=8.69ms). So may be current openCL’s schedule for multibox_prior is not good?

#20

I think this is probably not the copy issue. I would suggest you measure each of the workload/op and see if there is a timing problem. My problem was caused the inappropriate handling a certain convolution shape, it was largely solved by PR #1709.

1 Like