Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logger uses lots of CPU time as entries are added #350

Open
arbokrad opened this issue Aug 10, 2022 · 6 comments
Open

Logger uses lots of CPU time as entries are added #350

arbokrad opened this issue Aug 10, 2022 · 6 comments
Assignees
Labels
documentation Layer: Logger Engine Items related to the core logging engine optimization Type: Bug Something isn't working

Comments

@arbokrad
Copy link

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:
image

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

@arbokrad arbokrad added the Type: Bug Something isn't working label Aug 10, 2022
@jongpie
Copy link
Owner

jongpie commented Aug 11, 2022

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
Copy link
Collaborator

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
Copy link
Author

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

@jongpie
Copy link
Owner

jongpie commented Apr 3, 2024

@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
Copy link
Author

arbokrad commented Apr 3, 2024

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
Copy link
Owner

jongpie commented Apr 4, 2024

@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!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
documentation Layer: Logger Engine Items related to the core logging engine optimization Type: Bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants