Add a profile script #475

Closed
wants to merge 1 commit into
from

Projects

None yet

4 participants

@jamestalmage
Member

I've been working on getting iron-node working with AVA so we can do some proper profiling. I think I finally cracked it.

The first thing was to run in a single process (this means only running a single test file), and fake the response of a parent process. It logs test results to the Chrome DevTools console (and it's not very pretty), but we shouldn't really care about the test results much while profiling.

The second was working around some weirdness with setTimeout in iron-node. I'm not sure if it's an iron-node problem, or an electron one, but storing setTimeout the way we do in globals.js breaks things. The solution here was to just undo our safe copies of setTimeout and clearTimeout. This means we can't profile against anything that manipulates timers (not sure why that would ever be necessary).

@sindresorhus sindresorhus and 1 other commented on an outdated diff Jan 26, 2016
+var path = require('path');
+var meow = require('meow');
+var Promise = require('bluebird');
+var pkgConf = require('pkg-conf');
+var arrify = require('arrify');
+var findCacheDir = require('find-cache-dir');
+var uniqueTempDir = require('unique-temp-dir');
+var EventEmitter = require('events').EventEmitter;
+var CachingPrecompiler = require('./lib/caching-precompiler');
+var globals = require('./lib/globals');
+
+// copy original console and console.log so tests can't manipulate them.
+var originalConsole = console;
+var consoleLog = originalConsole.log;
+
+// Our usage of globals to store setTimeout/clearTimeout upsets iron-node for some reason.
@sindresorhus
sindresorhus Jan 26, 2016 Member

Can you open an issue on iron-node about this?

@sindresorhus sindresorhus and 1 other commented on an outdated diff Jan 26, 2016
+// Intended to be used with iron-node for profiling purposes.
+
+var path = require('path');
+var meow = require('meow');
+var Promise = require('bluebird');
+var pkgConf = require('pkg-conf');
+var arrify = require('arrify');
+var findCacheDir = require('find-cache-dir');
+var uniqueTempDir = require('unique-temp-dir');
+var EventEmitter = require('events').EventEmitter;
+var CachingPrecompiler = require('./lib/caching-precompiler');
+var globals = require('./lib/globals');
+
+// copy original console and console.log so tests can't manipulate them.
+var originalConsole = console;
+var consoleLog = originalConsole.log;
@sindresorhus
sindresorhus Jan 26, 2016 Member

Add these to ./lib/globals?

@jamestalmage
jamestalmage Jan 29, 2016 Member

I don't think any of our child-process code will ever call console.log.

@sindresorhus
sindresorhus Jan 29, 2016 Member

Yeah, I know. Just thought it would be cleaner to keep all overridden globals in our globals file.

@jamestalmage
jamestalmage Jan 29, 2016 Member

I am just dropping the safe copies. If someone ever asks us to profile a suite that does something to console.log we can address it then.

@sindresorhus
Member

Can you quickly mention how to use this in maintaining.md?

@sindresorhus
Member

Tried it now. What's the workflow for profiling? The tests run on startup and finish before I manage to do anything. Is the recommended practise to put a debugger; statement at the top of the test file?

@jamestalmage
Member

Sorry @sindresorhus - for some reason I never got notifications on any of these.

What's the workflow for profiling?

Click record then reload the page (that is what I did). I did not put any debugger statements in. That's an interesting thought though.

@jamestalmage jamestalmage Add a profile script.
946fec3
@sindresorhus sindresorhus changed the title from Add a profile script. to Add a profile script Jan 29, 2016
@sindresorhus sindresorhus added a commit that referenced this pull request Jan 29, 2016
@sindresorhus sindresorhus followup tweaks to #475 e778047
@sindresorhus
Member

Awesome. Excited to have an easy way to perf test AVA.

@s-a
s-a commented Jan 29, 2016

I find this very intersting! Are you willing to share your workflow to profile your software in something like markdown documentation? I like to link from my repo to share your work with the community. Just want to say... keep in mind that results might differ from native node but it will in fact deliver insightful results.

@sindresorhus
Member

@s-a I added a short section in https://github.com/sindresorhus/ava/blob/master/maintaining.md#profiling. Was hoping @jamestalmage would fill it out with his workflow.

@s-a
s-a commented Jan 29, 2016

👍 I can not wait to read it . :) @jamestalmage Please ping me here when you finished.

@mattdesl

I'm also interested in the progress of this thread and how we can combine efforts with devtool to provide better debugging/profiling all around.

e.g. The setTimeout issue was resolved in a recent commit to devtool, since now we are using true Node.js timers instead of the built-in browser timers.
s-a/iron-node#85

Relevant commit:
Jam3/devtool@11e491c

@jamestalmage jamestalmage deleted the jamestalmage:profile-script branch Jan 29, 2016
@sindresorhus
Member

Relevant: https://github.com/Jam3/devtool#iron-node

@mattdesl Is there anything devtools is worse at than iron-node for our needs (profiling CPU usage)?

@jamestalmage
Member

I just played with devtool, it seems great, and it already works with profile.js.

devtool node_modules/ava/profile.js test/someTest.js

@mattdesl @s-a, with either project, is there a way to tell Chrome DevTools to start recording a CPU profile programmatically? It would be awesome not to have to start the recording and then reload the page.

@sindresorhus
Member

@jamestalmage console.profile('foo') and console.profileEnd('foo').

@mattdesl

I think the differences will be subtle between the two tools, though my end goal is to have devtool support most Node.js use cases with minimal effort (which involves lots of tweaks for require.main, process, and all that).

You can use console.profile("foo") and console.profileEnd("foo"). So you could programmatically add profiles for files or whatever.

I am currently writing a blog post on all things devtool, you can see it here:
http://mattdesl.svbtle.com/debugging-nodejs-in-chrome-devtools

@jamestalmage
Member

I am currently writing a blog post on all things devtool

Awesome - great writeup - I just added it to #489

console.profile('foo')

@mattdesl @s-a Feedback on #491 would be appreciated.

@s-a
s-a commented Jan 30, 2016

@jamestalmage sorry #491 is out of my scope. I feel this could have something to do with

e.g. The setTimeout issue was resolved in a recent commit to devtool, since now we are using true Node.js timers instead of the built-in browser timers.

As matt metioned in his README.md devTool is in an experimental state.

Note: This tool is still in early stages. So far it has only been tested on a couple of OSX machines. :)

However FYI just added https://github.com/s-a/iron-node/blob/master/docs/PROFILE.md. There is a lot more work todo. :) Nice weekend @all 😄

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment