Significant performance degradation in logging.TimedRotatingFileHandler due to fix to #89564

[dgrisby]

The fix to #89564 was to add two file checks to the shouldRollover() method of logging.TimedRotatingFileHandler and RotatingFileHandler (see 62a6677 )

This means that every single log call now does two stat() calls to the log file, which is quite expensive. If the log file is stored on NFS, those stat() calls become extremely expensive. In our application it caused a dramatic (and hard to diagnose) performance loss.

It would be better if shouldRollover() was reverted to its previous implementation, and the check for special files was moved into doRollover(). That would mean the cost of the additional checks was only incurred when there is a rollover to do.

[vsajip]

Well, the logic belongs in shouldRollover() because that's where the decision on whether to rollover (i.e. whether or not to call doRollover()) is made, and that depends on the result of the file-exists-but-is-not-really-a-file check. One could possibly mitigate the issue you've hit in several ways:

1. Cache the result of that check in the handler.
2. Determine the result of the check via a single os.stat() call rather than two (I assume that one is due to the os.path.exists() call and the other is due to os.path.isfile() call).
3. Move the check in shouldRollover() to where the method would otherwise return True, so that rollover would have occurred but for the check.

As you're hitting the performance issue in your environment, I invite you to consider making a patch using one or more of the above suggestions and then testing the performance impact, and if a solution is found which is acceptable, working up a PR with that patch.

[dgrisby]

In our application we know for a fact that the logfile is not a special file, so the new check is not required for us. We already had our own subclass of TimedRotatingFileHandler, so we have fixed this for ourselves by simply giving our subclass a shouldRollover method containing a copy of the original code.

We no longer suffer from this issue because we are no longer using the problematic code. I raised this defect to try to be helpful for other people who hit the same issue.

[vsajip]

OK, thanks - that was thoughtful of you. I'll close this issue then, but aim to remember if a performance issue is logged in this area. Of course, that "problematic code" was added because its absence caused problems in other scenarios 🙂

[dgrisby]

I do think this is something that should be fixed in the standard library. I will create a PR for it.

[vsajip]

Thanks, Duncan. As you're best placed to test the result of the fix, I was hoping for this.