Skip to content

[NPUW] Add timestamps to LLM execution profiling#34919

Draft
dylanneve1 wants to merge 3 commits intoopenvinotoolkit:masterfrom
dylanneve1:EISW-209703
Draft

[NPUW] Add timestamps to LLM execution profiling#34919
dylanneve1 wants to merge 3 commits intoopenvinotoolkit:masterfrom
dylanneve1:EISW-209703

Conversation

@dylanneve1
Copy link
Member

@dylanneve1 dylanneve1 commented Mar 25, 2026

Details:

  • Expands on 04293e6 by adding HH:MM:SS.microsecond timestamps to LLM execution profiling points only (prefill/generate phases), for correlation with external voltage measurements on NPU. Gated behind OPENVINO_NPUW_PROF=1 and OPENVINO_NPUW_LOG_LEVEL=INFO.

Tickets:

AI Assistance:

  • AI assistance used: yes
  • Claude Code used for implementing timestamps on top of existing profiling. Reviewed and verified on hardware collected logs below.
[ NPUW:INFO ]     PROF 1/prefill:1.prepare_for_new_conversation START @ 09:56:18.743016
[ NPUW:INFO ]     PROF 1/prefill:1.prepare_for_new_conversation END   @ 09:56:18.743558 (took 0.542 ms)
[ NPUW:INFO ]     PROF 1/prefill:2.apply_lora START @ 09:56:18.743626
[ NPUW:INFO ]     PROF 1/prefill:2.apply_lora END   @ 09:56:18.743671 (took 0.045 ms)
[ NPUW:INFO ]     PROF 1/prefill:3.infer START @ 09:56:18.743710
[ NPUW:INFO ]         PROF 1/prefill:3a.prepare START @ 09:56:18.743748
[ NPUW:INFO ]         PROF 1/prefill:3a.prepare END   @ 09:56:18.743788 (took 0.040 ms)
[ NPUW:INFO ]         PROF 1/prefill:3b.infer START @ 09:56:18.743825
[ NPUW:INFO ]         PROF 1/prefill:3b.infer END   @ 09:56:19.153621 (took 409.796 ms)
[ NPUW:INFO ]     PROF 1/prefill:3.infer END   @ 09:56:19.153834 (took 410.124 ms)
[ NPUW:INFO ]     PROF 1/prefill:4.lm_head START @ 09:56:19.154059
[ NPUW:INFO ]     PROF 1/prefill:4.lm_head END   @ 09:56:19.164822 (took 10.763 ms)
[ NPUW:INFO ]     PROF N/generate:1.prepare START @ 09:56:19.165196
[ NPUW:INFO ]     PROF N/generate:1.prepare END   @ 09:56:19.166234 (took 1.038 ms)
[ NPUW:INFO ]     PROF N/generate:2.infer START @ 09:56:19.166428
[ NPUW:INFO ]     PROF N/generate:2.infer END   @ 09:56:19.222619 (took 56.191 ms)
[ NPUW:INFO ]     PROF N/generate:3.update_kvcache START @ 09:56:19.222753
[ NPUW:INFO ]     PROF N/generate:3.update_kvcache END   @ 09:56:19.223128 (took 0.375 ms)
[ NPUW:INFO ]     PROF N/generate:4.lm_head START @ 09:56:19.223183
[ NPUW:INFO ]     PROF N/generate:4.lm_head END   @ 09:56:19.225248 (took 2.065 ms)
[ NPUW:INFO ]     PROF N/generate:1.prepare START @ 09:56:19.225482
[ NPUW:INFO ]     PROF N/generate:1.prepare END   @ 09:56:19.225546 (took 0.064 ms)
[ NPUW:INFO ]     PROF N/generate:2.infer START @ 09:56:19.225596
[ NPUW:INFO ]     PROF N/generate:2.infer END   @ 09:56:19.249015 (took 23.419 ms)
[ NPUW:INFO ]     PROF N/generate:3.update_kvcache START @ 09:56:19.249199
[ NPUW:INFO ]     PROF N/generate:3.update_kvcache END   @ 09:56:19.249571 (took 0.372 ms)
[ NPUW:INFO ]     PROF N/generate:4.lm_head START @ 09:56:19.249629
[ NPUW:INFO ]     PROF N/generate:4.lm_head END   @ 09:56:19.251631 (took 2.002 ms)

Expands on 04293e6 by adding HH:MM:SS.microsecond timestamps to
LLM execution profiling points only (prefill/generate phases),
for correlation with external voltage measurements on NPU.
Gated behind OPENVINO_NPUW_PROF=1 and OPENVINO_NPUW_LOG_LEVEL=INFO.
@dylanneve1 dylanneve1 requested review from a team as code owners March 25, 2026 10:00
@github-actions github-actions bot added category: NPU OpenVINO NPU plugin category: NPUW NPUW plugin labels Mar 25, 2026
@dylanneve1 dylanneve1 requested a review from Copilot March 25, 2026 10:03
Copy link
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Adds wall-clock timestamps to NPUW LLM execution profiling events to help correlate prefill/generate phases with external measurements (e.g., voltage traces), while reusing the existing profiling infrastructure.

Changes:

  • Extend ov::npuw::perf::metric to optionally emit START/END timestamped INFO logs around record().
  • Add emit_timestamps plumbing to ov::npuw::perf::Profile and enable it for LLMInferRequest profiling.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 4 comments.

File Description
src/plugins/intel_npu/src/plugin/npuw/perf.hpp Adds timestamp emission support inside metric::record() and propagates timestamp enabling through Profile.
src/plugins/intel_npu/src/plugin/npuw/llm_infer_request.cpp Enables timestamp emission for LLM execution profiling when profiling is enabled.

@dylanneve1 dylanneve1 marked this pull request as draft March 25, 2026 10:09
- Fix move ctor to preserve vmin/vmax/total statistics
- Use localtime_s/_r instead of localtime for thread safety
- Gate timestamp computation on log level >= INFO to avoid
  unnecessary overhead when timestamps won't be visible
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

category: NPU OpenVINO NPU plugin category: NPUW NPUW plugin

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants