Time processing for every ONNX nodes in a graph

Links: notebook, html, PDF, python, slides, GitHub

The following notebook show how long the runtime spends in each node of an ONNX graph.

from jyquickhelper import add_notebook_menu
add_notebook_menu()

%load_ext mlprodict

%matplotlib inline

LogisticRegression

from sklearn.datasets import load_iris
from sklearn.model_selection import train_test_split
from sklearn.linear_model import LogisticRegression
iris = load_iris()
X, y = iris.data, iris.target
X_train, X_test, y_train, y_test = train_test_split(X, y)
clr = LogisticRegression(solver='liblinear')
clr.fit(X_train, y_train)

LogisticRegression(solver='liblinear')

import numpy
from mlprodict.onnx_conv import to_onnx
onx = to_onnx(clr, X_test.astype(numpy.float32))
with open("logreg_time.onnx", "wb") as f:
    f.write(onx.SerializeToString())
# add -l 1 if nothing shows up
%onnxview onx

from mlprodict.onnxrt import OnnxInference
import pandas
oinf = OnnxInference(onx)
res = oinf.run({'X': X_test}, node_time=True)
pandas.DataFrame(list(res[1]))

	i	name	op_type	time
0	0	LinearClassifier	LinearClassifier	0.199603
1	1	Normalizer	Normalizer	0.000091
2	2	Cast	Cast	0.000014
3	3	ZipMap	ZipMap	0.000016

oinf.run({'X': X_test})['output_probability'][:5]

{0: array([8.38235830e-01, 1.21554664e-03, 6.97352537e-04, 7.93823160e-01,
        9.24825077e-01]),
 1: array([0.16162989, 0.39692812, 0.25688601, 0.20607722, 0.07516498]),
 2: array([1.34279470e-04, 6.01856333e-01, 7.42416637e-01, 9.96200831e-05,
        9.94208860e-06])}

Measure time spent in each node

With parameter node_time=True, method run returns the output and time measurement.

exe = oinf.run({'X': X_test}, node_time=True)
exe[1]

[{'i': 0,
  'name': 'LinearClassifier',
  'op_type': 'LinearClassifier',
  'time': 0.00015699999999974068},
 {'i': 1,
  'name': 'Normalizer',
  'op_type': 'Normalizer',
  'time': 5.43000000003957e-05},
 {'i': 2, 'name': 'Cast', 'op_type': 'Cast', 'time': 1.1699999999947863e-05},
 {'i': 3,
  'name': 'ZipMap',
  'op_type': 'ZipMap',
  'time': 1.940000000111297e-05}]

import pandas
pandas.DataFrame(exe[1])

	i	name	op_type	time
0	0	LinearClassifier	LinearClassifier	0.000157
1	1	Normalizer	Normalizer	0.000054
2	2	Cast	Cast	0.000012
3	3	ZipMap	ZipMap	0.000019

Logistic regression: python runtime vs onnxruntime

Function enumerate_validated_operator_opsets implements automated tests for every model with artificial data. Option node_time automatically returns the time spent in each node and does it multiple time.

from mlprodict.onnxrt.validate import enumerate_validated_operator_opsets
res = list(enumerate_validated_operator_opsets(
            verbose=0, models={"LogisticRegression"}, opset_min=12,
            runtime='python', debug=False, node_time=True,
            filter_exp=lambda m, p: p == "b-cl"))

C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))

import pandas
df = pandas.DataFrame(res[0]['bench-batch'])
df['step'] = df.apply(lambda row: '{}-{}'.format(row['i'], row["name"]), axis=1)
df

	i	name	op_type	time	N	max_time	min_time	repeat	number	step
0	0	LinearClassifier	LinearClassifier	0.000018	1	0.000033	0.000015	20	30	0-LinearClassifier
1	1	Normalizer	Normalizer	0.000017	1	0.000069	0.000012	20	30	1-Normalizer
2	2	Cast	Cast	0.000004	1	0.000009	0.000003	20	30	2-Cast
3	3	ZipMap	ZipMap	0.000005	1	0.000007	0.000004	20	30	3-ZipMap
4	0	LinearClassifier	LinearClassifier	0.000020	10	0.000052	0.000017	20	20	0-LinearClassifier
5	1	Normalizer	Normalizer	0.000015	10	0.000035	0.000013	20	20	1-Normalizer
6	2	Cast	Cast	0.000004	10	0.000013	0.000003	20	20	2-Cast
7	3	ZipMap	ZipMap	0.000004	10	0.000008	0.000004	20	20	3-ZipMap
8	0	LinearClassifier	LinearClassifier	0.000024	100	0.000036	0.000019	10	8	0-LinearClassifier
9	1	Normalizer	Normalizer	0.000018	100	0.000023	0.000015	10	8	1-Normalizer
10	2	Cast	Cast	0.000004	100	0.000006	0.000003	10	8	2-Cast
11	3	ZipMap	ZipMap	0.000007	100	0.000005	0.000004	10	8	3-ZipMap
12	0	LinearClassifier	LinearClassifier	0.000051	1000	0.000057	0.000047	5	5	0-LinearClassifier
13	1	Normalizer	Normalizer	0.000041	1000	0.000045	0.000040	5	5	1-Normalizer
14	2	Cast	Cast	0.000003	1000	0.000004	0.000003	5	5	2-Cast
15	3	ZipMap	ZipMap	0.000004	1000	0.000004	0.000004	5	5	3-ZipMap
16	0	LinearClassifier	LinearClassifier	0.000315	10000	0.000328	0.000315	3	3	0-LinearClassifier
17	1	Normalizer	Normalizer	0.000272	10000	0.000284	0.000256	3	3	1-Normalizer
18	2	Cast	Cast	0.000004	10000	0.000004	0.000004	3	3	2-Cast
19	3	ZipMap	ZipMap	0.000004	10000	0.000004	0.000004	3	3	3-ZipMap
20	0	LinearClassifier	LinearClassifier	0.005634	100000	0.005634	0.005634	1	2	0-LinearClassifier
21	1	Normalizer	Normalizer	0.004671	100000	0.004671	0.004671	1	2	1-Normalizer
22	2	Cast	Cast	0.000024	100000	0.000024	0.000024	1	2	2-Cast
23	3	ZipMap	ZipMap	0.000013	100000	0.000013	0.000013	1	2	3-ZipMap

Following tables shows the time spent in each node, it is relative to the total time. For one observation, the runtime spends 10% of the time in ZipMap, it is only 1% or 2% with 10 observations. These proportions change due to the computing cost of each node.

piv = df.pivot('step', 'N', 'time')
total = piv.sum(axis=0)
piv / total

N	1	10	100	1000	10000	100000
step
0-LinearClassifier	0.410138	0.459103	0.450882	0.512622	0.530490	0.544785
1-Normalizer	0.390060	0.353622	0.350126	0.414227	0.456671	0.451642
2-Cast	0.095729	0.089857	0.074343	0.034398	0.006092	0.002306
3-ZipMap	0.104073	0.097418	0.124649	0.038753	0.006747	0.001267

The python implementation of ZipMap does not change the data but wraps in into a frozen class ArrayZipMapDitionary which mocks a list of dictionaries pandas can ingest to create a DataFrame. The cost is a fixed cost and does not depend on the number of processed rows.

from pyquickhelper.pycode.profiling import profile
bigX = numpy.random.randn(100000, X_test.shape[1]).astype(numpy.float32)
print(profile(lambda: oinf.run({'X': bigX}), pyinst_format="text")[1])

  _     ._   __/__   _ _  _  _ _/_   Recorded: 00:28:08  Samples:  4
 /_//_/// /_/ //_// / //_'/ //     Duration: 0.009     CPU time: 0.031
/   _/                      v3.0.1
Program: c:python372_x64libsite-packagesipykernel_launcher.py -f C:UsersxavieAppDataRoamingjupyterruntimekernel-287476aa-b8ba-4140-902a-b0aad833ffd0.json
0.008 profile  pyquickhelperpycodeprofiling.py:49
`- 0.008 <lambda>  <ipython-input-13-ccd42692a7ed>:3
   `- 0.008 run  mlprodictonnxrtonnx_inference.py:475
      `- 0.008 _run_sequence_runtime  mlprodictonnxrtonnx_inference.py:558
         `- 0.008 run  mlprodictonnxrtonnx_inference_node.py:141
            |- 0.005 run  mlprodictonnxrtops_cpu_op.py:417
            |  `- 0.005 run  mlprodictonnxrtops_cpu_op.py:298
            |     `- 0.005 _run  mlprodictonnxrtops_cpuop_linear_classifier.py:40
            |        |- 0.003 [self]
            |        `- 0.002 argmax  <__array_function__ internals>:2
            |           `- 0.002 argmax  numpycorefromnumeric.py:1112
            |                 [3 frames hidden]  numpy
            |                    0.002 _wrapfunc  numpycorefromnumeric.py:55
            `- 0.003 run  mlprodictonnxrtops_cpu_op.py:383
               `- 0.003 run  mlprodictonnxrtops_cpu_op.py:298
                  `- 0.003 _run  mlprodictonnxrtops_cpuop_normalizer.py:66
                     `- 0.003 norm_l1  mlprodictonnxrtops_cpuop_normalizer.py:42
                        `- 0.003 _norm_L1_inplace  mlprodictonnxrtops_cpuop_normalizer.py:49
                           |- 0.002 [self]
                           `- 0.002 _sum  numpycore_methods.py:36
                                 [2 frames hidden]  numpy

The class ArrayZipMapDictionary is fast to build but has an overhead after that because it builds data when needed.

res = oinf.run({'X': bigX})
prob = res['output_probability']
type(prob)

mlprodict.onnxrt.ops_cpu.op_zipmap.ArrayZipMapDictionary

%timeit pandas.DataFrame(prob)

721 ms ± 54.5 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

list_of_dict = [v.asdict() for v in prob]
%timeit pandas.DataFrame(list_of_dict)

108 ms ± 2.01 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)

But if you just need to do the following:

%timeit pandas.DataFrame(prob).values

713 ms ± 56.6 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

Then, you can just do that:

print(prob.columns)
%timeit prob.values

[0, 1, 2]
390 ns ± 51.2 ns per loop (mean ± std. dev. of 7 runs, 1000000 loops each)

And then:

%timeit -n 100 pandas.DataFrame(prob.values, columns=prob.columns)

215 µs ± 82.6 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)

We can then compare to what onnxruntime would do when the runtime is called indenpently for each node. We use the runtime named onnxruntime2. Class OnnxInference splits the ONNX graph into multiple ONNX graphs, one for each node, and then calls onnxruntime for each of them indenpently. Python handles the graph logic.

res = list(enumerate_validated_operator_opsets(
            verbose=0, models={"LogisticRegression"}, opset_min=12,
            runtime='onnxruntime2', debug=False, node_time=True))

C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))
C:xavierdupre__home_github_forkscikit-learnsklearnlinear_model_logistic.py:1356: UserWarning: 'n_jobs' > 1 does not have any effect when 'solver' is set to 'liblinear'. Got 'n_jobs' = 4.
  " = {}.".format(effective_n_jobs(self.n_jobs)))

res0 = None
for i, r in enumerate(res):
    if "available-ERROR" in r:
        print(i, str(r['available-ERROR']).split("\n")[0])
    elif res0 is None:
        res0 = r

0 Unable to load node 'ZipMap' (output type was inferred)
1 Unable to load node 'ZipMap' (output type was inferred)
4 Unable to load node 'LinearClassifier' (output type was guessed)
5 Unable to load node 'LinearClassifier' (output type was guessed)
6 Unable to load node 'LinearClassifier' (output type was guessed)
7 Unable to load node 'LinearClassifier' (output type was guessed)
8 Unable to load node 'ZipMap' (output type was inferred)
9 Unable to load node 'ZipMap' (output type was inferred)

if '_6ort_run_batch_exc' in res[0]:
    m = "Something went wrong.", res[0]['_6ort_run_batch_exc']
else:
    df = pandas.DataFrame(res0['bench-batch'])
    print(df)
    df['step'] = df.apply(lambda row: '{}-{}'.format(row['i'], row["name"]), axis=1)
    piv = df.pivot('step', 'N', 'time')
    total = piv.sum(axis=0)
    m = piv / total
m

   i              name           op_type      time       N  max_time  0  0  LinearClassifier  LinearClassifier  0.000052       1  0.000190
1  0  LinearClassifier  LinearClassifier  0.000044      10  0.000070
2  0  LinearClassifier  LinearClassifier  0.000071     100  0.000133
3  0  LinearClassifier  LinearClassifier  0.000066    1000  0.000079
4  0  LinearClassifier  LinearClassifier  0.000409   10000  0.000408
5  0  LinearClassifier  LinearClassifier  0.003275  100000  0.003275
   min_time  repeat  number
0  0.000028      20      30
1  0.000031      20      20
2  0.000046      10       8
3  0.000057       5       5
4  0.000365       3       3
5  0.003275       1       2

N	1	10	100	1000	10000	100000
step
0-LinearClassifier	1.0	1.0	1.0	1.0	1.0	1.0

onnxruntime creates a new container each time a ZipMap is executed. That’s whay it takes that much time and the ratio increases when the number of observations increases.

GaussianProcessRegressor

This operator is slow for small batches compare to scikit-learn but closes the gap as the batch size increases. Let’s see where the time goes.

from onnx.defs import onnx_opset_version
from mlprodict.tools.asv_options_helper import get_opset_number_from_onnx
onnx_opset_version(), get_opset_number_from_onnx()

(12, 12)

res = list(enumerate_validated_operator_opsets(
            verbose=1, models={"GaussianProcessRegressor"},
            opset_min=get_opset_number_from_onnx(),
            opset_max=get_opset_number_from_onnx(),
            runtime='python', debug=False, node_time=True,
            filter_exp=lambda m, p: p == "b-reg"))

[enumerate_validated_operator_opsets] opset in [12, 12].

GaussianProcessRegressor    :   0%|          | 0/1 [00:00<?, ?it/s]

[enumerate_compatible_opset] opset in [12, 12].

GaussianProcessRegressor    : 100%|██████████| 1/1 [00:05<00:00,  5.66s/it]

res0 = None
for i, r in enumerate(res):
    if "available-ERROR" in r:
        print(i, str(r['available-ERROR']).split("\n")[0])
    elif res0 is None:
        res0 = r

df = pandas.DataFrame(res0['bench-batch'])
df['step'] = df.apply(lambda row: '{0:02d}-{1}'.format(row['i'], row["name"]), axis=1)
df.head()

	i	name	op_type	time	N	max_time	min_time	repeat	number	step
0	0	kgpd_CDist	CDist	0.000033	1	0.000045	0.000027	20	30	00-kgpd_CDist
1	1	kgpd_Div	Div	0.000009	1	0.000016	0.000007	20	30	01-kgpd_Div
2	2	kgpd_Mul	Mul	0.000006	1	0.000007	0.000005	20	30	02-kgpd_Mul
3	3	kgpd_Sin	Sin	0.000007	1	0.000009	0.000006	20	30	03-kgpd_Sin
4	4	kgpd_Div1	Div	0.000007	1	0.000008	0.000005	20	30	04-kgpd_Div1

pivpy = df.pivot('step', 'N', 'time')
total = pivpy.sum(axis=0)
pivpy / total

N	1	10	100	1000	10000	100000
step
00-kgpd_CDist	0.311496	0.300665	0.244035	0.227984	0.264447	0.288546
01-kgpd_Div	0.082535	0.067193	0.028348	0.011667	0.012230	0.015447
02-kgpd_Mul	0.059840	0.050664	0.018670	0.006959	0.010950	0.012468
03-kgpd_Sin	0.067037	0.086529	0.106165	0.113068	0.102102	0.107563
04-kgpd_Div1	0.061852	0.053088	0.025749	0.010935	0.009810	0.009875
05-kgpd_Pow	0.072520	0.166539	0.361318	0.438253	0.418169	0.404182
06-kgpd_Mul1	0.057508	0.050477	0.020386	0.010334	0.009079	0.010466
07-kgpd_Exp	0.067885	0.098850	0.150876	0.168079	0.165177	0.145106
08-gpr_MatMul	0.137546	0.064570	0.025069	0.009029	0.007134	0.006159
09-gpr_Add	0.081782	0.061424	0.019383	0.003692	0.000903	0.000190

ax = (pivpy / total).T.plot(logx=True, figsize=(14, 4))
ax.set_ylim([0,1])
ax.set_title("Time spent in each node relatively to the total time\npython runtime");

The operator Scan is clearly time consuming when the batch size is small. onnxruntime is more efficient for this one.

res = list(enumerate_validated_operator_opsets(
            verbose=1, models={"GaussianProcessRegressor"},
            opset_min=get_opset_number_from_onnx(),
            opset_max=get_opset_number_from_onnx(),
            runtime='onnxruntime2', debug=False, node_time=True,
            filter_exp=lambda m, p: p == "b-reg"))

[enumerate_validated_operator_opsets] opset in [12, 12].

GaussianProcessRegressor    :   0%|          | 0/1 [00:00<?, ?it/s]

[enumerate_compatible_opset] opset in [12, 12].

GaussianProcessRegressor    : 100%|██████████| 1/1 [00:06<00:00,  6.84s/it]

try:
    df = pandas.DataFrame(res[0]['bench-batch'])
except KeyError as e:
    print("No model available.")
    r, df = None, None
if df is not None:
    df['step'] = df.apply(lambda row: '{0:02d}-{1}'.format(row['i'], row["name"]), axis=1)
    pivort = df.pivot('step', 'N', 'time')
    total = pivort.sum(axis=0)
    r = pivort / total
r

N	1	10	100	1000	10000	100000
step
00-kgpd_CDist	0.114001	0.120884	0.128845	0.148042	0.156776	0.180377
01-kgpd_Div	0.101792	0.098622	0.085983	0.085108	0.086603	0.084520
02-kgpd_Mul	0.099980	0.097547	0.084001	0.064706	0.072849	0.081023
03-kgpd_Sin	0.089632	0.103505	0.194194	0.301002	0.245769	0.260717
04-kgpd_Div1	0.099119	0.096737	0.088709	0.063237	0.095840	0.091635
05-kgpd_Pow	0.108045	0.098307	0.081161	0.064898	0.079015	0.076962
06-kgpd_Mul1	0.098561	0.098475	0.082770	0.063557	0.087732	0.076762
07-kgpd_Exp	0.090019	0.087015	0.086282	0.088542	0.103798	0.087690
08-gpr_MatMul	0.100426	0.102766	0.106220	0.102751	0.069157	0.059617
09-gpr_Add	0.098425	0.096143	0.061836	0.018155	0.002462	0.000696

if r is not None:
    ax = (pivort / total).T.plot(logx=True, figsize=(14, 4))
    ax.set_ylim([0,1])
    ax.set_title("Time spent in each node relatively to the total time\nonnxtunime");

The results are relative. Let’s see which runtime is best node by node.

if r is not None:
    r = (pivort - pivpy) / pivpy
r

N	1	10	100	1000	10000	100000
step
00-kgpd_CDist	-0.239113	-0.367743	-0.630420	-0.703226	-0.677041	-0.631775
01-kgpd_Div	1.564119	1.308106	1.123155	2.333824	2.857590	2.223117
02-kgpd_Mul	2.473648	2.027773	2.149388	3.249448	2.624165	2.828025
03-kgpd_Sin	1.779780	0.881090	0.280401	0.216680	0.311288	0.427768
04-kgpd_Div1	2.331710	1.865534	1.411570	1.642922	4.321977	4.466249
05-kgpd_Pow	2.097502	-0.071724	-0.842765	-0.932321	-0.897065	-0.887837
06-kgpd_Mul1	2.563218	2.067909	1.842112	1.811019	4.263897	3.320524
07-kgpd_Exp	1.756911	0.384288	-0.599693	-0.759241	-0.657668	-0.644029
08-gpr_MatMul	0.517953	1.502798	1.965953	4.201281	4.281286	4.701255
09-gpr_Add	1.502111	1.461452	1.233097	1.247736	0.486358	1.160395

Based on this, onnxruntime is faster for operators Scan, Pow, Exp and slower for all the others.

Measuring the time with a custom dataset

We use the example Comparison of kernel ridge and Gaussian process regression.

import numpy
import pandas
import matplotlib.pyplot as plt
from sklearn.kernel_ridge import KernelRidge
from sklearn.model_selection import GridSearchCV
from sklearn.gaussian_process import GaussianProcessRegressor
from sklearn.gaussian_process.kernels import WhiteKernel, ExpSineSquared

rng = numpy.random.RandomState(0)

# Generate sample data
X = 15 * rng.rand(100, 1)
y = numpy.sin(X).ravel()
y += 3 * (0.5 - rng.rand(X.shape[0]))  # add noise

gp_kernel = ExpSineSquared(1.0, 5.0, periodicity_bounds=(1e-2, 1e1))
gpr = GaussianProcessRegressor(kernel=gp_kernel)
gpr.fit(X, y)

C:xavierdupre__home_github_forkscikit-learnsklearngaussian_processkernels.py:409: ConvergenceWarning: The optimal value found for dimension 0 of parameter length_scale is close to the specified lower bound 1e-05. Decreasing the bound and calling fit again may find a better value.
  ConvergenceWarning)
C:xavierdupre__home_github_forkscikit-learnsklearngaussian_processkernels.py:418: ConvergenceWarning: The optimal value found for dimension 0 of parameter periodicity is close to the specified upper bound 10.0. Increasing the bound and calling fit again may find a better value.
  ConvergenceWarning)

GaussianProcessRegressor(kernel=ExpSineSquared(length_scale=1, periodicity=5))

onx = to_onnx(gpr, X_test.astype(numpy.float64))
with open("gpr_time.onnx", "wb") as f:
    f.write(onx.SerializeToString())
%onnxview onx -r 1

from mlprodict.tools import get_ir_version_from_onnx
onx.ir_version = get_ir_version_from_onnx()

oinfpy = OnnxInference(onx, runtime="python")
oinfort = OnnxInference(onx, runtime="onnxruntime2")

runtime==onnxruntime2 tells the class OnnxInference to use onnxruntime for every node independently, there are as many calls as there are nodes in the graph.

respy = oinfpy.run({'X': X_test}, node_time=True)
try:
    resort = oinfort.run({'X': X_test}, node_time=True)
except Exception as e:
    print(e)
    resort = None

if resort is not None:
    df = pandas.DataFrame(respy[1]).merge(pandas.DataFrame(resort[1]), on=["i", "name", "op_type"],
                                        suffixes=("_py", "_ort"))
    df['delta'] = df.time_ort - df.time_py
else:
    df = None
df

	i	name	op_type	time_py	time_ort	delta
0	0	Sc_Scan	Scan	0.007998	0.005970	-0.002028
1	1	kgpd_Transpose	Transpose	0.000032	0.000599	0.000567
2	2	kgpd_Sqrt	Sqrt	0.000063	0.000112	0.000049
3	3	kgpd_Div	Div	0.000143	0.000097	-0.000045
4	4	kgpd_Mul	Mul	0.000038	0.000321	0.000283
5	5	kgpd_Sin	Sin	0.000095	0.000146	0.000051
6	6	kgpd_Div1	Div	0.000027	0.000096	0.000069
7	7	kgpd_Pow	Pow	0.000299	0.000104	-0.000196
8	8	kgpd_Mul1	Mul	0.000032	0.000097	0.000065
9	9	kgpd_Exp	Exp	0.000383	0.000111	-0.000271
10	10	gpr_MatMul	MatMul	0.000080	0.004359	0.004279
11	11	gpr_Add	Add	0.000034	0.000165	0.000131

The following function runs multiple the same inference and aggregates the results node by node.

from mlprodict.onnxrt.validate.validate import benchmark_fct
res = benchmark_fct(lambda X: oinfpy.run({'X': X_test}, node_time=True),
                    X_test, node_time=True)

df = pandas.DataFrame(res)
df[df.N == 100]

	i	name	op_type	time	N	max_time	min_time	repeat	number
24	0	Sc_Scan	Scan	0.004154	100	0.004330	0.003843	10	8
25	1	kgpd_Transpose	Transpose	0.000013	100	0.000019	0.000010	10	8
26	2	kgpd_Sqrt	Sqrt	0.000018	100	0.000022	0.000015	10	8
27	3	kgpd_Div	Div	0.000025	100	0.000092	0.000015	10	8
28	4	kgpd_Mul	Mul	0.000012	100	0.000019	0.000009	10	8
29	5	kgpd_Sin	Sin	0.000057	100	0.000070	0.000050	10	8
30	6	kgpd_Div1	Div	0.000014	100	0.000017	0.000011	10	8
31	7	kgpd_Pow	Pow	0.000172	100	0.000198	0.000155	10	8
32	8	kgpd_Mul1	Mul	0.000020	100	0.000101	0.000009	10	8
33	9	kgpd_Exp	Exp	0.000213	100	0.000249	0.000193	10	8
34	10	gpr_MatMul	MatMul	0.000034	100	0.000047	0.000026	10	8
35	11	gpr_Add	Add	0.000013	100	0.000019	0.000011	10	8

df100 = df[df.N == 100]

%matplotlib inline

fig, ax = plt.subplots(1, 1, figsize=(14, 4))
ax.bar(df100.i, df100.time, align='center', color='orange')
ax.set_xticks(df100.i)
ax.set_yscale('log')
ax.set_xticklabels(df100.op_type)
ax.errorbar(df100.i, df100.time,
            numpy.abs(df100[["min_time", "max_time"]].T.values - df100.time.values.ravel()),
            uplims=True, lolims=True, color='blue')
ax.set_title("Time spent in each node for 100 observations\nGaussianProcess");

df100c = df100.cumsum()

fig, ax = plt.subplots(1, 1, figsize=(14, 4))
ax.bar(df100.i, df100c.time, align='center', color='orange')
ax.set_xticks(df100.i)
#ax.set_yscale('log')
ax.set_ylim([df100c.min_time.min(), df100c.max_time.max()])
ax.set_xticklabels(df100.op_type)
ax.errorbar(df100.i, df100c.time,
            numpy.abs((df100c[["min_time", "max_time"]].T.values - df100c.time.values.ravel())),
            uplims=True, lolims=True)
ax.set_title("Cumulated time spent in each node for 100 observations\nGaussianProcess");

onnxruntime2 / onnxruntime1

The runtime onnxruntime1 uses onnxruntime for the whole ONNX graph. There is no way to get the computation time for each node except if we create a ONNX graph for each intermediate node.

oinfort1 = OnnxInference(onx, runtime='onnxruntime1')

split = oinfort1.build_intermediate()
split

OrderedDict([('scan0', OnnxInference(...)),
             ('scan1', OnnxInference(...)),
             ('kgpd_transposed0', OnnxInference(...)),
             ('kgpd_Y0', OnnxInference(...)),
             ('kgpd_C03', OnnxInference(...)),
             ('kgpd_C02', OnnxInference(...)),
             ('kgpd_output02', OnnxInference(...)),
             ('kgpd_C01', OnnxInference(...)),
             ('kgpd_Z0', OnnxInference(...)),
             ('kgpd_C0', OnnxInference(...)),
             ('kgpd_output01', OnnxInference(...)),
             ('gpr_Y0', OnnxInference(...)),
             ('GPmean', OnnxInference(...))])

dfs = []
for k, v in split.items():
    print("node", k)
    res = benchmark_fct(lambda x: v.run({'X': x}), X_test)
    df = pandas.DataFrame(res)
    df['name'] = k
    dfs.append(df.reset_index(drop=False))

node scan0
node scan1
node kgpd_transposed0
node kgpd_Y0
node kgpd_C03
node kgpd_C02
node kgpd_output02
node kgpd_C01
node kgpd_Z0
node kgpd_C0
node kgpd_output01
node gpr_Y0
node GPmean

df = pandas.concat(dfs)
df.head()

	index	1	10	100	1000	10000	100000	name
0	average	0.000623	0.000592	0.000754	0.002202	0.017529	0.201192	scan0
1	deviation	0.000115	0.000030	0.000034	0.000026	0.000976	0.000000	scan0
2	min_exec	0.000541	0.000537	0.000657	0.002169	0.016677	0.201192	scan0
3	max_exec	0.000980	0.000639	0.000780	0.002239	0.018896	0.201192	scan0
4	repeat	20.000000	20.000000	10.000000	5.000000	3.000000	1.000000	scan0

df100c = df[df['index'] == "average"]
df100c_min = df[df['index'] == "min_exec"]
df100c_max = df[df['index'] == "max_exec"]
ave = df100c.iloc[:, 4]
ave_min = df100c_min.iloc[:, 4]
ave_max = df100c_max.iloc[:, 4]
ave.shape, ave_min.shape, ave_max.shape
index = numpy.arange(ave.shape[0])

fig, ax = plt.subplots(1, 1, figsize=(14, 4))
ax.bar(index, ave, align='center', color='orange')
ax.set_xticks(index)
ax.set_xticklabels(df100c.name)
for tick in ax.get_xticklabels():
    tick.set_rotation(20)
ax.errorbar(index, ave,
            numpy.abs((numpy.vstack([ave_min.values, ave_max.values]) - ave.values.ravel())),
            uplims=True, lolims=True)
ax.set_title("Cumulated time spent in each node for 100 "
             "observations\nGaussianProcess and onnxruntime1");

The visual graph helps matching the output names with the operator type. The curve is not monotononic because each experiment computes every output from the start. The number of repetitions should be increased. Documentation of function benchmark_fct tells how to do it.

previous

Profiling with onnxruntime

next

Transfer Learning with ONNX