Profiling Python Plugins



  • Maxime pointed me to Profiling Python Plugins.

    However I have problems implementing it.
    I added all the code: import cProfile, def profile(func), def PluginMessage(msg_type, data) and in the Area class

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

    Now I get the console message:

        @profile
    NameError: name 'profile' is not defined
    


  • 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



  • 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 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



  • 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



  • 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



  • @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.



  • @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



  • 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.



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



  • 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://plugincafe.maxon.net/topic/12988/profiling-of-objects-in-python-3

    Cheers,
    Ferdinand



  • @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



  • 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



  • Hi,

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

    Cheers,
    Ferdinand


Log in to reply