{"id":1213,"date":"2010-04-29T13:05:16","date_gmt":"2010-04-29T03:05:16","guid":{"rendered":"http:\/\/www.somethinkodd.com\/oddthinking\/?p=1213"},"modified":"2010-04-29T13:08:53","modified_gmt":"2010-04-29T03:08:53","slug":"how-python-logging-bit-me-part-1","status":"publish","type":"post","link":"https:\/\/www.somethinkodd.com\/oddthinking\/2010\/04\/29\/how-python-logging-bit-me-part-1\/","title":{"rendered":"How Python Logging Bit Me, Part 1."},"content":{"rendered":"
This is offered to the world in the spirit of “If other programmers can learn from my mistakes, maybe my threads won’t have died in vain.” The trouble is, I don’t think anyone will ever find this by Googling. Maybe I am wrong.<\/div>\n

Here is a heavily-sanitised snippet of Python code, sitting inside a loop, being run by a pool of threads.<\/p>\n

<\/p>\n

    start_time = datetime.now()\r\n    if start_time >= next_run_due:\r\n        logging.debug(\"Starting the performance-critical section\")\r\n        # Ensure that the results we send are based on the freshest data.\r\n\t   \r\n        fetch_data() # Have noticed this runs slow sometimes. Keep an eye on it.\r\n        fetch_completed_time = datetime.now() # Don't examine now. Wait until outside performance-critical section!\r\n        process_data()\r\n        send_results()\r\n\t   \r\n        # Relax. Now outside the performance-critical section.\r\n\r\n        # This performance check has been placed outside the performance-critical section, because logging.critical() may send a (slow) email.\r\n        if fetch_completed_time - start_time > threshold:\r\n            logging.critical(\"Fetch time is running slow again.\") # Implicitly sends an email.\r\n            # If you see this message, check the network and CPU aren't congested.\r\n        next_run_due = next_due_date()<\/pre>\n
<\/code><\/p>\n
So this code checks if some processing is due, and if so, fetchs the data, processes it and sends out the results. It tries to make sure that when it sends out results, it is based on the freshest possible data, so the key section does as little extraneous work as possible.<\/p>\n
Sometimes, the data-fetch takes longer than expected – historically, that has been because something else on the server is chewing up more resources that it should. I want to know when that happens, so I can go and fix it, so I log a critical message. The critical message log is linked to send an SMTP message with Python’s logging library’s SMTPHandler. I do this check outside the key section, so processing the email doesn’t (further) slow the sending of the results.<\/p>\n
Can you see the problem with this code? I couldn’t. (I love asking this question, because people tend to find dozens of other problems I never thought about!)<\/p>\n
Sure, there is no throttling on the critical messages, but that is because this doesn’t occur frequently enough to cause email flooding.<\/p>\n
Here’s a hint. Multi-threading<\/em> and locking<\/em>.<\/p>\n
Some code, in some thread, somewhere, called logging.critical(). Logging.critical() tried to send an email. I expected logging.critical() to write the email to a local buffer, and for sendmail (or whatever) to pick it up and deliver it later. I knew it would be slow, but I was expecting sub-second response times. I haven’t worked out why that isn’t always true, but it isn’t always true. It can take many seconds to send this email.<\/p>\n
But that’s okay, because there are no logging.critical() calls during any performance-sensitive areas, so it won’t affect the “freshness” or the data which is really the critical performance characteristic.<\/p>\n
Can you see the call to logging.debug()? It does not<\/em> send an email; it writes to a log file. Its execution time is measured in hundreds of microseconds, so it isn’t a concern.<\/p>\n
Or so I thought.<\/p>\n
It turns out that logging.debug() blocks, waiting for the logging.critical() call to complete. Now the debug message is taking 10,000 times longer than it normally does! It still isn’t inside the critical part, but note that it is<\/em> inside the part that is timed. So when fetching + logging it takes more time than the threshold, out goes another logging.critical() call, which is another email message, which is another blocked logging system, which holds up the next thread, and so it goes.<\/p>\n
Meanwhile, the time taken to do a logging.critical() call is increasing as they all wait in queue to send emails. The first one goes out, as expected, in less than a second. The second one took twice as long. The third, three times as long. It got to the stage that my threads were freezing up for 90 seconds. I said before that there weren’t enough of these calls to cause email flooding. I stand by that – there was a burst of few hundred over a couple hours which should be easily handled by a server’s email system. But that is assuming that all the threads in the system are not waiting for every email to actually reach its destination before they continue.<\/p>\n
Short Term Solution<\/h4>\n
I’ve turned off emailing of critical logs for the time being. I have moved the debug log outside of the timed section, to stop it from propagating the problem, in any case.<\/p>\n
Outstanding Questions<\/h4>\n
Before I can implement a long-term solution, I have to understand some issues.<\/p>\n
Is my MTA<\/a> running too slowly, even though it is on the localhost? Could it be making me wait while it sends the email, rather than buffering and sending it later? Could it be protecting itself from elephant-interferers<\/strike> err.. spammers by deliberately running slowly? Or is it inappropriate for me (and SMTPHandler) to have every thought it should be fast enough?<\/p>\n
Does SMTPHandler buffer emails before sending them out in a different thread? Apparently not. Could it be configured or rewritten to do so? Do I really need to write such a beast myself?<\/p>\n
Could BufferingSMTPHandler<\/a> help? It seems to try to minimise emails sent by chunking them and only sending when the buffer is full. Presumably, it still blocks other logging during this occasional email, so it remains a problem.<\/p>\n
Could SysLogHandler help by taking it out of the domain of Python? Or given my limited experience with syslog, will I just have a new set of problems?<\/p>\n
In the meantime, if you use SMTPHandler, and you get random periods of sustained bad performance, maybe this will help you?<\/p>\n","protected":false},"excerpt":{"rendered":"
In which Julian stumbles over a serious gotcha in Python’s SMTPHandler for logging messages.<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_s2mail":"","footnotes":""},"categories":[35,25,34],"tags":[353,81,352,69],"class_list":["post-1213","post","type-post","status-publish","format-standard","hentry","category-heroic-failures","category-insufficiently-advanced-technology","category-software-development","tag-logging-gotcha","tag-python","tag-smtphandler","tag-software"],"_links":{"self":[{"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/posts\/1213","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/comments?post=1213"}],"version-history":[{"count":6,"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/posts\/1213\/revisions"}],"predecessor-version":[{"id":1217,"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/posts\/1213\/revisions\/1217"}],"wp:attachment":[{"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/media?parent=1213"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/categories?post=1213"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.somethinkodd.com\/oddthinking\/wp-json\/wp\/v2\/tags?post=1213"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}