一半君的总结纸

听话只听一半君

#117 如何计算脚本运行所需时间?

经常会遇到需要知道某段代码运行需要耗费多少时间的情况,得有个量化的数值才好知道这次操作花了多少时间,作为以后优化的参考依据,甚至可以用来”预测未来”

比如动画组的抱怨说,最近rig升级为什么这么慢,当然你在公司可能自己有做一个升级rig的工具,升级前会把动画曲线,constraints,动态添加的deformers之类的导出,升级完rig之后再导回来,如果工具已经使用了多年,无数代鼠标民工修修补补之后,已经变得很复杂,不再是几百行的小脚本,而是和公司内部的其他各种module错综复杂的交织在一起,很难判断到底是哪儿出了问题,

换句话说,代码太长了,又不是一个人写的,想快速找到哪儿造成了速度慢该如何找?当然可以用排除法一点一点找,试不同文件,不同shot,不同电脑等等,但是如果还是没辙,此时最显然的方法当然是看看各个函数调用哪一个比较慢

  • 最脑残的方法当然是直接用maya自己给的timer / timerX 命令
    start = cmds.timerX()
    # code that is being timed
    totalTime = cmds.timerX(startTime=start)
    print "Total time: ", totalTime
    

    这样不是不可以,但是写起来有点乱,每次想用计时功能的时候,都要把这几句贴进功能性的代码里,不太好

  • 如果是在interpreter里临时测试,或者script是单个可执行文件,也可以用python自带的timeit
    # 命令行里用
    $ python -m timeit '"-".join(str(n) for n in range(100))'
    10000 loops, best of 3: 40.3 usec per loop
    
    # 代码里用
    import timeit
    timeit.timeit('"-".join(str(n) for n in range(100))', number=10000)
    0.8187260627746582
    

    但是代码里用还是不方便简洁,这和python的time module的差不多

    import time
    start_time = time.time()
    main()
    print("--- %s seconds ---" % (time.time() - start_time))
    
  • 用decorator
    下面是2.5时代的做法

    import time
    
    def timefunc(f):
        def f_timer(*args, **kwargs):
            """timer doc"""
            start = time.time()
            result = f(*args, **kwargs)
            end = time.time()
            print f.__name__, 'took', end - start, 'time'
            return result
        return f_timer
    
    @timefunc
    def expensive_function():
        """expensive_function doc"""
        pass
    

    这样改进过后

    >>> expensive_function.__name__
    'expensive_function'
    >>> expensive_function.__doc__
    'expensive_function doc\n - decorated by @timefunc'
    

    但是这种用decorator的只能放在function上面

    改进1,上面的代码有个问题

    >>> expensive_function()
    expensive_function took 1.90734863281e-06 time
    >>> expensive_function.__name__
    'f_timer'
    >>> expensive_function.__doc__
    'timer doc'
    

    如上所示 expensive_function的__name__和__doc__都被改变了,这不利于文档的自动生成和日常debug,所以可以这样

    def timefunc(f):
        def f_timer(*args, **kwargs):
            """timer doc"""
            start = time.time()
            result = f(*args, **kwargs)
            end = time.time()
            print f.__name__, 'took', end - start, 'time'
            return result
    
        f_timer.__name__ = f.__name__
        f_timer.__doc__ = '%s\n - decorated by @timefunc' % f.__doc__
        f_timer.__dict__.update(f.__dict__)
    
        return f_timer
    

    这样改进过后

    >>> expensive_function.__name__
    'expensive_function'
    >>> expensive_function.__doc__
    'expensive_function doc\n - decorated by @timefunc'
    

    改进2,Python 2.5以后,functools.wrap能自动做到上面这一点

    from functools import wraps
    
    def timefunc(f):
        @wraps(f)
        def f_timer(*args, **kwargs):
            start = time.time()
            result = f(*args, **kwargs)
            end = time.time()
            print f.__name__, 'took', end - start, 'time'
            return result
        return f_timer
    

    当然如果想像改进1里那样有”自定义”的docstring,当然还是只能自己加上

    上面的通用形式是这样的

    from functools import wraps
    def my_decorator(f):
        @wraps(f)
        def wrapper(*args, **kwds):
            print 'Calling decorated function'
            return f(*args, **kwds)
        return wrapper
    
  • 用context manager
    import time
    
    class timewith():
        def __init__(self, name=''):
            self.name = name
            self.start = time.time()
    
        @property
        def elapsed(self):
            return time.time() - self.start
    
        def checkpoint(self, name=''):
            print '{timer} {checkpoint} took {elapsed} seconds'.format(
                timer=self.name,
                checkpoint=name,
                elapsed=self.elapsed,
            ).strip()
    
        def __enter__(self):
            return self
    
        def __exit__(self, type, value, traceback):
            self.checkpoint('finished')
            pass
    
    # 当context manager用
    with timewith('fancy thing') as timer:
        expensive_function()
        timer.checkpoint('done with something')
    
    # 直接用
    timer = timewith('fancy thing')
    expensive_function()
    timer.checkpoint('done with something')
    
    

    但是上面没有考虑exception出现的情况,如果出错,__exit__()会先运行,然后才会看到reraise的exception

    写法2,不用class,写成generator的形式

    from contextlib import contextmanager
    
    @contextmanager
    def timewith(name):
        print '%s started running' % name
        start = time.time()
        yield
        elapsed = time.time() - start
        print '%s took %s seconds' % (name, elapsed)
    
    
    with timewith('fancy thing'):
        expensive_function()
    
    

    如果出错了,会卡在yield那行,所以如果要exception handling应该、

    def timewith(name):
        print '%s started running' % name
        start = time.time()
        try:
            yield
        finally:
            elapsed = time.time() - start
            print '%s took %s seconds' % (name, elapsed)
    

    这样就和前面一样了,在最后的__exit__()才会reraise exception

  • decorator和context manager二合一

    from functools import wraps
    import time
    
    class ContextDecorator(object):
        def __init__(self, **kwargs):
            self.__dict__.update(kwargs)
    
        def __enter__(self):
            # Note: Returning self means that in "with ... as x", x will be self
            return self
    
        def __exit__(self, typ, val, traceback):
            pass
    
        def __call__(self, f):
            @wraps(f)
            def wrapper(*args, **kw):
                with self:
                    return f(*args, **kw)
            return wrapper
    
    
    class log_runtime(ContextDecorator):
        def __enter__(self):
            self.start_time = time.time()
            return self
        def __exit__(self, typ, val, traceback):
            # Note: typ, val and traceback will only be not None
            # If an exception occured
            # logger.info("{}: {}".format(self.label, time.time() - self.start))
            print "{}: {}".format(self.label, time.time() - self.start_time)
    
    
    def do_stuff():
        print 'inside do_stuff'
        for i in range(10000):
            i += 1
    
    
    
    @log_runtime(label="foo")
    def foo():
        do_stuff()
    
    
    with log_runtime(label="bar"):
        do_stuff()
    
  • 上面的两种方法都是看某个function或者某段代码的,如果代码太多,而且不想在里面改来改去,就是祭出各种profiler的时候了,比如内建的cProfile

    import cProfile
    
    def do_cprofile(func):
        def profiled_func(*args, **kwargs):
            profile = cProfile.Profile()
            try:
                profile.enable()
                result = func(*args, **kwargs)
                profile.disable()
                return result
            finally:
                profile.print_stats()
        return profiled_func
    
    
    >>> expensive_function()
             2 function calls in 0.000 seconds
    
       Ordered by: standard name
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            1    0.000    0.000    0.000    0.000 <stdin>:1(expensive_function)
            1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    
    

    line_profiler

    from line_profiler import LineProfiler
    
    def do_profile():
        def inner(func):
            def profiled_func(*args, **kwargs):
                try:
                    profiler = LineProfiler()
                    profiler.add_function(func)
                    profiler.enable_by_count()
                    return func(*args, **kwargs)
                finally:
                    profiler.print_stats()
            return profiled_func
        return inner
    
    
    @do_profile()
    def expensive_function():
        pass
    
    expensive_function()
    

    pprofile

    import pprofile
    
    def someHotSpotCallable():
        profiler = pprofile.Profile()
        with profiler:
            # Some hot-spot code
        profiler.print_stats()
    
  • 华丽点的方法,用pycallgraph
    可以得到这种图,看到各个函数之间是如何调用的,以及所需时间

参考:
timeit – Measure execution time of small code snippets
Profiling Python Like a Boss
The Python “with” Statement by Example
what is difference between __init__ and __call__ in python?
A Guide to Python’s Magic Methods

Python Decorators vs. Context Managers: Have your cake and eat it!
Python: Tips, Tricks and Idioms – Part 2 – Decorators and Context Managers
functools — Higher-order functions and operations on callable objects
What does functools.wraps do?
A guide to Python’s function decorators

Advertisements

发表评论

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / 更改 )

Twitter picture

You are commenting using your Twitter account. Log Out / 更改 )

Facebook photo

You are commenting using your Facebook account. Log Out / 更改 )

Google+ photo

You are commenting using your Google+ account. Log Out / 更改 )

Connecting to %s

%d 博主赞过: