Profiling Python Plugins

ferdinand

Hi,

well have you exposed an implementation of the decorator profile like shown in the blog? Here is a small snippet to give you an idea how cProfile works in principal.

Cheers,
zipit

import cProfile
import math
import pstats

def some_function():
    """
    """
    profile = cProfile.Profile()

    # Start of profiling
    profile.enable()
    data = [math.sqrt(abs(math.sin(i * .001) * math.cos(i * .001)))
            for i in range(100000)]
    profile.disable()
    # End of profiling

    stats = pstats.Stats(profile)
    stats.strip_dirs()
    stats.sort_stats("cumtime")
    stats.print_stats()

if __name__ == "__main__":
    some_function()

400002 function calls in 0.060 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   100000    0.018    0.000    0.018    0.000 {math.cos}
   100000    0.016    0.000    0.016    0.000 {math.sin}
   100000    0.016    0.000    0.016    0.000 {math.sqrt}
   100000    0.008    0.000    0.008    0.000 {abs}
        1    0.003    0.003    0.003    0.003 {range}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

[Finished in 0.3s]

pim

@pim said in Profiling Python Plugins:

@profile
def DrawMsg(self, x1, y1, x2, y2, msg):

I thought above should be enough.
I guess I have to study the blog a bit better.
Your example seems quite different and I will try it.

Thanks, Pim

ferdinand

Hi,

my example does nothing terribly unusual (I didn't red the whole blog though). I just gave you an example without the syntactic sugar of a decorator, because I assumed you are maybe a bit confused by it - do not know how decorators work - and therefor struggle to understand how cProfile works (which is not that hard to understand).

Cheers,
zipit

a_block

While the output is not as detailed and neat as with zipit's use of profile, this is what I like to use to measure timing of functions:

import time

g_timingInfo = ['']
def timing(f):
    def wrapTiming(*args, **kwargs):
        global g_timingInfo
        time1 = time.clock()
        ret = f(*args, **kwargs)
        time2 = time.clock()
        g_timingInfo.append('T %-8.2f ms : ' % ((time2-time1)*1000.0) + f.func_name)
        return ret
    return wrapTiming

def PrintTiming():
    global g_timingInfo
    if len(g_timingInfo):
        print '\nTIMING INFO:'
        for t in g_timingInfo:
            print t
        print ' '
    else:
        print 'No timing info'
    g_timingInfo = []

In oder to use it, you simply decorate a function (or multiple) with @timing and at a later point of execution you call PrintTiming() to get the accumulated results printed to the Console.
Like so:

@timing
def MyFunction():
    pass
@timing
def MyFunction2():
    pass

def SomewhereInYourCode():
    MyFunction()
    for idx in xrange(100000):
        MyFunction2()
    PrintTiming()

I like the decoration approach, as it's fast to pour some "probes" into your code without modifying the actual implementation of functions.
Using module inspect you can easily beef it up by adding stack information or nice indentation of results based on call level.
And this may also give you an idea, how to build decorations yourself. Useful for all kinds of stuff.

Cheers

m_adam

@pim said in Profiling Python Plugins:

Maxime pointed me to Profiling Python Plugins.
    @profile
NameError: name 'profile' is not defined

I guess the issue is written clearly, the profile decorator is not defined. A decorator is nothing more than a function in Python, for more information see Primer on Python Decorators, so to fix your issue, you only have to copy the profile function provided in the Niklas blog post.

Cheers,
Maxime.

mogh

@a_block

how would I implement your code in python 3.x (R23)
regarding

time.process_time() 
time.perf_counter() 
f.__name__

this is also interesting: https://docs.python.org/3/library/timeit.html

~~I tried this but had no luck.~~

~~Got it somehow working but no timing to display ...~~

getting there still a little bit funky

TIMING INFO:

T 0.00     ms : MyFunction
T 0.00     ms : MySecondFunction
T 15.62    ms : MySecondFunction
T 0.00     ms : MySecondFunction
T 15.62    ms : MySecondFunction
T 0.00     ms : MySecondFunction
T 15.62    ms : MySecondFunction
T 0.00     ms : MySecondFunction
T 0.00     ms : MySecondFunction
T 15.62    ms : MySecondFunction
T 0.00     ms : MySecondFunction
>>>

import c4d
import math
from c4d import gui
from c4d.documents import GetActiveDocument
import time

g_timingInfo = ['']
def timing(f):
    def wrapTiming(*args, **kwargs):
        global g_timingInfo
        time1 = time.process_time()
        ret = f(*args, **kwargs)
        time2 = time.process_time()
        g_timingInfo.append('T %-8.2f ms : ' % ((time2-time1)*1000.0) + f.__name__)
        return ret
    return wrapTiming

def PrintTiming():
    global g_timingInfo
    if len(g_timingInfo):
        print ('\nTIMING INFO:')
        for t in g_timingInfo:
            print (t)
        print (' ')
    else:
        print ('No timing info')
    g_timingInfo = []
	
	
@timing
def MyFunction():
    pass
@timing
def MySecondFunction():
    data = [math.sqrt(abs(math.sin(i * .001) * math.cos(i * .001)))
            for i in range(10000)]    
    pass

def SomewhereInYourCode():
    MyFunction()
    for idx in range(10):
        MySecondFunction()
    PrintTiming()	

def main():
    c4d.CallCommand(13957) # Konsole löschen  / delete console log

    SomewhereInYourCode()
    c4d.EventAdd()

if __name__=='__main__':
    main()

kind regards
mogh

a_block

how would I implement your code in python 3.x (R23)

Not sure, what exactly your problem is. I'm currently using a simpler version of above code in C4D R23 and it works for me. Well, I build the string a bit differently and the print is also written differently in Python 3. But this doesn't seem to be your problem.
I'm aware there are parts of time module deprecated in Python 3, but... I mean, deprecated doesn't mean it's gone, only that it will be gone some time in future. And as I use it as a debugging tool, I don't care too much for the moment. The code is not meant to stay in my projects.

Can you post an error message maybe? I'm too lazy to test that exact version now.

a_block

@mogh It looks as if my reply this morning somehow got lost. I basically asked, what errors you get exactly?

ferdinand

Hi Andreas,

no, your answer did not get lost, I just separated the threads, since this is basically a new question. Probably should have collected the two others posts too.

You will find the new thread here:

https://developers.maxon.net/forum/topic/12988/profiling-of-objects-in-python-3

Cheers,
Ferdinand

mogh

@a_block your code says myfunction2 and mysecondfunction .. easy fix no problem then I was accidently moving block around thats why I crossed my questions out the last problem was just the python 3 thing ->
which I got working as far as getting some strange numbers with it (se top post )

I have a feeling I upset you that was not my intend and I am sorry, If so please acept my appologie.
kind regards
mogh

a_block

Good catch, I fixed the post.

No, you didn't upset me. And I may have been a bit short, asking for actual errors.
For me the latter indeed is an important point. You will help yourself a lot, improving the information contained in a question. For example when talking about errors, but not providing any information or details about the actual errors. On your journey into C4D development and Python programming the Console is your friend and more often than not it already contains good information to solve an issue (and even if messages therein seem to make no sense, they may mean something to others). If I have been too harsh, I apologize, but also please try to view it from the other side. The people wanting to help, spend time for this. Having to ask the same questions again and again, just to find out what the actual question or problem is, is just time lost. For the one wanting to help simply lost and for the one asking it only takes longer to get the desired answer. On top assume, there may be multiple people wanting to help, so parts of this equation even multiply... so asking good questions, will help you reaching a solution in shorter amount of time and save time on side of those helping, which in turn will increase chances to get help at all.

I hope, you don't get me wrong. Really in this case it wasn't a big deal and it was probably my fault, to just insist on an error message without further words. Sorry for that. And the above, while addressing you, you should actually rather read as a hint to everybody asking questions on any forum.
In a nutshell, if you are having a problem, try to help other people help you.

And please keep asking questions. It's the best way to improve as a developer. Believe me, I know, what I am talking about. Looking at my code should be evidence enough, I asked way too few questions...

Cheers

ferdinand

Hi,

without further feedback, we will consider this thread as solved by tomorrow and flag it accordingly.

Cheers,
Ferdinand