From e8bce00b04be4526113ca64dcaf73ca8611ba5d1 Mon Sep 17 00:00:00 2001
From: Sam Reid <reids@colorado.edu>
Date: Mon, 17 Oct 2022 11:01:20 -0600
Subject: [PATCH] Add phetTimingLog, see
 https://github.com/phetsims/chipper/issues/1342

---
 .gitignore                 |   3 +-
 js/common/phetTimingLog.js | 115 +++++++++++++++++++++++++++++++++++++
 2 files changed, 117 insertions(+), 1 deletion(-)
 create mode 100644 js/common/phetTimingLog.js

diff --git a/.gitignore b/.gitignore
index 0bebc2cd..7846f8cb 100644
--- a/.gitignore
+++ b/.gitignore
@@ -10,4 +10,5 @@ node_modules/
 build-server.log
 lintreport.txt
 js/build-server/tmp*
-.maintenance.json
\ No newline at end of file
+.maintenance.json
+logs/
\ No newline at end of file
diff --git a/js/common/phetTimingLog.js b/js/common/phetTimingLog.js
new file mode 100644
index 00000000..09d29e1e
--- /dev/null
+++ b/js/common/phetTimingLog.js
@@ -0,0 +1,115 @@
+// Copyright 2022, University of Colorado Boulder
+
+/**
+ * Outputs timing information for nested structured tasks, so they can be inspected to understand what is
+ * taking so long. This is optimized for human-readability. Use an XML-like syntax for structuring, though the overall
+ * format is not xml since there are multiple root elements.  Output timing information in a comment after a closing tag.
+ * Sessions are delimited by a blank line. Un-truncated sessions are XML parseable, but the timing data is in the comments
+ * so naive XML parsing won't help in analysis.
+ *
+ * - Data is streamed as it is generated, and hence may be incomplete if a process is interrupted.
+ * - This is coded in perennial so it can be used in chipper tasks (via perennial-alias) and also for perennial tasks as needed.
+ * - Assumes single-threaded access to the interface
+ *
+ * You can watch the results stream out live, and get a good sense of where the time is being spent by running
+ * tail -f /path/to/perennial-alias/logs/phet-timing-log.txt
+ *
+ * This task is to help identify bottlenecks and cross-platform differences. It is not intended to account for
+ * every millisecond in self-time.
+ *
+ * The log file is dedicated to timing information and structuring of tasks, and we should not add supplemental metadata
+ * such as messages or results from tasks.
+ *
+ * Assumes that task structuring is all done in one frame--not possible to start an event in one animation frame
+ * and end it in another.
+ *
+ * @author Sam Reid (PhET Interactive Simulations)
+ */
+
+const path = require( 'path' );
+const fs = require( 'fs' );
+const assert = require( 'assert' );
+
+const logDir = path.resolve( __dirname, '../../logs' );
+try {
+  fs.mkdirSync( logDir );
+}
+catch( e ) {
+  // already exists
+}
+
+// Log to perennial-alias if running a perennial-alias task, or perennial if running a perennial task.
+const logPath = path.resolve( logDir, 'phet-timing-log.txt' );
+
+// Create file if it doesn't exist, and append to it
+const stream = fs.createWriteStream( logPath, { flags: 'a' } );
+
+// Depth of nesting.  -1 means not yet started.  0 means top-level.
+let depth = -1;
+
+const indent = depth => '  '.repeat( depth );
+
+const push = taskName => {
+  depth++;
+
+  assert( !taskName.includes( ':' ), 'task name cannot include :, it was ' + taskName );
+  if ( depth === 0 ) {
+    const time = new Date().toLocaleString( 'en-US', { timeZone: 'America/Denver' } );
+    stream.write( `<!-- ${time} -->\n` );
+  }
+  stream.write( `${indent( depth )}<${taskName}>\n` );
+
+  const startTime = Date.now();
+  return startTime;
+};
+
+const pop = ( taskName, startTime ) => {
+  const endTime = Date.now();
+
+  stream.write( `${indent( depth )}</${taskName}> <!-- ${endTime - startTime}ms -->\n` );
+
+  if ( depth === 0 ) {
+    stream.write( '\n' );
+  }
+
+  depth--;
+};
+
+const phetTimingLog = {
+
+  /**
+   * Invoke the task and return the return value of the task.
+   * @param {string} taskName
+   * @param {()=>T} task
+   * @returns {T}
+   */
+  start( taskName, task ) {
+    const startTime = push( taskName );
+    const result = task();
+    pop( taskName, startTime );
+    return result;
+  },
+
+  /**
+   * Invoke the task and return the return value of the task.
+   * @param {string} taskName
+   * @param {()=>Promise<T>} task
+   * @returns {Promise<T>}
+   */
+  async startAsync( taskName, task ) {
+    const startTime = push( taskName );
+    const result = await task();
+    pop( taskName, startTime );
+    return result;
+  },
+
+  /**
+   * Flush the write stream before exiting node.
+   * @param {()=>void} [callback]
+   */
+  close( callback = () => {} ) {
+    stream.close( callback );
+  }
+};
+
+module.exports = phetTimingLog;
\ No newline at end of file