pre-commit-hooks should keep a log for diagnostics #1342
Assignees
Labels
Comments
|
So far I have been logging my pre-commit-hooks output by saving the output in my bash alias for it.
|
|
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: 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. |
|
We should also consider how we want to look at these logs. Is it more like:
or
Summarizing questions: |
|
I'm planning to work on this issue today |
|
@jessegreenberg said on slack:
|
|
Some more considerations for this log:
Current patch: 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
|
|
Here's an improved patch: 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. Or 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 --> |
|
Current status: 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 )}</${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
UPDATE: even better patch. 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( `<!-- ${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
|
|
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
added a commit
to phetsims/perennial
that referenced
this issue
Oct 17, 2022
samreid
added a commit
that referenced
this issue
Oct 17, 2022
samreid
added a commit
to phetsims/perennial
that referenced
this issue
Oct 26, 2022
|
This is at a good checkpoint for Dev Meeting PSA. |
|
This doesn't support multiple thread access very well, CT snapshots look like this: |
|
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. That's over 4 minutes to build one brand of one sim. |
|
I shared a PSA today. @kathy-phet asked @AgustinVallejo to review. Please see the checkboxes above for questions. |
|
@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? |
|
I opened #1350 about improving the precommit hook developer experience. This issue can remain specific to the timing logging. |
|
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. |
|
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. |
|
Now that we have subbprocesses for our pre commit tasks, we need to add 2 things:
|
zepumph
added a commit
to phetsims/perennial
that referenced
this issue
Jan 10, 2023
|
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:
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? |
|
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 |
|
I checked recent timing logs and everything seems OK. No further work for this issue. Thanks @zepumph! Closing. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
From #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.
The text was updated successfully, but these errors were encountered: