Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)

Borja, that is pretty strange. These are the times it takes to calculate a couple of translations (with SQL query included) in my system:

0.00142478942871 seconds
0.00103211402893 seconds

Maybe inspect is exponentially slower when the number of calls in the backtrace increases (I just tested with a simple raise osv.except_osv I had in hand). Can you try with such a simple case?

Albert, stack() seems to be O(n) with n being the number stack items. See this example:

----------------------------
$ cat test-python-inspect.py

import inspect
import time

def test(n, maxn):
    start = time.time()
    frame = inspect.stack()[1][0]
    stop = time.time()
    if n % 100 == 0:
        print "Test time (n=%s): " % n, stop-start
    if n <= maxn:
        return test(n+1, maxn)
    else:
        return n

test(1, 500)

$ python test-python-inspect.py
Test time (n=100): 0.0100071430206
Test time (n=200): 0.0189220905304
Test time (n=300): 0.0286138057709
Test time (n=400): 0.0375599861145
Test time (n=500): 0.0474269390106

----------------------------

But anyway, on my simple example it takes less than 0.05 seconds per call in the 500th recursive call, so I must be missing something: why does it takes so much when called from OpenERP? threading stalls or something?

By the way, we just inspected the stack ourselves and found than when the _() method is called, the stack length is greater than 100. Yep, more than 100 calls!

We found that most of the stack items are related to four bin/workflow/workitem.py methods: create, process, _split_test and _join_test that appear again and again in a kind of recursive way.

A Dijous, 26 d'agost de 2010, Borja López Soilán (Pexego) va escriure:
> But anyway, on my simple example it takes less than 0.05 seconds per
> call in the 500th recursive call, so I must be missing something: why
> does it takes so much when called from OpenERP? threading stalls or
> something?

In my case I tried it with OpenERP and it was fast, so it must be something
specific to your test case...

--
Albert Cervera i Areny
http://www.NaN-tic.com
OpenERP Partners
Mòbil: +34 669 40 40 18

http://twitter.com/albertnan
http://albert-nan.blogspot.com

I don't now if it is specific to MRP with JIT, but I've been printing the times of the inspect.stack() call on a normal OpenERP usage and it seems that the times are not deterministic at all:

GettextAlias time: 0.0242729187012
GettextAlias time: 0.0695328712463
GettextAlias time: 0.0346441268921
GettextAlias time: 0.108239173889
GettextAlias time: 0.0100328922272
GettextAlias time: 0.0330319404602
GettextAlias time: 0.0410368442535
GettextAlias time: 0.00120401382446
GettextAlias time: 0.00120115280151
GettextAlias time: 0.0012469291687

The average on those ten calls is 0.032; but some of them took 0.001 while others took 0.1 (100 times more!).

I'm linking this bug to the addons too, just in case it has something to do with how the MRP works, and so somebody at least replaces the _() call with a translate() call in that single point...

By the way, maybe we should provide an option to override the whole inspection part.

I mean, maybe we could allow an optional parameter for _( ) with the language to use, something like: _("Translate this", 'es_ES')

That would allow to workaround this kind of performance problems with small changes on our code. Instead of:

      cr.execute('update mrp_procurement set message=%s where id=%s', (_('from stock and no minimum orderpoint rule defined'), procurement.id))

We would use:

      cr.execute('update mrp_procurement set message=%s where id=%s', (_('from stock and no minimum orderpoint rule defined', context.get('lang')), procurement.id))

It would be much quicker, and it would be clean!

In our modules, we could use a 5-line replacement like this:
    def my_method(self, cr, uid, ids, context=None):
        def _(source):
            lang = (context or {}).get('lang', False)
            if not lang:
                return source
            return translate(cr, False, 'code', lang, source) or source

A Dilluns, 30 d'agost de 2010, Dukai Gábor va escriure:
> In our modules, we could use a 5-line replacement like this:
> def my_method(self, cr, uid, ids, context=None):
> def _(source):
> lang = (context or {}).get('lang', False)
> if not lang:
> return source
> return translate(cr, False, 'code', lang, source) or source

Which sounds terrible. I think that adding an optional parameter to standard
_() like Borja said, is much much better.

>
> >>> stats.sort_stats("cumulative").print_stats()
>
> Wed Aug 25 16:53:45 2010 prof.dat
>
> 37130567 function calls (37126505 primitive calls) in 78.907 CPU
> seconds
>
> Ordered by: cumulative time
>
> ncalls tottime percall cumtime percall filename:lineno(function)
> 1 0.000 0.000 78.911 78.911
> /openerp-server/bin/tools/misc.py:941(__call__) 1 0.001 0.001
> 78.911 78.911
> /openerp-server/bin/addons/sale/sale.py:570(action_ship_create_orig)
> 303/13 0.010 0.000 78.396 6.030
> /openerp-server/bin/workflow/workitem.py:44(process) 37/4 0.001
> 0.000 78.372 19.593
> /openerp-server/bin/workflow/wkf_service.py:75(trg_validate) 142/8
> 0.007 0.000 78.369 9.796
> /openerp-server/bin/workflow/workitem.py:34(create) 220/12 0.010
> 0.000 78.367 6.531
> /openerp-server/bin/workflow/workitem.py:148(_split_test) 37/4 0.001
> 0.000 78.367 19.592
> /openerp-server/bin/workflow/instance.py:45(validate) 105/4 0.003
> 0.000 78.336 19.584
> /openerp-server/bin/workflow/workitem.py:179(_join_test) 243/28 0.004
> 0.000 78.143 2.791
> /openerp-server/bin/workflow/wkf_expr.py:44(_eval_expr) 208/24 0.016
> 0.000 78.140 3.256 {eval}
> 181/24 0.003 0.000 78.120 3.255
> /openerp-server/bin/osv/orm.py:167(<lambda>) 142/20 0.002 0.000
> 77.939 3.897 /openerp-server/bin/workflow/workitem.py:86(_execute)
> 72/10 0.001 0.000 77.895 7.789
> /openerp-server/bin/workflow/wkf_expr.py:67(execute) 3 0.000 0.000
> 77.622 25.874
> /openerp-server/bin/addons/cc_mrp_packing_bom/mrp_procurement.py:32(action
> _produce_assign_product) 3 0.001 0.000 77.578 25.859
> /openerp-server/bin/addons/mrp/mrp.py:1041(action_produce_assign_product)
> 3 0.010 0.003 76.721 25.574
> /openerp-server/bin/addons/mrp/mrp.py:630(action_confirm) 28 0.002
> 0.000 68.910 2.461
> /openerp-server/bin/tools/translate.py:128(__call__)
> *********************************** 28 0.000 0.000 68.909 2.461
> /usr/lib/python2.5/inspect.py:882(stack) 28 0.025 0.001 68.909
> 2.461 /usr/lib/python2.5/inspect.py:858(getouterframes) 2887 0.057
> 0.000 68.881 0.024 /usr/lib/python2.5/inspect.py:820(getframeinfo)
> 442/440 0.004 0.000 68.565 0.156
> /openerp-server/bin/workflow/wkf_expr.py:70(check) 27 0.001 0.000
> 67.363 2.495
> /openerp-server/bin/addons/mrp/mrp.py:939(check_make_to_stock) 27 0.003
> 0.000 67.023 2.482
> /openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)
> 6983 29.313 0.004 65.240 0.009
...

On Monday 30 August 2010, you wrote:
> By the way, maybe we should provide an option to override the whole
> inspection part.
>
> I mean, maybe we could allow an optional parameter for _( ) with the
> language to use, something like: _("Translate this", 'es_ES')

I would vote against that. The _("...") should really behave the gettext
way, just localize the string. If we needed some other fn, yes, that
would be the translate(), with more arguments.

Please, try that patch I have written today, and see if it performs
any better..

http://git.hellug.gr/?p=xrg/openobject-server;a=commitdiff;h=8817593e29d00dd672d552

Borja, did you try xrg's patch? It seems it may go to the right direction.

Thanks xrg, we haven't tested the patch yet (holidays...), but I've taken a look to the diff file.

As Albert says, your patch might make a difference: As you detected, "frame = inspect.stack()[1][0]" is getting the full stack (with all the variables, parameters and such) into a list, just to discard all the info and get only the second element (the parent frame). So the performance of that like is "O(n)" depending on the stack size (n frames inspected), while your patch would be just "O(2)" (just two frames inspected, always).

We would test it, I wonder how much it may improve...

Closing for addons, as this really should be handled on the server side

Basically we need to stop using 'inspect' just to access the last frames, because it is really only meant for debugging.
Obviously it will be O(n) according to the size of the stack, but it will also hit the disk to lookup line numbers in source code!

This refactoring is pending and will be merged before RC2.

Thanks for reporting!

BTW Borja, great job with the profiling and analysis, muchas gracias :-)

This should be vastly improved after server revision 3114 <email address hidden> in trunk.

The call to inspect.stack() has been removed, the heuristics to locate the language and cursor have been improved, and we now even attempt to use the cache from ir.translation if available, by calling _get_source instead of hitting the DB every time.

Profiling shows a nice difference, for example during a simple call to action_ship_create() with mrp_jit (as in your example), I see this difference:

Revision 3112: 4.17s, with __call__ (translate.py:183), 11 calls, cumulative time: 2.92918s (70.19% total time)
Revision 3114: 1.07s, with __call__ (translate.py:200), 11 calls, cumulative time: 0.00371s (00.36% total time)

Notice the difference in the percentage of the total time used by _( ), not just the decreased overall duration.

Wow, it looks like a great improvement, good job Olivier :)

By the way, thanks also to xrg and everyone else that contributed ;)

A Dijous, 16 de desembre de 2010, Borja López Soilán va escriure:
> By the way, thanks also to xrg and everyone else that contributed ;)

+1

By the way, I'd be nice if _() was exported to globals and we didn't need to
import it in each python file!

>
> >>> stats.sort_stats("cumulative").print_stats()
>
> Wed Aug 25 16:53:45 2010 prof.dat
>
> 37130567 function calls (37126505 primitive calls) in 78.907 CPU
> seconds
>
> Ordered by: cumulative time
>
> ncalls tottime percall cumtime percall filename:lineno(function)
> 1 0.000 0.000 78.911 78.911
> /openerp-server/bin/tools/misc.py:941(__call__) 1 0.001 0.001
> 78.911 78.911
> /openerp-server/bin/addons/sale/sale.py:570(action_ship_create_orig)
> 303/13 0.010 0.000 78.396 6.030
> /openerp-server/bin/workflow/workitem.py:44(process) 37/4 0.001
> 0.000 78.372 19.593
> /openerp-server/bin/workflow/wkf_service.py:75(trg_validate) 142/8
> 0.007 0.000 78.369 9.796
> /openerp-server/bin/workflow/workitem.py:34(create) 220/12 0.010
> 0.000 78.367 6.531
> /openerp-server/bin/workflow/workitem.py:148(_split_test) 37/4 0.001
> 0.000 78.367 19.592
> /openerp-server/bin/workflow/instance.py:45(validate) 105/4 0.003
> 0.000 78.336 19.584
> /openerp-server/bin/workflow/workitem.py:179(_join_test) 243/28 0.004
> 0.000 78.143 2.791
> /openerp-server/bin/workflow/wkf_expr.py:44(_eval_expr) 208/24 0.016
> 0.000 78.140 3.256 {eval}
> 181/24 0.003 0.000 78.120 3.255
> /openerp-server/bin/osv/orm.py:167(<lambda>) 142/20 0.002 0.000
> 77.939 3.897 /openerp-server/bin/workflow/workitem.py:86(_execute)
> 72/10 0.001 0.000 77.895 7.789
> /openerp-server/bin/workflow/wkf_expr.py:67(execute) 3 0.000 0.000
> 77.622 25.874
> /openerp-server/bin/addons/cc_mrp_packing_bom/mrp_procurement.py:32(action
> _produce_assign_product) 3 0.001 0.000 77.578 25.859
> /openerp-server/bin/addons/mrp/mrp.py:1041(action_produce_assign_product)
> 3 0.010 0.003 76.721 25.574
> /openerp-server/bin/addons/mrp/mrp.py:630(action_confirm) 28 0.002
> 0.000 68.910 2.461
> /openerp-server/bin/tools/translate.py:128(__call__)
> *********************************** 28 0.000 0.000 68.909 2.461
> /usr/lib/python2.5/inspect.py:882(stack) 28 0.025 0.001 68.909
> 2.461 /usr/lib/python2.5/inspect.py:858(getouterframes) 2887 0.057
> 0.000 68.881 0.024 /usr/lib/python2.5/inspect.py:820(getframeinfo)
> 442/440 0.004 0.000 68.565 0.156
> /openerp-server/bin/workflow/wkf_expr.py:70(check) 27 0.001 0.000
> 67.363 2.495
> /openerp-server/bin/addons/mrp/mrp.py:939(check_make_to_stock) 27 0.003
> 0.000 67.023 2.482
> /openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)
> 6983 29.313 0.004 65.240 0.009
> /usr/lib/python2.5/inspect.py:408(getmodule) 2887 0.049 0.000
> 47.001 0.016 /usr/lib/python2.5/inspect.py:454(findsource) 5778/5774
> 0.177 0.000 43.856 0.008
> /usr/lib/python2.5/inspect.py:381(getsourcefile) 12041505 18.983
> ...

albert, I think you mean builtins (globals is module-global scope so it would not help much if any). But this should be in a different ticket.

A Dijous, 16 de desembre de 2010, Xavier (Open ERP) va escriure:
> albert, I think you mean builtins (globals is module-global scope so it
> would not help much if any). But this should be in a different ticket.

That's it :)

>
> >>> stats.sort_stats("cumulative").print_stats()
>
> Wed Aug 25 16:53:45 2010 prof.dat
>
> 37130567 function calls (37126505 primitive calls) in 78.907 CPU
> seconds
>
> Ordered by: cumulative time
>
> ncalls tottime percall cumtime percall filename:lineno(function)
> 1 0.000 0.000 78.911 78.911
> /openerp-server/bin/tools/misc.py:941(__call__) 1 0.001 0.001
> 78.911 78.911
> /openerp-server/bin/addons/sale/sale.py:570(action_ship_create_orig)
> 303/13 0.010 0.000 78.396 6.030
> /openerp-server/bin/workflow/workitem.py:44(process) 37/4 0.001
> 0.000 78.372 19.593
> /openerp-server/bin/workflow/wkf_service.py:75(trg_validate) 142/8
> 0.007 0.000 78.369 9.796
> /openerp-server/bin/workflow/workitem.py:34(create) 220/12 0.010
> 0.000 78.367 6.531
> /openerp-server/bin/workflow/workitem.py:148(_split_test) 37/4 0.001
> 0.000 78.367 19.592
> /openerp-server/bin/workflow/instance.py:45(validate) 105/4 0.003
> 0.000 78.336 19.584
> /openerp-server/bin/workflow/workitem.py:179(_join_test) 243/28 0.004
> 0.000 78.143 2.791
> /openerp-server/bin/workflow/wkf_expr.py:44(_eval_expr) 208/24 0.016
> 0.000 78.140 3.256 {eval}
> 181/24 0.003 0.000 78.120 3.255
> /openerp-server/bin/osv/orm.py:167(<lambda>) 142/20 0.002 0.000
> 77.939 3.897 /openerp-server/bin/workflow/workitem.py:86(_execute)
> 72/10 0.001 0.000 77.895 7.789
> /openerp-server/bin/workflow/wkf_expr.py:67(execute) 3 0.000 0.000
> 77.622 25.874
> /openerp-server/bin/addons/cc_mrp_packing_bom/mrp_procurement.py:32(action
> _produce_assign_product) 3 0.001 0.000 77.578 25.859
> /openerp-server/bin/addons/mrp/mrp.py:1041(action_produce_assign_product)
> 3 0.010 0.003 76.721 25.574
> /openerp-server/bin/addons/mrp/mrp.py:630(action_confirm) 28 0.002
> 0.000 68.910 2.461
> /openerp-server/bin/tools/translate.py:128(__call__)
> *********************************** 28 0.000 0.000 68.909 2.461
> /usr/lib/python2.5/inspect.py:882(stack) 28 0.025 0.001 68.909
> 2.461 /usr/lib/python2.5/inspect.py:858(getouterframes) 2887 0.057
> 0.000 68.881 0.024 /usr/lib/python2.5/inspect.py:820(getframeinfo)
> 442/440 0.004 0.000 68.565 0.156
> /openerp-server/bin/workflow/wkf_expr.py:70(check) 27 0.001 0.000
> 67.363 2.495
> /openerp-server/bin/addons/mrp/mrp.py:939(check_make_to_stock) 27 0.003
> 0.000 67.023 2.482
> /openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)
> 6983 29.313 0.004 65.240 0.009
> /usr/lib/python2.5/inspect.py:408(getmodule) 2887 0.049 0.000
> 47.001 0.016 /usr/lib/python2.5/inspect.py:454(findsource) 5778/5774
> 0.177 0.000 43.856 0.008
> /usr/lib/python2.5/inspect.py:381(getsourcefile) 12041505 18.983
> 0.000 26.680 0.000 /u...