gistfile3.sh

vinay@eta-jaunty:~/projects/scratch$ python3.2 timefc.py 
filename_comparison  50.61 microseconds
module_globals       49.56 microseconds
vinay@eta-jaunty:~/projects/scratch$ python2.7 timefc.py 
filename_comparison  50.79 microseconds
module_globals       50.01 microseconds

logging.diff

Index: Lib/logging/__init__.py
===================================================================
--- Lib/logging/__init__.py	(revision 85055)
+++ Lib/logging/__init__.py	(working copy)
@@ -89,6 +89,16 @@
 #    _srcfile = None
 
 #
+# An alternative approach to finding the caller is to use module globals
+# to determine whether we're in inside logging code.
+#
+# Let's also have a flag _useglobals which determines whether or not to
+# use this strategy - it allows us to compare more easily the performance
+# of the two approaches.
+
+_useglobals = False
+
+#
 #_startTime is used as the base when calculating the relative time of events
 #
 _startTime = time.time()
@@ -1199,20 +1209,28 @@
         Find the stack frame of the caller so that we can note the source
         file name, line number and function name.
         """
+        rv = "(unknown file)", 0, "(unknown function)"
         f = currentframe()
-        #On some versions of IronPython, currentframe() returns None if
-        #IronPython isn't run with -X:Frames.
-        if f is not None:
-            f = f.f_back
-        rv = "(unknown file)", 0, "(unknown function)"
-        while hasattr(f, "f_code"):
-            co = f.f_code
-            filename = os.path.normcase(co.co_filename)
-            if filename == _srcfile:
+        if _useglobals:
+            globs = globals()
+            while f is not None and f.f_globals is globs:
                 f = f.f_back
-                continue
-            rv = (filename, f.f_lineno, co.co_name)
-            break
+            if f is not None:
+                co = f.f_code
+                rv = (co.co_filename, f.f_lineno, co.co_name)
+        else:
+            #On some versions of IronPython, currentframe() returns None if
+            #IronPython isn't run with -X:Frames.
+            if f is not None:
+                f = f.f_back
+            while hasattr(f, "f_code"):
+                co = f.f_code
+                filename = os.path.normcase(co.co_filename)
+                if filename == _srcfile:
+                    f = f.f_back
+                    continue
+                rv = (co.co_filename, f.f_lineno, co.co_name)
+                break
         return rv
 
     def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):

timefc.py

#!/usr/bin/env python
# Time different findCaller strategies.

import logging
import timeit

logger = logging.getLogger()

def filename_comparison():
    logger.info('This is a test for filename comparison')

def module_globals():
    logger.info('This is a test for module globals')

def do_timing(func):
    t = timeit.Timer(func)
    elapsed = t.timeit(number=1000000)
    print("%-20s %5.2f microseconds" % (func.__name__, elapsed))

def main():
    logging.basicConfig(level=logging.INFO, filename="timefc.log", filemode="w", format="%(funcName)s %(filename)s %(lineno)d %(message)s")
    do_timing(filename_comparison)
    logging._useglobals = True
    do_timing(module_globals)

if __name__ == "__main__":
    main()