Big performance hit when upgrading from 1.4.2 to 1.5.0

[sdepablos]

A few days ago we upgraded a few packages in our SF2 project and realized that our times when from 60 ms to almost 100 ms (confirmed both by newrelic and logstash), so we started to debug which one of the upgrades was to blame.

Finally we've found the cause on the metadata package upgrade from 1.4.2 to 1.5.0. Here's a screenshot of 500 requests with version 1.4.2 vs 500 with version 1.5.0

Taking a look to the differences between 1.4.2 vs 1.5.0 the only possible cause may be the pull request #36 (medatada caching improvement). I see on the issue that a benchmark was done, but I don't know which kind of benchmark and if it was done with "real code". Could it be that the change from one call to instanceof to five (two directly on getMetadataForClass and three more calling filterNullMetadata) is causing this performance hit? It seems that as instanceof uses strings comparisons, the class name length has a big impact, but this is just a guess.

[schmittjoh]

Could you verify this by reverting said commit and measuring the impact?

[acasademont]

Checking the diff between 1.4.2 and 1.5.0 there's only this change really. The other one is just adding a method for adding drivers, not an issu at all.

From what I can see, there is now one extra function call filterNullMetadata where previously there was none. I really don't know how many times this funcion must be called to cause that big time bump.

Maybe @adrienbrault can give us some clues

[sdepablos]

Commit from full request #36 removed and we're back to normal performance. We have not tried changing any of the code, but our intuition says is has to be something related with the extra calls to instanceof. @adrienbrault, do you remember how the performance test was done?

[adrienbrault]

Yep, serializing an object graph with a lot of objects without any metadata was super slow.

Maybe you could use xhprof to find the bottleneck (likely io related, instanceof is supposed to be super fast).

[sdepablos]

@adrienbrault did you take a look to issue #45? It looks like a good explanation for the performance hit.

[goetas]

fixed in #46