[NPUW] Add timestamps to LLM execution profiling

src/plugins/intel_npu/src/plugin/npuw/llm_infer_request.cpp

@@ -222,6 +222,7 @@ ov::npuw::LLMInferRequest::LLMInferRequest(const std::shared_ptr<ov::npuw::LLMCo
     m_generate_initialized = false;
 
     m_llm_profile.report_on_die = ov::npuw::profiling_enabled();
+    m_llm_profile.emit_timestamps = ov::npuw::profiling_enabled();
     m_llm_profile.area = "LLM/execution";
 }
 

src/plugins/intel_npu/src/plugin/npuw/perf.hpp

@@ -5,7 +5,10 @@
 #pragma once
 
 #include <algorithm>
+#include <chrono>
+#include <ctime>
 #include <functional>
+#include <iomanip>
 #include <limits>
 #include <ostream>
 #include <string>
@@ -64,17 +67,29 @@ class metric {
     T total = 0;
     std::string name;
     bool enabled = false;
+    bool emit_timestamps = false;
 
 public:
     metric() = default;
-    metric(metric&& m) : records(std::move(m.records)), name(std::move(m.name)), enabled(m.enabled) {}
+    metric(metric&& m)
+        : records(std::move(m.records)),
+          vmin(m.vmin),
+          vmax(m.vmax),
+          total(m.total),
+          name(std::move(m.name)),
+          enabled(m.enabled),
+          emit_timestamps(m.emit_timestamps) {}
 
     explicit metric(const std::string& named, bool active = false) : name(named), enabled(active) {}
 
     void enable() {
         enabled = true;
     }
 
+    void set_timestamps(bool v) {
+        emit_timestamps = v;
+    }
+
     void operator+=(T&& t) {
         if (!enabled) {
             return;
@@ -105,8 +120,37 @@ class metric {
     void record(F&& f) {
         if (!enabled) {
             f();
-        } else {
+        } else if (!emit_timestamps || ov::npuw::get_log_level() < ov::npuw::LogLevel::Info) {
             *this += U::sample(f);
+        } else {
+            auto t_start = std::chrono::system_clock::now();
+            auto start_us =
+                std::chrono::duration_cast<std::chrono::microseconds>(t_start.time_since_epoch()).count();
+            std::time_t start_tt = std::chrono::system_clock::to_time_t(t_start);
+            std::tm start_tm{};
+#ifdef _WIN32
+            localtime_s(&start_tm, &start_tt);
+#else
+            localtime_r(&start_tt, &start_tm);
+#endif
+            LOG_INFO("PROF " << name << " START @ " << std::put_time(&start_tm, "%H:%M:%S") << "."
+                             << std::setfill('0') << std::setw(6) << (start_us % 1000000));
+            auto sample_ms = U::sample(f);
+            *this += std::move(sample_ms);
+            auto t_end = std::chrono::system_clock::now();
+            auto end_us =
+                std::chrono::duration_cast<std::chrono::microseconds>(t_end.time_since_epoch()).count();
+            std::time_t end_tt = std::chrono::system_clock::to_time_t(t_end);
+            std::tm end_tm{};
+#ifdef _WIN32
+            localtime_s(&end_tm, &end_tt);
+#else
+            localtime_r(&end_tt, &end_tm);
+#endif
+            LOG_INFO("PROF " << name << " END   @ " << std::put_time(&end_tm, "%H:%M:%S") << "."
+                             << std::setfill('0') << std::setw(6) << (end_us % 1000000) << " (took "
+                             << std::fixed << std::setprecision(3) << ((end_us - start_us) / 1000.0)
+                             << " ms)");
         }
     }
 
@@ -151,6 +195,8 @@ class counter {
         enabled = true;
     }
 
+    void set_timestamps(bool) {}  // no-op for counters
+
     void operator+=(T&& t) {
         if (enabled) {
             total += t;
@@ -178,12 +224,15 @@ struct Profile {
     std::map<std::string, Metric> metrics;
     std::string area;
     bool report_on_die = false;
+    bool emit_timestamps = false;
 
     Metric& operator[](const std::string& tag) {
         auto iter = metrics.find(tag);
         if (iter == metrics.end()) {
-            // Use report_on_die as a "enabled" marker here
             auto [new_iter, unused] = metrics.insert({tag, Metric(tag, report_on_die)});
+            if (emit_timestamps) {
+                new_iter->second.set_timestamps(true);
+            }
             return new_iter->second;
         }
         return iter->second;