This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Do not acquire lock in MemoryHandler.flush() if no target defined
Type: performance Stage: resolved
Components: Library (Lib) Versions: Python 3.10, Python 3.9
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: ankostis, iritkatriel, penlect, vinay.sajip
Priority: normal Keywords:

Created on 2020-08-05 06:06 by ankostis, last changed 2022-04-11 14:59 by admin. This issue is now closed.

Messages (10)
msg374859 - (view) Author: Kostis Anagnostopoulos (ankostis) * Date: 2020-08-05 06:06
The `logging.handlers.MemoryHandler.flush()` method acquire the lock even if target has not been set, and the method is a noop:

```
def flush(self):
    # (Docstring skipped)
    self.acquire()
    try:
        if self.target:
	    for record in self.buffer:
	        self.target.handle(record)
	    self.buffer..clear()
    finally:
        self.release()
```

An optimized version would re-arrrange the nesting to avoid the locking:

```
def flush(self):
    # (Docstring skipped)
    if self.target:
        self.acquire()
        try:
            for record in self.buffer:
                self.target.handle(record)
            self.buffer.clear()
        finally:
            self.release()
```

- There is no use-case, beyond the expected performance gain.
- Without having searched, i would deem highly improbable the existence of code in the std-library or 3rdp code that depends on the current noop-locking when `flush()` is called.
msg374995 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-08-07 11:57
Actually the lock is needed and it is currently missing from setTarget. 

The script below causes handle to be called on None, causing:

  File "C:\Users\User\src\cpython\lib\logging\handlers.py", line 1265, in emit
    self.flush()
  File "C:\Users\User\src\cpython\lib\logging\handlers.py", line 1348, in flush
    self.target.handle(record)
AttributeError: 'NoneType' object has no attribute 'handle'


------------------------------------------------
import io
import logging.handlers
import threading
import time

class SlowHandler:
    def __init__(self):
        self.stream = io.StringIO()
        self.streamHandler = logging.StreamHandler(self.stream)

    def handle(self, msg):
        time.sleep(1)
        self.streamHandler.handle(msg)

target = SlowHandler()
mem_hdlr = logging.handlers.MemoryHandler(10, logging.ERROR, target)
mem_logger = logging.getLogger('mem')
mem_logger.propagate = False
mem_logger.addHandler(mem_hdlr)

def toggleTarget():
    time.sleep(1)
    mem_hdlr.setTarget(None)

t = threading.Thread(target=toggleTarget, args=())
t.daemon = True
t.start()

while True:
    time.sleep(0.1)
    mem_logger.warning("warning not flushed")
    mem_logger.error("error is flushed")
    print("%s" % target.stream.getvalue().splitlines())

------------------------------------------------
msg374999 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-08-07 15:01
I guess the missing lock in setTarget is a different issue than the one you raise here and should be a separate ticket - I will create one.
msg375006 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-08-07 15:39
Regarding the change you suggest here - I think you need add another check that target is not None after you've acquired the lock to make it safe.
msg375629 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-08-18 22:11
I think it is unlikely that this change would make a measurable speedup (benchmarks would be needed to prove that it does).

And even if it does, it's for the case where no target has been set, in which case the logger isn't doing anything anyway. Why is this a case worth optimizing?
msg377944 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-10-04 14:57
I think this issue should be closed - Kostis doesn't seem keen to discuss the merits of this change, and as I've said I don't think it's worth pursuing.
msg377947 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2020-10-04 15:42
OK, I'll mark as pending and close in a few days if nothing more is heard from Kostis.
msg377954 - (view) Author: Kostis Anagnostopoulos (ankostis) * Date: 2020-10-04 15:56
Have nothing else to say on top of what iritkatriel discovered, a double-check would be needed, but may be a pointless speed up, if MemoryHandler is impossible to work without a `target`.  

Fixing the no-target error is more important.  Actually that's how i came to notice this optimization.
msg377955 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-10-04 16:03
The missing target error was fixed under issue41503
msg378231 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2020-10-08 10:42
This can be closed now - we all agree there is nothing left to do.
History
Date User Action Args
2022-04-11 14:59:34adminsetgithub: 85655
2020-10-09 13:28:15vinay.sajipsetstatus: open -> closed
resolution: not a bug
stage: resolved
2020-10-08 10:42:02iritkatrielsetmessages: + msg378231
2020-10-04 16:03:05iritkatrielsetmessages: + msg377955
2020-10-04 15:56:06ankostissetstatus: pending -> open

messages: + msg377954
2020-10-04 15:42:16vinay.sajipsetstatus: open -> pending

messages: + msg377947
2020-10-04 14:57:39iritkatrielsetmessages: + msg377944
2020-08-18 22:11:22iritkatrielsetmessages: + msg375629
2020-08-07 15:39:42iritkatrielsetmessages: + msg375006
2020-08-07 15:01:00iritkatrielsetmessages: + msg374999
2020-08-07 11:57:16iritkatrielsetnosy: + iritkatriel
messages: + msg374995
2020-08-05 06:06:13ankostiscreate