CI Timing Statistics

[kwryankrattiger]

Getting timing statistics for all of the packages installed in CI

Spack and Spack CI

• Add timing logs to packages installed via a build cache
• Rework timer to better handle nested timers (cache install phases extract and relocate)
• Collect all install_times.json for upload
• Include all timing logs in CI artifacts

Spack infrastructure

• Scrape timing logs and store data in database
• Create dashboard(s) for exploring timing data

CC: @tgamblin

[kwryankrattiger]

The result of this change is the packages installed from cache also dump a install_times.jsonand CI aggregates all of the install_times.json files for all packages into a single artifact for the job.

** Note ** two new fields are now present in the install_times.json, name and cache. One question I have to @tgamblin and others is whether or not it makes sense to also include the spec hash in this file, or what extra meta data should be included in the timer json output if any.

From cache:
zlib-install_times.json.txt

From source:
zstd-install_times.json.txt

Aggregated install_times.json files from all installed packages
aggregated_install_times.json.txt

[kwryankrattiger]

this try really shouldn't be required, but for some reason the _install_from_cache routine doesn't actually install anything in the test_install_from_cache_ok test.

[haampie]

Just thinking out loud: what about an interface timer.start(identifier), timer.stop(identifier), with timer.measure(identifier), where all these operation just push an event tuple (time, start/stop, identifier) to a list, and we do processing only afterwards by looping over the list? Then you can construct whatever type of format out of it, whether it's a tree, or a reduction on identifier, etc.

Also worth checking if there is some standard format for this

[haampie]

Suggested change

	self._events: list(TimerEvent) = []
	self._events: List[TimerEvent] = []

[haampie]

Can you follow up with a PR that makes this code actually readable? It's hard to see the intent, probably also for you after a couple months.

[kwryankrattiger]

Like more comments, or re-written in a more pythonic way?

[haampie]

(let's fix this in a follow-up PR) there's no need to use max here. In fact del self._timer_stack[index:] is what you want?

[kwryankrattiger]

Basically I am trying to truncate all of the timer labels in the timer stack after and including "index"

[haampie]

What if this is not true? (let's fix this in a follow-up PR if necessary)

[kwryankrattiger]

If it isn't true, you are stopping a timer that was never started, so it is just a noop. Is there something you think should be done in that case?

[haampie]

(let's fix this in a follow-up PR) This always allocates a TimeTracker(...), also when self._timers[event.label] exists. So, then it's better to use a standard if-else, or use defaultdict.

[kwryankrattiger]

I was not aware of deafultdict, noted for the update later to improve the code clarity.

[haampie]

Maybe I'm missing something, but (a) the flag --timer-summary-file is not set for Gitlab CI and (b) db lock acquire time only makes sense when installing dependencies in parallel, whereas this timer seems to be for a single process? Are you planning to run spack install --timer-summary-file=... for each process?

[kwryankrattiger]

@haampie I talked about this with @scottwittenburg today and we agree this file is kind of useless. I originally wanted to do the timer aggregation with this flag, but since the parallelism is handled by Make and not Spack it is not so straightforward as to how to write the lock timer information. Instead of this flag, I added a timer to the spack ci rebuild sub-command to collect information on the unaccounted for overhead of runnering rebuild, ie. locks, makefile generation, etc. and will remove the --time-summary-file

[scottwittenburg]

I've been using this as the base for some branches I'm testing, here, and it seems to be providing the data we expect. Unless there are objections, I vote to merge it.