Performance characteristic of and'ing matchers on expected args appears exponential

[imtayadeway]

I don't know if this is a bug per se, or just unavoidable from the way I am writing this test.

Basically I am trying to solve a problem that looks something like this:

require "rspec/autorun"

class Logger
  def info(_message)
  end
end

RSpec.describe "and" do
  it "does something" do
    logger = Logger.new
    allow(logger).to receive(:info)

    message = ("a".."z").each_with_object({}) { |c, hsh| hsh[c.to_sym] = c }.inspect

    expect(logger).to receive(:info).with(
                        a_string_matching(':a=>"a"')
                        .and(matching(':b=>"b"'))
                        .and(matching(':c=>"c"'))
                        .and(matching(':d=>"d"'))
                        .and(matching(':e=>"e"')))

    logger.info("foo")
    logger.info("bar")
    logger.info("baz")
    logger.info("qux")
    logger.info(message)
  end
end

Basically, I'm trying to refactor some tests concerned with logging and putting expectations on logged messages. There are some parts of the message that might be non-deterministic, so I may not be able to specify the whole of the expected message in one matcher, or be able to say with certainty which order the elements might appear.

The time for this test to finish seems to grow exponentially as the number of chained matchers increases. Here are some numbers showing the time taken as I increase the number of chained matchers, with 5 actual received messages:

no. chained matchers	time
5	0m0.122s
6	0m0.143s
7	0m0.188s
8	0m0.293s
9	0m0.590s
10	0m1.346s
11	0m3.434s
12	0m9.384s
13	0m23.155s

I can't tell if the problem I have is inherently exponential, although naively it seems it doesn't necessarily have to be so - I'd expect (again, naively) that the first failed match would short circuit any additional ones.

Perhaps there's a better way to write this test? If you think this could be a bug, as always, I'm happy to dig into this.

[myronmarston]

It's definitely something we should improve.

I'd expect (again, naively) that the first failed match would short circuit any additional ones.

That makes a lot of sense, but we evaluate the subject against all of the matchers (even if each fails) so that the failure message can list the failure message from each non-matching part. That way, the user gets a list of everything that failed to match instead of just getting the first failure, and then having to fix that and re-run to see the next failure.

Here you are using the compound matcher as an arg matcher to with, which won't wind up using the matcher's failure message at all....but the matcher doesn't know that, so it still checks against all the matchers.

So yes, it would be nice to improve this, but it's not clear how to do so while retaining the current detailed failure messages. We welcome any attempt to improve it!

As for your specific example, I think you can avoid the problem by moving away from using a message expectation here. Instead, I'd inject a StringIO into the logger here, and then you can make expectations about the logged output against StringIO#string at the end of the example. That should avoid the problem, I think.

[imtayadeway]

So yes, it would be nice to improve this, but it's not clear how to do so while retaining the current detailed failure messages. We welcome any attempt to improve it!

Thanks @myronmarston ! I will try to dig in and let you know if I make any progress with this