Avoid to log if the log is not set #776

allevo · 2018-02-11T23:19:55Z

loggerUtils.onResponseCallback logs only if there's a logger

Bench:

this branch:

[1] Running 5s test @ http://localhost:3000/
[1] 100 connections with 10 pipelining factor
[1] 
[0] server listening on 3000
[1] Stat         Avg     Stdev  Max     
[1] Latency (ms) 8.3     27.44  511.66  
[1] Req/Sec      11710   2804.9 13896   
[1] Bytes/Sec    1.75 MB 411 kB 2.07 MB 
[1] 
[1] 59k requests in 5s, 8.72 MB read
[1] 112 errors (0 timeouts)

master:

[1] Running 5s test @ http://localhost:3000/
[1] 100 connections with 10 pipelining factor
[1] 
[0] server listening on 3000
[1] Stat         Avg     Stdev   Max     
[1] Latency (ms) 8.78    29.27   340.12  
[1] Req/Sec      11079.6 3750.94 14926   
[1] Bytes/Sec    1.64 MB 535 kB  2.22 MB 
[1] 
[1] 55k requests in 5s, 8.25 MB read
[1] 130 errors (0 timeouts)

Can someone else confirm this improvement?

Checklist

run npm run test and npm run benchmark
tests and/or benchmarks are included
documentation is changed or added
commit message and code follows Code of conduct

nwoltman · 2018-02-11T23:46:13Z

fastify.js

@@ -26,6 +26,8 @@ const runHooks = require('./lib/hookRunner')

 const DEFAULT_JSON_BODY_LIMIT = 1024 * 1024 // 1 MiB

+function noop (anError, res) { }


I don't think there's any reason for a no-op to have parameters.

delvedor

Should we add the isAbstract check also here?

fastify/fastify.js

Line 202 in 81b6e01

res._startTime = now()

allevo · 2018-02-13T19:31:42Z

@delvedor yeah, _startTime should be considered as a private variable.

delvedor · 2018-02-13T20:41:05Z

fastify.js

@@ -199,7 +203,9 @@ function build (options) {

    req.log.info({ req }, 'incoming request')

-    res._startTime = now()
+    if (!isAbstract) {


Please use isAbstract === false it should be faster.
Can you also paste the new benchmarks?

allevo · 2018-02-13T20:53:15Z

New bench:
master

754k requests in 50s, 112 MB read

this branch

787k requests in 50s, 117 MB read

I don't know if this bench are accurate or not. Is there someone that is able to confirm it?

allevo · 2018-02-13T21:51:28Z

Last commit removes two listener: if the logger is abstract and the current context has no onResponse hooks, those lines can be skipped

fastify/fastify.js

Lines 203 to 204 in 8aa6b1d

    
           res.on('finish', onResFinished) 
        
           res.on('error', onResFinished)

delvedor · 2018-02-13T21:53:23Z

fastify.js

@@ -206,8 +206,10 @@ function build (options) {
    if (isAbstract === false) {
      res._startTime = now()
    }
-    res.on('finish', onResFinished)
-    res.on('error', onResFinished)
+    if (isAbstract === false || context.onResponse !== null) {


You can do the same for res._context = context :)

mcollina · 2018-02-13T21:55:31Z

fastify.js

-    res.on('error', onResFinished)
+    if (isAbstract === false) {
+      res._startTime = now()
+    }


This might create some deopts and prevent some inlining if logging is indeed enable (which will be the majority of cases). Can you test if the throughput drops with logging enabled?

I fear that might be the case, as I've seen this happening when properties are added within an if.

I haven't seen any drops.

NB: In the whole application isAbstract is a constant

mcollina

LGTM

mcollina · 2018-02-14T00:40:10Z

fastify.js

@@ -40,12 +42,14 @@ function build (options) {
  }

  var log
+  var isAbstract = false


can you make this variable name more precise? hasLogger is a good one for example.

delvedor · 2018-02-14T09:27:26Z

fastify.js

-    res.on('finish', onResFinished)
-    res.on('error', onResFinished)
+    if (isAbstract === false) {
+      res._startTime = now()


I think you can safely move res._startTime = now() inside the if below, since it is used only inside the onResponseCallback function.

again, I would not touch this. The chances to have a change of shape is very high.

Your suggestion is to remove all the if checks inside this function?

no. Adding a property within an if is a clear strategy to cause deopts.

mcollina · 2018-02-26T11:47:45Z

@allevo any update on this?

allevo · 2018-02-26T23:14:48Z

Tomorrow I'll update this PR Il lun 26 feb 2018, 12:47 Matteo Collina <notifications@github.com> ha scritto:

…

@allevo <https://github.com/allevo> any update on this? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#776 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABAVrVXTmxeOnec9TfYBlOIUkN5eOaP-ks5tYpnlgaJpZM4SBjvX> .

allevo · 2018-02-27T18:48:41Z

rebased

mcollina · 2018-02-28T08:29:47Z

Can you please check if the improvement is still there?

mcollina · 2018-02-28T13:33:02Z

A quick explanation on the Date.now() problem:

allevo · 2018-02-28T13:48:13Z

@mcollina Removing the call to now, we should remove that 5.8% on the top. Am I right?

delvedor

LGTM

Introduced in #776 Fixes #826

github-actions · 2022-02-18T00:17:31Z

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

nwoltman reviewed Feb 11, 2018

View reviewed changes

delvedor reviewed Feb 13, 2018

View reviewed changes

delvedor added enhancement performances Everything related to performances labels Feb 13, 2018

delvedor reviewed Feb 13, 2018

View reviewed changes

allevo force-pushed the no-log-if-no-logger-is-set branch from 3662ea2 to d4c577b Compare February 13, 2018 20:44

delvedor reviewed Feb 13, 2018

View reviewed changes

mcollina reviewed Feb 13, 2018

View reviewed changes

mcollina approved these changes Feb 14, 2018

View reviewed changes

mcollina reviewed Feb 14, 2018

View reviewed changes

delvedor reviewed Feb 14, 2018

View reviewed changes

Avoid to log if the log is not set

9aa8789

allevo force-pushed the no-log-if-no-logger-is-set branch from aa99ca6 to 9aa8789 Compare February 27, 2018 18:48

delvedor approved these changes Feb 28, 2018

View reviewed changes

mcollina merged commit f545acc into fastify:master Feb 28, 2018

mcollina added a commit that referenced this pull request Mar 4, 2018

fix responseTime regression

1b9986e

Introduced in #776 Fixes #826

mcollina mentioned this pull request Mar 4, 2018

fix responseTime regression #827

Merged

3 tasks

mcollina added a commit that referenced this pull request Mar 4, 2018

fix responseTime regression (#827)

288903a

Introduced in #776 Fixes #826

github-actions bot locked as resolved and limited conversation to collaborators Feb 18, 2022

Eomm added the semver-minor Issue or PR that should land as semver minor label Apr 1, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Avoid to log if the log is not set #776

Avoid to log if the log is not set #776

allevo commented Feb 11, 2018

nwoltman Feb 11, 2018

jsumners Feb 12, 2018

allevo Feb 12, 2018

delvedor left a comment

allevo commented Feb 13, 2018

delvedor Feb 13, 2018

allevo commented Feb 13, 2018

allevo commented Feb 13, 2018 •

edited

delvedor Feb 13, 2018

allevo Feb 13, 2018

mcollina Feb 13, 2018

allevo Feb 13, 2018

allevo Feb 27, 2018

mcollina left a comment

mcollina Feb 14, 2018

allevo Feb 27, 2018

delvedor Feb 14, 2018

mcollina Feb 14, 2018

delvedor Feb 14, 2018

mcollina Feb 14, 2018

allevo Feb 27, 2018

mcollina commented Feb 26, 2018

allevo commented Feb 26, 2018 via email

allevo commented Feb 27, 2018

mcollina commented Feb 28, 2018 •

edited

mcollina commented Feb 28, 2018

allevo commented Feb 28, 2018

delvedor left a comment

github-actions bot commented Feb 18, 2022

		@@ -26,6 +26,8 @@ const runHooks = require('./lib/hookRunner')

		const DEFAULT_JSON_BODY_LIMIT = 1024 * 1024 // 1 MiB

		function noop (anError, res) { }

Avoid to log if the log is not set #776

Avoid to log if the log is not set #776

Conversation

allevo commented Feb 11, 2018

Checklist

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

delvedor left a comment

Choose a reason for hiding this comment

allevo commented Feb 13, 2018

Choose a reason for hiding this comment

allevo commented Feb 13, 2018

allevo commented Feb 13, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina commented Feb 26, 2018

allevo commented Feb 26, 2018 via email

allevo commented Feb 27, 2018

mcollina commented Feb 28, 2018 • edited

mcollina commented Feb 28, 2018

allevo commented Feb 28, 2018

delvedor left a comment

Choose a reason for hiding this comment

github-actions bot commented Feb 18, 2022

allevo commented Feb 13, 2018 •

edited

mcollina commented Feb 28, 2018 •

edited