xolvio / chimp

Tooling that helps you do quality, faster.
MIT License
798 stars 141 forks source link

Much higher memory usage since upgrading to 0.14.10 #88

Closed samhatoum closed 8 years ago

samhatoum commented 8 years ago

From @jamiecollinson on October 7, 2015 16:45

I recently upgraded Meteor to 1.2, and in the process upgraded meteor-cucumber from 0.13.x -> 0.14.10. In the process I migrated to synchronous tests but didn't add anything new. Everything went pretty smoothly but I have noticed much higher memory consumption, to the extent that my CI builds on circleci are running out of memory and failing. The test suite is fairly large at ~1600 steps in all scenarios combined, but I imagine there must be people with much larger suites and I'd hope memory usage shouldn't scale with test steps anyway!

I completely understand this may be velocity, meteor or something else other than meteor-cucumber, but didn't really know where to start looking and wondered if anyone else had experienced something similar? Maybe there's some obvious mistake I've made in translating the tests to synchronous style which could be the culprit?

The following is the memory usage as dumped from circleci when the tests hit the memory limit. Any help gratefully received:

   PID   RSS %CPU COMMAND
 10296 977752 13.7 /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/lib/cucumber-wrapper.js node /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/node_modules/.bin/cucumber.js -r features -r /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/lib/cucumberjs/world.js -r /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/lib/cucumberjs/hooks.js -r /home/ubuntu/RealtimeCRM/tests/cucumber/features --snippets true --tags ~@ignore --format pretty
  9654 728732 38.4 /home/ubuntu/.meteor/packages/meteor-tool/.1.1.9.ltydx3++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/.meteor/packages/meteor-tool/.1.1.9.ltydx3++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/tools/index.js --test
 10100 545384 53.3 /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/tools/index.js run --test-app --port 40654 --include-tests cucumber/fixtures --once --settings /tmp/tmp-10072yRQckNdgDSaG.tmp --raw-logs --release velocity:METEOR@1.2.0.2_1
  3397 475688 3.5 /usr/lib/jvm/jdk1.8.0/jre/bin/java -jar /tmp/clj-inference-0.2.90-standalone.jar --daemon 26667
 10257 374396 5.0 /usr/bin/java -jar /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/node_modules/selenium-standalone/.selenium/selenium-server/2.47.1-server.jar -Dwebdriver.chrome.driver=/home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/node_modules/selenium-standalone/.selenium/chromedriver/2.19-x64-chromedriver -port 45935
 10392 283376 55.5 /opt/google/chrome/chrome --type=renderer --enable-logging --log-level=0 --no-sandbox --test-type=webdriver --enable-deferred-image-decoding --lang=en-US --user-data-dir=/tmp/.com.google.Chrome.Aq3tyO --disable-client-side-phishing-detection --enable-offline-auto-reload --enable-offline-auto-reload-visible-only --enable-pinch-virtual-viewport --enable-delegated-renderer --num-raster-threads=2 --use-image-texture-target=3553 --disable-accelerated-video-decode --disable-webrtc-hw-encoding --disable-gpu-compositing --channel=10313.3.1285023949
 10204 247660 14.0 /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /tmp/meteor-test-runsaas3w/.meteor/local/build/main.js
 10072 160912 1.8 /home/ubuntu/.meteor/packages/meteor-tool/.1.1.9.ltydx3++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/RealtimeCRM/.meteor/local/build/main.js
 10231 104808 1.9 /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/bin/chimp -r /home/ubuntu/RealtimeCRM/tests/cucumber/features --snippets --ddp=http://localhost:40654/ --log=error --screenshotsOnError=true --saveScreenshots=true --screenshotsPath=/tmp/circle-artifacts.gB3zrRF/screenshots/chrome --tags=~@ignore --jsonOutput=/tmp/circle-junit.WejRSzd/chrome.cucumber --browser=chrome --server --serverPort=8866
 10313 101384 14.6 /opt/google/chrome/chrome --disable-setuid-sandbox --enable-logging --no-sandbox --disable-background-networking --disable-client-side-phishing-detection --disable-component-update --disable-default-apps --disable-hang-monitor --disable-popup-blocking --disable-prompt-on-repost --disable-sync --disable-web-resources --enable-logging --ignore-certificate-errors --load-extension=/tmp/.com.google.Chrome.4CS2zl/internal --log-level=0 --metrics-recording-only --no-first-run --password-store=basic --remote-debugging-port=12426 --safebrowsing-disable-auto-update --safebrowsing-disable-download-protection --test-type=webdriver --use-mock-keychain --user-data-dir=/tmp/.com.google.Chrome.Aq3tyO data:,       
 10233 95780  1.1 /home/ubuntu/.meteor/packages/meteor-tool/.1.1.9.ltydx3++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/lib/node_modules/phantomjs/lib/phantom/bin/phantomjs /dev/stdin
  1679 64544  0.3 /usr/lib/erlang/erts-5.8.5/bin/beam.smp -W w -A 64 -P 1048576 -K true -- -root /usr/lib/erlang -progname erl -- -home /var/lib/rabbitmq -- -pa /usr/lib/rabbitmq/lib/rabbitmq_server-3.5.4/sbin/../ebin -noshell -noinput -s rabbit boot -sname rabbit@box192 -boot start_sasl -config /etc/rabbitmq/rabbitmq -kernel inet_default_connect_options [{nodelay,true}] -sasl errlog_type error -sasl sasl_error_logger false -rabbit error_logger {file,"/var/log/rabbitmq/rabbit@box192.log"} -rabbit sasl_error_logger {file,"/var/log/rabbitmq/rabbit@box192-sasl.log"} -rabbit enabled_plugins_file "/etc/rabbitmq/enabled_plugins" -rabbit plugins_dir "/usr/lib/rabbitmq/lib/rabbitmq_server-3.5.4/sbin/../plugins" -rabbit plugins_expand_dir "/var/lib/rabbitmq/mnesia/rabbit@box192-plugins-expand" -os_mon start_cpu_sup false -os_mon start_disksup false -os_mon start_memsup false -mnesia dir "/var/lib/rabbitmq/mnesia/rabbit@box192" -kernel inet_dist_listen_min 25672 -kernel inet_dist_listen_max 25672
   665 56420  0.3 /usr/bin/mongod --config /etc/mongodb.conf
   660 53684  0.1 /usr/bin/java -cp /etc/zookeeper/conf:/usr/share/java/jline.jar:/usr/share/java/log4j-1.2.jar:/usr/share/java/xercesImpl.jar:/usr/share/java/xmlParserAPIs.jar:/usr/share/java/zookeeper.jar -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.local.only=false -Dzookeeper.log.dir=/var/log/zookeeper -Dzookeeper.root.logger=INFO,ROLLINGFILE org.apache.zookeeper.server.quorum.QuorumPeerMain /etc/zookeeper/conf/zoo.cfg
  1379 51152  0.2 /usr/lib/erlang/erts-5.8.5/bin/beam.smp -Bd -K true -A 4 -- -root /usr/lib/erlang -progname erl -- -home /home/couchdb -- -noshell -noinput -os_mon start_memsup false start_cpu_sup false disk_space_check_interval 1 disk_almost_full_threshold 1 -sasl errlog_type error -couch_ini /usr/local/etc/couchdb/default.ini /usr/local/etc/couchdb/local.ini /usr/local/etc/couchdb/default.ini /usr/local/etc/couchdb/local.ini -s couch -pidfile /usr/local/var/run/couchdb/couchdb.pid -heart
   716 45060  0.0 /usr/sbin/mysqld
  9963 44416  0.8 /home/ubuntu/.meteor/packages/meteor-tool/.1.1.9.ltydx3++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/mongodb/bin/mongod --bind_ip 127.0.0.1 --smallfiles --port 3001 --dbpath /home/ubuntu/RealtimeCRM/.meteor/local/db --oplogSize 8 --replSet meteor
 10381 38384  0.3 /opt/google/chrome/chrome --type=renderer --enable-logging --log-level=0 --no-sandbox --test-type=webdriver --enable-deferred-image-decoding --lang=en-US --user-data-dir=/tmp/.com.google.Chrome.Aq3tyO --extension-process --enable-webrtc-hw-h264-encoding --disable-client-side-phishing-detection --enable-offline-auto-reload --enable-offline-auto-reload-visible-only --enable-pinch-virtual-viewport --enable-delegated-renderer --num-raster-threads=2 --use-image-texture-target=3553 --disable-accelerated-video-decode --disable-webrtc-hw-encoding --disable-gpu-compositing --channel=10313.2.652749986
 10341 37836  0.0 /opt/google/chrome/chrome --type=gpu-process --channel=10313.0.1857482260 --enable-logging --log-level=0 --no-sandbox --user-data-dir=/tmp/.com.google.Chrome.Aq3tyO --supports-dual-gpus=false --gpu-driver-bug-workarounds=2,44 --disable-accelerated-video-decode --gpu-vendor-id=0x1013 --gpu-device-id=0x00b8 --gpu-driver-vendor --gpu-driver-version --user-data-dir=/tmp/.com.google.Chrome.Aq3tyO --enable-logging --log-level=0
 10325 28484  0.0 /opt/google/chrome/chrome --type=zygote --enable-logging --log-level=0 --no-sandbox --user-data-dir=/tmp/.com.google.Chrome.Aq3tyO
  2252 22836  0.4 Xvfb :99 -screen 0 1280x1024x24
   885 16732  0.0 /usr/lib/postgresql/9.4/bin/postgres -D /var/lib/postgresql/9.4/main -c config_file=/etc/postgresql/9.4/main/postgresql.conf
 10306 15256  1.1 /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/node_modules/selenium-standalone/.selenium/chromedriver/2.19-x64-chromedriver --port=17903
  3443 12284  0.0 xfwm4 --daemon
 10098 10996  0.0 /home/ubuntu/.meteor/packages/meteor-tool/.1.1.9.ltydx3++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/RealtimeCRM/.meteor/local/build/programs/server/assets/packages/sanjo_long-running-child-process/lib/spawnScript.js 9654 cucumber meteor run --test-app --port 40654 --include-tests cucumber/fixtures --once --settings /tmp/tmp-10072yRQckNdgDSaG.tmp --raw-logs --release velocity:METEOR@1.2.0.2_1
 10229 10928  0.0 /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /tmp/meteor-test-runsaas3w/.meteor/local/build/programs/server/assets/packages/sanjo_long-running-child-process/lib/spawnScript.js 10100 Chimp_8866 /home/ubuntu/.meteor/packages/velocity_meteor-tool/.1.1.9_1.7w8nhl++os.linux.x86_64+web.browser+web.cordova/mt-os.linux.x86_64/dev_bundle/bin/node /home/ubuntu/.meteor/packages/xolvio_cucumber/.0.14.10.1we9gvo++os.linux.x86_64+web.browser+web.cordova/npm/node_modules/chimp/bin/chimp -r /home/ubuntu/RealtimeCRM/tests/cucumber/features --snippets --ddp=http://localhost:40654/ --log=error --screenshotsOnError=true --saveScreenshots=true --screenshotsPath=/tmp/circle-artifacts.gB3zrRF/screenshots/chrome --tags=~@ignore --jsonOutput=/tmp/circle-junit.WejRSzd/chrome.cucumber --browser=chrome --server --serverPort=8866
  2223  7380  0.0 /usr/local/bin/redis-server *:6379              
   995  4832  0.0 /usr/sbin/console-kit-daemon --no-daemon
  1063  4296  0.0 /usr/lib/policykit-1/polkitd --no-debug
 10331  3940  0.0 /opt/google/chrome/nacl_helper --no-sandbox
  2266  3768  0.0 sshd: ubuntu [priv] 
  2469  3032  0.9 sshd: ubuntu@pts/0  
  1277  2904  1.1 /usr/bin/freshclam -d --quiet
   581  2864  0.0 /usr/sbin/sshd -D
 10368  2716  0.0 /usr/lib/x86_64-linux-gnu/gconf/gconfd-2
   890  2696  0.0 postgres: autovacuum launcher process                                                                                       
  2584  2628  0.0 /usr/lib/xfce4/xfconf/xfconfd
     1  2340  0.0 /sbin/init
  3069  2156  0.0 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 116:122
   888  1836  0.0 postgres: writer process                                                                                                    
   887  1828  0.0 postgres: checkpointer process                                                                                              
   891  1824  0.0 postgres: stats collector process                                                                                           
   889  1608  0.0 postgres: wal writer process                                                                                                
   288  1508  0.0 avahi-daemon: running [box192.local]
   269  1464  0.0 rsyslogd -c5
  3395  1380  0.0 /bin/bash
   270  1316  0.0 /sbin/cgproxy --sigstop
   248  1288  0.0 /sbin/udevd --daemon
  1376  1176  0.0 /usr/bin/memcached -m 64 -p 11211 -u memcache -l 127.0.0.1

Copied from original issue: xolvio/meteor-cucumber#223

samhatoum commented 8 years ago

From @Sanjo on October 7, 2015 19:14

Is the RSS column the memory usage? Is it in kB?

Note to me: Maybe Fiber leak (use Fiber pool everywhere instead)

samhatoum commented 8 years ago

From @jamiecollinson on October 8, 2015 6:43

Yep - the RSS column is memory in kB. So the top node process is using over 900mb.

This is much higher than on our production server where the app takes 200 - 300mb depending on number of users.

On Wed, 7 Oct 2015 20:14 Jonas Aschenbrenner notifications@github.com wrote:

Is the RSS column the memory usage? Is it in kB?

Note to me: Maybe Fiber leak (use Fiber pool everywhere instead)

— Reply to this email directly or view it on GitHub https://github.com/xolvio/meteor-cucumber/issues/223#issuecomment-146300029 .

samhatoum commented 8 years ago

From @workflow on October 16, 2015 12:38

Same here with memory usage >4GB and only ~600 steps.

Cucumber: 0.14.11

Anything we can do to help isolate the culprit?

samhatoum commented 8 years ago

Do the # of steps affect the memory usage?

samhatoum commented 8 years ago

From @workflow on October 16, 2015 23:58

Ran a couple of tests (on Ubuntu 14.04, Cucumber 0.14.11) and came up with some hopefully interesting things:

1

General Memory usage after booting up and just before executing the first step seems very high. Especially given that the underlying meteor app itself uses < 300MB when running.

Total Mirror Memory Usage at the beginning of the first step (600 Steps): 2.0GB
Total Mirror Memory Usage at the beginning of the first step (60 Steps): 1.5GB
Total Mirror Memory Usage at the beginning of the first step (6 Steps): 1.3GB

2

Here it get's interesting

That's the result of a test run with ~600 steps, all of them passing:

Full (600 steps, no failing ones):
Just b4 first step: 2.0GB
At finish: 2.4GB

SUCCESSFULLY COMPLETED

Here's the same run with 4 FAILING features (~60 steps or 10%) added.

Full Run (660 steps): 
Just b4 first step: 2.2GB
Later: 2.6
Linearly increasing slowly with big jumps whenever a scenario fails
CRASHED AT 4.0GB RAM USAGE

FATAL ERROR: JS Allocation failed - process out of memory

The step fail errors thrown are all of the kind

      Error: element (#btnSettingsPopover) still not existing after 10000ms
        at World.<anonymous> (features/Investor/discovering/companies/step_definitions/sort.js:17:17)

In conclusio it would seem like failing steps (of the kind above) increase the memory usage significantly.

samhatoum commented 8 years ago

From @jamiecollinson on October 17, 2015 6:58

Anecdotal support for the failing tests use more memory theory - I raised this issue because our circleci builds were hitting the 4GB limit, and after spending some time this week refining our tests to be more robust (we had intermittent failures) our circleci builds just popped back to life and are working again.

I'll try and get some hard numbers after the weekend.

samhatoum commented 8 years ago

From @Sanjo on October 17, 2015 14:21

Maybe the screenshot blobs cause this significant increase of memory usage? Can someone try it with those lines replaced (https://github.com/xolvio/meteor-cucumber/blob/master/src/mirror-server.js#L349-L351) with args.push('--screenshotsOnError=false'); (just clone this repo into the ./packages/ folder before).

samhatoum commented 8 years ago

I think that is the problem, I'm basically capturing the entire screenshot blob into the json report. It's probably better to save the screenshot to disk and reference it from the report.

I'll change this default behavior in the next release

samhatoum commented 8 years ago

From @workflow on October 18, 2015 20:59

Yep, that's it guys! (tested as @Sanjo suggested)

Yay :) @samhatoum - really looking forward to this one

What do you think about the base memory usage as reported above? Normal and expected? Or should I file a separate issue?

samhatoum commented 8 years ago

If the memory is general, then it makes sense since you have Java + chrome + Meteor + mongo etc. Would be good to get a breakdown

samhatoum commented 8 years ago

we've decommissioned xolvio:cucumber - please update to chimp - this shouldn't happen using it

mario-ortiz commented 8 years ago

I've tested this, it seems that I'm no longer getting the memory allocation error with v.0.30. But the JSON report also no longer have Screenshots, maybe there is a new parameter I should send?. This is the command I'm running

node_modules.bin\chimp --offline --screenshotsOnError=true --screenshotsPath=screenshots --captureAllStepScreenshots --attachScreenshotsToReport --saveScreenshots --format=pretty --jsonOutput=out\report.json --host=127.0.0.1 --port=4723 --platform=Android --name="Android Emulator" --tags=@mobile

It was working with version 0.22, but if I had more than 7 scenarios I was getting the memory allocation error. RIght now it's working, its just not attaching images anymore (blob or reference to file in disk).

mario-ortiz commented 8 years ago

There seems to be an error here: if (!stepResult.isSuccessful() && (booleanHelper.isTruthy(process.env['chimp.captureAllStepScreenshots']) || booleanHelper.isTruthy(process.env['chimp.screenshotsOnError']))) {

In the dist\lib\cucumberjs\hooks.js file (around line 45).

stepResult doesn't have a isSuccessful() function, so it never goes to take the screenshot. At least not in my environment. It breaks exactly in that line.