Performance change of Protocols reflection in Elixir v1.11

Questions / Help
, ,
1

Hi everyone,

I worked on some issue on my project that was related to the performance slowdown brought by Protocol impl_for/1 active usage (on Elixir v.1.10.4).

I found out that on newer elixir versions (starting from v.1.11) this issue has gone.
According to my measurements the cost of impl_for call reduced from ~70ms on v1.10.4 to < 1ms on v1.11.

I tried to find some change logs that mention this improvement or at least some specific commit in v.1.10.4…v1.11 diff but did not succeed with it.

Does anyone knows what exactly could improve impl_for performance?

Thanks

2 Likes
2

@josevalim maybe you know?

3

I think having exact line we suspect is useful - https://github.com/kobil-systems/mongodb/blob/21037d700fc8e9675d99b1d3c6b58ade2f6b61bb/lib/bson/encoder.ex#L122

4

Other interesting detail is that impl_for on v.1.10.4 costs a lot when it returns false (no implementation found).
In case when it returns true performance is almost equal to the v1.11 impl_for version.

However in elixir v.1.11 impl_for works always fast regardless if implementation was found or not.

5

70ms for a single impl_for lookup? something else is amiss, how are you measuring this?

1 Like
6

deadtrickster provided the link above to point where exact impl_for happens. Hope it can give some context.

70ms for a single impl_for lookup?

And it was not the worst case. I tried more series (~2k calls with different datatypes) and some series showed 100ms+ average.
However as I mentioned above it works that slow only when the protocol implementation is not found.
When implementation present (for Map) it works pretty fast, in 90% of cases it takes less then 20 microseconds.

how are you measuring this?

Just with

    start = :erlang.system_time(:microsecond)
    check = Mongo.Encoder.impl_for(value)
    :erlang.system_time(:microsecond) - start
7

AFAIK we didn’t change anything around this so, if I had to guess, you are having an issue with protocol consolidation on previous versions. Perhaps the protocol was not consolidated for some reason?

1 Like
8

thanks, i took 70ms as milliseconds, microseconds commonly abbreviated us.

I’m guessing measuring wall time around a single statement is susceptible, to context switch or other cpu/system activity. Maybe someone can suggest a better way to benchmark this.

9

You can use benchfella or benchee for example if you need more “accurate” results.

10

You right!
I’ve checked it with Protocol.consolidated?/1 and it returned false on v1.10.4 version but true on v.1.11

But what is the reason of such behaviour?

I’ve set consolidate_protocols: true explicitly both for mongodb and the project where I use it as a dependency.

On both versions Elixir.Mongo.Encoder.beam was present into consolidated app directory (_build/**/lib/**/consolidated/), but Elixir.Mongo.Encoder.Map.beam presented in _build/**/lib/mongodb/ebin/ only on v1.11

11

I mean exactly ~70ms (~70000 microseconds).

12

Not relevant when difference is ~70 000 microseconds for a call on one version and ~20 microseconds on the other for the same code.