Reduce access log overhead when logging is disabled

[bdraco]

What do these changes do?

If the logger was disabled the log message would be formatted and thrown away. Avoid formatting the log message when logging is not enabled at info level.

In testing this represented up to 12% of the run time of serving a static file.

Are there changes in behavior for the user?

No

Related issue number

Checklist

• I think the code is well written
• Unit tests for the changes exist
• Documentation reflects the changes
• If you provide code modification, please add yourself to CONTRIBUTORS.txt
  • The format is <Name> <Surname>.
  • Please keep alphabetical order, the file is sorted by names.
• Add a new news fragment into the CHANGES folder
  • name it <issue_id>.<type> for example (588.bugfix)
  • if you don't have an issue_id change it to the pr id after creating the pr
  • ensure type is one of the following:
    • .feature: Signifying a new feature.
    • .bugfix: Signifying a bug fix.
    • .doc: Signifying a documentation improvement.
    • .removal: Signifying a deprecation or removal of public API.
    • .misc: A ticket has been closed, but it is not of interest to users.
  • Make sure to use full sentences with correct case and punctuation, for example: "Fix issue with non-ascii contents in doctest text files."

[codecov]

Codecov Report

Merging #7240 (7eaa6fb) into master (6da0469) will decrease coverage by 0.01%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master    #7240      +/-   ##
==========================================
- Coverage   97.31%   97.31%   -0.01%     
==========================================
  Files         107      107              
  Lines       31405    31414       +9     
  Branches     3926     3927       +1     
==========================================
+ Hits        30562    30569       +7     
- Misses        640      641       +1     
- Partials      203      204       +1     

Flag	Coverage Δ
CI-GHA	97.21% <100.00%> (-0.01%)	⬇️
OS-Linux	96.87% <100.00%> (-0.01%)	⬇️
OS-Windows	95.29% <100.00%> (-0.01%)	⬇️
OS-macOS	96.45% <100.00%> (-0.01%)	⬇️
Py-3.10.10	?
Py-3.10.11	96.97% <100.00%> (?)
Py-3.11.0	96.40% <100.00%> (+<0.01%)	⬆️
Py-3.7.16	96.69% <100.00%> (+<0.01%)	⬆️
Py-3.7.9	95.16% <100.00%> (-0.01%)	⬇️
Py-3.8.10	95.08% <100.00%> (-0.01%)	⬇️
Py-3.8.16	96.60% <100.00%> (+<0.01%)	⬆️
Py-3.9.13	95.07% <100.00%> (-0.01%)	⬇️
Py-3.9.16	96.62% <100.00%> (+<0.01%)	⬆️
Py-pypy7.3.11	94.12% <100.00%> (-0.01%)	⬇️
VM-macos	96.45% <100.00%> (-0.01%)	⬇️
VM-ubuntu	96.87% <100.00%> (-0.01%)	⬇️
VM-windows	95.29% <100.00%> (-0.01%)	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
aiohttp/web_log.py	100.00% <100.00%> (ø)
tests/test_web_log.py	98.60% <100.00%> (+0.07%)	⬆️

... and 1 file with indirect coverage changes

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

[Dreamsorcerer]

I wonder if there isn't a better solution. The logging code there looks kind of wrong to me.

e.g. self.logger.info(self._log_format % tuple(values), extra=extra) should surely be self.logger.info(self._log_format, tuple(values), extra=extra) so the string formatting doesn't happen if it's not going to be logged (not sure the tuple() call is really needed either). Presumably all the code above that line should also be done as a logging Formatter, rather than done pre-emptively (https://docs.python.org/3/howto/logging.html#formatters), although I've not looked in detail so there could be a reason that won't work..

I suspect if that were refactored to use the logging module better, then we wouldn't need any extra checks for performance (and maybe lose that method entirely as it'd become a 1 liner).

[bdraco]

I wonder if there isn't a better solution. The logging code there looks kind of wrong to me.

e.g. self.logger.info(self._log_format % tuple(values), extra=extra) should surely be self.logger.info(self._log_format, tuple(values), extra=extra) so the string formatting doesn't happen if it's not going to be logged (not sure the tuple() call is really needed either). Presumably all the code above that line should also be done as a logging Formatter, rather than done pre-emptively (docs.python.org/3/howto/logging.html#formatters), although I've not looked in detail so there could be a reason that won't work..

I suspect if that were refactored to use the logging module better, then we wouldn't need any extra checks for performance (and maybe lose that method entirely as it'd become a 1 liner).

There isn't much we can do to defer construction in LogRecord as most of this has to be constructed ahead of time for this case https://github.com/python/cpython/blob/70bc8c936dfbd936959efd32f0cddc2597598592/Lib/logging/__init__.py#L280

I don't think there is a way to defer the construction of extra here
https://github.com/python/cpython/blob/70bc8c936dfbd936959efd32f0cddc2597598592/Lib/logging/__init__.py#L1603

isEnabledFor is what the logging howto docs recommend at least:
https://docs.python.org/3/howto/logging.html#optimization

[Dreamsorcerer]

There isn't much we can do to defer construction in LogRecord as most of this has to be constructed ahead of time for this case https://github.com/python/cpython/blob/70bc8c936dfbd936959efd32f0cddc2597598592/Lib/logging/__init__.py#L280

Maybe you're right, I just saw code that looks like it is doing formatting, and am wondering if it can't be done by a Formatter.

isEnabledFor is what the logging howto docs recommend at least:
https://docs.python.org/3/howto/logging.html#optimization

Well, that's more because you need to call an expensive function to get the logging object (e.g. get_user() to include the user in the log output or something). At a glance, this code looks like the objects to log are already passed in and the computation time is spent formatting them into the log message.

[Dreamsorcerer]

So, here's a section that talks about using filters to add contextual information (which looks an awful lot like what this code is doing):
https://docs.python.org/3/howto/logging-cookbook.html#using-filters-to-impart-contextual-information
Or LoggerAdapter above that section:
https://docs.python.org/3/howto/logging-cookbook.html#using-loggeradapters-to-impart-contextual-information

[bdraco]

https://docs.python.org/3/howto/logging-cookbook.html#using-filters-to-impart-contextual-information

Filter instances are allowed to modify the LogRecords passed to them

I think the filter would happen too late as we already had to pay the overhead of constructing the LogRecord before it can be filtered.

https://docs.python.org/3/howto/logging.html#optimization

However, computing the arguments passed to the logging method can also be expensive

Unless I've been dense, I think the problem we are solving is computing the arguments is computationally expensive.

[Dreamsorcerer]

I think the filter would happen too late as we already had to pay the overhead of constructing the LogRecord before it can be filtered.

When an event is logged and not filtered out by a logger’s level, a LogRecord is created
https://docs.python.org/3/howto/logging-cookbook.html#customizing-logrecord

So, this is only happening only if the log level is enabled (likewise with the LoggerAdapter).

However, computing the arguments passed to the logging method can also be expensive

Unless I've been dense, I think the problem we are solving is computing the arguments is computationally expensive.

My point is that we should just pass the request etc. with extra= and then do the processing to format the message correctly as shown in one of those examples. i.e. The arguments being passed here are not arguments of the message, they are contextual information that can be parsed separately, rather than being included in the main message. If you look at those examples, they seem very similar to what we are doing here (we're just not leveraging the logger module fully and instead preprocessing all the contextual information).

[bdraco]

My point is that we should just pass the request etc. with extra= and then do the processing to format the message correctly as shown in one of those examples. i.e. The arguments being passed here are not arguments of the message, they are contextual information that can be parsed separately, rather than being included in the main message. If you look at those examples, they seem very similar to what we are doing here (we're just not leveraging the logger module fully and instead preprocessing all the contextual information).

I think that would work to defer the extra processing but it won't solve the cost of constructing values which is a large part of the expense.

The code from the example is operating on the LogRecord

    def filter(self, record):

        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

But its not deferring the construction of the other arguments

a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

[Dreamsorcerer]

I think that would work to defer the extra processing but it won't solve the cost of constructing values which is a large part of the expense.

values is the contextual information. What I'm proposing is to do all of that work in a Filter or LoggerAdapter, so there is no code before the actual log call. At that point, the AccessLogger could maybe just become a normal Logger and you just call access_logger.info(..., extra={"request": request, "response": response}), I'm not sure if the custom class is actually needed at that point.

[bdraco]

values is the contextual information. What I'm proposing is to do all of that work in a Filter or LoggerAdapter, so there is no code before the actual log call. At that point, the AccessLogger could maybe just become a normal Logger and you just call access_logger.info(..., extra={"request": request, "response": response}), I'm not sure if the custom class is actually needed at that point.

That should solve the performance problem, but its going to break anything that operates on LogRecord objects like Home Assistant's system_log integration because it won't know how to reconstruct the logger message in the standard way.

[Dreamsorcerer]

That should solve the performance problem, but its going to break anything that operates on LogRecord objects like Home Assistant's system_log integration because it won't know how to reconstruct the logger message in the standard way.

My impression was that the Filter modifies the LogRecord and passes it on, so I'd assume the resulting LogRecord could look identical to the current one?

[bdraco]

That should solve the performance problem, but its going to break anything that operates on LogRecord objects like Home Assistant's system_log integration because it won't know how to reconstruct the logger message in the standard way.

My impression was that the Filter modifies the LogRecord and passes it on, so I'd assume the resulting LogRecord could look identical to the current one?

It looks like the emit happens after the filter so that should work.

https://github.com/python/cpython/blob/4fa5fda14b11457dda7ef389e5486bfe3ea7b8f5/Lib/logging/__init__.py#L978

[bdraco]

I started a draft as #7251 but I ran into a problem

We have to attach the logging filter to the logger object that gets passed in which affects anything else being logged with that logger which seems like a breaking change

[Dreamsorcerer]

Yep, if it still looks good we could use that in master and merge this PR for 3.9.

[bdraco]

I think adding the filter is going to be too much of a breaking change as the what the user needs to do section looks something like this. I stopped writing it when it became clear the side effects are going to be a problem

Are there changes in behavior for the user?

If you are using multiple aiohttp.web.AppRunner in the same python process you must also now pass a unique logger to each because AccessLogger will now attach a filter which affects the state of any logger object passed in and is not re-entrant.

Consumers of AccessLogger MUST use a new unique logger as the AccessLogger will now add logging filter to any existing logger that is passed in which will affect logging for all handlers attached to that logger. Be sure to generate a unique logger object for each instance of AccessLogger. It is important the logger is unique because if other code is using the same logger, the logging filter will likely raise an exception or mutate the log messages in an unexpected way.

        log = logging.getLogger("my_unique_logger_per_instance_of_aiohttp")
        log_format = "%a %{User-Agent}i"
        access_logger = AccessLogger(log, log_format)
        access_logger.log(request, response, time)

If multiple aiohttp instances use the same logger object then the log filter will be attached multiple times which will lead to undefined behavior.

[Dreamsorcerer]

OK, I guess I was thinking of the access logger as more of an internal logger, rather than using another logger. Looks like it's not worth the hassle then. Thanks for investigating though!

[patchback]

Backport to 3.9: 💚 backport PR created

✅ Backport PR branch: patchback/backports/3.9/315ae9037438351b48a712734173020374e5ff33/pr-7240

Backported as #7254

🤖 @patchback
I'm built with octomachinery and
my source is open — https://github.com/sanitizers/patchback-github-app.

[bdraco]

Thanks