No slowdown when logging through child loggers.

[mcollina]

@davidmarkclements and @danjenkins. Here you are.

Some notes (all bad):

1. creating a logger is going to be relatively slow (might still be faster than bunyan)
2. the child logger does not inherits anything really, if you change the parent you are going to have issues
3. you can pass a meta property to any pino instance, and all the properties in there will be added
4. creating a child of a child does not work, currently
5. the data is made immutable when you create the logger, prejsonified it and stored

Good news: there is no drawback.

Any ideas on how to solve point 1-5?

[danjenkins]

I'm fine with 2, 3, 4 and 5 so can we just say yay and woot? 💃

But in all seriousness... I didn't realise you could make a child of a child in bunyan... I wonder how many people do and I've never gone and changed the meta data stored against a child logger once it's been created, that's kinda against the point of the child logger... so I wonder if these are valid points in terms of whether they need to be solved...

[danjenkins]

oh and ❤️ for working on this when I know it's late in italy 😄

[mcollina]

So, how ofter do you create child loggers? It's probably possible to make creation of the logger a fast operation as well. Currently it's very very bad.

I'll give it another pass tomorrow

[danjenkins]

I generally create a child logger at the beginning of a transaction, be it an HTTP request coming into the server, or something similar

An example is a request comes in and I want X params from that transaction in all logs that are related to that transaction so I create a child logger and then that's it, I just use that child logger for the length of that transaction.

[mcollina]

@danjenkins so I need to make child log creation fast :D.

[danjenkins]

Yes! The other issues I personally don't see as issues, others may disagree. But yes, creation should be fast fast fast like the flash!

[mcollina]

So, it's faster now (50% faster), but it still 25% slower than not doing it in the first place.

benchPinoCreation*10000: 503ms
benchBunyanCreation*10000: 1558ms
benchBoleCreation*10000: 1854ms
benchPinoCreation*10000: 496ms
benchBunyanCreation*10000: 1489ms
benchBoleCreation*10000: 1881ms

This is due to the fact that the logging functions will not be optimized yet. If you keep the child around enough time, you will see no worries.

Anybody that will do a code review for me?

[davidmarkclements]

@mcollina yah I'll take a look but no capacity till maybe, Fri aft - I want to profile this all with 0x and take a stab as well

[mcollina]

Feature wise, after we land this I think pino is "done", and I will mark 1.0.0.

[davidmarkclements]

so question - why in the childCreation benchmarks are we doing a log ten times? Doesn't that skew the results? also - bole "child" isn't really a fair test is it?

[davidmarkclements]

not sure that "opts" is the right word? bunyan docs refers to them as "bound fields" so maybe "fields" would be a better description? or "bindings"?

[mcollina]

agreed for bindings.

[davidmarkclements]

yah so I'm not seeing any cost of child logging vs normal logging:

benchPinoObj_10000: 373.550ms
benchPinoChild_10000: 358.387ms
benchPinoObj_10000: 352.645ms
benchPinoChild_10000: 350.087ms

so that's awesome, goal achieved I feel

there is sometimes a 20ms diff when logging just strings:

benchPino_10000: 293.992ms
benchPinoChild_10000: 299.618ms
benchPino_10000: 268.867ms
benchPinoChild_10000: 287.241ms

(in this case benchPinoChild and benchPino are just logging the string: 'world')

[mcollina]

so question - why in the childCreation benchmarks are we doing a log ten times? Doesn't that skew the results?

All benchmarks are set up in the same way. We might even move all of that into a helper module, so we avoid that situation. Logging ten times is a fairly heavy use case for a logger: we are testing logging 10 times in the same tick.This is more for filling up the underlining buffer for the stream, rather than anything else.

also - bole "child" isn't really a fair test is it?

No it is not, but pino is faster anyway, so why not?

[mcollina]

there is sometimes a 20ms diff when logging just strings

It highly possible because we are logging more data, I don't think we can do much about it at this point. Maybe with 100k repetitions, but I think we are mostly there.

[mcollina]

I have updated for bindings. I think I am happy to call this done.
Child creation can still be better, but we are competing against ourselves at this point.

@davidmarkclements @danjenkins review this tomorrow and then I release :)

[davidmarkclements]

I'm happy 👍 lgtm as the cool kids say

[danjenkins]

this should be leverages shouldn't it?

[danjenkins]

Small nit on language but it's only the one so feel free to ignore me if you want to merge it :) I'm not even sure I'm right.

And @davidmarkclements , don't we all want to be cool kids? 😄

[danjenkins]

@mcollina you need to close this PR now?

[mcollina]

Yes you are right, not sure why Github didn't pick it up automagically.

Released in v1.0.0

[github-actions]

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.