Python: Counting executing time of a recursion function with decorator

Question

I want to write a function which behaves exactly similar to the given function, except that it prints the time consumed in executing it. Just like this:

>>> fib = profile(fib)
>>> fib(20)
time taken: 0.1 sec
10946

This is my code,and it will print message in each function call.

import time


def profile(f):
    def g(x):
        start_time = time.clock()
        value = f(x)
        end_time = time.clock()
        print('time taken: {time}'.format(time=end_time-start_time))
        return value
    return g


@profile
def fib(n):
    if n is 0 or n is 1:
        return 1
    else:
        return fib(n-1) + fib(n-2)

My code above will print a message 'taken time:...' for each fib(n-1).So there will be many many messages 'taken time:...'. Can I find a way to just print executing time of fib(20) not every executing time of fib(n-1)?

Sorry...I forgot to post my question.My code will print a "time taken: ..." for each call fib(n-1). So there will be many many message 'time taken: ...'.And I just want one "time taken:" — wdfeng94, Apr 10 '15 at 12:59

score 5 · Accepted Answer · answered Apr 10 '15 at 13:00

I'm assuming your question is "how do I write profile so that it only prints one message even when I decorate a function that can call itself?"

You could keep track of which functions are currently being timed. That way, if a function calls itself, you know that you're already timing it further up the stack, and don't need to do anything for the second instance.

def profile(f, currently_evaluating=set()):
    #`currently_evaluating` will persist across all decorated functions, due to "mutable default argument" behavior.
    #see also http://stackoverflow.com/questions/1132941/least-astonishment-in-python-the-mutable-default-argument
    def g(x):
        #don't bother timing it if we're already doing so
        if f in currently_evaluating: 
            return f(x)
        else:
            start_time = time.clock()
            currently_evaluating.add(f)
            try:
                value = f(x)
            finally:
                currently_evaluating.remove(f)
            end_time = time.clock()
            print('time taken: {time}'.format(time=end_time-start_time))
            return value
    return g

If you're using 3.X, you can cut down on mutable default argument weirdness by using the nonlocal keyword.

def profile(f):
    is_evaluating = False
    def g(x):
        nonlocal is_evaluating
        if is_evaluating:
            return f(x)
        else:
            start_time = time.clock()
            is_evaluating = True
            try:
                value = f(x)
            finally:
                is_evaluating = False
            end_time = time.clock()
            print('time taken: {time}'.format(time=end_time-start_time))
            return value
    return g

This answer is really good one and adds little overhead, thanks about it! — BPL, Feb 19 '18 at 17:52
@Kevin could you please explain why do you use **try/finally** construction? — Kirill Dolmatov, Mar 07 '20 at 18:24

score 1 · Answer 2 · answered Apr 10 '15 at 13:08

1

You can use a class as your profiler:

import time

class ProfileRecursiveFib(object):
    def __call__(self, func):
        self.start_time = time.clock()    
        def g(x):
            return func(x)
        self.end_time = time.clock()
        print('time taken: {0}'.format(self.end_time - self.start_time))
        return g


profile = ProfileRecursiveFib()

@profile
def fib(n):
    if n is 0 or n is 1:
        return 1
    else:
        return fib(n-1) + fib(n-2)

result = fib(20)
print(result)

This prints time (only once) and result:

time taken: 9.056212818586247e-07
10946

answered Apr 10 '15 at 13:08

Raydel Miranda

13,825
3
38
60

I believe the OP's desired behavior is like: if I call `fib` three times, It will print "time taken: whatever seconds" three times. But your code only prints "time taken" once, no matter how many times `fib` is called. – Kevin Apr 10 '15 at 13:10
@Kevin I don't think so, the OP wrote *"Can I find a way to just print executing time of fib(20) not every executing time of fib(n-1)?"* – Raydel Miranda Apr 10 '15 at 14:10
@RaydelMiranda Kevin's code is correct. But he should say, I want to count time of fib(20),and I just want to print that message once.And if you check it ,you will know the output of your code is the time of profile, not time of fib(20,)so it's very short. – wdfeng94 Apr 10 '15 at 14:28
@FengWeidong I see, you're totally right. I am only meassuring the time that takes Python to define `g()` – Raydel Miranda Apr 10 '15 at 14:37

score 0 · Answer 3 · answered Apr 10 '15 at 13:07

0

I understood the answer you expected. you have tiny mistakes in your code, just go through the below code,

import time

def profile(f):
    start_time=time.time()
    def g(x):      
        value = f(x)
        return value
    print("time taken : %f seconds"%(time.time()-start_time))
    return g

def fib(n):
    if n is 0 or n is 1:
        return 1
    else:
        return fib(n-1) + fib(n-2)

x = profile(fib)
print(x(20))

answered Apr 10 '15 at 13:07

Dass

326
1
11

This looks like it will time how long `profile` takes, not how long it takes to call `fib`. I believe the OP's desired behavior is like: if I call `fib` three times, It will print "time taken: whatever seconds" three times. But your code only prints "time taken" once, no matter how many times `fib` is called. – Kevin Apr 10 '15 at 13:07
Yes Kevin, you are right. But the person, who posts a question to expect it would be print only once so that I amend his code. – Dass Apr 10 '15 at 13:40
I tried your code.But there is a mistake.I need to count executing time of fib(20), but your output may be the time of profile. – wdfeng94 Apr 10 '15 at 14:21

Python: Counting executing time of a recursion function with decorator

3 Answers3

Linked