[Buildroot] Build time increase in 2018.02

[Buildroot] Build time increase in 2018.02

[Trent Piepho]

We've seen a big increase in build time with the latest buildroot.  On
a vpshere instance, times have gone up from 45 minutes to 180+ minutes.
 I think there are some issues with poor vm performance that can be
addressed outside of buildroot, but even on a real Linux workstation,
there's been a significant increase in time.

Here's a breakdown of build time by task for a build that takes 26.5
minutes.  ccache is in use and is quite effectively decreasing the
compile time.  I've split out all the instrumentation steps so they can
be accounted separately from the rest of host-install, etc.  In this
list, host-install only includes the time spent executing the install
commands, not instrumentation or pre/post-hooks.

step_pkg_size        831.17
configure            441.77
build                149.56
extract               40.28
host-install          31.96
all other             27.78
check_host_rpath      20.86
check_bin_arch        20.77
target-install        19.84
stage-install         13.25

Finding the package sizes takes more time than everything else put
together.  And indeed, if I remove that step, check_bin_arch, and fake
out check-uniq-files, the build drops from 26.5 minutes to 12 minutes!

If we consider config+buid+extract+*-install to be the actual package
building and the rest overhead, then the build is about %56 overhead
and %44 building.  And most of the building time is (re-)running
autoconf scripts.

On the vsphere instance, the time is much much worse.  I'm still
waiting for numbers.  It takes hours.  I think the lousy vm filesystem
performance magnifies the problem.

[Buildroot] Build time increase in 2018.02

[Peter Korsgaard]

>>>>> "Trent" == Trent Piepho <tpiepho@impinj.com> writes:

Hi,

 > We've seen a big increase in build time with the latest buildroot.  On
 > a vpshere instance, times have gone up from 45 minutes to 180+ minutes.

Wow! What version did you use before upgrading to 2018.02 (the 45min)?

 > Here's a breakdown of build time by task for a build that takes 26.5
 > minutes.  ccache is in use and is quite effectively decreasing the
 > compile time.  I've split out all the instrumentation steps so they can
 > be accounted separately from the rest of host-install, etc.  In this
 > list, host-install only includes the time spent executing the install
 > commands, not instrumentation or pre/post-hooks.

 > step_pkg_size        831.17
 > configure            441.77
 > build                149.56
 > extract               40.28
 > host-install          31.96
 > all other             27.78
 > check_host_rpath      20.86
 > check_bin_arch        20.77
 > target-install        19.84
 > stage-install         13.25

 > Finding the package sizes takes more time than everything else put
 > together.  And indeed, if I remove that step, check_bin_arch, and fake
 > out check-uniq-files, the build drops from 26.5 minutes to 12 minutes!

Argh, that's pretty horrible :/ I have noticed some overhead from the
various instrumentation steps, but nothing as significant as this.

Out of interest, what kind of storage are you building this on? SSD or
spinning disk?

 > On the vsphere instance, the time is much much worse.  I'm still
 > waiting for numbers.  It takes hours.  I think the lousy vm filesystem
 > performance magnifies the problem.

Yes, I/O performance is absolutely critical for stuff like Buildroot.

-- 
Bye, Peter Korsgaard

[Buildroot] Build time increase in 2018.02

[Trent Piepho]

On Sat, 2018-03-10 at 12:32 +0100, Peter Korsgaard wrote:
> > > > > >  > We've seen a big increase in build time with the latest buildroot.  On
>  > a vpshere instance, times have gone up from 45 minutes to 180+ minutes.
> 
> Wow! What version did you use before upgrading to 2018.02 (the 45min)?

2017.11.1.  I see one change that went in between that and 2018.02 is,
"core/pkg-generic: store file->package list for staging and host too"

If I breakdown step_pkg_size by tree:
step_pkg_size-stage      143.50
step_pkg_size-target     267.14
step_pkg_size-host       419.21

The other targets, extract, build, etc. are <1 second.  So adding
package size stats for staging and host is responsible for tripling the
time this step takes.

Looking@how the file accounting is done, it will md5sum the tree
with complexity O(n^2) on the size of the tree.  So it is not
surprising that it is very slow.  It also explains why re-installing a
host package after the build is done slow, since it must md5sum the
entire host tree twice.  At least when building it takes about half as
long since the earlier packages to install have a smaller tree to sum.


>  > step_pkg_size        831.17
>  > configure            441.77
>  > build                149.56
>  > extract               40.28
>  > host-install          31.96
>  > all other             27.78
>  > check_host_rpath      20.86
>  > check_bin_arch        20.77
>  > target-install        19.84
>  > stage-install         13.25
> 
>  > Finding the package sizes takes more time than everything else put
>  > together.  And indeed, if I remove that step, check_bin_arch, and fake
>  > out check-uniq-files, the build drops from 26.5 minutes to 12 minutes!
> 
> Argh, that's pretty horrible :/ I have noticed some overhead from the
> various instrumentation steps, but nothing as significant as this.
> 
> Out of interest, what kind of storage are you building this on? SSD or
> spinning disk?

A good NVMe SSD using PCI-Express.

>  > On the vsphere instance, the time is much much worse.  I'm still
>  > waiting for numbers.  It takes hours.  I think the lousy vm filesystem
>  > performance magnifies the problem.
> 
> Yes, I/O performance is absolutely critical for stuff like Buildroot.

Here's the time for running on a VM.  
targetinstall             29.65
stageinstall              31.57
check_bin_arch            34.11
post_image                38.63
check_host_rpath          41.23
hostinstall               55.40
extract                   72.99
other                     73.77
build                    465.93
configure                689.38
step_pkg_size            2872.76

47 minutes to check the package sizes.

While I don't use a VM myself, the people who run the infrastructure
for the CI and nightly builds think they are great.  It's the way
things are now.  Everyone's IT dept uses vsphere or AWS or some other
tech to allow them to create instances that are decoupled from the
physical hardware present (or in the cloud).

[Buildroot] Build time increase in 2018.02

[Peter Korsgaard]

>>>>> "Trent" == Trent Piepho <tpiepho@impinj.com> writes:

 > On Sat, 2018-03-10 at 12:32 +0100, Peter Korsgaard wrote:
 >> > > > > >  > We've seen a big increase in build time with the latest buildroot.  On
 >> > a vpshere instance, times have gone up from 45 minutes to 180+ minutes.
 >> 
 >> Wow! What version did you use before upgrading to 2018.02 (the 45min)?

 > 2017.11.1.  I see one change that went in between that and 2018.02 is,
 > "core/pkg-generic: store file->package list for staging and host too"

Ok, then lets ensure the author on that patch (Yann) is aware of this
discussion.

 > If I breakdown step_pkg_size by tree:
 > step_pkg_size-stage      143.50
 > step_pkg_size-target     267.14
 > step_pkg_size-host       419.21

 > The other targets, extract, build, etc. are <1 second.  So adding
 > package size stats for staging and host is responsible for tripling the
 > time this step takes.

 > Looking at how the file accounting is done, it will md5sum the tree
 > with complexity O(n^2) on the size of the tree.  So it is not
 > surprising that it is very slow.  It also explains why re-installing a
 > host package after the build is done slow, since it must md5sum the
 > entire host tree twice.  At least when building it takes about half as
 > long since the earlier packages to install have a smaller tree to sum.

This indeed looks quite bad performance wise. Yann, any input?

 >> Argh, that's pretty horrible :/ I have noticed some overhead from the
 >> various instrumentation steps, but nothing as significant as this.
 >> 
 >> Out of interest, what kind of storage are you building this on? SSD or
 >> spinning disk?

 > A good NVMe SSD using PCI-Express.

Ok, nice ;)


 >> > On the vsphere instance, the time is much much worse.  I'm still
 >> > waiting for numbers.  It takes hours.  I think the lousy vm filesystem
 >> > performance magnifies the problem.
 >> 
 >> Yes, I/O performance is absolutely critical for stuff like Buildroot.

 > Here's the time for running on a VM.  
 > targetinstall             29.65
 > stageinstall              31.57
 > check_bin_arch            34.11
 > post_image                38.63
 > check_host_rpath          41.23
 > hostinstall               55.40
 > extract                   72.99
 > other                     73.77
 > build                    465.93
 > configure                689.38
 > step_pkg_size            2872.76

 > 47 minutes to check the package sizes.

 > While I don't use a VM myself, the people who run the infrastructure
 > for the CI and nightly builds think they are great.  It's the way
 > things are now.  Everyone's IT dept uses vsphere or AWS or some other
 > tech to allow them to create instances that are decoupled from the
 > physical hardware present (or in the cloud).

Yes :/

-- 
Bye, Peter Korsgaard

[Buildroot] Build time increase in 2018.02

[Yann E. MORIN]

Trent, All,

On 2018-03-12 18:27 +0000, Trent Piepho spake thusly:
> On Sat, 2018-03-10 at 12:32 +0100, Peter Korsgaard wrote:
> > > > > > >  > We've seen a big increase in build time with the latest buildroot.  On
> >  > a vpshere instance, times have gone up from 45 minutes to 180+ minutes.
> > 
> > Wow! What version did you use before upgrading to 2018.02 (the 45min)?
> 
> 2017.11.1.  I see one change that went in between that and 2018.02 is,
> "core/pkg-generic: store file->package list for staging and host too"
> 
> If I breakdown step_pkg_size by tree:
> step_pkg_size-stage      143.50
> step_pkg_size-target     267.14
> step_pkg_size-host       419.21
> 
> The other targets, extract, build, etc. are <1 second.  So adding
> package size stats for staging and host is responsible for tripling the
> time this step takes.
> 
> Looking at how the file accounting is done, it will md5sum the tree
> with complexity O(n^2) on the size of the tree.  So it is not
> surprising that it is very slow.  It also explains why re-installing a
> host package after the build is done slow, since it must md5sum the
> entire host tree twice.  At least when building it takes about half as
> long since the earlier packages to install have a smaller tree to sum.

I remember very well doing some analysis back when we initially
introduced this feature just for the content of target/ and that the
overhead was virtually unnoticeable:

    http://lists.busybox.net/pipermail/buildroot/2015-February/119431.html

So I did a new round of timing on my machine, just to see how bad this
is.  My machine is: Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz, with an
NVME SSD that can spit out at least 1.4GiB/s:

    $ dd if=/dev/nvme0n1 of=/dev/null bs=16M count=256
    4294967296 bytes (4,3 GB, 4,0 GiB) copied, 2,80702 s, 1,5 GB/s

I first created a single big file of 32GiB, which is twice the RAM I
have, so that I can be sure that nothing gets cached. Then I did a
smaller file, 2GiB, that fits in cache in RAM. I repeated each test
about 10 times, and took the mean value (roughly):

    $ dd if=/dev/urandom of=foo-32G bs=1M count=32768
    $ time md5sum foo-32G
    real    0m54,891s

    $ dd if=/dev/urandom of=foo-2G  bs=1M count=2048
    $ time md5sum foo-2G
    real    0m3,232s

What can be seen with htop and iotop, is that md5sum-ing the 32GiB file
is CPU bound, not I/O bound. And this reflects in the timings: the ratio
is roughly 17x, which can be explained by a 6x size plus I/O scheduling.

So, whether the data fits in cache or not is not meaningful, unless the
storage is not up-to-speed.

Let's say that a 32GiB is highly unlikely, but that a 2GiB is more
reasonable. Also, this is done only for host packages. So, at worst
case, this is ~3s per host package... With 50 host packages, that's
about 150s (worst case), which is very far from the 47 minutes
reported below. Even if we double the host/ size up 4GiB, we get a
3-minute overhead, still far from 47 minutes...

> Here's the time for running on a VM.  
> targetinstall             29.65
> stageinstall              31.57
> check_bin_arch            34.11
> post_image                38.63
> check_host_rpath          41.23
> hostinstall               55.40
> extract                   72.99
> other                     73.77
> build                    465.93
> configure                689.38
> step_pkg_size            2872.76
> 
> 47 minutes to check the package sizes.
> 
> While I don't use a VM myself, the people who run the infrastructure
> for the CI and nightly builds think they are great.  It's the way
> things are now.  Everyone's IT dept uses vsphere or AWS or some other
> tech to allow them to create instances that are decoupled from the
> physical hardware present (or in the cloud).

Yeah, a VM is a performance killer, especially for I/Os... :-/

Regards,
Yann E. MORIN.

-- 
.-----------------.--------------------.------------------.--------------------.
|  Yann E. MORIN  | Real-Time Embedded | /"\ ASCII RIBBON | Erics' conspiracy: |
| +33 662 376 056 | Software  Designer | \ / CAMPAIGN     |  ___               |
| +33 223 225 172 `------------.-------:  X  AGAINST      |  \e/  There is no  |
| http://ymorin.is-a-geek.org/ | _/*\_ | / \ HTML MAIL    |   v   conspiracy.  |
'------------------------------^-------^------------------^--------------------'

[Buildroot] Build time increase in 2018.02

[Trent Piepho]

On Mon, 2018-03-12 at 21:08 +0100, Yann E. MORIN wrote:
> On 2018-03-12 18:27 +0000, Trent Piepho spake thusly:
> > On Sat, 2018-03-10 at 12:32 +0100, Peter Korsgaard wrote:
> > > > > > > >  > We've seen a big increase in build time with the latest buildroot.  On
> > > 
> > >  > a vpshere instance, times have gone up from 45 minutes to 180+ minutes.
> > > 
> > > Wow! What version did you use before upgrading to 2018.02 (the 45min)?
> > 
> > 2017.11.1.  I see one change that went in between that and 2018.02 is,
> > "core/pkg-generic: store file->package list for staging and host too"
> > 
> > If I breakdown step_pkg_size by tree:
> > step_pkg_size-stage      143.50
> > step_pkg_size-target     267.14
> > step_pkg_size-host       419.21
> > 
> > So I did a new round of timing on my machine, just to see how bad this
> is.  My machine is: Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz, with an
> NVME SSD that can spit out at least 1.4GiB/s:

I tested on an Intel(R) Core(TM) i7-7700K CPU @ 4.20GHz.
I also ran some tests last night on my home computer, AMD Ryzen 5 1600X
Six-Core Processor @ 3.60 GHz.

>     $ dd if=/dev/nvme0n1 of=/dev/null bs=16M count=256
>     4294967296 bytes (4,3 GB, 4,0 GiB) copied, 2,80702 s, 1,5 GB/s

Workstation
4294967296 bytes (4.3 GB, 4.0 GiB) copied, 1.58329 s, 2.7 GB/s

Home
4294967296 bytes (4.3 GB, 4.0 GiB) copied, 1.60107 s, 2.7 GB/s

Not surprising, since one is Samsung 960 EVO and the other is a Dell
OEM drive, both based on the same Samsung Polaris controller.

> I first created a single big file of 32GiB, which is twice the RAM I
> have, so that I can be sure that nothing gets cached. Then I did a
> smaller file, 2GiB, that fits in cache in RAM. I repeated each test
> about 10 times, and took the mean value (roughly):

I think this test simply isn't representative enough of what is really
happening.  It doesn't match the reality of timing the operations in
buildroot nor a before/after test with the package size instrumentation
disabled.  I don't know why it's different, but the numbers clearly
show that it is so.  14 minutes of a 26 minute build are accounted to
package size and without that step the build takes 12 minutes.

> t's say that a 32GiB is highly unlikely, but that a 2GiB is more
> reasonable. Also, this is done only for host packages. So, at worst

2.2G    host
89M     target
511M    staging/.

Lest you think I have some huge build that is not representative.

> case, this is ~3s per host package... With 50 host packages, that's
> about 150s (worst case), which is very far from the 47 minutes
> reported below. Even if we double the host/ size up 4GiB, we get a
> 3-minute overhead, still far from 47 minutes...

The 47 minutes is from a vm.  On the workstation, I got almost 14
minutes out of 26 total.  Still far more than 2.5 minutes worse case.

On my home computer (slightly different package selection), 711 seconds
are accounted to pkg_size out of 26:54.  The final pkg_size of a host
package took 4.267 seconds for the before install step and 4.363 for
the after install step.  The first host package only needed .001
seconds.

Why does the package size step take 4.3 seconds for a 2.2 GB host tree?
 Timing just the md5sum step, that time does not seem out of line:

$ time find host -type f -print0 | xargs -0 md5sum > /dev/null
real    0m9.454s
$ time find host -type f -print0 | xargs -0 md5sum > /dev/null
real    0m3.256s

3.2 seconds with the files in the cache vs 9.4.  I think the VM had
issues with the cache not being large enough. Also shows the I/O speed
is still relevant even with an SSD that can deliver 2.4 GB/sec.

If I look at the host install pkg size time, it starts at 0.02 with the
first host package (HOST_LZIP), then jumps quickly after the toolchain
is installed (which is a staging package, not a host package) to 5.78
seconds, ending at 8.63 seconds on the 54th host package.

If we consider 52 host packages, with md5sum, which happens twice per
package, starting at 2.9 seconds and increasing linearly to 4.3
seconds, for a 2 GB host dir.  Then we get (2.9+4.3)/2 * 52 * 2 = 374.4
seconds.  Observed is 391.38 seconds.

I think you are not taking into account:
* The md5sum happens twice per host package.
* Most of the host dir appears after just two host packages (lzip,
ccache) as part of the toolchain, causing the host dir average size to
be nearly double vs a linear increase from zero to the final size.
* md5summing many small files is slower than one large file of the same
total size.
* Searching a directory tree and reading every file is much slower than
the sequential read rate of an SSD.  The 4k random read rate for a high
end SSD, which can do 2.5 GB/sec sequential read, tops out at 250k
iops/sec.  That's only 1 GB/sec.  And that's with a huge queue depth,
more realistic would be < 100k IOPS/sec.