Debug discrepancy of `avg_inference_latency` reported from optimum-et models

[guangy10]

🐛 Describe the bug

As highlighted in the screenshot, avg_inference_latency doesn't make sense between the etLLM and optimum-et generated models.

Upon checking the raw results from the CI, I can see the other latency related metrics like generate_time and tokens_per_sec (TPS) are close between etLLM and optimum-et.

The avg_inference_latency is a separate metric that is measured separately from how generate_timean and tokens_per_sec (TPS) are reported (a separate test), and it should just report the latency on forward() call regardless the model is LLM or not. Since the reported generate_time and TPS are very close, I suspect if there is a bug in how the avg_inference_latency are measured, or wired to the dashboard.

Versions

trunk

[guangy10]

Pulling the PTE and run it locally via pybind API, I got identical latency number on forward():

Model loaded from qwen3-0.6b_et/model.pte

⚠️ DISCLAIMER: Python-based perf measurements are approximate and may not match absolute speeds on Android/iOS apps. They are intended for relative comparisons—-e.g. SDPA vs. custom SDPA, FP16 vs. FP32—-so you can gauge performance improvements from each optimization step. For end-to-end, platform-accurate benchmarks, please use the official ExecuTorch apps:
  • iOS:     https://github.com/pytorch/executorch/tree/main/extension/benchmark/apple/Benchmark
  • Android: https://github.com/pytorch/executorch/tree/main/extension/benchmark/android/benchmark

PyTorchObserver {"prompt_tokens": 5, "generated_tokens": 95, "model_load_start_ms": 0, "model_load_end_ms": 0, "inference_start_ms": 1750199253236, "token_encode_end_ms": 1750199253237, "model_execution_start_ms": 1750199254558, "model_execution_end_ms": 1750199254573, "inference_end_ms": 1750199254573, "prompt_eval_end_ms": 1750199253299, "first_token_ms": 1750199253311, "aggregate_sampling_time_ms": 1316, "SCALING_FACTOR_UNITS_PER_SECOND": 1000}
	Prompt Tokens: 5 Generated Tokens: 95
	Model Load Time:		0.000000 (seconds)
	Total inference time:		1.337000 (seconds)		 Rate: 	71.054600 (tokens/second)
		Prompt evaluation:	0.063000 (seconds)		 Rate: 	79.365079 (tokens/second)
		Generated 95 tokens:	1.274000 (seconds)		 Rate: 	74.568289 (tokens/second)
	Time to first generated token:	0.075000 (seconds)
	Sampling time over 100 tokens:	1.316000 (seconds)

model_execution_end_ms - model_execution_start_ms = 15

Model loaded from qwen3-0.6b_hf/model.pte

⚠️ DISCLAIMER: Python-based perf measurements are approximate and may not match absolute speeds on Android/iOS apps. They are intended for relative comparisons—-e.g. SDPA vs. custom SDPA, FP16 vs. FP32—-so you can gauge performance improvements from each optimization step. For end-to-end, platform-accurate benchmarks, please use the official ExecuTorch apps:
  • iOS:     https://github.com/pytorch/executorch/tree/main/extension/benchmark/apple/Benchmark
  • Android: https://github.com/pytorch/executorch/tree/main/extension/benchmark/android/benchmark

PyTorchObserver {"prompt_tokens": 5, "generated_tokens": 95, "model_load_start_ms": 0, "model_load_end_ms": 0, "inference_start_ms": 1750198960861, "token_encode_end_ms": 1750198960862, "model_execution_start_ms": 1750198962197, "model_execution_end_ms": 1750198962212, "inference_end_ms": 1750198962212, "prompt_eval_end_ms": 1750198960926, "first_token_ms": 1750198960938, "aggregate_sampling_time_ms": 1340, "SCALING_FACTOR_UNITS_PER_SECOND": 1000}
	Prompt Tokens: 5 Generated Tokens: 95
	Model Load Time:		0.000000 (seconds)
	Total inference time:		1.351000 (seconds)		 Rate: 	70.318283 (tokens/second)
		Prompt evaluation:	0.065000 (seconds)		 Rate: 	76.923077 (tokens/second)
		Generated 95 tokens:	1.286000 (seconds)		 Rate: 	73.872473 (tokens/second)
	Time to first generated token:	0.077000 (seconds)
	Sampling time over 100 tokens:	1.340000 (seconds)

model_execution_end_ms - model_execution_start_ms = 15

[guangy10]

I suspect if the discrepancy is due to prefill, then discrepancy is expected. Because today etLLM generated PTE supports prefill but optimum-et doesn't yet. generated (WIP). I think this can be easily verified it once optimum-et supportd prefill.