Add iteration timestamp to CSV and JSON (openvinotoolkit#1070)

The json file adds two fields, start and end, to indicate the start and
end timestamps of processing each prompt.

[qwen2-0.5b.txt](https://github.com/user-attachments/files/17531006/qwen2-0.5b.txt)

[qwen2-0.5b.json](https://github.com/user-attachments/files/17531002/qwen2-0.5b.json)

[qwen2-0.5b.csv](https://github.com/user-attachments/files/17531005/qwen2-0.5b.csv)

Author: wgzintel

tools/llm_bench/benchmark.py

@@ -181,7 +181,7 @@ def main():
     if args.memory_consumption:
         mem_consumption.start_collect_mem_consumption_thread()
     try:
-        iter_data_list, pretrain_time = CASE_TO_BENCH[model_args['use_case']](
+        iter_data_list, pretrain_time, iter_timestamp = CASE_TO_BENCH[model_args['use_case']](
             model_path, framework, args.device, model_args, args.num_iters, mem_consumption)
         if args.report is not None or args.report_json is not None:
             model_precision = ''
@@ -200,6 +200,7 @@ def main():
                     iter_data_list,
                     pretrain_time,
                     model_precision,
+                    iter_timestamp
                 )
             if args.report_json is not None:
                 llm_bench_utils.output_json.write_result(
@@ -211,6 +212,7 @@ def main():
                     iter_data_list,
                     pretrain_time,
                     model_precision,
+                    iter_timestamp
                 )
     except Exception:
         log.error('An exception occurred')

tools/llm_bench/llm_bench_utils/model_utils.py

@@ -272,3 +272,13 @@ def get_model_precision(model_name_list):
         if model_precision != 'unknown':
             break
     return model_precision
+
+
+def init_timestamp(num_iters, prompt_list, prompt_idx_list):
+    iter_timestamp = {}
+    for num in range(num_iters + 1):
+        iter_timestamp[num] = {}
+        for idx, input_text in enumerate(prompt_list):
+            p_idx = prompt_idx_list[idx]
+            iter_timestamp[num][p_idx] = {}
+    return iter_timestamp

tools/llm_bench/llm_bench_utils/output_csv.py

@@ -5,6 +5,7 @@
 import numpy as np
 import copy
 from pathlib import Path
+import llm_bench_utils.output_json as output_json
 
 
 def output_comments(result, use_case, writer):
@@ -86,7 +87,7 @@ def output_avg_min_median(iter_data_list):
     return result
 
 
-def gen_data_to_csv(result, iter_data, pretrain_time):
+def gen_data_to_csv(result, iter_data, pretrain_time, iter_timestamp):
     generation_time = iter_data['generation_time']
     latency = iter_data['latency']
     first_latency = iter_data['first_token_latency']
@@ -128,9 +129,10 @@ def gen_data_to_csv(result, iter_data, pretrain_time):
     result['prompt_idx'] = iter_data['prompt_idx']
     result['tokenization_time'] = round(token_time, 5) if token_time != '' else token_time
     result['detokenization_time'] = round(detoken_time, 5) if detoken_time != '' else detoken_time
+    result['start'], result['end'] = output_json.get_timestamp(iter_data['iteration'], iter_data['prompt_idx'], iter_timestamp)
 
 
-def write_result(report_file, model, framework, device, model_args, iter_data_list, pretrain_time, model_precision):
+def write_result(report_file, model, framework, device, model_args, iter_data_list, pretrain_time, model_precision, iter_timestamp):
     header = [
         'iteration',
         'model',
@@ -156,6 +158,8 @@ def write_result(report_file, model, framework, device, model_args, iter_data_li
         'tokenization_time',
         'detokenization_time',
         'result_md5',
+        'start',
+        'end'
     ]
     out_file = Path(report_file)
 
@@ -174,13 +178,13 @@ def write_result(report_file, model, framework, device, model_args, iter_data_li
             for i in range(len(iter_data_list)):
                 iter_data = iter_data_list[i]
                 pre_time = '' if i > 0 else result['pretrain_time(s)']
-                gen_data_to_csv(result, iter_data, pre_time)
+                gen_data_to_csv(result, iter_data, pre_time, iter_timestamp)
                 writer.writerow(result)
 
             res_data = output_avg_min_median(iter_data_list)
 
             for key in res_data.keys():
                 for data in res_data[key]:
-                    gen_data_to_csv(result, data, '')
+                    gen_data_to_csv(result, data, '', iter_timestamp)
                     writer.writerow(result)
             output_comments(result, model_args['use_case'], writer)

tools/llm_bench/llm_bench_utils/output_json.py

@@ -1,7 +1,7 @@
 import json
 
 
-def write_result(report_file, model, framework, device, model_args, iter_data_list, pretrain_time, model_precision):
+def write_result(report_file, model, framework, device, model_args, iter_data_list, pretrain_time, model_precision, iter_timestamp):
     metadata = {'model': model, 'framework': framework, 'device': device, 'precision': model_precision,
                 'num_beams': model_args['num_beams'], 'batch_size': model_args['batch_size']}
     result = []
@@ -24,6 +24,8 @@ def write_result(report_file, model, framework, device, model_args, iter_data_li
         for idx_md5 in range(len(iter_data['result_md5'])):
             result_md5.append(iter_data['result_md5'][idx_md5])
 
+        timestamp_start, timestamp_end = get_timestamp(iter_data['iteration'], iter_data['prompt_idx'], iter_timestamp)
+
         res_data = {
             'iteration': iter_data['iteration'],
             'input_size': iter_data['input_size'],
@@ -42,6 +44,8 @@ def write_result(report_file, model, framework, device, model_args, iter_data_li
             'prompt_idx': iter_data['prompt_idx'],
             'tokenization_time': round(tokenization_time, 5) if tokenization_time != '' else tokenization_time,
             'detokenization_time': round(detokenization_time, 5) if detokenization_time != '' else detokenization_time,
+            'start': timestamp_start,
+            'end': timestamp_end
         }
 
         result.append(res_data)
@@ -50,3 +54,14 @@ def write_result(report_file, model, framework, device, model_args, iter_data_li
 
     with open(report_file, 'w') as outfile:
         json.dump(output_result, outfile)
+
+
+def get_timestamp(iter_idx, prompt_idx, iter_timestamp):
+    timestamp_start = ''
+    timestamp_end = ''
+    if iter_idx in iter_timestamp.keys():
+        if prompt_idx in iter_timestamp[iter_idx].keys():
+            timestamp_start = iter_timestamp[iter_idx][prompt_idx]['start']
+            timestamp_end = iter_timestamp[iter_idx][prompt_idx]['end']
+
+    return timestamp_start, timestamp_end

tools/llm_bench/task/image_generation.py

@@ -3,6 +3,7 @@
 # SPDX-License-Identifier: Apache-2.0
 import os
 import time
+import datetime
 from PIL import Image
 import hashlib
 import logging as log
@@ -121,14 +122,25 @@ def run_image_generation_benchmark(model_path, framework, device, args, num_iter
 
     # if num_iters == 0, just output warm-up data
     proc_id = os.getpid()
+    iter_timestamp = model_utils.init_timestamp(num_iters, image_list, prompt_idx_list)
     if args['subsequent'] is False:
         for num in range(num_iters + 1):
             for image_id, image_param in enumerate(image_list):
+                p_idx = prompt_idx_list[image_id]
+                iter_timestamp[num][p_idx]['start'] = datetime.datetime.now().isoformat()
                 run_image_generation(image_param, num, prompt_idx_list[image_id], pipe, args, iter_data_list, proc_id, mem_consumption)
+                iter_timestamp[num][p_idx]['end'] = datetime.datetime.now().isoformat()
+                prefix = '[warm-up]' if num == 0 else '[{}]'.format(num)
+                log.info(f"{prefix}[P{p_idx}] start: {iter_timestamp[num][p_idx]['start']}, end: {iter_timestamp[num][p_idx]['end']}")
     else:
         for image_id, image_param in enumerate(image_list):
+            p_idx = prompt_idx_list[image_id]
             for num in range(num_iters + 1):
-                run_image_generation(image_param, num, prompt_idx_list[image_id], pipe, args, iter_data_list, proc_id, mem_consumption)
+                iter_timestamp[num][p_idx]['start'] = datetime.datetime.now().isoformat()
+                run_image_generation(image_param, num, p_idx, pipe, args, iter_data_list, proc_id, mem_consumption)
+                iter_timestamp[num][p_idx]['end'] = datetime.datetime.now().isoformat()
+                prefix = '[warm-up]' if num == 0 else '[{}]'.format(num)
+                log.info(f"{prefix}[P{p_idx}] start: {iter_timestamp[num][p_idx]['start']}, end: {iter_timestamp[num][p_idx]['end']}")
 
     metrics_print.print_average(iter_data_list, prompt_idx_list, args['batch_size'], False)
-    return iter_data_list, pretrain_time
+    return iter_data_list, pretrain_time, iter_timestamp

tools/llm_bench/task/super_resolution_generation.py

@@ -3,6 +3,7 @@
 # SPDX-License-Identifier: Apache-2.0
 import os
 import time
+import datetime
 from pathlib import Path
 from PIL import Image
 import hashlib
@@ -116,14 +117,20 @@ def run_ldm_super_resolution_benchmark(model_path, framework, device, args, num_
 
     # if num_iters == 0, just output warm-up data
     proc_id = os.getpid()
+    iter_timestamp = model_utils.init_timestamp(num_iters, image_list, prompt_idx_list)
     for num in range(num_iters + 1):
         for image_id, img in enumerate(image_list):
+            p_idx = prompt_idx_list[image_id]
             if num == 0:
                 if args["output_dir"] is not None:
-                    llm_bench_utils.output_file.output_image_input_text(str(img['prompt']), args, prompt_idx_list[image_id], None, proc_id)
-            log.info(f"[{'warm-up' if num == 0 else num}][P{prompt_idx_list[image_id]}] Input image={img['prompt']}")
+                    llm_bench_utils.output_file.output_image_input_text(str(img['prompt']), args, p_idx, None, proc_id)
+            log.info(f"[{'warm-up' if num == 0 else num}][P{p_idx}] Input image={img['prompt']}")
+            iter_timestamp[num][p_idx]['start'] = datetime.datetime.now().isoformat()
             run_ldm_super_resolution(img, num, pipe, args, framework, iter_data_list, prompt_idx_list[image_id], tm_list, proc_id, mem_consumption)
+            iter_timestamp[num][p_idx]['end'] = datetime.datetime.now().isoformat()
             tm_list.clear()
+            prefix = '[warm-up]' if num == 0 else '[{}]'.format(num)
+            log.info(f"{prefix}[P{p_idx}] start: {iter_timestamp[num][p_idx]['start']}, end: {iter_timestamp[num][p_idx]['end']}")
     metrics_print.print_average(iter_data_list, prompt_idx_list, 1, False)
 
-    return iter_data_list, pretrain_time
+    return iter_data_list, pretrain_time, iter_timestamp

tools/llm_bench/task/text_generation.py

@@ -3,6 +3,7 @@
 # SPDX-License-Identifier: Apache-2.0
 import os
 import time
+import datetime
 import logging as log
 import llm_bench_utils.ov_utils
 import llm_bench_utils.pt_utils
@@ -421,21 +422,33 @@ def run_text_generation_benchmark(model_path, framework, device, args, num_iters
         text_gen_fn = run_text_generation_genai_with_stream
     else:
         text_gen_fn = run_text_generation_genai
+
     proc_id = os.getpid()
+    iter_timestamp = model_utils.init_timestamp(num_iters, text_list, prompt_idx_list)
     if args['subsequent'] is False:
         for num in range(num_iters + 1):
             for idx, input_text in enumerate(text_list):
+                p_idx = prompt_idx_list[idx]
                 if num == 0:
-                    log.info(f'[warm-up][P{prompt_idx_list[idx]}] Input text: {input_text}')
+                    log.info(f'[warm-up][P{p_idx}] Input text: {input_text}')
+                iter_timestamp[num][p_idx]['start'] = datetime.datetime.now().isoformat()
                 text_gen_fn(input_text, num, model, tokenizer, args, iter_data_list, md5_list,
-                            prompt_idx_list[idx], bench_hook, model_precision, proc_id, mem_consumption)
+                            p_idx, bench_hook, model_precision, proc_id, mem_consumption)
+                iter_timestamp[num][p_idx]['end'] = datetime.datetime.now().isoformat()
+                prefix = '[warm-up]' if num == 0 else '[{}]'.format(num)
+                log.info(f"{prefix}[P{p_idx}] start: {iter_timestamp[num][p_idx]['start']}, end: {iter_timestamp[num][p_idx]['end']}")
     else:
         for idx, input_text in enumerate(text_list):
+            p_idx = prompt_idx_list[idx]
             for num in range(num_iters + 1):
                 if num == 0:
-                    log.info(f'[warm-up][P{prompt_idx_list[idx]}] Input text: {input_text}')
+                    log.info(f'[warm-up][P{p_idx}] Input text: {input_text}')
+                iter_timestamp[num][p_idx]['start'] = datetime.datetime.now().isoformat()
                 text_gen_fn(input_text, num, model, tokenizer, args, iter_data_list, md5_list,
                             prompt_idx_list[idx], bench_hook, model_precision, proc_id, mem_consumption)
+                iter_timestamp[num][p_idx]['end'] = datetime.datetime.now().isoformat()
+                prefix = '[warm-up]' if num == 0 else '[{}]'.format(num)
+                log.info(f"{prefix}[P{p_idx}] start: {iter_timestamp[num][p_idx]['start']}, end: {iter_timestamp[num][p_idx]['end']}")
 
     metrics_print.print_average(iter_data_list, prompt_idx_list, args['batch_size'], True)
-    return iter_data_list, pretrain_time
+    return iter_data_list, pretrain_time, iter_timestamp