account - Legal Statements - General Ledger Performance issue [memory leak?]

Bug #514808 reported by Ferdinand
64
This bug affects 13 people
Affects Status Importance Assigned to Milestone
KDE OpenObject Client
New
Wishlist
Unassigned
Odoo Addons (MOVED TO GITHUB)
Fix Released
High
Jay Vora (Serpent Consulting Services)

Bug Description

The General Ledger report generation is too slow, leading to a "timeout" on the client side if there are too many records (1000 are enough), making it impossible to print the general ledger without using 'workarounds' (printjob module), and even then it uses all the CPU for too long making the server irresponsible.

***

Times reported by Ferdinand @ ChriCar:

   About 3700 account move lines for 5 years (very small company) it takes
      * 1:40 min to print General Ledger for all 5 years (60 pages 3700 records)
      * 0:30 min to print GL for period 200912 (6 pages, 120 records)

***

Times reported by Borja López Soilán:

   Tested on a Core2Duo 4400@2Ghz with 2GB RAM.
   Created a new demo database (service profile), and then used a script to create 10.000 account moves.

   It took about 35 minutes to generate the general ledger report (the client did timeout after 3 minutes):
      * 30m of CPU time consumed by Python
      * 1m30s of CPU time consumed by Postgres
                 Number of queries: 282,193 // Total query duration: 1m30s // Query peak: 845 queries/s at 2010-02-10 12:04:21

   Notes:
      * Some queries related with the RML translation (formatLang function), may be cached to save up to 30% of the Postgres time. For example, this single query is done 160.000 times, taking 38.9 seconds: "SELECT date_format","direction","code","name","thousands_sep","translatable","time_format","decimal_point","active","grouping",id FROM "res_lang" WHERE id IN (0) ORDER BY id;" (See the attached pgFouine file, for a detailed report of the queries performed by OpenERP while generating the general ledger)
      * 10.000 account moves take 30m, so everything with more than 1000 account moves would give a timeout on the client side.

Related branches

Revision history for this message
Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan) wrote : Re: [Bug 514808] [NEW] account - Legal Statements - General Ledger Performance issue

A Dissabte, 30 de gener de 2010, Ferdinand @ ChriCar va escriure:
> Public bug reported:
>
> about 3700 account move lines for 5 years (very small company)
> it takes
> * 1:40 min to print General Ledger for all 5 years (60 pages 3700 records)
> * 0:30 min to print GL for period 200912 (6 pages, 120 records)
>
> during this the terminal is blocked
>
> alternate solutions are needed !!!

printjob module in community works very well

>
> ** Affects: openobject-client-kde
> Importance: Undecided
> Status: New
>

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

Revision history for this message
Ferdinand (office-chricar) wrote : Re: account - Legal Statements - General Ledger Performance issue

Hmm
after some problems

 - needed to install pycups-1.9.22 on OpenSuSE 11.0 (later versions do not compile - and setting up CUPS on the OpenERP server (which is not hte print server) and adding some printers there manually (I know should work automatically)

 I can see printer and print jobs in the Printing Menu (IMHO should be in Administration?)
BUT all output is sent to the screen prior of beeing available in print jobs
 the menu for
* Settings can be configured globaly, per user, per report and per user and report.
is not available / not clear where to configure this

Revision history for this message
Ferdinand (office-chricar) wrote :

Found the settings in user, but "sent to printer" does not pop up the print job form (I assume it should)

Revision history for this message
Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan) wrote : Re: [Bug 514808] Re: account - Legal Statements - General Ledger Performance issue

A Diumenge, 31 de gener de 2010, Ferdinand @ ChriCar va escriure:
> Found the settings in user, but "sent to printer" does not pop up the
> print job form (I assume it should)
>

Possibly not the place to discuss this, but it does not open the dialog. You
can configure the printer to send the document to in the report, globally
(default printer) in the user form, etc...

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

Revision history for this message
Ferdinand (office-chricar) wrote : Re: account - Legal Statements - General Ledger Performance issue

thanks
I used the printjob from here
trunk-addons-community/printjob
r 178

this part of the code seems not to be called or does inherit - so IMHO it's not possible to define necesary settings
 <!-- printjob.report.xml.action -->
        <record model="ir.ui.view" id="printjob_report_xml_action_form">
                <field name="name">printjob.report.xml.action.form</field>
                <field name="model">printjob.report.xml.action</field>
                <field name="type">form</field>
                <field name="arch" type="xml">
                        <form string="Report Printing Actions">
....
may be I used a wrong branch - IMHO it's very confusing

Revision history for this message
Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan) wrote : Re: [Bug 514808] Re: account - Legal Statements - General Ledger Performance issue

A Diumenge, 31 de gener de 2010, Ferdinand @ ChriCar va escriure:
> thanks
> I used the printjob from here
> trunk-addons-community/printjob
> r 178
>
> this part of the code seems not to be called or does inherit - so IMHO it's
> not possible to define necesary settings <!-- printjob.report.xml.action
> -->
> <record model="ir.ui.view" id="printjob_report_xml_action_form">
> <field name="name">printjob.report.xml.action.form</field>
> <field name="model">printjob.report.xml.action</field>
> <field name="type">form</field>
> <field name="arch" type="xml">
> <form string="Report Printing Actions">
> ....
> may be I used a wrong branch - IMHO it's very confusing
>

That is the correct branch. I don't see anything wrong with that and the
module works properly for us.

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

Changed in openobject-client-kde:
importance: Undecided → Wishlist
Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote : Re: account - Legal Statements - General Ledger Performance issue
description: updated
Changed in openobject-addons:
status: New → Confirmed
assignee: nobody → Anup (Open ERP) (ach-openerp)
Revision history for this message
Ferdinand (office-chricar) wrote :

IMHO the printjob module should make it into the standard ASAP
regardless how fast the generation of a report might be - many should be printed directly without displaying it - and asking the user to print it manualy.
pls see also my suggestion
https://blueprints.launchpad.net/openobject-server/+spec/generalized-report-start-form

PS
 http://pgfouine.projects.postgresql.org/ seems to be a great tool -
IMHO should become part of the test suite

Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote :

Ferdinand, I think that we don't just need the printjob module.
Instead of a "OpenERP is working" dialog that ends up timing out, I think we need real progress dialogs, where the user can cancel the operation and he receives some progress information.

------

By the way though not perfect, this can be actually done on the 5.0 server. And I think it could be greatly improved on the 5.2 version with a small change.

It can be done like this:

On the wizard, instead one state/activity that does the job and then shows the output (and that may time out), we might use three activities:
  - start: For starting the job in the background.
  - in_progress: For progress reporting. With a "choice" type action, that may return this state (in progress) or the next state (done).
  - done: For showing the output.

On the wizard, the start action, just spawns a second thread to do the real job and returns (we go to the in progress state).
     The spawned thread updates does the hard work and, from time to time,
     updates some 'wizard_progress' variable on the form data dictionary
     (for example on each "for loop" or each several records processed).

The in_progress state/activity, just waits for some seconds (always less than the client timeout, like 10 seconds)
      to the previously spawned thread to end, checks whether the job is done
      (wizard_progress = 100, wizard_done = True)
      or it is in progress
      (wizard_progress = XX, wizard_done = False)
      and returns "done" or "in_progress" as the next state/activity.

The user would be shown a wizard form with:
      - Some label like "OpenERP is performing X. It may be take some time."
      - A progress widget (showing the wizard_progress value).
      - Some buttons like "Continue waiting", "Perform in background" or "Cancel".
          Continue waiting will just call the in_progress activity again
          (that would wait some seconds for the job to be done, and show the same dialog again if it still in progress);
          perform in background will end the wizard, but let the thread end his job;
          and cancel would tell the child thread to stop (and rollback).

Finally when the child thread does the job, the user would be shown the results in the same way as is it done now.

As I say, this currently works, and we have done it for some wizard (take a look here: http://bazaar.launchpad.net/~openerp-spain-team/openerp-spain/5.0/annotate/head%3A/l10n_es_extras/l10n_ES_aeat_mod347/wizard/wizard_calculate.py).

And can be easily improved!: Just let the auto_refresh tag be used on the wizard forms, so the progress form can refresh from time to time without the need of the user to push the "continue waiting" button and it's done! A real progress dialog :)

Changed in openobject-addons:
status: Confirmed → In Progress
Revision history for this message
xrg (xrg) wrote : Re: [Bug 514808] Re: account - Legal Statements - General Ledger Performance issue

On Monday 15 March 2010, you wrote:
> ** Changed in: openobject-addons

We can as well *optimize* more and reduce that time. Can you locate which
objects get queried repeatedly there?

Revision history for this message
Anup(SerpentCS) (anup-serpent) wrote : Re: account - Legal Statements - General Ledger Performance issue

Hello everyone,

   I have optimized the code and with this code the no of queries have decreased. I have attached a patch along with this. Kindly check and let us know.

Thanks

Revision history for this message
Anup(SerpentCS) (anup-serpent) wrote :
Revision history for this message
xrg (xrg) wrote : [Bug 514808] Re: account - Legal Statements - General Ledger Performance issue

Anup,
do you have a large dataset, that we could try against my optimized
openobject-server, as well?

In theory, I have almost made the browse(.., ids, fields_only=[...]) use as
little queries as the read() method..

If so, we could avoid re-writting all those reports/wizards that made bad
usage of browse() loops.

--
Say NO to spam and viruses. Stop using Microsoft Windows!

Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote : Re: account - Legal Statements - General Ledger Performance issue

Anup, I have just tested your patch, and I'm sorry to say the improvement is neligible :(

BUT, the good part is that I think I have an idea about what it is happening. Spoiler!: We have a memory leak.

These are the new times (same Core2Duo 4400@2Ghz computer and same database with 10.000 account moves from the previous unpatched test):

   It took about 32 minutes to generate the general ledger report (the client did timeout, "Printing aborted, too long delay" after 3 minutes):
      * 29m of CPU time consumed by Python
      * 1m23s of CPU time consumed by Postgres
                 Number of queries: 303,302 // Total query duration: 1m23s // Query peak: 1,176 queries/s at 2010-03-17 09:27:05

That means:
   Python time: 30m => 29m
   Number of queries: 282,193 => 303,302
   Total query duration: 1m30s => 1m23s
   Query peak: 845 queries/s => 1,176 queries/s

What is new, is that I also noticed that OpenERP is using 821MB of memory after running the general ledger report!!! (compare that to the 36MB that openerp uses when freshly started):

$ ps v -p 20743
  PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
20743 pts/2 Sl+ 29:48 19 1905 908786 843732 42.2 python2.6 ./bin/openerp-server.py

So I think that we have a big memory leak problem here, that is causing OpenERP to crawl...

summary: - account - Legal Statements - General Ledger Performance issue
+ account - Legal Statements - General Ledger Performance issue [memory
+ leak?]
Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote :

xgr, I'm attaching a small script that (connects to OpenERP via XML-RPC and) creates as many account moves as you want.
This is the one I made to do stress testing of the account_renumber module (from extra-addons).

Revision history for this message
Vinay Rana (OpenERP) (vra-openerp) wrote :

Hello Guys,

 Apply the more improved patch of General Ledger report and notify me?

Thanks.

Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote :

Times reported with the new patch applied (same Core2Duo 4400@2Ghz computer and same database with 10.000 account moves from the previous unpatched test):

  It took about 20 minutes to generate the general ledger report (the client did timeout, "Printing aborted, too long delay" after 3 minutes):
      * 18m of CPU time consumed by Python
      * 43s of CPU time consumed by Postgres
                 Number of queries: 112,239 // Total query duration: 43.4s // Query peak: 849 queries/s at 2010-04-05 10:57:04

That means:
   Python time: 30m => 18m
   Number of queries: 282,193 => 112,239
   Total query duration: 1m30s => 43.4s
   Query peak: 845 queries/s => 849 queries/s at 2010-04-05 10:57:04

Now OpenERP also seems to use less memory (367MB) after the report:
$ ps v -p 6576
 PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
 6576 pts/0 Sl+ 18:08 2 1905 435058 382476 19.1 python2.6 ./bin/openerp-server.py -r openerp -w openerp --db_host localhost --log-level=debug -d demo

It seems it is a good improvement.

Thought is still impossible to print the General Ledger on the test database (cause it timeouts after 3 minutes) :(

Revision history for this message
Ferdinand (office-chricar) wrote :

18m of Python time - on the server ???? meaning more or less 100% CPU usage ???? with normal priority ????

also the number of queries - and hence the load on the optimizer - seems to high

May be a solution is to build a distinct view which returns the columns to print explicitly (translated name instead of id...), which is called once per account.- this will reduce the number of queries to some 100 (1 per account) and probably the load of python too.

Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote :

Ferdinand: Yes, 18 of 100% usage of one CPU core (50% usage total as it doesn't use the second core) at normal priority.

Using a database with 10000 moves with 2 lines each.

It does about 2 SELECTs per move line (2x2000 => 40000 queries), plus 3 more related queries per move line (3 x 20000 => 60000 queries), plus some extra queries on translations and such (12000 more). But as I said, the 112000 queries are pretty quick: just about 45s!

The other 17 minutes (and >350mb of ram) are spent by the OpenERP python thread. It may be a problem with the RML engine itself: Maybe it does not scale well, or maybe it is lossing (not freeing) resources.

Revision history for this message
Ferdinand (office-chricar) wrote :

Borja:
\timing on
\o test.out
select * from table_with_107000 rows;

Time: 1880.773 ms ~ 2 seconds

I added 3 joins to fetch the name of id-columns
Time: 2046.530 ms

SQL time down from 43 to ~ 2 seconds (if all records are fetcehd at once) - so may be 10 seconds if the query must run for each account.

So IMHO it's a must to go this way for large tables and use the efficiency of SQL.
The statement must of course be tuned well and we had made the experience some years ago with ORACLE that it was necessary to store the parameters passed to the SQL statements in a database table (job_id, param_1,param_2....) - can give more details if needed.

Python and report engine will be used "only" to produce a nice layout.

It would be interesting if RML or report_openoffice perform better

Revision history for this message
Borja López Soilán (NeoPolus) (borjals) wrote :

Ferdinand:

I think you are right, doing most of the work at the SQL level, or having it precalculated, would be much faster. I wonder if, being used only to layout, the RML processing part would be faster too (I don't know why it is currently so slow and why it uses so much memory that is never freed).

Revision history for this message
xrg (xrg) wrote : Re: [Bug 514808] Re: account - Legal Statements - General Ledger Performance issue [memory leak?]

On Monday 05 April 2010, you wrote:
> The other 17 minutes (and >350mb of ram) are spent by the OpenERP python
> thread. It may be a problem with the RML engine itself: Maybe it does
> not scale well, or maybe it is lossing (not freeing) resources.

Allow me to barge in and remind you of another performance hog: frame
allocation. At languages such as Python, Java etc, where objects are
automatically allocated and freed (and especially when all vars. are objects),
there is a hidden cost of having each function call (aka stack frame). Also,
when a variable is introduced in the code, the memory manager needs to compute
its allocation. That is non-trivial. Freeing the stack after it's used
(assuming a garbage collector) is even more hard.

So, the trick is to keep highly repetitive tasks in "flat" code, where for-
loops are preferred and data is kept in local vars (not easy in python, where
even local vars contain volatile objects).

Revision history for this message
Joël Grand-Guillaume @ camptocamp (jgrandguillaume-c2c) wrote :

Hi,

Just consider also this related bug : https://bugs.launchpad.net/bugs/551630

Regards,

Revision history for this message
Ferdinand (office-chricar) wrote :

Joël, will OpenerpScenario be able to check reports too ?

Revision history for this message
Joël Grand-Guillaume @ camptocamp (jgrandguillaume-c2c) wrote :

Hi Ferdinand,

We are studying this :) ! I think this will be possible, but probably not for all kind of.

This means, we'll probably need to code one "plugin" per report type.

This will be studied at the end of this year. First we want to provide a better API for OERPScenario.

Thanks for your interest :)

Regards,

Joël

Changed in openobject-addons:
assignee: Anup (Open ERP) (ach-openerp) → Jay (Open ERP) (jvo-openerp)
Changed in openobject-addons:
milestone: none → 5.0.13
Revision history for this message
Jay Vora (Serpent Consulting Services) (jayvora) wrote :

Hello Experts,

We would like to have an opinion from you for this fix.

Patch is attached herewith.

Thanks.

Revision history for this message
Joël Grand-Guillaume @ camptocamp (jgrandguillaume-c2c) wrote :

@ Jay,

FYI : We @ Camptocamp will test all the report on the new v6.0, including this one. We will validate them all and once done, we'll backport them on v5.0 ion a module to have something perfect for all reports. This was discussed with Fabien some weeks ago. Quentin (qdp) told me they are progressing well... This means some result in mid-august.

Regards,

Revision history for this message
Jay Vora (Serpent Consulting Services) (jayvora) wrote :

Fixed by revision 2785 <email address hidden>.
Queries and suggestions invited.
Thanks.

Changed in openobject-addons:
importance: Undecided → High
status: In Progress → Fix Released
Revision history for this message
Fabrice Actergal @ Taktik (fa-taktik) wrote :

Hi,

We have the same problem : we are unable to print out this report.

Here are the server details:

Processor : Intel(R) Xeon(R) CPU E31270 @ 3.40GHz
Memory : 16Gb
Swap : 16Gb

OpenERP instance :

account.move : over 13.000 and daily increase
account.move.line : overs 68.000 and daily increase

After more than one hour, the report.account.general.ledger (or report.account.general.ledger_landscape) does not print out. The OpenERP process takes 115% of CPU.
And more important : the overall performances of OpenERP are impaired : the other users are freezed in their work!

Revision history for this message
ERPSystems.ro (erpsystems) wrote : Re: [Openerp-expert-accounting] [Bug 514808] Re: account - Legal Statements - General Ledger Performance issue [memory leak?]
Download full text (3.6 KiB)

Hi

  for us it's working for about 31000 account moves and 93000 account move
lines in about one minute and a half...

  there's nothing in the log?...everything is ok?

On Thu, Jul 26, 2012 at 12:12 PM, Fabrice Actergal @ Taktik <
<email address hidden>> wrote:

> Hi,
>
> We have the same problem : we are unable to print out this report.
>
> Here are the server details:
>
> Processor : Intel(R) Xeon(R) CPU E31270 @ 3.40GHz
> Memory : 16Gb
> Swap : 16Gb
>
> OpenERP instance :
>
> account.move : over 13.000 and daily increase
> account.move.line : overs 68.000 and daily increase
>
> After more than one hour, the report.account.general.ledger (or
> report.account.general.ledger_landscape) does not print out. The OpenERP
> process takes 115% of CPU.
> And more important : the overall performances of OpenERP are impaired :
> the other users are freezed in their work!
>
> --
> You received this bug notification because you are a member of OpenERP
> Accounting Experts, which is subscribed to the bug report.
> https://bugs.launchpad.net/bugs/514808
>
> Title:
> account - Legal Statements - General Ledger Performance issue [memory
> leak?]
>
> Status in OpenERP Addons (modules):
> Fix Released
> Status in Qt/KDE OpenObject Client:
> New
>
> Bug description:
> The General Ledger report generation is too slow, leading to a
> "timeout" on the client side if there are too many records (1000 are
> enough), making it impossible to print the general ledger without
> using 'workarounds' (printjob module), and even then it uses all the
> CPU for too long making the server irresponsible.
>
> ***
>
> Times reported by Ferdinand @ ChriCar:
>
> About 3700 account move lines for 5 years (very small company) it
> takes
> * 1:40 min to print General Ledger for all 5 years (60 pages 3700
> records)
> * 0:30 min to print GL for period 200912 (6 pages, 120 records)
>
> ***
>
> Times reported by Borja López Soilán:
>
> Tested on a Core2Duo 4400@2Ghz with 2GB RAM.
> Created a new demo database (service profile), and then used a script
> to create 10.000 account moves.
>
> It took about 35 minutes to generate the general ledger report (the
> client did timeout after 3 minutes):
> * 30m of CPU time consumed by Python
> * 1m30s of CPU time consumed by Postgres
> Number of queries: 282,193 // Total query duration:
> 1m30s // Query peak: 845 queries/s at 2010-02-10 12:04:21
>
> Notes:
> * Some queries related with the RML translation (formatLang
> function), may be cached to save up to 30% of the Postgres time. For
> example, this single query is done 160.000 times, taking 38.9 seconds:
> "SELECT
> date_format","direction","code","name","thousands_sep","translatable","time_format","decimal_point","active","grouping",id
> FROM "res_lang" WHERE id IN (0) ORDER BY id;" (See the attached pgFouine
> file, for a detailed report of the queries performed by OpenERP while
> generating the general ledger)
> * 10.000 account moves take 30m, so everything with more than 1000
> account moves would give a timeout on the client side.
>
> To manage notifications abou...

Read more...

Revision history for this message
Ferdinand (office-chricar) wrote :

may be you want to check much faster and feature rich webkit based reports from here
https://code.launchpad.net/~c2c/c2c-financial-addons/6.1
or
https://code.launchpad.net/~c2c/c2c-financial-addons/6.0

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.