Proposal: Provide feedback on push progress.

[coollog]

Regards issues: #1251, #806

Project tracker at #1297

Preview at: https://github.com/GoogleContainerTools/jib/blob/proposal-progress-output/proposals/progress_output.md

Brief recording of the current state of the POC: https://asciinema.org/a/H4BIcjEYsSa8Rtyy0ayZt01Xh

[chanseokoh]

I like this. Some layers are tiny and others huge. You get the feeling of how much it will take when you know the entire size.

[coollog]

What do you think about including time elapsed and/or a progress bar as well?

[chanseokoh]

Adding time sounds fine, but I think the process bar won't help much unless you are doing in-place ncurses-like line replacement. I think we can start simple.

[TadCordle]

Don't we need to do in-place replacement anyway if we're showing byte completion?

[coollog]

It'll be just like the percentage completion except rather than a percent, it will show the absolute byte counts.

[briandealwis]

Elapsed time and throughput (average and instantaneous) are helpful when diagnosing sloooow connections.

[coollog]

Let's take a poll:

Place your name after the option(s) you would like to vote for

• byte completion | votes: chanseokoh, TadCordle
• time elapsed | votes: chanseokoh, TadCordle
• progress bar | votes:
• throughput | votes: chanseokoh (average only)

[loosebazooka]

1. In Jib core this will be implemented as events?

2. We don't have to use gradle/maven logging directly. We might be able to use system.out and mess with \r conditionally based on the log level

if loglevel.atleast INFO {
  print "progress\r"
}

3. We could then potentially do a single progress bar of some style for example:

Executing 6/10 tasks [========================         ] 80% complete

[coollog]

1. Yes, we should have the progress be emitted via progress events.
2. Not sure how we would be able to find which line to update in this case since different lines may print after other lines return to the beginning?
3. So as in we would perform synchronization among the tasks? I feel like we should avoid that since it might unnecessarily add a bit to build times and increase complexity.

[loosebazooka]

2. Yeah I'm not sure how clean this would be, but ending a line with \r should just move the cursor so any new log message will overwrite it and our next progress will just be on the latest line.
3. Would not be synchronization of the tasks, but smarter handling of the progress on the plugin side.

[chanseokoh]

3. So as in we would perform synchronization among the tasks? I feel like we should avoid that since it might unnecessarily add a bit to build times and increase complexity.

One way is to do something our internal build tool does: start with known total bytes to process, and as we discover more bytes to process, re-scale the whole progress workload. For example, at first it might look "10MB/100MB", but as you start processing more layers, it may become "11MB/254MB", "12MB/318MB", and so on.

[loosebazooka]

3. Oh yeah, sorry, the progress bar would be variable as @chanseokoh describes, moving around like a drunken windows progress bar (in a good way)

[coollog]

Yea, a variable progress bar would work, though it would still mean that there would have to be synchronization of some running total across the tasks though, whereas currently we don't have any explicit shared mutable memory between the concurrent tasks.

[loosebazooka]

They all just send their progress over to the progress handler? And it does the math? They don't have to know about eachother.

[coollog]

The tasks won't need to know about each other, but the progress handler would need to have synchronized memory to handle the concurrent mutations of its progress/total counters, which would lock the tasks against each other during progress updates.

[loosebazooka]

Oh I see, so the event manager isn't dispatching events on a single thread? A UI Thread, like swing?

[coollog]

The event manager dispatches to a method call on the thread it is dispatched from, although that method could be implemented to execute logic on another thread if needed. However, we probably should avoid having another thread purely for progress monitoring since that could incur a significant cost in context switching for all the progress updates.

[chanseokoh]

For updating a global counter, I think AtomicInteger.getAndAdd() may work, which atomically adds a number in a lock-free and thread-safe manner. No explicit synchronization is required.

From the Javadoc,

The specifications of these methods enable implementations to employ efficient machine-level atomic instructions that are available on contemporary processors. However on some platforms, support may entail some form of internal locking. Thus the methods are not strictly guaranteed to be non-blocking -- a thread may block transiently before performing the operation.

I think nowadays with most users using contemporary processors, it will work efficiently without blocking. Even if it blocks, it should be transient (which I don't think will actually happen in practice on modern machines). And given the very low update frequency (10-second interval or so?), the chance of contention seems extremely low.

[chanseokoh]

Oh I see, so the event manager isn't dispatching events on a single thread? A UI Thread, like swing?

AFAIK, Gradle uses a separate dedicated thread (via Executors.newSingleThreadExecutor()) to print logs, while on the Maven side, logs are printed by the thread firing the log event.

[coollog]

There's also the issue that we would not be able to log anything else after the progress bar starts and before it finishes, so this would not be compatible with other messages like retrying with auth token. The original "Building..." messages would all be replaced too.

[chanseokoh]

Yeah, so I'm actually skeptical with the \r approach. (On the other hand, the single, uber progress "bar" can still work without \r.)

[loosebazooka]

Yeah using \r is susceptible to corruption, but the idea is basically something like this

#!/bin/bash

printf "progress [----    ]\r"
sleep 1
printf "some log statement here\n"
printf "progress [----   ]\r"
sleep 1
printf "some other log statment\n"
printf "progress [----   ]\r"

[TadCordle]

I think I'm with @loosebazooka on this one, \r may be susceptible to corruption but I think we can make it work if we're careful. It may be a little extra work on our end but I think it ends up being a better user experience than just printing more log messages.

[coollog]

Updated with design towards the progress bar approach. See Proposal section. If looks good, I will start implementing the DAT-based progress events first.

[chanseokoh]

I read through it, and still not clear if this will work as intended, if what I understood is correct, which makes me think probably I'm missing something.

So, what I can only think of for the intention of a tree is that, basically, the root node corresponds to the top-level entity that kicks off multiple second-level async "steps". For example, if you look at BuildSteps.forBuildToDockerRegistry, it spawns 12 steps:

  public static BuildSteps forBuildToDockerRegistry(BuildConfiguration buildConfiguration) {
    return new BuildSteps(
        DESCRIPTION_FOR_DOCKER_REGISTRY,
        buildConfiguration,
        () ->
            new StepsRunner(buildConfiguration)
                .runRetrieveTargetRegistryCredentialsStep()
                .runAuthenticatePushStep()
                .runPullBaseImageStep()
                .runPullAndCacheBaseImageLayersStep()
                .runPushBaseImageLayersStep()
                .runBuildAndCacheApplicationLayerSteps()
                .runBuildImageStep()
                .runPushContainerConfigurationStep()
                .runPushApplicationLayersStep()
                .runFinalizingPushStep()
                .runPushImageStep()
                .waitOnPushImageStep());
  }

So you intend that you create a root node here with 12 allocation units, pass the root node to the 12 Step instances, and each step will create a single child node (with some allocation units) soon, resulting in 13 nodes (1 root + 12 children) at some point? And each Step further passe down its child node to methods and instances it own in the similar manner?

[coollog]

Yes, that is how it is intended to work. The only thing that will need to known prior to an allocation node being created is the number of allocation units that node should have.

[coollog]

Oh one thing to note is that the root node with 12 allocation units does not necessarily need to have 12 children - allocation units can be "occupied" by non-node-based updates (like received bytes in the download progress case).

[chanseokoh]

If so (passing down the root node to multiple async step instances), and if the root and the children are physically connected (I assume so, because otherwise, it isn't a tree at all), isn't it that you are sharing the tree (at least the root node) concurrently? It sounds like basically you are sharing a single progress state. I thought it'd be cool if anyone could just fire progress events in an isolated manner, not having to establish any connection in relation to others. With no communications with others, it may be impossible to avoid the "backward-moving" progress bar, but I think it's worth the sacrifice for simplicity.

[coollog]

The node(s) are passed down, but they are all immutable with no progress state. The state is only kept at the receiving end (the progress monitor that receives the progress events). The DAT is essentially just a representation of what fraction of the total progress a progress event actually accounts for. This allows for progress events to be emitted asynchronously and in a decentralized manner, only to be collected by the progress monitor and summed into an overall current progress.

[briandealwis]

https://github.com/GoogleCloudPlatform/appengine-plugins-core/blob/master/src/main/java/com/google/cloud/tools/managedcloudsdk/ChildProgressListener.java

[TadCordle]

It may end up being difficult reading these log messages if we put them on one line/constantly update them; it seems like this layout would be great for serial operations, but when we have a bunch of steps executing at once, showing the log messages like this may not add a lot of value.

[coollog]

Update: working on prototyping having these on multiple lines - it makes things look a lot clearer

[TadCordle]

How will this work at different logging levels?

[coollog]

I think we can disable the progress bar for logging levels debug and higher since there will be many log messages to indicate progress anyways, but the progress bar itself should be implemented such that it does not interfere with the other log messages Jib emits.

[coollog]

A recording of the WIP POC: https://asciinema.org/a/H4BIcjEYsSa8Rtyy0ayZt01Xh

There are still a few artifacts to clean up, most notably Gradle's own progress logs being left over. Also, the old log messages would be disabled since they don't add anything of value anymore.

[TadCordle]

The prototype looks good to me, I think you just need to update the proposal with your findings from prototyping.

[coollog]

Updated the example and made a note about the things that need to be handled for Gradle logging.