Re: Benchmarking BuildStream commands from user point of view

[Angelos Evripiotis <angelos evripiotis gmail com>]

> I haven't looked at the script, but I can say that we want to shoot for
> maintainability and longevity here, in other projects it's taken me a
> long time to get off the ground to run benchmarks after they have bit
> rotted for a year or so.

I agree on the aims. I think we should set up a schedule for the benchmarks to
be run, so that they don't rot away in this manner. One kind of run could be to
make sure it is still compatible with bst, another kind could be to actually
produce the results.

For when you do look at it, I'll note that I'm prioritising getting early
feedback over architectural beauty, it's all in one file now but it doesn't
have to land that way :)

> I *think* that it probably makes sense to maintain this as a separate
> git repository beside buildstream in the buildstream 'group' - because
> one thing we'll certainly want to do is run the benchmarks against
> multiple versions of buildstream and plot the results together so that
> we can easily observe performance improvements, regressions and
> tradeoffs.

Sounds good, if you make it I'm happy to push an MR to get it started.

> While this is not extremely helpful, I feel like I should point to the
> benchmarks I worked on back with Openismus, the code is entirely not
> useful for this, but the same concepts apply:
>
> git repo: https://gitorious.org/openismus-playground/phonebook-benchmarks
> sample blog post: https://blogs.gnome.org/tvb/2013/12/03/smart-fast-addressbooks/

Nice, I had a quick look. I like that you made it
reproducible, kept it simple, and did valid comparisons. I think it's
a similar problem.

> So first thing I notice in your graph is that you are measuring time of
> session, not time of record - if for example, we are benchmarking
> BuildStream parse and initial load performance (it's a great place to
> start !); we should be measuring the time *per element*, this way we
> can easily observe:
>
>   o The actual time it takes to load a single element
>   o Whether the algorithm is linear or not, ideally we want it to take
>     approximately the same time to load a single element in a 1 element
>     pipeline as it takes to load a single element in a 100,000 element
>     pipeline.

I agree that this is useful to measure, I think we should do it as well.

I think there are at least three use-cases for the measurements we'll be
making:

    o Simulated-user acceptance testing - e.g. if I have many things, is
      performance ok?

    o Profiling - if performance is not ok, how can we make it faster?

    o Regression testing - what was the change that introduced a problem? Here
      I think we can count these things as changes: commits in bst, versions of
      dependencies, OS, system config, hardware.

I hadn't really thought of the regression case until reading your reply, I
think it will be really important.

I'll look at addressing all three.

> Also in your graph, I notice that the graph seems exponential at first
> and then becomes linear, this is because we are counting time to load
> the BuildStream program itself in the python interpretor (I think you
> mentioned this already).

I agree start-up time is a factor here, I would expect this to show up as a
constant cost though. I think the exponential appearance might have a different
explanation. I look forward to digging!

> To fix this, I would be willing to expose some internal API entry
> points in the BuildStream core, allowing us to measure things more
> precisely, i.e. in this case it will be useful for a benchmarking
> program to know:
>
>   o When buildstream starts to actually run
>   o When buildstream has internally completed the load of the pipeline
>
> If you can come up with something simple enough, perhaps some kind of
> handle that buildstream can call into and mark significant events which
> your benchmarking program can observe, this will get us on the right
> track I think.

I think this is a great idea! I think it feeds into the 'profiling' use-case
above. I'll have a look at it.

Before we started this thread, I had modified plugin.timed_activity() to
separately log timing and capture a cProfile. It was pretty useful for
focussing on the numbers I was really interested in.

> Also, this gets a bit more complex with Source plugins which exercise
> host tooling - it should be noted that if we run the benchmarks in 2017
> and then a year later on a different host - the performance man improve
> or regress depending on developments which have occurred in third party
> tooling - I dont think it's important to setup an identical environment
> for benchmarking though; just that we run the full benchmarking suite
> against every interesting version of BuildStream on the same host
> setup, and know that external debris might change performance.

Very good points, it's really important to have a basis for comparison. We
can't really change environments and BuildStream version at the same time and
expect to have a useful comparison. One variable at a time! Testing on all
interesting versions should give us a good basis, I think if we manage some of
the environment then we can make an even better basis.

I'm thinking that if we have e.g. a Vagrant setup for this then we should be
able to easily manage the environment part (e.g. deps, OS, config), apart from
the hardware.

> For load time performance specifically, it is interesting to exercise
> the benchmarks with different initial element states and source
> consistency states, i.e.:
>
>   o Is the element cached, or must it be built, this will effect
>     codepaths determining such at load time
>   o Is the source code available, or must it be fetched, this
>     will also effect initial interrogation of element state

Yup definitely, I'll include! Cached / not-cached is already covered at least.

> I have noticed a regression in load performance in recent months, this
> seems to happen specifically when running a command on a pipeline where
> nothing is locally cached and sources need to be downloaded - to be
> fair after diagnosing, it was not a load time regression, but rather it
> seems that in that case - *after* loading the whole pipeline, cache
> keys seem to be redundantly re-calculated after the load completes and
> while displaying the summary (e.g. doing `bst show`).

Aha, if we had a regression thing set up then we could perhaps pinpoint the
commit.

> Looks like a fun project, I'm excited about this :)

Yay, me too! :)

P.S. I meant to include the raw results in the first message:

time python3 -u /tmp/buildstream/benchmark.py | tee /tmp/buildstream/times2.txt
python,0.03
python_import_buildstream,0.56
help,0.68
write_files,1,0.00
write_files,1001,0.17
write_files,2001,0.32
write_files,3001,0.48
write_files,4001,0.64
write_files,5001,0.79
write_files,6001,0.93
write_files,7001,1.07
write_files,8001,1.41
write_files,9001,1.54
import_files_tar:track import element,1,1.04
import_files_tar:show compose element,1,1.01
import_files_tar:build import element,1,1.58
import_files_tar:build compose element,1,1.55
import_files_tar:build cached compose element,1,1.05
import_files_tar:checkout compose element,1,1.29
import_files_tar:track import element,1001,0.92
import_files_tar:show compose element,1001,0.99
import_files_tar:build import element,1001,11.09
import_files_tar:build compose element,1001,10.79
import_files_tar:build cached compose element,1001,1.08
import_files_tar:checkout compose element,1001,2.32
import_files_tar:track import element,2001,0.98
import_files_tar:show compose element,2001,0.97
import_files_tar:build import element,2001,12.92
import_files_tar:build compose element,2001,12.51
import_files_tar:build cached compose element,2001,1.02
import_files_tar:checkout compose element,2001,3.12
import_files_tar:track import element,3001,0.92
import_files_tar:show compose element,3001,1.01
import_files_tar:build import element,3001,15.09
import_files_tar:build compose element,3001,14.77
import_files_tar:build cached compose element,3001,1.04
import_files_tar:checkout compose element,3001,4.05
import_files_tar:track import element,4001,0.94
import_files_tar:show compose element,4001,0.99
import_files_tar:build import element,4001,17.73
import_files_tar:build compose element,4001,18.34
import_files_tar:build cached compose element,4001,0.97
import_files_tar:checkout compose element,4001,5.44
import_files_tar:track import element,5001,0.92
import_files_tar:show compose element,5001,0.98
import_files_tar:build import element,5001,17.60
import_files_tar:build compose element,5001,22.04
import_files_tar:build cached compose element,5001,1.01
import_files_tar:checkout compose element,5001,6.99
import_files_tar:track import element,6001,0.93
import_files_tar:show compose element,6001,0.94
import_files_tar:build import element,6001,20.55
import_files_tar:build compose element,6001,26.41
import_files_tar:build cached compose element,6001,0.94
import_files_tar:checkout compose element,6001,6.89
import_files_tar:track import element,7001,0.98
import_files_tar:show compose element,7001,1.02
import_files_tar:build import element,7001,22.52
import_files_tar:build compose element,7001,26.49
import_files_tar:build cached compose element,7001,1.01
import_files_tar:checkout compose element,7001,14.69
import_files_tar:track import element,8001,1.02
import_files_tar:show compose element,8001,1.00
import_files_tar:build import element,8001,26.52
import_files_tar:build compose element,8001,29.07
import_files_tar:build cached compose element,8001,1.04
import_files_tar:checkout compose element,8001,13.60
import_files_tar:track import element,9001,0.96
import_files_tar:show compose element,9001,1.00
import_files_tar:build import element,9001,29.83
import_files_tar:build compose element,9001,28.55
import_files_tar:build cached compose element,9001,0.97
import_files_tar:checkout compose element,9001,16.55
import_local_files:show compose element,1,0.97
import_local_files:build import element,1,1.47
import_local_files:build compose element,1,1.37
import_local_files:build cached compose element,1,1.03
import_local_files:checkout compose element,1,1.17
import_local_files:show compose element,1001,1.22
import_local_files:build import element,1001,10.87
import_local_files:build compose element,1001,10.76
import_local_files:build cached compose element,1001,1.14
import_local_files:checkout compose element,1001,2.44
import_local_files:show compose element,2001,1.43
import_local_files:build import element,2001,12.74
import_local_files:build compose element,2001,12.77
import_local_files:build cached compose element,2001,1.26
import_local_files:checkout compose element,2001,3.69
import_local_files:show compose element,3001,1.54
import_local_files:build import element,3001,15.25
import_local_files:build compose element,3001,15.28
import_local_files:build cached compose element,3001,1.51
import_local_files:checkout compose element,3001,4.63
import_local_files:show compose element,4001,1.66
import_local_files:build import element,4001,17.34
import_local_files:build compose element,4001,17.04
import_local_files:build cached compose element,4001,1.76
import_local_files:checkout compose element,4001,5.96
import_local_files:show compose element,5001,1.82
import_local_files:build import element,5001,19.28
import_local_files:build compose element,5001,24.39
import_local_files:build cached compose element,5001,1.89
import_local_files:checkout compose element,5001,6.87
import_local_files:show compose element,6001,2.03
import_local_files:build import element,6001,21.21
import_local_files:build compose element,6001,27.18
import_local_files:build cached compose element,6001,1.91
import_local_files:checkout compose element,6001,12.89
import_local_files:show compose element,7001,2.22
import_local_files:build import element,7001,24.40
import_local_files:build compose element,7001,29.86
import_local_files:build cached compose element,7001,2.18
import_local_files:checkout compose element,7001,15.05
import_local_files:show compose element,8001,2.31
import_local_files:build import element,8001,27.26
import_local_files:build compose element,8001,31.63
import_local_files:build cached compose element,8001,2.63
import_local_files:checkout compose element,8001,15.09
import_local_files:show compose element,9001,2.61
import_local_files:build import element,9001,30.52
import_local_files:build compose element,9001,33.22
import_local_files:build cached compose element,9001,2.54
import_local_files:checkout compose element,9001,15.98

real    19m20.629s
user    5m47.510s
sys     5m23.110s