Benchmarking the logger

[tvvignesh]

Issue Description
Hi. I tried the decorator (Class Logger to be exact) but the thing we noticed was that our benchmarks deteriorated. http_req_duration went from 6ms to 35.15ms (a huge jump).

We are interested in intercepting only errors. So, we have a custom logger like this:

const logger = {
  info: function () {
    return;
  },
  verbose: function () {
    return;
  },
  error: console.error
};

import { Decorator } from 'logger-decorator';
export const log = new Decorator({
  name: 'myapp',
  logger: logger,
  timestamp: true
});

Where we log only errors. No other custom code has been used and we just decorate the classes with @log() but this still leads to a huge impact on the benchmark. Any ideas on how we can solve this? Thanks 🙂

Please follow the general troubleshooting steps first:

• I've searched on the issue tracker before creating one.
• I'm running the latest package version.
• I'm ready to provide help with a fix if needed.

What do you expect to happen?

There is minimal impact to the benchmarks after adding the decorators.

What is actually happening?

Adding the decorator leads to a 29ms jump in the benchmarks.

Output here

Before

✓ no_errors
     ✓ expected_result

     checks.........................: 100.00% ✓ 92154      ✗ 0    
     data_received..................: 16 MB   266 kB/s
     data_sent......................: 22 MB   361 kB/s
     http_req_blocked...............: avg=2.4µs   min=1.19µs  med=2.06µs  max=236.84µs p(90)=3.33µs  p(95)=3.93µs 
     http_req_connecting............: avg=15ns    min=0s      med=0s      max=177.64µs p(90)=0s      p(95)=0s     
   ✓ http_req_duration..............: avg=6.35ms  min=1.22ms  med=4.55ms  max=212.13ms p(90)=9.54ms  p(95)=11.09ms
       { expected_response:true }...: avg=6.35ms  min=1.22ms  med=4.55ms  max=212.13ms p(90)=9.54ms  p(95)=11.09ms
     http_req_failed................: 0.00%   ✓ 0          ✗ 46077
     http_req_receiving.............: avg=46.83µs min=18.26µs med=44.07µs max=8.95ms   p(90)=58.28µs p(95)=64.29µs
     http_req_sending...............: avg=20.62µs min=8.65µs  med=19.18µs max=2.56ms   p(90)=29.51µs p(95)=32.91µs
     http_req_tls_handshaking.......: avg=0s      min=0s      med=0s      max=0s       p(90)=0s      p(95)=0s     
     http_req_waiting...............: avg=6.28ms  min=1.12ms  med=4.48ms  max=212.07ms p(90)=9.46ms  p(95)=11ms   
     http_reqs......................: 46077   767.837431/s
     iteration_duration.............: avg=6.5ms   min=1.41ms  med=4.69ms  max=212.27ms p(90)=9.7ms   p(95)=11.25ms
     iterations.....................: 46077   767.837431/s
     vus............................: 5       min=5        max=5  
     vus_max........................: 5       min=5        max=5

After

     ✓ no_errors
     ✓ expected_result

     checks.........................: 100.00% ✓ 17010      ✗ 0   
     data_received..................: 3.0 MB  49 kB/s
     data_sent......................: 4.0 MB  67 kB/s
     http_req_blocked...............: avg=2.54µs  min=1.19µs med=2.14µs  max=200.64µs p(90)=3.59µs  p(95)=4.16µs  
     http_req_connecting............: avg=83ns    min=0s     med=0s      max=158.51µs p(90)=0s      p(95)=0s      
   ✗ http_req_duration..............: avg=35.15ms min=6.56ms med=19.37ms max=294.24ms p(90)=64.41ms p(95)=111.89ms
       { expected_response:true }...: avg=35.15ms min=6.56ms med=19.37ms max=294.24ms p(90)=64.41ms p(95)=111.89ms
     http_req_failed................: 0.00%   ✓ 0          ✗ 8505
     http_req_receiving.............: avg=46.58µs min=18.3µs med=44.49µs max=265.25µs p(90)=63.11µs p(95)=70.55µs 
     http_req_sending...............: avg=20.69µs min=8.97µs med=19.59µs max=124.37µs p(90)=29.77µs p(95)=33.1µs  
     http_req_tls_handshaking.......: avg=0s      min=0s     med=0s      max=0s       p(90)=0s      p(95)=0s      
     http_req_waiting...............: avg=35.08ms min=6.48ms med=19.32ms max=294.15ms p(90)=64.33ms p(95)=111.81ms
     http_reqs......................: 8505    141.472685/s
     iteration_duration.............: avg=35.3ms  min=6.75ms med=19.52ms max=294.42ms p(90)=64.58ms p(95)=112.07ms
     iterations.....................: 8505    141.472685/s
     vus............................: 5       min=5        max=5 
     vus_max........................: 5       min=5        max=5 

Environment:

• Version: 1.4.1
• Node.js version: v12.18.2
• Operating System: ubuntu-1604:202104-01

[pustovitDmytro]

Hi, I've made some observations from my side. Most likely data sanitizers bring the greatest impact on performance. logger-decorator scans all incoming and outgoing data for sensitive patterns like /password/i. If you don't need this check or have an efficient algorithm of data sanitizing for your case, you can use custom paramsSanitizer and resultSanitizer.
The simplest example is:

import { inspect } from 'util';

const decorator = new Decorator({
    logger,
    timestamp : true,

    resultSanitizer : inspect,
    paramsSanitizer : inspect
});

It should fix most performance problems with huge data processing. Unfortunately, if you need to analyze complex objects, performance losses are inevitable.

However, your case of logging only errors is quite interesting for me, so I've created another issue #46 to cover it.

Please notify here if custom sanitizers work for you, and subscribe linked issue if you're interested in the logging only errors feature.

[tvvignesh]

Thanks for your reply. Will watch out for it 🙂