triton-inference-server / onnxruntime_backend

The Triton backend for the ONNX Runtime.
BSD 3-Clause "New" or "Revised" License
134 stars 57 forks source link

Triton ONNX runtime backend slower than onnxruntime python client on CPU #265

Open Mitix-EPI opened 3 months ago

Mitix-EPI commented 3 months ago

Description When deploying an ONNX model using the Triton Inference Server's ONNX runtime backend, the inference performance on the CPU is noticeably slower compared to running the same model using the ONNXRuntime Python client directly. This performance discrepancy is observed under identical conditions, including the same hardware, model, and input data.

Triton Information TRITON_VERSION <= 24.09

To Reproduce

model used:

wget -O model.onnx https://github.com/onnx/models/raw/refs/heads/main/validated/vision/classification/densenet-121/model/densenet-12.onnx

Triton server (ONNX runtime)

config.pbtxt

name: "test_densenet" 
platform: "onnxruntime_onnx"

Python clients

Triton client

import numpy as np
import tritonclient.grpc as grpcclient
import tritonclient.grpc._infer_input as infer_input

grpcclient = grpcclient.InferenceServerClient(url='localhost:9178')

i = infer_input.InferInput('data_0', [1, 3, 224, 224], 'FP32')
i.set_data_from_numpy(np.zeros((1, 3, 224, 224), dtype=np.float32))
%%timeit
res = grpcclient.infer(model_name="test_densenet", inputs=[i])

results: 473 ms ± 87.9 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

ONNX Runtime

import onnxruntime as ort

ort_sess = ort.InferenceSession('model.onnx')
test_inputs = {"data_0": np.zeros((1, 3, 224, 224), dtype=np.float32)}
%%timeit
ort_sess.run(["fc6_1"], test_inputs)

results: 159 ms ± 23.9 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)

Mitix-EPI commented 1 month ago

@fpetrini15 ?? it's a black box

tanmayv25 commented 1 month ago

@Mitix-EPI Can you add get_inference_statistics function call after infer and share the numbers?

It would help us in identifying the bottleneck. Additionally, what happens when you run the infer command multiple times? Does the latency remain the same or it reduces with repetition? This would help us identifying if this is a warmup issue.

fpetrini15 commented 1 month ago

Hi @Mitix-EPI,

I set up a simple test suite on my local machine with minor modifications (mostly altering the code to work outside of Jupytr) and could not replicate your results. While the result you report in your ONNX Runtime section is consistent with what I am observing in my testing, Triton is consistently clocking between 178-185ms of execution time when deploying an instance to the CPU. Here's my data from a single run:

# 10 requests
Single execution time: 27.143945917487144 ms
Single execution time: 16.90200436860323 ms
Single execution time: 16.530546359717846 ms
Single execution time: 16.570006497204304 ms
Single execution time: 16.596742905676365 ms
Single execution time: 16.560756601393223 ms
Single execution time: 16.599184833467007 ms
Single execution time: 16.567444428801537 ms
Single execution time: 16.583171673119068 ms
Single execution time: 16.47179201245308 ms
AVG Execution time: 17.686644196510315 ms per inference
TOTAL Execution time: 176.86644196510315 seconds ms inference

However, if the model is deployed to the GPU (server log should contain something like "TRITONBACKEND_ModelInstanceInitialize: test_densenet_0 (GPU device 0)", then I do observe a large delay for the first request, whereafter subsequent requests level off to a much lower number.

# 1000 requests
Single execution time: 968.3446865528822 ms per inference
Single execution time: 30.06432857364416 ms per inference
Single execution time: 11.44306268543005 ms per inference
...
AVG Execution time: 10.60993140405044 ms per inference
TOTAL Execution time: 106099.3140405044 seconds ms inference

You can make explicitly sure that your model is being deployed to the CPU by adding the following to your config:

instance_group [ 
    { 
        count: 1
        kind: KIND_CPU
     }
]
Mitix-EPI commented 1 month ago

@Mitix-EPI Can you add get_inference_statistics function call after infer and share the numbers?

It would help us in identifying the bottleneck. Additionally, what happens when you run the infer command multiple times? Does the latency remain the same or it reduces with repetition? This would help us identifying if this is a warmup issue.

Thank you so much for your interest on this issue !

Over 100 iterations, I observed no fluctual time inference between requests. The only two first requests are anomalies. Each time inference is, more or less, around 75-95ms.

Here's more informations:

shell run

docker run --rm -p8000:8000 -p8001:8001 -p8002:8002 -v ./triton-test-inference:/models nvcr.io/nvidia/tritonserver:24.09-py3 tritonserver --model-repository=/models

test_triton_inference.py

import numpy as np
import time
import tritonclient.grpc as grpcclient
import tritonclient.grpc._infer_input as infer_input

grpcclient = grpcclient.InferenceServerClient(url='localhost:8001')

i = infer_input.InferInput('data_0', [1, 3, 224, 224], 'FP32')
i.set_data_from_numpy(np.zeros((1, 3, 224, 224), dtype=np.float32))

times = np.array([])
for _ in range(100):
    start = time.time()
    res = grpcclient.infer(model_name="test_densenet", inputs=[i])
    end = time.time()
    time_spend = (end-start) * 1000
    times = np.append(times, time_spend)
    print(f"Time: {time_spend:.2f} ms")

print(f"Mean: {np.mean(times):.2f} ms")
print(f"Median: {np.median(times):.2f} ms")
print(f"Std: {np.std(times):.2f} ms")

print("Inference statistics:")
print(grpcclient.get_inference_statistics(model_name="test_densenet"))

results

Time: 41.82 ms
Time: 185.61 ms
Time: 71.81 ms
...
Time: 91.11 ms
Time: 77.40 ms
Time: 95.15 ms
Mean: 85.26 ms
Median: 87.08 ms
Std: 15.61 ms
Inference statistics:
model_stats {
  name: "test_densenet"
  version: "1"
  last_inference: 1728293121207
  inference_count: 100
  execution_count: 100
  inference_stats {
    success {
      count: 100
      ns: 8419514015
    }
    fail {
    }
    queue {
      count: 100
      ns: 2680622
    }
    compute_input {
      count: 100
      ns: 1792863
    }
    compute_infer {
      count: 100
      ns: 8384467212
    }
    compute_output {
      count: 100
      ns: 2270801
    }
    cache_hit {
    }
    cache_miss {
    }
  }
  batch_stats {
    batch_size: 1
    compute_input {
      count: 100
      ns: 1792863
    }
    compute_infer {
      count: 100
      ns: 8384467212
    }
    compute_output {
      count: 100
      ns: 2270801
    }
  }
}

test_onnxruntime_inference.py

import numpy as np
import time
import onnxruntime as ort

ort_sess = ort.InferenceSession('triton-test-inference/test_densenet/1/model.onnx')
test_inputs = {"data_0": np.zeros((1, 3, 224, 224), dtype=np.float32)}

times = np.array([])
for _ in range(100):
    start = time.time()
    ort_sess.run(["fc6_1"], test_inputs)
    end = time.time()
    time_spend = (end-start) * 1000
    times = np.append(times, time_spend)
    print(f"Time: {time_spend:.2f} ms")

print(f"Mean: {np.mean(times):.2f} ms")
print(f"Median: {np.median(times):.2f} ms")
print(f"Std: {np.std(times):.2f} ms")

results

Time: 26.44 ms
Time: 25.06 ms
Time: 25.47 ms
...
Time: 32.01 ms
Time: 28.06 ms
Time: 27.27 ms
Mean: 26.08 ms
Median: 25.64 ms
Std: 1.10 ms
Mitix-EPI commented 1 month ago

Hi @Mitix-EPI,

I set up a simple test suite on my local machine with minor modifications (mostly altering the code to work outside of Jupytr) and could not replicate your results. While the result you report in your ONNX Runtime section is consistent with what I am observing in my testing, Triton is consistently clocking between 178-185ms of execution time when deploying an instance to the CPU. Here's my data from a single run:

# 10 requests
Single execution time: 27.143945917487144 ms
Single execution time: 16.90200436860323 ms
Single execution time: 16.530546359717846 ms
Single execution time: 16.570006497204304 ms
Single execution time: 16.596742905676365 ms
Single execution time: 16.560756601393223 ms
Single execution time: 16.599184833467007 ms
Single execution time: 16.567444428801537 ms
Single execution time: 16.583171673119068 ms
Single execution time: 16.47179201245308 ms
AVG Execution time: 17.686644196510315 ms per inference
TOTAL Execution time: 176.86644196510315 seconds ms inference

However, if the model is deployed to the GPU (server log should contain something like "TRITONBACKEND_ModelInstanceInitialize: test_densenet_0 (GPU device 0)", then I do observe a large delay for the first request, whereafter subsequent requests level off to a much lower number.

# 1000 requests
Single execution time: 968.3446865528822 ms per inference
Single execution time: 30.06432857364416 ms per inference
Single execution time: 11.44306268543005 ms per inference
...
AVG Execution time: 10.60993140405044 ms per inference
TOTAL Execution time: 106099.3140405044 seconds ms inference

You can make explicitly sure that your model is being deployed to the CPU by adding the following to your config:

instance_group [ 
    { 
        count: 1
        kind: KIND_CPU
     }
]

Thanks ++ for your interest on my issue !

Nothing about GPU, the device I use does not have GPU.

I1007 09:04:52.000928 1 onnxruntime.cc:2986] "TRITONBACKEND_ModelInitialize: test_densenet (version 1)"
I1007 09:04:52.134176 1 onnxruntime.cc:3051] "TRITONBACKEND_ModelInstanceInitialize: test_densenet_0 (CPU device 0)"
I1007 09:04:52.134301 1 onnxruntime.cc:3051] "TRITONBACKEND_ModelInstanceInitialize: test_densenet_1 (CPU device 0)"
I1007 09:04:52.398852 1 model_lifecycle.cc:839] "successfully loaded 'test_densenet'"

I just tested on another computer with another cpu and it ⚠️ DOES NOT ⚠️ reproduce the slow triton onnx inference... maybe cpu compatibility issue ?

>lscpu 
Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         46 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  12
  On-line CPU(s) list:   0-11
Vendor ID:               GenuineIntel
  Model name:            13th Gen Intel(R) Core(TM) i5-1345U
    CPU family:          6
    Model:               186
    Thread(s) per core:  2
    Core(s) per socket:  10
    Socket(s):           1
    Stepping:            3
    CPU max MHz:         4700,0000
    CPU min MHz:         400,0000
    BogoMIPS:            4992.00
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr 
                         sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good
                          nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vm
                         x smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_ti
                         mer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb invpcid_single ssbd ibrs i
                         bpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2
                          smep bmi2 erms invpcid rdseed adx smap clflushopt clwb intel_pt sha_ni xsaveopt xsavec xgetbv1 xs
                         aves avx_vnni dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp hwp_pkg_req hfi umip p
                         ku ospke waitpkg gfni vaes vpclmulqdq tme rdpid movdiri movdir64b fsrm md_clear serialize pconfig 
                         arch_lbr ibt flush_l1d arch_capabilities
Virtualization features: 
  Virtualization:        VT-x
Caches (sum of all):     
  L1d:                   352 KiB (10 instances)
  L1i:                   576 KiB (10 instances)
  L2:                    6,5 MiB (4 instances)
  L3:                    12 MiB (1 instance)
NUMA:                    
  NUMA node(s):          1
  NUMA node0 CPU(s):     0-11
Vulnerabilities:         
  Itlb multihit:         Not affected
  L1tf:                  Not affected
  Mds:                   Not affected
  Meltdown:              Not affected
  Mmio stale data:       Not affected
  Retbleed:              Not affected
  Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl
  Spectre v1:            Mitigation; usercopy/swapgs barriers and __user pointer sanitization
  Spectre v2:            Mitigation; Enhanced IBRS, IBPB conditional, RSB filling, PBRSB-eIBRS SW sequence
  Srbds:                 Not affected
  Tsx async abort:       Not affected

I don't actually know how to deal with it ...

I don't have any kind of slow inference with TF SavedModels or OpenVINO triton backends. It's only with ONNXRuntime.

tanmayv25 commented 1 month ago

@Mitix-EPI You can try Model Warmup feature to issue two requests to the model during the load time.

Mitix-EPI commented 1 month ago

@Mitix-EPI You can try Model Warmup feature to issue two requests to the model during the load time.

I just tried to add model warmup but it does not affect the time inference.

config.pbtxt

name: "test_densenet" 
platform: "onnxruntime_onnx"

input [
  {
    name: "data_0"
    data_type: TYPE_FP32
    dims: [ 1, 3, 224, 224 ]
  }
]
output [
  {
    name: "fc6_1"
    data_type: TYPE_FP32
    dims: [ 1, 1000, 1, 1 ]
  }
]

instance_group [{ kind: KIND_CPU }]
model_warmup [
{
    name : "zero sample"
    batch_size: 1
    inputs {
        key: "data_0"
        value: {
            data_type: TYPE_FP32
            dims: [ 1, 3, 224, 224 ]
            zero_data: true
        }
    }
    count: 100 <----------- A lot of warmup, just to see that in runtime it takes time and the warmup exists 
}]

results of test_triton_inference.py

Time: 33.84 ms
Time: 98.95 ms
Time: 89.65 ms
...
Time: 70.02 ms
Time: 87.91 ms
Time: 77.67 ms
Mean: 74.03 ms
Median: 72.99 ms
Std: 13.33 ms
Inference statistics:
model_stats {
  name: "test_densenet"
  version: "1"
  last_inference: 1728375230536
  inference_count: 300
  execution_count: 300
  inference_stats {
    success {
      count: 300
      ns: 30130533560
    }
    fail {
    }
    queue {
      count: 300
      ns: 2986235
    }
    compute_input {
      count: 300
      ns: 4255835
    }
    compute_infer {
      count: 300
      ns: 30094400062
    }
    compute_output {
      count: 300
      ns: 6082487
    }
    cache_hit {
    }
    cache_miss {
    }
  }
  batch_stats {
    batch_size: 1
    compute_input {
      count: 300
      ns: 4255835
    }
    compute_infer {
      count: 300
      ns: 30094400062
    }
    compute_output {
      count: 300
      ns: 6082487
    }
  }
}