Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Odoo Addons (MOVED TO GITHUB) |
Invalid
|
Undecided
|
Unassigned | ||
Odoo Server (MOVED TO GITHUB) |
Fix Released
|
Medium
|
OpenERP's Framework R&D |
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_
- The rest of the _check_
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(
def __call__(self, source):
try:
frame = inspect.
except:
return source
Replace it with this to get the timings:
class GettextAlias(
def __call__(self, source):
import time
start = time.time()
try:
frame = inspect.
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://
>>> stats.sort_
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:
1 0.000 0.000 78.911 78.911 /openerp-
1 0.001 0.001 78.911 78.911 /openerp-
303/13 0.010 0.000 78.396 6.030 /openerp-
37/4 0.001 0.000 78.372 19.593 /openerp-
142/8 0.007 0.000 78.369 9.796 /openerp-
220/12 0.010 0.000 78.367 6.531 /openerp-
37/4 0.001 0.000 78.367 19.592 /openerp-
105/4 0.003 0.000 78.336 19.584 /openerp-
243/28 0.004 0.000 78.143 2.791 /openerp-
208/24 0.016 0.000 78.140 3.256 {eval}
181/24 0.003 0.000 78.120 3.255 /openerp-
142/20 0.002 0.000 77.939 3.897 /openerp-
72/10 0.001 0.000 77.895 7.789 /openerp-
3 0.000 0.000 77.622 25.874 /openerp-
3 0.001 0.000 77.578 25.859 /openerp-
3 0.010 0.003 76.721 25.574 /openerp-
28 0.002 0.000 68.910 2.461 /openerp-
28 0.000 0.000 68.909 2.461 /usr/lib/
28 0.025 0.001 68.909 2.461 /usr/lib/
2887 0.057 0.000 68.881 0.024 /usr/lib/
442/440 0.004 0.000 68.565 0.156 /openerp-
27 0.001 0.000 67.363 2.495 /openerp-
27 0.003 0.000 67.023 2.482 /openerp-
6983 29.313 0.004 65.240 0.009 /usr/lib/
2887 0.049 0.000 47.001 0.016 /usr/lib/
5778/5774 0.177 0.000 43.856 0.008 /usr/lib/
12041505 18.983 0.000 26.680 0.000 /usr/lib/
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_
Ordered by: internal time
List reduced from 333 to 2 due to restriction <'__call__'>
Function was called by...
/openerp-
/openerp-
So, _() is called 27 times from _check_
def _check_
ok = True
if procurement.
id = procurement.
if not (procurement.
ok = ok and self.pool.
if not cr.fetchone()[0]:
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 _):
With this one (that uses translate):
Then the time (with profiling enabled) is reduced to 10.498 seconds (instead of 68 seconds)!!!:
>>> stats2.
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:
1 0.000 0.000 10.498 10.498 /srv/openerp/
1 0.001 0.001 10.498 10.498 /srv/openerp/
303/13 0.011 0.000 9.967 0.767 /home/omar/
37/4 0.001 0.000 9.951 2.488 /srv/openerp/
37/4 0.001 0.000 9.946 2.487 /home/omar/
220/12 0.011 0.000 9.939 0.828 /home/omar/
142/8 0.007 0.000 9.938 1.242 /home/omar/
105/4 0.003 0.000 9.913 2.478 /home/omar/
243/28 0.004 0.000 9.718 0.347 /home/omar/
208/24 0.017 0.000 9.715 0.405 {eval}
181/24 0.003 0.000 9.695 0.404 /srv/openerp/
142/20 0.002 0.000 9.501 0.475 /home/omar/
72/10 0.001 0.000 9.457 0.946 /home/omar/
3 0.000 0.000 9.165 3.055 /srv/openerp/
3 0.001 0.000 9.117 3.039 /srv/openerp/
3 0.011 0.004 8.288 2.763 /srv/openerp/
8382 0.054 0.000 6.611 0.001 /srv/openerp/
4624 0.278 0.000 6.540 0.001 /srv/openerp/
5114/5026 0.378 0.000 5.786 0.001 /srv/openerp/
4866/4788 0.033 0.000 5.635 0.001 /srv/openerp/
4624 5.130 0.001 5.201 0.001 {method 'execute' of 'psycopg2.
1328/1140 0.382 0.000 5.000 0.004 /srv/openerp/
1409/1140 0.444 0.000 4.359 0.004 /srv/openerp/
124 0.062 0.001 3.053 0.025 /srv/openerp/
442/440 0.004 0.000 2.587 0.006 /home/omar/
131/125 0.025 0.000 1.499 0.012 /srv/openerp/
30 0.003 0.000 1.428 0.048 /srv/openerp/
27 0.001 0.000 1.341 0.050 /srv/openerp/
50/48 0.001 0.000 1.133 0.024 /srv/openerp/
40 0.002 0.000 1.112 0.028 /srv/openerp/
27 0.003 0.000 0.976 0.036 /srv/openerp/
Related branches
Changed in openobject-addons: | |
status: | New → Triaged |
Changed in openobject-server: | |
status: | New → Triaged |
Changed in openobject-server: | |
status: | Confirmed → In Progress |
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?