Improve performance when logging is disabled

[tomer-w]

Improve the logging performance by not running expensive JSON.stringify when the logging is disabled.
The old pattern was something like that:

logger.debug(`sendZclFrameToAll ${JSON.stringify(payload)}`, NS);

This was calling the stringify function even if eventually the logger was disabled.
The new pattern is:

logger.debug(() => `sendZclFrameToAll ${JSON.stringify(payload)}`, NS);

Which will not call the lambda if the tracing is disabled.
The logger function will accept both string messages as they used to be and the new lambda format, so there is no need to change all logging calls, only the ones that are deemed expensive.

I am also adding Logger.isEnabled function which can be used by the caller to decide if there is a need to prepare complex log message.

I also changed all the expensive calls to the logger in the zigbee-herdsman to use the new functionality:
Koenkk/zigbee-herdsman#1178

[Nerivec]

Should provide a decent performance boost:

┌─────────┬────────────────────────────────┬─────────────┬────────────────────┬──────────┬──────────┐
│ (index) │ Task Name                      │ ops/sec     │ Average Time (ns)  │ Margin   │ Samples  │
├─────────┼────────────────────────────────┼─────────────┼────────────────────┼──────────┼──────────┤
│ 0       │ 'plain log'                    │ '275,104'   │ 3634.9870738169716 │ '±1.29%' │ 1375521  │
│ 1       │ 'plain log new'                │ '273,253'   │ 3659.602662925059  │ '±1.41%' │ 1366291  │
│ 2       │ 'stringify log'                │ '226,876'   │ 4407.674646871684  │ '±0.79%' │ 1134385  │
│ 3       │ 'stringify log new'            │ '226,783'   │ 4409.496455342999  │ '±0.82%' │ 1133917  │
│ 4       │ 'plain log - disabled'         │ '7,542,096' │ 132.5891300310219  │ '±0.15%' │ 37710482 │
│ 5       │ 'plain log new - disabled'     │ '7,154,958' │ 139.7632147654249  │ '±0.47%' │ 35774793 │
│ 6       │ 'stringify log - disabled'     │ '1,706,746' │ 585.9101057924765  │ '±0.15%' │ 8533733  │
│ 7       │ 'stringify log new - disabled' │ '5,587,460' │ 178.9721728850612  │ '±1.57%' │ 27937304 │
└─────────┴────────────────────────────────┴─────────────┴────────────────────┴──────────┴──────────┘

code

// https://github.com/tinylibs/tinybench
import {Bench, hrtimeNow} from 'tinybench';
import logger from './logger.js';
import loggernew from './loggernew.js';

const bench = new Bench({time: 5000, warmupTime: 1000, now: hrtimeNow});

logger.init(); // set to 'info' with silenced Console transport
loggernew.init(); // set to 'info' with silenced Console transport

bench.add('plain log', function() {
    logger.error('test');
});

bench.add('plain log new', function() {
    loggernew.error('test');
});

bench.add('stringify log', function() {
    logger.error(`test ${JSON.stringify({ a: 1, b: 2 })}`);
});

bench.add('stringify log new', function() {
    loggernew.error(() => `test ${JSON.stringify({ a: 1, b: 2 })}`);
});

bench.add('plain log - disabled', function() {
    logger.debug('test');
});

bench.add('plain log new - disabled', function() {
    loggernew.debug('test');
});

bench.add('stringify log - disabled', function() {
    logger.debug(`test ${JSON.stringify({ a: 1, b: 2 })}`);
});

bench.add('stringify log new - disabled', function() {
    loggernew.debug(() => `test ${JSON.stringify({ a: 1, b: 2 })}`);
});

await bench.warmup(); // make results more reliable, ref: https://github.com/tinylibs/tinybench/pull/50
await bench.run();

console.table(bench.table());

await logger.end();
await loggernew.end();

PS: Should remove package json edits, same in ZH PR.

[tomer-w]

Thanks @Nerivec !! Great feedback. Specially loved your perf test. I created one as well but it was so ugly I didn't thought about quoting it here. This is my first ts/js coding so I have lot to learn from your comments. I will work on fixes tomorrow. Thanks again for spending time on this.

[tomer-w]

I submitted all changes. Thanks again for the CR!

[Nerivec]

z2m uses stringify from a package instead of JSON.stringify in several places. Might want to go through these too.

[Koenkk]

Instead of having to do this can't we modify stub/logger.js to evaluate the lambda?

[Nerivec]

See https://github.com/Koenkk/zigbee2mqtt/pull/23893/files#r1750650326 I was thinking, ignoring the logging completely and spying on eventBus instead? Cleaner to test the code than the logs.

[Koenkk]

For this specific test case it's possible, but there are also some test cases on which this cannot be used. So having the stub/logger.js modified would be nice anyway.

[tomer-w]

I did both:

1. Changed the code to spy on eventBus as it really seems more robust.
2. Changed the stub logger implementation so it will be easy to spy on the actual logger message. I added an example of this in the last line of the 'Handle mqtt message' test case so you can see that it is simple to do.

[tomer-w]

z2m uses stringify from a package instead of JSON.stringify in several places. Might want to go through these too.

I saw that usage only as part of MQTT.publish so it can not be optimized out.

[tomer-w]

I think I resolved all your comments. Let me know if anything else is needed. Thanks guys!!

[Nerivec]

Quick regex search (might be others):

zigbee2mqtt/lib/extension/legacy/bridgeLegacy.ts

Line 77 in 403d3c0

logger.info(`Changed device specific options of '${json.friendly_name}' (${stringify(json.options)})`);

zigbee2mqtt/lib/zigbee.ts

Lines 114 to 119 in 403d3c0

	logger.debug(
	`Received Zigbee message from '${device.name}', type '${data.type}', ` +
	`cluster '${data.cluster}', data '${stringify(data.data)}' from endpoint ${data.endpoint.ID}` +
	(data.hasOwnProperty('groupID') ? ` with groupID ${data.groupID}` : ``) +
	(device.zh.type === 'Coordinator' ? `, ignoring since it is from coordinator` : ``),
	);

zigbee2mqtt/lib/extension/receive.ts

Lines 111 to 114 in 403d3c0

	logger.debug(
	`No converter available for '${data.device.definition.model}' with ` +
	`cluster '${data.cluster}' and type '${data.type}' and data '${stringify(data.data)}'`,
	);

Also these, though minimal impact since only called once on start (but removes potential requests to the adapter, which is always good):

zigbee2mqtt/lib/zigbee.ts

Lines 58 to 59 in 403d3c0

	const herdsmanSettingsLog = JSON.stringify(herdsmanSettings).replaceAll(JSON.stringify(herdsmanSettings.network.networkKey), '"HIDDEN"');
	logger.debug(`Using zigbee-herdsman with settings: '${stringify(herdsmanSettingsLog)}'`);

zigbee2mqtt/lib/zigbee.ts

Lines 125 to 126 in 403d3c0

	logger.info(`Coordinator firmware version: '${stringify(await this.getCoordinatorVersion())}'`);
	logger.debug(`Zigbee network parameters: ${stringify(await this.herdsman.getNetworkParameters())}`);

[tomer-w]

I found couple more usages I could swap. I think the commit is ready to merge. Thanks for your support.

[tomer-w]

OK, now it is really ready. Sorry for the mess.

[Koenkk]

Thanks @tomer-w !

[tomer-w]

Thank you!! Amazing project which is centerpiece for home automation.