Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Lazy progress + Progress Groups #2513

Merged
merged 5 commits into from
Feb 9, 2022
Merged

Conversation

sipsma
Copy link
Collaborator

@sipsma sipsma commented Dec 9, 2021

Example output for the following LLB (built w/ a local export in order to force unlazying):

pg := llb.ProgressGroup("group", "TestGroup")
base := llb.Image("busybox")
src := llb.Image("alpine").
		File(llb.Mkfile("/foo", 0755, nil)).
		File(llb.Mkfile("/bar", 0755, nil))
a := llb.Scratch().File(llb.Copy(src, "/foo", "/a"), pg)
b := llb.Scratch().File(llb.Copy(src, "/bar", "/b"), pg)
m := llb.Merge([]llb.State{base, a, b}, pg)
dt, err := m.Marshal(context.TODO())

Here's the output when using tty mode:

[+] Building 0.8s (9/9) FINISHED
 => docker-image://docker.io/library/alpine:latest                                                                                                                                      0.4s
 => => resolve docker.io/library/alpine:latest                                                                                                                                          1.4s
 => => sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99 2.72MB / 2.72MB                                                                                          0.4s
 => => extracting sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99                                                                                               0.1s
 => docker-image://docker.io/library/busybox:latest                                                                                                                                     0.2s
 => => resolve docker.io/library/busybox:latest                                                                                                                                         1.4s
 => => sha256:a01966dde7f8d5ba10b6d87e776c7c8fb5a5f6bfa678874bd28b33b1fc6dba34 828.50kB / 828.50kB                                                                                      0.2s
 => mkfile /foo                                                                                                                                                                         0.0s
 => mkfile /bar                                                                                                                                                                         0.0s
 => TestGroup                                                                                                                                                                           0.3s
 => => extracting sha256:a01966dde7f8d5ba10b6d87e776c7c8fb5a5f6bfa678874bd28b33b1fc6dba34                                                                                               0.0s
 => => merging                                                                                                                                                                          0.0s
 => => copying files 1.43MB                                                                                                                                                             0.0s

And here's the output when using plain mode:

#1 docker-image://docker.io/library/busybox:latest
#1 resolve docker.io/library/busybox:latest
#1 resolve docker.io/library/busybox:latest 1.4s done
#1 DONE 0.0s

#2 docker-image://docker.io/library/alpine:latest
#2 resolve docker.io/library/alpine:latest 1.4s done
#2 sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99 0B / 2.72MB 0.2s
#2 sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99 1.05MB / 2.72MB 0.3s
#2 sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99 2.72MB / 2.72MB 0.5s done
#2 extracting sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99 0.1s done
#2 DONE 0.5s

#3 mkfile /foo
#3 DONE 0.0s

#4 mkfile /bar
#4 DONE 0.0s

#5 TestGroup
#5 extracting sha256:a01966dde7f8d5ba10b6d87e776c7c8fb5a5f6bfa678874bd28b33b1fc6dba34 0.0s done
#5 merging done
#5 copying files 1.43MB 0.0s done
#5 DONE 0.3s

#1 docker-image://docker.io/library/busybox:latest
#1 sha256:a01966dde7f8d5ba10b6d87e776c7c8fb5a5f6bfa678874bd28b33b1fc6dba34 828.50kB / 828.50kB 0.2s done
#1 DONE 0.2s

@tonistiigi
Copy link
Member

I don't think we should push terms like "lazy" to the users. They shouldn't need to think about the internal implementation.

I would suggest 2 changes:

  • Ability to mark a vertex as a "helper" of another vertex. In that case (in updated clients) the helper vertex will not show up but restart the main vertex. The time would be sum of all the end-start differences of the vertex group. We could use the same to group some of the [internal] blocks together for nicer UI. For the copy+merge case it would mean that only COPY row would be shown and when merge starts, its time is added to the COPY.
  • Ensure that the order of items in the progressbar is related to how far the vertex is from the build result in llb graph. (After the sorting by whether the vertex is running has been done).

@sipsma sipsma mentioned this pull request Jan 6, 2022
10 tasks
@tonistiigi tonistiigi added this to the v0.10.0 milestone Jan 24, 2022
@tonistiigi
Copy link
Member

@sipsma Any update with this?

@sipsma
Copy link
Collaborator Author

sipsma commented Jan 31, 2022

@sipsma Any update with this?

I've been working on it intermittently but have been very busy with other stuff the last few weeks. Have more time this week so I will aim to get some updated code out for review by end of week (let me know if you have any time constraints for the v0.10 release I should know about).

In general, I'm structuring it in two commits; the first is the baseline behavior that at least results in merge+diff unlazies to show up under the right vertex (basically the same idea as how lazy blob refs work). After that I'll layer on some of the fancier progress grouping you were describing for merges specifically.

@tonistiigi
Copy link
Member

the first is the baseline behavior that at least results in merge+diff unlazies to show up under the right vertex

This is just the order of items, right? Because I don't think we need anything else special if we have grouping support.

@sipsma
Copy link
Collaborator Author

sipsma commented Jan 31, 2022

This is just the order of items, right? Because I don't think we need anything else special if we have grouping support.

For Merge yes. For Diff, I think grouping support won't cover all the cases (it would only help when diff is plugged into a merge, which while a majority of the cases is not all) and we will need the first commit.

@tonistiigi
Copy link
Member

let me know if you have any time constraints for the v0.10 release I should know about

Targeting v0.10 RC for next week

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 3, 2022

Updated w/ the 2 commits described before; they don't overlap in terms of code so I'm happy to split them up into separate PRs if desired, but I wanted to develop them together because they do have indirect impacts on each other and I wanted to ensure the final output looked okay.

@sipsma sipsma marked this pull request as ready for review February 3, 2022 04:15
@sipsma sipsma changed the title Lazy progress Lazy progress + Progress Groups Feb 3, 2022
solver/llbsolver/solver.go Outdated Show resolved Hide resolved
solver/llbsolver/solver.go Outdated Show resolved Hide resolved
util/progress/progressui/display.go Outdated Show resolved Hide resolved
util/progress/progressui/display.go Outdated Show resolved Hide resolved
util/progress/progressui/display.go Outdated Show resolved Hide resolved
@tonistiigi
Copy link
Member

tonistiigi commented Feb 4, 2022

image

Is what I get every time on the first build.

Otherwise, groups seem to work in #2596 but the issue with the out of order items remains and needs to be addressed separately

progress.mov

Haven't reviewed updated code yet.

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 4, 2022

Is what I get every time on the first build.

Just to confirm, the issue is that steps aren't appearing in the right order? so like in the screenshot/video [internal] load build context appears after [1/5] and [2/5] is after [4/5], etc.? If so, I can definitely imagine how both the lazy progress and progress group handling could result in that.

@tonistiigi
Copy link
Member

tonistiigi commented Feb 4, 2022

The issue with the first screenshot (no progressgroup there) is that the FROM line is not complete although the build is done and the top line says 6/7. Note that I only get this on the first build, if I have cache then this doesn't appear.

In the video (this uses mergeop) yes 3/5 and 4/5 are before 2/5 that is confusing to user as this is not how the order of lines is in the Dockerfile. Where the "build context" line is isn't that important I think..

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 4, 2022

The issue with the first screenshot (no progressgroup there) is that the FROM line is not complete although the build is done and the top line says 6/7. Note that I only get this on the first build, if I have cache then this doesn't appear.

I can't reproduce it locally. I'm starting buildkit w/ ./hack/shell using this PR's branch, and running buildctl build --frontend dockerfile.v0 --local dockerfile=. --local context=. with this Dockerfile:

FROM alpine
COPY Dockerfile /
COPY foo /

I ran 5 times and each time the output looks the same with everything being complete (blue):

[+] Building 2.0s (7/7) FINISHED
 => [internal] load build definition from Dockerfile                                                                                                                                    0.0s
 => => transferring dockerfile: 78B                                                                                                                                                     0.0s
 => [internal] load .dockerignore                                                                                                                                                       0.0s
 => => transferring context: 2B                                                                                                                                                         0.0s
 => [internal] load metadata for docker.io/library/alpine:latest                                                                                                                        1.5s
 => [1/3] FROM docker.io/library/alpine@sha256:21a3deaa0d32a8057914f36584b5288d2e5ecc984380bc0118285c70fa8c9300                                                                         0.5s
 => => resolve docker.io/library/alpine@sha256:21a3deaa0d32a8057914f36584b5288d2e5ecc984380bc0118285c70fa8c9300                                                                         0.0s
 => => sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99 2.72MB / 2.72MB                                                                                          0.4s
 => => extracting sha256:9b3977197b4f2147bdd31e1271f811319dcd5c2fc595f14e81f5351ab6275b99                                                                                               0.1s
 => [internal] load build context                                                                                                                                                       0.0s
 => => transferring context: 102B                                                                                                                                                       0.0s
 => [2/3] COPY Dockerfile /                                                                                                                                                             0.0s
 => [3/3] COPY foo /                                                                                                                                                                    0.0s

Are you doing anything different? It could also possibly be a timing thing that just varies host to host. I wonder if the client progressui is being shut down before the final vertex Completed update is received.

In the video (this uses mergeop) yes 3/5 and 4/5 are before 2/5 that is confusing to user as this is not how the order of lines is in the Dockerfile. Where the "build context" line is isn't that important I think..

I'll take a look at this, my initial suspicion is that it's a result of the code handling all the progress group updates after handling the non-group vertexes.

@tonistiigi
Copy link
Member

I'll take a look at this, my initial suspicion is that it's a result of the code handling all the progress group updates after handling the non-group vertexes.

I don't think it is progress groups. It is expected that the copy to scratch runs early as it doesn't depend on other commands. But we should figure out how to avoid this and keep the order that makes sense in the build graph.

I'll see if I can debug the first case more on my side.

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 4, 2022

I don't think it is progress groups. It is expected that the copy to scratch runs early as it doesn't depend on other commands. But we should figure out how to avoid this and keep the order that makes sense in the build graph.

Ah right. It might not be that hard to add another field to LLB metadata that specifies an order progress vertexes (and groups) should appear in. The progressui trace can then just sort its vertex list by that index.

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 4, 2022

I actually hit the first case where the FROM case never completes, it seems like it happens maybe 1/20 runs for me. I did some println debugging between these two lines to see each vertex received by the progress ui and found that when things do work the relevant vertexes received have start/complete times set to:

Started:<nil> Completed:<nil>

Started:2022-02-04 21:09:50.120528645 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:50.120528645 +0000 UTC Completed:2022-02-04 21:09:50.133164684 +0000 UTC 

Started:2022-02-04 21:09:50.133207933 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:50.133207933 +0000 UTC Completed:2022-02-04 21:09:50.133233391 +0000 UTC

Started:2022-02-04 21:09:50.133292389 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:50.133292389 +0000 UTC Completed:2022-02-04 21:09:50.142885665 +0000 UTC

Started:2022-02-04 21:09:50.145763182 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:50.145763182 +0000 UTC Completed:2022-02-04 21:09:50.509056664 +0000 UTC 

Started:2022-02-04 21:09:50.145763182 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:50.145763182 +0000 UTC Completed:2022-02-04 21:09:50.582821026 +0000 UTC

But when it doesn't complete they are:

Started:<nil> Completed:<nil>

Started:2022-02-04 21:09:58.775115015 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:58.789572264 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:58.789572264 +0000 UTC Completed:2022-02-04 21:09:58.799409704 +0000 UTC 

Started:2022-02-04 21:09:58.802618255 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:58.802618255 +0000 UTC Completed:2022-02-04 21:09:59.16156281 +0000 UTC 

Started:2022-02-04 21:09:58.802618255 +0000 UTC Completed:<nil>

Started:2022-02-04 21:09:58.802618255 +0000 UTC Completed:2022-02-04 21:09:59.232716669 +0000 UTC 

Not sure what's happening differently that causes the vertexes received to be different in the broken case.

But the reason this happens now is because the commit to support start/stop intervals in progress results in all intervals being merged and a complete time is never received for the start time of 21:09:58.775115015. The vertex as a whole is therefore still considered to be running because that first interval never stopped.

It seems like figuring out why the vertexes received by the progress code are different in the broken case would be a good next step. Let me know if there's any known cases where that's expected to happen.

@tonistiigi
Copy link
Member

Is this all from same vertex? If it is then it already looks wrong that it switches so much. A single FROM should only go active twice.

If the server is already sending the wrong data then an additional backward-compatible way to fix it would be that if there is no progress-group then for a single vertex a completed time always marks it as finished.

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 5, 2022

Is this all from same vertex? If it is then it already looks wrong that it switches so much. A single FROM should only go active twice.

Yeah those are all from just the vertex for the FROM statement, I filtered out the others. The only additional detail I gathered was that it seemed like the vertex with non-nil start that never got a corresponding complete always came from the CacheMap method here (added some extra metadata to the vertex to figure this out). Haven't found anything there that would explain this more though. It might be worth looking at this server-side code to see if something wrong is happening there or if the problem is upstream from that point.

If the server is already sending the wrong data then an additional backward-compatible way to fix it would be that if there is no progress-group then for a single vertex a completed time always marks it as finished.

Pushed an extra commit with this workaround for now.

@tonistiigi
Copy link
Member

I looked the server side. The reason it goes active for 5 times is:

As usual, now I'm having trouble triggering the race so don't know what path produces the starting without matching completed time.

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 7, 2022

I may have figured out the underlying issue. I added logging to the notifyStarted and notifyCompleted funcs in solver/jobs.go and saw that when the missing completion case happens in progress, the functions are actually all running and the missing completion does get written here.

I think the issue is on this line. CacheMap runs twice (as expected) but both instances of it use the same ID field for the progress struct, so a race is possible where the map value for the key of ID gets overwritten by the second cache map run before the progress written by the first cache map run gets picked up by the progress reader.

I made a change to just use a random ID in those notifyStarted and notifyCompleted funcs (which is hacky but works because ID is not used in those cases) and can no longer reproduce the issue after 50 attempts.

Just need to figure out a better solution than using a random ID now, will push this fix soon.

EDIT: I also just realized this code in flightcontrol could be involved too, so need to determine whether that's a relevant factor or not.

@sipsma sipsma force-pushed the lazy-progress branch 2 times, most recently from 07579c6 to 29a5ceb Compare February 7, 2022 23:59
@sipsma
Copy link
Collaborator Author

sipsma commented Feb 8, 2022

Pushed the fix (and removed the previous commit with the workaround in the progress ui). I updated to just include the start time (in unix nanos) with the ID, so then we can still dedupe multiple updates within the same start/stop interval, but won't dedupe across start/stop intervals.

solver/jobs.go Outdated
pw.Write(v.Digest.String(), *v)
// id dedupes progress updates; use of the start time ensures that distinct
// stop/start intervals of the vertex don't get deduped with one another.
id := v.Digest.String() + strconv.Itoa(int(v.Started.UnixNano()))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure about using started time there. Might as well just use random then. If this is for the second cache key then what if we just pass a suffix for that case. Then at least the caller side still controls the ID. Could even be variadic I think.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My thinking was that we care about preserving vertex updates from different start/stop intervals, but it's okay to dedupe multiple updates within a single interval, so the start time was the right key to use in every possible situation. That being said, putting in suffixes set by the caller works perfectly fine too, so updated with that.

// interval's stop time is nil, it is treated as positive infinity and consumes
// any intervals after it. Intervals with nil start times are ignored and not
// returned.
func mergeIntervals(intervals []interval) []interval {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of these calculations wouldn't it be easier to just add the last compled-started diff every time vertex goes to completed state. If vertex is active then current time is now-started+previous_sum. Not a blocker but looks like it would be faster and simpler.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was trying to handle as many cases as possible, including ones where progress updates come into the client out of order in arbitrary ways. I don't think that's expected at the moment but wanted to be safe against unknown bugs or possible behavior changes in the future. So I'd prefer to leave this as is given the extra complication is fairly minimal and self-contained, but if you still prefer the other version let me know and I'll update.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you think the extra complexity might become an issue for this for big builds? Does this get called repeatedly after every 100ms on tty mode?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It will get called for each job representing a vertex update (i.e. not status update, log, etc.) on each ui refresh. I just quickly ran a benchmark test using the complex test case in the unit tests I added and got 775 ns/op (in a linux VM running on an m1 macbook). That test case has 15 start/stop intervals to merge, whereas in the real world we'd usually expect at most 5. But round that up to 1 microsecond anyways, then assume that an extremely large build has 100 vertex jobs per update and it still only takes 100 microseconds. Let me know if you think the estimate is off, but I'd be biased towards thinking the performance shouldn't make a difference here.

localTimeDiff time.Duration
vertexes []*vertex
byDigest map[digest.Digest]*vertex
nextIndex int
updates map[digest.Digest]struct{}
modeConsole bool
groups map[string]*vertexGroup // group id -> group
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If all items would be "groups" and vertex without a progressgroup would just be a group with only one item I think some duplications could be avoided and maybe easier to understand. Not needed atm unless you think it is easy but I think worth considering as optimization.

We can assume that vertex digest and progress group id never collide.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking about ways to refactor the existing code more and fit it in with the groups better, but ultimately became biased against it because it felt too risky to significantly impact the existing code even more right before the release, especially given most of the testing of the progress is not automated. So I'd prefer to save that for a follow-up, probably after the release is done.

This is easier to read than quotes, which result in lots of escaping in
progress output.

Signed-off-by: Erik Sipsma <erik@sipsma.dev>
Now, when a merge or diff ref is unlazied, the progress will show up
under the vertex for the merge/diff ref. Additionally, any ancestors of
the op that also need to be unlazied as part of unlazying the merge/diff
will show status updates under its vertex in the progress.

Signed-off-by: Erik Sipsma <erik@sipsma.dev>
This allows clients to specify that LLB states should be grouped in
progress output under a custom name. Status updates for all vertexes in
the group will show up under a single vertex in the output.

The intended use cases are for Dockerfile COPY's that use MergeOp as a
backend and for grouping some other internal vertexes during frontend
builds.

Signed-off-by: Erik Sipsma <erik@sipsma.dev>
Previously, vertexes sent to progress might have multiple intervals in
which they started+stopped, but the output only knew about the most
recent interval. Now, all the intervals are tracked and the total time
spent on each (after accounting for overlaps) is displayed. This is
implemented both for normal vertexes and progress group vertexes.

Signed-off-by: Erik Sipsma <erik@sipsma.dev>
This fixes an issue where if a vertex rapidly had progress updates (such
as the case where CacheMap runs in succession for multiple indexes),
then progress updates were all using the same ID and could incorrectly
override one another, resulting in missing vertex updates.

Signed-off-by: Erik Sipsma <erik@sipsma.dev>
@tonistiigi tonistiigi merged commit 81c4d74 into moby:master Feb 9, 2022
@tonistiigi
Copy link
Member

Ah right. It might not be that hard to add another field to LLB metadata that specifies an order progress vertexes (and groups) should appear in. The progressui trace can then just sort its vertex list by that index.

Are you working on this?

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 19, 2022

Are you working on this?

I haven't been but if you're good with that approach I'm happy to implement it. I should have time to send out a PR early next week.

@tonistiigi
Copy link
Member

@sipsma I'm not sure if there is a way to just do it automatically. We could compute how far the vertex is from the final build result that should be correct but that doesn't define how the multiple inputs of a mergeop should be sorted. Atm. the most critical need is something that would put COPY --link in Dockerfile to the correct place where it is in the file.

Note that there is some sorting fixes already in place iirc. It should be that when there is a lot of screen space it pushes the active items down so they are visible. That should still take precedence over the order defined in LLB. We need to avoid the case where the user doesn't see what is currently running as the whole screen is filled with already completed progress rows.

@sipsma
Copy link
Collaborator Author

sipsma commented Feb 22, 2022

Note that there is some sorting fixes already in place iirc. It should be that when there is a lot of screen space it pushes the active items down so they are visible. That should still take precedence over the order defined in LLB. We need to avoid the case where the user doesn't see what is currently running as the whole screen is filled with already completed progress rows.

Makes sense. Taking a look at this today.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants