PR#1790: Don't block main image build phase on ostree_install phase - pungi

pungi

#1790 Don't block main image build phase on ostree_install phase

Merged 2 months ago by lsedlar. Opened 2 months ago by adamwill.

adamwill/pungi ostree-parallel-phase into master

Don't block main image build phase on ostree_install phase

Adam Williamson • 2 months ago

b83ac49

pungi/scripts/pungi_koji.py

file modified

+11 -4

		`@@ -476,11 +476,15 @@`
		`buildinstall_phase,`
		`(gather_phase, createrepo_phase),`
		`extrafiles_phase,`
		`+ )`
		`+ ostree_schema = (`
		`(ostree_phase, ostree_installer_phase),`
		`ostree_container_phase,`
		`)`
		`essentials_phase = pungi.phases.WeaverPhase(compose, essentials_schema)`
		`+ ostree_phase = pungi.phases.WeaverPhase(compose, ostree_schema)`
		`essentials_phase.start()`
		`+ ostree_phase.start()`
		`essentials_phase.stop()`

		`# write treeinfo before ISOs are created`
		`@@ -507,12 +511,9 @@`
		`osbuild_phase,`
		`kiwibuild_phase,`
		`)`
		`- post_image_phase = pungi.phases.WeaverPhase(`
		`- compose, (image_checksum_phase, image_container_phase)`
		`- )`
		`compose_images_phase = pungi.phases.WeaverPhase(compose, compose_images_schema)`
		`extra_phase_schema = (`
		`- (compose_images_phase, post_image_phase),`
		`+ (compose_images_phase, image_container_phase),`
		`osbs_phase,`
		`repoclosure_phase,`
		`)`
		`@@ -520,6 +521,12 @@`

		`extra_phase.start()`
		`extra_phase.stop()`
		`+ # wait for ostree phase here too - it can happily run in parallel`
		`+ # with all of the other stuff`
		`+ ostree_phase.stop()`
		`+ # now we do checksums as all images are done`
		`+ image_checksum_phase.start()`
		`+ image_checksum_phase.stop()`

		`pungi.metadata.write_compose_info(compose)`
		`if not (`

adamwill commented 2 months ago

I did a time map of a Fedora compose today, and noticed that we
spend about an hour waiting for the ostree_install phase to
complete before we start up the compose_images_phase which does
all the other image builds.

This is unnecessary. Nothing else depends on ostree_install; it
should be fine to start up the extra_phase (which contains
compose_images_phase) while the ostree stuff is still running.

This implements that by splitting the ostree phases out of the
essentials_phase which contains the real precursors to the
extra_phase. We start the essentials and ostree phases together,
but only wait for the essentials phase to complete before
kicking off extra_phase, so it can start while the ostree
phase is still running.

One tweak we have to make to accommodate this is to move
image_checksum_phase out of extra_phase, to avoid it potentially
running before all ostree installer images are built. The
checksum phase is quite fast - it takes about five minutes -
and any time benefit of running it in parallel with the osbs and
repoclosure phases seems like it must be smaller than the time
loss of waiting for ostree_install before kicking off extra.

Signed-off-by: Adam Williamson awilliam@redhat.com

adamwill commented 2 months ago

Small note: the ostree_installer phase does depend on the buildinstall_phase, so you might think they need to run together, but they don't - all ostree_installer needs to know is whether or not the buildinstall phase is skipped, which information is always available to it whether the buildinstall phase has even started or not.

adamwill commented 2 months ago

Here's the time map I did, based on the Rawhide 20241010.n.0 compose:

5:15    INIT    PKGSET
5:30            PKGSET

5:51    WEAVER1 BUILDINSTALL    GATHER  OSTREE  OSTREE_CONTAINER
6:00    WEAVER1 BUILDINSTALL    GATHER  OSTREE  OSTREE_CONTAINER
6:15    WEAVER1 BUILDINSTALL    GATHER  OSTREE  OSTREE_CONTAINER
6:34/7  WEAVER1                         OSTREE  OSTREE_CONTAINER    CREATEREPO
6:48    WEAVER1                         OSTREE  OSTREE_CONTAINER
7:00/1  WEAVER1                                                                 OSTREE_INSTALLER
7:15    WEAVER1                                                                 OSTREE_INSTALLER
7:30    WEAVER1                                                                 OSTREE_INSTALLER
7:45    WEAVER1                                                                 OSTREE_INSTALLER
8:00    WEAVER1                                                                 OSTREE_INSTALLER

8:18    WEAVER23    REPOCLOSURE CREATEISO   IMAGE_BUILD LIVE_MEDIA  OSBUILD KIWIBUILD
8:30    WEAVER23                            IMAGE_BUILD LIVE_MEDIA  OSBUILD KIWIBUILD
8:45    WEAVER23                            IMAGE_BUILD LIVE_MEDIA  OSBUILD KIWIBUILD
9:00    WEAVER23                            IMAGE_BUILD LIVE_MEDIA  OSBUILD KIWIBUILD
9:11    WEAVER23                            IMAGE_BUILD LIVE_MEDIA          KIWIBUILD
9:25/7  WEAVER23                            IMAGE_BUILD
9:45    WEAVER23                            IMAGE_BUILD

9:58    WEAVER34    IMAGE_CHECKSUM

10:03   TEST

so from 6:48, when createrepo finished, to 8:16, when ostree_installer finished, we are sitting around doing nothing but wait for ostree tasks to finish, even though we could happily start all the other image builds as soon as createrepo is done. These are the log messages I based the map on:

[adamw@xps13a tmp]$ egrep "(BEGIN.*PHASE|DONE.*PHASE)" pungi.global.log 
2024-10-10 05:15:05 [INFO    ] [BEGIN] ---------- PHASE: INIT ----------
2024-10-10 05:15:27 [INFO    ] [DONE ] ---------- PHASE: INIT ----------
2024-10-10 05:15:28 [INFO    ] [BEGIN] ---------- PHASE: PKGSET ----------
2024-10-10 05:51:03 [INFO    ] [DONE ] ---------- PHASE: PKGSET ----------
2024-10-10 05:51:04 [INFO    ] [BEGIN] ---------- PHASE: WEAVER ----------
2024-10-10 05:51:04 [INFO    ] [BEGIN] ---------- PHASE: BUILDINSTALL ----------
2024-10-10 05:51:04 [INFO    ] [BEGIN] ---------- PHASE: GATHER ----------
2024-10-10 05:51:04 [INFO    ] [BEGIN] ---------- PHASE: OSTREE ----------
2024-10-10 05:51:04 [INFO    ] [BEGIN] ---------- PHASE: OSTREE_CONTAINER ----------
2024-10-10 06:34:48 [INFO    ] [DONE ] ---------- PHASE: BUILDINSTALL ----------
2024-10-10 06:37:55 [INFO    ] [DONE ] ---------- PHASE: GATHER ----------
2024-10-10 06:37:56 [INFO    ] [BEGIN] ---------- PHASE: CREATEREPO ----------
2024-10-10 06:48:22 [INFO    ] [DONE ] ---------- PHASE: CREATEREPO ----------
2024-10-10 07:00:35 [INFO    ] [DONE ] ---------- PHASE: OSTREE_CONTAINER ----------
2024-10-10 07:01:01 [INFO    ] [DONE ] ---------- PHASE: OSTREE ----------
2024-10-10 07:01:02 [INFO    ] [BEGIN] ---------- PHASE: OSTREE_INSTALLER ----------
2024-10-10 08:16:47 [INFO    ] [DONE ] ---------- PHASE: OSTREE_INSTALLER ----------
2024-10-10 08:16:49 [INFO    ] [DONE ] ---------- PHASE: WEAVER ----------
2024-10-10 08:18:16 [INFO    ] [BEGIN] ---------- PHASE: WEAVER ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: WEAVER ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: REPOCLOSURE ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: CREATEISO ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: IMAGE_BUILD ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: LIVE_MEDIA ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: OSBUILD ----------
2024-10-10 08:18:21 [INFO    ] [BEGIN] ---------- PHASE: KIWIBUILD ----------
2024-10-10 08:20:23 [INFO    ] [DONE ] ---------- PHASE: REPOCLOSURE ----------
2024-10-10 08:23:13 [INFO    ] [DONE ] ---------- PHASE: CREATEISO ----------
2024-10-10 09:11:35 [INFO    ] [DONE ] ---------- PHASE: OSBUILD ----------
2024-10-10 09:25:24 [INFO    ] [DONE ] ---------- PHASE: KIWIBUILD ----------
2024-10-10 09:27:22 [INFO    ] [DONE ] ---------- PHASE: LIVE_MEDIA ----------
2024-10-10 09:58:36 [INFO    ] [DONE ] ---------- PHASE: IMAGE_BUILD ----------
2024-10-10 09:58:37 [INFO    ] [DONE ] ---------- PHASE: WEAVER ----------
2024-10-10 09:58:37 [INFO    ] [BEGIN] ---------- PHASE: WEAVER ----------
2024-10-10 09:58:37 [INFO    ] [BEGIN] ---------- PHASE: IMAGE_CHECKSUM ----------
2024-10-10 10:03:24 [INFO    ] [DONE ] ---------- PHASE: IMAGE_CHECKSUM ----------
2024-10-10 10:03:25 [INFO    ] [DONE ] ---------- PHASE: WEAVER ----------
2024-10-10 10:03:25 [INFO    ] [DONE ] ---------- PHASE: WEAVER ----------
2024-10-10 10:03:26 [INFO    ] [BEGIN] ---------- PHASE: TEST ----------
2024-10-10 10:03:28 [INFO    ] [DONE ] ---------- PHASE: TEST ----------

Edited 2 months ago by adamwill

siosm commented 2 months ago

+1 from me. It's possible that this is a leftover from the project Atomic times.

I don't know if it's doable but the ostree builds can also happen in parallel, they do not depend on each other.

adamwill commented 2 months ago

I suspect what happened is that, originally, ostree got put in the essential phase as an optimization, because it can run before gather and createrepo, unlike the image build phases. ostree itself is quite fast, and finishes only slightly slower than createrepo (see the logs).

but then ostree_installer came along. We put it along with ostree because that's the obvious thing to do. But...it's much slower, and has to run after ostree. so it created this big lag.

individual tasks within a phase do run in parallel, that's just how it works. ostree and ostree_container phases also are configured to run in parallel, both before and after this PR. ostree_installer phase is set to run after ostree phase, because those tasks use the ostrees built by the tasks in the ostree phase.

Edited 2 months ago by adamwill

adamwill commented 2 months ago

I guess another way we could slice this is to leave ostree and ostree_container in the essential phase and move ostree_installer into the compose_images_phase. I think I kinda prefer this to that, though.

adamwill commented 2 months ago

yeah, what i guessed seems to be the case: https://pagure.io/pungi/issue/778 . "The advantage of doing this is that we could start making ostrees (and then ostree installers) immediately after pkgset phase finishes, which could save time." before that, when it was first introduced, ostree_phase ran on its own between essentials_phase and compose_images_phase .