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..0d22cdaf7 100644 --- a/codeflash/languages/java/test_runner.py +++ b/codeflash/languages/java/test_runner.py @@ -228,32 +228,450 @@ 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", + # 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) + 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 +684,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 +751,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 +774,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 +797,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}"