Timing and aspect oriented programming (Was Re: Equivalent of Perl chomp?)

[Huaiyu Zhu]

On Thu, 31 Jan 2002 12:29:06 -0800, Mark McEahern <marklists at mceahern.com>
wrote: 
>
>I timed them with the following code and it occurred to me here's a possibly
>good case where aspect-oriented programming would be nice. 

I tried the example with aspect oriented programming.  In this case the cost
is too high, but it might be useful in some other cases.  Following are the
test program, the results, and the aspect module.


#-------------- test_ends.py -----------------------

from time import time

a = "das af dsa fdsaa fdsaf as das as fdas as fsa as dsa fadasfdsa "
x = "adsfasdf";
n = 10000; 

#------------------------------------------------------------------
# plain old test

def slice(a, x, n):
    _time = time()
    for i in xrange(n):
        #a[-1:] == x
        a[-len(x):] == x
    return time() - _time

def endswith(a, x, n):
    _time = time()
    for i in xrange(n):
        a.endswith(x)
    return time() - _time

print ; print "slice endswith"
for i in range(5):  print slice(a, x, n), endswith(a, x, n)
print ; print "endswith slice"
for i in range(5):  print endswith(a, x, n), slice(a, x, n)

#------------------------------------------------------------------
# aspect test

class Test:
    def slice(self, a, x):
        a[len(x):] == x
    
    def endswith(self, a, x):
        a.endswith(x)

from aspect1 import timeit
timeit(Test, 'slice', n)
timeit(Test, 'endswith', n)
t = Test()

print ; print "slice endswith"
for i in range(5):  print t.slice(a, x), t.endswith(a, x)
print ; print "endswith slice"
for i in range(5):  print t.endswith(a, x), t.slice(a, x)

# --------- the results
When slice uses [-1:]

slice endswith
0.226076006889 0.30391895771
0.21536898613 0.293772935867
0.214552998543 0.296599984169
0.215177059174 0.301518917084
0.214749097824 0.296058058739

endswith slice
0.287701964378 0.2228089571
0.288692951202 0.231354951859
0.28769505024 0.222257971764
0.287680029869 0.22406899929
0.287147045135 0.228953003883

When slice uses [-len(x):]

slice endswith
0.0638729333878 0.0270719528198
0.0566090345383 0.0265839099884
0.0572431087494 0.0265699625015
0.0570579767227 0.0334140062332
0.0567760467529 0.0265719890594

endswith slice
0.0266000032425 0.0571140050888
0.0265990495682 0.0568480491638
0.0266120433807 0.0567020177841
0.026643037796 0.056519985199
0.0268899202347 0.0658220052719


When slice uses [-len(x):], using "aspect-oriented" timing:

slice endswith
0.122717022896 0.0866810083389
0.122745990753 0.0862590074539
0.13433098793 0.0857419967651
0.121955990791 0.0860439538956
0.129957079887 0.0868830680847

endswith slice
0.0857659578323 0.121948957443
0.085440993309 0.12923002243
0.0860010385513 0.122326016426
0.0858659744263 0.123429894447
0.0925229787827 0.121724009514


Here's the aspect module used:

# --------------------------------- aspect1.py ----------------------

#! /usr/bin/env python
# --------------------------------------------------------------------------
# aspect.py
# 
# From: Pedro Rodriguez (pedro_rodriguez at club-internet.fr)
# Newsgroups: comp.lang.python
# Date: 2002-01-13 02:27:51 PST
# Date: Tue, 22 Jan 2002 16:29:18 +0100
#
# Modified: Huaiyu Zhu 2002-01-27, 2002-01-30

# --------------------------------------------------------------------------
# The core functions

from __future__ import nested_scopes

def wrap(aspect, wrapper, cls, *method_names):
    #print "wrap", aspect, wrapper, cls, method_names
    for method_name in method_names:
        orig_method = getattr(cls, method_name)
        wrapped_method = aspect(wrapper, orig_method, method_name)
        setattr(cls, method_name, wrapped_method)

def around(wrapper, orig_method, method_name):
    def wrapped_method(inst, *args, **kwargs):
        return wrapper(inst, orig_method, method_name, *args, **kwargs)
    return wrapped_method

def before(wrapper, orig_method, method_name):
    def wrapped_method(inst, *args, **kwargs):
        wrapper(inst, orig_method, method_name, *args, **kwargs)
        result = orig_method(inst, *args, **kwargs)
        return result
    return wrapped_method

def after(wrapper, orig_method, method_name):
    def wrapped_method(inst, *args, **kwargs):
        result = orig_method(inst, *args, **kwargs)
        wrapper(inst, orig_method, method_name, *args, **kwargs)
        return result
    return wrapped_method 

# ------------------------------------------------------------------
# Example aspects

def log_around(cls, method_name, file=None):
    def wrapper(inst, method, method_name, *args, **kwargs):
        print >> file, "starting:", inst, method_name, args, kwargs
        result =  method(inst, *args, **kwargs)
        print >> file, "stopping:", inst, method_name
        return result
    wrap(around, wrapper, cls, method_name)

def log_before(cls, method_name, file=None):
    def wrapper(inst, method, method_name, *args, **kwargs):
        print >> file, "before:", inst, method_name, args, kwargs
    wrap(before, wrapper, cls, method_name)

def log_after(cls, method_name, file=None):
    def wrapper(inst, method, method_name, *args, **kwargs):
        print >> file, "after:", inst, method_name, args, kwargs
    wrap(after, wrapper, cls, method_name)

def err_abort(cls, method_name, file=None):
    def wrapper(inst, method, method_name, *args, **kwargs):
        try:
            return method(inst, *args, **kwargs)
        except Exception, e:
            print >> file, "Error abort: %s.%s(*%s, **%s)" % (
                inst, method_name, args, kwargs), e
            raise SystemExit
    wrap(around, wrapper, cls, method_name)

def err_ignore(cls, method_name, file=None):
    def wrapper(inst, method, method_name, *args, **kwargs):
        try:
            return method(inst, *args, **kwargs)
        except Exception, e:
            print >> file, "Error ignore: %s.%s(*%s, **%s)" % (
                inst, method_name, args, kwargs), e
            return None
    wrap(around, wrapper, cls, method_name)

def timeit(cls, method_name, num=100):
    from time import time
    def wrapper(inst, method, method_name, *args, **kwargs):
        _time = time()
        for i in xrange(num):
            method(inst, *args, **kwargs)
        return time() - _time
    wrap(around, wrapper, cls, method_name)
    
# ------------------------------------------------------------------
# Example applications

if __name__ == "__main__":
    
    class A:
        def f1(self, x, y):
            s =  "f %s %s" % (x, y)
            print " - inside", s; return s
    
        def g1(self, x):
            s = "g %s" % x
            print " - inside", s; return s

        def h1(self, x):
            s = "h %s" % (1/x)
            print " - inside", s; return s

        def i1(self, x):
            s = "i %s" % (1/x)
            print " - inside", s; return s
    
    class B:
        def z(self, *args, **kwargs):
            s = "z %s %s" % (str(args), str(kwargs))
            print " - inside", s; return s
                    
    log_around(A, "h1")
    log_before(A, "g1")
    err_abort(A, "h1")
    err_ignore(A, "i1")
    log_after(B, "z")
    log_around(B, "z")

    class C(A): pass
    
    a = C()
    print a.f1(1,2)
    print a.g1(3)
    
    print
    
    b = B()
    print b.z(1,2,3, x=42)
    print b.z(4)

    print 
    print a.h1(3)
    print a.i1(0)
    print a.h1(0)
    print "Should not get here"