10x slowdown in 0.5.8 after 0.4.0 #334

ahaurw01 · 2013-02-06T22:39:17Z

Anecdotal evidence of troublesome performance decreases in 0.5.8:

I have a suite of about 150 tests being run with the mocha adapter in phantomjs. Using 0.4.0 these tests finish within a little over 1 second. Upgrading to 0.5.8 sees a running time of around 11 seconds.

Is anyone else seeing these results?

vojtajina · 2013-02-07T06:33:23Z

I just tried to run AngularJS unit tests, it's almost 1600 unit tests. The times are comparable.

~/Code/angular.js [testacular-demo *] $ testacular --version
Testacular version: 0.5.8
~/Code/angular.js [testacular-demo *] $ testacular start --browsers Chrome,Safari,PhantomJS
Chrome 24.0 (Mac): Executed 1582 of 1582 SUCCESS (6.37 secs / 5.505 secs)
PhantomJS 1.6 (Mac): Executed 1582 of 1582 SUCCESS (5.047 secs / 4.399 secs)
Safari 6.0 (Mac): Executed 1582 of 1582 SUCCESS (4.382 secs / 3.547 secs)
TOTAL: 4746 SUCCESS
Chrome 24.0 (Mac): Executed 1582 of 1582 SUCCESS (6.049 secs / 5.334 secs)
PhantomJS 1.6 (Mac): Executed 1582 of 1582 SUCCESS (4.809 secs / 4.1 secs)
Safari 6.0 (Mac): Executed 1582 of 1582 SUCCESS (3.785 secs / 3.24 secs)
TOTAL: 4746 SUCCESS
Chrome 24.0 (Mac): Executed 1582 of 1582 SUCCESS (6.203 secs / 5.482 secs)
PhantomJS 1.6 (Mac): Executed 1582 of 1582 SUCCESS (4.855 secs / 4.378 secs)
Safari 6.0 (Mac): Executed 1582 of 1582 SUCCESS (3.974 secs / 3.435 secs)
TOTAL: 4746 SUCCESS

~/Code/angular.js [testacular-demo *] $ testacular --version
Testacular version: 0.4.0
~/Code/angular.js [testacular-demo *] $ testacular start --browsers Chrome,Safari,PhantomJS
PhantomJS 1.6: Executed 1582 of 1582 SUCCESS (4.898 secs / 4.168 secs)
Chrome 24.0: Executed 1582 of 1582 SUCCESS (6.112 secs / 5.271 secs)
Safari 6.0: Executed 1582 of 1582 SUCCESS (4.053 secs / 3.43 secs)
TOTAL: 4746 SUCCESS
PhantomJS 1.6: Executed 1582 of 1582 SUCCESS (4.468 secs / 4.02 secs)
Chrome 24.0: Executed 1582 of 1582 SUCCESS (5.899 secs / 5.436 secs)
Safari 6.0: Executed 1582 of 1582 SUCCESS (3.514 secs / 3.224 secs)
TOTAL: 4746 SUCCESS
PhantomJS 1.6: Executed 1582 of 1582 SUCCESS (4.504 secs / 4.08 secs)
Chrome 24.0: Executed 1582 of 1582 SUCCESS (5.616 secs / 5.2 secs)
Safari 6.0: Executed 1582 of 1582 SUCCESS (3.617 secs / 3.322 secs)
TOTAL: 4746 SUCCESS

vojtajina · 2013-02-07T06:33:58Z

We should definitely investigate this. Speed is very important.

vojtajina · 2013-02-07T06:36:23Z

Do you see this slow down in Chrome as well ?
If so, can you please go to http://localhost:9876/debug.html, open web inspector and try to investigate, where's the time being spent ?

ahaurw01 · 2013-02-07T12:15:11Z

Very interesting. That's a good idea, thanks. I'll do some investigation and report back.

bitwiseman · 2013-02-07T18:57:13Z

Do your tests do a lot of console logging?

ahaurw01 · 2013-02-07T19:06:39Z

Not intentionally, but our mvc framework (ember) often does spit out a bunch of warnings along the way. (Commence angular vs ember jokes ;)
Sorry, haven't had a chance to do more investigation yet.

vojtajina · 2013-02-09T02:35:07Z

@bitwiseman that's a very good point, I think we introduced patching console, so every console.log() means a sending the output to the server.

bitwiseman · 2013-02-15T22:00:27Z

I just found this info about stdout and stderr in [http://nodejs.org/api/process.html#process_process_stdout](the nodejs documentation):

process.stderr and process.stdout are unlike other streams in Node in that writes to them
are usually blocking. They are blocking in the case that they refer to regular files or TTY file
descriptors. In the case they refer to pipes, they are non-blocking like other streams.

It might not be sending to the server that is the worst offender.

ahaurw01 · 2013-02-15T23:27:54Z

I found our tests run just as fast in Chrome and Firefox between 0.4.0 and 0.5.8. Fast across the board there.

The difference lies in phantomjs only. I'm running phantomjs 1.8.1. Although our tests do spit out some console.warns and console.traces, I don't believe this is the root of the cause.

Before the tests run, I did the following:

console.warn = function () {};
console.error = function () {};
console.trace = function () {};

That stops the chatter in the browser when running the tests. I hope that does what I think it does in phantomjs.

Any ideas for profiling phantom?

vojtajina · 2013-02-19T18:48:46Z

Did you null console.log as well ? Just a note, you should be doing this after the jasmine adapter is loaded. Is Testacular still showing "LOG..." in the commandline output ? Coz that would mean, the logs are still sent to the server...

I'm not sure how to profile PhantomJS. But I still think, that this console.log thing might be the problem.

You might try https://github.com/ariya/phantomjs/wiki/Network-Monitoring (capture the browser manually with your script).

stevermeister · 2013-03-13T19:13:32Z

any progress with this issue?

vojtajina · 2013-03-20T00:48:30Z

@ahaurw01 Any updates ?

alindsay55661 · 2013-03-21T22:10:23Z

This is running quite slow for me as well. Here is the output from my latest:

Chrome 25.0 (Mac): Executed 25 of 25 SUCCESS (5.006 secs / 0.02 secs)

Only 25 tests and it is crawling at 5 seconds. At first I thought it was the preprocessor but even after disabling code coverage there is no change. This is painfully slow, anything you can do to speed it up is greatly appreciated.

alindsay55661 · 2013-03-21T22:34:29Z

After upgrading from node 8.11 to 10.1 this is now running about 1 second faster. Also, below is a screenshot of the Chrome browser timeline. Context.html takes 4 seconds to load.

alindsay55661 · 2013-03-21T22:45:53Z

I just realized that I am using v0.8.0 if that helps.

bitwiseman · 2013-03-21T22:46:30Z

Are the tests you speak of for an open source project when we could pull and run them locally for debugging? That would be really helpful.

Is this on windows? OSX?

alindsay55661 · 2013-03-21T22:49:19Z

Unfortunately the tests are not open source so I can't share them. I am running OS X 10.7.5.

alindsay55661 · 2013-03-21T23:28:44Z

Another interesting observation. When I turn on singleRun: true and switch from using karma run to karma start it takes about the same amount of time to run the tests but that time gets reported as much faster:

Chrome 25.0 (Mac): Executed 25 of 25 SUCCESS (0.385 secs / 0.011 secs)

vojtajina · 2013-03-25T18:59:40Z

@alindsay55661 thanks, the chrome timelime helps. This means, Karma spends this time by composing context.html.

Could you try different versions (of testacular as the project got just renamed so there are no older versions of karma). And see which version introduced this ? Can you try 0.4.0 first ?

Can you also run it with --log-level debug and send the output ? I'm just curious how many files are resolved.

Can you try just regular karma start with --no-single-run and rather --auto-watch and rely on triggering the test run by changing a file rather then calling karma run ?

Can you also share your karma.conf.js ? I'm curious about your patterns, because it looks like it take a long time to resolve them.

alindsay55661 · 2013-03-26T16:24:40Z

Yikes, after turning on debug it became obvious what the problem is, or at least part of the problem. On startup the resolver is going through every file in my project, including a deep list of node modules. There are no paths in karma.conf.js that include node modules so not sure why this is happening. At first the resolver lists the paths I am actually using:

DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/index.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/prettify.css" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/prettify.js" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/core-extensions/core.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/core-extensions/index.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/core-extensions/logger.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/auth.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/index.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/locale.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/main.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/router.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/util.js.html" ignored. Does not match any file in the list. DEBUG [watcher]: Changed file "/Users/alindsay/projects/insight-ui/coverage/PhantomJS 1.8 (Mac)/hub-extensions/validation.js.html" ignored. Does not match any file in the list.

But then is lists hundreds of node modules and other files including my .hg directory:

DEBUG [watcher]: Add file "/Users/alindsay/projects/insight-ui/.hg/store/data/src/client/app/app.js.i" ignored. Does not match any pattern.

DEBUG [watcher]: Add file "/Users/alindsay/projects/insight-ui/node_modules/grunt-clean/node_modules/grunt/lib/grunt/cli.js" ignored. Does not match any pattern.

Using karma's --auto-watch works well and the resolver checks only a handful of files, but still it is reporting that several files (the list at the top here) have changed when they haven't, only one file changed. It looks like the changed files that are being reported are internal to karma (html versions of my js files) so I guess that is not a problem (but what happens if one of those files is matched?). But still, I was expecting only one file to be reported as changed.

Node is now running at 100%+ cpu when using karma's --log-level debug.

The problem with using karm's --auto-watch is that I am compiling handlebars templates that get included by karma. So this fits nicely into a grunt task but isn't something I can do directly with karma. Also, it would be nice if karma fit well into a grunt work flow but so far karma run is reporting slower than karma start with single run. So currently I have a grunt task that compiles handlebars templates and then start karma with single run. Maybe in server mode karma is reporting the time it takes to compile the templates, I'm not really sure.

Here is my karma.conf.js:

// Karma configuration
// Generated on Tue Mar 19 2013 16:52:55 GMT-0700 (PDT)


// base path, that will be used to resolve files and exclude
basePath = '';


// list of files / patterns to load in the browser
files = [

  // jasmine
  JASMINE,
  JASMINE_ADAPTER,

  // libraries
  '**/build/development/site/js/lib.js',

  // app
  '**/src/client/core-extensions/*.js',
  '**/src/client/hub-extensions/*.js',
  '**/src/client/modules/**/*.js',
  // '**/src/client/app/app.js',

  // config
  '**/config.development.js',

  // Include stand alone template file
  '**/specs/spec-templates.js',

  // Include special modules used only in specs
  '**/specs/spec-modules.js',

  // specs
  '**/specs/core-extensions/*.js',
  '**/specs/hub-extensions/*.js',
  '**/specs/modules/**/*.js'


];

preprocessors = {
  // '**/build/development/site/js/app.js': 'coverage'
  '**/src/client/core-extensions/*.js': 'coverage',
  '**/src/client/hub-extensions/*.js': 'coverage'
  // '**/src/client/modules/**/*.js': 'coverage'
};

// list of files to exclude
exclude = [

];


// test results reporter to use
// possible values: 'dots', 'progress', 'junit'
reporters = ['progress', 'coverage'];
// reporters = ['progress'];


// web server port
port = 9876;


// cli runner port
runnerPort = 9100;


// enable / disable colors in the output (reporters and logs)
colors = true;


// level of logging
// possible values: LOG_DISABLE || LOG_ERROR || LOG_WARN || LOG_INFO || LOG_DEBUG
logLevel = LOG_INFO;
// logLevel = LOG_DEBUG;


// enable / disable watching file and executing tests whenever any file changes
autoWatch = false;
// autoWatch = true;


// Start these browsers, currently available:
// - Chrome
// - ChromeCanary
// - Firefox
// - Opera
// - Safari (only Mac)
// - PhantomJS
// - IE (only Windows)
browsers = ['PhantomJS'];
// browsers = ['PhantomJS', 'Chrome'];
// browsers = ['Chrome'];


// If browser does not capture in given timeout [ms], kill it
captureTimeout = 60000;


// Continuous Integration mode
// if true, it capture browsers, run tests and exit
// singleRun = true;
singleRun = false;

When I get some time I will take a look at past versions.

vojtajina · 2013-03-29T07:37:56Z

There's nothing like html version of js files in karma, I guess these are your handlebars files or something.

Remove the **/from all the files patterns! Eg. change**/build/development/site/js/lib.jstobuild/development/site/js/lib.js'. This is forcing Karma to watch your whole project directory recursively.

The fact that Karma watches even files that does not match patterns needs to be fixed, it's already on my list.

Ad. watching and compiling stuff. I think you could use a Karma preprocessor for compiling handlebars on the fly. Another solution is to use grunt for that and let Testacular to watch the output (already compiled files) rather then the sources. Does it make sense ?

alindsay55661 · 2013-03-29T16:02:23Z

Yeah makes sense, will give it a try. As far as the html files go, they are definitely not from handlebars. Are you sure these aren't from your Istanbul implementation? I would consider that part of Karma since I never installed it and it automagically works.

vojtajina · 2013-03-29T16:41:36Z

Oh, yep, the istanbul, that's it! Sorry about the confusion.

On Fri, Mar 29, 2013 at 9:02 AM, Alan Lindsay notifications@github.comwrote:

Yeah makes sense, will give it a try. As far as the html files go, they
are definitely not from handlebars. Are you sure these aren't from your
Istanbul implementation? I would consider that part of Karma since I never
installed it and it automagically works.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/334#issuecomment-15647511
.

alindsay55661 · 2013-03-29T16:55:00Z

Ok the change in paths fixed the speed issue for me. If you recently renamed context.html to debug.html then the following screenshot shows the difference.

I had had some issues with the paths before and several posts in this forum were suggesting the use of **/ as a fix. Incidentally that worked for me. I'm glad this is no longer needed, thanks!

vojtajina · 2013-03-29T17:07:32Z

Cool. Btw, no renaming, use debug.html only for debugging (it disables
caching and does not communicate with the server).

On Fri, Mar 29, 2013 at 9:55 AM, Alan Lindsay notifications@github.comwrote:

Ok the change in paths fixed the speed issue for me. If you recently
renamed context.html to debug.html then the following screenshot shows
the difference.

[image: Screen Shot 2013-03-29 at 9 51 51 AM]https://f.cloud.github.com/assets/270710/318229/31ed60e0-9891-11e2-9c91-85b648b37e18.png

I had had some issues with the paths before and several posts in this
forum were suggesting the use of **/ as a fix. Incidentally that worked
for me. I'm glad this is no longer needed, thanks!

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/334#issuecomment-15649774
.

vojtajina · 2013-07-04T07:13:20Z

Ok, I believed we resolved @alindsay55661 's issue.

@ahaurw01 did you figure out ?

I'm planning on adding captureConsole config, so that it is possible to disable sending the logs to the server, which can slow down the test run a bit (if you have a lot of console.logs), however it wouldn't do 10x slower, there must be something else...

RobinHoody · 2013-07-11T11:07:10Z

I'm not sure how much this will help but I've been getting slow down issues where i'm using the jasmine .toContain() function.

E.g.
var test = "display: none";
expect(test).toContain("display: none");

Sometimes I'm searching text larger than above but normally only the innerHTML of an element (so not too much more). I figured if I was doing a search of all the text of the page that would cause an issue but not a small block.

If I use chrome and clear the cache or right click reload -> empty cache and hard reload the tests run in 1.1 seconds but after a couple of runs they can be up to 40 secs and i've only got 40 tests.

I'm doing directive testing so compiling directives and injecting data so I know that can make it run a little slower but there's a significant slow down, maybe it's a memory leak or something in my code.

EDIT: I've just switched to grabbing the css value with jquery and that seems to have sped it up for me.

EDIT 2: I've noticed if I give the chrome browser window focus the tests run in the expected time but otherwise they crawl if the window doesn't have focus (Chrome 28).

ahaurw01 · 2013-07-11T12:34:16Z

I'm sorry I've gone dark, @vojtajina. I actually have switched to using mocha-phantomjs for my needs, which right now is strictly running a set of unit tests on a headless CI server.

mlynch · 2013-09-04T16:56:47Z

Just to follow up on @RobinHoody's comment, I am seeing huge slow-downs running a simple test suite on a tiny angular app when the tab is not focused in Chrome. When I focus the tab the tests complete almost instantly. I'm on Chrome OS X 29.0.1547.65

am17torres · 2013-09-12T21:46:14Z

I am seeing the same thign as @mlynch the first run is when the tab is not in focus, the second is with the tab in focus

Chrome 29.0.1547 (Linux): Executed 4 of 4 SUCCESS (11.998 secs / 3.89 secs)
Chrome 29.0.1547 (Linux): Executed 4 of 4 SUCCESS (0.515 secs / 0.023 secs)

vojtajina · 2013-11-30T07:23:00Z

@mlynch @am17torres yep, that's a good point - the tab has to be "focused" (that's one of the reasons why Karma starts its own browser). If the tab is not focused, the browser does not give it CPU. Karma can't do anything about that.

Guys, is there any other issue?

Also the issue with watching all the files inside node_modules has been fixed.

dignifiedquire · 2015-06-04T08:54:00Z

Closing this for now due to inactivity. Feel free to open a new issue with current information if this is still a problem.

ghost assigned vojtajina Feb 7, 2013

vojtajina mentioned this issue Feb 28, 2013

Allow for multiple preprocessors to be chained #161

Closed

NateRedding mentioned this issue Mar 25, 2014

Severe test performance degradation when using karma-phantomjs-launcher karma-runner/karma-phantomjs-launcher#30

Open

google-admin unassigned vojtajina Mar 26, 2015

dignifiedquire added the type: backlog label May 16, 2015

dignifiedquire closed this as completed Jun 4, 2015

snyk-bot mentioned this issue Nov 7, 2021

[Snyk] Upgrade source-map from 0.6.1 to 0.7.3 ilw4r/karma#1

Open

snyk-bot mentioned this issue Jun 26, 2022

[Snyk] Upgrade source-map from 0.6.1 to 0.7.4 Visva92/karma#4

Open

Chadzzz1 mentioned this issue Nov 5, 2022

[Snyk] Upgrade source-map from 0.6.1 to 0.7.4 Chadzzz1/karma#3

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

10x slowdown in 0.5.8 after 0.4.0 #334

10x slowdown in 0.5.8 after 0.4.0 #334

ahaurw01 commented Feb 6, 2013

vojtajina commented Feb 7, 2013

vojtajina commented Feb 7, 2013

vojtajina commented Feb 7, 2013

ahaurw01 commented Feb 7, 2013

bitwiseman commented Feb 7, 2013

ahaurw01 commented Feb 7, 2013

vojtajina commented Feb 9, 2013

bitwiseman commented Feb 15, 2013

ahaurw01 commented Feb 15, 2013

vojtajina commented Feb 19, 2013

stevermeister commented Mar 13, 2013

vojtajina commented Mar 20, 2013

alindsay55661 commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

bitwiseman commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

vojtajina commented Mar 25, 2013

alindsay55661 commented Mar 26, 2013

vojtajina commented Mar 29, 2013

alindsay55661 commented Mar 29, 2013

vojtajina commented Mar 29, 2013

alindsay55661 commented Mar 29, 2013

vojtajina commented Mar 29, 2013

vojtajina commented Jul 4, 2013

RobinHoody commented Jul 11, 2013

ahaurw01 commented Jul 11, 2013

mlynch commented Sep 4, 2013

am17torres commented Sep 12, 2013

vojtajina commented Nov 30, 2013

dignifiedquire commented Jun 4, 2015

10x slowdown in 0.5.8 after 0.4.0 #334

10x slowdown in 0.5.8 after 0.4.0 #334

Comments

ahaurw01 commented Feb 6, 2013

vojtajina commented Feb 7, 2013

vojtajina commented Feb 7, 2013

vojtajina commented Feb 7, 2013

ahaurw01 commented Feb 7, 2013

bitwiseman commented Feb 7, 2013

ahaurw01 commented Feb 7, 2013

vojtajina commented Feb 9, 2013

bitwiseman commented Feb 15, 2013

ahaurw01 commented Feb 15, 2013

vojtajina commented Feb 19, 2013

stevermeister commented Mar 13, 2013

vojtajina commented Mar 20, 2013

alindsay55661 commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

bitwiseman commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

alindsay55661 commented Mar 21, 2013

vojtajina commented Mar 25, 2013

alindsay55661 commented Mar 26, 2013

vojtajina commented Mar 29, 2013

alindsay55661 commented Mar 29, 2013

vojtajina commented Mar 29, 2013

alindsay55661 commented Mar 29, 2013

vojtajina commented Mar 29, 2013

vojtajina commented Jul 4, 2013

RobinHoody commented Jul 11, 2013

ahaurw01 commented Jul 11, 2013

mlynch commented Sep 4, 2013

am17torres commented Sep 12, 2013

vojtajina commented Nov 30, 2013

dignifiedquire commented Jun 4, 2015