Merge pull request #471 from jawkio/443-add-profiling-option

Add profiling report file support

Author: bertysentry

src/it/java/io/jawk/site/CompatibilitySummaryGenerator.java

@@ -4,7 +4,7 @@
  * ╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲╱╲
  * Jawk
  * ჻჻჻჻჻჻
- * Copyright 2006 - 2026 MetricsHub
+ * Copyright (C) 2006 - 2026 MetricsHub
  * ჻჻჻჻჻჻
  * This program is free software: you can redistribute it and/or modify
  * it under the terms of the GNU Lesser General Public License as

src/main/java/io/jawk/Awk.java

@@ -310,6 +310,17 @@ public AVM createAvm() {
 		return createAvm(this.settings);
 	}
 
+	/**
+	 * Creates a reusable runtime backed by one {@link AVM} instance, optionally
+	 * collecting runtime profiling statistics.
+	 *
+	 * @param profilingEnabled whether runtime profiling should be enabled
+	 * @return reusable AVM
+	 */
+	public AVM createAvm(boolean profilingEnabled) {
+		return createAvm(this.settings, profilingEnabled);
+	}
+
 	/**
 	 * Starts building a run request for a compiled AWK program.
 	 * <p>
@@ -680,7 +691,19 @@ public AVM prepareEval(InputSource source) throws IOException {
 	 * @return reusable AVM
 	 */
 	protected AVM createAvm(AwkSettings settingsParam) {
-		return new AVM(settingsParam, this.extensionInstances);
+		return createAvm(settingsParam, false);
+	}
+
+	/**
+	 * Creates an {@link AVM} using the provided runtime settings and profiling
+	 * mode.
+	 *
+	 * @param settingsParam runtime settings to apply
+	 * @param profilingEnabled whether runtime profiling should be enabled
+	 * @return reusable AVM
+	 */
+	protected AVM createAvm(AwkSettings settingsParam, boolean profilingEnabled) {
+		return new AVM(settingsParam, this.extensionInstances, profilingEnabled);
 	}
 
 	/**

src/main/java/io/jawk/Cli.java

@@ -34,6 +34,7 @@
 import java.io.ObjectOutputStream;
 import java.io.PrintStream;
 import java.io.StringReader;
+import java.io.UncheckedIOException;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.LinkedHashMap;
@@ -92,6 +93,8 @@ public final class Cli {
 	private boolean printUsage;
 	private boolean sandbox;
 	private boolean disableOptimize;
+	private boolean profiling;
+	private File profilingOutputFile;
 	private File persistentMemoryFile;
 
 	/**
@@ -163,6 +166,15 @@ public boolean isDisableOptimize() {
 		return disableOptimize;
 	}
 
+	/**
+	 * Indicates whether runtime profiling was requested.
+	 *
+	 * @return {@code true} when profiling should be enabled
+	 */
+	public boolean isProfiling() {
+		return profiling;
+	}
+
 	/**
 	 * Returns the list of script sources specified on the command line.
 	 *
@@ -276,6 +288,17 @@ public void parse(String[] args) {
 			} else if (arg.equals("-s") || arg.equals("--no-optimize")) {
 				// -s/--no-optimize : skip tuple queue optimizations
 				disableOptimize = true;
+			} else if (arg.equals("--profile")) {
+				// --profile : collect and print runtime profiling statistics
+				profiling = true;
+			} else if (arg.startsWith("--profile=")) {
+				// --profile=filename : collect profiling statistics and write them to a file
+				String file = arg.substring("--profile=".length());
+				if (file.length() == 0) {
+					throw new IllegalArgumentException("Need output filename for --profile");
+				}
+				profiling = true;
+				profilingOutputFile = new File(file);
 			} else if (arg.equals("--dump-intermediate")) {
 				// --dump-intermediate : dump intermediate tuples to file
 				dumpIntermediateCode = true;
@@ -470,7 +493,7 @@ private File resolvePersistentMemoryFile() {
 	 */
 	private void executeProgram(Awk awk, AwkProgram program, File memoryFile) throws Exception {
 		OutputStreamAwkSink sink = new OutputStreamAwkSink(out, settings.getLocale());
-		try (AVM avm = awk.createAvm()) {
+		try (AVM avm = awk.createAvm(profiling)) {
 			avm.setAwkSink(sink);
 			avm.setErrorStream(err);
 			if (memoryFile != null) {
@@ -493,7 +516,36 @@ private void executeProgram(Awk awk, AwkProgram program, File memoryFile) throws
 				if (memoryFile != null) {
 					savePersistentMemory(avm, memoryFile);
 				}
+				if (profiling) {
+					printProfilingReport(avm);
+				}
+			}
+		}
+	}
+
+	private void printProfilingReport(AVM avm) {
+		if (profilingOutputFile == null) {
+			err.println();
+			avm.getProfilingReport().print(err);
+			return;
+		}
+		File parent = profilingOutputFile.getAbsoluteFile().getParentFile();
+		if (parent != null && !parent.isDirectory() && !parent.mkdirs() && !parent.isDirectory()) {
+			String message = "Failed to create directory '" + parent + "' for profiling report.";
+			throw new UncheckedIOException(message, new IOException(message));
+		}
+		try (PrintStream profileOut = new PrintStream(profilingOutputFile, "UTF-8")) {
+			avm.getProfilingReport().print(profileOut);
+			profileOut.flush();
+			if (profileOut.checkError()) {
+				throw new UncheckedIOException(
+						"Failed to write profiling report '" + profilingOutputFile + "'.",
+						new IOException("PrintStream reported an error"));
 			}
+		} catch (IOException ex) {
+			throw new UncheckedIOException(
+					"Failed to write profiling report '" + profilingOutputFile + "': " + ex.getMessage(),
+					ex);
 		}
 	}
 
@@ -571,6 +623,7 @@ private static void usage(PrintStream dest) {
 								" [--dump-syntax]" +
 								" [--dump-intermediate]" +
 								" [-s|--no-optimize]" +
+								" [--profile[=filename]]" +
 								" [--locale locale]" +
 								" [-t]" +
 								" [-l extension]..." +
@@ -605,6 +658,9 @@ private static void usage(PrintStream dest) {
 		dest.println(" --dump-syntax = Print the syntax tree.");
 		dest.println(" --dump-intermediate = Print the intermediate code.");
 		dest.println(" -s, --no-optimize = (extension) Disable optimizations during compilation.");
+		dest
+				.println(
+						" --profile[=filename] = (extension) Print tuple and function execution statistics to stderr or file.");
 		dest.println(" --locale Locale = (extension) Specify a locale to be used instead of US-English");
 		dest.println(" --list-ext = (extension) List available extensions.");
 		dest.println();
@@ -665,6 +721,9 @@ public static void main(String[] args) {
 			System.err.println("Failed to parse arguments. Please see the help/usage output (cmd line switch '-h').");
 			e.printStackTrace(System.err);
 			System.exit(1);
+		} catch (UncheckedIOException e) {
+			System.err.printf("%s: %s%n", e.getClass().getSimpleName(), e.getMessage());
+			System.exit(1);
 		} catch (Exception e) {
 			System.err.printf("%s: %s%n", e.getClass().getSimpleName(), e.getMessage());
 			System.exit(1);

src/main/java/io/jawk/SandboxedAwk.java

@@ -96,9 +96,19 @@ public AVM createAvm() {
 		return createAvm(getSettings());
 	}
 
+	@Override
+	public AVM createAvm(boolean profilingEnabled) {
+		return createAvm(getSettings(), profilingEnabled);
+	}
+
 	@Override
 	protected AVM createAvm(AwkSettings settingsParam) {
-		return new SandboxedAVM(settingsParam, getExtensionInstances());
+		return createAvm(settingsParam, false);
+	}
+
+	@Override
+	protected AVM createAvm(AwkSettings settingsParam, boolean profilingEnabled) {
+		return new SandboxedAVM(settingsParam, getExtensionInstances(), profilingEnabled);
 	}
 }
 

src/main/java/io/jawk/backend/AVM.java

@@ -133,6 +133,10 @@ private void push(Object o) {
 	}
 
 	private final AwkSettings settings;
+	private final boolean profiling;
+	private final Map<Opcode, ProfilingReport.Accumulator> tupleProfilingStats;
+	private final Map<String, ProfilingReport.Accumulator> functionProfilingStats;
+	private final Deque<ActiveFunction> activeProfilingFunctions;
 	private boolean inputSourceFilelistAssignmentsApplied;
 	private InputSource resolvedInputSource;
 	private AwkExpression installedEvalExpression;
@@ -158,9 +162,34 @@ public AVM() {
 	 */
 	public AVM(final AwkSettings parameters,
 			final Map<String, JawkExtension> extensionInstances) {
+		this(parameters, extensionInstances, false);
+	}
+
+	/**
+	 * Construct the interpreter, optionally enabling runtime profiling.
+	 *
+	 * @param parameters The parameters affecting the behavior of the
+	 *        interpreter.
+	 * @param extensionInstances Map of the extensions to load
+	 * @param profilingEnabled Whether to collect profiling statistics
+	 */
+	public AVM(
+			final AwkSettings parameters,
+			final Map<String, JawkExtension> extensionInstances,
+			final boolean profilingEnabled) {
 		this.settings = parameters != null ? parameters : AwkSettings.DEFAULT_SETTINGS;
 		this.extensionInstances = extensionInstances == null ?
 				Collections.<String, JawkExtension>emptyMap() : extensionInstances;
+		this.profiling = profilingEnabled;
+		if (profilingEnabled) {
+			this.tupleProfilingStats = new java.util.EnumMap<Opcode, ProfilingReport.Accumulator>(Opcode.class);
+			this.functionProfilingStats = new LinkedHashMap<String, ProfilingReport.Accumulator>();
+			this.activeProfilingFunctions = new ArrayDeque<ActiveFunction>();
+		} else {
+			this.tupleProfilingStats = null;
+			this.functionProfilingStats = null;
+			this.activeProfilingFunctions = null;
+		}
 
 		arguments = Collections.emptyList();
 		sortedArrayKeys = this.settings.isUseSortedArrayKeys();
@@ -975,10 +1004,14 @@ private void executeTuples(PositionTracker position)
 			IOException {
 		Map<Integer, ConditionPair> conditionPairs = null;
 		Opcode opcode = null;
+		long tupleStartNanos = 0L;
 		try {
 			while (!position.isEOF()) {
 				// System_out.println("--> "+position);
 				opcode = position.opcode();
+				if (profiling) {
+					tupleStartNanos = beforeProfiledTuple(position, opcode);
+				}
 				// switch on OPCODE
 				switch (opcode) {
 				case PRINT: {
@@ -2217,7 +2250,8 @@ private void executeTuples(PositionTracker position)
 					if (!position.classArg().isInstance(o)) {
 						throw new AwkRuntimeException(
 								position.lineNumber(),
-								"Verification failed. Top-of-stack = " + o.getClass() + " isn't an instance of " + position.classArg());
+								"Verification failed. Top-of-stack = " + o.getClass() + " isn't an instance of "
+										+ position.classArg());
 					}
 					push(o);
 					position.next();
@@ -2811,8 +2845,16 @@ private void executeTuples(PositionTracker position)
 				default:
 					throw new Error("invalid opcode: " + position.opcode());
 				}
+				if (profiling) {
+					afterProfiledTuple(opcode, tupleStartNanos);
+				}
 			}
 
+		} catch (ExitException ee) {
+			if (profiling && (opcode == Opcode.EXIT_WITH_CODE || opcode == Opcode.EXIT_WITHOUT_CODE)) {
+				afterProfiledTuple(opcode, tupleStartNanos);
+			}
+			throw ee;
 		} catch (IOException ioe) {
 			// clear runtime stack
 			runtimeStack.popAllFrames();
@@ -2842,6 +2884,86 @@ private void executeTuples(PositionTracker position)
 		}
 	}
 
+	/**
+	 * Clears all collected profiling statistics.
+	 */
+	public void resetProfiling() {
+		if (!profiling) {
+			return;
+		}
+		tupleProfilingStats.clear();
+		functionProfilingStats.clear();
+		activeProfilingFunctions.clear();
+	}
+
+	/**
+	 * Returns an immutable snapshot of the collected profiling statistics.
+	 *
+	 * @return profiling report snapshot
+	 */
+	public ProfilingReport getProfilingReport() {
+		if (!profiling) {
+			return ProfilingReport.empty();
+		}
+		return new ProfilingReport(tupleProfilingStats, functionProfilingStats);
+	}
+
+	private long beforeProfiledTuple(PositionTracker position, Opcode opcode) {
+		long now = System.nanoTime();
+		if (opcode == Opcode.CALL_FUNCTION) {
+			activeProfilingFunctions.push(new ActiveFunction(position.stringArg(1), now));
+		} else if (opcode == Opcode.EXTENSION) {
+			ExtensionFunction function = position.extensionFunctionArg();
+			activeProfilingFunctions.push(new ActiveFunction(function.getKeyword(), now));
+		}
+		return now;
+	}
+
+	private void afterProfiledTuple(Opcode opcode, long tupleStartNanos) {
+		long now = System.nanoTime();
+		statisticsFor(tupleProfilingStats, opcode).add(now - tupleStartNanos);
+		if (opcode == Opcode.EXIT_WITH_CODE || opcode == Opcode.EXIT_WITHOUT_CODE) {
+			recordAllFunctionExits(now);
+		} else if (opcode == Opcode.EXTENSION || opcode == Opcode.RETURN_FROM_FUNCTION) {
+			recordFunctionExit(now);
+		}
+	}
+
+	private static <K> ProfilingReport.Accumulator statisticsFor(
+			Map<K, ProfilingReport.Accumulator> stats,
+			K key) {
+		ProfilingReport.Accumulator accumulator = stats.get(key);
+		if (accumulator == null) {
+			accumulator = new ProfilingReport.Accumulator();
+			stats.put(key, accumulator);
+		}
+		return accumulator;
+	}
+
+	private void recordFunctionExit(long now) {
+		if (activeProfilingFunctions.isEmpty()) {
+			return;
+		}
+		ActiveFunction function = activeProfilingFunctions.pop();
+		statisticsFor(functionProfilingStats, function.name).add(now - function.startNanos);
+	}
+
+	private void recordAllFunctionExits(long now) {
+		while (!activeProfilingFunctions.isEmpty()) {
+			recordFunctionExit(now);
+		}
+	}
+
+	private static final class ActiveFunction {
+		private final String name;
+		private final long startNanos;
+
+		private ActiveFunction(String name, long startNanos) {
+			this.name = name;
+			this.startNanos = startNanos;
+		}
+	}
+
 	/**
 	 * Releases any prepared input source and runtime I/O resources owned by this
 	 * AVM.