Writing to Log Blocks Other Operations

[brianlong]

Problem

Writing to the log blocks other validator operations.

In Discord, I asked "Q: Does writing to the log file block any other threads/procedures within the validator?" and Leo replied "Logging does block. interesting. it's a synchronous write to a fd."

When the log level is low (info or debug), the amount of data written to the logs might interfere with block production on a busy validator.

Proposed Solution

Move the logger to an asynchronous thread.

If that is not possible, review the amount of data written to the logs and the log level for each. A busy validator should be able to run a log level of 'error' or 'warn' without a performance hit.

[mvines]

There's a convenient central location where the dispatch to another dedicated logging thread could be plugged in:

solana/logger/src/lib.rs

Lines 18 to 20 in 69d90b5

	fn log(&self, record: &log::Record) {
	LOGGER.read().unwrap().log(record);
	}

This would incur another memory allocation for each log message, and might skew the logging timestamp (nbd).

Seems like we could enable "async logging" initially as a solana-validator command-line argument, to allow people to experiment with it

[mvines]

It would be worthwhile to invest some time measuring where the time goes while logging. We burrow through at least 4 software layers within the validator itself from the info!() macro to when the contents finally hit the log file.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.

[stale]

This stale issue has been automatically closed. Thank you for your contributions.

[github-actions]

This issue has been automatically locked since there has not been any activity in past 7 days after it was closed. Please open a new issue for related bugs.