search

phetsims / chipper

Tools for developing and building PhET interactive simulations.
http://scenerystack.org/
MIT License
11 stars 14 forks source link

pre-commit-hooks should keep a log for diagnostics #1342

Closed zepumph closed 1 year ago

zepumph commented 2 years ago

From https://github.com/phetsims/chipper/issues/1325 today, we should investigate logging output from pre-commit hooks to help us analyze timing and problems, and to make improvements. Assigning @samreid and ME.

jessegreenberg commented 2 years ago

So far I have been logging my pre-commit-hooks output by saving the output in my bash alias for it.

alias pch="( cd ~/Documents/Development/phetsims && (node.exe chipper/js/scripts/precommit-hook-multi.js)) 2>&1 | tee -a ~/pch-times.txt"

samreid commented 2 years ago

Let's also add output from other parts of the tooling, so we can track how long builds are taking, etc.

If we go with plaintext, it could look like:

# precommit hooks 10-13-2022 9:43am
  - lint 23s CACHE MISS
  - type check 1s CACHE HIT
  - phet-io API check 15s CACHE MISS
# build gravity-and-orbits --brands=phet,phet-io 10-13-2022 9:43am
  - lint 1s CACHE HIT
  - type check 12s CACHE MISS
  - phet brand output 22s
  - phet-io brand output 24s

If we want JSON, it could look like:

[{
  "taskname": "precommit-hooks",
  "startTime": "Oct 13, 2022 9am",
  "subtasks": {
    "lint": { "time": 23, "cacheHit": false },
    "type check": { "time": 23, "cacheHit": false }
  }
}]

Or we would probably want subtasks in an array

[{
  "taskname": "precommit-hooks",
  "startTime": "Oct 13, 2022 9am",
  "subtasks": [
    {"taskname":"lint", "time": 23, "cacheHit": false },
    {"taskname":"type check", "time": 23, "cacheHit": false }
  ]
},
  {
    "taskname": "build gravity-and-orbits --brands=phet,phet-io",
    "startTime": "Oct 13, 2022 9am",
    "subtasks": [
      {"taskname":"lint", "time": 23, "cacheHit": false },
      {"taskname":"type check", "time": 23, "cacheHit": false },
      {"taskname":"phet brand output", "time": 23, "cacheHit": false },
      {"taskname":"phet-io brand output", "time": 23, "cacheHit": false },
    ]
  }
]

Plain text sounds easier to stream to it and more human-readable, but JSON sounds more machine readable-friendly. Not clear what's more important here, but I'm thinking we should probably start with JSON for ease of parsing and generating.

samreid commented 2 years ago

We should also consider how we want to look at these logs. Is it more like:

or

Summarizing questions: How do we use/aggregate/report the data? Should this be "always on", or "opt in"? Where should the log output? Syntax/format for output? Should we support infinitely nested sub-tasks?

samreid commented 2 years ago

I'm planning to work on this issue today

samreid commented 2 years ago

@jessegreenberg said on slack:

That is kind of what I was thinking [focus on human readability]. From a file like that it would be easy enough to sum/average times. I am fine with always on. Maybe save to chipper/data? Infinitely nested sub-tasks sounds more complicated but might help optimize if we decide that is necessary.

samreid commented 2 years ago

Some more considerations for this log:

Current patch:

```diff Index: main/perennial-alias/.gitignore IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/.gitignore b/main/perennial-alias/.gitignore --- a/main/perennial-alias/.gitignore (revision 566de03f8a9a187aa817deebd8b60f38b139fd49) +++ b/main/perennial-alias/.gitignore (date 1665784138073) @@ -10,4 +10,5 @@ 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 Index: main/perennial-alias/js/common/phetTimingLog.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/js/common/phetTimingLog.js b/main/perennial-alias/js/common/phetTimingLog.js new file mode 100644 --- /dev/null (date 1665793116519) +++ b/main/perennial-alias/js/common/phetTimingLog.js (date 1665793116519) @@ -0,0 +1,99 @@ +// Copyright 2022, University of Colorado Boulder + +const path = require( 'path' ); +const fs = require( 'fs' ); +const assert = require( 'assert' ); + +// Log to perennial-alias if running a perennial-alias task, or perennial if running a perennial task. +const logPath = path.resolve( __dirname, '../../logs/phet-timing-log.txt' ); + +// Create file if it doesn't exist, and append to it +const stream = fs.createWriteStream( logPath, { flags: 'a' } ); + +/** + * + * @author Sam Reid (PhET Interactive Simulations) + */ +// const depth = 0; +let currentTask = null; + +const visit = ( task, nestingString = '' ) => { + console.log( nestingString + task.taskName + ': ' + ( task.endTime - task.startTime ) + ( task.message || '' ) ); + stream.write( nestingString + task.taskName + ': ' + ( task.endTime - task.startTime ) + + ( task.message || '' ) + + '\n' ); + + task.subtasks.forEach( subtask => visit( subtask, nestingString + ' ' ) ); + if ( nestingString === '' ) { + console.log(); + stream.write( '\n' ); + } +}; + +const phetTimingLog = { + async startAsync( taskName, task ) { + + assert( !taskName.includes( ':' ), 'task name cannot include :, it was ' + taskName ); + + if ( currentTask === null ) { + currentTask = { + taskName: taskName, + startTime: Date.now(), + subtasks: [], + parentTask: null + }; + } + else { + + const childTask = { + taskName: taskName, + startTime: Date.now(), + subtasks: [], + parentTask: currentTask + }; + currentTask.subtasks.push( childTask ); + currentTask = childTask; + } + // const startTime = Date.now(); + // // writeStream.write( taskName + ': ' ); + // // const nesting = pathArray.map( element => ' ' ); + // let prefix = ''; + // for ( let i = 0; i < depth; i++ ) { + // prefix = prefix + ' '; + // } + // const prefix = nesting.join( '' ); + + // console.log( prefix + taskName + ': ' ); + // writest.write( prefix + taskName + ': \n' ); + + // pathArray.push( { + // taskName: taskName, + // startTime: Date.now() + // } ); + const message = await task(); + + currentTask.message = message || null; + currentTask.endTime = Date.now(); + + if ( currentTask.parentTask === null ) { + // print out the tree and null out the task + // console.log( 'done' ); + visit( currentTask ); + } + else { + // console.log( 'pop' ); + currentTask = currentTask.parentTask; + } + + // const entry = pathArray.pop(); + // const correspondingTime = startTimes.pop(); + // const elapsed = Date.now() - startTime; + // + // // console.log( prefix + taskName + ': ' + elapsed ); + // writest.write( prefix + taskName + ': ' + elapsed + '\n' ); + // + // depth--; + } +}; + +module.exports = phetTimingLog; \ No newline at end of file Index: main/chipper/js/scripts/hook-pre-commit.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/chipper/js/scripts/hook-pre-commit.js b/main/chipper/js/scripts/hook-pre-commit.js --- a/main/chipper/js/scripts/hook-pre-commit.js (revision e27c7f4e72cc4b0a3e1a57bdc32b83f677438aa2) +++ b/main/chipper/js/scripts/hook-pre-commit.js (date 1665793188204) @@ -26,167 +26,185 @@ const generatePhetioMacroAPI = require( '../phet-io/generatePhetioMacroAPI' ); const CacheLayer = require( '../../../chipper/js/common/CacheLayer' ); const phetioCompareAPISets = require( '../phet-io/phetioCompareAPISets' ); +const phetTimingLog = require( '../../../perennial-alias/js/common/phetTimingLog' ); ( async () => { + await phetTimingLog.startAsync( 'hook-pre-commit', ( async () => { // Identify the current repo - const repo = process.cwd().split( path.sep ).pop(); + const repo = process.cwd().split( path.sep ).pop(); // Console logging via --console - const commandLineArguments = process.argv.slice( 2 ); - const outputToConsole = commandLineArguments.includes( '--console' ); + const commandLineArguments = process.argv.slice( 2 ); + const outputToConsole = commandLineArguments.includes( '--console' ); // Run lint tests if they exist in the checked-out SHAs. - try { - const lint = require( '../../../chipper/js/grunt/lint' ); - if ( lint.chipperAPIVersion === 'promisesPerRepo1' ) { + try { + await phetTimingLog.startAsync( 'lint', async () => { + const lint = require( '../../../chipper/js/grunt/lint' ); + if ( lint.chipperAPIVersion === 'promisesPerRepo1' ) { - // lint() automatically filters out non-lintable repos - const lintReturnValue = await lint( [ repo ] ); + // lint() automatically filters out non-lintable repos + const lintReturnValue = await lint( [ repo ] ); - if ( !lintReturnValue.ok ) { - process.exit( 1 ); - } + if ( !lintReturnValue.ok ) { + process.exit( 1 ); + } - outputToConsole && console.log( `Linting passed with results.length: ${lintReturnValue.results.length}` ); - } - else { - console.log( 'chipper/js/grunt/lint not compatible' ); - } - } - catch( e ) { - console.log( 'chipper/js/grunt/lint not found' ); - } + outputToConsole && console.log( `Linting passed with results.length: ${lintReturnValue.results.length}` ); + } + else { + console.log( 'chipper/js/grunt/lint not compatible' ); + } + } ); + } + catch( e ) { + console.log( 'chipper/js/grunt/lint not found' ); + } + await phetTimingLog.startAsync( 'report-media', async () => { + // These sims don't have package.json or media that requires checking. - const optOutOfReportMedia = [ - 'decaf', - 'phet-android-app', - 'babel', - 'phet-info', - 'phet-ios-app', - 'sherpa', - 'smithers', - 'tasks', - 'weddell' - ]; + const optOutOfReportMedia = [ + 'decaf', + 'phet-android-app', + 'babel', + 'phet-info', + 'phet-ios-app', + 'sherpa', + 'smithers', + 'tasks', + 'weddell' + ]; // Make sure license.json for images/audio is up-to-date - if ( !optOutOfReportMedia.includes( repo ) ) { - try { - const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); + if ( !optOutOfReportMedia.includes( repo ) ) { + try { + const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); - const success = await reportMedia( repo ); + const success = await reportMedia( repo ); - // At the moment reportMedia uses grunt.fail, but we defensively use the return value here in case that changes. - if ( !success ) { - process.exit( 1 ); - } - } - catch( e ) { - console.log( 'chipper/js/grunt/reportMedia not found' ); - } - } + // At the moment reportMedia uses grunt.fail, but we defensively use the return value here in case that changes. + if ( !success ) { + process.exit( 1 ); + } + } + catch( e ) { + console.log( 'chipper/js/grunt/reportMedia not found' ); + } + } + } ); + + await phetTimingLog.startAsync( 'tsc', async () => { - // Run typescript type checker if it exists in the checked-out shas - const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { - errors: 'resolve' - } ); + // Run typescript type checker if it exists in the checked-out shas + const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { + errors: 'resolve' + } ); - results.stderr.trim().length > 0 && console.log( results.stderr ); - results.stdout.trim().length > 0 && console.log( results.stdout ); + results.stderr.trim().length > 0 && console.log( results.stderr ); + results.stdout.trim().length > 0 && console.log( results.stdout ); - if ( results.code === 0 ) { - outputToConsole && console.log( 'tsc passed' ); - } - else { - console.log( results ); - process.exit( results.code ); - } + await phetTimingLog.startAsync( 'tsc fake subtask', async () => { + await new Promise( resolve => setTimeout( resolve, 1000 ) ); + } ); + + if ( results.code === 0 ) { + outputToConsole && console.log( 'tsc passed' ); + } + else { + console.log( results ); + process.exit( results.code ); + } + } ); + + await phetTimingLog.startAsync( 'qunit', async () => { // Run qunit tests if puppeteerQUnit exists in the checked-out SHAs and a test HTML exists. - try { - const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); - const cacheKey = `puppeteerQUnit#${repo}`; + try { + const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); + const cacheKey = `puppeteerQUnit#${repo}`; - if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those - const testFilePath = `${repo}/${repo}-tests.html`; - const exists = fs.existsSync( `../${testFilePath}` ); - if ( exists ) { + if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those + const testFilePath = `${repo}/${repo}-tests.html`; + const exists = fs.existsSync( `../${testFilePath}` ); + if ( exists ) { - if ( CacheLayer.isCacheSafe( cacheKey ) ) { - console.log( 'unit tests success cached' ); - } - else { - const browser = await puppeteer.launch(); + if ( CacheLayer.isCacheSafe( cacheKey ) ) { + console.log( 'unit tests success cached' ); + } + else { + const browser = await puppeteer.launch(); - const result = await withServer( async port => { - return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); - } ); + const result = await withServer( async port => { + return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); + } ); - await browser.close(); + await browser.close(); - outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); - if ( !result.ok ) { - console.error( `unit tests failed in ${repo}`, result ); - process.exit( 1 ); // fail as soon as there is one problem - } - else { - CacheLayer.onSuccess( cacheKey ); - } - } - } + outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); + if ( !result.ok ) { + console.error( `unit tests failed in ${repo}`, result ); + process.exit( 1 ); // fail as soon as there is one problem + } + else { + CacheLayer.onSuccess( cacheKey ); + } + } + } - outputToConsole && console.log( 'QUnit: no problems detected' ); - } - } - catch( e ) { - console.log( e ); - } + outputToConsole && console.log( 'QUnit: no problems detected' ); + } + } + catch( e ) { + console.log( e ); + } + } ); - //////////////////////////////////////////////////////////////////////////////// - // Compare PhET-iO APIs for this repo and anything that has it as a dependency - // - ( async () => { + //////////////////////////////////////////////////////////////////////////////// + // Compare PhET-iO APIs for this repo and anything that has it as a dependency + // + await phetTimingLog.startAsync( 'phet-io-api-compare', async () => { - // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test - // every phet-io stable sim. - const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); + // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test + // every phet-io stable sim. + const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); - const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); + const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); - if ( reposToTest.length > 0 ) { - console.log( 'PhET-iO API testing: ' + reposToTest ); + if ( reposToTest.length > 0 ) { + console.log( 'PhET-iO API testing: ' + reposToTest ); - const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); + const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); - if ( !CacheLayer.isCacheSafe( cacheKey ) ) { + if ( !CacheLayer.isCacheSafe( cacheKey ) ) { - const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { - showProgressBar: reposToTest.length > 1, - showMessagesFromSim: false - } ); + const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { + showProgressBar: reposToTest.length > 1, + showMessagesFromSim: false + } ); - const compareSuccess = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); + const compareSuccess = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); - if ( compareSuccess ) { + if ( compareSuccess ) { - CacheLayer.onSuccess( cacheKey ); + CacheLayer.onSuccess( cacheKey ); - // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here - process.exit( 0 ); - } - else { - process.exit( 1 ); - } - } - } - else { - console.log( 'PhET-iO API testing: no repos detected' ); - } + // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here + setTimeout( () => process.exit( 0 ), 0 ); + } + else { + process.exit( 1 ); + } + } + } + else { + console.log( 'PhET-iO API testing: no repos detected' ); + } - } )(); + } ); - // NOTE: if adding or rearranging rules, be careful about the early exit above + // NOTE: if adding or rearranging rules, be careful about the early exit above + } ) ); } )(); \ No newline at end of file ```
samreid commented 2 years ago

Here's an improved patch:

```diff Index: main/perennial-alias/.gitignore IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/.gitignore b/main/perennial-alias/.gitignore --- a/main/perennial-alias/.gitignore (revision 566de03f8a9a187aa817deebd8b60f38b139fd49) +++ b/main/perennial-alias/.gitignore (date 1665784138073) @@ -10,4 +10,5 @@ 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 Index: main/perennial-alias/js/common/phetTimingLog.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/js/common/phetTimingLog.js b/main/perennial-alias/js/common/phetTimingLog.js new file mode 100644 --- /dev/null (date 1665855237015) +++ b/main/perennial-alias/js/common/phetTimingLog.js (date 1665855237015) @@ -0,0 +1,72 @@ +// Copyright 2022, University of Colorado Boulder + +const path = require( 'path' ); +const fs = require( 'fs' ); +const assert = require( 'assert' ); + +// Log to perennial-alias if running a perennial-alias task, or perennial if running a perennial task. +const logPath = path.resolve( __dirname, '../../logs/phet-timing-log.txt' ); + +// Create file if it doesn't exist, and append to it +const stream = fs.createWriteStream( logPath, { flags: 'a' } ); + +/** + * + * @author Sam Reid (PhET Interactive Simulations) + */ +let currentTask = null; + +const visit = ( task, nestingString = '' ) => { + console.log( nestingString + task.taskName + ': ' + ( task.endTime - task.startTime ) + ( task.message || '' ) ); + stream.write( nestingString + task.taskName + ': ' + ( task.endTime - task.startTime ) + + ( task.message || '' ) + + '\n' ); + + task.subtasks.forEach( subtask => visit( subtask, nestingString + ' ' ) ); + if ( nestingString === '' ) { + console.log(); + stream.write( '\n' ); + } +}; + +const phetTimingLog = { + async startAsync( taskName, task ) { + + assert( !taskName.includes( ':' ), 'task name cannot include :, it was ' + taskName ); + + if ( currentTask === null ) { + currentTask = { + taskName: taskName, + startTime: Date.now(), + subtasks: [], + parentTask: null + }; + } + else { + + const childTask = { + taskName: taskName, + startTime: Date.now(), + subtasks: [], + parentTask: currentTask + }; + currentTask.subtasks.push( childTask ); + currentTask = childTask; + } + const message = await task(); + + currentTask.message = message || null; + currentTask.endTime = Date.now(); + + if ( currentTask.parentTask === null ) { + + // print out the tree and null out the task to get ready for a new top-level task + visit( currentTask ); + } + else { + currentTask = currentTask.parentTask; + } + } +}; + +module.exports = phetTimingLog; \ No newline at end of file Index: main/chipper/js/scripts/hook-pre-commit.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/chipper/js/scripts/hook-pre-commit.js b/main/chipper/js/scripts/hook-pre-commit.js --- a/main/chipper/js/scripts/hook-pre-commit.js (revision e27c7f4e72cc4b0a3e1a57bdc32b83f677438aa2) +++ b/main/chipper/js/scripts/hook-pre-commit.js (date 1665793188204) @@ -26,167 +26,185 @@ const generatePhetioMacroAPI = require( '../phet-io/generatePhetioMacroAPI' ); const CacheLayer = require( '../../../chipper/js/common/CacheLayer' ); const phetioCompareAPISets = require( '../phet-io/phetioCompareAPISets' ); +const phetTimingLog = require( '../../../perennial-alias/js/common/phetTimingLog' ); ( async () => { + await phetTimingLog.startAsync( 'hook-pre-commit', ( async () => { // Identify the current repo - const repo = process.cwd().split( path.sep ).pop(); + const repo = process.cwd().split( path.sep ).pop(); // Console logging via --console - const commandLineArguments = process.argv.slice( 2 ); - const outputToConsole = commandLineArguments.includes( '--console' ); + const commandLineArguments = process.argv.slice( 2 ); + const outputToConsole = commandLineArguments.includes( '--console' ); // Run lint tests if they exist in the checked-out SHAs. - try { - const lint = require( '../../../chipper/js/grunt/lint' ); - if ( lint.chipperAPIVersion === 'promisesPerRepo1' ) { + try { + await phetTimingLog.startAsync( 'lint', async () => { + const lint = require( '../../../chipper/js/grunt/lint' ); + if ( lint.chipperAPIVersion === 'promisesPerRepo1' ) { - // lint() automatically filters out non-lintable repos - const lintReturnValue = await lint( [ repo ] ); + // lint() automatically filters out non-lintable repos + const lintReturnValue = await lint( [ repo ] ); - if ( !lintReturnValue.ok ) { - process.exit( 1 ); - } + if ( !lintReturnValue.ok ) { + process.exit( 1 ); + } - outputToConsole && console.log( `Linting passed with results.length: ${lintReturnValue.results.length}` ); - } - else { - console.log( 'chipper/js/grunt/lint not compatible' ); - } - } - catch( e ) { - console.log( 'chipper/js/grunt/lint not found' ); - } + outputToConsole && console.log( `Linting passed with results.length: ${lintReturnValue.results.length}` ); + } + else { + console.log( 'chipper/js/grunt/lint not compatible' ); + } + } ); + } + catch( e ) { + console.log( 'chipper/js/grunt/lint not found' ); + } + await phetTimingLog.startAsync( 'report-media', async () => { + // These sims don't have package.json or media that requires checking. - const optOutOfReportMedia = [ - 'decaf', - 'phet-android-app', - 'babel', - 'phet-info', - 'phet-ios-app', - 'sherpa', - 'smithers', - 'tasks', - 'weddell' - ]; + const optOutOfReportMedia = [ + 'decaf', + 'phet-android-app', + 'babel', + 'phet-info', + 'phet-ios-app', + 'sherpa', + 'smithers', + 'tasks', + 'weddell' + ]; // Make sure license.json for images/audio is up-to-date - if ( !optOutOfReportMedia.includes( repo ) ) { - try { - const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); + if ( !optOutOfReportMedia.includes( repo ) ) { + try { + const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); - const success = await reportMedia( repo ); + const success = await reportMedia( repo ); - // At the moment reportMedia uses grunt.fail, but we defensively use the return value here in case that changes. - if ( !success ) { - process.exit( 1 ); - } - } - catch( e ) { - console.log( 'chipper/js/grunt/reportMedia not found' ); - } - } + // At the moment reportMedia uses grunt.fail, but we defensively use the return value here in case that changes. + if ( !success ) { + process.exit( 1 ); + } + } + catch( e ) { + console.log( 'chipper/js/grunt/reportMedia not found' ); + } + } + } ); + + await phetTimingLog.startAsync( 'tsc', async () => { - // Run typescript type checker if it exists in the checked-out shas - const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { - errors: 'resolve' - } ); + // Run typescript type checker if it exists in the checked-out shas + const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { + errors: 'resolve' + } ); - results.stderr.trim().length > 0 && console.log( results.stderr ); - results.stdout.trim().length > 0 && console.log( results.stdout ); + results.stderr.trim().length > 0 && console.log( results.stderr ); + results.stdout.trim().length > 0 && console.log( results.stdout ); - if ( results.code === 0 ) { - outputToConsole && console.log( 'tsc passed' ); - } - else { - console.log( results ); - process.exit( results.code ); - } + await phetTimingLog.startAsync( 'tsc fake subtask', async () => { + await new Promise( resolve => setTimeout( resolve, 1000 ) ); + } ); + + if ( results.code === 0 ) { + outputToConsole && console.log( 'tsc passed' ); + } + else { + console.log( results ); + process.exit( results.code ); + } + } ); + + await phetTimingLog.startAsync( 'qunit', async () => { // Run qunit tests if puppeteerQUnit exists in the checked-out SHAs and a test HTML exists. - try { - const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); - const cacheKey = `puppeteerQUnit#${repo}`; + try { + const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); + const cacheKey = `puppeteerQUnit#${repo}`; - if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those - const testFilePath = `${repo}/${repo}-tests.html`; - const exists = fs.existsSync( `../${testFilePath}` ); - if ( exists ) { + if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those + const testFilePath = `${repo}/${repo}-tests.html`; + const exists = fs.existsSync( `../${testFilePath}` ); + if ( exists ) { - if ( CacheLayer.isCacheSafe( cacheKey ) ) { - console.log( 'unit tests success cached' ); - } - else { - const browser = await puppeteer.launch(); + if ( CacheLayer.isCacheSafe( cacheKey ) ) { + console.log( 'unit tests success cached' ); + } + else { + const browser = await puppeteer.launch(); - const result = await withServer( async port => { - return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); - } ); + const result = await withServer( async port => { + return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); + } ); - await browser.close(); + await browser.close(); - outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); - if ( !result.ok ) { - console.error( `unit tests failed in ${repo}`, result ); - process.exit( 1 ); // fail as soon as there is one problem - } - else { - CacheLayer.onSuccess( cacheKey ); - } - } - } + outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); + if ( !result.ok ) { + console.error( `unit tests failed in ${repo}`, result ); + process.exit( 1 ); // fail as soon as there is one problem + } + else { + CacheLayer.onSuccess( cacheKey ); + } + } + } - outputToConsole && console.log( 'QUnit: no problems detected' ); - } - } - catch( e ) { - console.log( e ); - } + outputToConsole && console.log( 'QUnit: no problems detected' ); + } + } + catch( e ) { + console.log( e ); + } + } ); - //////////////////////////////////////////////////////////////////////////////// - // Compare PhET-iO APIs for this repo and anything that has it as a dependency - // - ( async () => { + //////////////////////////////////////////////////////////////////////////////// + // Compare PhET-iO APIs for this repo and anything that has it as a dependency + // + await phetTimingLog.startAsync( 'phet-io-api-compare', async () => { - // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test - // every phet-io stable sim. - const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); + // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test + // every phet-io stable sim. + const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); - const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); + const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); - if ( reposToTest.length > 0 ) { - console.log( 'PhET-iO API testing: ' + reposToTest ); + if ( reposToTest.length > 0 ) { + console.log( 'PhET-iO API testing: ' + reposToTest ); - const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); + const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); - if ( !CacheLayer.isCacheSafe( cacheKey ) ) { + if ( !CacheLayer.isCacheSafe( cacheKey ) ) { - const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { - showProgressBar: reposToTest.length > 1, - showMessagesFromSim: false - } ); + const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { + showProgressBar: reposToTest.length > 1, + showMessagesFromSim: false + } ); - const compareSuccess = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); + const compareSuccess = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); - if ( compareSuccess ) { + if ( compareSuccess ) { - CacheLayer.onSuccess( cacheKey ); + CacheLayer.onSuccess( cacheKey ); - // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here - process.exit( 0 ); - } - else { - process.exit( 1 ); - } - } - } - else { - console.log( 'PhET-iO API testing: no repos detected' ); - } + // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here + setTimeout( () => process.exit( 0 ), 0 ); + } + else { + process.exit( 1 ); + } + } + } + else { + console.log( 'PhET-iO API testing: no repos detected' ); + } - } )(); + } ); - // NOTE: if adding or rearranging rules, be careful about the early exit above + // NOTE: if adding or rearranging rules, be careful about the early exit above + } ) ); } )(); \ No newline at end of file ```

However, this strategy is incompatible with early exit (like process.exit) or even throwing errors, so we may need a different strategy. Or maybe try/catch the task?

Just jotting down an output style that can be streamed out, so would support early exiting and could also be used to see "what's happening currently" in a long process.

<hook-pre-commit>
  <lint></lint>: 644 
  <report-media></report-media>: 12 
  <tsc>
    <tsc fake subtask></tsc fake subtask>: 1002
  </tsc>: 123
  <qunit></qunit>: 4
  <phet-io-api-compare></phet-io-api-compare>: 13
</hook-pre-commit>: 6523

Or

<hook-pre-commit>
  <lint/>: 644
  <report-media/>: 12
  <tsc>
    <tsc fake subtask/>: 1002
  </tsc>: 123
  <qunit/>: 4
  <phet-io-api-compare/>: 13
</hook-pre-commit>: 6523

Here's an XML version:

<hook-pre-commit>
    <lint/> <!-- 644ms -->
    <report-media/> <!-- 12ms -->
    <tsc>
        <tsc-fake-subtask/> <!-- 1002ms -->
    </tsc> <!-- 123ms -->
    <qunit/> <!-- 4ms -->
    <phet-io-api-compare/> <!-- 13ms -->
</hook-pre-commit> <!-- 6523ms -->
samreid commented 2 years ago

Current status:

```diff Index: main/chipper/js/grunt/Gruntfile.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/chipper/js/grunt/Gruntfile.js b/main/chipper/js/grunt/Gruntfile.js --- a/main/chipper/js/grunt/Gruntfile.js (revision e27c7f4e72cc4b0a3e1a57bdc32b83f677438aa2) +++ b/main/chipper/js/grunt/Gruntfile.js (date 1665896682571) @@ -217,76 +217,88 @@ const path = require( 'path' ); const fs = require( 'fs' ); const getPhetLibs = require( './getPhetLibs' ); + const phetTimingLog = require( '../../../perennial-alias/js/common/phetTimingLog' ); + + await phetTimingLog.startAsync( 'grunt-build', async () => { - // Parse minification keys - const minifyKeys = Object.keys( minify.MINIFY_DEFAULTS ); - const minifyOptions = {}; - minifyKeys.forEach( minifyKey => { - const option = grunt.option( `minify.${minifyKey}` ); - if ( option === true || option === false ) { - minifyOptions[ minifyKey ] = option; - } - } ); + // Parse minification keys + const minifyKeys = Object.keys( minify.MINIFY_DEFAULTS ); + const minifyOptions = {}; + minifyKeys.forEach( minifyKey => { + const option = grunt.option( `minify.${minifyKey}` ); + if ( option === true || option === false ) { + minifyOptions[ minifyKey ] = option; + } + } ); - // grunt options that apply to multiple build tasks - const instrument = !!grunt.option( 'instrument' ); + // grunt options that apply to multiple build tasks + const instrument = !!grunt.option( 'instrument' ); - // Do not uglify or transpile if it is being instrumented, so it will match development code as closely as possible - if ( instrument ) { - minifyOptions.babelTranspile = false; - minifyOptions.uglify = false; - } + // Do not uglify or transpile if it is being instrumented, so it will match development code as closely as possible + if ( instrument ) { + minifyOptions.babelTranspile = false; + minifyOptions.uglify = false; + } - const repoPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); + const repoPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); - // Run the type checker first. - const brands = getBrands( grunt, repo, buildLocal ); + // Run the type checker first. + const brands = getBrands( grunt, repo, buildLocal ); - // We must have phet-io code checked out to type check, since simLauncher imports phetioEngine - if ( brands.includes( 'phet-io' ) || brands.includes( 'phet' ) ) { - const results = await tsc( `../${repo}` ); - reportTscResults( results, grunt ); - } - else { - grunt.log.writeln( 'skipping type checking' ); - } + await phetTimingLog.startAsync( 'tsc', async () => { + + // We must have phet-io code checked out to type check, since simLauncher imports phetioEngine + if ( brands.includes( 'phet-io' ) || brands.includes( 'phet' ) ) { + const results = await tsc( `../${repo}` ); + reportTscResults( results, grunt ); + } + else { + grunt.log.writeln( 'skipping type checking' ); + } + } ); + + phetTimingLog.start( 'transpile', () => { - // If that succeeds, then convert the code to JS - transpiler.transpileRepos( getPhetLibs( repo ) ); + // If that succeeds, then convert the code to JS + transpiler.transpileRepos( getPhetLibs( repo ) ); + } ); - // standalone - if ( repoPackageObject.phet.buildStandalone ) { - grunt.log.writeln( 'Building standalone repository' ); + // standalone + if ( repoPackageObject.phet.buildStandalone ) { + grunt.log.writeln( 'Building standalone repository' ); - const parentDir = `../${repo}/build/`; - if ( !fs.existsSync( parentDir ) ) { - fs.mkdirSync( parentDir ); - } + const parentDir = `../${repo}/build/`; + if ( !fs.existsSync( parentDir ) ) { + fs.mkdirSync( parentDir ); + } - fs.writeFileSync( `${parentDir}/${repo}.min.js`, await buildStandalone( repo, minifyOptions ) ); + fs.writeFileSync( `${parentDir}/${repo}.min.js`, await buildStandalone( repo, minifyOptions ) ); - if ( repoPackageObject.phet.standaloneTranspiles ) { - for ( const file of repoPackageObject.phet.standaloneTranspiles ) { - fs.writeFileSync( `../${repo}/build/${path.basename( file )}`, minify( grunt.file.read( file ) ) ); - } - } - } - else { + if ( repoPackageObject.phet.standaloneTranspiles ) { + for ( const file of repoPackageObject.phet.standaloneTranspiles ) { + fs.writeFileSync( `../${repo}/build/${path.basename( file )}`, minify( grunt.file.read( file ) ) ); + } + } + } + else { - const localPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); - assert( localPackageObject.phet.runnable, `${repo} does not appear to be runnable` ); - grunt.log.writeln( `Building runnable repository (${repo}, brands: ${brands.join( ', ' )})` ); + const localPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); + assert( localPackageObject.phet.runnable, `${repo} does not appear to be runnable` ); + grunt.log.writeln( `Building runnable repository (${repo}, brands: ${brands.join( ', ' )})` ); - // Other options - const allHTML = !!grunt.option( 'allHTML' ); - const localesOption = grunt.option( 'locales' ) || 'en'; // Default back to English for now + // Other options + const allHTML = !!grunt.option( 'allHTML' ); + const localesOption = grunt.option( 'locales' ) || 'en'; // Default back to English for now - for ( const brand of brands ) { - grunt.log.writeln( `Building brand: ${brand}` ); + for ( const brand of brands ) { + grunt.log.writeln( `Building brand: ${brand}` ); - await buildRunnable( repo, minifyOptions, instrument, allHTML, brand, localesOption, buildLocal ); - } - } + await phetTimingLog.startAsync( 'build-brand-' + brand, async () => { + await buildRunnable( repo, minifyOptions, instrument, allHTML, brand, localesOption, buildLocal ); + } ); + } + } + } ); } ) ); Index: main/perennial-alias/.gitignore IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/.gitignore b/main/perennial-alias/.gitignore --- a/main/perennial-alias/.gitignore (revision 566de03f8a9a187aa817deebd8b60f38b139fd49) +++ b/main/perennial-alias/.gitignore (date 1665884357276) @@ -10,4 +10,5 @@ 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 Index: main/chipper/js/scripts/hook-pre-commit.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/chipper/js/scripts/hook-pre-commit.js b/main/chipper/js/scripts/hook-pre-commit.js --- a/main/chipper/js/scripts/hook-pre-commit.js (revision e27c7f4e72cc4b0a3e1a57bdc32b83f677438aa2) +++ b/main/chipper/js/scripts/hook-pre-commit.js (date 1665896658241) @@ -1,7 +1,13 @@ // Copyright 2020-2022, University of Colorado Boulder /** - * Runs tasks for pre-commit, including lint and qunit testing. Avoids the overhead of grunt and Gruntfile.js for speed + * Runs tasks for pre-commit, including lint and qunit testing. Avoids the overhead of grunt and Gruntfile.js for speed. + * + * Should only be run when developing in master, because when dependency shas are checked out for one sim, + * they will likely be inconsistent for other repos which would cause failures for processes like type checking. + * This means when running maintenance release steps, you may need to run git commands with --no-verify. + * + * Timing data is streamed through phetTimingLog, please see that file for how to see the results live and/or afterwards. * * USAGE: * cd ${repo} @@ -15,7 +21,6 @@ * @author Sam Reid (PhET Interactive Simulations) */ -// Require statements which should be generally available via node or perennial const fs = require( 'fs' ); const path = require( 'path' ); const puppeteer = require( 'puppeteer' ); @@ -26,167 +31,189 @@ const generatePhetioMacroAPI = require( '../phet-io/generatePhetioMacroAPI' ); const CacheLayer = require( '../../../chipper/js/common/CacheLayer' ); const phetioCompareAPISets = require( '../phet-io/phetioCompareAPISets' ); +const phetTimingLog = require( '../../../perennial-alias/js/common/phetTimingLog' ); +const lint = require( '../../../chipper/js/grunt/lint' ); +const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); +const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); ( async () => { -// Identify the current repo - const repo = process.cwd().split( path.sep ).pop(); + const precommitSuccess = await phetTimingLog.startAsync( 'hook-pre-commit', async () => { + + // Identify the current repo + const repo = process.cwd().split( path.sep ).pop(); -// Console logging via --console - const commandLineArguments = process.argv.slice( 2 ); - const outputToConsole = commandLineArguments.includes( '--console' ); + // Console logging via --console + const commandLineArguments = process.argv.slice( 2 ); + const outputToConsole = commandLineArguments.includes( '--console' ); -// Run lint tests if they exist in the checked-out SHAs. - try { - const lint = require( '../../../chipper/js/grunt/lint' ); - if ( lint.chipperAPIVersion === 'promisesPerRepo1' ) { + // Run lint tests if they exist in the checked-out SHAs. + const lintOK = await phetTimingLog.startAsync( 'lint', async () => { // lint() automatically filters out non-lintable repos const lintReturnValue = await lint( [ repo ] ); - - if ( !lintReturnValue.ok ) { - process.exit( 1 ); - } - outputToConsole && console.log( `Linting passed with results.length: ${lintReturnValue.results.length}` ); - } - else { - console.log( 'chipper/js/grunt/lint not compatible' ); + return lintReturnValue.ok; + } ); + + if ( !lintOK ) { + return false; } - } - catch( e ) { - console.log( 'chipper/js/grunt/lint not found' ); - } + + const reportMediaOK = await phetTimingLog.startAsync( 'report-media', async () => { -// These sims don't have package.json or media that requires checking. - const optOutOfReportMedia = [ - 'decaf', - 'phet-android-app', - 'babel', - 'phet-info', - 'phet-ios-app', - 'sherpa', - 'smithers', - 'tasks', - 'weddell' - ]; + // These sims don't have package.json or media that requires checking. + const optOutOfReportMedia = [ + 'decaf', + 'phet-android-app', + 'babel', + 'phet-info', + 'phet-ios-app', + 'sherpa', + 'smithers', + 'tasks', + 'weddell' + ]; -// Make sure license.json for images/audio is up-to-date - if ( !optOutOfReportMedia.includes( repo ) ) { - try { - const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); + // Make sure license.json for images/audio is up-to-date + if ( !optOutOfReportMedia.includes( repo ) ) { - const success = await reportMedia( repo ); + const success = await reportMedia( repo ); + return success; + } + else { - // At the moment reportMedia uses grunt.fail, but we defensively use the return value here in case that changes. - if ( !success ) { - process.exit( 1 ); + // no need to check + return true; } + } ); + + if ( !reportMediaOK ) { + return false; } - catch( e ) { - console.log( 'chipper/js/grunt/reportMedia not found' ); - } - } + + const tscOK = await phetTimingLog.startAsync( 'tsc', async () => { - // Run typescript type checker if it exists in the checked-out shas - const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { - errors: 'resolve' - } ); + // Run typescript type checker if it exists in the checked-out shas + const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { + errors: 'resolve' + } ); - results.stderr.trim().length > 0 && console.log( results.stderr ); - results.stdout.trim().length > 0 && console.log( results.stdout ); + results.stderr.trim().length > 0 && console.log( results.stderr ); + results.stdout.trim().length > 0 && console.log( results.stdout ); - if ( results.code === 0 ) { - outputToConsole && console.log( 'tsc passed' ); - } - else { - console.log( results ); - process.exit( results.code ); - } + if ( results.code === 0 ) { + outputToConsole && console.log( 'tsc passed' ); + return true; + } + else { + console.log( results ); + return false; + } + } ); + + if ( !tscOK ) { + return false; + } + const qunitOK = await phetTimingLog.startAsync( 'qunit', async () => { // Run qunit tests if puppeteerQUnit exists in the checked-out SHAs and a test HTML exists. - try { - const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); - const cacheKey = `puppeteerQUnit#${repo}`; + + const cacheKey = `puppeteerQUnit#${repo}`; - if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those - const testFilePath = `${repo}/${repo}-tests.html`; - const exists = fs.existsSync( `../${testFilePath}` ); - if ( exists ) { + if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those + const testFilePath = `${repo}/${repo}-tests.html`; + const exists = fs.existsSync( `../${testFilePath}` ); + if ( exists ) { - if ( CacheLayer.isCacheSafe( cacheKey ) ) { - console.log( 'unit tests success cached' ); - } - else { - const browser = await puppeteer.launch(); + if ( CacheLayer.isCacheSafe( cacheKey ) ) { + console.log( 'unit tests success cached' ); + return true; + } + else { + const browser = await puppeteer.launch(); - const result = await withServer( async port => { - return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); - } ); + const result = await withServer( async port => { + return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); + } ); - await browser.close(); + await browser.close(); - outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); - if ( !result.ok ) { - console.error( `unit tests failed in ${repo}`, result ); - process.exit( 1 ); // fail as soon as there is one problem - } - else { - CacheLayer.onSuccess( cacheKey ); - } - } - } + outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); + if ( !result.ok ) { + console.error( `unit tests failed in ${repo}`, result ); + return false; + } + else { + CacheLayer.onSuccess( cacheKey ); + return true; + } + } + } - outputToConsole && console.log( 'QUnit: no problems detected' ); - } - } - catch( e ) { - console.log( e ); - } + outputToConsole && console.log( 'QUnit: no problems detected' ); + return true; + } + return true; + } ); + + if ( !qunitOK ) { + return false; + } - //////////////////////////////////////////////////////////////////////////////// - // Compare PhET-iO APIs for this repo and anything that has it as a dependency - // - ( async () => { + //////////////////////////////////////////////////////////////////////////////// + // Compare PhET-iO APIs for this repo and anything that has it as a dependency + // + const phetioAPIOK = await phetTimingLog.startAsync( 'phet-io-api-compare', async () => { - // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test - // every phet-io stable sim. - const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); - - const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); + // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test + // every phet-io stable sim. + const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); + const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); - if ( reposToTest.length > 0 ) { - console.log( 'PhET-iO API testing: ' + reposToTest ); + if ( reposToTest.length > 0 ) { + console.log( 'PhET-iO API testing: ' + reposToTest ); - const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); + const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); - if ( !CacheLayer.isCacheSafe( cacheKey ) ) { + if ( !CacheLayer.isCacheSafe( cacheKey ) ) { - const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { - showProgressBar: reposToTest.length > 1, - showMessagesFromSim: false - } ); + const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { + showProgressBar: reposToTest.length > 1, + showMessagesFromSim: false + } ); - const compareSuccess = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); + const phetioAPIComparisonSuccessful = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); - if ( compareSuccess ) { - - CacheLayer.onSuccess( cacheKey ); + if ( phetioAPIComparisonSuccessful ) { + CacheLayer.onSuccess( cacheKey ); + } - // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here - process.exit( 0 ); + return phetioAPIComparisonSuccessful; } else { - process.exit( 1 ); + + // Cached and cache is good + return true; } } - } - else { - console.log( 'PhET-iO API testing: no repos detected' ); + else { + console.log( 'PhET-iO API testing: no repos detected' ); + return true; + } + } ); + + if ( !phetioAPIOK ) { + return false; } - } )(); + // OTHER TESTS GO HERE - // NOTE: if adding or rearranging rules, be careful about the early exit above + // NOTE: if adding or rearranging rules, be careful about the early exit above + // If everything passed, return true for success + return true; + } ); + // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here + phetTimingLog.close( () => process.exit( precommitSuccess ? 0 : 1 ) ); } )(); \ No newline at end of file Index: main/perennial-alias/js/common/phetTimingLog.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/js/common/phetTimingLog.js b/main/perennial-alias/js/common/phetTimingLog.js new file mode 100644 --- /dev/null (date 1665896832576) +++ b/main/perennial-alias/js/common/phetTimingLog.js (date 1665896832576) @@ -0,0 +1,108 @@ +// 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' ); + +// Log to perennial-alias if running a perennial-alias task, or perennial if running a perennial task. +const logPath = path.resolve( __dirname, '../../logs/phet-timing-log.txt' ); + +// Create file if it doesn't exist, and append to it +const stream = fs.createWriteStream( logPath, { flags: 'a' } ); + +let depth = -1; + +const indent = depth => { + let x = ''; + for ( let i = 0; i < depth; i++ ) { + x = x + ' '; + } + return x; +}; + +const push = taskName => { + depth++; + + assert( !taskName.includes( ':' ), 'task name cannot include :, it was ' + taskName ); + stream.write( `${indent( depth )}<${taskName}>\n` ); + + const startTime = Date.now(); + return startTime; +}; + +const pop = ( taskName, startTime ) => { + const endTime = Date.now(); + + stream.write( `${indent( depth )} \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} task + * @returns {Promise} + */ + 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 ```

UPDATE: even better patch.

```diff Index: main/chipper/js/grunt/Gruntfile.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/chipper/js/grunt/Gruntfile.js b/main/chipper/js/grunt/Gruntfile.js --- a/main/chipper/js/grunt/Gruntfile.js (revision e27c7f4e72cc4b0a3e1a57bdc32b83f677438aa2) +++ b/main/chipper/js/grunt/Gruntfile.js (date 1665896682571) @@ -217,76 +217,88 @@ const path = require( 'path' ); const fs = require( 'fs' ); const getPhetLibs = require( './getPhetLibs' ); + const phetTimingLog = require( '../../../perennial-alias/js/common/phetTimingLog' ); + + await phetTimingLog.startAsync( 'grunt-build', async () => { - // Parse minification keys - const minifyKeys = Object.keys( minify.MINIFY_DEFAULTS ); - const minifyOptions = {}; - minifyKeys.forEach( minifyKey => { - const option = grunt.option( `minify.${minifyKey}` ); - if ( option === true || option === false ) { - minifyOptions[ minifyKey ] = option; - } - } ); + // Parse minification keys + const minifyKeys = Object.keys( minify.MINIFY_DEFAULTS ); + const minifyOptions = {}; + minifyKeys.forEach( minifyKey => { + const option = grunt.option( `minify.${minifyKey}` ); + if ( option === true || option === false ) { + minifyOptions[ minifyKey ] = option; + } + } ); - // grunt options that apply to multiple build tasks - const instrument = !!grunt.option( 'instrument' ); + // grunt options that apply to multiple build tasks + const instrument = !!grunt.option( 'instrument' ); - // Do not uglify or transpile if it is being instrumented, so it will match development code as closely as possible - if ( instrument ) { - minifyOptions.babelTranspile = false; - minifyOptions.uglify = false; - } + // Do not uglify or transpile if it is being instrumented, so it will match development code as closely as possible + if ( instrument ) { + minifyOptions.babelTranspile = false; + minifyOptions.uglify = false; + } - const repoPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); + const repoPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); - // Run the type checker first. - const brands = getBrands( grunt, repo, buildLocal ); + // Run the type checker first. + const brands = getBrands( grunt, repo, buildLocal ); - // We must have phet-io code checked out to type check, since simLauncher imports phetioEngine - if ( brands.includes( 'phet-io' ) || brands.includes( 'phet' ) ) { - const results = await tsc( `../${repo}` ); - reportTscResults( results, grunt ); - } - else { - grunt.log.writeln( 'skipping type checking' ); - } + await phetTimingLog.startAsync( 'tsc', async () => { + + // We must have phet-io code checked out to type check, since simLauncher imports phetioEngine + if ( brands.includes( 'phet-io' ) || brands.includes( 'phet' ) ) { + const results = await tsc( `../${repo}` ); + reportTscResults( results, grunt ); + } + else { + grunt.log.writeln( 'skipping type checking' ); + } + } ); + + phetTimingLog.start( 'transpile', () => { - // If that succeeds, then convert the code to JS - transpiler.transpileRepos( getPhetLibs( repo ) ); + // If that succeeds, then convert the code to JS + transpiler.transpileRepos( getPhetLibs( repo ) ); + } ); - // standalone - if ( repoPackageObject.phet.buildStandalone ) { - grunt.log.writeln( 'Building standalone repository' ); + // standalone + if ( repoPackageObject.phet.buildStandalone ) { + grunt.log.writeln( 'Building standalone repository' ); - const parentDir = `../${repo}/build/`; - if ( !fs.existsSync( parentDir ) ) { - fs.mkdirSync( parentDir ); - } + const parentDir = `../${repo}/build/`; + if ( !fs.existsSync( parentDir ) ) { + fs.mkdirSync( parentDir ); + } - fs.writeFileSync( `${parentDir}/${repo}.min.js`, await buildStandalone( repo, minifyOptions ) ); + fs.writeFileSync( `${parentDir}/${repo}.min.js`, await buildStandalone( repo, minifyOptions ) ); - if ( repoPackageObject.phet.standaloneTranspiles ) { - for ( const file of repoPackageObject.phet.standaloneTranspiles ) { - fs.writeFileSync( `../${repo}/build/${path.basename( file )}`, minify( grunt.file.read( file ) ) ); - } - } - } - else { + if ( repoPackageObject.phet.standaloneTranspiles ) { + for ( const file of repoPackageObject.phet.standaloneTranspiles ) { + fs.writeFileSync( `../${repo}/build/${path.basename( file )}`, minify( grunt.file.read( file ) ) ); + } + } + } + else { - const localPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); - assert( localPackageObject.phet.runnable, `${repo} does not appear to be runnable` ); - grunt.log.writeln( `Building runnable repository (${repo}, brands: ${brands.join( ', ' )})` ); + const localPackageObject = grunt.file.readJSON( `../${repo}/package.json` ); + assert( localPackageObject.phet.runnable, `${repo} does not appear to be runnable` ); + grunt.log.writeln( `Building runnable repository (${repo}, brands: ${brands.join( ', ' )})` ); - // Other options - const allHTML = !!grunt.option( 'allHTML' ); - const localesOption = grunt.option( 'locales' ) || 'en'; // Default back to English for now + // Other options + const allHTML = !!grunt.option( 'allHTML' ); + const localesOption = grunt.option( 'locales' ) || 'en'; // Default back to English for now - for ( const brand of brands ) { - grunt.log.writeln( `Building brand: ${brand}` ); + for ( const brand of brands ) { + grunt.log.writeln( `Building brand: ${brand}` ); - await buildRunnable( repo, minifyOptions, instrument, allHTML, brand, localesOption, buildLocal ); - } - } + await phetTimingLog.startAsync( 'build-brand-' + brand, async () => { + await buildRunnable( repo, minifyOptions, instrument, allHTML, brand, localesOption, buildLocal ); + } ); + } + } + } ); } ) ); Index: main/perennial-alias/.gitignore IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/.gitignore b/main/perennial-alias/.gitignore --- a/main/perennial-alias/.gitignore (revision 566de03f8a9a187aa817deebd8b60f38b139fd49) +++ b/main/perennial-alias/.gitignore (date 1665884357276) @@ -10,4 +10,5 @@ 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 Index: main/chipper/js/scripts/hook-pre-commit.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/chipper/js/scripts/hook-pre-commit.js b/main/chipper/js/scripts/hook-pre-commit.js --- a/main/chipper/js/scripts/hook-pre-commit.js (revision e27c7f4e72cc4b0a3e1a57bdc32b83f677438aa2) +++ b/main/chipper/js/scripts/hook-pre-commit.js (date 1665938723013) @@ -1,7 +1,13 @@ // Copyright 2020-2022, University of Colorado Boulder /** - * Runs tasks for pre-commit, including lint and qunit testing. Avoids the overhead of grunt and Gruntfile.js for speed + * Runs tasks for pre-commit, including lint and qunit testing. Avoids the overhead of grunt and Gruntfile.js for speed. + * + * Should only be run when developing in master, because when dependency shas are checked out for one sim, + * they will likely be inconsistent for other repos which would cause failures for processes like type checking. + * This means when running maintenance release steps, you may need to run git commands with --no-verify. + * + * Timing data is streamed through phetTimingLog, please see that file for how to see the results live and/or afterwards. * * USAGE: * cd ${repo} @@ -15,7 +21,6 @@ * @author Sam Reid (PhET Interactive Simulations) */ -// Require statements which should be generally available via node or perennial const fs = require( 'fs' ); const path = require( 'path' ); const puppeteer = require( 'puppeteer' ); @@ -26,167 +31,189 @@ const generatePhetioMacroAPI = require( '../phet-io/generatePhetioMacroAPI' ); const CacheLayer = require( '../../../chipper/js/common/CacheLayer' ); const phetioCompareAPISets = require( '../phet-io/phetioCompareAPISets' ); +const phetTimingLog = require( '../../../perennial-alias/js/common/phetTimingLog' ); +const lint = require( '../../../chipper/js/grunt/lint' ); +const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); +const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); ( async () => { -// Identify the current repo + // Identify the current repo const repo = process.cwd().split( path.sep ).pop(); -// Console logging via --console - const commandLineArguments = process.argv.slice( 2 ); - const outputToConsole = commandLineArguments.includes( '--console' ); + const precommitSuccess = await phetTimingLog.startAsync( `hook-pre-commit repo="${repo}"`, async () => { + + // Console logging via --console + const commandLineArguments = process.argv.slice( 2 ); + const outputToConsole = commandLineArguments.includes( '--console' ); -// Run lint tests if they exist in the checked-out SHAs. - try { - const lint = require( '../../../chipper/js/grunt/lint' ); - if ( lint.chipperAPIVersion === 'promisesPerRepo1' ) { + // Run lint tests if they exist in the checked-out SHAs. + const lintOK = await phetTimingLog.startAsync( 'lint', async () => { // lint() automatically filters out non-lintable repos const lintReturnValue = await lint( [ repo ] ); - - if ( !lintReturnValue.ok ) { - process.exit( 1 ); - } - outputToConsole && console.log( `Linting passed with results.length: ${lintReturnValue.results.length}` ); - } - else { - console.log( 'chipper/js/grunt/lint not compatible' ); + return lintReturnValue.ok; + } ); + + if ( !lintOK ) { + return false; } - } - catch( e ) { - console.log( 'chipper/js/grunt/lint not found' ); - } + + const reportMediaOK = await phetTimingLog.startAsync( 'report-media', async () => { -// These sims don't have package.json or media that requires checking. - const optOutOfReportMedia = [ - 'decaf', - 'phet-android-app', - 'babel', - 'phet-info', - 'phet-ios-app', - 'sherpa', - 'smithers', - 'tasks', - 'weddell' - ]; + // These sims don't have package.json or media that requires checking. + const optOutOfReportMedia = [ + 'decaf', + 'phet-android-app', + 'babel', + 'phet-info', + 'phet-ios-app', + 'sherpa', + 'smithers', + 'tasks', + 'weddell' + ]; -// Make sure license.json for images/audio is up-to-date - if ( !optOutOfReportMedia.includes( repo ) ) { - try { - const reportMedia = require( '../../../chipper/js/grunt/reportMedia' ); + // Make sure license.json for images/audio is up-to-date + if ( !optOutOfReportMedia.includes( repo ) ) { - const success = await reportMedia( repo ); + const success = await reportMedia( repo ); + return success; + } + else { - // At the moment reportMedia uses grunt.fail, but we defensively use the return value here in case that changes. - if ( !success ) { - process.exit( 1 ); + // no need to check + return true; } + } ); + + if ( !reportMediaOK ) { + return false; } - catch( e ) { - console.log( 'chipper/js/grunt/reportMedia not found' ); - } - } + + const tscOK = await phetTimingLog.startAsync( 'tsc', async () => { - // Run typescript type checker if it exists in the checked-out shas - const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { - errors: 'resolve' - } ); + // Run typescript type checker if it exists in the checked-out shas + const results = await execute( 'node', [ '../chipper/js/scripts/absolute-tsc.js', '../chipper/tsconfig/all' ], '../chipper', { + errors: 'resolve' + } ); - results.stderr.trim().length > 0 && console.log( results.stderr ); - results.stdout.trim().length > 0 && console.log( results.stdout ); + results.stderr.trim().length > 0 && console.log( results.stderr ); + results.stdout.trim().length > 0 && console.log( results.stdout ); - if ( results.code === 0 ) { - outputToConsole && console.log( 'tsc passed' ); - } - else { - console.log( results ); - process.exit( results.code ); - } + if ( results.code === 0 ) { + outputToConsole && console.log( 'tsc passed' ); + return true; + } + else { + console.log( results ); + return false; + } + } ); + + if ( !tscOK ) { + return false; + } + const qunitOK = await phetTimingLog.startAsync( 'qunit', async () => { // Run qunit tests if puppeteerQUnit exists in the checked-out SHAs and a test HTML exists. - try { - const puppeteerQUnit = require( '../../../aqua/js/local/puppeteerQUnit' ); - const cacheKey = `puppeteerQUnit#${repo}`; + + const cacheKey = `puppeteerQUnit#${repo}`; - if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those - const testFilePath = `${repo}/${repo}-tests.html`; - const exists = fs.existsSync( `../${testFilePath}` ); - if ( exists ) { + if ( repo !== 'scenery' && repo !== 'phet-io-wrappers' ) { // scenery unit tests take too long, so skip those + const testFilePath = `${repo}/${repo}-tests.html`; + const exists = fs.existsSync( `../${testFilePath}` ); + if ( exists ) { - if ( CacheLayer.isCacheSafe( cacheKey ) ) { - console.log( 'unit tests success cached' ); - } - else { - const browser = await puppeteer.launch(); + if ( CacheLayer.isCacheSafe( cacheKey ) ) { + console.log( 'unit tests success cached' ); + return true; + } + else { + const browser = await puppeteer.launch(); - const result = await withServer( async port => { - return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); - } ); + const result = await withServer( async port => { + return puppeteerQUnit( browser, `http://localhost:${port}/${testFilePath}?ea&brand=phet-io` ); + } ); - await browser.close(); + await browser.close(); - outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); - if ( !result.ok ) { - console.error( `unit tests failed in ${repo}`, result ); - process.exit( 1 ); // fail as soon as there is one problem - } - else { - CacheLayer.onSuccess( cacheKey ); - } - } - } + outputToConsole && console.log( `${repo}: ${JSON.stringify( result, null, 2 )}` ); + if ( !result.ok ) { + console.error( `unit tests failed in ${repo}`, result ); + return false; + } + else { + CacheLayer.onSuccess( cacheKey ); + return true; + } + } + } - outputToConsole && console.log( 'QUnit: no problems detected' ); - } - } - catch( e ) { - console.log( e ); - } + outputToConsole && console.log( 'QUnit: no problems detected' ); + return true; + } + return true; + } ); + + if ( !qunitOK ) { + return false; + } - //////////////////////////////////////////////////////////////////////////////// - // Compare PhET-iO APIs for this repo and anything that has it as a dependency - // - ( async () => { + //////////////////////////////////////////////////////////////////////////////// + // Compare PhET-iO APIs for this repo and anything that has it as a dependency + // + const phetioAPIOK = await phetTimingLog.startAsync( 'phet-io-api-compare', async () => { - // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test - // every phet-io stable sim. - const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); - - const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); + // Test this repo and all phet-io sims that have it as a dependency. For instance, changing sun would test + // every phet-io stable sim. + const phetioAPIStable = getRepoList( 'phet-io-api-stable' ); + const reposToTest = phetioAPIStable.filter( phetioSimRepo => getPhetLibs( phetioSimRepo ).includes( repo ) ); - if ( reposToTest.length > 0 ) { - console.log( 'PhET-iO API testing: ' + reposToTest ); + if ( reposToTest.length > 0 ) { + console.log( 'PhET-iO API testing: ' + reposToTest ); - const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); + const cacheKey = 'phet-io-api-testing_' + reposToTest.join( '_' ); - if ( !CacheLayer.isCacheSafe( cacheKey ) ) { + if ( !CacheLayer.isCacheSafe( cacheKey ) ) { - const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { - showProgressBar: reposToTest.length > 1, - showMessagesFromSim: false - } ); + const proposedAPIs = await generatePhetioMacroAPI( reposToTest, { + showProgressBar: reposToTest.length > 1, + showMessagesFromSim: false + } ); - const compareSuccess = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); + const phetioAPIComparisonSuccessful = await phetioCompareAPISets( reposToTest, proposedAPIs, {} ); - if ( compareSuccess ) { - - CacheLayer.onSuccess( cacheKey ); + if ( phetioAPIComparisonSuccessful ) { + CacheLayer.onSuccess( cacheKey ); + } - // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here - process.exit( 0 ); + return phetioAPIComparisonSuccessful; } else { - process.exit( 1 ); + + // Cached and cache is good + return true; } } - } - else { - console.log( 'PhET-iO API testing: no repos detected' ); + else { + console.log( 'PhET-iO API testing: no repos detected' ); + return true; + } + } ); + + if ( !phetioAPIOK ) { + return false; } - } )(); + // OTHER TESTS GO HERE - // NOTE: if adding or rearranging rules, be careful about the early exit above + // NOTE: if adding or rearranging rules, be careful about the early exit above + // If everything passed, return true for success + return true; + } ); + // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here + phetTimingLog.close( () => process.exit( precommitSuccess ? 0 : 1 ) ); } )(); \ No newline at end of file Index: main/perennial-alias/js/common/phetTimingLog.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/main/perennial-alias/js/common/phetTimingLog.js b/main/perennial-alias/js/common/phetTimingLog.js new file mode 100644 --- /dev/null (date 1665932007581) +++ b/main/perennial-alias/js/common/phetTimingLog.js (date 1665932007581) @@ -0,0 +1,121 @@ +// 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 => { + let x = ''; + for ( let i = 0; i < depth; i++ ) { + x = x + ' '; + } + return x; +}; + +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( `\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 )} \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} task + * @returns {Promise} + */ + 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 ```
samreid commented 2 years ago

Remaining work and questions for the reviewer:

<!-- 10/16/2022, 10:45:37 AM -->
<hook-pre-commit repo="gravity-and-orbits">
  <lint>
  </lint> <!-- 554ms -->
  <report-media>
  </report-media> <!-- 12ms -->
  <tsc>
  </tsc> <!-- 4807ms -->
  <qunit>
  </qunit> <!-- 7962ms -->
  <phet-io-api-compare>
  </phet-io-api-compare> <!-- 5414ms -->
</hook-pre-commit repo="gravity-and-orbits"> <!-- 18749ms -->

But we could shorten it to:

<!-- 10/16/2022, 10:45:37 AM -->
<hook-pre-commit repo="gravity-and-orbits">
  <lint/><!-- 554ms -->
  <report-media/> <!-- 12ms -->
  <tsc/> <!-- 4807ms -->
  <qunit/> <!-- 7962ms -->
  <phet-io-api-compare/> <!-- 5414ms -->
</hook-pre-commit repo="gravity-and-orbits"> <!-- 18749ms -->
samreid commented 2 years ago

This is at a good checkpoint for Dev Meeting PSA.

samreid commented 2 years ago

This doesn't support multiple thread access very well, CT snapshots look like this:

  <transpile>
  </transpile> <!-- 9148ms -->
  <build-brand-phet>
    <webpack>
  <transpile>
  </transpile> <!-- 5440ms -->
  <build-brand-phet>
    <webpack>
    </webpack> <!-- 9889ms -->
    </webpack> <!-- 10292ms -->
    </webpack> <!-- 9059ms -->
    <minify-production>
    <minify-production>
samreid commented 2 years ago

Looks like log rotation is not critical on CT for this file. Each snapshot log file was not too big, and they disappear with each snapshot.

By the way, there are some very disturbing numbers in the bayes CT phet-timing-log.

  </build-brand-phet-io> <!-- 248430ms -->

That's over 4 minutes to build one brand of one sim.

samreid commented 2 years ago

I shared a PSA today. @kathy-phet asked @AgustinVallejo to review. Please see the checkboxes above for questions.

jessegreenberg commented 2 years ago

@samreid showed a demo of logs in perennial-alias/logs/phet-timing-log.txt. You can see how long processes take. It reports timing for several processes like tsc, lint, and grunt tasks.

There is documentation in the phet-timing-log about this and how to print output in real time.

@zepumph: How should we use this tool? I often have commit hooks that take longer than 100 seconds. What is an acceptable amount of time? @zepumph - sometimes to get around commit hook timing I commit locally without hooks and then run tests before pushing. @marlitas - I thought we shouldn't be making breaking changes even locally? @jonathanolson - Yes, it is better for checking out SHAs at a certain date to not have breaks committed to master. @jonathanolson - Have the commit hooks been successfully saving us from pushing breaking changes? @pixelzoom @jbphet @jessegreenberg - Yes! @marlitas - I think it would be nice to be able to make rapid commits locally or to a branch without waiting for commit hooks. @jbphet - You could make commits to a feature branch. Then when merge to master when the changes are complete. @samreid - Lets form a sub team for this. We have log data to look through now, and need a sub team to make decisions about this. @zepumph - I waited for built tools for 18.5 minutes yesterday. The time could be longer. Sometimes run without commit hooks. @jessegreenberg - I am going to try feature branches without commit hooks when working in a single repo for a bit! @kathy-phet - After the POSE convening we can have a sub-group discuss this.

samreid commented 2 years ago

I opened https://github.com/phetsims/chipper/issues/1350 about improving the precommit hook developer experience. This issue can remain specific to the timing logging.

samreid commented 1 year ago

Today @marlitas and I observed this output in the timing log:

~/apache-document-root/main$ tail -f ./perennial-alias/logs/phet-timing-log.txt
<hook-pre-commit repo="axon">
  <lint>
  <report-media>
  <tsc>
  <qunit>
  <phet-io-api-compare>
  </report-media> <!-- 533ms -->
  </tsc> <!-- 620ms -->
  </qunit> <!-- 8863ms -->
    </hook-pre-commit repo="axon"> <!-- 23194ms -->

Note that lint never reported an end time. We think lint completed, but it did not flush the write buffer before exiting. We should check on that.

samreid commented 1 year ago

I'm not sure what caused that, since there is a flush command at the end of the hook-pre-commit:

  // generatePhetioMacroAPI is preventing exit for unknown reasons, so manually exit here
  phetTimingLog.close( () => process.exit( precommitSuccess ? 0 : 1 ) );

Maybe the reviewer can investigate and suggest possibilities.

zepumph commented 1 year ago

Now that we have subbprocesses for our pre commit tasks, we need to add 2 things:

  1. It needs restructuring away from XML since it isn't synchronous anymore
  2. Each task needs its "buffer flushed" before exiting from the last process run in hook-pre-commit.
zepumph commented 1 year ago

I updated the timing script to print much nicer, machine parsable text. It also doesn't have the start/end pieces anymore. We lose the ability to look into the logs at what is "currently" going, but we already kinda lost that when we started running the pre-commit-hook subtasks in parallel.

Now things look like:


<hook-pre-commit-perennial-alias date="1/10/2023, 11:05:17 AM">
  <lint time="1042ms"/>
  <qunit time="1036ms"/>
  <phet-io-api-compare time="1057ms"/>
  <report-media time="1094ms"/>
  <tsc time="1369ms"/>
</hook-pre-commit-perennial-alias time="1389ms">

<hook-pre-commit repo="perennial-alias" date="1/10/2023, 11:05:50 AM">
  <qunit time="1084ms"/>
  <report-media time="1128ms"/>
  <lint time="3231ms"/>
  <tsc time="22616ms"/>
  <phet-io-api-compare time="26748ms"/>
</hook-pre-commit repo="perennial-alias" time="26789ms">

<hook-pre-commit repo="perennial-alias" date="1/10/2023, 11:06:27 AM">
  <qunit time="1075ms"/>
  <report-media time="1150ms"/>
  <lint time="3389ms"/>
  <tsc time="22195ms"/>
  <phet-io-api-compare time="25938ms"/>
</hook-pre-commit repo="perennial-alias" time="25984ms">

<hook-pre-commit repo="ratio-and-proportion" date="1/10/2023, 11:06:53 AM">
  <phet-io-api-compare time="1123ms"/>
  <report-media time="1226ms"/>
  <qunit time="9386ms"/>
  <tsc time="17299ms"/>
  <lint time="20553ms"/>
</hook-pre-commit repo="ratio-and-proportion" time="20553ms">

Each task needs its "buffer flushed" before exiting from the last process run in hook-pre-commit.

I'm not sure what this means or what the bug is. Perhaps forget about it unless someone else can remember.

@samreid anything else here?

samreid commented 1 year ago

That looks better to me and more useful to me, but I'm somewhat concerned about the overlap between the buffer flushed issue and not reporting when a task starts. The symptom of the "buffer not flushed" issue is that the task exits before it has a chance to print to the console. So if there is a latent or spurious bug there, it would be difficult to detect.

In checking my phet-timing-log file, I see 1002 occurrences of <hook-pre-commit repo and only 969 occurrences of <hook-pre-commit repo. It could be that some of these are a failed process which never completed. But I wonder if some of these completed but due to a timing issue the process closed before the task could write the closing tag. Maybe it's best to manually inspect the code and make sure we are flushing the buffer before processes exit, and hope that is good enough? (And keep the improved formatting?)

samreid commented 1 year ago

I checked recent timing logs and everything seems OK. No further work for this issue. Thanks @zepumph! Closing.