From 051d1b688226ce5dba821c005de073b150fa5df3 Mon Sep 17 00:00:00 2001 From: Saurabh Misra Date: Sun, 1 Feb 2026 23:36:06 +0000 Subject: [PATCH 1/2] feat: add inner loop and compile-once-run-many optimization for Java benchmarking - Add inner loop in Java test instrumentation for JIT warmup within single JVM - Implement compile-once-run-many: compile tests once with Maven, then run directly via JUnit Console Launcher (~500ms vs ~5-10s per invocation) - Add fallback to Maven-based execution when direct execution fails - Update parsing to handle JUnit Console Launcher output format - Add inner_iterations parameter (default: 100) to control loop count - Add comprehensive E2E tests for inner loop benchmarking Co-Authored-By: Claude Opus 4.5 --- codeflash/languages/base.py | 2 + codeflash/languages/java/instrumentation.py | 108 +-- codeflash/languages/java/support.py | 8 +- codeflash/languages/java/test_runner.py | 513 +++++++++++- codeflash/verification/parse_test_output.py | 17 + .../test_java/test_instrumentation.py | 742 +++++++++++++----- 6 files changed, 1123 insertions(+), 267 deletions(-) diff --git a/codeflash/languages/base.py b/codeflash/languages/base.py index f5d7f76ea..b158c24b7 100644 --- a/codeflash/languages/base.py +++ b/codeflash/languages/base.py @@ -653,6 +653,7 @@ def run_benchmarking_tests( min_loops: int = 5, max_loops: int = 100_000, target_duration_seconds: float = 10.0, + inner_iterations: int = 100, ) -> tuple[Path, Any]: """Run benchmarking tests for this language. @@ -665,6 +666,7 @@ def run_benchmarking_tests( min_loops: Minimum number of loops for benchmarking. max_loops: Maximum number of loops for benchmarking. target_duration_seconds: Target duration for benchmarking in seconds. + inner_iterations: Number of inner loop iterations per test method (Java only). Returns: Tuple of (result_file_path, subprocess_result). diff --git a/codeflash/languages/java/instrumentation.py b/codeflash/languages/java/instrumentation.py index 93670e9d1..10d3a17f2 100644 --- a/codeflash/languages/java/instrumentation.py +++ b/codeflash/languages/java/instrumentation.py @@ -20,7 +20,7 @@ from typing import TYPE_CHECKING from codeflash.languages.base import FunctionInfo -from codeflash.languages.java.parser import JavaAnalyzer, get_java_analyzer +from codeflash.languages.java.parser import JavaAnalyzer if TYPE_CHECKING: from collections.abc import Sequence @@ -154,8 +154,8 @@ def instrument_existing_test( # Rename the class declaration in the source # Pattern: "public class ClassName" or "class ClassName" - pattern = rf'\b(public\s+)?class\s+{re.escape(original_class_name)}\b' - replacement = rf'\1class {new_class_name}' + pattern = rf"\b(public\s+)?class\s+{re.escape(original_class_name)}\b" + replacement = rf"\1class {new_class_name}" modified_source = re.sub(pattern, replacement, source) # Add timing instrumentation to test methods @@ -214,7 +214,7 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) ] # Find position to insert imports (after package, before class) - lines = source.split('\n') + lines = source.split("\n") result = [] imports_added = False i = 0 @@ -225,11 +225,11 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) # Add imports after the last existing import or before the class declaration if not imports_added: - if stripped.startswith('import '): + if stripped.startswith("import "): result.append(line) i += 1 # Find end of imports - while i < len(lines) and lines[i].strip().startswith('import '): + while i < len(lines) and lines[i].strip().startswith("import "): result.append(lines[i]) i += 1 # Add our imports @@ -238,7 +238,7 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) result.append(imp) imports_added = True continue - elif stripped.startswith('public class') or stripped.startswith('class'): + if stripped.startswith("public class") or stripped.startswith("class"): # No imports found, add before class for imp in import_statements: result.append(imp) @@ -249,8 +249,8 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) i += 1 # Now add timing and SQLite instrumentation to test methods - source = '\n'.join(result) - lines = source.split('\n') + source = "\n".join(result) + lines = source.split("\n") result = [] i = 0 iteration_counter = 0 @@ -260,12 +260,12 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) stripped = line.strip() # Look for @Test annotation - if stripped.startswith('@Test'): + if stripped.startswith("@Test"): result.append(line) i += 1 # Collect any additional annotations - while i < len(lines) and lines[i].strip().startswith('@'): + while i < len(lines) and lines[i].strip().startswith("@"): result.append(lines[i]) i += 1 @@ -273,7 +273,7 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) method_lines = [] while i < len(lines): method_lines.append(lines[i]) - if '{' in lines[i]: + if "{" in lines[i]: break i += 1 @@ -298,9 +298,9 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) while i < len(lines) and brace_depth > 0: body_line = lines[i] for ch in body_line: - if ch == '{': + if ch == "{": brace_depth += 1 - elif ch == '}': + elif ch == "}": brace_depth -= 1 if brace_depth > 0: @@ -323,13 +323,13 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) # - new ClassName(args) # - this method_call_pattern = re.compile( - rf'((?:new\s+\w+\s*\([^)]*\)|[a-zA-Z_]\w*))\s*\.\s*({re.escape(func_name)})\s*\(([^)]*)\)', + rf"((?:new\s+\w+\s*\([^)]*\)|[a-zA-Z_]\w*))\s*\.\s*({re.escape(func_name)})\s*\(([^)]*)\)", re.MULTILINE ) for body_line in body_lines: # Check if this line contains a call to the target function - if func_name in body_line and '(' in body_line: + if func_name in body_line and "(" in body_line: line_indent = len(body_line) - len(body_line.lstrip()) line_indent_str = " " * line_indent @@ -360,7 +360,7 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) # If we captured any calls, serialize the last one; otherwise serialize null if call_counter > 0: result_var = f"_cf_result{iter_id}_{call_counter}" - serialize_expr = f'new GsonBuilder().serializeNulls().create().toJson({result_var})' + serialize_expr = f"new GsonBuilder().serializeNulls().create().toJson({result_var})" else: serialize_expr = '"null"' @@ -399,8 +399,8 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) f"{indent} // Write to SQLite if output file is set", f"{indent} if (_cf_outputFile{iter_id} != null && !_cf_outputFile{iter_id}.isEmpty()) {{", f"{indent} try {{", - f"{indent} Class.forName(\"org.sqlite.JDBC\");", - f"{indent} try (Connection _cf_conn{iter_id} = DriverManager.getConnection(\"jdbc:sqlite:\" + _cf_outputFile{iter_id})) {{", + f'{indent} Class.forName("org.sqlite.JDBC");', + f'{indent} try (Connection _cf_conn{iter_id} = DriverManager.getConnection("jdbc:sqlite:" + _cf_outputFile{iter_id})) {{', f"{indent} try (Statement _cf_stmt{iter_id} = _cf_conn{iter_id}.createStatement()) {{", f'{indent} _cf_stmt{iter_id}.execute("CREATE TABLE IF NOT EXISTS test_results (" +', f'{indent} "test_module_path TEXT, test_class_name TEXT, test_function_name TEXT, " +', @@ -433,20 +433,26 @@ def _add_behavior_instrumentation(source: str, class_name: str, func_name: str) result.append(line) i += 1 - return '\n'.join(result) + return "\n".join(result) def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> str: - """Add timing instrumentation to test methods. + """Add timing instrumentation to test methods with inner loop for JIT warmup. For each @Test method, this adds: - 1. Start timing marker printed at the beginning - 2. End timing marker printed at the end (in a finally block) + 1. Inner loop that runs N iterations (controlled by CODEFLASH_INNER_ITERATIONS env var) + 2. Start timing marker printed at the beginning of each iteration + 3. End timing marker printed at the end of each iteration (in a finally block) + + The inner loop allows JIT warmup within a single JVM invocation, avoiding + expensive Maven restarts. Post-processing uses min runtime across all iterations. Timing markers format: Start: !$######testModule:testClass:funcName:loopIndex:iterationId######$! End: !######testModule:testClass:funcName:loopIndex:iterationId:durationNs######! + Where iterationId is the inner iteration number (0, 1, 2, ..., N-1). + Args: source: The test source code. class_name: Name of the test class. @@ -460,7 +466,7 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> # Pattern matches: @Test (with optional parameters) followed by method declaration # We process line by line for cleaner handling - lines = source.split('\n') + lines = source.split("\n") result = [] i = 0 iteration_counter = 0 @@ -470,12 +476,12 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> stripped = line.strip() # Look for @Test annotation - if stripped.startswith('@Test'): + if stripped.startswith("@Test"): result.append(line) i += 1 # Collect any additional annotations - while i < len(lines) and lines[i].strip().startswith('@'): + while i < len(lines) and lines[i].strip().startswith("@"): result.append(lines[i]) i += 1 @@ -483,7 +489,7 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> method_lines = [] while i < len(lines): method_lines.append(lines[i]) - if '{' in lines[i]: + if "{" in lines[i]: break i += 1 @@ -500,21 +506,24 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> method_sig_line = method_lines[-1] if method_lines else "" base_indent = len(method_sig_line) - len(method_sig_line.lstrip()) indent = " " * (base_indent + 4) # Add one level of indentation + inner_indent = " " * (base_indent + 8) # Two levels for inside inner loop + inner_body_indent = " " * (base_indent + 12) # Three levels for try block body - # Add timing start code + # Add timing instrumentation with inner loop # Note: CODEFLASH_LOOP_INDEX must always be set - no null check, crash if missing - # Start marker is printed BEFORE timing starts - # System.nanoTime() immediately precedes try block with test code + # CODEFLASH_INNER_ITERATIONS controls inner loop count (default: 100) timing_start_code = [ - f"{indent}// Codeflash timing instrumentation", + f"{indent}// Codeflash timing instrumentation with inner loop for JIT warmup", f'{indent}int _cf_loop{iter_id} = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX"));', - f"{indent}int _cf_iter{iter_id} = {iter_id};", + f'{indent}int _cf_innerIterations{iter_id} = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100"));', f'{indent}String _cf_mod{iter_id} = "{class_name}";', f'{indent}String _cf_cls{iter_id} = "{class_name}";', f'{indent}String _cf_fn{iter_id} = "{func_name}";', - f'{indent}System.out.println("!$######" + _cf_mod{iter_id} + ":" + _cf_cls{iter_id} + ":" + _cf_fn{iter_id} + ":" + _cf_loop{iter_id} + ":" + _cf_iter{iter_id} + "######$!");', - f"{indent}long _cf_start{iter_id} = System.nanoTime();", - f"{indent}try {{", + "", + f"{indent}for (int _cf_i{iter_id} = 0; _cf_i{iter_id} < _cf_innerIterations{iter_id}; _cf_i{iter_id}++) {{", + f'{inner_indent}System.out.println("!$######" + _cf_mod{iter_id} + ":" + _cf_cls{iter_id} + ":" + _cf_fn{iter_id} + ":" + _cf_loop{iter_id} + ":" + _cf_i{iter_id} + "######$!");', + f"{inner_indent}long _cf_start{iter_id} = System.nanoTime();", + f"{inner_indent}try {{", ] result.extend(timing_start_code) @@ -526,9 +535,9 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> body_line = lines[i] # Count braces (simple approach - doesn't handle strings/comments perfectly) for ch in body_line: - if ch == '{': + if ch == "{": brace_depth += 1 - elif ch == '}': + elif ch == "}": brace_depth -= 1 if brace_depth > 0: @@ -536,18 +545,19 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> i += 1 else: # This line contains the closing brace, but we've hit depth 0 - # Add indented body lines + # Add indented body lines (inside try block, inside for loop) for bl in body_lines: - result.append(" " + bl) + result.append(" " + bl) # 8 extra spaces for inner loop + try - # Add finally block + # Add finally block and close inner loop method_close_indent = " " * base_indent # Same level as method signature timing_end_code = [ - f"{indent}}} finally {{", - f"{indent} long _cf_end{iter_id} = System.nanoTime();", - f"{indent} long _cf_dur{iter_id} = _cf_end{iter_id} - _cf_start{iter_id};", - f'{indent} System.out.println("!######" + _cf_mod{iter_id} + ":" + _cf_cls{iter_id} + ":" + _cf_fn{iter_id} + ":" + _cf_loop{iter_id} + ":" + _cf_iter{iter_id} + ":" + _cf_dur{iter_id} + "######!");', - f"{indent}}}", + f"{inner_indent}}} finally {{", + f"{inner_indent} long _cf_end{iter_id} = System.nanoTime();", + f"{inner_indent} long _cf_dur{iter_id} = _cf_end{iter_id} - _cf_start{iter_id};", + f'{inner_indent} System.out.println("!######" + _cf_mod{iter_id} + ":" + _cf_cls{iter_id} + ":" + _cf_fn{iter_id} + ":" + _cf_loop{iter_id} + ":" + _cf_i{iter_id} + ":" + _cf_dur{iter_id} + "######!");', + f"{inner_indent}}}", + f"{indent}}}", # Close for loop f"{method_close_indent}}}", # Method closing brace ] result.extend(timing_end_code) @@ -556,7 +566,7 @@ def _add_timing_instrumentation(source: str, class_name: str, func_name: str) -> result.append(line) i += 1 - return '\n'.join(result) + return "\n".join(result) def create_benchmark_test( @@ -653,7 +663,7 @@ def instrument_generated_java_test( """ # Extract class name from the test code # Use pattern that starts at beginning of line to avoid matching words in comments - class_match = re.search(r'^(?:public\s+)?class\s+(\w+)', test_code, re.MULTILINE) + class_match = re.search(r"^(?:public\s+)?class\s+(\w+)", test_code, re.MULTILINE) if not class_match: logger.warning("Could not find class name in generated test") return test_code @@ -668,8 +678,8 @@ def instrument_generated_java_test( # Rename the class in the source modified_code = re.sub( - rf'\b(public\s+)?class\s+{re.escape(original_class_name)}\b', - rf'\1class {new_class_name}', + rf"\b(public\s+)?class\s+{re.escape(original_class_name)}\b", + rf"\1class {new_class_name}", test_code, ) diff --git a/codeflash/languages/java/support.py b/codeflash/languages/java/support.py index ab81d0f63..abde1f824 100644 --- a/codeflash/languages/java/support.py +++ b/codeflash/languages/java/support.py @@ -356,11 +356,12 @@ def run_benchmarking_tests( cwd: Path, timeout: int | None = None, project_root: Path | None = None, - min_loops: int = 5, - max_loops: int = 100_000, + min_loops: int = 1, + max_loops: int = 3, target_duration_seconds: float = 10.0, + inner_iterations: int = 100, ) -> tuple[Path, Any]: - """Run benchmarking tests for Java.""" + """Run benchmarking tests for Java with inner loop for JIT warmup.""" return run_benchmarking_tests( test_paths, test_env, @@ -370,6 +371,7 @@ def run_benchmarking_tests( min_loops, max_loops, target_duration_seconds, + inner_iterations, ) diff --git a/codeflash/languages/java/test_runner.py b/codeflash/languages/java/test_runner.py index cba6d63fb..a8e2a0d3e 100644 --- a/codeflash/languages/java/test_runner.py +++ b/codeflash/languages/java/test_runner.py @@ -228,32 +228,444 @@ def run_behavioral_tests( return result_xml_path, result, sqlite_db_path, coverage_xml_path +def _compile_tests( + project_root: Path, + env: dict[str, str], + test_module: str | None = None, + timeout: int = 120, +) -> subprocess.CompletedProcess: + """Compile test code using Maven (without running tests). + + Args: + project_root: Root directory of the Maven project. + env: Environment variables. + test_module: For multi-module projects, the module containing tests. + timeout: Maximum execution time in seconds. + + Returns: + CompletedProcess with compilation results. + + """ + mvn = find_maven_executable() + if not mvn: + logger.error("Maven not found") + return subprocess.CompletedProcess( + args=["mvn"], + returncode=-1, + stdout="", + stderr="Maven not found", + ) + + cmd = [mvn, "test-compile", "-q"] # Quiet mode for faster output + + if test_module: + cmd.extend(["-pl", test_module, "-am"]) + + logger.debug("Compiling tests: %s in %s", " ".join(cmd), project_root) + + try: + return subprocess.run( + cmd, + check=False, + cwd=project_root, + env=env, + capture_output=True, + text=True, + timeout=timeout, + ) + except subprocess.TimeoutExpired: + logger.error("Maven compilation timed out after %d seconds", timeout) + return subprocess.CompletedProcess( + args=cmd, + returncode=-2, + stdout="", + stderr=f"Compilation timed out after {timeout} seconds", + ) + except Exception as e: + logger.exception("Maven compilation failed: %s", e) + return subprocess.CompletedProcess( + args=cmd, + returncode=-1, + stdout="", + stderr=str(e), + ) + + +def _get_test_classpath( + project_root: Path, + env: dict[str, str], + test_module: str | None = None, + timeout: int = 60, +) -> str | None: + """Get the test classpath from Maven. + + Args: + project_root: Root directory of the Maven project. + env: Environment variables. + test_module: For multi-module projects, the module containing tests. + timeout: Maximum execution time in seconds. + + Returns: + Classpath string, or None if failed. + + """ + mvn = find_maven_executable() + if not mvn: + return None + + # Create temp file for classpath output + cp_file = project_root / ".codeflash_classpath.txt" + + cmd = [ + mvn, + "dependency:build-classpath", + "-DincludeScope=test", + f"-Dmdep.outputFile={cp_file}", + "-q", + ] + + if test_module: + cmd.extend(["-pl", test_module]) + + logger.debug("Getting classpath: %s", " ".join(cmd)) + + try: + result = subprocess.run( + cmd, + check=False, + cwd=project_root, + env=env, + capture_output=True, + text=True, + timeout=timeout, + ) + + if result.returncode != 0: + logger.error("Failed to get classpath: %s", result.stderr) + return None + + if not cp_file.exists(): + logger.error("Classpath file not created") + return None + + classpath = cp_file.read_text(encoding="utf-8").strip() + + # Add compiled classes directories to classpath + # For multi-module, we need to find the correct target directories + if test_module: + module_path = project_root / test_module + else: + module_path = project_root + + test_classes = module_path / "target" / "test-classes" + main_classes = module_path / "target" / "classes" + + cp_parts = [classpath] + if test_classes.exists(): + cp_parts.append(str(test_classes)) + if main_classes.exists(): + cp_parts.append(str(main_classes)) + + return os.pathsep.join(cp_parts) + + except subprocess.TimeoutExpired: + logger.error("Getting classpath timed out") + return None + except Exception as e: + logger.exception("Failed to get classpath: %s", e) + return None + finally: + # Clean up temp file + if cp_file.exists(): + cp_file.unlink() + + +def _run_tests_direct( + classpath: str, + test_classes: list[str], + env: dict[str, str], + working_dir: Path, + timeout: int = 60, + reports_dir: Path | None = None, +) -> subprocess.CompletedProcess: + """Run JUnit tests directly using java command (bypassing Maven). + + This is much faster than Maven invocation (~500ms vs ~5-10s overhead). + + Args: + classpath: Full classpath including test dependencies. + test_classes: List of fully qualified test class names to run. + env: Environment variables. + working_dir: Working directory for execution. + timeout: Maximum execution time in seconds. + reports_dir: Optional directory for JUnit XML reports. + + Returns: + CompletedProcess with test results. + + """ + # Find java executable + java_home = os.environ.get("JAVA_HOME") + if java_home: + java = Path(java_home) / "bin" / "java" + if not java.exists(): + java = "java" + else: + java = "java" + + # Build command using JUnit Platform Console Launcher + # The launcher is included in junit-platform-console-standalone or junit-jupiter + cmd = [ + str(java), + "-cp", + classpath, + "org.junit.platform.console.ConsoleLauncher", + "--disable-banner", + "--disable-ansi-colors", + "--details=verbose", + ] + + # Add reports directory if specified (for XML output) + if reports_dir: + reports_dir.mkdir(parents=True, exist_ok=True) + cmd.extend(["--reports-dir", str(reports_dir)]) + + # Add test classes to select + for test_class in test_classes: + cmd.extend(["--select-class", test_class]) + + logger.debug("Running tests directly: java -cp ... ConsoleLauncher --select-class %s", test_classes) + + try: + return subprocess.run( + cmd, + check=False, + cwd=working_dir, + env=env, + capture_output=True, + text=True, + timeout=timeout, + ) + except subprocess.TimeoutExpired: + logger.error("Direct test execution timed out after %d seconds", timeout) + return subprocess.CompletedProcess( + args=cmd, + returncode=-2, + stdout="", + stderr=f"Test execution timed out after {timeout} seconds", + ) + except Exception as e: + logger.exception("Direct test execution failed: %s", e) + return subprocess.CompletedProcess( + args=cmd, + returncode=-1, + stdout="", + stderr=str(e), + ) + + +def _get_test_class_names(test_paths: Any, mode: str = "performance") -> list[str]: + """Extract fully qualified test class names from test paths. + + Args: + test_paths: TestFiles object or list of test file paths. + mode: Testing mode - "behavior" or "performance". + + Returns: + List of fully qualified class names. + + """ + class_names = [] + + if hasattr(test_paths, "test_files"): + for test_file in test_paths.test_files: + if mode == "performance": + if hasattr(test_file, "benchmarking_file_path") and test_file.benchmarking_file_path: + class_name = _path_to_class_name(test_file.benchmarking_file_path) + if class_name: + class_names.append(class_name) + elif hasattr(test_file, "instrumented_behavior_file_path") and test_file.instrumented_behavior_file_path: + class_name = _path_to_class_name(test_file.instrumented_behavior_file_path) + if class_name: + class_names.append(class_name) + elif isinstance(test_paths, (list, tuple)): + for path in test_paths: + if isinstance(path, Path): + class_name = _path_to_class_name(path) + if class_name: + class_names.append(class_name) + elif isinstance(path, str): + class_names.append(path) + + return class_names + + +def _get_empty_result(maven_root: Path, test_module: str | None) -> tuple[Path, Any]: + """Return an empty result for when no tests can be run. + + Args: + maven_root: Maven project root. + test_module: Optional test module name. + + Returns: + Tuple of (empty_xml_path, empty_result). + + """ + target_dir = _get_test_module_target_dir(maven_root, test_module) + surefire_dir = target_dir / "surefire-reports" + result_xml_path = _get_combined_junit_xml(surefire_dir, -1) + + empty_result = subprocess.CompletedProcess( + args=["java", "-cp", "...", "ConsoleLauncher"], + returncode=-1, + stdout="", + stderr="No test classes found", + ) + return result_xml_path, empty_result + + +def _run_benchmarking_tests_maven( + test_paths: Any, + test_env: dict[str, str], + cwd: Path, + timeout: int | None, + project_root: Path | None, + min_loops: int, + max_loops: int, + target_duration_seconds: float, + inner_iterations: int, +) -> tuple[Path, Any]: + """Fallback: Run benchmarking tests using Maven (slower but more reliable). + + This is used when direct JVM execution fails (e.g., classpath issues). + + Args: + test_paths: TestFiles object or list of test file paths. + test_env: Environment variables for the test run. + cwd: Working directory for running tests. + timeout: Optional timeout in seconds. + project_root: Project root directory. + min_loops: Minimum number of outer loops. + max_loops: Maximum number of outer loops. + target_duration_seconds: Target duration for benchmarking. + inner_iterations: Number of inner loop iterations. + + Returns: + Tuple of (result_file_path, subprocess_result with aggregated stdout). + + """ + import time + + project_root = project_root or cwd + maven_root, test_module = _find_multi_module_root(project_root, test_paths) + + all_stdout = [] + all_stderr = [] + total_start_time = time.time() + loop_count = 0 + last_result = None + + per_loop_timeout = timeout or max(120, 60 + inner_iterations) + + logger.debug("Using Maven-based benchmarking (fallback mode)") + + for loop_idx in range(1, max_loops + 1): + run_env = os.environ.copy() + run_env.update(test_env) + run_env["CODEFLASH_LOOP_INDEX"] = str(loop_idx) + run_env["CODEFLASH_MODE"] = "performance" + run_env["CODEFLASH_TEST_ITERATION"] = "0" + run_env["CODEFLASH_INNER_ITERATIONS"] = str(inner_iterations) + + result = _run_maven_tests( + maven_root, + test_paths, + run_env, + timeout=per_loop_timeout, + mode="performance", + test_module=test_module, + ) + + last_result = result + loop_count = loop_idx + + if result.stdout: + all_stdout.append(result.stdout) + if result.stderr: + all_stderr.append(result.stderr) + + elapsed = time.time() - total_start_time + if loop_idx >= min_loops and elapsed >= target_duration_seconds: + logger.debug( + "Stopping Maven benchmark after %d loops (%.2fs elapsed)", + loop_idx, + elapsed, + ) + break + + if result.returncode != 0: + logger.warning("Tests failed in Maven loop %d, stopping", loop_idx) + break + + combined_stdout = "\n".join(all_stdout) + combined_stderr = "\n".join(all_stderr) + + total_iterations = loop_count * inner_iterations + logger.debug( + "Maven fallback: %d loops x %d iterations = %d total in %.2fs", + loop_count, + inner_iterations, + total_iterations, + time.time() - total_start_time, + ) + + combined_result = subprocess.CompletedProcess( + args=last_result.args if last_result else ["mvn", "test"], + returncode=last_result.returncode if last_result else -1, + stdout=combined_stdout, + stderr=combined_stderr, + ) + + target_dir = _get_test_module_target_dir(maven_root, test_module) + surefire_dir = target_dir / "surefire-reports" + result_xml_path = _get_combined_junit_xml(surefire_dir, -1) + + return result_xml_path, combined_result + + def run_benchmarking_tests( test_paths: Any, test_env: dict[str, str], cwd: Path, timeout: int | None = None, project_root: Path | None = None, - min_loops: int = 5, - max_loops: int = 100, + min_loops: int = 1, + max_loops: int = 3, target_duration_seconds: float = 10.0, + inner_iterations: int = 100, ) -> tuple[Path, Any]: - """Run benchmarking tests for Java code. + """Run benchmarking tests for Java code with compile-once-run-many optimization. - This runs tests multiple times with performance measurement. - The instrumented tests print timing markers that are parsed from stdout: + This compiles tests once, then runs them multiple times directly via JVM, + bypassing Maven overhead (~500ms vs ~5-10s per invocation). + + The instrumented tests run CODEFLASH_INNER_ITERATIONS iterations per JVM invocation, + printing timing markers that are parsed from stdout: Start: !$######testModule:testClass:funcName:loopIndex:iterationId######$! End: !######testModule:testClass:funcName:loopIndex:iterationId:durationNs######! + Where iterationId is the inner iteration number (0, 1, 2, ..., inner_iterations-1). + Args: test_paths: TestFiles object or list of test file paths. test_env: Environment variables for the test run. cwd: Working directory for running tests. timeout: Optional timeout in seconds. project_root: Project root directory. - min_loops: Minimum number of loops for benchmarking. - max_loops: Maximum number of loops for benchmarking. + min_loops: Minimum number of outer loops (JVM invocations). Default: 1. + max_loops: Maximum number of outer loops (JVM invocations). Default: 3. target_duration_seconds: Target duration for benchmarking in seconds. + inner_iterations: Number of inner loop iterations per JVM invocation. Default: 100. Returns: Tuple of (result_file_path, subprocess_result with aggregated stdout). @@ -266,14 +678,66 @@ def run_benchmarking_tests( # Detect multi-module Maven projects where tests are in a different module maven_root, test_module = _find_multi_module_root(project_root, test_paths) - # Collect stdout from all loops + # Get test class names + test_classes = _get_test_class_names(test_paths, mode="performance") + if not test_classes: + logger.error("No test classes found") + return _get_empty_result(maven_root, test_module) + + # Step 1: Compile tests once using Maven + compile_env = os.environ.copy() + compile_env.update(test_env) + + logger.debug("Step 1: Compiling tests (one-time Maven overhead)") + compile_start = time.time() + compile_result = _compile_tests(maven_root, compile_env, test_module, timeout=120) + compile_time = time.time() - compile_start + + if compile_result.returncode != 0: + logger.error("Test compilation failed: %s", compile_result.stderr) + # Fall back to Maven-based execution + logger.warning("Falling back to Maven-based test execution") + return _run_benchmarking_tests_maven( + test_paths, test_env, cwd, timeout, project_root, + min_loops, max_loops, target_duration_seconds, inner_iterations + ) + + logger.debug("Compilation completed in %.2fs", compile_time) + + # Step 2: Get classpath from Maven + logger.debug("Step 2: Getting classpath") + classpath = _get_test_classpath(maven_root, compile_env, test_module, timeout=60) + + if not classpath: + logger.warning("Failed to get classpath, falling back to Maven-based execution") + return _run_benchmarking_tests_maven( + test_paths, test_env, cwd, timeout, project_root, + min_loops, max_loops, target_duration_seconds, inner_iterations + ) + + # Step 3: Run tests multiple times directly via JVM + logger.debug("Step 3: Running tests directly (bypassing Maven)") + all_stdout = [] all_stderr = [] total_start_time = time.time() loop_count = 0 last_result = None - # Run multiple loops until we hit target duration or max loops + # Calculate timeout per loop + per_loop_timeout = timeout or max(60, 30 + inner_iterations // 10) + + # Determine working directory for test execution + if test_module: + working_dir = maven_root / test_module + else: + working_dir = maven_root + + # Create reports directory for JUnit XML output (in Surefire-compatible location) + target_dir = _get_test_module_target_dir(maven_root, test_module) + reports_dir = target_dir / "surefire-reports" + reports_dir.mkdir(parents=True, exist_ok=True) + for loop_idx in range(1, max_loops + 1): # Set environment variables for this loop run_env = os.environ.copy() @@ -281,16 +745,19 @@ def run_benchmarking_tests( run_env["CODEFLASH_LOOP_INDEX"] = str(loop_idx) run_env["CODEFLASH_MODE"] = "performance" run_env["CODEFLASH_TEST_ITERATION"] = "0" + run_env["CODEFLASH_INNER_ITERATIONS"] = str(inner_iterations) - # Run Maven tests for this loop - result = _run_maven_tests( - maven_root, - test_paths, + # Run tests directly with XML report generation + loop_start = time.time() + result = _run_tests_direct( + classpath, + test_classes, run_env, - timeout=timeout or 120, # Per-loop timeout - mode="performance", - test_module=test_module, + working_dir, + timeout=per_loop_timeout, + reports_dir=reports_dir, ) + loop_time = time.time() - loop_start last_result = result loop_count = loop_idx @@ -301,14 +768,17 @@ def run_benchmarking_tests( if result.stderr: all_stderr.append(result.stderr) + logger.debug("Loop %d completed in %.2fs (returncode=%d)", loop_idx, loop_time, result.returncode) + # Check if we've hit the target duration elapsed = time.time() - total_start_time if loop_idx >= min_loops and elapsed >= target_duration_seconds: logger.debug( - "Stopping benchmark after %d loops (%.2fs elapsed, target: %.2fs)", + "Stopping benchmark after %d loops (%.2fs elapsed, target: %.2fs, %d inner iterations each)", loop_idx, elapsed, target_duration_seconds, + inner_iterations, ) break @@ -321,10 +791,15 @@ def run_benchmarking_tests( combined_stdout = "\n".join(all_stdout) combined_stderr = "\n".join(all_stderr) + total_time = time.time() - total_start_time + total_iterations = loop_count * inner_iterations logger.debug( - "Completed %d benchmark loops in %.2fs", + "Completed %d loops x %d inner iterations = %d total iterations in %.2fs (compile: %.2fs)", loop_count, - time.time() - total_start_time, + inner_iterations, + total_iterations, + total_time, + compile_time, ) # Create a combined subprocess result diff --git a/codeflash/verification/parse_test_output.py b/codeflash/verification/parse_test_output.py index 1a59df399..7e54d0149 100644 --- a/codeflash/verification/parse_test_output.py +++ b/codeflash/verification/parse_test_output.py @@ -1058,6 +1058,23 @@ def parse_test_xml( groups = match.groups() # Key is first 5 groups (module, class, func, loop, iter) end_matches[groups[:5]] = match + + # For Java: fallback to subprocess stdout when XML system-out has no timing markers + # This happens when using JUnit Console Launcher directly (bypassing Maven) + if not begin_matches and run_result is not None: + try: + fallback_stdout = run_result.stdout if isinstance(run_result.stdout, str) else run_result.stdout.decode() + begin_matches = list(start_pattern.finditer(fallback_stdout)) + if begin_matches: + # Found timing markers in subprocess stdout, use it + sys_stdout = fallback_stdout + end_matches = {} + for match in end_pattern.finditer(sys_stdout): + groups = match.groups() + end_matches[groups[:5]] = match + logger.debug(f"Java: Found {len(begin_matches)} timing markers in subprocess stdout (fallback)") + except (AttributeError, UnicodeDecodeError): + pass else: begin_matches = list(matches_re_start.finditer(sys_stdout)) end_matches = {} diff --git a/tests/test_languages/test_java/test_instrumentation.py b/tests/test_languages/test_java/test_instrumentation.py index e50d4c579..a6ebed679 100644 --- a/tests/test_languages/test_java/test_instrumentation.py +++ b/tests/test_languages/test_java/test_instrumentation.py @@ -143,7 +143,7 @@ def test_instrument_behavior_mode_simple(self, tmp_path: Path): assert "System.nanoTime()" in result def test_instrument_performance_mode_simple(self, tmp_path: Path): - """Test instrumenting a simple test in performance mode.""" + """Test instrumenting a simple test in performance mode with inner loop.""" test_file = tmp_path / "CalculatorTest.java" source = """import org.junit.jupiter.api.Test; @@ -180,21 +180,24 @@ def test_instrument_performance_mode_simple(self, tmp_path: Path): public class CalculatorTest__perfonlyinstrumented { @Test public void testAdd() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "CalculatorTest"; String _cf_cls1 = "CalculatorTest"; String _cf_fn1 = "add"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - Calculator calc = new Calculator(); - assertEquals(4, calc.add(2, 2)); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + Calculator calc = new Calculator(); + assertEquals(4, calc.add(2, 2)); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } } @@ -203,7 +206,7 @@ def test_instrument_performance_mode_simple(self, tmp_path: Path): assert result == expected def test_instrument_performance_mode_multiple_tests(self, tmp_path: Path): - """Test instrumenting multiple test methods in performance mode.""" + """Test instrumenting multiple test methods in performance mode with inner loop.""" test_file = tmp_path / "MathTest.java" source = """import org.junit.jupiter.api.Test; @@ -244,39 +247,45 @@ def test_instrument_performance_mode_multiple_tests(self, tmp_path: Path): public class MathTest__perfonlyinstrumented { @Test public void testAdd() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "MathTest"; String _cf_cls1 = "MathTest"; String _cf_fn1 = "calculate"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - assertEquals(4, add(2, 2)); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + assertEquals(4, add(2, 2)); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } @Test public void testSubtract() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop2 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter2 = 2; + int _cf_innerIterations2 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod2 = "MathTest"; String _cf_cls2 = "MathTest"; String _cf_fn2 = "calculate"; - System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + "######$!"); - long _cf_start2 = System.nanoTime(); - try { - assertEquals(0, subtract(2, 2)); - } finally { - long _cf_end2 = System.nanoTime(); - long _cf_dur2 = _cf_end2 - _cf_start2; - System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + ":" + _cf_dur2 + "######!"); + + for (int _cf_i2 = 0; _cf_i2 < _cf_innerIterations2; _cf_i2++) { + System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + "######$!"); + long _cf_start2 = System.nanoTime(); + try { + assertEquals(0, subtract(2, 2)); + } finally { + long _cf_end2 = System.nanoTime(); + long _cf_dur2 = _cf_end2 - _cf_start2; + System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + ":" + _cf_dur2 + "######!"); + } } } } @@ -285,7 +294,7 @@ def test_instrument_performance_mode_multiple_tests(self, tmp_path: Path): assert result == expected def test_instrument_preserves_annotations(self, tmp_path: Path): - """Test that annotations other than @Test are preserved.""" + """Test that annotations other than @Test are preserved with inner loop.""" test_file = tmp_path / "ServiceTest.java" source = """import org.junit.jupiter.api.Test; import org.junit.jupiter.api.DisplayName; @@ -333,40 +342,46 @@ def test_instrument_preserves_annotations(self, tmp_path: Path): @Test @DisplayName("Test service call") public void testService() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "ServiceTest"; String _cf_cls1 = "ServiceTest"; String _cf_fn1 = "call"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - service.call(); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + service.call(); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } @Disabled @Test public void testDisabled() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop2 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter2 = 2; + int _cf_innerIterations2 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod2 = "ServiceTest"; String _cf_cls2 = "ServiceTest"; String _cf_fn2 = "call"; - System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + "######$!"); - long _cf_start2 = System.nanoTime(); - try { - service.other(); - } finally { - long _cf_end2 = System.nanoTime(); - long _cf_dur2 = _cf_end2 - _cf_start2; - System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + ":" + _cf_dur2 + "######!"); + + for (int _cf_i2 = 0; _cf_i2 < _cf_innerIterations2; _cf_i2++) { + System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + "######$!"); + long _cf_start2 = System.nanoTime(); + try { + service.other(); + } finally { + long _cf_end2 = System.nanoTime(); + long _cf_dur2 = _cf_end2 - _cf_start2; + System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + ":" + _cf_dur2 + "######!"); + } } } } @@ -400,10 +415,10 @@ def test_missing_file(self, tmp_path: Path): class TestAddTimingInstrumentation: - """Tests for _add_timing_instrumentation helper function.""" + """Tests for _add_timing_instrumentation helper function with inner loop.""" def test_single_test_method(self): - """Test timing instrumentation for a single test method.""" + """Test timing instrumentation for a single test method with inner loop.""" source = """public class SimpleTest { @Test public void testSomething() { @@ -416,20 +431,23 @@ def test_single_test_method(self): expected = """public class SimpleTest { @Test public void testSomething() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "SimpleTest"; String _cf_cls1 = "SimpleTest"; String _cf_fn1 = "targetFunc"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - doSomething(); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + doSomething(); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } } @@ -437,7 +455,7 @@ def test_single_test_method(self): assert result == expected def test_multiple_test_methods(self): - """Test timing instrumentation for multiple test methods.""" + """Test timing instrumentation for multiple test methods with inner loop.""" source = """public class MultiTest { @Test public void testFirst() { @@ -455,39 +473,45 @@ def test_multiple_test_methods(self): expected = """public class MultiTest { @Test public void testFirst() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "MultiTest"; String _cf_cls1 = "MultiTest"; String _cf_fn1 = "func"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - first(); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + first(); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } @Test public void testSecond() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop2 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter2 = 2; + int _cf_innerIterations2 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod2 = "MultiTest"; String _cf_cls2 = "MultiTest"; String _cf_fn2 = "func"; - System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + "######$!"); - long _cf_start2 = System.nanoTime(); - try { - second(); - } finally { - long _cf_end2 = System.nanoTime(); - long _cf_dur2 = _cf_end2 - _cf_start2; - System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + ":" + _cf_dur2 + "######!"); + + for (int _cf_i2 = 0; _cf_i2 < _cf_innerIterations2; _cf_i2++) { + System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + "######$!"); + long _cf_start2 = System.nanoTime(); + try { + second(); + } finally { + long _cf_end2 = System.nanoTime(); + long _cf_dur2 = _cf_end2 - _cf_start2; + System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + ":" + _cf_dur2 + "######!"); + } } } } @@ -495,7 +519,7 @@ def test_multiple_test_methods(self): assert result == expected def test_timing_markers_format(self): - """Test that timing markers have the correct format.""" + """Test that timing markers have the correct format with inner loop.""" source = """public class MarkerTest { @Test public void testMarkers() { @@ -508,20 +532,23 @@ def test_timing_markers_format(self): expected = """public class MarkerTest { @Test public void testMarkers() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "TestClass"; String _cf_cls1 = "TestClass"; String _cf_fn1 = "targetMethod"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - action(); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + action(); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } } @@ -703,7 +730,7 @@ def test_instrument_generated_test_behavior_mode(self): assert result == expected def test_instrument_generated_test_performance_mode(self): - """Test instrumenting generated test in performance mode.""" + """Test instrumenting generated test in performance mode with inner loop.""" test_code = """import org.junit.jupiter.api.Test; public class GeneratedTest { @@ -725,20 +752,23 @@ def test_instrument_generated_test_performance_mode(self): public class GeneratedTest__perfonlyinstrumented { @Test public void testMethod() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "GeneratedTest"; String _cf_cls1 = "GeneratedTest"; String _cf_fn1 = "method"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - target.method(); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + target.method(); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } } @@ -804,12 +834,55 @@ def test_multiple_timing_markers(self): durations = [int(m[5]) for m in end_matches] assert durations == [100000, 200000, 150000] + def test_inner_loop_timing_markers(self): + """Test parsing timing markers from inner loop iterations. + + With the inner loop, each test method produces N timing markers (one per iteration). + The iterationId (5th field) now represents the inner iteration number (0, 1, 2, ..., N-1). + """ + # Simulate stdout from 3 inner iterations (inner_iterations=3) + stdout = """ +!$######Module:Class:func:1:0######$! +iteration 0 +!######Module:Class:func:1:0:150000######! +!$######Module:Class:func:1:1######$! +iteration 1 +!######Module:Class:func:1:1:50000######! +!$######Module:Class:func:1:2######$! +iteration 2 +!######Module:Class:func:1:2:45000######! +""" + start_pattern = re.compile(r"!\$######([^:]*):([^:]*):([^:]*):([^:]*):([^:]+)######\$!") + end_pattern = re.compile(r"!######([^:]*):([^:]*):([^:]*):([^:]*):([^:]+):([^:]+)######!") + + start_matches = start_pattern.findall(stdout) + end_matches = end_pattern.findall(stdout) + + # Should have 3 start and 3 end markers (one per inner iteration) + assert len(start_matches) == 3 + assert len(end_matches) == 3 + + # All markers should have the same loopIndex (1) but different iterationIds (0, 1, 2) + for i, (start, end) in enumerate(zip(start_matches, end_matches)): + assert start[3] == "1" # loopIndex + assert start[4] == str(i) # iterationId (0, 1, 2) + assert end[3] == "1" # loopIndex + assert end[4] == str(i) # iterationId (0, 1, 2) + + # Verify durations - iteration 0 is slower (JIT warmup), iterations 1 and 2 are faster + durations = [int(m[5]) for m in end_matches] + assert durations == [150000, 50000, 45000] + + # Min runtime logic would select 45000ns (the fastest iteration after JIT warmup) + min_runtime = min(durations) + assert min_runtime == 45000 + class TestInstrumentedCodeValidity: - """Tests to verify that instrumented code is syntactically valid Java.""" + """Tests to verify that instrumented code is syntactically valid Java with inner loop.""" def test_instrumented_code_has_balanced_braces(self, tmp_path: Path): - """Test that instrumented code has balanced braces.""" + """Test that instrumented code has balanced braces with inner loop.""" test_file = tmp_path / "BraceTest.java" source = """import org.junit.jupiter.api.Test; @@ -854,43 +927,49 @@ def test_instrumented_code_has_balanced_braces(self, tmp_path: Path): public class BraceTest__perfonlyinstrumented { @Test public void testOne() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "BraceTest"; String _cf_cls1 = "BraceTest"; String _cf_fn1 = "process"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - if (true) { - doSomething(); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + if (true) { + doSomething(); + } + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); } - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); } } @Test public void testTwo() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop2 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter2 = 2; + int _cf_innerIterations2 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod2 = "BraceTest"; String _cf_cls2 = "BraceTest"; String _cf_fn2 = "process"; - System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + "######$!"); - long _cf_start2 = System.nanoTime(); - try { - for (int i = 0; i < 10; i++) { - process(i); + + for (int _cf_i2 = 0; _cf_i2 < _cf_innerIterations2; _cf_i2++) { + System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + "######$!"); + long _cf_start2 = System.nanoTime(); + try { + for (int i = 0; i < 10; i++) { + process(i); + } + } finally { + long _cf_end2 = System.nanoTime(); + long _cf_dur2 = _cf_end2 - _cf_start2; + System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + ":" + _cf_dur2 + "######!"); } - } finally { - long _cf_end2 = System.nanoTime(); - long _cf_dur2 = _cf_end2 - _cf_start2; - System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + ":" + _cf_dur2 + "######!"); } } } @@ -899,7 +978,7 @@ def test_instrumented_code_has_balanced_braces(self, tmp_path: Path): assert result == expected def test_instrumented_code_preserves_imports(self, tmp_path: Path): - """Test that imports are preserved in instrumented code.""" + """Test that imports are preserved in instrumented code with inner loop.""" test_file = tmp_path / "ImportTest.java" source = """package com.example; @@ -946,21 +1025,24 @@ def test_instrumented_code_preserves_imports(self, tmp_path: Path): public class ImportTest__perfonlyinstrumented { @Test public void testCollections() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "ImportTest"; String _cf_cls1 = "ImportTest"; String _cf_fn1 = "size"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - List list = new ArrayList<>(); - assertEquals(0, list.size()); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + List list = new ArrayList<>(); + assertEquals(0, list.size()); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } } @@ -970,10 +1052,10 @@ def test_instrumented_code_preserves_imports(self, tmp_path: Path): class TestEdgeCases: - """Edge cases for Java instrumentation.""" + """Edge cases for Java instrumentation with inner loop.""" def test_empty_test_method(self, tmp_path: Path): - """Test instrumenting an empty test method.""" + """Test instrumenting an empty test method with inner loop.""" test_file = tmp_path / "EmptyTest.java" source = """import org.junit.jupiter.api.Test; @@ -1008,19 +1090,22 @@ def test_empty_test_method(self, tmp_path: Path): public class EmptyTest__perfonlyinstrumented { @Test public void testEmpty() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "EmptyTest"; String _cf_cls1 = "EmptyTest"; String _cf_fn1 = "empty"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } } @@ -1029,7 +1114,7 @@ def test_empty_test_method(self, tmp_path: Path): assert result == expected def test_test_with_nested_braces(self, tmp_path: Path): - """Test instrumenting code with nested braces.""" + """Test instrumenting code with nested braces with inner loop.""" test_file = tmp_path / "NestedTest.java" source = """import org.junit.jupiter.api.Test; @@ -1071,26 +1156,29 @@ def test_test_with_nested_braces(self, tmp_path: Path): public class NestedTest__perfonlyinstrumented { @Test public void testNested() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "NestedTest"; String _cf_cls1 = "NestedTest"; String _cf_fn1 = "process"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - if (condition) { - for (int i = 0; i < 10; i++) { - if (i > 5) { - process(i); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + if (condition) { + for (int i = 0; i < 10; i++) { + if (i > 5) { + process(i); + } } } + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); } - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); } } } @@ -1099,7 +1187,7 @@ def test_test_with_nested_braces(self, tmp_path: Path): assert result == expected def test_class_with_inner_class(self, tmp_path: Path): - """Test instrumenting test class with inner class.""" + """Test instrumenting test class with inner class with inner loop.""" test_file = tmp_path / "InnerClassTest.java" source = """import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Nested; @@ -1145,20 +1233,23 @@ class InnerTests { public class InnerClassTest__perfonlyinstrumented { @Test public void testOuter() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop1 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter1 = 1; + int _cf_innerIterations1 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod1 = "InnerClassTest"; String _cf_cls1 = "InnerClassTest"; String _cf_fn1 = "testMethod"; - System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + "######$!"); - long _cf_start1 = System.nanoTime(); - try { - outerMethod(); - } finally { - long _cf_end1 = System.nanoTime(); - long _cf_dur1 = _cf_end1 - _cf_start1; - System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_iter1 + ":" + _cf_dur1 + "######!"); + + for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++) { + System.out.println("!$######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + "######$!"); + long _cf_start1 = System.nanoTime(); + try { + outerMethod(); + } finally { + long _cf_end1 = System.nanoTime(); + long _cf_dur1 = _cf_end1 - _cf_start1; + System.out.println("!######" + _cf_mod1 + ":" + _cf_cls1 + ":" + _cf_fn1 + ":" + _cf_loop1 + ":" + _cf_i1 + ":" + _cf_dur1 + "######!"); + } } } @@ -1166,20 +1257,23 @@ class InnerTests { class InnerTests { @Test public void testInner() { - // Codeflash timing instrumentation + // Codeflash timing instrumentation with inner loop for JIT warmup int _cf_loop2 = Integer.parseInt(System.getenv("CODEFLASH_LOOP_INDEX")); - int _cf_iter2 = 2; + int _cf_innerIterations2 = Integer.parseInt(System.getenv().getOrDefault("CODEFLASH_INNER_ITERATIONS", "100")); String _cf_mod2 = "InnerClassTest"; String _cf_cls2 = "InnerClassTest"; String _cf_fn2 = "testMethod"; - System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + "######$!"); - long _cf_start2 = System.nanoTime(); - try { - innerMethod(); - } finally { - long _cf_end2 = System.nanoTime(); - long _cf_dur2 = _cf_end2 - _cf_start2; - System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_iter2 + ":" + _cf_dur2 + "######!"); + + for (int _cf_i2 = 0; _cf_i2 < _cf_innerIterations2; _cf_i2++) { + System.out.println("!$######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + "######$!"); + long _cf_start2 = System.nanoTime(); + try { + innerMethod(); + } finally { + long _cf_end2 = System.nanoTime(); + long _cf_dur2 = _cf_end2 - _cf_start2; + System.out.println("!######" + _cf_mod2 + ":" + _cf_cls2 + ":" + _cf_fn2 + ":" + _cf_loop2 + ":" + _cf_i2 + ":" + _cf_dur2 + "######!"); + } } } } @@ -1222,6 +1316,12 @@ class TestRunAndParseTests: 5.9.3 test + + org.junit.platform + junit-platform-console-standalone + 1.9.3 + test + org.xerial sqlite-jdbc @@ -1380,7 +1480,14 @@ def test_run_and_parse_behavior_mode(self, java_project): assert result.runtime > 0 def test_run_and_parse_performance_mode(self, java_project): - """Test run_and_parse_tests in PERFORMANCE mode with timing markers.""" + """Test run_and_parse_tests in PERFORMANCE mode with inner loop timing. + + This test verifies the complete performance benchmarking flow: + 1. Instruments test with inner loop for JIT warmup + 2. Runs with inner_iterations=2 (fast test) + 3. Validates multiple timing markers are produced (one per inner iteration) + 4. Validates parsed results contain timing data + """ from argparse import Namespace from codeflash.discovery.functions_to_optimize import FunctionToOptimize @@ -1431,6 +1538,10 @@ def test_run_and_parse_performance_mode(self, java_project): ) assert success + # Verify instrumented code contains inner loop for JIT warmup + assert "CODEFLASH_INNER_ITERATIONS" in instrumented, "Performance mode should use inner loop" + assert "for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++)" in instrumented + instrumented_file = test_dir / "MathUtilsTest__perfonlyinstrumented.java" instrumented_file.write_text(instrumented, encoding="utf-8") @@ -1463,9 +1574,10 @@ def test_run_and_parse_performance_mode(self, java_project): ) ]) - # Run performance tests + # Run performance tests with inner_iterations=2 for fast test test_env = os.environ.copy() test_env["CODEFLASH_TEST_ITERATION"] = "0" + test_env["CODEFLASH_INNER_ITERATIONS"] = "2" # Only 2 inner iterations for fast test test_results, _ = func_optimizer.run_and_parse_tests( testing_type=TestingMode.PERFORMANCE, @@ -1473,16 +1585,30 @@ def test_run_and_parse_performance_mode(self, java_project): test_files=func_optimizer.test_files, optimization_iteration=0, pytest_min_loops=1, - pytest_max_loops=3, + pytest_max_loops=1, # Only 1 outer loop (Maven invocation) testing_time=1.0, ) - # Verify results - assert len(test_results.test_results) >= 1 + # Should have 2 results (one per inner iteration) + assert len(test_results.test_results) >= 2, ( + f"Expected at least 2 results from inner loop (inner_iterations=2), got {len(test_results.test_results)}" + ) + + # All results should pass with valid timing + runtimes = [] for result in test_results.test_results: assert result.did_pass is True assert result.runtime is not None assert result.runtime > 0 + runtimes.append(result.runtime) + + # Verify we have multiple timing measurements + assert len(runtimes) >= 2, f"Expected at least 2 runtimes, got {len(runtimes)}" + + # Log runtime info (min would be selected for benchmarking comparison) + min_runtime = min(runtimes) + max_runtime = max(runtimes) + print(f"Inner loop runtimes: min={min_runtime}ns, max={max_runtime}ns, count={len(runtimes)}") def test_run_and_parse_multiple_test_methods(self, java_project): """Test run_and_parse_tests with multiple test methods.""" @@ -1863,3 +1989,227 @@ def test_behavior_mode_writes_to_sqlite(self, java_project): assert return_value == "1", f"Expected serialized integer '1', got: {return_value}" conn.close() + + def test_performance_mode_inner_loop_timing_markers(self, java_project): + """Test that performance mode produces multiple timing markers from inner loop. + + This test verifies that: + 1. Instrumented code runs inner_iterations=2 times + 2. Two timing markers are produced (one per inner iteration) + 3. Each marker has a unique iteration ID (0, 1) + 4. Both markers have valid durations + """ + from codeflash.languages.java.test_runner import run_benchmarking_tests + + project_root, src_dir, test_dir = java_project + + # Create a simple function to optimize + (src_dir / "Fibonacci.java").write_text("""package com.example; + +public class Fibonacci { + public int fib(int n) { + if (n <= 1) return n; + return fib(n - 1) + fib(n - 2); + } +} +""", encoding="utf-8") + + # Create test file + test_source = """package com.example; + +import org.junit.jupiter.api.Test; +import static org.junit.jupiter.api.Assertions.*; + +public class FibonacciTest { + @Test + public void testFib() { + Fibonacci fib = new Fibonacci(); + assertEquals(5, fib.fib(5)); + } +} +""" + test_file = test_dir / "FibonacciTest.java" + test_file.write_text(test_source, encoding="utf-8") + + # Instrument for performance mode (adds inner loop) + func_info = FunctionInfo( + name="fib", + file_path=src_dir / "Fibonacci.java", + start_line=4, + end_line=7, + parents=(), + is_method=True, + language=Language.JAVA, + ) + + success, instrumented = instrument_existing_test( + test_file, [], func_info, test_dir, mode="performance" + ) + assert success + + # Verify instrumented code contains inner loop + assert "CODEFLASH_INNER_ITERATIONS" in instrumented + assert "for (int _cf_i1 = 0; _cf_i1 < _cf_innerIterations1; _cf_i1++)" in instrumented + + instrumented_file = test_dir / "FibonacciTest__perfonlyinstrumented.java" + instrumented_file.write_text(instrumented, encoding="utf-8") + + # Run benchmarking with inner_iterations=2 (fast) + test_env = os.environ.copy() + + # Use TestFiles-like object + class MockTestFiles: + def __init__(self, files): + self.test_files = files + + class MockTestFile: + def __init__(self, path): + self.benchmarking_file_path = path + self.instrumented_behavior_file_path = path + + test_files = MockTestFiles([MockTestFile(instrumented_file)]) + + result_xml_path, result = run_benchmarking_tests( + test_paths=test_files, + test_env=test_env, + cwd=project_root, + timeout=120, + project_root=project_root, + min_loops=1, + max_loops=1, # Only 1 outer loop + target_duration_seconds=1.0, + inner_iterations=2, # Only 2 inner iterations for fast test + ) + + # Verify the test ran successfully + assert result.returncode == 0, f"Maven test failed: {result.stderr}" + + # Parse timing markers from stdout + stdout = result.stdout + start_pattern = re.compile(r"!\$######([^:]*):([^:]*):([^:]*):([^:]*):([^:]+)######\$!") + end_pattern = re.compile(r"!######([^:]*):([^:]*):([^:]*):([^:]*):([^:]+):([^:]+)######!") + + start_matches = start_pattern.findall(stdout) + end_matches = end_pattern.findall(stdout) + + # Should have 2 timing markers (inner_iterations=2) + assert len(start_matches) == 2, f"Expected 2 start markers, got {len(start_matches)}: {start_matches}" + assert len(end_matches) == 2, f"Expected 2 end markers, got {len(end_matches)}: {end_matches}" + + # Verify iteration IDs are 0 and 1 + iteration_ids = [m[4] for m in start_matches] + assert "0" in iteration_ids, f"Expected iteration ID 0, got: {iteration_ids}" + assert "1" in iteration_ids, f"Expected iteration ID 1, got: {iteration_ids}" + + # Verify all markers have the same loop index (1) + loop_indices = [m[3] for m in start_matches] + assert all(idx == "1" for idx in loop_indices), f"Expected all loop indices to be 1, got: {loop_indices}" + + # Verify durations are positive + durations = [int(m[5]) for m in end_matches] + assert all(d > 0 for d in durations), f"Expected positive durations, got: {durations}" + + def test_performance_mode_multiple_methods_inner_loop(self, java_project): + """Test inner loop with multiple test methods. + + Each test method should run inner_iterations times independently. + This produces 2 test methods x 2 inner iterations = 4 total timing markers. + """ + from codeflash.languages.java.test_runner import run_benchmarking_tests + + project_root, src_dir, test_dir = java_project + + # Create a simple math class + (src_dir / "MathOps.java").write_text("""package com.example; + +public class MathOps { + public int add(int a, int b) { + return a + b; + } +} +""", encoding="utf-8") + + # Create test with multiple test methods + test_source = """package com.example; + +import org.junit.jupiter.api.Test; +import static org.junit.jupiter.api.Assertions.*; + +public class MathOpsTest { + @Test + public void testAddPositive() { + MathOps math = new MathOps(); + assertEquals(5, math.add(2, 3)); + } + + @Test + public void testAddNegative() { + MathOps math = new MathOps(); + assertEquals(-1, math.add(2, -3)); + } +} +""" + test_file = test_dir / "MathOpsTest.java" + test_file.write_text(test_source, encoding="utf-8") + + # Instrument for performance mode + func_info = FunctionInfo( + name="add", + file_path=src_dir / "MathOps.java", + start_line=4, + end_line=6, + parents=(), + is_method=True, + language=Language.JAVA, + ) + + success, instrumented = instrument_existing_test( + test_file, [], func_info, test_dir, mode="performance" + ) + assert success + + instrumented_file = test_dir / "MathOpsTest__perfonlyinstrumented.java" + instrumented_file.write_text(instrumented, encoding="utf-8") + + # Run benchmarking with inner_iterations=2 + test_env = os.environ.copy() + + class MockTestFiles: + def __init__(self, files): + self.test_files = files + + class MockTestFile: + def __init__(self, path): + self.benchmarking_file_path = path + self.instrumented_behavior_file_path = path + + test_files = MockTestFiles([MockTestFile(instrumented_file)]) + + result_xml_path, result = run_benchmarking_tests( + test_paths=test_files, + test_env=test_env, + cwd=project_root, + timeout=120, + project_root=project_root, + min_loops=1, + max_loops=1, + target_duration_seconds=1.0, + inner_iterations=2, + ) + + assert result.returncode == 0, f"Maven test failed: {result.stderr}" + + # Parse timing markers + stdout = result.stdout + end_pattern = re.compile(r"!######([^:]*):([^:]*):([^:]*):([^:]*):([^:]+):([^:]+)######!") + end_matches = end_pattern.findall(stdout) + + # Should have 4 timing markers (2 test methods x 2 inner iterations) + assert len(end_matches) == 4, f"Expected 4 end markers, got {len(end_matches)}: {end_matches}" + + # Count markers per iteration ID + iter_0_count = sum(1 for m in end_matches if m[4] == "0") + iter_1_count = sum(1 for m in end_matches if m[4] == "1") + + assert iter_0_count == 2, f"Expected 2 markers for iteration 0, got {iter_0_count}" + assert iter_1_count == 2, f"Expected 2 markers for iteration 1, got {iter_1_count}" From 578b73731c4e429009b89ccb8072e73483cfc5db Mon Sep 17 00:00:00 2001 From: Saurabh Misra Date: Sun, 1 Feb 2026 23:46:49 +0000 Subject: [PATCH 2/2] fix: enable stdout capture in JUnit Console Launcher XML reports Configure JUnit Console Launcher to capture stdout/stderr in XML reports: - Add --config=junit.platform.output.capture.stdout=true - Add --config=junit.platform.output.capture.stderr=true - Change --details=verbose to --details=none to avoid duplicate output This ensures timing markers are properly captured in the JUnit XML's element, eliminating the need to rely on subprocess stdout fallback for parsing timing markers. Co-Authored-By: Claude Opus 4.5 --- codeflash/languages/java/test_runner.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/codeflash/languages/java/test_runner.py b/codeflash/languages/java/test_runner.py index a8e2a0d3e..0d22cdaf7 100644 --- a/codeflash/languages/java/test_runner.py +++ b/codeflash/languages/java/test_runner.py @@ -422,7 +422,13 @@ def _run_tests_direct( "org.junit.platform.console.ConsoleLauncher", "--disable-banner", "--disable-ansi-colors", - "--details=verbose", + # Use 'none' details to avoid duplicate output + # Timing markers are captured in XML via stdout capture config + "--details=none", + # Enable stdout/stderr capture in XML reports + # This ensures timing markers are included in the XML system-out element + "--config=junit.platform.output.capture.stdout=true", + "--config=junit.platform.output.capture.stderr=true", ] # Add reports directory if specified (for XML output)