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

Silent wrong interrupted error for interrupted iteration #1284

Closed

Conversation

cuonglm
Copy link
Contributor

@cuonglm cuonglm commented Dec 19, 2019

goja Interrupt only interrupts the JS vm, not the Go code which runs it.
So there might be a race condition that an interrupted iteration was not
probably detected, especially in case of heavy load.

Detect that case and silent the interrupted error.

Fixes #1283

@cuonglm cuonglm requested review from imiric and na-- December 19, 2019 07:28
@cuonglm cuonglm added this to the v1.0.0 milestone Dec 19, 2019
goja Interrupt only interrupts the JS vm, not the Go code which runs it.
So there might be a race condition that an interrupted iteration was not
probably detected, especially in case of heavy load.

Detect that case and silent the interrupted error.

Fixes #1283
@cuonglm cuonglm force-pushed the cuonglm/fix-error-msg-interrupted-iteration branch from 0f58cb9 to bb93559 Compare December 19, 2019 07:29
@codecov-io
Copy link

codecov-io commented Dec 19, 2019

Codecov Report

Merging #1284 into new-schedulers will decrease coverage by 0.02%.
The diff coverage is 0%.

Impacted file tree graph

@@                Coverage Diff                 @@
##           new-schedulers    #1284      +/-   ##
==================================================
- Coverage           74.92%   74.89%   -0.03%     
==================================================
  Files                 159      159              
  Lines               12288    12290       +2     
==================================================
- Hits                 9207     9205       -2     
- Misses               2590     2593       +3     
- Partials              491      492       +1
Impacted Files Coverage Δ
js/runner.go 82.5% <0%> (-0.64%) ⬇️
lib/executor/vu_handle.go 90% <0%> (-5.72%) ⬇️
lib/helpers.go 95.83% <0%> (-4.17%) ⬇️
lib/executor/variable_looping_vus.go 91.62% <0%> (+0.93%) ⬆️
lib/executor/per_vu_iterations.go 96.55% <0%> (+2.29%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f6be35c...bb93559. Read the comment docs.

@cuonglm cuonglm requested a review from mstoykov December 19, 2019 07:48
@na--
Copy link
Member

na-- commented Dec 19, 2019

I'm confused... 😕 We're interrupting the JS VM only after the VU context is done: https://github.com/loadimpact/k6/blob/f6be35cfa006c56954d6821e0f94f4863f063e45/js/runner.go#L316-L319

But isFullIteration is true only if the VU context isn't done: https://github.com/loadimpact/k6/blob/f6be35cfa006c56954d6821e0f94f4863f063e45/js/runner.go#L483-L489

So how come your fix, which checks both of these things, work? https://github.com/loadimpact/k6/blob/bb935595d622d99006bad431cf0eee3b3ec84b23/js/runner.go#L444-L446

Something smells fishy and I think we have a bigger underlying issue here 😕

@cuonglm
Copy link
Contributor Author

cuonglm commented Dec 20, 2019

@na-- the one you linked above are in runPart, what’s actually happened in RunOnce. But the main thing here is we interrupt the VU.Runtime and checking ctx.Done (both in RunOnce and runFn) concurrently, that leads to the racy behavior.

If you see the other place where we call runFn, there’s also a check like I added.

@na--
Copy link
Member

na-- commented Dec 20, 2019

hmm I'm still not sure I completely grok what's happening here... 😕 Something seems fishy, because your fix, as well as the one you pointed out in runPart() just seem like they're masking the race instead of fixing it: https://github.com/loadimpact/k6/blob/f6be35cfa006c56954d6821e0f94f4863f063e45/js/runner.go#L328-L337

If we call interrupt only after the context is done: https://github.com/loadimpact/k6/blob/f6be35cfa006c56954d6821e0f94f4863f063e45/js/runner.go#L407-L411

And if we set isFullIteration to true only if the context isn't done, but the err result is before that check: https://github.com/loadimpact/k6/blob/f6be35cfa006c56954d6821e0f94f4863f063e45/js/runner.go#L480-L489

How is it possible that we have both a full iteration and an interrupted one at the same time? https://github.com/loadimpact/k6/blob/bb935595d622d99006bad431cf0eee3b3ec84b23/js/runner.go#L444-L446

Just to have those two things in the same if statement seems like a contradiction... 😕

@cuonglm
Copy link
Contributor Author

cuonglm commented Dec 20, 2019

@na-- That's a race, so you can't guarantee anything. The main point is that you run the interrupt inside a goroutine, so it's completely upto scheduler to schedule them to run. I add some logrus.Debug lines and see that whenever this happen, isFullIteration is true and the call JS runtime return an error.

If you see commit message in a2e1c6f, @mstoykov also mention about this problem.

Copy link
Member

@na-- na-- left a comment

Choose a reason for hiding this comment

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

Well, if it's a race, shouldn't we fix it, instead of working around it? The isFullIteration && gErr.Value() == errInterrupt check is obviously fishy - an iteration cannot be both Full and also interrupted at the same time. If both of these conditions are true, then one of them doesn't make sense and has to be fixed...

If you see commit message in a2e1c6f, @mstoykov also mention about this problem.

I'm not sure that's the same problem. His change fixed a panic that occurs when the number of VUs is rapidly changed via the k6 REST API. Now that I think about it, I'm not sure his change is actually necessary in the new-schedulers branch...

@cuonglm cuonglm closed this Dec 24, 2019
@cuonglm cuonglm deleted the cuonglm/fix-error-msg-interrupted-iteration branch December 24, 2019 06:29
@mstoykov mstoykov modified the milestones: v1.0.0, v0.27.0 Jul 13, 2020
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.

4 participants