Add ability to display intermediate result while the test is running #1849
Conversation
|
Thanks, we'll take a look soon! Before that, can you forego the update of the |
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
9fd84f2 to
81bed3b
Compare
done. |
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
2 times, most recently
from
35d979a to
f6e81ca
Compare
Codecov Report
@@ Coverage Diff @@
## master #1849 +/- ##
==========================================
- Coverage 71.57% 71.46% -0.11%
==========================================
Files 179 179
Lines 13930 13957 +27
==========================================
+ Hits 9971 9975 +4
- Misses 3327 3350 +23
Partials 632 632
Flags with carried forward coverage won't be shown. Click here to find out more.
Continue to review full report at Codecov.
|
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
f6e81ca to
164f911
Compare
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
164f911 to
a379c37
Compare
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
f6e81ca to
3e3873e
Compare
There was a problem hiding this comment.
Thanks for making the PR! While it technically satisfies most of the requirements of the issue, there are some bugs, as well as several things that aren't done optimally - both from an UX and from an implementation perspective. I've noted some of them as inline comments and I'll explain the rest below.
First, there seem to be some data races when we run k6 with go run -race:
Write at 0x00c000d94000 by goroutine 26:
github.com/loadimpact/k6/cmd.showProgress.func2()
github.com/loadimpact/k6/cmd/ui.go:296 +0x1ef
github.com/loadimpact/k6/cmd.showProgress()
github.com/loadimpact/k6/cmd/ui.go:363 +0x3c5
github.com/loadimpact/k6/cmd.getRunCmd.func1.1()
github.com/loadimpact/k6/cmd/run.go:191 +0x2cd
Previous read at 0x00c000d94000 by goroutine 32:
github.com/loadimpact/k6/cmd.showProgress.func1()
github.com/loadimpact/k6/cmd/ui.go:288 +0x90
github.com/loadimpact/k6/cmd.(*consoleWriter).Write()
github.com/loadimpact/k6/cmd/ui.go:73 +0x24a
bytes.(*Buffer).WriteTo()
bytes/buffer.go:239 +0x1e7
io.copyBuffer()
io/io.go:391 +0x482
io.Copy()
io/io.go:368 +0x464
github.com/loadimpact/k6/cmd.handleSummaryResult()
github.com/loadimpact/k6/cmd/run.go:453 +0x474
github.com/loadimpact/k6/cmd.printSummaryResults()
github.com/loadimpact/k6/cmd/run.go:473 +0x2e4
github.com/loadimpact/k6/cmd.readInput()
github.com/loadimpact/k6/cmd/run.go:502 +0x225
github.com/loadimpact/k6/cmd.getRunCmd.func1.4()
github.com/loadimpact/k6/cmd/run.go:258 +0x8a
and
Read at 0x00c00270a608 by goroutine 32:
github.com/loadimpact/k6/stats.(*RateSink).Calc()
<autogenerated>:1 +0x4f
github.com/loadimpact/k6/js.metricValueGetter.func1()
github.com/loadimpact/k6/js/summary.go:129 +0x72
github.com/loadimpact/k6/js.summarizeMetricsToObject()
github.com/loadimpact/k6/js/summary.go:176 +0x638
github.com/loadimpact/k6/js.(*Runner).HandleSummary()
github.com/loadimpact/k6/js/runner.go:312 +0x117
github.com/loadimpact/k6/cmd.printSummaryResults()
github.com/loadimpact/k6/cmd/run.go:467 +0x1ab
github.com/loadimpact/k6/cmd.readInput()
github.com/loadimpact/k6/cmd/run.go:502 +0x225
github.com/loadimpact/k6/cmd.getRunCmd.func1.4()
github.com/loadimpact/k6/cmd/run.go:258 +0x8a
Previous write at 0x00c00270a608 by goroutine 48:
github.com/loadimpact/k6/stats.(*RateSink).Add()
github.com/loadimpact/k6/stats/sink.go:168 +0x64
github.com/loadimpact/k6/core.(*Engine).processSamplesForMetrics()
github.com/loadimpact/k6/core/engine.go:413 +0xc1b
github.com/loadimpact/k6/core.(*Engine).processSamples()
github.com/loadimpact/k6/core/engine.go:443 +0x10b
github.com/loadimpact/k6/core.(*Engine).processMetrics.func2()
github.com/loadimpact/k6/core/engine.go:275 +0x38e
github.com/loadimpact/k6/core.(*Engine).processMetrics()
github.com/loadimpact/k6/core/engine.go:285 +0x333
And this is when the handleSummary() call is synchronous with detecting the key presses, which it probably shouldn't be (see inline comment on the topic). I also realize that testing UI input is very difficult, but some tests of the actual logic here (without any keyboard) would have probably caught at least the second data race in CI. So please add some... 😅
Finally, I am not sure about the https://github.com/eiannone/keyboard dependency... It has some scary open issues, and me and @imiric actually managed to hit a strange bug we think was caused by the dependency. We haven't been able to consistently reproduce it, but we somehow managed to enter a state where hitting Esc would sometimes disable special input entirely, ignoring even Ctrl-C / Ctrl-Z! This messed up the terminal even after k6 exits - Ctrl-C/Ctrl-Z were ignored and are printed instead, and the only fix was running reset in the terminal... 😕 We independently hit the issue while testing your code, him twice and me once, but we can't reproduce it consistently... 🤷♂️
Also, in general, I am not sure such a dependency is needed. See this SO answer for example. You can use golang.org/x/term.MakeRaw() to switch the terminal to raw mode (and back to cooked mode at the end of k6) and just read a single character from stdin. There are other ways to check what stdin actually is as well: https://stackoverflow.com/a/26567513/9629802
We already use a precursor to this stdlib-adjacent library, golang.org/x/crypto/ssh/terminal for k6 login forms and progressbars. I think using the same golang.org/x dependency for reading characters from stdin would have a much lower possibility of issues long-term. And if for some reason that library doesn't work on some OS, there seem to be a lot of drop-in replacements that enable setting terminals to raw mode (e.g. https://github.com/containerd/console, https://github.com/pkg/term), whereas this keyboard seems to be its own special thing that doesn't work very well...
cmd/run.go
Outdated
| @@ -457,3 +457,55 @@ func handleSummaryResult(fs afero.Fs, stdOut, stdErr io.Writer, result map[strin | |||
|
|
|||
| return consolidateErrorMessage(errs, "Could not save some summary information:") | |||
| } | |||
|
|
|||
| func printSummaryResults(globalCtx context.Context, | |||
There was a problem hiding this comment.
This is a potentially a wrong name - handleSummary() might not print anything to stdout or stderr, it might just write files.
Also, I realize that stdout and stderr are unfortunately global variables. We want to clean that up eventually, and the way to do that is to use dependency injection even with them, i.e. pass them as parameters. See how handleSummaryResult() expects them as parameters, despite also having access to the same global variables directly. As a side-benefit, this also makes it much more testable...
cmd/run.go
Outdated
| defer func() { | ||
| _ = keyboard.Close() | ||
| }() | ||
| fmt.Println("Press R to get summary or esc to run Ctrl-C/Ctrl-Z") |
There was a problem hiding this comment.
This is suboptimal in two different ways. First, instead of directly printing to stdout with fmt.Println(), it would be much better to use fmt.Fprintf(stdout, "Press R..."), ideally with stdout being injected as parameter.
Second, and more importantly, we wouldn't want to enter a separate state to handle R specifically and ignore Ctrl+C. If you must capture all keyboard input exclusively here, you can simply capture Ctrl+C as well and send an event over sigC, so the Ctrl+C handling occurs normally. And if we don't have a separate mode for the summary, we don't need this message at all.
cmd/run.go
Outdated
| return err | ||
| } | ||
| defer func() { | ||
| _ = keyboard.Close() |
There was a problem hiding this comment.
An error here probably deserves at least logging it, you already have the logger anyway.
cmd/run.go
Outdated
| forLoop: | ||
| for { | ||
| event := <-keysEvents |
There was a problem hiding this comment.
Why this code and not for event := range keysEvents {}?
| @@ -251,6 +252,15 @@ a commandline interface for interacting with it.`, | |||
| os.Exit(externalAbortErrorCode) | |||
| }() | |||
|
|
|||
| // start reading user input | |||
| if !runtimeOptions.NoSummary.Bool { | |||
There was a problem hiding this comment.
Checking if stdin is a terminal here is probably a good idea. I don't know how the github.com/eiannone/keyboard dependency would react if it isn't, but at best, we're going to get a useless error in the logs from logger.Error(riErr) below, when it fails on most CI systems to listen to key presses.
cmd/run.go
Outdated
| return event.Err | ||
| } | ||
| if event.Rune == 'R' { | ||
| printSummaryResults(globalCtx, runner, engine, executionState, log) |
There was a problem hiding this comment.
This can potentially take quite a long time, e.g. if you have a ton of metrics data or you make HTTP requests in handleSummary(). With the current code, k6 would be stuck waiting for it to complete before it processes any other input, including Esc or Ctrl+C... So, this needs to happen asynchronously.
To easily replicate the issue, try putting sleep(5) in handleSummary() and see how this code behaves.
|
few notes:
still there are few small bugs, i'm trying to fix right now. in OSX it's still break terminal size... so Please let me know wdyt regarding new approach? |
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
b0607f3 to
227eaa9
Compare
|
on separate note: |
I haven't looked at the new code, but yes, we'd like this feature to not require hitting enter after whatever trigger we've decided is written ( |
Few links might help when you try on your side: |
|
Wow, so this turned out to be a can of worms... 😅 Sorry Andrii! There's a couple of issues with the current implementation:
Given that k6 constantly writes to stdout, we can't really switch to raw mode for this feature. So how about this: interpret The obvious drawback of this is that we can't listen for any other key presses, but I'd argue that we really shouldn't anyway. WDYT? |
|
Thanks for the PR @AndriiChuzhynov 🎉 quick thoughts before actually looking at the code:
I have the feeling all of those visual artifacts are due to one problem, and fixing them IMO is more important than whether we will be hitting enter or not. I at least don't get my terminal botched if I additionally (although this is likely unfixable for now) if the scripts are read from the stdin as in edit: I am fine with just hitting enter as well as @imiric proposes. |
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
f376629 to
a0f18e7
Compare
|
@na-- @imiric @mstoykov but than... i get stucked on any ideas where to check to fix this RC: but concerned how to fix showProgress one: looks like we have global variable to lock also i found i can reproduce this bug from time to time in master branch ^^ using 0dd04a3 issue #1860 has been created. |
andriisoldatenko
force-pushed
the
implement-get-summary-when-press-r
branch
from
00a39d3 to
991f1ee
Compare
There was a problem hiding this comment.
Thanks for fixing the data race and reporting the one we have on master! I've tested your latest code and it works, though it's apparent we have to go back to the drawing board with the feature itself... 😞 The UX of the current approach is not great, but the complexity and fragility of the alternative is also bad, even if we manage to get it working nicely without a full-blown ncurses-like CLI UI... I've added a note in #1315 to that effect and tag the issue as evaluation needed.
The locking you've employed to get rid of the data race also deserves some further consideration and improvements. I'll try to explain, even though there's no point in doing the work for now, given that it doesn't seem likely we'll merge the feature soon because of the other problems with the whole feature.
You are currently locking the whole Engine from processing new metrics and thresholds for the whole duration of handleSummary(), however handleSummary() can potentially take quite a long time to execute if it makes HTTP requests or something like that. If it takes a long time, various VUs can continue generating new metric samples and sending them to the buffered metric Samples channel in the Engine. I think it has a size of 1000 by default, and if that ever overflows, VUs will be blocked, which would affect the load test execution negatively.
A better locking approach instead would be to only lock the Engine.MetricsLock only while we export the data we pass to handleSummary, but not during the actual execution of the callback. So, basically, wrap this line: https://github.com/loadimpact/k6/blob/6bebdd632eceadf6f8b50d4c47814b3a1688e976/js/runner.go#L312
Or do it inside of the actual summarizeMetricsToObject() function: https://github.com/loadimpact/k6/blob/6bebdd632eceadf6f8b50d4c47814b3a1688e976/js/summary.go#L160
But as I said, no need to fix this or spend any more time on improvements until we're sure what we want to do here. And despite the fact we're not going to merge the PR for now, the whole effort has been very useful in illuminating all of the tricky issues here, so thank you very much for that and sorry again for the unexpected complexity!
na--
added
the
evaluation needed
|
|
|
I'll close this so it doesn't clutter the list with open PRs. We are not going to merge it as it is, for the reasons explained in #1849 (review), and any lessons learned can still be gleaned from a closed PR, given that it's linked in #1315 (which I'll keep open). |
Closes #1315
https://terminalizer.com/view/fc96dd924634
Example of usage.