Added minimal support to do some timing of OM Runtime functionality

[AlexandreEichenberger]

Tried to determine where some of the time is spend when invoking the python runtime. Time printed in seconds.

Timing information is read using indentation, more indented timers are within the following less indented timers.

Test program:

module {
  func.func @main_graph(%arg0: tensor<1x384x30522xf32>, %arg1: tensor<1x384x30522xf32>) -> (tensor<1x384x30522xf32> {onnx.name = "y"}) {
    %0 = "onnx.Add"(%arg0, %arg1) : (tensor<1x384x30522xf32>, tensor<1x384x30522xf32>) -> tensor<1x384x30522xf32>
    return %0 : tensor<1x384x30522xf32>
  }
  "onnx.EntryPoint"() {func = @main_graph} : () -> ()
}

Results when compiling with -O3 for Z using RunONNXModel.py

@OM_DRIVER, process_input, 0.000003
@OM_DRIVER,   tensor_list_create, 0.000000
@OM_DRIVER, tensor_list_create, 0.000000
@OM_DRIVER, inference, 0.003231
@OM_DRIVER,   process_output_types, 0.000002
@OM_DRIVER,   process_output_pyarray, 0.004537
@OM_DRIVER, process_output, 0.004542
@OM_DRIVER,     tensor_destroy_ptr, 0.000085
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,   tensor_list_destroy, 0.000087
@OM_DRIVER, delete_out_lists, 0.000092
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,   tensor_list_destroy, 0.000003
@OM_DRIVER, delete_in_lists, 0.000005
  2nd iteration, 0.008029167998756748, seconds

where notably a singnificant amount of time is spent in process_output_pyarray, which corresponds to this in onnx-mlir/src/Runtime/python/PyExecutionSessionBase.cpp

outputPyArrays.emplace_back(
        py::array(dtype, shape, omTensorGetDataPtr(omt)));

[AlexandreEichenberger]

Measured overheads of the pyarray creation for 3 different output size and it seems to be linear in the data size

[chentong319]

Did you use the docker env for your measure? Not sure whether the problem is related to the version of python or pybind11, or the combination.

[AlexandreEichenberger]

It turns out that there is a way when "copying" a C++ data structure to a numpy object that allows the creation of a capsule object that enables python to free objects not allocated by it.

We have to save the pointer of the "allocated" data for the free to works, as sometime the buffer is padded so that the actual data might be a the correct alignment.

The trace below shows that the allocated data is at one address, the data is at another, and when data is freed, it will be effectively the allocated buffer that is freed

Running inference ...
@OM_DRIVER, process_input, 0.004687
@OM_DRIVER,   tensor_list_create, 0.000000
@OM_DRIVER, tensor_list_create, 0.000001
@OM_DRIVER, inference, 0.009955
@OM_DRIVER,   process_output_types, 0.000007
hi alex, preparing free for omTensor with ptr value 0x3ff9397f010 and data ptr 0x3ff93980000
@OM_DRIVER,   process_output_pyarray, 0.000007
@OM_DRIVER, process_output, 0.000020
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,   tensor_list_destroy, 0.000003
@OM_DRIVER, delete_out_lists, 0.000004
@OM_DRIVER,     tensor_destroy_ptr, 0.000095
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,     tensor_destroy_ptr, 0.000139
@OM_DRIVER,     tensor_destroy_struct, 0.000001
@OM_DRIVER,   tensor_list_destroy, 0.000242
@OM_DRIVER, delete_in_lists, 0.000243
  1st iteration, 0.015086764004081488, seconds
Reading reference outputs from check-ref ...
  - 1st output: [1x384x30522xfloat32]
  done.

Verifying value of output_0:[1, 384, 30522] using atol=0.01, rtol=0.05 ...
  correct.

hi alex, freeing omTensor with ptr value 0x3ff9397f010

Above, we can see the 2 different addresses for alloc and data, and we can see that the data is freed after verification (as the python driver, here CheckONNX.py keep the numpy array live until after the verification is performed.

[AlexandreEichenberger]

Results of the timing:

@OM_DRIVER, process_input, 0.000008
@OM_DRIVER,   tensor_list_create, 0.000000
@OM_DRIVER, tensor_list_create, 0.000001
@OM_DRIVER, inference, 0.003783
@OM_DRIVER,   process_output_types, 0.000007
@OM_DRIVER,   process_output_pyarray, 0.000005
@OM_DRIVER, process_output, 0.000020
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,   tensor_list_destroy, 0.000003
@OM_DRIVER, delete_out_lists, 0.000005
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,     tensor_destroy_struct, 0.000000
@OM_DRIVER,   tensor_list_destroy, 0.000005
@OM_DRIVER, delete_in_lists, 0.000006
  1st iteration, 0.0039923149888636544, seconds

we see now that inference takes 0.003783 s, and model takes 0.0039923149888636544. So now 94% of the time is spent in the inference, when driving it from python. Before it was less than 50%... obviously skewed by the fact that this was a single node operation. Nevertheless, we can now see that the "copy" is removed as the overheads are so much lowered, and the log above shows that the freeing of the data was done in the proper location within the python program using the provided lambda function by the C++ runtime.

[AlexandreEichenberger]

Did you use the docker env for your measure? Not sure whether the problem is related to the version of python or pybind11, or the combination.

I think it was due to the copy operation within the py::array as moving to a scheme that does not require the copying removed the issue. Thanks for the good suggestion.

[chentong319]

LGTM!

[AlexandreEichenberger]

@Sunny-Anand let me know if you want to merge this now or in a bit.

It removes a copy for the outputs of a model when using in a python environment.

My tests cover usages using the RunONNXModel.py scripts and the backend tests. I verified the results for one model on a Z arch using NNPA, as there are alignments "tricks" that we do for NNPA buffers that we don't otherwise do.

I let you the final go ahead/wait choice.

[Sunny-Anand]

@AlexandreEichenberger, let's merge this improvement in the main. Thanks for improving it, it's essential for those performance benchmark measurements.

[tungld]

LGTM!

[tungld]

We can avoid using timing_nest_string by using %* to print out "" l times, e.g.

fprintf(stderr, "@OM_DRIVER, %*s%s, %ld.%06ld\n", l, "",
           #_var_name, (long int)_var_name.tv_sec, (long int)_var_name.tv_usec);

[AlexandreEichenberger]

I will give this pattern a try.

[tungld]

Two needing.

[AlexandreEichenberger]

tx, added some additional comments on the difference between data and allocated pointers.

[jenkins-droid]

Jenkins Linux s390x Build #16394 [push] Added minimal support to... started at 10:32

[jenkins-droid]

Jenkins Linux amd64 Build #16392 [push] Added minimal support to... started at 09:32

[jenkins-droid]

Jenkins Linux ppc64le Build #15375 [push] Added minimal support to... started at 10:44

[jenkins-droid]

Jenkins Linux amd64 Build #16392 [push] Added minimal support to... passed after 1 hr 20 min

[jenkins-droid]

Jenkins Linux s390x Build #16394 [push] Added minimal support to... passed after 1 hr 30 min

[jenkins-droid]

Jenkins Linux ppc64le Build #15375 [push] Added minimal support to... passed after 2 hr 25 min