← Back to team overview

c2c-oerpscenario team mailing list archive

[Bug 624114] Re: [5.0] Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)

 

** Changed in: openobject-addons
       Status: New => Triaged

** Changed in: openobject-server
       Status: New => Triaged

-- 
[5.0] Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
https://bugs.launchpad.net/bugs/624114
You received this bug notification because you are a member of C2C
OERPScenario, which is subscribed to the OpenERP Project Group.

Status in OpenObject Addons Modules: Triaged
Status in OpenObject Server: Triaged

Bug description:
The current implementation of the translation method "_()" seems to be extremely slow (about 1 second per call) on some circumstances, to the point that is the most time consuming method on some business process.

For example the confirming a sale order, with mrp_jit installed, will take about 40 seconds!
       - Of those, about 28.44 seconds are spent on 27 calls to _() on the _check_make_to_stock_product calculation. And most of that time is spent by Python, not Postgres.
       - The rest of the _check_make_to_stock_product calculation takes less than 5 total seconds on the 27 calls to it.


We profiled the action_ship_create method (of sale orders) with several methods, and the only conclusion is that the _()  method (from tools.translate import _) is too slow to be usable (though it is used everywhere on OpenERP!!!), while the translate() method (from tools.translate import translate)  proved to be hundreds of time faster.

Now we wonder:

    - Is this a a general problem?   (a problem with the current implementation of "_()" that relies on the inspect module)
    - Should _() be deprecated? (and use "translate()" instead, which is lots of times faster?).


Now the proof:


--- BASIC TIME.TIME() PROFILING -------------------------------------------------------------

To do a basic profiling, just edit the GettextAlias source code, and where it looks like this:

class GettextAlias(object):
    def __call__(self, source):
        try:
            frame = inspect.stack()[1][0]
        except:
            return source


Replace it with this to get the timings:

class GettextAlias(object):
    def __call__(self, source):
        import time
        start = time.time()
        try:
            frame = inspect.stack()[1][0]
        except:
            return source
        stop = time.time()
        print "GettextAlias time: ", stop-start


Confirming one sale order will call the _() method 27 times, these are the timings of those 27 calls:

GettextAlias time:  1.10414505005
GettextAlias time:  1.10945105553
GettextAlias time:  1.10807609558
GettextAlias time:  0.989851951599
GettextAlias time:  0.996656179428
GettextAlias time:  0.986680030823
GettextAlias time:  1.00202202797
GettextAlias time:  1.01647782326
GettextAlias time:  0.956711053848
GettextAlias time:  1.03200602531
GettextAlias time:  0.976341962814
GettextAlias time:  1.1115489006
GettextAlias time:  0.962368965149
GettextAlias time:  1.09971618652
GettextAlias time:  1.02273511887
GettextAlias time:  0.996299982071
GettextAlias time:  0.975975036621
GettextAlias time:  1.00379395485
GettextAlias time:  1.00497484207
GettextAlias time:  1.08288192749
GettextAlias time:  0.96357011795
GettextAlias time:  1.02459406853
GettextAlias time:  0.991461038589
GettextAlias time:  0.961183071136
GettextAlias time:  0.976219892502
GettextAlias time:  0.969728946686
GettextAlias time:  1.00834703445
GettextAlias time:  1.00862288475


--- PROFILING WITH PROFILE - STATS -------------------------------------------------------------

This is the trace of a profile (http://docs.python.org/library/profile.html) of the action_ship_create method of the sale orders, sorted by cumulative time. Notice how 68.9 seconds are spent on the translate.py module (marked with **** for easier look up): 


>>> 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 /usr/lib/python2.5/inspect.py:35(ismodule)
 12223925    7.889    0.000    7.889    0.000 {isinstance}



--- PROFILING WITH PROFILE - CALLERS -------------------------------------------------------------

Ok, now we now that a lot of time is spent on the __call__ method of GettextAlias (that has _ as an alias/shortcut). Now the question is: who is calling it and how many times? and the answer is: 


>>> stats.sort_stats("t").print_callers('__call__')
   Ordered by: internal time
   List reduced from 333 to 2 due to restriction <'__call__'>

Function                                                                                was called by...
                                                                                            ncalls  tottime  cumtime
/openerp-server/bin/tools/translate.py:128(__call__)  <-       1    0.000    2.816  /openerp-server/bin/addons/mrp/mrp.py:1018(action_move_assigned) 
                                                                                                27    0.001   66.094  /openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)  
/openerp-server/bin/tools/misc.py:941(__call__)       <-       1    0.000   78.911  <string>:1(<module>)


So, _() is called 27 times from _check_make_to_stock_product (taking 66 seconds), and one time from action_move_assigned (taking 2.8 seconds). The  _check_make_to_stock_product method looks like this:


    def _check_make_to_stock_product(self, cr, uid, procurement, context={}):
        ok = True
        if procurement.move_id:
            id = procurement.move_id.id
            if not (procurement.move_id.state in ('done','assigned','cancel')):
                ok = ok and self.pool.get('stock.move').action_assign(cr, uid, [id])
                cr.execute('select count(id) from stock_warehouse_orderpoint where product_id=%s', (procurement.product_id.id,))
                if not cr.fetchone()[0]:
                    cr.execute('update mrp_procurement set message=%s where id=%s', (_('from stock and no minimum orderpoint rule defined'), procurement.id))
        return ok


And the sentence that is taking one second per call is the single "_('from stock and no minimum orderpoint rule defined')".


--- PROFILING WITH TRANSLATE() INSTEAD OF _() -------------------------------------------------------------

If we replace this line (that uses _):
                    cr.execute('update mrp_procurement set message=%s where id=%s', (_('from stock and no minimum orderpoint rule defined'), procurement.id))
With this one (that uses translate):
                    cr.execute('update mrp_procurement set message=%s where id=%s', (translate(cr, None, 'code', context.get('lang'), 'from stock and no minimum orderpoint rule defined'), procurement.id))

Then the time (with profiling enabled) is reduced to 10.498 seconds (instead of 68 seconds)!!!:


>>> stats2.sort_stats("cumulative").print_stats()
Wed Aug 25 17:12:19 2010    prof2.dat

         900222 function calls (896164 primitive calls) in 10.494 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   10.498   10.498 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/tools/misc.py:941(__call__)
        1    0.001    0.001   10.498   10.498 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/sale/sale.py:570(action_ship_create_orig)
   303/13    0.011    0.000    9.967    0.767 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:44(process)
     37/4    0.001    0.000    9.951    2.488 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/workflow/wkf_service.py:75(trg_validate)
     37/4    0.001    0.000    9.946    2.487 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/instance.py:45(validate)
   220/12    0.011    0.000    9.939    0.828 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:148(_split_test)
    142/8    0.007    0.000    9.938    1.242 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:34(create)
    105/4    0.003    0.000    9.913    2.478 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:179(_join_test)
   243/28    0.004    0.000    9.718    0.347 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/wkf_expr.py:44(_eval_expr)
   208/24    0.017    0.000    9.715    0.405 {eval}
   181/24    0.003    0.000    9.695    0.404 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:167(<lambda>)
   142/20    0.002    0.000    9.501    0.475 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:86(_execute)
    72/10    0.001    0.000    9.457    0.946 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/wkf_expr.py:67(execute)
        3    0.000    0.000    9.165    3.055 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/cc_mrp_packing_bom/mrp_procurement.py:32(action_produce_assign_product)
        3    0.001    0.000    9.117    3.039 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:1041(action_produce_assign_product)
        3    0.011    0.004    8.288    2.763 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:630(action_confirm)
     8382    0.054    0.000    6.611    0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/sql_db.py:73(wrapper)
     4624    0.278    0.000    6.540    0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/sql_db.py:109(execute)
5114/5026    0.378    0.000    5.786    0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:154(__getitem__)
4866/4788    0.033    0.000    5.635    0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:237(__getattr__)
     4624    5.130    0.001    5.201    0.001 {method 'execute' of 'psycopg2._psycopg.cursor' objects}
1328/1140    0.382    0.000    5.000    0.004 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2221(read)
1409/1140    0.444    0.000    4.359    0.004 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2256(_read_flat)
      124    0.062    0.001    3.053    0.025 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2742(create)
  442/440    0.004    0.000    2.587    0.006 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/wkf_expr.py:70(check)
  131/125    0.025    0.000    1.499    0.012 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2506(write)
       30    0.003    0.000    1.428    0.048 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:991(action_confirm)
       27    0.001    0.000    1.341    0.050 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:939(check_make_to_stock)
    50/48    0.001    0.000    1.133    0.024 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/fields.py:654(get)
       40    0.002    0.000    1.112    0.028 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2943(_store_set_values)
       27    0.003    0.000    0.976    0.036 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)