@@ -175,6 +175,19 @@ def parse_jest_test_xml(
175175 logger .debug (f"Found { marker_count } timing start markers in Jest stdout" )
176176 else :
177177 logger .debug (f"No timing start markers found in Jest stdout (len={ len (global_stdout )} )" )
178+ # Check for END markers with duration (perf test markers)
179+ end_marker_count = len (jest_end_pattern .findall (global_stdout ))
180+ if end_marker_count > 0 :
181+ logger .debug (
182+ f"[PERF-DEBUG] Found { end_marker_count } END timing markers with duration in Jest stdout"
183+ )
184+ # Sample a few markers to verify loop indices
185+ end_samples = list (jest_end_pattern .finditer (global_stdout ))[:5 ]
186+ for sample in end_samples :
187+ groups = sample .groups ()
188+ logger .debug (f"[PERF-DEBUG] Sample END marker: loopIndex={ groups [3 ]} , duration={ groups [5 ]} " )
189+ else :
190+ logger .debug ("[PERF-DEBUG] No END markers with duration found in Jest stdout" )
178191 except (AttributeError , UnicodeDecodeError ):
179192 global_stdout = ""
180193
@@ -197,6 +210,14 @@ def parse_jest_test_xml(
197210 key = match .groups ()[:5 ]
198211 end_matches_dict [key ] = match
199212
213+ # Debug: log suite-level END marker parsing for perf tests
214+ if end_matches_dict :
215+ # Get unique loop indices from the parsed END markers
216+ loop_indices = sorted ({int (k [3 ]) if k [3 ].isdigit () else 1 for k in end_matches_dict })
217+ logger .debug (
218+ f"[PERF-DEBUG] Suite { suite_count } : parsed { len (end_matches_dict )} END markers from suite_stdout, loop_index range: { min (loop_indices )} -{ max (loop_indices )} "
219+ )
220+
200221 # Also collect timing markers from testcase-level system-out (Vitest puts output at testcase level)
201222 for tc in suite :
202223 tc_system_out = tc ._elem .find ("system-out" ) # noqa: SLF001
@@ -327,6 +348,13 @@ def parse_jest_test_xml(
327348 sanitized_test_name = re .sub (r"[!#: ()\[\]{}|\\/*?^$.+\-]" , "_" , test_name )
328349 matching_starts = [m for m in start_matches if sanitized_test_name in m .group (2 )]
329350
351+ # Debug: log which branch we're taking
352+ logger .debug (
353+ f"[FLOW-DEBUG] Testcase '{ test_name [:50 ]} ': "
354+ f"total_start_matches={ len (start_matches )} , matching_starts={ len (matching_starts )} , "
355+ f"total_end_matches={ len (end_matches_dict )} "
356+ )
357+
330358 # For performance tests (capturePerf), there are no START markers - only END markers with duration
331359 # Check for END markers directly if no START markers found
332360 matching_ends_direct = []
@@ -337,6 +365,28 @@ def parse_jest_test_xml(
337365 # end_key is (module, testName, funcName, loopIndex, invocationId)
338366 if len (end_key ) >= 2 and sanitized_test_name in end_key [1 ]:
339367 matching_ends_direct .append (end_match )
368+ # Debug: log matching results for perf tests
369+ if matching_ends_direct :
370+ loop_indices = [int (m .groups ()[3 ]) if m .groups ()[3 ].isdigit () else 1 for m in matching_ends_direct ]
371+ logger .debug (
372+ f"[PERF-MATCH] Testcase '{ test_name [:40 ]} ': matched { len (matching_ends_direct )} END markers, "
373+ f"loop_index range: { min (loop_indices )} -{ max (loop_indices )} "
374+ )
375+ elif end_matches_dict :
376+ # No matches but we have END markers - check why
377+ sample_keys = list (end_matches_dict .keys ())[:3 ]
378+ logger .debug (
379+ f"[PERF-MISMATCH] Testcase '{ test_name [:40 ]} ': no matches found. "
380+ f"sanitized_test_name='{ sanitized_test_name [:50 ]} ', "
381+ f"sample end_keys={ [k [1 ][:30 ] if len (k ) >= 2 else k for k in sample_keys ]} "
382+ )
383+
384+ # Log if we're skipping the matching_ends_direct branch
385+ if matching_starts and end_matches_dict :
386+ logger .debug (
387+ f"[FLOW-SKIP] Testcase '{ test_name [:40 ]} ': has { len (matching_starts )} START markers, "
388+ f"skipping { len (end_matches_dict )} END markers (behavior test mode)"
389+ )
340390
341391 if not matching_starts and not matching_ends_direct :
342392 # No timing markers found - use JUnit XML time attribute as fallback
@@ -373,11 +423,13 @@ def parse_jest_test_xml(
373423 )
374424 elif matching_ends_direct :
375425 # Performance test format: process END markers directly (no START markers)
426+ loop_indices_found = []
376427 for end_match in matching_ends_direct :
377428 groups = end_match .groups ()
378429 # groups: (module, testName, funcName, loopIndex, invocationId, durationNs)
379430 func_name = groups [2 ]
380431 loop_index = int (groups [3 ]) if groups [3 ].isdigit () else 1
432+ loop_indices_found .append (loop_index )
381433 line_id = groups [4 ]
382434 try :
383435 runtime = int (groups [5 ])
@@ -403,6 +455,12 @@ def parse_jest_test_xml(
403455 stdout = "" ,
404456 )
405457 )
458+ if loop_indices_found :
459+ logger .debug (
460+ f"[LOOP-DEBUG] Testcase '{ test_name } ': processed { len (matching_ends_direct )} END markers, "
461+ f"loop_index range: { min (loop_indices_found )} -{ max (loop_indices_found )} , "
462+ f"total results so far: { len (test_results .test_results )} "
463+ )
406464 else :
407465 # Process each timing marker
408466 for match in matching_starts :
@@ -454,5 +512,19 @@ def parse_jest_test_xml(
454512 f"Jest XML parsing complete: { len (test_results .test_results )} results "
455513 f"from { suite_count } suites, { testcase_count } testcases"
456514 )
515+ # Debug: show loop_index distribution for perf analysis
516+ if test_results .test_results :
517+ loop_indices = [r .loop_index for r in test_results .test_results ]
518+ unique_loop_indices = sorted (set (loop_indices ))
519+ min_idx , max_idx = min (unique_loop_indices ), max (unique_loop_indices )
520+ logger .debug (
521+ f"[LOOP-SUMMARY] Results loop_index: min={ min_idx } , max={ max_idx } , "
522+ f"unique_count={ len (unique_loop_indices )} , total_results={ len (loop_indices )} "
523+ )
524+ if max_idx == 1 and len (loop_indices ) > 1 :
525+ logger .warning (
526+ f"[LOOP-WARNING] All { len (loop_indices )} results have loop_index=1. "
527+ "Perf test markers may not have been parsed correctly."
528+ )
457529
458530 return test_results
0 commit comments