fluent / fluent-logger-node

A structured logger for Fluentd (Node.js)
Apache License 2.0
259 stars 83 forks source link

Performance improvements #131

Closed zbjornson closed 5 years ago

zbjornson commented 5 years ago

Hello!

These small perf changes speed up this library a tremendous amount. I kept the commits separate so that they're easier to review. The current behavior when calling emit() in a loop is worse-than-linear because Buffer.concat() in a loop moves a tremendous amount of memory. The first commit (perf: avoid repeated calls to Buffer.concat) fixes that and is a huge improvement on its own. The rest are small but noticeable improvements.

image

Note both axes are log10. At 10k iterations, it's 80x faster.

I used the code below to benchmark, sending to a @null fluentd instance.

const fluent = require('.');

fluent.configure('test.null', {
  eventMode: 'CompressedPackedForward' // default in next major release
});
fluent.on('error', console.log);

const content = Object.assign({}, require('./package.json'));

console.time('emit');
for (let i = 0; i < 100; i++) { // or 1000, or 10000, etc
  fluent.emit(content);
}
console.timeEnd('emit');

Separately, it looks like you have more nextTicks() than you need. I didn't want to touch those in case they were necessary for some reason.

okkez commented 5 years ago

Wow, thanks! I will check this PR tomorrow.

BTW, could you check DCO results?

zbjornson commented 5 years ago

Fixed :)

zbjornson commented 5 years ago

it looks like you have more nextTicks() than you need. I didn't want to touch those in case they were necessary for some reason.

I just added a commit that simplifies some of the async handling. I've traced all these code paths (explained in the commit message) and I think this change is safe. However, you're certainly more familiar with this code than I am.

It's unfortunate to always schedule a nextTick when emit() is called because that puts unnecessary pressure on the GC. I'd instead propose doing the equivalent of the below. (This change is simple but isn't the perfect place for that check to be.)

--- a/lib/sender.js
+++ b/lib/sender.js
@@ -110,9 +110,11 @@ class FluentSender {
     }

     this._push(tag, timestamp, data, callback);
-    this._connect(() => {
-      this._flushSendQueue();
-    });
+    if (!this._flushingSendQueue) {
+      this._connect(() => {
+        this._flushSendQueue();
+      });
+    }
   }

   end(label, data, callback) {
zbjornson commented 5 years ago

Thanks for reviewing.

Fixed the string syntax.

I usually use the Chrome DevTools profiler with node --inspect (https://nodejs.org/en/docs/guides/debugging-getting-started/, https://flaviocopes.com/node-debug-devtools/).

zbjornson commented 5 years ago

@okkez do you want anything else done on this before merging?

okkez commented 5 years ago

I'm OK, but I don't have enough time to release the new version for these days :sob: I will work for this ASAP, please wait.