Caching 2.0 #108

jamestalmage · 2015-12-20T22:20:26Z

see #101 for historical conversation.

First, An Apology:

This is PR #101 rebased onto master. The rebase was not entirely smooth, and getting to a perfect git history has proven fairly difficult. My apologies to reviewers, but I think this is about as good as it is going to get.

I have squashed the initial ~27 commits down to 14. The commit messages are now very detailed, so I encourage you to step through them one by one.

Most of the commits are logical units of work, but there are two unfortunate "fixup" commits, that I would have preferred squashing with earlier commits, but reordering the git history to accommodate proved too difficult to be worth it.

A number of the commit messages contain a "Future Changes" section, where I explain what eventually is changed by the "fixup" commits. Not a perfect solution, but hopefully helpful to you as you review.

The meat of the work can be found in the 5 commits linked in the benchmarking section below. Much of those are refactored in future commits, based on feedback received here and in the #101 PR.

Overview:

This PR greatly improves the speed of nyc via a number of strategies, the primary one being caching.

It caches the results of istanbul transforms.
It caches the inline source-maps it extracts before instrumentation. Instead of remapping coverage reports as they are saved to disk, it instead uses the cached source-map information to remap coverage when it is loaded from disk when a report is requested.
It drops our runtime dependency on lodash, which was expensive to require.
It defers requireing instanbul until it is actually needed (i.e. there is a cache miss). istanbul is also expensive to require.
A minor optimization of how we handle globs.

Benchmarks

I decided to use the AVA test suite as my primary benchmark. The AVA test suite forks 50 some processes, nearly all of which collect coverage information. This makes it an ideal candidate for benchmarking nycs performance. I have tested on much simpler projects, and the improvements are noticeable even in projects that only fork one additional process (though I suspect that has to do more with simplifying our dependency graph than caching).

I use the term "coverage penalty" to mean how much additional time the test suite takes to execute when nyc is in use. This provides a better indication of the significance of each optimization.

-	run time	coverage penalty	reduction in penalty
no coverage	25 sec	-	-
nyc master	42 sec	17 sec	-
cache instrumentation (`3f58e88`)	32 sec	7 sec	59%
cache source maps (`2125be0`)	30 sec	5 sec	29% (70% overall)
drop lodash (`0a04c3b`)	~29 sec	4 sec	20% (76% overall)
shortcut include glob (`7452b40`)	28 sec	3 sec	25% (82% overall)

bcoe · 2015-12-20T23:37:43Z

@jamestalmage give this a shot:

https://www.npmjs.com/package/win-fork

jamestalmage · 2015-12-20T23:38:26Z

I found at least part of the problem. See #109

jamestalmage · 2015-12-20T23:54:12Z

test/src/nyc-test.js

+      var nyc = new NYC({cwd: fixtures})
+      nyc.clearCache()
+
+      var args = isWindows ? [bin] : [bin, process.execPath]


This makes me thinks we are making a mistake in mungeArgs when it coms to windows.

jamestalmage · 2015-12-20T23:56:45Z

@novemberborn - This test suite now makes it all the way through to source-maps. Some of the tests you merged into my branch are broken on Windows. It looks like it may just be a matter of different path separators being used.

bcoe · 2015-12-21T00:03:19Z

@jamestalmage make sure you wrap all the appropriate objects with this helper:

https://github.com/bcoe/any-path

YOLO.

jamestalmage · 2015-12-21T00:26:06Z

make sure you wrap all the appropriate objects with this helper

I am OK with that as a temporary solution. I think it would be better if the istanbul spec were changed to insist on posix paths.

bcoe · 2015-12-21T00:44:46Z

test/src/source-map-cache.js

 })

-var coverage = ap(require('../fixtures/coverage'))
+var getReport = function () {
+  return _.cloneDeep(require('../fixtures/report'))


I think if you switch this line to:

return ap(_.cloneDeep(require('../fixtures/report')))

I wouldn't complain if istanbul only stored posix-style paths, it's a bit of an edge-case though -- both \, and / work on Windows, it's just biting us in the lookups we're doing for tests.

Looks like another place I screwed up the rebase.

posix-style paths

yeah, might not even make sense to request that change. Since the spec demands absolute paths anyways, that would make windows paths look really weird: C:/foo/bar

bcoe · 2015-12-21T01:36:56Z

@jamestalmage I can figure out these annoying path issues in my Windows VM, if you want to work on the logic for making caching toggled via a CLI flag.

jamestalmage · 2015-12-21T01:40:53Z

I would be incredibly happy to punt that one to you!!

bcoe · 2015-12-21T04:12:01Z

@jamestalmage if you chery-pick this change:

25eb6a7

I think it will get your tests passing.

jamestalmage · 2015-12-21T05:02:54Z

woot! green tests

jamestalmage · 2015-12-21T05:32:54Z

OK, just pushed an enableCache property on the NYC instance. With it hard coded to false, the tests pass locally.

How do we want to enable/disable the cache?

bcoe · 2015-12-21T05:37:11Z

@jamestalmage my preference would be a flag like this:

https://github.com/bcoe/nyc/blob/master/bin/nyc.js#L72

bcoe · 2015-12-21T05:47:44Z

index.js

+      return report
+    }
+
+    Object.keys(report).forEach(function (relFile) {


This logic is fairly complicated, I'd be tempted to pull it into a logically named "private" method (prefix with _).

an alternative thought, perhaps we try to pull the caching logic into /lib/cache.js, like we did for source-map-cache.js .

Keep index.js as thin as possible.

bcoe · 2015-12-21T06:00:28Z

@jamestalmage since caching is defaulting to false now, I think we suddenly stopped covering quite a bit of the caching logic -- hence coveralls yelling.

It would probably be good to add a couple explicit tests here:

https://github.com/bcoe/nyc/pull/108/files#diff-7332f11ea438d83b6d316f2064202ebbR442

Creating the nyc instance like so:

new NYC({enableCache: true})

Another nit, there's quite a bit of refactoring work on this branch that I think isn't directly related to the cache logic?

https://github.com/bcoe/nyc/pull/108/files#diff-168726dbe96b3ce427e7fedce31bb0bcR107
https://github.com/bcoe/nyc/pull/108/files#diff-168726dbe96b3ce427e7fedce31bb0bcL21

This makes it hard for me to differentiate the logic related to the new cache, vs. other optimizations -- making my code-review less directed and making me more gun-shy about merging.

In a perfect world, we'd land these unrelated changes in separate patches -- this also helps communicate in the git-history, the reasoning behind each change (they all seem logical from what I'm reading).

I should add this is ⭐ ⭐ amazing ⭐ ⭐ work.

jamestalmage · 2015-12-21T06:23:47Z

Another nit, there's quite a bit of refactoring work on this branch that I think isn't directly related to the cache logic

Yeah, I let it get away from me. I could try and squash into a more logical series of commits, then cherrypick into multiple PR's. It might be a pain though. The Windows changes broke a number of things on this branch, and my rebase was less than "smooth"

bcoe · 2015-12-21T06:25:02Z

@jamestalmage perhaps, since there are so many commits from our Windows changes, etc, just amend the git history at some point on this branch, and squash it into a few logical steps?

bcoe · 2015-12-21T06:27:57Z

I'd say, let's shoot for this:

get everything working.
do an interactive squash on this branch and break the changes into logical steps.
update the issue description to provide a description of each refactor, and a thorough description of the caching logic.
loop in a couple more code reviewers, once everything is looking ready.

jamestalmage · 2015-12-21T06:29:42Z

It would probably be good to add a couple explicit tests here:

I opted to just run all the tests twice, both ways. There are probably a number of tests where it doesn't make sense to do the duplication (i.e. _prepGlobPatterns, etc). But I think we should explicitly move those to another test file that does not get run twice. Otherwise I think we end up in situations where we are running lots of duplicate tests, or are not catching corner cases that are different with/without caching.

bcoe · 2015-12-21T06:41:51Z

@jamestalmage running twice seems reasonable to me. Good way to thoroughly test the cache logic 👍

Looks like we just need to figure out a good way to toggle the value -- could you simply generate two copies of each test during the build phase? Maybe I'm blanking on an easier solution for Windows, since I'm tired :)

jamestalmage · 2015-12-21T06:48:26Z

could you simply generate two copies of each test during the build phase

working on that now.

jamestalmage · 2015-12-21T06:57:31Z

test/src/nyc-test.js

@@ -405,7 +421,7 @@ describe('nyc', function () {
      })
      var report = reports[0]['./test/fixtures/not-loaded.js']

-      reports.length.should.equal(1)
+      reports.length.should.equal(enableCache ? 2 : 1)


I had to add this because the tests don't clean up after themselves between runs.
They really should.
After we merge this, we should just add rimraf .... all the output dirs... to the top of the test file. That acts like a beforeEach will get us a clean state for every test.

If that breaks a test because it needed a specific output from a previous test, it should instead explicitly spawn the CLI. That makes our tests much more explicit.

jamestalmage · 2015-12-21T07:39:04Z

@bcoe - OK, I think I've squashed it down as much as I can without things getting painful. It's still not the cleanest history, but reducing further would require a lot of work. I should still go back and add some more detailed commit messages (it is currently just the default squash result - concatenation of all the squashed messages).

@novemberborn - I just squashed your contributions into a single commit.

jamestalmage · 2015-12-21T07:51:06Z

@bcoe - I guess I am a little unclear on how I should use spawn wrap to propagate the cache setting to child processes. Set a process.env variable?

bah - nevermind - just found it

jamestalmage · 2015-12-24T10:28:58Z

OK,
I have bumped caching-transform to a new release that uses write-file-atomic.

I also made the recommended change to _generateReport, this is what I see now:

$  node test/fixtures/_generateReport.js 
Written coverage report.

It exits with a 0 exit code, so I'm guessing that is correct. (I still have no idea what that file does).

jamestalmage · 2015-12-24T10:31:00Z

Assuming CI passes, I think we are good to go.

novemberborn · 2015-12-24T13:27:46Z

I also made the recommended change to _generateReport

Thanks.

It exits with a 0 exit code, so I'm guessing that is correct. (I still have no idea what that file does).

It writes the report.js fixture, which includes coverage reports for source map fixtures, prior to applying the respective source maps. The source-map-cache tests use this report to test whether source maps are applied correctly.

jamestalmage · 2015-12-24T13:29:08Z

Gotcha. I figured out that it wrote report.js bug couldn't figure out what it did.

isaacs · 2015-12-24T20:30:30Z

@jamestalmage

That was what I suspected after reading the source. I have hammered caching-transform with a dozen processes at once, and not seen a failure, but good to get a definitive answer.

Chalk this one up to "aren't file systems fun?"

If you have a dozen processes but it's always reading/writing to the same file, then the OS's heuristics will see that the same file is being read and written repeatedly, and keep it in the file system's cache. (Ie, it won't even get written to disk.) This means that the operations take a lot less time, and race conditions magically disappear! Lovely!

Except, when you have dozens or hundreds of files, especially if they're pretty big, and even a small number of processes, what happens is that the caching mechanisms can't hold all the data, and the race conditions get more relevant again.

So, "works on my machine", "tests all pass", but repeatedly breaks in production. File systems are liars. Well-intended liars that usually make programs faster and more reliable, but... still liars.

Not to mention, often stuff will work fine on a Linux machine, but not on Windows. Or work on a Linux VM on a windows machine, but not on an actual linux machine. Or it'll work on OS X, but not if you use a specific FS option when you set up your machine, or with SSDs but not with spinning platter drives.

And here I thought server side JS would mean getting away from all that browser incompatibility bs. ;P

bcoe · 2015-12-24T20:37:04Z

Great work on this @jamestalmage; I'll do a final pass of tests on the usual suspects, and some testing on Windows -- I'm pretty excited about this branch.

This will automatically invalidate the cache anytime `nyc` or `istanbul` change versions.

bcoe · 2015-12-25T04:43:16Z

@jamestalmage https://twitter.com/jfuerth/status/587249053630648320

bcoe · 2015-12-25T06:55:46Z

@jamestalmage did another smoke test with the current branch, I tested the following libraries with --cache enabled and disabled:

yargs, yarsay, mkdirp, uuid, moment, coffeescript, I found one weird edge-case in the process:

link this branch of nyc.
run the yarsay test-suite with --cache added.
run nyc report --reporter=lcov.

I get the following error:

Everything else worked like a charm.

Even if the `--cache` flag is not set. If the report has a `contentHash` property set, then we know caching was enabled when they generated it. Users shouldn't have to specify `--cache` when running the report command anyways, especially since it's possible for us to auto-detect this.

jamestalmage · 2015-12-25T09:29:24Z

@bcoe fixed in 4d4093b

bcoe · 2015-12-25T18:25:37Z

@jamestalmage unfortunately, I'm still getting this behavior:

I've changed the testing line to the following:

nyc --reporter=lcov --cache --require babel-core/register mocha

So it doesn't appear to be an issue with running report independently of running the actual testing suite.

Again everything works if I don't pass cache, seems like it must be something small.

jamestalmage · 2015-12-25T19:20:45Z

Try deleting the cache. This is yargs right? It all worked for me.

bcoe · 2015-12-25T20:12:02Z

@jamestalmage can't seem to get it to run, I'm testing using yarsay (which is my one library with a babel require hook, so I find it's good for smoke tests).

It would probably be smart for us to create a script that tests against several libraries, rather than my painful manual step.

jamestalmage · 2015-12-25T20:17:04Z

I used yarsay to debug the problem, and made the same script modifications you did. I'm away from my computer most of the day - I can verify later.

Previously, we were only recording the hash in `hashCache` if there was a cache miss. This meant that the `contentHash` property was only properly attached for files not in the cache, and that source maps would not be applied correctly to reports generated from cached instrumentations. The solution is to always store the hash, but selectively attach `contentHash` to the reports based on `options.enableCache`.

jamestalmage · 2015-12-26T19:57:29Z

@bcoe
I found my problem. I was testing almost identically to you, but I had added rm -rf node_modules/.cache to yarsay's pretest script. This mean I always had a cache miss. So I never saw the problem I just fixed in c3b47fc.

bcoe · 2015-12-26T21:26:24Z

@jamestalmage awesome, I will re-test today.

bcoe · 2015-12-27T20:29:58Z

@jamestalmage I've confirmed that everything is working with my set of smoke-testing libraries 👍 rebase and merge at will?

jamestalmage · 2015-12-27T21:29:42Z

I am on mobile ATM, but it appears mergeable now.

Caching

bcoe · 2015-12-28T05:17:35Z

@novemberborn @jamestalmage give the next tag a spin, it has the cache functionality (also we're no longer bundling spawn-wrap).

npm i nyc@next

bcoe · 2015-12-30T23:00:29Z

@novemberborn @jamestalmage @sindresorhus nyc@5.1.1 is out with caching.

ronkorving · 2016-01-07T02:42:33Z

Awesome job guys!

Just some numbers from a very small project to confirm the improvements:

(I took the most average result of 4 runs)

Test only:

$ time ./node_modules/.bin/tape 'test/*.js' > /dev/null 2>&1

real    0m0.590s
user    0m0.519s
sys 0m0.067s

nyc 4.0.0:

$ time ./node_modules/.bin/nyc --silent --all ./node_modules/.bin/tape 'test/*.js' > /dev/null 2>&1

real    0m3.838s
user    0m3.102s
sys 0m0.852s

nyc 5.3.0:

$ time ./node_modules/.bin/nyc --silent --all ./node_modules/.bin/tape 'test/*.js' > /dev/null 2>&1

real    0m1.821s
user    0m1.754s
sys 0m0.183s

So thank you :) This is great!

jamestalmage reviewed Dec 20, 2015
View reviewed changes

bcoe reviewed Dec 21, 2015
View reviewed changes

bcoe changed the title ~~Caching Merged~~ Caching 2.0 Dec 21, 2015

jamestalmage force-pushed the caching-merge branch from 182ee44 to 21be8f5 Compare December 21, 2015 06:50

jamestalmage reviewed Dec 21, 2015
View reviewed changes

jamestalmage force-pushed the caching-merge branch 3 times, most recently from 6a798de to bc4e9b9 Compare December 21, 2015 07:28

jamestalmage force-pushed the caching-merge branch from 26c0665 to f5ace84 Compare December 21, 2015 08:16

fix _generateReport

e29d0ae

properly salt and hash the cache keys.

24e873b

This will automatically invalidate the cache anytime `nyc` or `istanbul` change versions.

jamestalmage mentioned this pull request Dec 26, 2015

A few devops ideas. avajs/ava#374

Closed

jamestalmage mentioned this pull request Dec 26, 2015

Script for automatically "smoke testing" against a set of libraries, looking for regressions. #116

Closed

jamestalmage added a commit that referenced this pull request Dec 27, 2015

Merge pull request #108 from jamestalmage/caching-merge

e4d5c31

Caching

jamestalmage merged commit e4d5c31 into istanbuljs:master Dec 27, 2015

jamestalmage deleted the caching-merge branch December 27, 2015 22:56

bcoe mentioned this pull request Dec 28, 2015

cache instrumentation for speed. #100

Closed

Caching 2.0 #108

Caching 2.0 #108

Conversation

jamestalmage commented Dec 20, 2015

First, An Apology:

Overview:

Benchmarks

bcoe commented Dec 20, 2015

jamestalmage commented Dec 20, 2015

jamestalmage Dec 20, 2015

Choose a reason for hiding this comment

jamestalmage commented Dec 20, 2015

bcoe commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

bcoe Dec 21, 2015

Choose a reason for hiding this comment

jamestalmage Dec 21, 2015

Choose a reason for hiding this comment

bcoe commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

bcoe commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

bcoe commented Dec 21, 2015

bcoe Dec 21, 2015

Choose a reason for hiding this comment

bcoe Dec 21, 2015

Choose a reason for hiding this comment

novemberborn Dec 22, 2015

Choose a reason for hiding this comment

bcoe commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

bcoe commented Dec 21, 2015

bcoe commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

bcoe commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

jamestalmage Dec 21, 2015

Choose a reason for hiding this comment

jamestalmage commented Dec 21, 2015

jamestalmage commented Dec 21, 2015

jamestalmage commented Dec 24, 2015

jamestalmage commented Dec 24, 2015

novemberborn commented Dec 24, 2015

jamestalmage commented Dec 24, 2015

isaacs commented Dec 24, 2015

bcoe commented Dec 24, 2015

bcoe commented Dec 25, 2015

bcoe commented Dec 25, 2015

jamestalmage commented Dec 25, 2015

bcoe commented Dec 25, 2015

jamestalmage commented Dec 25, 2015

bcoe commented Dec 25, 2015

jamestalmage commented Dec 25, 2015

jamestalmage commented Dec 26, 2015

bcoe commented Dec 26, 2015

bcoe commented Dec 27, 2015

jamestalmage commented Dec 27, 2015

bcoe commented Dec 28, 2015

bcoe commented Dec 30, 2015

ronkorving commented Jan 7, 2016