approvals / Approvals.NodeJS

Approval Tests implementation in NodeJS
Apache License 2.0
105 stars 41 forks source link

Slow performance on Windows #20

Closed robdmoore closed 9 years ago

robdmoore commented 9 years ago

Hi,

Great project! Really glad to see that approvals has been ported to JavaScript (I use it extensively via .NET).

I'm not sure on what the performance expectations are for this project on Windows and I'm a little surprised with how long it seems to take to do an approval.

For instance, I just ran the following on a number of computers we have here:

var approvals = require('approvals');

console.log (new Date().getTime() + " Starting");
try {
    approvals.verify(__dirname, "test", "asdf");
} catch (e) {
    console.log (e);
}
console.log (new Date().getTime() + " Finishing");

And it's taking between 1s - 3s depending on the machine and the diff viewer (e.g. kdiff, tortoisediff, p4merge, git diff). e.g.:

C:\dev\temp\> node main.js
1429163375410 Starting
CMD: C:/Program Files/TortoiseGit/bin/TortoiseGitMerge.exe C:\dev\temp\test.
received.txt C:\dev\temp\test.approved.txt
File sizes do not match:
Approved: C:\dev\temp\test.approved.txt
Received: C:\dev\temp\test.received.txt

1429163377028 Finishing

Is this expected? Is there anything I can do to improve performance? Is there any more information I can send you to help diagnose?

Thanks!

staxmanade commented 9 years ago

Agreed... Running the tests on windows is much slower then on a Mac.

I haven't looked into why, but my assumption might be the work it does to try and find a diff program in various ways. (But haven't measured or done any specific perf investigations)

Would appreciate anything you find or dig up. Let me know if you have any questions.

isidore commented 9 years ago

What is the speed if the test passes?

The reason I ask is 1-3 seconds is to judge the size of this problem. it's okish if it doesn't add up. so if 1000 tests run fast and the slowness is when 1 of them fail then it's not a huge issue. if 1000 tests X 1-3 seconds it's a complete issue.

robdmoore commented 9 years ago

@isidore great question. I'll check that out and get back to you, but anecdotal evidence from my tests that do pass is it's still slow.

@staxmanade I wonder if we compare the approvals.net code with the nodejs version? I've never had perf problems I noticed with the .NET one.

robdmoore commented 9 years ago

FYI I'm getting similar times for a valid result as the failed result

robdmoore commented 9 years ago

If it helps I get this using node --prof main.js && node-tick-processor:

Statistical profiling result from v8.log, (803 ticks, 780 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
    780   97.1%

 [Shared libraries]:
   ticks  total  nonlib   name

 [JavaScript]:
   ticks  total  nonlib   name
    239   29.8%   29.8%  LazyCompile: *fs.openSync fs.js:499:23
    198   24.7%   24.7%  LazyCompile: *fs.closeSync fs.js:470:24
     92   11.5%   11.5%  LazyCompile: *fs.writeSync fs.js:611:24
     74    9.2%    9.2%  LazyCompile: fs.existsSync fs.js:232:25
     19    2.4%    2.4%  LazyCompile: ~fs.openSync fs.js:499:23
     15    1.9%    1.9%  LazyCompile: *captureStackTrace native messages.js:831:49
     10    1.2%    1.2%  LazyCompile: ~fs.writeSync fs.js:611:24
      9    1.1%    1.1%  LazyCompile: ~runInThisContext node.js:740:28
      9    1.1%    1.1%  LazyCompile: Join native array.js:75:14
      6    0.7%    0.7%  LazyCompile: ~exports.runInThisContext vm.js:72:36
      6    0.7%    0.7%  LazyCompile: *DefineObjectProperty native v8natives.js:494:30
      4    0.5%    0.5%  LazyCompile: ~fs.unlinkSync fs.js:885:25
      4    0.5%    0.5%  LazyCompile: ~fs.statSync fs.js:799:23
      4    0.5%    0.5%  LazyCompile: ~ChildProcess.spawn child_process.js:1108:40
      4    0.5%    0.5%  LazyCompile: *StringSplitOnRegExp native string.js:416:29
      3    0.4%    0.4%  LazyCompile: ~win32.resolve path.js:84:25
      3    0.4%    0.4%  LazyCompile: ~fs.lstatSync fs.js:794:24
      3    0.4%    0.4%  LazyCompile: ~fs.closeSync fs.js:470:24
      3    0.4%    0.4%  LazyCompile: ~captureStackTrace native messages.js:831:49
      3    0.4%    0.4%  LazyCompile: ~DefineObjectProperty native v8natives.js:494:30
      2    0.2%    0.2%  Stub: CallICStub(args(0), FUNCTION, 
      2    0.2%    0.2%  LazyCompile: ~replace native string.js:122:23
      2    0.2%    0.2%  LazyCompile: ~ToPropertyDescriptor native v8natives.js:269:30
      2    0.2%    0.2%  LazyCompile: ~Socket._destroy net.js:442:37
      2    0.2%    0.2%  LazyCompile: ~Module._findPath module.js:153:28
      2    0.2%    0.2%  LazyCompile: InstantiateFunction native apinatives.js:31:29
      2    0.2%    0.2%  LazyCompile: *test native regexp.js:145:20
      2    0.2%    0.2%  LazyCompile: *DoRegExpExec native regexp.js:67:22
      2    0.2%    0.2%  Function: ~<anonymous> net.js:1:11
      1    0.1%    0.1%  Stub: StringAddStub
      1    0.1%    0.1%  Stub: CompareICStub
      1    0.1%    0.1%  Stub: CallICStub(args(1), METHOD, 
      1    0.1%    0.1%  Stub: BinaryOpICStub(SUB:Smi*Smi->Smi)
      1    0.1%    0.1%  Stub: BinaryOpICStub(SHR:Smi*Smi->Smi)
      1    0.1%    0.1%  Script: ~native typedarray.js
      1    0.1%    0.1%  Script: ~native string.js
      1    0.1%    0.1%  Script: ~native messages.js
      1    0.1%    0.1%  Script: ~native collection-iterator.js
      1    0.1%    0.1%  Script: ~native array.js
      1    0.1%    0.1%  RegExp: ^([a-zA-Z]:|[\\\\\\/]{2}[^\\\\\\/]+[\\\\\\/]+[^\\\\\\/]+)?([\\\\\\/])?([\\s\\S]*?)$
      1    0.1%    0.1%  LazyCompile: ~writeOrBuffer _stream_writable.js:265:23
      1    0.1%    0.1%  LazyCompile: ~win32._makeLong path.js:286:27
      1    0.1%    0.1%  LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%    0.1%  LazyCompile: ~startup node.js:30:19
      1    0.1%    0.1%  LazyCompile: ~resume_ _stream_readable.js:722:17
      1    0.1%    0.1%  LazyCompile: ~reduce native array.js:1044:21
      1    0.1%    0.1%  LazyCompile: ~realpathSync fs.js:1327:40
      1    0.1%    0.1%  LazyCompile: ~randomHash c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1244:22
      1    0.1%    0.1%  LazyCompile: ~match native string.js:95:23
      1    0.1%    0.1%  LazyCompile: ~indexOf native string.js:53:25
      1    0.1%    0.1%  LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
      1    0.1%    0.1%  LazyCompile: ~filter native array.js:835:21
      1    0.1%    0.1%  LazyCompile: ~exports.execFile child_process.js:649:28
      1    0.1%    0.1%  LazyCompile: ~exports.exec child_process.js:640:24
      1    0.1%    0.1%  LazyCompile: ~exec native regexp.js:98:20
      1    0.1%    0.1%  LazyCompile: ~emit events.js:68:44
      1    0.1%    0.1%  LazyCompile: ~defineProperties native v8natives.js:868:32
      1    0.1%    0.1%  LazyCompile: ~WriteStream tty.js:73:21
      1    0.1%    0.1%  LazyCompile: ~Socket net.js:137:16
      1    0.1%    0.1%  LazyCompile: ~SetUpObject native v8natives.js:1032:21
      1    0.1%    0.1%  LazyCompile: ~SetUpDate native date.js:489:19
      1    0.1%    0.1%  LazyCompile: ~Readable.setEncoding _stream_readable.js:203:42
      1    0.1%    0.1%  LazyCompile: ~Readable _stream_readable.js:99:18
      1    0.1%    0.1%  LazyCompile: ~Module.load module.js:345:33
      1    0.1%    0.1%  LazyCompile: ~LRUCache.set c:\dev\temp\node_modules\approvals\node_modules\glob\node_modules\minimatch\node_modules\lru-cache\lib\lru-cache.js:150:35
      1    0.1%    0.1%  LazyCompile: ~Glob._process c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:352:36
      1    0.1%    0.1%  LazyCompile: ~Buffer.isEncoding buffer.js:161:29
      1    0.1%    0.1%  LazyCompile: ~Buffer buffer.js:48:16
      1    0.1%    0.1%  LazyCompile: ~<anonymous> node.js:515:48
      1    0.1%    0.1%  LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:1068:36
      1    0.1%    0.1%  LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Approvals.js:67:29
      1    0.1%    0.1%  LazyCompile: fs.writeFileSync fs.js:1091:28
      1    0.1%    0.1%  LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
      1    0.1%    0.1%  LazyCompile: EQUALS native runtime.js:9:16
      1    0.1%    0.1%  LazyCompile: ADD native runtime.js:99:13
      1    0.1%    0.1%  LazyCompile: *win32.resolve path.js:84:25
      1    0.1%    0.1%  LazyCompile: *win32.isAbsolute path.js:189:28
      1    0.1%    0.1%  LazyCompile: *win32._makeLong path.js:286:27
      1    0.1%    0.1%  LazyCompile: *normalizeArray path.js:31:24
      1    0.1%    0.1%  LazyCompile: *fs.fstatSync fs.js:790:24
      1    0.1%    0.1%  LazyCompile: *DefineOwnProperty native v8natives.js:708:27
      1    0.1%    0.1%  KeyedLoadPolymorphicIC:  {137}
      1    0.1%    0.1%  Function: ~<anonymous> console.js:1:11
      1    0.1%    0.1%  Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:6:10
      1    0.1%    0.1%  Function: ~<anonymous> buffer.js:1:11
      1    0.1%    0.1%  Builtin: JSEntryTrampoline

 [C++]:
   ticks  total  nonlib   name

 [GC]:
   ticks  total  nonlib   name
      6    0.7%

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
    239   29.8%  LazyCompile: *fs.openSync fs.js:499:23
    239  100.0%    LazyCompile: fs.writeFileSync fs.js:1091:28
    238   99.6%      LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    238  100.0%        LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    238  100.0%          LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    238  100.0%            LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34

    198   24.7%  LazyCompile: *fs.closeSync fs.js:470:24
    197   99.5%    LazyCompile: fs.writeFileSync fs.js:1091:28
    197  100.0%      LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    197  100.0%        LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    197  100.0%          LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    197  100.0%            LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34

     92   11.5%  LazyCompile: *fs.writeSync fs.js:611:24
     92  100.0%    LazyCompile: fs.writeFileSync fs.js:1091:28
     92  100.0%      LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
     92  100.0%        LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
     92  100.0%          LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
     92  100.0%            LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34

     74    9.2%  LazyCompile: fs.existsSync fs.js:232:25
     73   98.6%    LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
     73  100.0%      LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
     73  100.0%        LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
     73  100.0%          LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
     63   86.3%            LazyCompile: ~searchForExecutable c:\dev\temp\node_modules\approvals\lib\AUtils.js:84:36
     10   13.7%            LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34

     19    2.4%  LazyCompile: ~fs.openSync fs.js:499:23
     19  100.0%    LazyCompile: fs.writeFileSync fs.js:1091:28
     19  100.0%      LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
     19  100.0%        LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
     19  100.0%          LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
     19  100.0%            LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34

 [Top down (heavy) profile]:
  Note: callees occupying less than 0.1% are not shown.

  inclusive      self           name
  ticks   total  ticks   total
    760   94.6%      0    0.0%  Function: ~<anonymous> node.js:27:10
    760   94.6%      1    0.1%    LazyCompile: ~startup node.js:30:19
    748   93.2%      0    0.0%      LazyCompile: ~Module.runMain module.js:499:26
    747   93.0%      0    0.0%        LazyCompile: Module._load module.js:273:24
    745   92.8%      0    0.0%          LazyCompile: ~Module.load module.js:345:33
    745   92.8%      0    0.0%            LazyCompile: ~Module._extensions..js module.js:476:37
    744   92.7%      0    0.0%              LazyCompile: ~Module._compile module.js:378:37
    744   92.7%      0    0.0%                Function: <anonymous> c:\dev\temp\main.js:1:11
    726   90.4%      0    0.0%                  LazyCompile: ~exports.verify c:\dev\temp\node_modules\approvals\lib\Approvals.js:108:27
    714   88.9%      0    0.0%                    LazyCompile: loadReporter c:\dev\temp\node_modules\approvals\lib\Reporters\ReporterFactory.js:4:29
    714   88.9%      0    0.0%                      LazyCompile: ~loadAllReporters c:\dev\temp\node_modules\approvals\lib\Reporters\ReporterFactory.js:36:33
    714   88.9%      0    0.0%                        LazyCompile: ~forEach native array.js:863:22
    714   88.9%      0    0.0%                          LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Reporters\ReporterFactory.js:39:32
    714   88.9%      0    0.0%                            LazyCompile: loadReporter c:\dev\temp\node_modules\approvals\lib\Reporters\ReporterFactory.js:4:29
    280   34.9%      0    0.0%                              LazyCompile: ~P4MergeReporter c:\dev\temp\node_modules\approvals\lib\Reporters\p4mergeReporter.js:4:32
    280   34.9%      0    0.0%                                LazyCompile: ~searchForExecutable c:\dev\temp\node_modules\approvals\lib\AUtils.js:84:36
    280   34.9%      0    0.0%                                  LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
    146   18.2%      0    0.0%                                    LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    146   18.2%      0    0.0%                                      LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    146   18.2%      0    0.0%                                        LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    116   14.4%      0    0.0%                                          LazyCompile: fs.writeFileSync fs.js:1091:28
     64    8.0%     57    7.1%                                            LazyCompile: *fs.openSync fs.js:499:23
      7    0.9%      0    0.0%                                              LazyCompile: *win32._makeLong path.js:286:27
      6    0.7%      0    0.0%                                                LazyCompile: ~win32.resolve path.js:84:25
      4    0.5%      0    0.0%                                                  LazyCompile: ~join native array.js:272:19
      3    0.4%      2    0.2%                                                    LazyCompile: Join native array.js:75:14
      1    0.1%      1    0.1%                                                      Builtin: JSEntryTrampoline
      1    0.1%      1    0.1%                                                    Stub: BinaryOpICStub(SHR:Smi*Smi->Smi)
      1    0.1%      1    0.1%                                                  LazyCompile: *win32.isAbsolute path.js:189:28
      1    0.1%      0    0.0%                                                  LazyCompile: *split native string.js:399:23
      1    0.1%      0    0.0%                                                    LazyCompile: *StringSplitOnRegExp native string.js:416:29
      1    0.1%      1    0.1%                                                      LazyCompile: *DoRegExpExec native regexp.js:67:22
      1    0.1%      1    0.1%                                                Stub: StringAddStub
     40    5.0%     40    5.0%                                            LazyCompile: *fs.closeSync fs.js:470:24
     12    1.5%     12    1.5%                                            LazyCompile: *fs.writeSync fs.js:611:24
     26    3.2%     22    2.7%                                          LazyCompile: fs.existsSync fs.js:232:25
      3    0.4%      0    0.0%                                            LazyCompile: <anonymous> native messages.js:854:20
      3    0.4%      0    0.0%                                              LazyCompile: <anonymous> native messages.js:854:20
      3    0.4%      1    0.1%                                                LazyCompile: *captureStackTrace native messages.js:831:49
      2    0.2%      0    0.0%                                                  LazyCompile: ~defineProperty native v8natives.js:833:30
      2    0.2%      0    0.0%                                                    LazyCompile: *DefineOwnProperty native v8natives.js:708:27
      2    0.2%      2    0.2%                                                      LazyCompile: *DefineObjectProperty native v8natives.js:494:30
      1    0.1%      0    0.0%                                            LazyCompile: *win32._makeLong path.js:286:27
      1    0.1%      0    0.0%                                              LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                LazyCompile: *split native string.js:399:23
      1    0.1%      1    0.1%                                                  LazyCompile: *StringSplitOnRegExp native string.js:416:29
      2    0.2%      0    0.0%                                          LazyCompile: ~exports.exec child_process.js:640:24
      2    0.2%      1    0.1%                                            LazyCompile: ~exports.execFile child_process.js:649:28
      1    0.1%      0    0.0%                                              LazyCompile: ~exports.spawn child_process.js:983:37
      1    0.1%      1    0.1%                                                LazyCompile: ~ChildProcess.spawn child_process.js:1108:40
      1    0.1%      1    0.1%                                          Stub: CallICStub(args(0), FUNCTION, 
      1    0.1%      0    0.0%                                          LazyCompile: _unlinkSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1457:21
      1    0.1%      1    0.1%                                            LazyCompile: ~fs.unlinkSync fs.js:885:25
    134   16.7%      0    0.0%                                    LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
    134   16.7%      0    0.0%                                      LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    134   16.7%      0    0.0%                                        LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    134   16.7%      0    0.0%                                          LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    113   14.1%      0    0.0%                                            LazyCompile: fs.writeFileSync fs.js:1091:28
     58    7.2%     51    6.4%                                              LazyCompile: *fs.openSync fs.js:499:23
      6    0.7%      0    0.0%                                                LazyCompile: *win32._makeLong path.js:286:27
      3    0.4%      0    0.0%                                                  LazyCompile: *win32.resolve path.js:84:25
      2    0.2%      0    0.0%                                                    LazyCompile: ~join native array.js:272:19
      2    0.2%      2    0.2%                                                      LazyCompile: Join native array.js:75:14
      1    0.1%      0    0.0%                                                    LazyCompile: *split native string.js:399:23
      1    0.1%      1    0.1%                                                      LazyCompile: *StringSplitOnRegExp native string.js:416:29
      2    0.2%      0    0.0%                                                  LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                    LazyCompile: ~join native array.js:272:19
      1    0.1%      0    0.0%                                                      LazyCompile: Join native array.js:75:14
      1    0.1%      1    0.1%                                                        Stub: BinaryOpICStub(SUB:Smi*Smi->Smi)
      1    0.1%      1    0.1%                                                    LazyCompile: *normalizeArray path.js:31:24
      1    0.1%      1    0.1%                                                  LazyCompile: *test native regexp.js:145:20
      1    0.1%      0    0.0%                                                LazyCompile: *nullCheck fs.js:109:19
      1    0.1%      1    0.1%                                                  LazyCompile: ~indexOf native string.js:53:25
     35    4.4%     35    4.4%                                              LazyCompile: *fs.closeSync fs.js:470:24
     20    2.5%     20    2.5%                                              LazyCompile: *fs.writeSync fs.js:611:24
     20    2.5%     10    1.2%                                            LazyCompile: fs.existsSync fs.js:232:25
      5    0.6%      0    0.0%                                              LazyCompile: <anonymous> native messages.js:854:20
      5    0.6%      0    0.0%                                                LazyCompile: <anonymous> native messages.js:854:20
      5    0.6%      4    0.5%                                                  LazyCompile: *captureStackTrace native messages.js:831:49
      1    0.1%      0    0.0%                                                    LazyCompile: ~defineProperty native v8natives.js:833:30
      1    0.1%      0    0.0%                                                      LazyCompile: *DefineOwnProperty native v8natives.js:708:27
      1    0.1%      1    0.1%                                                        LazyCompile: *DefineObjectProperty native v8natives.js:494:30
      5    0.6%      0    0.0%                                              LazyCompile: *win32._makeLong path.js:286:27
      3    0.4%      1    0.1%                                                LazyCompile: *win32.resolve path.js:84:25
      2    0.2%      0    0.0%                                                  LazyCompile: *split native string.js:399:23
      2    0.2%      1    0.1%                                                    LazyCompile: *StringSplitOnRegExp native string.js:416:29
      1    0.1%      1    0.1%                                                      LazyCompile: *DoRegExpExec native regexp.js:67:22
      2    0.2%      0    0.0%                                                LazyCompile: ~win32.resolve path.js:84:25
      2    0.2%      0    0.0%                                                  LazyCompile: ~join native array.js:272:19
      2    0.2%      1    0.1%                                                    LazyCompile: Join native array.js:75:14
      1    0.1%      1    0.1%                                                      KeyedLoadPolymorphicIC:  {137}
      1    0.1%      0    0.0%                                            LazyCompile: _unlinkSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1457:21
      1    0.1%      1    0.1%                                              LazyCompile: ~fs.unlinkSync fs.js:885:25
    150   18.7%      0    0.0%                              LazyCompile: ~OpenDiffReporter c:\dev\temp\node_modules\approvals\lib\Reporters\opendiffReporter.js:4:33
    150   18.7%      0    0.0%                                LazyCompile: ~searchForExecutable c:\dev\temp\node_modules\approvals\lib\AUtils.js:84:36
    150   18.7%      1    0.1%                                  LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
    149   18.6%      0    0.0%                                    LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    149   18.6%      0    0.0%                                      LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    149   18.6%      1    0.1%                                        LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    121   15.1%      1    0.1%                                          LazyCompile: fs.writeFileSync fs.js:1091:28
     39    4.9%     39    4.9%                                            LazyCompile: *fs.closeSync fs.js:470:24
     29    3.6%     24    3.0%                                            LazyCompile: *fs.openSync fs.js:499:23
      4    0.5%      0    0.0%                                              LazyCompile: *win32._makeLong path.js:286:27
      4    0.5%      2    0.2%                                                LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                  LazyCompile: ~join native array.js:272:19
      1    0.1%      1    0.1%                                                    LazyCompile: Join native array.js:75:14
      1    0.1%      0    0.0%                                                  LazyCompile: ~exec native regexp.js:98:20
      1    0.1%      1    0.1%                                                    RegExp: ^([a-zA-Z]:|[\\\\\\/]{2}[^\\\\\\/]+[\\\\\\/]+[^\\\\\\/]+)?([\\\\\\/])?([\\s\\S]*?)$
      1    0.1%      0    0.0%                                              LazyCompile: ~stringToFlags fs.js:420:23
      1    0.1%      1    0.1%                                                Stub: CompareICStub
     20    2.5%     20    2.5%                                            LazyCompile: *fs.writeSync fs.js:611:24
     19    2.4%     19    2.4%                                            LazyCompile: ~fs.openSync fs.js:499:23
     10    1.2%     10    1.2%                                            LazyCompile: ~fs.writeSync fs.js:611:24
      3    0.4%      3    0.4%                                            LazyCompile: ~fs.closeSync fs.js:470:24
     19    2.4%      9    1.1%                                          LazyCompile: fs.existsSync fs.js:232:25
      7    0.9%      0    0.0%                                            LazyCompile: <anonymous> native messages.js:854:20
      7    0.9%      0    0.0%                                              LazyCompile: <anonymous> native messages.js:854:20
      5    0.6%      2    0.2%                                                LazyCompile: *captureStackTrace native messages.js:831:49
      3    0.4%      0    0.0%                                                  LazyCompile: ~defineProperty native v8natives.js:833:30
      3    0.4%      1    0.1%                                                    LazyCompile: *DefineOwnProperty native v8natives.js:708:27
      1    0.1%      1    0.1%                                                      LazyCompile: ~DefineObjectProperty native v8natives.js:494:30
      1    0.1%      1    0.1%                                                      LazyCompile: *DefineObjectProperty native v8natives.js:494:30
      2    0.2%      2    0.2%                                                LazyCompile: ~captureStackTrace native messages.js:831:49
      2    0.2%      1    0.1%                                            LazyCompile: ~win32._makeLong path.js:286:27
      1    0.1%      0    0.0%                                              LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      1    0.1%                                                Stub: CallICStub(args(1), METHOD, 
      1    0.1%      0    0.0%                                            LazyCompile: *win32._makeLong path.js:286:27
      1    0.1%      0    0.0%                                              LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                LazyCompile: *split native string.js:399:23
      1    0.1%      1    0.1%                                                  LazyCompile: *StringSplitOnRegExp native string.js:416:29
      5    0.6%      1    0.1%                                          LazyCompile: ~exports.exec child_process.js:640:24
      4    0.5%      0    0.0%                                            LazyCompile: ~exports.execFile child_process.js:649:28
      3    0.4%      0    0.0%                                              LazyCompile: ~exports.spawn child_process.js:983:37
      3    0.4%      1    0.1%                                                LazyCompile: ~ChildProcess.spawn child_process.js:1108:40
      1    0.1%      0    0.0%                                                  LazyCompile: ~forEach native array.js:863:22
      1    0.1%      0    0.0%                                                    LazyCompile: ~<anonymous> child_process.js:1160:25
      1    0.1%      0    0.0%                                                      LazyCompile: ~createSocket child_process.js:71:22
      1    0.1%      1    0.1%                                                        LazyCompile: ~Socket net.js:137:16
      1    0.1%      0    0.0%                                                  LazyCompile: ~_validateStdio child_process.js:833:24
      1    0.1%      1    0.1%                                                    LazyCompile: ~reduce native array.js:1044:21
      1    0.1%      1    0.1%                                              LazyCompile: ~Readable.setEncoding _stream_readable.js:203:42
      2    0.2%      0    0.0%                                          LazyCompile: ~tempDir c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1279:17
      2    0.2%      0    0.0%                                            LazyCompile: writeableDir c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1259:22
      1    0.1%      0    0.0%                                              LazyCompile: fs.writeFileSync fs.js:1091:28
      1    0.1%      1    0.1%                                                LazyCompile: ~Buffer buffer.js:48:16
      1    0.1%      1    0.1%                                              LazyCompile: fs.existsSync fs.js:232:25
      1    0.1%      0    0.0%                                          LazyCompile: fs.readFileSync fs.js:341:27
      1    0.1%      1    0.1%                                            LazyCompile: *fs.closeSync fs.js:470:24
    144   17.9%      0    0.0%                              LazyCompile: ~TortoiseMergeReporter c:\dev\temp\node_modules\approvals\lib\Reporters\tortoisemergeReporter.js:4:38
    144   17.9%      0    0.0%                                LazyCompile: ~searchForExecutable c:\dev\temp\node_modules\approvals\lib\AUtils.js:84:36
    144   17.9%      0    0.0%                                  LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
    144   17.9%      0    0.0%                                    LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    144   17.9%      0    0.0%                                      LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    144   17.9%      0    0.0%                                        LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    120   14.9%      0    0.0%                                          LazyCompile: fs.writeFileSync fs.js:1091:28
     56    7.0%     55    6.8%                                            LazyCompile: *fs.openSync fs.js:499:23
      1    0.1%      1    0.1%                                              LazyCompile: *win32._makeLong path.js:286:27
     38    4.7%     38    4.7%                                            LazyCompile: *fs.closeSync fs.js:470:24
     26    3.2%     26    3.2%                                            LazyCompile: *fs.writeSync fs.js:611:24
     21    2.6%     14    1.7%                                          LazyCompile: fs.existsSync fs.js:232:25
      6    0.7%      0    0.0%                                            LazyCompile: <anonymous> native messages.js:854:20
      6    0.7%      0    0.0%                                              LazyCompile: <anonymous> native messages.js:854:20
      6    0.7%      5    0.6%                                                LazyCompile: *captureStackTrace native messages.js:831:49
      1    0.1%      0    0.0%                                                  LazyCompile: ~defineProperty native v8natives.js:833:30
      1    0.1%      0    0.0%                                                    LazyCompile: *DefineOwnProperty native v8natives.js:708:27
      1    0.1%      0    0.0%                                                      LazyCompile: *DefineObjectProperty native v8natives.js:494:30
      1    0.1%      1    0.1%                                                        LazyCompile: EQUALS native runtime.js:9:16
      1    0.1%      0    0.0%                                            LazyCompile: *win32._makeLong path.js:286:27
      1    0.1%      0    0.0%                                              LazyCompile: *win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                LazyCompile: ~join native array.js:272:19
      1    0.1%      1    0.1%                                                  LazyCompile: Join native array.js:75:14
      1    0.1%      1    0.1%                                          Stub: CallICStub(args(0), FUNCTION, 
      1    0.1%      0    0.0%                                          LazyCompile: ~exports.exec child_process.js:640:24
      1    0.1%      0    0.0%                                            LazyCompile: ~exports.execFile child_process.js:649:28
      1    0.1%      0    0.0%                                              LazyCompile: ~exports.spawn child_process.js:983:37
      1    0.1%      1    0.1%                                                LazyCompile: ~ChildProcess.spawn child_process.js:1108:40
      1    0.1%      0    0.0%                                          LazyCompile: _unlinkSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1457:21
      1    0.1%      1    0.1%                                            LazyCompile: ~fs.unlinkSync fs.js:885:25
    137   17.1%      0    0.0%                              LazyCompile: ~GitDiffReporter c:\dev\temp\node_modules\approvals\lib\Reporters\gitdiffReporter.js:5:32
    137   17.1%      0    0.0%                                LazyCompile: ~searchForExecutable c:\dev\temp\node_modules\approvals\lib\AUtils.js:84:36
    137   17.1%      0    0.0%                                  LazyCompile: ~findProgramOnPath c:\dev\temp\node_modules\approvals\lib\AUtils.js:55:34
    137   17.1%      0    0.0%                                    LazyCompile: <anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1059:18
    137   17.1%      0    0.0%                                      LazyCompile: ~_exec c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:899:15
    137   17.1%      0    0.0%                                        LazyCompile: execSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1332:18
    110   13.7%      0    0.0%                                          LazyCompile: fs.writeFileSync fs.js:1091:28
     51    6.4%     51    6.4%                                            LazyCompile: *fs.openSync fs.js:499:23
     45    5.6%     45    5.6%                                            LazyCompile: *fs.closeSync fs.js:470:24
     14    1.7%     14    1.7%                                            LazyCompile: *fs.writeSync fs.js:611:24
     24    3.0%     18    2.2%                                          LazyCompile: fs.existsSync fs.js:232:25
      5    0.6%      0    0.0%                                            LazyCompile: <anonymous> native messages.js:854:20
      5    0.6%      0    0.0%                                              LazyCompile: <anonymous> native messages.js:854:20
      5    0.6%      3    0.4%                                                LazyCompile: *captureStackTrace native messages.js:831:49
      2    0.2%      0    0.0%                                                  LazyCompile: ~defineProperty native v8natives.js:833:30
      2    0.2%      0    0.0%                                                    LazyCompile: *DefineOwnProperty native v8natives.js:708:27
      2    0.2%      2    0.2%                                                      LazyCompile: *DefineObjectProperty native v8natives.js:494:30
      1    0.1%      0    0.0%                                            LazyCompile: *win32._makeLong path.js:286:27
      1    0.1%      1    0.1%                                              LazyCompile: *test native regexp.js:145:20
      1    0.1%      0    0.0%                                          LazyCompile: ~randomFileName c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1243:24
      1    0.1%      0    0.0%                                            LazyCompile: ~randomHash c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1244:22
      1    0.1%      1    0.1%                                              LazyCompile: ~randomHash c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1244:22
      1    0.1%      0    0.0%                                          LazyCompile: ~exports.exec child_process.js:640:24
      1    0.1%      0    0.0%                                            LazyCompile: ~exports.execFile child_process.js:649:28
      1    0.1%      0    0.0%                                              LazyCompile: ~exports.spawn child_process.js:983:37
      1    0.1%      1    0.1%                                                LazyCompile: ~ChildProcess.spawn child_process.js:1108:40
      1    0.1%      0    0.0%                                          LazyCompile: _unlinkSync c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1457:21
      1    0.1%      1    0.1%                                            LazyCompile: ~fs.unlinkSync fs.js:885:25
      3    0.4%      0    0.0%                              LazyCompile: ~require module.js:383:19
      3    0.4%      0    0.0%                                LazyCompile: ~Module.require module.js:362:36
      3    0.4%      0    0.0%                                  LazyCompile: Module._load module.js:273:24
      3    0.4%      1    0.1%                                    LazyCompile: ~Module.load module.js:345:33
      2    0.2%      0    0.0%                                      LazyCompile: ~Module._extensions..js module.js:476:37
      1    0.1%      0    0.0%                                        LazyCompile: ~Module._compile module.js:378:37
      1    0.1%      1    0.1%                                          LazyCompile: ~exports.runInThisContext vm.js:72:36
      1    0.1%      0    0.0%                                        LazyCompile: fs.readFileSync fs.js:341:27
      1    0.1%      0    0.0%                                          LazyCompile: *fs.openSync fs.js:499:23
      1    0.1%      0    0.0%                                            LazyCompile: *win32._makeLong path.js:286:27
      1    0.1%      0    0.0%                                              LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                LazyCompile: ~join native array.js:272:19
      1    0.1%      1    0.1%                                                  LazyCompile: Join native array.js:75:14
     11    1.4%      0    0.0%                    LazyCompile: ~require module.js:383:19
     11    1.4%      0    0.0%                      LazyCompile: ~Module.require module.js:362:36
     11    1.4%      0    0.0%                        LazyCompile: Module._load module.js:273:24
      9    1.1%      0    0.0%                          LazyCompile: ~Module.load module.js:345:33
      9    1.1%      0    0.0%                            LazyCompile: ~Module._extensions..js module.js:476:37
      9    1.1%      0    0.0%                              LazyCompile: ~Module._compile module.js:378:37
      5    0.6%      0    0.0%                                Function: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\FileApprover.js:1:11
      5    0.6%      0    0.0%                                  LazyCompile: ~require module.js:383:19
      5    0.6%      0    0.0%                                    LazyCompile: ~Module.require module.js:362:36
      5    0.6%      0    0.0%                                      LazyCompile: Module._load module.js:273:24
      5    0.6%      0    0.0%                                        LazyCompile: ~Module.load module.js:345:33
      5    0.6%      0    0.0%                                          LazyCompile: ~Module._extensions..js module.js:476:37
      5    0.6%      0    0.0%                                            LazyCompile: ~Module._compile module.js:378:37
      5    0.6%      0    0.0%                                              Function: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\AUtils.js:1:11
      5    0.6%      0    0.0%                                                LazyCompile: ~require module.js:383:19
      5    0.6%      0    0.0%                                                  LazyCompile: ~Module.require module.js:362:36
      5    0.6%      0    0.0%                                                    LazyCompile: Module._load module.js:273:24
      4    0.5%      0    0.0%                                                      LazyCompile: ~Module.load module.js:345:33
      4    0.5%      0    0.0%                                                        LazyCompile: ~Module._extensions..js module.js:476:37
      4    0.5%      0    0.0%                                                          LazyCompile: ~Module._compile module.js:378:37
      3    0.4%      0    0.0%                                                            Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\shelljs\shell.js:1:11
      2    0.2%      0    0.0%                                                              LazyCompile: ~require module.js:383:19
      2    0.2%      0    0.0%                                                                LazyCompile: ~Module.require module.js:362:36
      2    0.2%      0    0.0%                                                                  LazyCompile: Module._load module.js:273:24
      2    0.2%      0    0.0%                                                                    LazyCompile: ~NativeModule.require node.js:755:34
      2    0.2%      0    0.0%                                                                      LazyCompile: ~NativeModule.compile node.js:800:44
      1    0.1%      1    0.1%                                                                        LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      0    0.0%                                                                        Function: ~<anonymous> child_process.js:1:11
      1    0.1%      0    0.0%                                                                          LazyCompile: ~NativeModule.require node.js:755:34
      1    0.1%      0    0.0%                                                                            LazyCompile: ~NativeModule.compile node.js:800:44
      1    0.1%      1    0.1%                                                                              LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      1    0.1%                                                              LazyCompile: ~match native string.js:95:23
      1    0.1%      1    0.1%                                                            LazyCompile: ~exports.runInThisContext vm.js:72:36
      1    0.1%      0    0.0%                                                      LazyCompile: ~Module._resolveFilename module.js:321:35
      1    0.1%      0    0.0%                                                        LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                                                          LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%      0    0.0%                                                            LazyCompile: *tryFile module.js:132:17
      1    0.1%      0    0.0%                                                              LazyCompile: statPath module.js:84:18
      1    0.1%      0    0.0%                                                                LazyCompile: ~fs.statSync fs.js:799:23
      1    0.1%      0    0.0%                                                                  LazyCompile: ~win32._makeLong path.js:286:27
      1    0.1%      0    0.0%                                                                    LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%                                                                      LazyCompile: ~join native array.js:272:19
      1    0.1%      1    0.1%                                                                        LazyCompile: Join native array.js:75:14
      2    0.2%      0    0.0%                                Function: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Reporters\ReporterFactory.js:1:11
      2    0.2%      0    0.0%                                  LazyCompile: ~require module.js:383:19
      2    0.2%      0    0.0%                                    LazyCompile: ~Module.require module.js:362:36
      2    0.2%      0    0.0%                                      LazyCompile: Module._load module.js:273:24
      2    0.2%      0    0.0%                                        LazyCompile: ~Module._resolveFilename module.js:321:35
      2    0.2%      0    0.0%                                          LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                                            LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%      0    0.0%                                              LazyCompile: *tryFile module.js:132:17
      1    0.1%      0    0.0%                                                LazyCompile: statPath module.js:84:18
      1    0.1%      0    0.0%                                                  LazyCompile: ~fs.statSync fs.js:799:23
      1    0.1%      0    0.0%                                                    LazyCompile: <anonymous> native messages.js:854:20
      1    0.1%      0    0.0%                                                      LazyCompile: <anonymous> native messages.js:854:20
      1    0.1%      1    0.1%                                                        LazyCompile: ~captureStackTrace native messages.js:831:49
      1    0.1%      0    0.0%                                            LazyCompile: *tryFile module.js:132:17
      1    0.1%      0    0.0%                                              LazyCompile: statPath module.js:84:18
      1    0.1%      1    0.1%                                                LazyCompile: ~fs.statSync fs.js:799:23
      1    0.1%      1    0.1%                                LazyCompile: ~exports.runInThisContext vm.js:72:36
      1    0.1%      0    0.0%                                Function: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\StringWriter.js:1:11
      1    0.1%      0    0.0%                                  LazyCompile: ~require module.js:383:19
      1    0.1%      0    0.0%                                    LazyCompile: ~Module.require module.js:362:36
      1    0.1%      0    0.0%                                      LazyCompile: Module._load module.js:273:24
      1    0.1%      0    0.0%                                        LazyCompile: ~Module._resolveFilename module.js:321:35
      1    0.1%      0    0.0%                                          LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      1    0.1%                                            LazyCompile: ~tryExtensions module.js:141:23
      2    0.2%      0    0.0%                          LazyCompile: ~Module._resolveFilename module.js:321:35
      2    0.2%      0    0.0%                            LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                              LazyCompile: ~tryFile module.js:132:17
      1    0.1%      0    0.0%                                LazyCompile: statPath module.js:84:18
      1    0.1%      1    0.1%                                  LazyCompile: ~fs.statSync fs.js:799:23
      1    0.1%      0    0.0%                              LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%      0    0.0%                                LazyCompile: *tryFile module.js:132:17
      1    0.1%      0    0.0%                                  LazyCompile: statPath module.js:84:18
      1    0.1%      1    0.1%                                    LazyCompile: ~fs.statSync fs.js:799:23
      1    0.1%      0    0.0%                    LazyCompile: ~FileApprover.verify c:\dev\temp\node_modules\approvals\lib\FileApprover.js:5:32
      1    0.1%      0    0.0%                      LazyCompile: ~StringWriter.write c:\dev\temp\node_modules\approvals\lib\StringWriter.js:16:41
      1    0.1%      0    0.0%                        LazyCompile: fs.writeFileSync fs.js:1091:28
      1    0.1%      1    0.1%                          LazyCompile: *fs.openSync fs.js:499:23
      8    1.0%      0    0.0%                  LazyCompile: ~require module.js:383:19
      8    1.0%      0    0.0%                    LazyCompile: ~Module.require module.js:362:36
      8    1.0%      0    0.0%                      LazyCompile: Module._load module.js:273:24
      6    0.7%      0    0.0%                        LazyCompile: ~Module.load module.js:345:33
      6    0.7%      0    0.0%                          LazyCompile: ~Module._extensions..js module.js:476:37
      6    0.7%      0    0.0%                            LazyCompile: ~Module._compile module.js:378:37
      6    0.7%      0    0.0%                              Function: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Approvals.js:1:11
      6    0.7%      0    0.0%                                LazyCompile: ~require module.js:383:19
      6    0.7%      0    0.0%                                  LazyCompile: ~Module.require module.js:362:36
      6    0.7%      0    0.0%                                    LazyCompile: Module._load module.js:273:24
      3    0.4%      0    0.0%                                      LazyCompile: ~Module.load module.js:345:33
      3    0.4%      0    0.0%                                        LazyCompile: ~Module._extensions..js module.js:476:37
      3    0.4%      0    0.0%                                          LazyCompile: ~Module._compile module.js:378:37
      2    0.2%      0    0.0%                                            Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:1:11
      2    0.2%      1    0.1%                                              Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:6:10
      1    0.1%      0    0.0%                                                LazyCompile: ~_.mixin c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:1067:21
      1    0.1%      0    0.0%                                                  LazyCompile: ~_.each._.forEach c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:75:43
      1    0.1%      0    0.0%                                                    LazyCompile: ~forEach native array.js:863:22
      1    0.1%      1    0.1%                                                      LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\underscore\underscore.js:1068:36
      1    0.1%      1    0.1%                                            LazyCompile: ~exports.runInThisContext vm.js:72:36
      3    0.4%      0    0.0%                                      LazyCompile: ~Module._resolveFilename module.js:321:35
      3    0.4%      0    0.0%                                        LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                                          LazyCompile: ~tryPackage module.js:116:20
      1    0.1%      0    0.0%                                            LazyCompile: ~tryFile module.js:132:17
      1    0.1%      0    0.0%                                              LazyCompile: ~realpathSync fs.js:1327:40
      1    0.1%      0    0.0%                                                LazyCompile: ~start fs.js:1350:17
      1    0.1%      1    0.1%                                                  LazyCompile: ~exec native regexp.js:98:20
      1    0.1%      0    0.0%                                          LazyCompile: ~tryFile module.js:132:17
      1    0.1%      0    0.0%                                            LazyCompile: ~realpathSync fs.js:1327:40
      1    0.1%      0    0.0%                                              LazyCompile: ~start fs.js:1350:17
      1    0.1%      1    0.1%                                                LazyCompile: ~fs.lstatSync fs.js:794:24
      1    0.1%      0    0.0%                                          LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%      0    0.0%                                            LazyCompile: ~tryFile module.js:132:17
      1    0.1%      0    0.0%                                              LazyCompile: statPath module.js:84:18
      1    0.1%      0    0.0%                                                LazyCompile: ~fs.statSync fs.js:799:23
      1    0.1%      0    0.0%                                                  LazyCompile: <anonymous> native messages.js:854:20
      1    0.1%      0    0.0%                                                    LazyCompile: <anonymous> native messages.js:854:20
      1    0.1%      0    0.0%                                                      LazyCompile: ~captureStackTrace native messages.js:831:49
      1    0.1%      0    0.0%                                                        LazyCompile: ~defineProperty native v8natives.js:833:30
      1    0.1%      0    0.0%                                                          LazyCompile: ~DefineOwnProperty native v8natives.js:708:27
      1    0.1%      1    0.1%                                                            LazyCompile: ~DefineObjectProperty native v8natives.js:494:30
      2    0.2%      0    0.0%                        LazyCompile: ~Module._resolveFilename module.js:321:35
      2    0.2%      1    0.1%                          LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                            LazyCompile: ~tryPackage module.js:116:20
      1    0.1%      0    0.0%                              LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%      0    0.0%                                LazyCompile: ~tryFile module.js:132:17
      1    0.1%      0    0.0%                                  LazyCompile: ~realpathSync fs.js:1327:40
      1    0.1%      0    0.0%                                    LazyCompile: ~start fs.js:1350:17
      1    0.1%      1    0.1%                                      LazyCompile: ~fs.lstatSync fs.js:794:24
      8    1.0%      0    0.0%                  LazyCompile: ~<anonymous> node.js:213:48
      8    1.0%      0    0.0%                    LazyCompile: ~NativeModule.require node.js:755:34
      8    1.0%      0    0.0%                      LazyCompile: ~NativeModule.compile node.js:800:44
      8    1.0%      1    0.1%                        Function: ~<anonymous> console.js:1:11
      5    0.6%      0    0.0%                          LazyCompile: ~<anonymous> node.js:500:48
      5    0.6%      0    0.0%                            LazyCompile: ~createWritableStdioStream node.js:435:37
      4    0.5%      0    0.0%                              LazyCompile: ~NativeModule.require node.js:755:34
      4    0.5%      0    0.0%                                LazyCompile: ~NativeModule.compile node.js:800:44
      4    0.5%      0    0.0%                                  Function: ~<anonymous> tty.js:1:11
      4    0.5%      0    0.0%                                    LazyCompile: ~NativeModule.require node.js:755:34
      4    0.5%      0    0.0%                                      LazyCompile: ~NativeModule.compile node.js:800:44
      3    0.4%      2    0.2%                                        Function: ~<anonymous> net.js:1:11
      1    0.1%      0    0.0%                                          LazyCompile: ~NativeModule.require node.js:755:34
      1    0.1%      0    0.0%                                            LazyCompile: ~NativeModule.compile node.js:800:44
      1    0.1%      0    0.0%                                              Function: ~<anonymous> timers.js:1:11
      1    0.1%      0    0.0%                                                LazyCompile: ~Instantiate native apinatives.js:10:21
      1    0.1%      1    0.1%                                                  LazyCompile: InstantiateFunction native apinatives.js:31:29
      1    0.1%      1    0.1%                                        LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      0    0.0%                              LazyCompile: ~WriteStream tty.js:73:21
      1    0.1%      0    0.0%                                LazyCompile: ~Socket net.js:137:16
      1    0.1%      0    0.0%                                  LazyCompile: ~Duplex _stream_duplex.js:41:16
      1    0.1%      1    0.1%                                    LazyCompile: ~Readable _stream_readable.js:99:18
      2    0.2%      1    0.1%                          LazyCompile: ~<anonymous> node.js:515:48
      1    0.1%      0    0.0%                            LazyCompile: ~createWritableStdioStream node.js:435:37
      1    0.1%      1    0.1%                              LazyCompile: ~WriteStream tty.js:73:21
      2    0.2%      0    0.0%                  LazyCompile: ~b native v8natives.js:1278:15
      2    0.2%      0    0.0%                    LazyCompile: ~Console.log console.js:54:33
      1    0.1%      0    0.0%                      LazyCompile: ~exports.format util.js:23:26
      1    0.1%      1    0.1%                        LazyCompile: ~replace native string.js:122:23
      1    0.1%      0    0.0%                      LazyCompile: ~Socket.write net.js:621:34
      1    0.1%      0    0.0%                        LazyCompile: ~Writable.write _stream_writable.js:196:36
      1    0.1%      1    0.1%                          LazyCompile: ~writeOrBuffer _stream_writable.js:265:23
      1    0.1%      0    0.0%              LazyCompile: fs.readFileSync fs.js:341:27
      1    0.1%      0    0.0%                LazyCompile: ~assertEncoding fs.js:103:24
      1    0.1%      1    0.1%                  LazyCompile: ~Buffer.isEncoding buffer.js:161:29
      2    0.2%      0    0.0%          LazyCompile: ~Module._resolveFilename module.js:321:35
      2    0.2%      1    0.1%            LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%              LazyCompile: ~tryFile module.js:132:17
      1    0.1%      1    0.1%                LazyCompile: ~realpathSync fs.js:1327:40
      1    0.1%      0    0.0%        LazyCompile: _tickCallback node.js:345:27
      1    0.1%      0    0.0%          LazyCompile: ~<anonymous> _stream_readable.js:716:30
      1    0.1%      1    0.1%            LazyCompile: ~resume_ _stream_readable.js:722:17
      7    0.9%      0    0.0%      LazyCompile: ~NativeModule.require node.js:755:34
      7    0.9%      0    0.0%        LazyCompile: ~NativeModule.compile node.js:800:44
      5    0.6%      0    0.0%          Function: ~<anonymous> module.js:1:11
      5    0.6%      0    0.0%            LazyCompile: ~NativeModule.require node.js:755:34
      5    0.6%      0    0.0%              LazyCompile: ~NativeModule.compile node.js:800:44
      3    0.4%      0    0.0%                Function: ~<anonymous> fs.js:1:11
      2    0.2%      0    0.0%                  LazyCompile: ~NativeModule.require node.js:755:34
      2    0.2%      0    0.0%                    LazyCompile: ~NativeModule.compile node.js:800:44
      2    0.2%      0    0.0%                      Function: ~<anonymous> stream.js:1:11
      2    0.2%      0    0.0%                        LazyCompile: ~NativeModule.require node.js:755:34
      2    0.2%      0    0.0%                          LazyCompile: ~NativeModule.compile node.js:800:44
      2    0.2%      2    0.2%                            LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      0    0.0%                  LazyCompile: ~exports.inherits util.js:632:28
      1    0.1%      0    0.0%                    LazyCompile: ~create native v8natives.js:824:22
      1    0.1%      0    0.0%                      LazyCompile: ~defineProperties native v8natives.js:868:32
      1    0.1%      1    0.1%                        LazyCompile: ~ToPropertyDescriptor native v8natives.js:269:30
      2    0.2%      2    0.2%                LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      1    0.1%          LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      0    0.0%          Function: ~<anonymous> events.js:1:11
      1    0.1%      0    0.0%            LazyCompile: ~NativeModule.require node.js:755:34
      1    0.1%      0    0.0%              LazyCompile: ~NativeModule.compile node.js:800:44
      1    0.1%      1    0.1%                LazyCompile: ~runInThisContext node.js:740:28
      1    0.1%      1    0.1%      LazyCompile: ~win32.resolve path.js:84:25
      1    0.1%      0    0.0%      LazyCompile: ~startup.processConfig node.js:266:35
      1    0.1%      1    0.1%        LazyCompile: ~replace native string.js:122:23
      1    0.1%      0    0.0%      LazyCompile: ~startup.globalVariables node.js:170:37
      1    0.1%      0    0.0%        LazyCompile: ~NativeModule.require node.js:755:34
      1    0.1%      0    0.0%          LazyCompile: ~NativeModule.compile node.js:800:44
      1    0.1%      1    0.1%            Function: ~<anonymous> buffer.js:1:11
      1    0.1%      0    0.0%      LazyCompile: ~create native v8natives.js:824:22
      1    0.1%      1    0.1%        LazyCompile: ~defineProperties native v8natives.js:868:32

      9    1.1%      0    0.0%  LazyCompile: ~emit events.js:68:44
      9    1.1%      0    0.0%    LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Approvals.js:30:28
      5    0.6%      0    0.0%      LazyCompile: ~require module.js:383:19
      5    0.6%      0    0.0%        LazyCompile: ~Module.require module.js:362:36
      5    0.6%      0    0.0%          LazyCompile: Module._load module.js:273:24
      4    0.5%      0    0.0%            LazyCompile: ~Module.load module.js:345:33
      4    0.5%      0    0.0%              LazyCompile: ~Module._extensions..js module.js:476:37
      4    0.5%      0    0.0%                LazyCompile: ~Module._compile module.js:378:37
      3    0.4%      0    0.0%                  Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:1:11
      3    0.4%      0    0.0%                    LazyCompile: ~require module.js:383:19
      3    0.4%      0    0.0%                      LazyCompile: ~Module.require module.js:362:36
      3    0.4%      0    0.0%                        LazyCompile: Module._load module.js:273:24
      3    0.4%      0    0.0%                          LazyCompile: ~Module.load module.js:345:33
      3    0.4%      0    0.0%                            LazyCompile: ~Module._extensions..js module.js:476:37
      3    0.4%      0    0.0%                              LazyCompile: ~Module._compile module.js:378:37
      2    0.2%      0    0.0%                                Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\glob\node_modules\minimatch\minimatch.js:1:11
      2    0.2%      0    0.0%                                  Function: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\glob\node_modules\minimatch\minimatch.js:1:74
      2    0.2%      0    0.0%                                    LazyCompile: ~require module.js:383:19
      2    0.2%      0    0.0%                                      LazyCompile: ~Module.require module.js:362:36
      2    0.2%      0    0.0%                                        LazyCompile: Module._load module.js:273:24
      1    0.1%      0    0.0%                                          LazyCompile: ~Module.load module.js:345:33
      1    0.1%      0    0.0%                                            LazyCompile: ~Module._extensions..js module.js:476:37
      1    0.1%      0    0.0%                                              LazyCompile: fs.readFileSync fs.js:341:27
      1    0.1%      1    0.1%                                                LazyCompile: *fs.fstatSync fs.js:790:24
      1    0.1%      0    0.0%                                          LazyCompile: ~Module._resolveFilename module.js:321:35
      1    0.1%      0    0.0%                                            LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                                              LazyCompile: ~tryPackage module.js:116:20
      1    0.1%      0    0.0%                                                LazyCompile: *tryFile module.js:132:17
      1    0.1%      0    0.0%                                                  LazyCompile: ~realpathSync fs.js:1327:40
      1    0.1%      1    0.1%                                                    LazyCompile: ~fs.lstatSync fs.js:794:24
      1    0.1%      1    0.1%                                LazyCompile: ~exports.runInThisContext vm.js:72:36
      1    0.1%      1    0.1%                  LazyCompile: ~exports.runInThisContext vm.js:72:36
      1    0.1%      0    0.0%            LazyCompile: ~Module._resolveFilename module.js:321:35
      1    0.1%      0    0.0%              LazyCompile: ~Module._findPath module.js:153:28
      1    0.1%      0    0.0%                LazyCompile: ~tryExtensions module.js:141:23
      1    0.1%      0    0.0%                  LazyCompile: *tryFile module.js:132:17
      1    0.1%      0    0.0%                    LazyCompile: statPath module.js:84:18
      1    0.1%      1    0.1%                      LazyCompile: ~fs.statSync fs.js:799:23
      3    0.4%      0    0.0%      LazyCompile: ~map native array.js:928:18
      3    0.4%      0    0.0%        LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Approvals.js:59:26
      3    0.4%      0    0.0%          LazyCompile: ~globSync c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:68:19
      3    0.4%      0    0.0%            LazyCompile: ~glob c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:48:15
      3    0.4%      0    0.0%              LazyCompile: ~Glob c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:83:15
      2    0.2%      0    0.0%                LazyCompile: ~Minimatch c:\dev\temp\node_modules\approvals\node_modules\glob\node_modules\minimatch\minimatch.js:132:20
      1    0.1%      0    0.0%                  LazyCompile: ~make c:\dev\temp\node_modules\approvals\node_modules\glob\node_modules\minimatch\minimatch.js:173:15
      1    0.1%      1    0.1%                    LazyCompile: ~filter native array.js:835:21
      1    0.1%      1    0.1%                  LazyCompile: ~LRUCache.set c:\dev\temp\node_modules\approvals\node_modules\glob\node_modules\minimatch\node_modules\lru-cache\lib\lru-cache.js:150:35
      1    0.1%      0    0.0%                LazyCompile: ~forEach native array.js:863:22
      1    0.1%      0    0.0%                  LazyCompile: ~b native v8natives.js:1278:15
      1    0.1%      0    0.0%                    LazyCompile: ~iterator c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:180:21
      1    0.1%      0    0.0%                      LazyCompile: ~Glob._process c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:352:36
      1    0.1%      0    0.0%                        LazyCompile: Glob._readdir c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:617:36
      1    0.1%      0    0.0%                          LazyCompile: ~Glob._afterReaddir c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:672:41
      1    0.1%      0    0.0%                            LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:446:39
      1    0.1%      0    0.0%                              LazyCompile: ~forEach native array.js:863:22
      1    0.1%      0    0.0%                                LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:533:30
      1    0.1%      1    0.1%                                  LazyCompile: ~Glob._process c:\dev\temp\node_modules\approvals\node_modules\glob\glob.js:352:36
      1    0.1%      0    0.0%      LazyCompile: ~filter native array.js:835:21
      1    0.1%      1    0.1%        LazyCompile: ~<anonymous> c:\dev\temp\node_modules\approvals\lib\Approvals.js:67:29

      3    0.4%      1    0.1%  Script: ~native messages.js
      2    0.2%      0    0.0%    LazyCompile: ~SetUpError native messages.js:837:20
      2    0.2%      0    0.0%      LazyCompile: ~SetUpError.a native messages.js:838:15
      2    0.2%      0    0.0%        LazyCompile: <anonymous> native messages.js:854:20
      2    0.2%      0    0.0%          LazyCompile: ~captureStackTrace native messages.js:831:49
      2    0.2%      0    0.0%            LazyCompile: ~defineProperty native v8natives.js:833:30
      1    0.1%      1    0.1%              LazyCompile: ~ToPropertyDescriptor native v8natives.js:269:30
      1    0.1%      0    0.0%              LazyCompile: ~DefineOwnProperty native v8natives.js:708:27
      1    0.1%      1    0.1%                LazyCompile: ~DefineObjectProperty native v8natives.js:494:30

      2    0.2%      0    0.0%  LazyCompile: ~onread net.js:507:16
      1    0.1%      0    0.0%    LazyCompile: ~maybeDestroy net.js:420:22
      1    0.1%      0    0.0%      LazyCompile: ~Socket.destroy net.js:499:36
      1    0.1%      1    0.1%        LazyCompile: ~Socket._destroy net.js:442:37
      1    0.1%      0    0.0%    LazyCompile: ~emit events.js:68:44
      1    0.1%      0    0.0%      LazyCompile: ~onSocketEnd net.js:257:21
      1    0.1%      0    0.0%        LazyCompile: ~Socket.destroySoon net.js:431:40
      1    0.1%      0    0.0%          LazyCompile: ~Socket.end net.js:406:32
      1    0.1%      0    0.0%            LazyCompile: ~Writable.end _stream_writable.js:436:34
      1    0.1%      0    0.0%              LazyCompile: ~endWritable _stream_writable.js:491:21
      1    0.1%      0    0.0%                LazyCompile: ~finishMaybe _stream_writable.js:478:21
      1    0.1%      0    0.0%                  LazyCompile: ~emit events.js:68:44
      1    0.1%      0    0.0%                    LazyCompile: ~onSocketFinish net.js:208:24
      1    0.1%      0    0.0%                      LazyCompile: ~Socket.destroy net.js:499:36
      1    0.1%      1    0.1%                        LazyCompile: ~Socket._destroy net.js:442:37

      1    0.1%      0    0.0%  Script: ~native v8natives.js
      1    0.1%      1    0.1%    LazyCompile: ~SetUpObject native v8natives.js:1032:21

      1    0.1%      1    0.1%  Script: ~native typedarray.js

      1    0.1%      1    0.1%  Script: ~native string.js

      1    0.1%      0    0.0%  Script: ~native regexp.js
      1    0.1%      0    0.0%    LazyCompile: ~SetUpRegExp native regexp.js:279:21
      1    0.1%      1    0.1%      LazyCompile: ADD native runtime.js:99:13

      1    0.1%      0    0.0%  Script: ~native date.js
      1    0.1%      1    0.1%    LazyCompile: ~SetUpDate native date.js:489:19

      1    0.1%      1    0.1%  Script: ~native collection-iterator.js

      1    0.1%      1    0.1%  Script: ~native array.js

      1    0.1%      0    0.0%  LazyCompile: ~Instantiate native apinatives.js:10:21
      1    0.1%      1    0.1%    LazyCompile: InstantiateFunction native apinatives.js:31:29

      1    0.1%      0    0.0%  LazyCompile: _tickCallback node.js:345:27
      1    0.1%      0    0.0%    LazyCompile: ~<anonymous> _stream_readable.js:903:30
      1    0.1%      1    0.1%      LazyCompile: ~emit events.js:68:44
robdmoore commented 9 years ago

Looks like the slow method is findProgramOnPath in AUtils.js.

2 questions:

var approvals = require('approvals');
for(var i = 0; i < 10; i++) {
    var x = new Date().getTime();
    try {
        approvals.verify(__dirname, "test", "asdf");
    } catch (e) {
        console.log (e);
    }
    var y = new Date().getTime();
    console.log ((y-x) + " ms");
}

Gives me:

c:\dev\temp>node main.js
1587 ms
1249 ms
1238 ms
1387 ms
1476 ms
1521 ms
1484 ms
1675 ms
1619 ms
1780 ms
staxmanade commented 9 years ago

what happens if you comment out the supposed caching?

staxmanade commented 9 years ago

to your question, lazily finding the reporters would be good. They're not at the moment.

robdmoore commented 9 years ago

If I comment out the ReporterFactory.loadReporter line and replace reporter with a {} then I get this:

C:\dev\temp\approvals>node main.js
27 ms
2 ms
2 ms
1 ms
1 ms
1 ms
1 ms
1 ms
1 ms
2 ms
staxmanade commented 9 years ago

:+1: