Performance significantly worse than building from a terminal

mbolivar commented 7 years ago

Hi, I'm trying atom from another editor where building from the editor is standard and ran into this package.

I've noticed that build times are significantly longer, at least on a project I build often (the Zephyr RTOS, https://www.zephyrproject.org/, building on Arch Linux with an ARM cross toolchain provided by Zephyr).

Here's my build file (which just times how long it takes to build one of the sample applications):

cmd: time
name: "shell"
args:
  - make
  - -C
  - samples/shell
  - -j8
sh: true,
cwd: /home/mbolivar/src/zephyr
env:
        ZEPHYR_GCC_VARIANT: zephyr
        ZEPHYR_SDK_INSTALL_DIR: /home/mbolivar/bin/zephyr-sdk
        ZEPHYR_BASE: /home/mbolivar/src/zephyr
        PATH: /usr/lib/ccache/bin/:/usr/local/sbin:/usr/local/bin:/usr/bin:/usr/lib/jvm/default/bin:/usr/bin/site_perl:/usr/bin/vendor_perl:/usr/bin/core_perl:/home/mbolivar/bin:/home/mbolivar/bin/arm-none-eabi/bin:/home/mbolivar/bin/arm-eabi/bin:/home/mbolivar/.local/bin:/home/mbolivar/src/zephyr/scripts

The environment variables are needed by the build system; normally you'd do:

. zephyr-env.sh
make -C samples/shell -j8

Results when building from within atom are consistently around 10-12 seconds of wall clock as reported by "time".

Here's an example when building from atom:

make: Entering directory '/home/mbolivar/src/zephyr/samples/shell'
make[1]: Entering directory '/home/mbolivar/src/zephyr'
make[2]: Entering directory '/home/mbolivar/src/zephyr/samples/shell/outdir/qemu_x86'
  Using /home/mbolivar/src/zephyr as source for kernel
  GEN     ./Makefile
  CHK     include/generated/version.h
  CHK     include/generated/offsets.h
  CHK     misc/generated/configs.c
  CHK     misc/generated/sysgen/prj.mdef
make[2]: Leaving directory '/home/mbolivar/src/zephyr/samples/shell/outdir/qemu_x86'
make[1]: Leaving directory '/home/mbolivar/src/zephyr'
make: Leaving directory '/home/mbolivar/src/zephyr/samples/shell'

real    0m12.265s
user    0m7.187s
sys     0m4.037s

Building from the shell is significantly faster, almost exactly 2.7 seconds on the nose each time.

dopey: zephyr (master) mbolivar$ time make -C samples/shell -j8
make: Entering directory '/home/mbolivar/src/zephyr/samples/shell'
make[1]: Entering directory '/home/mbolivar/src/zephyr'
make[2]: Entering directory '/home/mbolivar/src/zephyr/samples/shell/outdir/qemu_x86'
  Using /home/mbolivar/src/zephyr as source for kernel
  GEN     ./Makefile
  CHK     include/generated/version.h
  CHK     misc/generated/configs.c
  CHK     include/generated/offsets.h
  CHK     misc/generated/sysgen/prj.mdef
make[2]: Leaving directory '/home/mbolivar/src/zephyr/samples/shell/outdir/qemu_x86'
make[1]: Leaving directory '/home/mbolivar/src/zephyr'
make: Leaving directory '/home/mbolivar/src/zephyr/samples/shell'

real    0m2.738s
user    0m0.640s
sys 0m0.237s

I took a couple of javascript timelines. Some of the slowness can be attributed to the spawn calls when starting the build from within atom taking about a second or so each. But the extra time is confusing -- the CPU is idle a lot of the time.

Any ideas on how I could diagnose further and maybe speed this up? I'd really like to use this extension (and Atom in general) but this is a significantly slower build at the moment.

Thanks!

noseglid commented 7 years ago

That is very odd indeed. I have not experienced this. What OS are you on?

mbolivar commented 7 years ago

Arch Linux.

Cxarli commented 7 years ago

I'm not sure if this is because of atom-build, or because of Node. It's worth trying to make a javascript file only calling this build command and timing that

mbolivar commented 7 years ago

Edit copy/paste error on first post.

OK, I've re-run the measurements, including with a Javscript file that runs the commands. I've updated Atom and other system software, so all of these measurements are fresh.

In summary, I find that:

atom-build is 5.5x slower than command line on clean builds
running javascript directly is only 1.1x slower than command line on clean builds
atom-build is 5.5x slower on warm builds
running javascript directly is just as fast as command line builds on warm builds

Here is my Atom etc. version:

atom --version
Atom    : 1.15.0
Electron: 1.4.15
Chrome  : 53.0.2785.143
Node    : 6.5.0

atom-build is at version 0.67.0.

Here's the JS I ran (please forgive my naive Javascript):

#!/usr/bin/env node

exec = require('child_process').exec
exec('time make -C samples/shell -j8',
        { 'cwd': '/home/mbolivar/src/zephyr',
          'env': { 'ZEPHYR_GCC_VARIANT': 'zephyr',
                   'ZEPHYR_SDK_INSTALL_DIR': '/home/mbolivar/bin/zephyr-sdk',
                   'ZEPHYR_BASE': '/home/mbolivar/src/zephyr',
                   'PATH': '/usr/lib/ccache/bin/:/usr/local/sbin:/usr/local/bin:/usr/bin:/usr/lib/jvm/default/bin:/usr/bin/site_perl:/usr/bin/vendor_perl:/usr/bin/core_perl:/home/mbolivar/bin:/home/mbolivar/bin/arm-none-eabi/bin:/home/mbolivar/bin/arm-eabi/bin:/home/mbolivar/.local/bin:/home/mbolivar/src/zephyr/scripts'
                 }
        },
        (error, stdout, stderr) => {
                if (error) {
                        console.error(`error ${error}`)
                }
                console.log(`${stdout}`);
                console.log(`${stderr}`);
        });

For better comparison with atom-build, I ran this from within Atom, with atom-runner 2.7.1:

https://atom.io/packages/atom-runner

I ran each build three times, and took the median wall-clock time. I left the Atom runner window open between runs, as that seemed to cut down on ~1 second overhead needed to create the window and populate it, etc. This doesn't seem to be possible with atom-build.

Here is a summary table (with relative speeds to one decimal place for real / wall-clock time) for clean builds:

	Real (s)	Relative
Command line	5.600	1.0
atom-runner	6.168	1.1
atom-build	30.971	5.5

Here is the same table for warm builds (note atom-runner's median time was very slightly faster):

	Real (s)	Relative
Command line	2.743	1.0
atom-runner	2.739	1.0
atom-build	15.134	5.5

Full details for median runs:

Build from command line, clean build (delete build directory between runs, but in-memory file cache is still warm):

real    0m5.600s
user    0m1.797s
sys 0m0.653s

Build with atom-runner, clean build:

real    0m6.168s
user    0m5.093s
sys 0m0.917s

Build with atom-build, clean build:

real    0m30.971s
user    0m19.707s
sys     0m9.967s

Build from command line, warm build (no files changed, object files available in build directory):

real    0m2.743s
user    0m0.653s
sys 0m0.253s

Build from Javascript, warm build:

real    0m2.739s
user    0m0.767s
sys 0m0.350s

Build with atom-build, warm build:

real    0m15.134s
user    0m9.313s
sys     0m5.053s

I speculate that all of the live UI updates atom-build is doing as the build is ongoing may account for some of the slowdown, since the running the Javascript file directly and then printing the final output should share much of the same Atom-specific overhead, but is still much faster.

mbolivar commented 7 years ago

Update: UI updates in atom-build do account for the slowdown.

Variation 1

I tried a similar .atom-build.yml that:

Forces a clean build every time
Silences all build output except the final time values

Here it is:

cmd: rm -r samples/shell/outdir/; time make -C samples/shell -j8 > /dev/null
name: "shell"
sh: true
cwd: /home/mbolivar/src/zephyr
env:
        ZEPHYR_GCC_VARIANT: zephyr
        ZEPHYR_SDK_INSTALL_DIR: /home/mbolivar/bin/zephyr-sdk
        ZEPHYR_BASE: /home/mbolivar/src/zephyr
        PATH: /usr/lib/ccache/bin/:/usr/local/sbin:/usr/local/bin:/usr/bin:/usr/lib/jvm/default/bin:/usr/bin/site_perl:/usr/bin/vendor_perl:/usr/bin/core_perl:/home/mbolivar/bin:/home/mbolivar/bin/arm-none-eabi/bin:/home/mbolivar/bin/arm-eabi/bin:/home/mbolivar/.local/bin:/home/mbolivar/src/zephyr/scripts

The median of three runs by wall clock time is:

real    0m8.182s
user    0m3.753s
sys     0m1.047s

This brings atom-build down from 5.5x slower to 3.1x slower than the command line.

Variation 2

With the same build YML as variation 1, I turned off the running timer from the build view with this patch:

 diff -uN lib/build-view.js.orig lib/build-view.js
--- lib/build-view.js.orig  2017-03-16 23:40:53.940183853 -0400
+++ lib/build-view.js   2017-03-16 23:40:47.743517256 -0400
@@ -281,8 +281,8 @@
   }

   updateTitle() {
-    this.buildTimer.text(((new Date() - this.starttime) / 1000).toFixed(1) + ' s');
-    this.titleTimer = setTimeout(this.updateTitle.bind(this), 100);
+    // this.buildTimer.text(((new Date() - this.starttime) / 1000).toFixed(1) + ' s');
+    // this.titleTimer = setTimeout(this.updateTitle.bind(this), 100);
   }

   close() {

The median was then:

real    0m6.974s
user    0m2.827s
sys     0m0.790s

This brings atom-build down from 3.1x slower to 1.2x slower than command line, which is comparable to the 1.1x slowdown from executing the javascript using atom-runner.

Conclusion the 5.5x slowdown can be explained by UI updates in atom-build taking a long time.

Any suggestions on where to go from here? I wonder if the code in build-view.js can be optimized. A 1.1x or 1.2x slowdown is OK, but 5.5x is unusable for me.

Cxarli commented 7 years ago

Thanks a lot! This will probably speed up the fixing progress. Could you also run a javascript timeline to show us exactly what takes long?

noseglid commented 7 years ago

Thank you for the very detailed and in depth investigation.

We definitely need to to do something about build-view. I'm also pretty sure the terminal emulator I'm using (modified version of term.js) is slow as well as it constantly checks and re-renders control characters common in terminals.

While these may be worthwhile features I think an alternative must be provided which has better performance.

I've been thinking about it for a while and every report I get regarding this indicates that the solution has to be an ability to choose between build views. I'll be looking into extracting the build view component and then have an API integrating with it. Settings in atom-build should allow selecting which View to use.

Once again. Thanks for the report.

mbolivar commented 7 years ago

Sure thing! This is a 'killer' feature for me and I'm very interested in Atom, so I'm glad it's useful.

I'll try to find some time this weekend to take a Javascript timeline.

sgleizes commented 7 years ago

I am having similar performance issues due to UI updates and the above mentioned term.js. CPU load greatly increases when a build command is running, and CPU intensive builds (e.g. cpp) see their build time explode.

Is there any progress on the approach proposed above for a lightweight build-view implementation? Thanks!

noseglid / atom-build

Performance significantly worse than building from a terminal #500