Add perf metrics for CB VLM (openvinotoolkit#1897)

- Added passing CB perf metric for VLM cases as well. 
- Numbers are similar to vanilla pipeline

![image](https://github.com/user-attachments/assets/e2fbdfe0-cd0f-411a-90e4-f33ca1b06bbf)

Ticket CVS-163346

---------

Co-authored-by: Ilya Lavrenov <ilya.lavrenov@intel.com>

Author: pavel-esir

src/cpp/include/openvino/genai/continuous_batching_pipeline.hpp

@@ -15,6 +15,8 @@
 #include "openvino/genai/llm_pipeline.hpp"
 #include "openvino/genai/streamer_base.hpp"
 #include "openvino/genai/visibility.hpp"
+#include "openvino/genai/visual_language/pipeline.hpp"
+
 #include "cache_eviction.hpp"
 
 namespace ov::genai {
@@ -48,6 +50,11 @@ struct PipelineMetrics {
     * Running average of the KV cache usage during the lifetime of the pipeline, with max window size of 1000 steps
     */
     float avg_cache_usage = 0.0;
+
+    /**
+     * Duration of the last generation step in microseconds.
+     */
+    float inference_duration = 0.0;
 };
 
 class OPENVINO_GENAI_EXPORTS ContinuousBatchingPipeline {
@@ -164,7 +171,7 @@ class OPENVINO_GENAI_EXPORTS ContinuousBatchingPipeline {
     // more high level interface, which can process multiple prompts in continuous batching manner
     std::vector<EncodedGenerationResult> generate(const std::vector<ov::Tensor>& input_ids, const std::vector<ov::genai::GenerationConfig>& sampling_params, const ov::genai::StreamerVariant& streamer=std::monostate{});
     std::vector<GenerationResult> generate(const std::vector<std::string>& prompts, const std::vector<ov::genai::GenerationConfig>& sampling_params, const ov::genai::StreamerVariant& streamer=std::monostate{});
-    std::vector<GenerationResult> generate(
+    std::vector<VLMDecodedResults> generate(
              const std::vector<std::string>& prompts,
              const std::vector<std::vector<ov::Tensor>>& images,
              const std::vector<GenerationConfig>& sampling_params,

src/cpp/src/continuous_batching_impl.cpp

@@ -278,8 +278,11 @@ void ContinuousBatchingPipeline::ContinuousBatchingImpl::step() {
 
     {
         static ManualTimer timer("forward");
+        const auto infer_start = std::chrono::steady_clock::now();
         timer.start();
         logits = m_model_runner->forward(m_requests, scheduler_output);
+        const auto infer_end = std::chrono::steady_clock::now();
+        m_pipeline_metrics.inference_duration = PerfMetrics::get_microsec(infer_end - infer_start);
         timer.end();
     }
 
@@ -403,11 +406,13 @@ ContinuousBatchingPipeline::ContinuousBatchingImpl::generate(const std::vector<o
         try {
             const auto infer_start = std::chrono::steady_clock::now();
             step();
+            // During prefill step (or steps if max_batch_size < prompt_len) we don't generate new tokens,
+            // but still inference took place, so we need to add this time to the total inference duration.
+            raw_perf_counters.m_inference_durations[0] += MicroSeconds(m_pipeline_metrics.inference_duration);
             if (m_batch_size > 0) {
                 const auto infer_end = std::chrono::steady_clock::now();
-                const auto infer_ms = PerfMetrics::get_microsec(std::chrono::steady_clock::now() - infer_start);
+                const auto infer_ms = PerfMetrics::get_microsec(infer_end - infer_start);
                 raw_perf_counters.m_token_infer_durations.emplace_back(infer_ms);
-                raw_perf_counters.m_inference_durations[0] += MicroSeconds(infer_ms);
                 raw_perf_counters.m_new_token_times.emplace_back(infer_end);
                 raw_perf_counters.m_batch_sizes.emplace_back(m_batch_size);
             }

src/cpp/src/continuous_batching_pipeline.cpp

@@ -284,7 +284,7 @@ std::vector<GenerationResult> ContinuousBatchingPipeline::generate(const std::ve
     return decoded_results;
 }
 
-std::vector<GenerationResult> ContinuousBatchingPipeline::generate(
+std::vector<VLMDecodedResults> ContinuousBatchingPipeline::generate(
              const std::vector<std::string>& prompts,
              const std::vector<std::vector<ov::Tensor>>& images,
              const std::vector<GenerationConfig>& sampling_params,

src/cpp/src/icontinuous_batching.cpp

@@ -57,7 +57,16 @@ ContinuousBatchingPipeline::IContinuousBatchingPipeline::generate(
         // TODO: remove this code and within model runner add check: if sequence group type is tokens, 
         // but embedding model is available => compute embeddings first, then pass to LLM
         std::vector<std::vector<ov::Tensor>> images(prompts.size());
-        return generate(prompts, images, sampling_params, streamer);
+        auto results_vlm = generate(prompts, images, sampling_params, streamer);
+        std::vector<GenerationResult> resutls;
+        for (auto& vlm_result : results_vlm) {
+            GenerationResult result;
+            result.m_generation_ids = std::move(vlm_result.texts);
+            result.m_scores = std::move(vlm_result.scores);
+            result.perf_metrics = std::move(vlm_result.perf_metrics);
+            resutls.push_back(result);
+        }
+        return resutls;
     }
     std::vector<ov::Tensor> input_ids;
     auto start_time =  std::chrono::steady_clock::now();
@@ -142,20 +151,20 @@ ContinuousBatchingPipeline::IContinuousBatchingPipeline::generate(
     return decoded;
 }
 
-std::vector<GenerationResult>
+std::vector<VLMDecodedResults>
 ContinuousBatchingPipeline::IContinuousBatchingPipeline::generate(
              const std::vector<std::string>& prompts,
              const std::vector<std::vector<ov::Tensor>>& rgbs_vector,
              const std::vector<GenerationConfig>& sampling_params,
              const StreamerVariant& streamer)  {
-    // TODO: Add performance metrics
     auto generate_start_time = std::chrono::steady_clock::now();
     OPENVINO_ASSERT(m_model_input_type == ModelInputType::EMBEDDINGS);
 
     OPENVINO_ASSERT(prompts.size() == sampling_params.size(), "Number of prompts should be equal to the number of generation configs.");
     OPENVINO_ASSERT(prompts.size() == rgbs_vector.size(), "Number of prompts should be equal to the number of images vectors.");
 
     std::vector<ov::Tensor> input_embeds_list;
+    std::vector<VLMPerfMetrics> vlm_perf_metrics(prompts.size());
 
     if (m_is_chat_conversation) {
         OPENVINO_ASSERT(1 == prompts.size(), "Can't chat with multiple prompts");
@@ -171,37 +180,49 @@ ContinuousBatchingPipeline::IContinuousBatchingPipeline::generate(
 
         m_inputs_embedder->set_apply_chat_template_status(false);
 
-        VLMPerfMetrics perf_metrics;
-        input_embeds_list.push_back(m_inputs_embedder->get_inputs_embeds(templated_history, m_history_images, perf_metrics));
+        input_embeds_list.push_back(m_inputs_embedder->get_inputs_embeds(templated_history, m_history_images, vlm_perf_metrics[0]));
     } else {
         for (size_t i = 0; i < prompts.size(); i++) {
             const auto& prompt = prompts[i];
             const auto& rgbs = rgbs_vector[i];
 
+            auto start_get_inputs_embeds = std::chrono::steady_clock::now();
             m_inputs_embedder->set_apply_chat_template_status(sampling_params[i].apply_chat_template);
-
-            VLMPerfMetrics perf_metrics;
-            input_embeds_list.emplace_back(m_inputs_embedder->get_inputs_embeds(prompt, rgbs, perf_metrics));
+            input_embeds_list.emplace_back(m_inputs_embedder->get_inputs_embeds(prompt, rgbs, vlm_perf_metrics[i]));
+            auto end_get_inputs_embeds = std::chrono::steady_clock::now();
+            vlm_perf_metrics[i].vlm_raw_metrics.prepare_embeddings_durations.emplace_back(PerfMetrics::get_microsec(end_get_inputs_embeds - start_get_inputs_embeds));
         }
     }
-
-    std::vector<GenerationResult> results;
+    std::vector<VLMDecodedResults> results;
     auto encoded_results = generate(input_embeds_list, sampling_params, streamer);
-    for (const auto& result: encoded_results) {
-        GenerationResult gen_result;
+    for (size_t i = 0; i < prompts.size(); i++) {
+        auto result = encoded_results[i];
+        VLMDecodedResults gen_result;
+        gen_result.perf_metrics = result.perf_metrics;
+
+        gen_result.perf_metrics.vlm_raw_metrics = vlm_perf_metrics[i].vlm_raw_metrics;
+        gen_result.perf_metrics.raw_metrics.tokenization_durations = vlm_perf_metrics[i].raw_metrics.tokenization_durations;
+        gen_result.perf_metrics.raw_metrics.detokenization_durations = vlm_perf_metrics[i].raw_metrics.detokenization_durations;
+        
+        auto decode_start_time = std::chrono::steady_clock::now();
         for (size_t idx = 0; idx < result.m_generation_ids.size(); ++idx) {
-            gen_result.m_generation_ids.push_back(m_tokenizer.decode(result.m_generation_ids.at(idx)));
-            gen_result.m_scores.push_back(result.m_scores.at(idx));
-            gen_result.m_status = result.m_status;
+            gen_result.texts.push_back(m_tokenizer.decode(result.m_generation_ids.at(idx)));
+            gen_result.scores.push_back(result.m_scores.at(idx));
         }
+        auto decode_end_time = std::chrono::steady_clock::now();
+        gen_result.perf_metrics.raw_metrics.detokenization_durations.emplace_back(PerfMetrics::get_microsec(decode_end_time - decode_start_time));
+        
+        gen_result.perf_metrics.m_evaluated = false;
+        gen_result.perf_metrics.evaluate_statistics();
+
         results.emplace_back(gen_result);
     }
     if (m_is_chat_conversation) {
-        if (results[0].m_status == ov::genai::GenerationStatus::CANCEL) {
+        if (encoded_results[0].m_status == ov::genai::GenerationStatus::CANCEL) {
             m_history.pop_back();
         }
         else {
-            m_history.push_back({{"role", "assistant"}, {"content", results[0].m_generation_ids[0]}});
+            m_history.push_back({{"role", "assistant"}, {"content", results[0].texts[0]}});
         }
     }
     return results;

src/cpp/src/icontinuous_batching.hpp

@@ -115,7 +115,7 @@ class ContinuousBatchingPipeline::IContinuousBatchingPipeline {
              std::vector<GenerationConfig> sampling_params,
              const StreamerVariant& streamer);
 
-    virtual std::vector<GenerationResult>
+    virtual std::vector<VLMDecodedResults>
     generate(
              const std::vector<std::string>& prompts,
              const std::vector<std::vector<ov::Tensor>>& rgbs,

src/cpp/src/visual_language/continuous_batching_adapter.hpp

@@ -47,11 +47,22 @@ class ov::genai::VLMPipeline::VLMContinuousBatchingAdapter : public ov::genai::V
         GenerationConfig generation_config,
         const StreamerVariant& streamer
     ) override {
+        auto start_time = std::chrono::steady_clock::now();
         auto result = m_impl.generate({prompt}, {rgbs}, {generation_config}, streamer)[0];
+        auto stop_time = std::chrono::steady_clock::now();
+        
         VLMDecodedResults decoded;
-        for (size_t idx = 0; idx < result.m_generation_ids.size(); ++idx) {
-            decoded.texts.push_back(result.m_generation_ids.at(idx));
-            decoded.scores.push_back(result.m_scores.at(idx));
+        decoded.perf_metrics = result.perf_metrics;
+        decoded.perf_metrics.load_time = get_load_time();
+
+        decoded.perf_metrics.raw_metrics.generate_durations.clear();
+        decoded.perf_metrics.raw_metrics.generate_durations.emplace_back(PerfMetrics::get_microsec(stop_time - start_time));
+        decoded.perf_metrics.m_evaluated = false;
+        decoded.perf_metrics.evaluate_statistics(start_time);
+        
+        for (size_t idx = 0; idx < result.texts.size(); ++idx) {
+            decoded.texts.push_back(result.texts.at(idx));
+            decoded.scores.push_back(result.scores.at(idx));
         }
         return decoded;
     }

src/python/py_continuous_batching_pipeline.cpp

@@ -341,7 +341,7 @@ void init_continuous_batching_pipeline(py::module_& m) {
                const pyutils::PyBindStreamerVariant& py_streamer
             ) -> py::typing::Union<std::vector<ov::genai::GenerationResult>> {
                 ov::genai::StreamerVariant streamer = pyutils::pystreamer_to_streamer(py_streamer);
-                std::vector<ov::genai::GenerationResult> generated_results;
+                std::vector<ov::genai::VLMDecodedResults> generated_results;
                 {
                     py::gil_scoped_release rel;
                     generated_results = pipe.generate(prompts, images, generation_config, streamer);

tests/python_tests/test_vlm_pipeline.py

@@ -178,8 +178,8 @@ def test_vlm_continuous_batching_vs_stateful(config, cache):
 
         res_stateful = stateful_pipe.generate(prompts[0], images=images, generation_config=generation_config)
         for out_idx, text in enumerate(res_stateful.texts):
-            assert text == res_cb[idx][0].m_generation_ids[out_idx]
-            assert abs(res_stateful.scores[out_idx] - res_cb[idx][0].m_scores[out_idx]) < eps
+            assert text == res_cb[idx][0].texts[out_idx]
+            assert abs(res_stateful.scores[out_idx] - res_cb[idx][0].scores[out_idx]) < eps
 
 
 
@@ -287,7 +287,8 @@ def test_sampling(config, cache):
 
 @pytest.mark.precommit
 @pytest.mark.nightly
-def test_perf_metrics(cache):
+@pytest.mark.parametrize("scheduler_config", [SchedulerConfig(), None])
+def test_perf_metrics(cache, scheduler_config):
     import numpy as np
     from time import perf_counter_ns
     models_path = get_ov_model("katuni4ka/tiny-random-minicpmv-2_6", cache)
@@ -297,7 +298,11 @@ def test_perf_metrics(cache):
     max_new_tokens = 30
 
     start_time = perf_counter_ns()
-    pipe = VLMPipeline(models_path, "CPU")
+    if scheduler_config:
+        pipe = VLMPipeline(models_path, "CPU", scheduler_config=scheduler_config)
+    else:
+        pipe = VLMPipeline(models_path, "CPU")
+    
     start_generate = perf_counter_ns()
     result = pipe.generate(prompts[0], images=images, generation_config=GenerationConfig(max_new_tokens=max_new_tokens))
     generate_time = (perf_counter_ns() - start_generate) / 1_000_000.0
@@ -315,6 +320,7 @@ def test_perf_metrics(cache):
     assert 0 < perf_metrics.get_tpot().mean < generate_time / num_tokens
     assert 0 < perf_metrics.get_ipot().mean < generate_time / num_tokens
     assert num_tokens / (generate_time / 1000.0) < perf_metrics.get_throughput().mean < num_tokens / ((generate_time - perf_metrics.get_ttft().mean) / 1000.0)
+
     assert 0 < perf_metrics.get_inference_duration().mean < generate_time
     assert 0 < perf_metrics.get_generate_duration().mean < generate_time
     assert 0 < perf_metrics.get_tokenization_duration().mean < generate_time