v3.5 Matcher performance degradation

[kwhumphreys]

switching from v3.4.4 to v3.5.0 with the same set of Matcher rules gives a large performance decrease.
any suggestions on how to debug this? @adrianeboyd?
EntityMatcher seems unaffected.

v3.4.4

         7535576 function calls (7358145 primitive calls) in 15.440 seconds
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      ...
     1181    0.052    0.000    7.639    0.006 model.py:498(run)
       45    0.000    0.000    7.358    0.164 runner.py:153(pytest_runtest_setup)
       45    0.000    0.000    7.357    0.163 runner.py:476(setup)
       45    0.000    0.000    7.356    0.163 python.py:1791(setup)
       45    0.000    0.000    7.356    0.163 fixtures.py:545(_fillfixtures)
      230    0.000    0.000    7.355    0.032 fixtures.py:552(getfixturevalue)
  533/230    0.002    0.000    7.355    0.032 fixtures.py:576(_get_active_fixturedef)
  212/176    0.001    0.000    7.354    0.042 fixtures.py:604(_compute_fixture_value)


v3.5.0

         115113949 function calls (114933238 primitive calls) in 100.275 seconds
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      ...
     1230    0.054    0.000   64.121    0.052 model.py:498(run)
     1444    0.032    0.000   59.289    0.041 model.py:599(matcher_event)
     2243    0.132    0.000   58.795    0.026 matcher.pyx:211(__call__)
     2243    0.211    0.000   58.654    0.026 matcher.pyx:342(find_matches)
    18145    4.470    0.000   58.349    0.003 matcher.pyx:413(transition_states)
 22348050    5.919    0.000   53.880    0.000 matcher.pyx:525(update_predicate_cache)
 12212751   16.445    0.000   47.948    0.000 matcher.pyx:912(__call__)
       45    0.000    0.000   35.731    0.794 runner.py:153(pytest_runtest_setup)

[adrianeboyd]

Do you mean PhraseMatcher seems unaffected? Because it would be unexpected if Matcher by itself is affected but the exact same Matcher within EntityRuler is not affected.

I did a fair amount of profiling related to the fuzzy matcher changes to try to make sure that we weren't introducing a performance regression, but it's possible I missed something or there's a particular case my tests didn't cover. My first guess is that it is related to caching and the changes introduced in _get_extra_predicates_dict, but I don't know for sure.

I wouldn't be surprised by a slight performance hit (2-3%) but nothing like this. Can you provide more details about what you're doing here?

[kwhumphreys]

Thanks @adrianeboyd. I'm trying to narrow a large rule set down to a test case if possible. It is the Matcher while EntityRuler seems good.
My current hunch is that it's from using extension attributes in the Matcher rules. Both adding and matching patterns are significantly slower than v3.4 (even with validate=False)
Any tips for profiling the Cython code?

[adrianeboyd]

I just double-checked a case with just an extension attribute and didn't see any difference, so maybe it's a more complicated interaction or pattern type?

[kwhumphreys]

I found the cause: set operators in extension attributes. Not yet sure of the fix.

rules with {'_': {'NP': {'IN': ['B', 'I']}}

         11747941 function calls (11633336 primitive calls) in 11.994 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      ...
        1    0.000    0.000    4.782    4.782 model.py:452(__init__)
        1    0.008    0.008    4.713    4.713 model.py:478(_load_models)
     2261    0.013    0.000    4.675    0.002 matcher.pyx:81(add)
     2261    0.057    0.000    4.637    0.002 matcher.pyx:762(_preprocess_pattern)
    41055    4.182    0.000    4.478    0.000 matcher.pyx:1003(_get_extra_predicates)
      119    0.004    0.000    4.287    0.036 model.py:498(run)
       60    0.003    0.000    3.913    0.065 model.py:599(matcher_event)
      120    0.007    0.000    3.786    0.032 matcher.pyx:211(__call__)
      120    0.011    0.000    3.779    0.031 matcher.pyx:342(find_matches)
     1206    0.259    0.000    3.762    0.003 matcher.pyx:413(transition_states)
  1548359    0.371    0.000    3.503    0.000 matcher.pyx:525(update_predicate_cache)
   838414    1.080    0.000    3.132    0.000 matcher.pyx:912(__call__)

rules with only {'_': {'NP': 'B'}}

         5008829 function calls (4894224 primitive calls) in 4.482 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      ...
        1    0.000    0.000    0.703    0.703 model.py:452(__init__)
      119    0.004    0.000    0.694    0.006 model.py:498(run)
        1    0.000    0.000    0.662    0.662 date.py:1(<module>)
     2286    0.029    0.000    0.631    0.000 regex.py:453(_compile)
        1    0.007    0.007    0.631    0.631 model.py:478(_load_models)

[kwhumphreys]

I think the key calculated here https://github.com/explosion/spaCy/blob/master/spacy/matcher/matcher.pyx#L1095 is now a different format from the keys calculated inside the predicates, so extension predicates are never found in seen_predicates.
I'm testing a fix to standardize the keys throughout...

[kwhumphreys]

proposed fix https://github.com/explosion/spaCy/compare/master...kwhumphreys:spaCy:matcher_fix?expand=1

[adrianeboyd]

Ah, that is exactly the kind of bug that would cause this behavior, thanks for tracking that down! Would you like to submit a PR?

Does it completely resolve the speed differences or is anything like adding patterns still affected?

[kwhumphreys]

now just a small impact from adding extension predicates. I'll put together a PR with some tests.

with {'_': {'NP': 'B'}} only

         4920456 function calls (4806909 primitive calls) in 4.301 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.706    0.706 model.py:452(__init__)
      119    0.004    0.000    0.666    0.006 model.py:498(run)
        1    0.007    0.007    0.645    0.645 model.py:478(_load_models)
     2261    0.012    0.000    0.608    0.000 matcher.pyx:81(add)

with {'_': {'NP': {'IN': ['B', 'I']}}}

         5872625 function calls (5759074 primitive calls) in 4.549 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      119    0.004    0.000    0.784    0.007 model.py:498(run)
        1    0.000    0.000    0.773    0.773 model.py:452(__init__)
        1    0.007    0.007    0.708    0.708 model.py:478(_load_models)
     2261    0.013    0.000    0.667    0.000 matcher.pyx:81(add)

[kwhumphreys]

cleaner fix now at #12272
any recommendations for including performance tests in unit tests?