From eb26ffa8757035897ac04a27b2688149b2af1d47 Mon Sep 17 00:00:00 2001 From: Vidyasagar Ananthan Date: Tue, 8 Jul 2025 22:36:50 -0700 Subject: [PATCH] New ninja tracing script (#2472) * Adding ninja log json convertion utility * Updating to match old ninjatracing * Updating Jenkins to use new ninjatracing * Ensuring v7 works * Removing old ninjatracing from dockerfile [ROCm/composable_kernel commit: e391b025a05d368eb4f76f7ee0b2f910faf011ae] --- Dockerfile | 1 - Jenkinsfile | 3 +- script/ninja_json_converter.py | 510 +++++++++++++++++++++++++++++++++ 3 files changed, 511 insertions(+), 3 deletions(-) create mode 100644 script/ninja_json_converter.py diff --git a/Dockerfile b/Dockerfile index 1a47639d31..0219f99238 100644 --- a/Dockerfile +++ b/Dockerfile @@ -77,7 +77,6 @@ RUN git clone https://github.com/ccache/ccache.git && \ wget -qO /usr/local/bin/ninja.gz https://github.com/ninja-build/ninja/releases/latest/download/ninja-linux.zip && \ gunzip /usr/local/bin/ninja.gz && \ chmod a+x /usr/local/bin/ninja && \ - git clone https://github.com/nico/ninjatracing.git && \ #Install ClangBuildAnalyzer git clone https://github.com/aras-p/ClangBuildAnalyzer.git && \ cd ClangBuildAnalyzer/ && \ diff --git a/Jenkinsfile b/Jenkinsfile index 395e9bd836..50c15701a7 100644 --- a/Jenkinsfile +++ b/Jenkinsfile @@ -384,8 +384,7 @@ def cmake_build(Map conf=[:]){ sh "/ClangBuildAnalyzer/build/ClangBuildAnalyzer --analyze clang_build.log > clang_build_analysis.log" archiveArtifacts "clang_build_analysis.log" } - - sh "/ninjatracing/ninjatracing .ninja_log > ck_build_trace.json" + sh "python3 ../script/ninja_json_converter.py .ninja_log --legacy-format --output ck_build_trace.json" archiveArtifacts "ck_build_trace.json" // do not run unit tests when building instances only diff --git a/script/ninja_json_converter.py b/script/ninja_json_converter.py new file mode 100644 index 0000000000..92660dc7b3 --- /dev/null +++ b/script/ninja_json_converter.py @@ -0,0 +1,510 @@ +#!/usr/bin/env python3 + +""" +Converts .ninja_log files into Chrome's about:tracing format. +""" + +import argparse +import json +import os +import re +import sys +from pathlib import Path +from typing import Dict, List, Optional, Tuple, Iterator + + +class BuildTarget: + """Represents a single build target with timing information.""" + + def __init__(self, start_time: int, end_time: int, output_name: str, cmd_hash: str): + self.start_time = int(start_time) + self.end_time = int(end_time) + self.cmd_hash = cmd_hash + self.duration = self.end_time - self.start_time + self.targets = [output_name] # List of target names for this command hash + + @property + def category(self) -> str: + """Categorize the build target based on file extension.""" + # Use the first target for categorization + primary_target = self.targets[0] if self.targets else "" + ext = Path(primary_target).suffix.lower() + if ext in ['.o', '.obj']: + return 'compile' + elif ext in ['.a', '.lib']: + return 'archive' + elif ext in ['.so', '.dll', '.dylib']: + return 'link_shared' + elif ext in ['.exe', '.out']: + return 'link_executable' + elif 'test' in primary_target.lower(): + return 'test' + else: + return 'other' + + @property + def output_name(self) -> str: + """Get the primary output name (for backward compatibility).""" + return self.targets[0] if self.targets else "" + + +class ThreadScheduler: + """Simulates thread allocation for parallelism analysis.""" + + def __init__(self, legacy_mode: bool = False): + self.workers: List[int] = [] + self.legacy_mode = legacy_mode + + def allocate_thread(self, target: BuildTarget) -> int: + """Allocate a thread for the given target.""" + if self.legacy_mode: + # Legacy algorithm from old ninjatracer + for worker in range(len(self.workers)): + if self.workers[worker] >= target.end_time: + self.workers[worker] = target.start_time + return worker + self.workers.append(target.start_time) + return len(self.workers) - 1 + else: + # New algorithm + for i, worker_end_time in enumerate(self.workers): + if worker_end_time <= target.start_time: + self.workers[i] = target.end_time + return i + + # No available worker, create a new one + self.workers.append(target.end_time) + return len(self.workers) - 1 + + +class NinjaLogParser: + """Parser for ninja build log files.""" + + def __init__(self, show_all_builds: bool = False): + self.show_all_builds = show_all_builds + + def parse_log_file(self, log_path: str) -> List[BuildTarget]: + """Parse the ninja log file and return build targets.""" + if not os.path.exists(log_path): + raise FileNotFoundError(f"Ninja log file not found: {log_path}") + + with open(log_path, 'r', encoding='utf-8') as file: + lines = file.readlines() + + if not lines: + raise ValueError("Empty ninja log file") + + # Parse and validate header + header = lines[0].strip() + version_match = re.match(r'^# ninja log v(\d+)$', header) + if not version_match: + raise ValueError(f"Invalid ninja log header: {header}") + + version = int(version_match.group(1)) + if version < 5: + raise ValueError(f"Unsupported ninja log version: {version}") + + # Skip additional header line for version 6 + start_line = 2 if version > 5 else 1 + + targets: Dict[str, BuildTarget] = {} + last_end_time = 0 + + for line_num, line in enumerate(lines[start_line:], start=start_line + 1): + line = line.strip() + + # Skip empty lines and comments + if not line or line.startswith('#'): + continue + + parts = line.split('\t') + if len(parts) < 5: + print(f"Warning: Skipping malformed line {line_num}: {line}", file=sys.stderr) + continue + + try: + start_time, end_time, _, output_name, cmd_hash = parts[:5] + start_time, end_time = int(start_time), int(end_time) + + # Handle incremental builds + if not self.show_all_builds and end_time < last_end_time: + targets.clear() + + last_end_time = end_time + + # Group targets by command hash + if cmd_hash not in targets: + targets[cmd_hash] = BuildTarget(start_time, end_time, output_name, cmd_hash) + else: + # Update with the latest timing and add output + existing = targets[cmd_hash] + existing.start_time = min(existing.start_time, start_time) + existing.end_time = max(existing.end_time, end_time) + existing.duration = existing.end_time - existing.start_time + existing.targets.append(output_name) + + except (ValueError, IndexError) as e: + print(f"Warning: Error parsing line {line_num}: {e}", file=sys.stderr) + continue + + return sorted(targets.values(), key=lambda t: t.end_time, reverse=True) + + +class FTimeTraceReader: + """Reads and processes Clang -ftime-trace JSON files.""" + + def __init__(self, granularity_us: int = 50000): + self.granularity_us = granularity_us + + def read_trace_file(self, trace_path: str) -> Optional[Dict]: + """Read and parse a Clang time trace file.""" + try: + with open(trace_path, 'r', encoding='utf-8') as f: + return json.load(f) + except (FileNotFoundError, json.JSONDecodeError, IOError): + return None + + def filter_events(self, trace_data: Dict) -> List[Dict]: + """Filter trace events based on criteria.""" + if 'traceEvents' not in trace_data: + return [] + + filtered_events = [] + for event in trace_data['traceEvents']: + # Only include complete events (ph=X) that meet duration threshold + if (event.get('ph') == 'X' and + event.get('dur', 0) >= self.granularity_us and + not event.get('name', '').startswith('Total')): + filtered_events.append(event) + + return filtered_events + + def adjust_event_timing(self, event: Dict, target: BuildTarget, pid: int, tid: int) -> Dict: + """Adjust event timing to align with ninja build timing.""" + ninja_duration_us = target.duration * 1000 + + # Validate event duration against ninja timing + if event.get('dur', 0) > ninja_duration_us: + print(f"Warning: Clang trace event duration ({event['dur']}μs) exceeds " + f"ninja duration ({ninja_duration_us}μs) for {target.output_name}", + file=sys.stderr) + return None + + # Adjust event timing + adjusted_event = event.copy() + adjusted_event['pid'] = pid + adjusted_event['tid'] = tid + adjusted_event['ts'] += target.start_time * 1000 # Offset by ninja start time + + return adjusted_event + +class ChromeTraceGenerator: + """Generates Chrome tracing format from build targets.""" + + def __init__(self, process_id: int = 1, embed_ftime_traces: bool = False, + granularity_us: int = 50000, ninja_log_dir: Optional[str] = None, + legacy_format: bool = False): + self.process_id = process_id + self.scheduler = ThreadScheduler(legacy_mode=legacy_format) + self.embed_ftime_traces = embed_ftime_traces + self.ninja_log_dir = ninja_log_dir + self.ftime_reader = FTimeTraceReader(granularity_us) if embed_ftime_traces else None + self.legacy_format = legacy_format + + def find_ftime_trace_files(self, target: BuildTarget) -> List[str]: + """Find Clang -ftime-trace files for a build target.""" + if not self.ninja_log_dir: + return [] + + trace_files = [] + + # Look for .json files adjacent to object files + obj_path = Path(self.ninja_log_dir) / target.output_name + json_path = obj_path.with_suffix('.json') + + if json_path.exists(): + trace_files.append(str(json_path)) + + return trace_files + + def generate_ftime_events(self, target: BuildTarget, tid: int) -> Iterator[Dict]: + """Generate Clang -ftime-trace events for a target.""" + if not self.embed_ftime_traces or not self.ftime_reader: + return + + trace_files = self.find_ftime_trace_files(target) + + for trace_file in trace_files: + trace_data = self.ftime_reader.read_trace_file(trace_file) + if not trace_data: + continue + + filtered_events = self.ftime_reader.filter_events(trace_data) + + for event in filtered_events: + adjusted_event = self.ftime_reader.adjust_event_timing( + event, target, self.process_id, tid + ) + if adjusted_event: + yield adjusted_event + + def generate_trace_events(self, targets: List[BuildTarget]) -> List[Dict]: + """Generate Chrome trace events from build targets.""" + events = [] + + for target in targets: + thread_id = self.scheduler.allocate_thread(target) + + # Add main ninja build event + if self.legacy_format: + # Legacy format: join multiple targets with commas, use "targets" category, empty args + target_name = ', '.join(target.targets) if len(target.targets) > 1 else target.output_name + ninja_event = { + 'name': target_name, + 'cat': 'targets', + 'ph': 'X', # Complete event + 'ts': target.start_time * 1000, # Convert to microseconds + 'dur': target.duration * 1000, # Convert to microseconds + 'pid': self.process_id, + 'tid': thread_id, + 'args': {} + } + else: + # New format: smart categorization, detailed args + ninja_event = { + 'name': target.output_name, + 'cat': target.category, + 'ph': 'X', # Complete event + 'ts': target.start_time * 1000, # Convert to microseconds + 'dur': target.duration * 1000, # Convert to microseconds + 'pid': self.process_id, + 'tid': thread_id, + 'args': { + 'output': target.output_name, + 'duration_ms': target.duration, + 'cmd_hash': target.cmd_hash + } + } + events.append(ninja_event) + + # Add embedded Clang -ftime-trace events + if self.embed_ftime_traces: + ftime_events = list(self.generate_ftime_events(target, thread_id)) + events.extend(ftime_events) + + if ftime_events: + print(f"Embedded {len(ftime_events)} -ftime-trace events for {target.output_name}", + file=sys.stderr) + + return events + + +class BuildAnalyzer: + """Analyzes build performance and provides statistics.""" + + def __init__(self, targets: List[BuildTarget]): + self.targets = targets + + def get_build_summary(self) -> Dict: + """Generate build performance summary.""" + if not self.targets: + return {} + + total_duration = sum(t.duration for t in self.targets) + total_targets = len(self.targets) + + # Category statistics + category_stats = {} + for target in self.targets: + cat = target.category + if cat not in category_stats: + category_stats[cat] = {'count': 0, 'total_time': 0} + category_stats[cat]['count'] += 1 + category_stats[cat]['total_time'] += target.duration + + # Top slowest targets + slowest_targets = sorted(self.targets, key=lambda t: t.duration, reverse=True)[:10] + + return { + 'total_targets': total_targets, + 'total_duration_ms': total_duration, + 'total_duration_sec': total_duration / 1000, + 'average_duration_ms': total_duration / total_targets if total_targets > 0 else 0, + 'category_stats': category_stats, + 'slowest_targets': [ + {'name': t.output_name, 'duration_ms': t.duration, 'category': t.category} + for t in slowest_targets + ] + } + + def print_summary(self): + """Print build summary to stderr.""" + summary = self.get_build_summary() + if not summary: + print("No build data available", file=sys.stderr) + return + + print(f"\n=== Build Summary ===", file=sys.stderr) + print(f"Total targets: {summary['total_targets']}", file=sys.stderr) + print(f"Total time: {summary['total_duration_sec']:.2f}s", file=sys.stderr) + print(f"Average time per target: {summary['average_duration_ms']:.2f}ms", file=sys.stderr) + + print(f"\nBy category:", file=sys.stderr) + for category, stats in summary['category_stats'].items(): + avg_time = stats['total_time'] / stats['count'] if stats['count'] > 0 else 0 + print(f" {category:15} {stats['count']:6} targets " + f"{stats['total_time']/1000:8.2f}s " + f"(avg: {avg_time/1000:.3f}s)", file=sys.stderr) + + print(f"\nSlowest targets:", file=sys.stderr) + for i, target in enumerate(summary['slowest_targets'][:5], 1): + print(f" {i:2}. {target['name']} ({target['duration_ms']}ms, {target['category']})", file=sys.stderr) + + +def create_argument_parser() -> argparse.ArgumentParser: + """Create command line argument parser.""" + parser = argparse.ArgumentParser( + description="Convert ninja build logs to Chrome tracing format", + formatter_class=argparse.RawDescriptionHelpFormatter, + epilog=""" +Examples: + %(prog)s build/.ninja_log # Basic usage + %(prog)s build/.ninja_log --output trace.json # Save to file + %(prog)s build/.ninja_log --summary # Show build summary + %(prog)s build/.ninja_log --show-all # Include all builds + %(prog)s build/.ninja_log --embed-ftime-trace # Include Clang timing data + %(prog)s build/.ninja_log --granularity 10000 # Custom granularity threshold + """ + ) + + parser.add_argument( + 'ninja_logs', + nargs='+', # Accept one or more ninja log files + help='Path(s) to the .ninja_log file(s)' + ) + + parser.add_argument( + '-o', '--output', + help='Output file (default: stdout)' + ) + + parser.add_argument( + '--show-all', + action='store_true', + help='Show all builds, not just the last one' + ) + + parser.add_argument( + '--summary', + action='store_true', + help='Print build summary to stderr' + ) + + parser.add_argument( + '--pretty', + action='store_true', + help='Pretty-print JSON output' + ) + + parser.add_argument( + '--embed-ftime-trace', + action='store_true', + help='Embed Clang -ftime-trace JSON files found adjacent to targets' + ) + + parser.add_argument( + '--granularity', + type=int, + default=50000, + help='Minimum duration for -ftime-trace events in microseconds (default: 50000)' + ) + + parser.add_argument( + '--legacy-format', + action='store_true', + help='Output in legacy format compatible with old ninjatracer (simple JSON array, all categories as "targets", empty args)' + ) + + return parser + + +def main(): + """Main entry point.""" + parser = create_argument_parser() + args = parser.parse_args() + + try: + # Process multiple ninja log files + all_events = [] + + for pid, ninja_log_path in enumerate(args.ninja_logs): + # Parse ninja log + log_parser = NinjaLogParser(show_all_builds=args.show_all) + targets = log_parser.parse_log_file(ninja_log_path) + + if not targets: + print(f"No build targets found in ninja log: {ninja_log_path}", file=sys.stderr) + continue + + # Determine ninja log directory for -ftime-trace files + ninja_log_dir = os.path.dirname(os.path.abspath(ninja_log_path)) if args.embed_ftime_trace else None + + # Generate trace events for this log file + trace_generator = ChromeTraceGenerator( + process_id=pid, # Use different PID for each log file + embed_ftime_traces=args.embed_ftime_trace, + granularity_us=args.granularity, + ninja_log_dir=ninja_log_dir, + legacy_format=args.legacy_format + ) + events = trace_generator.generate_trace_events(targets) + all_events.extend(events) + + # Print summary if requested (for each log file) + if args.summary: + print(f"\n=== Summary for {ninja_log_path} ===", file=sys.stderr) + analyzer = BuildAnalyzer(targets) + analyzer.print_summary() + + if not all_events: + print("No build targets found in any ninja log files", file=sys.stderr) + return 1 + + # Output format logic + if args.legacy_format: + # Legacy format: always output simple JSON array + json_kwargs = {'indent': 2} if args.pretty else {} + json_output = json.dumps(all_events, **json_kwargs) + elif args.output or args.pretty: + # Enhanced format with metadata (when saving to file or pretty printing) + trace_data = { + 'traceEvents': all_events, + 'displayTimeUnit': 'ms', + 'systemTraceEvents': 'SystemTraceData', + 'otherData': { + 'version': '1.0', + 'generator': 'ninja_json_converter.py' + } + } + json_kwargs = {'indent': 2} if args.pretty else {} + json_output = json.dumps(trace_data, **json_kwargs) + else: + # Original format (simple JSON array to stdout) + json_output = json.dumps(all_events) + + if args.output: + with open(args.output, 'w') as f: + f.write(json_output) + print(f"Trace written to {args.output}", file=sys.stderr) + else: + print(json_output) + + return 0 + + except Exception as e: + print(f"Error: {e}", file=sys.stderr) + return 1 + + +if __name__ == "__main__": + sys.exit(main())