[LLava] Fix stats for C++ runner

Before:

I 00:00:28.414816 executorch:stats.h:84]        Prompt Tokens: 616    Generated Tokens: 33
I 00:00:28.414826 executorch:stats.h:90]        Model Load Time:                9.244000 (seconds)
I 00:00:28.414835 executorch:stats.h:100]       Total inference time:           0.000000 (seconds)               Rate:  inf (tokens/second)
I 00:00:28.414838 executorch:stats.h:108]               Prompt evaluation:      0.000000 (seconds)               Rate:  inf (tokens/second)
I 00:00:28.414839 executorch:stats.h:119]               Generated 33 tokens:    0.000000 (seconds)               Rate:  inf (tokens/second)
I 00:00:28.414841 executorch:stats.h:127]       Time to first generated token:  0.000000 (seconds)
I 00:00:28.414842 executorch:stats.h:134]       Sampling time over 649 tokens:  0.002000 (seconds)

With real image on M1:

I 00:00:34.231017 executorch:stats.h:84]        Prompt Tokens: 616    Generated Tokens: 33
I 00:00:34.231028 executorch:stats.h:90]        Model Load Time:                9.108000 (seconds)
I 00:00:34.231038 executorch:stats.h:100]       Total inference time:           25.103000 (seconds)              Rate:  1.314584 (tokens/second)
I 00:00:34.231040 executorch:stats.h:108]               Prompt evaluation:      11.544000 (seconds)              Rate:  53.361053 (tokens/second)
I 00:00:34.231042 executorch:stats.h:119]               Generated 33 tokens:    13.559000 (seconds)              Rate:  2.433808 (tokens/second)
I 00:00:34.231043 executorch:stats.h:127]       Time to first generated token:  11.544000 (seconds)
I 00:00:34.231045 executorch:stats.h:134]       Sampling time over 649 tokens:  0.000000 (seconds)

With bogus image (same dims) on Android S23:

I 00:00:34.649120 executorch:stats.h:84]        Prompt Tokens: 616    Generated Tokens: 33
I 00:00:34.649128 executorch:stats.h:90]        Model Load Time:                12.337000 (seconds)
I 00:00:34.649169 executorch:stats.h:100]       Total inference time:           22.301000 (seconds)              Rate:  1.479754 (tokens/second)
I 00:00:34.649174 executorch:stats.h:108]               Prompt evaluation:      17.964000 (seconds)              Rate:  34.290804 (tokens/second)
I 00:00:34.649179 executorch:stats.h:119]               Generated 33 tokens:    4.337000 (seconds)               Rate:  7.608946 (tokens/second)
I 00:00:34.649183 executorch:stats.h:127]       Time to first generated token:  17.964000 (seconds)
I 00:00:34.649186 executorch:stats.h:134]       Sampling time over 649 tokens:  0.001000 (seconds)

Author: digantdesai

.ci/scripts/test_llava.sh

@@ -33,6 +33,7 @@ if hash nproc &> /dev/null; then NPROC=$(nproc); fi
 EXECUTORCH_COMMON_CMAKE_ARGS="                      \
         -DCMAKE_INSTALL_PREFIX=${BUILD_DIR}         \
         -DCMAKE_BUILD_TYPE=${BUILD_TYPE}            \
+        -DEXECUTORCH_ENABLE_LOGGING=ON              \
         -DEXECUTORCH_BUILD_EXTENSION_MODULE=ON      \
         -DEXECUTORCH_BUILD_EXTENSION_DATA_LOADER=ON \
         -DEXECUTORCH_BUILD_EXTENSION_TENSOR=ON      \

examples/models/llava/runner/llava_runner.cpp

@@ -108,6 +108,8 @@ Error LlavaRunner::generate_from_pos(
 
   uint64_t prefill_next_token =
       ET_UNWRAP(prefill_prompt(prompt, start_pos, /*bos=*/0, /*eos*/ 0));
+  stats_.first_token_ms = util::time_in_ms();
+  stats_.prompt_eval_end_ms = util::time_in_ms();
   stats_.num_prompt_tokens = start_pos;
 
   // Generate tokens
@@ -116,7 +118,6 @@ Error LlavaRunner::generate_from_pos(
 
   // Bookkeeping
   stats_.num_generated_tokens = num_generated_tokens;
-  ::executorch::llm::print_report(stats_);
   if (stats_callback) {
     stats_callback(stats_);
   }
@@ -151,6 +152,7 @@ Error LlavaRunner::generate(
       };
 
   int64_t pos = 0;
+  stats_.inference_start_ms = util::time_in_ms();
 
   // prefill preset prompt
   prefill_prompt(kPresetPrompt, pos, /*bos=*/1, /*eos*/ 0);
@@ -167,6 +169,9 @@ Error LlavaRunner::generate(
   Error err = generate_from_pos(
       prompt, seq_len, pos, wrapped_callback, stats_callback, echo);
 
+  stats_.inference_end_ms = util::time_in_ms();
+  ::executorch::llm::print_report(stats_);
+
   ET_LOG(
       Info,
       "RSS after finishing text generation: %f MiB (0 if unsupported)",