Logger uses lots of CPU time as entries are added

[arbokrad]

Package Edition of Nebula Logger

Unlocked Package

Package Version of Nebula Logger

4.6.11

New Bug Summary

The logger appears to use a lot of CPU time as the number of times the logger is invoked grows:

Consider the following test class and measured CPU usage over multiple runs:

@IsTest(IsParallel=true)
private class TEST_Example {
	/**
	 * Sample CPU usages:
	 * 	1 - 885
	 * 	2 - 851
	 * 	3 - 798
	 * 	4 - 976
	 * 	5 - 1180
	 */
	@IsTest
	static void nebula_100_logs() {
		for( Integer i = 0; i < 100; i++ ) {
			Logger.debug('a' );
		}
	}

	/**
	 * Sample CPU usages:
	 * 	1 - 2891
	 * 	2 - 2937
	 * 	3 - 3116
	 * 	4 - 3071
	 * 	5 - 3234
	 */
	@IsTest
	static void nebula_250_logs() {
		for( Integer i = 0; i < 250; i++ ) {
			Logger.debug('a' );
		}
	}

	/**
	 * Sample CPU usages:
	 * 	1 - 7800
	 * 	2 - 7588
	 * 	3 - 9054
	 * 	4 - 8824
	 * 	5 - 8979
	 */
	@IsTest
	static void nebula_500_logs() {
		for( Integer i = 0; i < 500; i++ ) {
			Logger.debug('a' );
		}
	}

	/**
	 * Sample CPU usages (included because it appears to be approximately the boundary):
	 * 	1 - 14881
	 * 	2 - 14334
	 * 	3 - Exceeded CPU usage
	 * 	4 - Exceeded CPU usage
	 * 	5 - 14406
	 */
	@IsTest
	static void nebula_725_logs() {
		for( Integer i = 0; i < 725; i++ ) {
			Logger.debug('a' );
		}
	}

	/**
	 * Sample CPU usages:
	 * 	1 - Exceeded CPU usage
	 * 	2 - Exceeded CPU usage
	 * 	3 - Exceeded CPU usage
	 * 	4 - Exceeded CPU usage
	 * 	5 - Exceeded CPU usage
	 */
	@IsTest
	static void nebula_1000_logs() {
		for( Integer i = 0; i < 1000; i++ ) {
			Logger.debug('a' );
		}
	}
}

Visualized:

CPU usage appears to rise smoothly until it hits the hard cap of 15000 and starts failing.

[jongpie]

Thanks again @arbokrad for writing this up! Given that you're on an older version of the tool (v4.6.11 vs the latest version of v4.7.8), there are already some optimizations in place in newer releases.... but even the current version still fails to generate 1,000 log entries, so there's definitely more optimizations to be done. I'll include some of your tests when I work on some other optimizations in #311.

[jamessimone]

See my comments in #351 - we're working on making extensive improvements to Logger's CPU usage. There's definitely still optimizations to be had, but we're working hard to identify, isolate, and minimize the amount of time Nebula takes to create singular log entries.

[arbokrad]

I confirmed today that this (and #351) are present in the the most recent release of nebula (4.13.4)

[jongpie]

@arbokrad and @jamessimone I wanted to get your thoughts on this issue - @jamessimone released v4.13.5 a few days ago, which included several performance improvements for some of the most problematic/slowest parts of the logging code. Do y'all think that release v4.13.5 addresses this issue & and we can close it? Or do you think there's still more to be done before this issue should be closed?

[arbokrad]

I ran v4.13.5 in a scratch org the other day and confirmed that CPU usage is greatly reduced compared to previous versions. The example test class from the initial post passed successfully numerous times, so I kept bumping it until I could hit the new ceiling which appears to be somewhere between 1150-1200 calls to debug(). As @jamessimone noted in the release notes, the new LoggerParameters for heap size logging made a huge difference.

Since benchmark tests have already been added, maybe the right thing here is documenting a rough upper bound of logs per transaction and maybe even suggested/best practices for not going overboard on logging calls?

There's always going to be a ceiling, knowing that ceiling and ways to work with it are really helpful.

[jongpie]

@arbokrad I agree, there will always be a ceiling, so I love your idea of documenting the upper bound + best practices. In addition to the super-helpful new heap size parameter record that @jamessimone added, there are a couple of other configuration options that can also be disabled to help increase the ceiling (by reducing queries, CPU time, heap size, etc.) - so it's probably worth documenting...

• The upper bound out-of-the-box, based on default LoggerParameter__mdt records & LoggerSettings__c field values
• Some guidelines on which LoggerParameter__mdt records to consider disabling to help with overall performance
• Some guidelines on which LoggerSettings__c fields to consider disabling to help with overall performance

I'm going to keep this issue open until I've found a spot to document this info. Thanks for your feedback, and your help testing out v4.13.5 in a scratch org!