Rspec-core: Bisect hangs / 'minimal set' not very minimal / can't bisect a bisect?

[0xdevalias]

Subject of the issue

(Internal Ref for me)
I can't guarantee this isn't just something weird in my environment (this is running inside a docker container).. but I was trying to bisect an issue in our suite yesterday, and it seemed that each test run was increaasing in runtime, with the eventual one just never completing. I left it running overnight in the hopes that it would..

Round 1: bisecting over non-failing examples 1-622 .. multiple culprits detected - splitting candidates (6 minutes 43 seconds)
Round 2: bisecting over non-failing examples 1-311 .. multiple culprits detected - splitting candidates (8 minutes 54 seconds)
Round 3: bisecting over non-failing examples 1-156 .. multiple culprits detected - splitting candidates (10 minutes 0 seconds)
Round 4: bisecting over non-failing examples 1-78 .. multiple culprits detected - splitting candidates (12 minutes 30 seconds)
Round 5: bisecting over non-failing examples 1-39 .. multiple culprits detected - splitting candidates (12 minutes 34 seconds)
Round 6: bisecting over non-failing examples 1-20 .. multiple culprits detected - splitting candidates (12 minutes 17 seconds)
Round 7: bisecting over non-failing examples 1-10 .. multiple culprits detected - splitting candidates (53 minutes 3 seconds)
Round 8: bisecting over non-failing examples 1-5 .. multiple culprits detected - splitting candidates (73 minutes 29 seconds)
Round 9: bisecting over non-failing examples 1-3

So I cancelled it, and hoped the 'minimal' reproduction would help me, then I could bisect on that again to finish off the last little bit. But what it gave me back looked like more or less my entire spec suite again, but with extra keys added.

bin/rspec ./spec/commands/foo_commands/helpers/a_spec.rb[1:1:1:1,1:2:1:1,1:3:1:1] ./spec/commands/bar_commands/b_spec.rb[1:1:1,1:1:2,1:1:3,1:2:1,1:2:2,1:2:3] ./spec/commands/baz_commands/c_spec.rb[1:1:1,1:1:2,1:1:3,1:1:4,1:2:1,1:2:2] 
...etc for ~78 spec files total...

I thought those keys seem like they may just uniquely point to every single test anyway, but looking at the first one, it seems to have 5 tests in it (but only 3 keys). So I guess it is 'cut down'.

But if i try to --bisect on that list again, it tries to run all 622 tests again:

Round 1: bisecting over non-failing examples 1-622

Given the final 'useful' output I received was Round 9: bisecting over non-failing examples 1-3, I expected my 'minimal set' would only be maybe 3 specs or so, but obviously that didn't seem to be the case.

Your environment

• Ruby version: 2.4.6
• rspec-core version: 3.7.1

Steps to reproduce

Hard to give exact steps here... basically bisecting over a large slice of our specs and hitting this issue.

Expected behavior

• Bisect completes each test run in a similar timeframe (and thus ultimately, completes)
• Can bisect the 'cut down' list of tests, to make it run quicker next time
• The 'cut down' tests i get back when I cancel should be a lot smaller

Actual behavior

_described above_

[0xdevalias]

Note: i also tried bumping to rspec-core 3.8.0, hoping to get the bisect speed improvements mentioned in https://github.com/rspec/rspec-core/blob/master/Changelog.md#380--2018-08-04 but it hasn't seemed to make much of a difference: still jumps from ~12min -> ~54min+

Round 6: bisecting over non-failing examples 1-20 .[web] [f4f2ea1e-5fec-4c5e-ae12-061c183021a6] [127.0.0.1]
. multiple culprits detected - splitting candidates (12 minutes 53 seconds)

Round 7: bisecting over non-failing examples 1-10 .[web] [e5943343-50ad-4b3e-af4e-3522004dd416] [127.0.0.1]
. multiple culprits detected - splitting candidates (53 minutes 56 seconds)

Round 8: bisecting over non-failing examples 1-5 .[web] [b5c9005a-0747-40c3-962e-7cce674f245d] [127.0.0.1]
. multiple culprits detected - splitting candidates (74 minutes 1 second)

Round 9: bisecting over non-failing examples 1-3 [web] [7b2a548e-fc61-4b08-82ee-d976bd3fc254] [127.0.0.1]
. multiple culprits detected - splitting candidates (311 minutes 57 seconds)

Round 10: bisecting over non-failing examples 1-2 [web] [90fcaae4-4875-4946-b784-e1f346d3ba0e] 
. multiple culprits detected - splitting candidates (583 minutes 21 seconds)

Round 11: bisecting over non-failing examples 4-5 [web] [9dee9904-dd16-4761-bc40-89c1a83cb211] 
. multiple culprits detected - splitting candidates (73 minutes 49 seconds)

Round 12: bisecting over non-failing examples 6-10 [web] [1d398a4e-07d5-424f-98f7-ca5168fe3ba0] 
. multiple culprits detected - splitting candidates (73 minutes 52 seconds)

Round 13: bisecting over non-failing examples 6-8 [web] [83446f7e-d81c-475a-9291-2599f7c8db56] 
. multiple culprits detected - splitting candidates (73 minutes 35 seconds)

Round 14: bisecting over non-failing examples 6-7 [web] [77567638-45cf-4b08-84b3-e40c539c4502]
. multiple culprits detected - splitting candidates (73 minutes 38 seconds)

Round 15: bisecting over non-failing examples 9-10 [web] [b5703e52-de2a-47fe-b65b-fb38cccef0fc]
..in progress..

[JonRowe]

The forma of ./spec/commands/foo_commands/helpers/a_spec.rb[1:1:1:1,1:2:1:1,1:3:1:1] is multiple ids for a file, so it should be selecting specs. If these are groups it will run them all.

~Without further reproduction its going to be hard to find whats causing that not to work...~

When cancelling its the current set of examples its running to produce the failure, so fixing the performance should fix that.

Regards to performance its likely this its from your own specs, it'd be worth profiling the runs a bit. I'd guess you have a memory leak or an issue with something else backing up between runs which is evidencing itself in the repeated runs.

[0xdevalias]

The forma of ./spec/commands/foo_commands/helpers/a_spec.rb[1:1:1:1,1:2:1:1,1:3:1:1] is multiple ids for a file, so it should be selecting specs. If these are groups it will run them all.

I do understand that. From the initial few I manually dug into it seemed to be 'individually referencing' every spec in the file. But I have since disproved that theory. I've just segmented it off to see if it will ever actually finish running. Up to round 22 now, with most running in the ~70min range now (though I have seen as high as 965min).

Is there a way at this point to print out the 'minimal selection' command without cancelling the run? I'd be curious to see if/how much more minimal it appears now at this level. I know I could have seen it if I started in verbose mode.. but it's a little late for that now.

I'll have to see if I can do some profiling over the first few runs (maybe once this one finishes playing out, just for funsies) and see if I can pin down any more specifics with it.

Any thoughts on the 'bisecting a bisect'? Eg. if I take the 'minimal reproduction', and then bisect from that, should it theoretically be similar to 'picking up where I left off'? Or will it more or less be starting the entire process again.

[JonRowe]

It should take a minimal reproduction and try to bisect it to produce a... more minimal... reproduction. If it's adding more specs in then there is something awry with either the examples it's loading (e.g they're groups or triggering shared examples in some way) or with the filtering being applied.

Not ruling out a bug there but seeking more information for sure! :)

[pirj]

Closing for now, since there's no clear way how to reproduce.
Please feel free to reopen.

[benoittgt]

This PR may fix the issue. https://github.com/rspec/rspec-core/pull/2669

But it can be closed. Thanks @pirj