Skip to content

Add statistics option for stage durations#303

Closed
lzap wants to merge 6 commits intoosbuild:mainfrom
lzap:stats1
Closed

Add statistics option for stage durations#303
lzap wants to merge 6 commits intoosbuild:mainfrom
lzap:stats1

Conversation

@lzap
Copy link
Contributor

@lzap lzap commented Sep 16, 2025

This adds a new option that prints statistics. There is a small refactoring and enhancements of the progress bar in several separate commits. I took inspiration from e142ee3 but that commit was missing tests so I did not pulled that in and did this myself.

The first commit upgrades to the latest images library, I was not sure what to do with the repommd option so setting that to nil. This probably needs a followup.

Then a new option is added that collects data from osbuild (recent version needed). The goal is to print the top 10 stages at the end of the build. Anything shorter than 1 second is ignored and resolution is seconds (no fractions of seconds) because we are really interested in longest stages. Example:

$ OSBUILD_COMMAND=/home/lzap/bin/osbuild ibcli build --distro fedora-41 --with-statistics minimal-raw
~/image-builder-cli ~
[|] Image building step
[7 / 7] Pipeline xz [--------------------------------------------------------------------------------------------------------------------------------------------->] 100.00%
[2 / 2] Stage org.osbuild.xz [------------------------------------------------------------------------------------------------------------------------------------>] 100.00%
Message: Finished pipeline xz
Statistics:
  Finished module org.osbuild.rpm: 1m8s
  Finished module org.osbuild.xz: 22s
  Finished module org.osbuild.rpm: 9s
  Finished module org.osbuild.selinux: 6s
  Finished module org.osbuild.copy: 2s

Note: You need the most recent osbuild release in order to see any durations through JSONSeq monitor. If you run it with older version, nothing will be printed.

https://issues.redhat.com/browse/HMS-9311

@lzap lzap requested a review from a team as a code owner September 16, 2025 11:29
@lzap lzap requested review from bcl, mvo5 and supakeen and removed request for a team September 16, 2025 11:29
Copy link
Contributor

@mvo5 mvo5 left a comment

Choose a reason for hiding this comment

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

This looks nice, some quick feedback/suggestions inline, hope they are useful.

func getTerminalWidth() int {
width, _, err := term.GetSize(int(os.Stdout.Fd()))
if err != nil {
width = 80
Copy link
Contributor

Choose a reason for hiding this comment

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

I need to double check this but there was a reason to have the default at 60, my bad for not adding a comment though (sorry!). Did you try this for real and see no overflowing lines or other weird behavior?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Sure, it is better to be on the safe side with this.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Oh I think I might know - the spinner takes few characters, but I actually remove 10 characters on the next line so this 80 is effectively 70. Do you want me to subtract 20 characters instead?

I did not notice anything unusual but this is the first time I am playing around with the new progress bar. It falls apart when I mess around with terminal width so unsure about it. Please test this.

Copy link
Contributor

Choose a reason for hiding this comment

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

I looked into this and remember now. The issue is that the prefix needs to be substracted from the len of the terminal. The prefix is len("[/]") and len("Message: "). So just hardcoding 10 instead of 20 (or 60) works out because len("Message: ") is 9. But ideally we would do this properly when we touch this code again (the original code is very bad, no question here). I will make a tiny suggestion after lunch.

Fwiw, I still would prefer if this would just be split out and not part of this PR (as Simon also suggested).

Copy link
Contributor

Choose a reason for hiding this comment

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

Maybe something like this:

diff --git a/pkg/progress/progress.go b/pkg/progress/progress.go
index 564cc10..3194cd2 100644
--- a/pkg/progress/progress.go
+++ b/pkg/progress/progress.go
@@ -164,22 +164,22 @@ func getTerminalWidth() int {
 }
 
 func (b *terminalProgressBar) SetPulseMsgf(msg string, args ...any) {
-       b.spinnerPb.Set("spinnerMsg", util.ShortenString(fmt.Sprintf(msg, args...), getTerminalWidth()-10))
+       b.spinnerPb.Set("spinnerMsg", fmt.Sprintf(msg, args...))
 }
 
 func (b *terminalProgressBar) SetMessagef(msg string, args ...any) {
-       b.msgPb.Set("msg", util.ShortenString(fmt.Sprintf(msg, args...), getTerminalWidth()-10))
+       b.msgPb.Set("msg", fmt.Sprintf(msg, args...))
 }
 
 func (b *terminalProgressBar) render() {
        var renderedLines int
-       fmt.Fprintf(b.out, "%s%s\n", ERASE_LINE, b.spinnerPb.String())
+       fmt.Fprintf(b.out, "%s%s\n", ERASE_LINE, util.ShortenString(b.spinnerPb.String(), getTerminalWidth()))
        renderedLines++
        for _, prog := range b.subLevelPbs {
                fmt.Fprintf(b.out, "%s%s\n", ERASE_LINE, prog.String())
                renderedLines++
        }
-       fmt.Fprintf(b.out, "%s%s\n", ERASE_LINE, b.msgPb.String())
+       fmt.Fprintf(b.out, "%s%s\n", ERASE_LINE, util.ShortenString(b.msgPb.String(), getTerminalWidth()))
        renderedLines++
        fmt.Fprint(b.out, cursorUp(renderedLines))
 }

ie. shorten after the render.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Incorporated into: #317

@lzap
Copy link
Contributor Author

lzap commented Sep 16, 2025

Rebased:

* Squashed the refactoring and terminal width changes

  • Identified the "mysterious" problem I initially described in the description (I forgot to call a method I created)
  • Got rid of the init() function, but I still think using the ENV variable is very useful for testing
  • Statistics are indented by TAB characters instead of "markdown" like bullets
  • No fractions of seconds for better readability
Statistics:
  Finished module org.osbuild.rpm: 1m8s
  Finished module org.osbuild.xz: 22s
  Finished module org.osbuild.rpm: 9s
  Finished module org.osbuild.selinux: 6s
  Finished module org.osbuild.copy: 2s

@lzap
Copy link
Contributor Author

lzap commented Sep 16, 2025

Oh also squashed the go.mod change for x/term because images were already upgraded to v0.109 in the meantime.

Copy link
Member

@supakeen supakeen left a comment

Choose a reason for hiding this comment

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

I'd love to approve, everything looks fine but I don't like that you've added these terminal width changes into this PR, that will require me to do a bunch more testing to see if things don't break. Especially because I see suspicious slice-out-of-range errors in the test cases in CI here.

Is it maybe possible to decouple the terminal width changes from this PR?

What version of osbuild does this need and do you maybe need to update the Schutzfile or do we need to bump the minimum version of osbuild in images or such?

@lzap
Copy link
Contributor Author

lzap commented Sep 19, 2025

Filed one additional change for images which adds pipeline name for better experience: osbuild/images#1885

I will take a look on the test, I would prefer to keep it in one PR this is not a feature that needs to be rushed.

@lzap
Copy link
Contributor Author

lzap commented Sep 19, 2025

I have found the index of bounds issue, it was actually trivial. If the terminal is not present, width was reported as zero. But the ShortenString utility function had a bug, I fixed it and when the width is zero it returns the very same string without any shortening. Added more unit tests to cover the edge cases including zero width, one character width etc.

This probably means the test that is trying out the progress bar is executed in an environment that does not report proper terminal size, which is no surprise for CICD. Quick googling reveals that we should consider adding --terminal-size 80x24 to the podman command for those tests that show progress bars. I think the test might not even testing anything on CICD at all, not sure what is the behavior for the progress library we use in case of non-interactive terminals.

@supakeen
Copy link
Member

supakeen commented Sep 19, 2025

I have found the index of bounds issue, it was actually trivial. If the terminal is not present, width was reported as zero. But the ShortenString utility function had a bug, I fixed it and when the width is zero it returns the very same string without any shortening. Added more unit tests to cover the edge cases including zero width, one character width etc.

This probably means the test that is trying out the progress bar is executed in an environment that does not report proper terminal size, which is no surprise for CICD. Quick googling reveals that we should consider adding --terminal-size 80x24 to the podman command for those tests that show progress bars. I think the test might not even testing anything on CICD at all, not sure what is the behavior for the progress library we use in case of non-interactive terminals.

Things like these (and there are likely more lurking, terminals are finicky) is why I'd really like to not have the terminal width detection changes in this PR but a separate one where it can be fully considered without detracting from the statistics bits.

The rest of the PR looks great.

@lzap
Copy link
Contributor Author

lzap commented Sep 19, 2025

I fully agree and as much as I would like to split the second commit in this series does a big split of progress.go and command.go and then the last commit edits both. I mean this must be unresolvable via git and the only option would be to fully rewrite this.

What I could do tho is split the duration (the last) commit and rename this PR to be "progress: respect terminal width" if you want. Then I will make a draft that depends on this PR being merged first. But that is not what you are asking for.

I do not know how can I do the mentioned Schutzfile change, I do not see such file in this repo. The current patch needs v0.109 but I guess next week there will be another release already with the pipeline name so I can rebase this one.

Let me know if you want me to add another commit that adds --terminal-size 80x24 to the progress integration test.

@supakeen
Copy link
Member

supakeen commented Sep 19, 2025

I fully agree and as much as I would like to split the second commit in this series does a big split of progress.go and command.go and then the last commit edits both. I mean this must be unresolvable via git and the only option would be to fully rewrite this.

You are doing three separate things in a single PR. A splitting of files, a change in how we handle terminal output, and then the actual change you and I want to land: statistics output.

This is clearly not ideal and has happened in other PRs before as well. I'm really not happy to shoehorn in extra changes I'm not on board with just to get in the one change I do agree with.

If it's too much work for you to detangle this I can do that work for you. Let me know if that's what you prefer and I'll force-push over this branch and open a separate PR for the terminal changes.

I do not know how can I do the mentioned Schutzfile change, I do not see such file in this repo. The current patch needs v0.109 but I guess next week there will be another release already with the pipeline name so I can rebase this one.

Yea sorry, this repository doesn't use that. My bad.

I managed to commit a test image, this should prvent that in future.
The progress.go file is overloaded with functionality, so let's split it into
command.go and progress.go. The command.go will handle the command-line
interface, while progress.go will focus on the core progress tracking logic.

I need this change before I can implement the new feature to track
durations in a more clean way.
There is a common pattern in the progress bar code to shorten
strings to fit into terminal width. This commit introduces a new
utility function for that. It also introduces a fallback terminal
width of 80 columns in case the terminal size cannot be determined.

Added a test for the function and made sure it never returns string
longer than the specified length. That was not the case for the previous
implementation.

Additionally, the progress bar implementation was updated to dynamically
detect the terminal width and adjust message lengths accordingly. This
ensures that progress messages are fully visible without being
truncated, enhancing user experience during long-running operations.

There is few characters left for the spinner and padding, so we subtract
10 from the terminal width when setting message lengths.

A new dependency was introduced, but it was already an indirect one.
When something needs to be printed after the progress bar is done, it
was not possible to do so without messing up the terminal. This patch
adds a mutex around the buffer used to store output while the progress
bar is active. This allows to safely print after stopping the progress
bar.
This commit introduces a new statistics option for the image building
stages, allowing users to get more insights into the duration of each
stage.
@lzap
Copy link
Contributor Author

lzap commented Sep 23, 2025

Okay I did split several PRs from this one, closing.

@lzap lzap closed this Sep 23, 2025
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.

3 participants