[issue11369] Add caching for the isEnabledFor() computation
William Hart whart...@gmail.com added the comment: Understood! FYI, we worked around this caching issue explicitly in our code. This wound up being simpler than supporting a hacked version of the logger. Thanks for looking into this! On Mon, Apr 11, 2011 at 1:54 AM, Vinay Sajip rep...@bugs.python.org wrote: Vinay Sajip vinay_sa...@yahoo.co.uk added the comment: I'll regretfully have to mark this as wontfix, since adding threading interlocks for correct operation in multi-threaded environments will negate the performance benefit. -- resolution: - wont fix status: open - closed ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___ -- Added file: http://bugs.python.org/file21618/unnamed ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___Understood! FYI, we worked around this caching issue explicitly in our code. This wound up being simpler than supporting a hacked version of the logger.brbrThanks for looking into this!brbrdiv class=gmail_quote On Mon, Apr 11, 2011 at 1:54 AM, Vinay Sajip span dir=ltrlt;a href=mailto:rep...@bugs.python.org;rep...@bugs.python.org/agt;/span wrote:brblockquote class=gmail_quote style=margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex; br Vinay Sajip lt;a href=mailto:vinay_sa...@yahoo.co.uk;vinay_sa...@yahoo.co.uk/agt; added the comment:br br I#39;ll regretfully have to mark this as wontfix, since adding threading interlocks for correct operation in multi-threaded environments will negate the performance benefit.br br --br resolution:  -gt; wont fixbr status: open -gt; closedbr br ___br Python tracker lt;a href=mailto:rep...@bugs.python.org;rep...@bugs.python.org/agt;br lt;a href=http://bugs.python.org/issue11369; target=_blankhttp://bugs.python.org/issue11369/agt;br ___br /blockquote/divbr ___ Python-bugs-list mailing list Unsubscribe: http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue11369] Add caching for the isEnabledFor() computation
William Hart whart...@gmail.com added the comment: Vinay: No, I haven't tried this in multi-threaded applications. You're correct that this would require locks around the global data. --Bill On Thu, Mar 10, 2011 at 3:16 AM, Vinay Sajip rep...@bugs.python.org wrote: Vinay Sajip vinay_sa...@yahoo.co.uk added the comment: Bill, I was looking at this patch again, and I'm not sure about thread safety. The correctness of the caching depends on manager.status, which is state which is potentially shared across threads. There are no interlocks around it, so with the patch as it stands, ISTM it's possible in a multi-threaded application to get stale information. Has your patch been used in multi-threaded applications? -- ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___ -- Added file: http://bugs.python.org/file21107/unnamed ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___Vinay:brbrNo, I haven#39;t tried this in multi-threaded applications. You#39;re correct that this would require locks around the global data.brbr--Billbrbrdiv class=gmail_quoteOn Thu, Mar 10, 2011 at 3:16 AM, Vinay Sajip span dir=ltrlt;a href=mailto:rep...@bugs.python.org;rep...@bugs.python.org/agt;/span wrote:br blockquote class=gmail_quote style=margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;div class=imbr Vinay Sajip lt;a href=mailto:vinay_sa...@yahoo.co.uk;vinay_sa...@yahoo.co.uk/agt; added the comment:br br /divBill,br br I was looking at this patch again, and I#39;m not sure about thread safety. The correctness of the caching depends on manager.status, which is state which is potentially shared across threads. There are no interlocks around it, so with the patch as it stands, ISTM it#39;s possible in a multi-threaded application to get stale information. Has your patch been used in multi-threaded applications?br divdiv/divdiv class=h5br --br br ___br Python tracker lt;a href=mailto:rep...@bugs.python.org;rep...@bugs.python.org/agt;br lt;a href=http://bugs.python.org/issue11369; target=_blankhttp://bugs.python.org/issue11369/agt;br ___br /div/div/blockquote/divbr ___ Python-bugs-list mailing list Unsubscribe: http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue11369] Add caching for the isEnabledFor() computation
William Hart whart...@gmail.com added the comment: Vinay: Yes, the bulk of the time was spent in getEffectiveLevel(). Since that method is only called by isEnabledFor(), it made sense to cache isEnabledFor(). But, that probably reflects the characteristics of my use of logging. I never call getEffectiveLevel() otherwise, so caching isEnabledFor() minimized the total cost of logging. I think you could sensibly argue for caching getEffectiveLevel(). I had somewhat shallow logger hierarchies (3-4 deep). The real problem was that this was being called in a kernel of my code ... so even that additional cost was noteworthy. I think it's smart to focus on Python 3.3. As it happens, my colleagues did some explicit caching of logging information that made pyutilib.logging redundant. When you don't think you need this as a reference implementation, I'll delete it. --Bill On Wed, Mar 2, 2011 at 2:25 AM, Vinay Sajip rep...@bugs.python.org wrote: Vinay Sajip vinay_sa...@yahoo.co.uk added the comment: Bill, Thanks for the suggestion and the patch. It's a good idea, though I wonder whether you found that the bulk of the time spent in isEnabledFor() was actually spent in getEffectiveLevel()? That's the one which loops through a logger's ancestors looking for a level which is actually set, so intuitively it would take a while - especially for deeper levels in the logging hierarchy. If so (which I suspect to be the case, but it would be good to have you confirm it), a better solution may be to cache the effective level. Roughly how deep are/were your logger hierarchies in the situation where you experienced performance problems? I'm happy to look at caching effective level for Python 3.3: The 2.X branches are now closed for additions other than bugs and security issues. -- assignee: - vinay.sajip ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___ -- Added file: http://bugs.python.org/file20997/unnamed ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___Vinay:brbrYes, the bulk of the time was spent in getEffectiveLevel(). Since that method is only called by isEnabledFor(), it made sense to cache isEnabledFor(). But, that probably reflects the characteristics of my use of logging. I never call getEffectiveLevel() otherwise, so caching isEnabledFor() minimized the total cost of logging. I think you could sensibly argue for caching getEffectiveLevel().br brI had somewhat shallow logger hierarchies (3-4 deep). The real problem was that this was being called in a kernel of my code ... so even that additional cost was noteworthy.brbrI think it#39;s smart to focus on Python 3.3. As it happens, my colleagues did some explicit caching of logging information that made pyutilib.logging redundant. When you don#39;t think you need this as a reference implementation, I#39;ll delete it.br br--Billbrbrbrbrdiv class=gmail_quoteOn Wed, Mar 2, 2011 at 2:25 AM, Vinay Sajip span dir=ltrlt;a href=mailto:rep...@bugs.python.org;rep...@bugs.python.org/agt;/span wrote:brblockquote class=gmail_quote style=margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex; br Vinay Sajip lt;a href=mailto:vinay_sa...@yahoo.co.uk;vinay_sa...@yahoo.co.uk/agt; added the comment:br br Bill,br br Thanks for the suggestion and the patch. It#39;s a good idea, though I wonder whether you found that the bulk of the time spent in isEnabledFor() was actually spent in getEffectiveLevel()? That#39;s the one which loops through a logger#39;s ancestors looking for a level which is actually set, so intuitively it would take a while - especially for deeper levels in the logging hierarchy. If so (which I suspect to be the case, but it would be good to have you confirm it), a better solution may be to cache the effective level.br br Roughly how deep are/were your logger hierarchies in the situation where you experienced performance problems?br br I#39;m happy to look at caching effective level for Python 3.3: The 2.X branches are now closed for additions other than bugs and security issues.br br --br assignee:  -gt; vinay.sajipbr br ___br Python tracker lt;a href=mailto:rep...@bugs.python.org;rep...@bugs.python.org/agt;br lt;a href=http://bugs.python.org/issue11369; target=_blankhttp://bugs.python.org/issue11369/agt;br ___br /blockquote/divbr ___ Python-bugs-list mailing list Unsubscribe: http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue11369] Add caching for the isEnabledFor() computation
New submission from William Hart whart...@gmail.com: I recently started using logging extensively in the Coopr software, and I ran into some performance issues when logging was used within frequently used kernels in the code. After profiling, it became clear that the performance of the logging package could be improved by simply caching the value of the Logger.isEnabledFor() method. I've created a draft version of this cachine mechanism based on a snapshot of logging that I took from Python 2.7.1. This is currently hosted in pytuilib.logging, though I'd love to see this migrate into the Python library (see https://software.sandia.gov/trac/pyutilib/browser/pyutilib.logging/trunk/pyutilib/logging). Basically, I did the following: 1. Added a counter to the Manager class (status) that is incremented whenever the manager object has its level set 2. Add a counter to the Logger class (level_status) that represents the value of the manger status when the Logger's cache was last updated 3. Rework the isEnabledFor() method to update the cache if the logger status is older than the manager status. I moved the present isEnabledFor logic into the _isEnabledFor() method for simplicity. The attached file shows the diffs. Note that there were a few other diffs due to an effort to make pyutilib.logging work on Python 2.5-2.7. --Bill -- components: Library (Lib) files: logging__init__diffs.txt messages: 129851 nosy: William.Hart priority: normal severity: normal status: open title: Add caching for the isEnabledFor() computation versions: Python 2.7, Python 3.1, Python 3.2, Python 3.3 Added file: http://bugs.python.org/file20967/logging__init__diffs.txt ___ Python tracker rep...@bugs.python.org http://bugs.python.org/issue11369 ___ ___ Python-bugs-list mailing list Unsubscribe: http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
