Performance degradation

[orensolo]

Steps to reproduce

Run performance tests, when the performance criteria are requests per second and latency.

Current Behavior

I am using "@loopback/context": "^1.25.0", and I noticed a degradation in performance.
After analyzing the results using a profiler, I found out that interceptors loading is one of the main causes of this degradation.

Specifically, the following line (in getGlobalInterceptorBindingKeys function of InterceptedInvocationContext class) is causing a performance issue :

  const bindings: Readonly<Binding<Interceptor>>[] = this.find(
      binding =>
        filterByTag(ContextTags.GLOBAL_INTERCEPTOR)(binding) &&
        // Only include interceptors that match the source type of the invocation
        this.applicableTo(binding),
    );

After forcing the controllerRoute to use invokeTargetMethodWithInjection instead of invokeMethodWithInterceptors, the performance (Requests per seconds) improved by 25%.
Note also that I don't use interceptors in my application.

Expected Behavior

No degradation in performance after upgrading loopback

[raymondfeng]

Oren, great catch. We’ll come up a fix soon.

[raymondfeng]

It seems that finding matching bindings by tag can be expensive as we iterate through all bindings in the context hierarchy. I'll try to create an index for bindings by tag to see if it helps.

[raymondfeng]

1. With fix

autocannon -c 10 -d 40 -p 10 localhost:3000/greet/world
Running 40s test @ http://localhost:3000/greet/world
10 connections with 10 pipelining factor

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬───────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max       │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼───────────┤
│ Latency │ 0 ms │ 0 ms │ 16 ms │ 16 ms │ 1.59 ms │ 4.87 ms │ 120.15 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴───────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬─────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg     │ Stdev  │ Min    │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼────────┼────────┤
│ Req/Sec   │ 2391   │ 2391   │ 6231    │ 6291    │ 6034.33 │ 666.78 │ 2391   │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼────────┼────────┤
│ Bytes/Sec │ 741 kB │ 741 kB │ 1.93 MB │ 1.95 MB │ 1.87 MB │ 207 kB │ 741 kB │
└───────────┴────────┴────────┴─────────┴─────────┴─────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

241k requests in 40.04s, 74.8 MB read

2. Without fix

$ autocannon -c 10 -d 40 -p 10 localhost:3000/greet/world
Running 40s test @ http://localhost:3000/greet/world
10 connections with 10 pipelining factor

┌─────────┬──────┬──────┬───────┬───────┬─────────┬─────────┬───────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%   │ Avg     │ Stdev   │ Max       │
├─────────┼──────┼──────┼───────┼───────┼─────────┼─────────┼───────────┤
│ Latency │ 0 ms │ 0 ms │ 23 ms │ 25 ms │ 2.32 ms │ 7.09 ms │ 121.76 ms │
└─────────┴──────┴──────┴───────┴───────┴─────────┴─────────┴───────────┘
┌───────────┬────────┬────────┬─────────┬─────────┬─────────┬────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg     │ Stdev  │ Min    │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼────────┼────────┤
│ Req/Sec   │ 1981   │ 1981   │ 4339    │ 4411    │ 4183.28 │ 437.55 │ 1981   │
├───────────┼────────┼────────┼─────────┼─────────┼─────────┼────────┼────────┤
│ Bytes/Sec │ 614 kB │ 614 kB │ 1.34 MB │ 1.37 MB │ 1.3 MB  │ 136 kB │ 614 kB │
└───────────┴────────┴────────┴─────────┴─────────┴─────────┴────────┴────────┘

Req/Bytes counts sampled once per second.

167k requests in 40.04s, 51.9 MB read

[raymondfeng]

@orensolo Do you want to try out #4377?

[orensolo]

Hi,

There is ~15% improvement after the fix. Thanks for the quick fix.

Oren

[orensolo]

Hi,
I have 2 additional questions :

1. Will the fix be relevant also for the case where interceptors are used?
2. When will the fix be released?

Thanks,
Oren

[raymondfeng]

@orensolo

1. The fix helps regardless of the presence of interceptors
2. I would like to have feat: improve context.find/findByTag() and interceptor perf #4377 approved and landed this week ASAP.

@bajtos Please have the final review on #4377.

[raymondfeng]

@orensolo It's released in @loopback/context@2.0.0. Please install latest version of CLI (npm i -g @loopback/cli) and use lb4 update` to update dependencies of your app.

[orensolo]

Thanks