This question has been flagged
6 Replies
8388 Views
performanceupgradeopenerpslowodoo
Avatar
Christoph

We migrated one OpenERP v7 instance to Odoo v8 via OpenUpgrade. Before the upgrade the system was fast enough. After the upgrade the system is very slow if more than one user (10-20) accessing the system. Maybe you can help me to increase the performance.

The current setup:

  • four vservers in the cloud (provider: Strato)

    • one vserver hosts the PostgreSQL database system

    • two vservers provide the odoo v8 instances

    • one vserver is a "loadbalancer" (nginx) which forwards the traffic to the odoo vservers

Nearly all users access the same odoo instance because the loadbalancer is for the fallback if one odoo instance is not reachable (we use the ip hash algorithm).

Stats (in peak times):

vserver      | memory usage       | Disk I/O utilization   | load avg    | Network I/O
--------------------------------------------------------------------------------------
loadbalancer | 179 / 512MB        | < 2%                   | < 0.1       | 0.4 MB/s
odoo 1       | 0.6 / 2GB          | < 2%                   | < 0.8       | 0.6 MB/s
odoo 2       | 1   / 2 GB         | < 2%                   | < 0.4       | 0.8 MB/s
postgres     | 1.1 / 4 GB         | < 6%                   | < 0.3       | 0.8 MB/s

CPU usage is okay (see load)


Database:

  • I updated PostgreSQL from 9.1 to 9.4.

    • I see no difference in the speed (maybe a bit faster).

  • I increased some parameters like shared_buffers (=1GB).

    • The cache hits increased but no performance changes (maybe a bit faster).


Some postgresql stats (average in peak times):

  • Transactions:

    • yesterday: 250 transactions/s

    • today: 134 transactions/s

  • Reads: 3520 tuples/s

  • Updates: 2 tuples/s

  • Inserts: 1.6 tuples/s

  • Deletes: 0.9 tuples/s

  • Locks:

    • Access Share: 163

    • Row Exclusive: 30

Now some information about our tables:

SELECT schemaname || '.' || relname as table, n_live_tup as num_rows FROM pg_stat_user_tables ORDER BY n_live_tup DESC LIMIT 10;

                     table                      | num_rows 
------------------------------------------------+----------
 public.mail_message                            |   290485
 public.mail_followers_mail_message_subtype_rel |    99410
 public.mail_followers                          |    83080
 public.account_move_line                       |    70889
 public.ir_model_data                           |    57953
 public.res_partner                             |    51304
 public.wkf_workitem                            |    42916
 public.mail_notification                       |    41701
 public.wkf_instance                            |    40854
 public.res_partner_res_partner_category_rel    |    29752
(10 rows) 


SELECT schemaname || '.' || relname as table, heap_blks_read as disk_reads, heap_blks_hit as cache_reads, heap_blks_read + heap_blks_hit as total_reads FROM pg_statio_user_tables ORDER BY heap_blks_read + heap_blks_hit DESC LIMIT 15;
            table            | disk_reads | cache_reads | total_reads 
-----------------------------+------------+-------------+-------------
 public.purchase_order       |       4238 |    32316190 |    32320428
 public.res_partner          |      10170 |    21109387 |    21119557
 public.account_invoice      |       2594 |    20076555 |    20079149
 public.mail_message         |      50876 |    19058003 |    19108879
 public.account_move_line    |       7769 |     3946367 |     3954136
 public.mail_notification    |        924 |     2652774 |     2653698
 public.res_company          |          3 |     1573888 |     1573891
 public.account_move         |       3082 |     1482233 |     1485315
 public.res_users            |         19 |     1257049 |     1257068
 public.sale_order           |        690 |      981857 |      982547
 public.product_template     |        767 |      916337 |      917104
 public.account_account      |        251 |      857989 |      858240
 public.crm_lead             |       2316 |      498267 |      500583
 public.product_product      |        492 |      454269 |      454761
 public.res_groups_users_rel |         22 |      408204 |      408226
(15 rows) 


SELECT nspname || '.' || relname AS "table", pg_size_pretty(pg_total_relation_size(C.oid)) AS "total_size" FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname NOT IN ('pg_catalog', 'information_schema') AND C.relkind <> 'i' and nspname !~ '^pg_toast' ORDER BY pg_total_relation_size(C.oid) DESC LIMIT 10;
                     table                      | total_size 
------------------------------------------------+------------
 public.ir_attachment                           | 1333 MB
 public.mail_message                            | 225 MB
 public.res_partner                             | 134 MB
 public.account_move_line                       | 46 MB
 public.ir_model_data                           | 26 MB
 public.mail_followers                          | 21 MB
 public.purchase_order                          | 13 MB
 public.ir_translation                          | 12 MB
 public.mail_followers_mail_message_subtype_rel | 12 MB
 public.mail_notification                       | 12 MB
(10 rows)


sorted by lines_read_total: 

SELECT schemaname || '.' || relname as table, seq_scan, idx_scan, idx_tup_fetch + seq_tup_read as lines_read_total, n_tup_ins as num_insert, n_tup_upd as num_update, n_tup_del as num_delete FROM pg_stat_user_tables ORDER BY lines_read_total DESC LIMIT 10;
          table           | seq_scan | idx_scan | lines_read_total | num_insert | num_update | num_delete 
--------------------------+----------+----------+------------------+------------+------------+------------
 public.account_invoice   |    39389 |   219049 |        440230366 |      14666 |       6323 |          1
 public.res_partner       |     4801 |  2716984 |        255995782 |      51312 |       4819 |          1
 public.purchase_order    |    28235 |    98654 |        178473412 |       6479 |       3919 |          0
 public.account_move      |    12569 |    97578 |         61072327 |      28558 |       2930 |          0
 public.account_move_line |     4472 |   502235 |         51382939 |      71588 |      14476 |          1
 public.mail_message      |     1704 |  1403914 |         37891051 |     290921 |        286 |          4
 public.product_product   |     2777 |   123512 |         18006526 |       6634 |       1005 |          0
 public.account_account   |     8967 |   146644 |         16325954 |       1858 |       5384 |          0
 public.payment_line      |     5854 |    38098 |         14298565 |       2499 |        204 |          0
 public.res_users         |   347243 |    11889 |         13258621 |         45 |        238 |          0
(10 rows)


sorted by seq_scan:

SELECT schemaname || '.' || relname as table, seq_scan, idx_scan, idx_tup_fetch + seq_tup_read as lines_read_total, n_tup_ins as num_insert, n_tup_upd as num_update, n_tup_del as num_delete FROM pg_stat_user_tables ORDER BY seq_scan DESC LIMIT 10;
            table             | seq_scan | idx_scan | lines_read_total | num_insert | num_update | num_delete 
------------------------------+----------+----------+------------------+------------+------------+------------
 public.res_company           |  2016508 |        0 |          1584118 |          1 |          0 |          0
 public.res_users             |   347049 |    11889 |         13250453 |         45 |        238 |          0
 public.res_groups            |   114201 |   124449 |          4055919 |         57 |          0 |          0
 public.multi_company_default |    83315 |        0 |                0 |          0 |          0 |          0
 public.res_currency          |    65770 |        0 |         11125874 |        176 |          0 |          0
 public.ir_config_parameter   |    61542 |        0 |           676896 |         11 |          7 |          0
 public.account_tax           |    49250 |     2380 |           997255 |         21 |          0 |          0
 public.crm_case_section      |    44407 |      594 |           170207 |          4 |          0 |          0
 public.wkf_activity          |    43521 |    42293 |          1692101 |         63 |          0 |          0
 public.account_journal       |    42337 |       20 |           547950 |         22 |          0 |          1
(10 rows)


I activated the debug_rpc log - here is an extract of the last messages:

015-04-30 10:35:29,497 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: crm.case.section name_search: time:0.025s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:29,958 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.invoice search_read: time:0.224s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:30,302 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: crm.case.categ name_get: time:0.093s mem: 655460k -> 655460k (diff: 0k)
2015-04-30 10:35:30,865 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: res.partner name_get: time:0.658s mem: 655460k -> 655460k (diff: 0k)
2015-04-30 10:35:30,920 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: sale.order.line default_get: time:0.384s mem: 655460k -> 655460k (diff: 0k)
2015-04-30 10:35:31,110 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.invoice.line read: time:0.889s mem: 655460k -> 655460k (diff: 0k)
2015-04-30 10:35:31,391 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.uom name_get: time:0.138s mem: 663656k -> 680048k (diff: 16392k)
2015-04-30 10:35:31,525 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.tax name_get: time:0.131s mem: 680048k -> 680048k (diff: 0k)
2015-04-30 10:35:31,700 7225 DEBUG anydatabase openerp.http.rpc.request: notify: None None: time:0.391s mem: 671852k -> 680048k (diff: 8196k)
2015-04-30 10:35:31,801 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.invoice.tax read: time:0.332s mem: 680048k -> 680048k (diff: 0k)
2015-04-30 10:35:32,187 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.invoice.line fields_view_get: time:0.764s mem: 680048k -> 680048k (diff: 0k)
2015-04-30 10:35:32,309 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.invoice read_followers_data: time:2.091s mem: 655460k -> 680048k (diff: 24588k)
2015-04-30 10:35:32,627 7225 DEBUG anydatabase openerp.http.rpc.request: notify: None None: time:0.228s mem: 680048k -> 680048k (diff: 0k)
2015-04-30 10:35:32,671 7225 DEBUG anydatabase openerp.http.rpc.request: notify: None None: time:0.236s mem: 680048k -> 680048k (diff: 0k)
2015-04-30 10:35:33,077 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: sale.order.line onchange: time:1.905s mem: 663660k -> 680048k (diff: 16388k)
2015-04-30 10:35:33,135 7225 DEBUG anydatabase openerp.http.rpc.request: search_read: ir.attachment None: time:1.058s mem: 680048k -> 680048k (diff: 0k)
2015-04-30 10:35:33,334 7225 DEBUG anydatabase openerp.http.rpc.request: notify: None None: time:0.206s mem: 680048k -> 671852k (diff: -8196k)
2015-04-30 10:35:33,340 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.invoice message_get_subscription_data: time:0.680s mem: 680048k -> 671852k (diff: -8196k)
2015-04-30 10:35:33,430 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: mail.message message_read: time:3.216s mem: 655460k -> 663656k (diff: 8196k)
2015-04-30 10:35:33,453 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: crm.case.section name_search: time:0.049s mem: 663656k -> 655460k (diff: -8196k)
2015-04-30 10:35:33,694 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: mail.message set_message_read: time:0.010s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:36,189 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product name_search: time:0.077s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:36,639 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product name_search: time:0.135s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:37,939 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product name_search: time:0.088s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:38,330 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product name_search: time:0.107s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:39,440 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product name_search: time:0.092s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:40,232 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product name_search: time:0.101s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:41,763 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product fields_view_get: time:0.292s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:42,285 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product default_get: time:0.219s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:42,603 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.category name_get: time:0.097s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:42,730 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.uom name_get: time:0.135s mem: 647264k -> 663656k (diff: 16392k)
2015-04-30 10:35:42,987 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: stock.location.route search: time:0.121s mem: 663656k -> 663660k (diff: 4k)
2015-04-30 10:35:43,017 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.uom name_get: time:0.191s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:43,289 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: res.company name_search: time:0.481s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:43,455 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.tax name_get: time:0.174s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:43,487 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: stock.location name_get: time:0.602s mem: 663656k -> 663660k (diff: 4k)
2015-04-30 10:35:43,644 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: stock.location name_get: time:0.574s mem: 663656k -> 663660k (diff: 4k)
2015-04-30 10:35:43,770 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: account.tax name_get: time:0.182s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:43,825 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product read_followers_data: time:0.071s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:43,883 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: stock.location name_get: time:0.624s mem: 663656k -> 663660k (diff: 4k)
2015-04-30 10:35:44,209 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: stock.location.route name_get: time:0.189s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:44,376 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.supplierinfo fields_view_get: time:0.583s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:44,410 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.packaging fields_view_get: time:0.446s mem: 663656k -> 663656k (diff: 0k)
2015-04-30 10:35:44,461 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.product onchange: time:2.120s mem: 647264k -> 655460k (diff: 8196k)
2015-04-30 10:35:46,837 7225 DEBUG anydatabase openerp.http.rpc.request: notify: None None: time:0.027s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:57,006 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: sale.order fields_view_get: time:0.159s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:58,037 7225 DEBUG anydatabase openerp.http.rpc.request: notify: None None: time:0.145s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:35:58,073 7225 DEBUG anydatabase openerp.http.rpc.request: search_read: sale.order None: time:0.904s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:36:03,363 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.supplierinfo fields_view_get: time:0.051s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:36:03,523 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.supplierinfo default_get: time:0.032s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:36:03,604 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: product.supplierinfo onchange: time:0.012s mem: 647264k -> 647264k (diff: 0k)
2015-04-30 10:36:03,710 7225 DEBUG anydatabase openerp.http.rpc.request: call_kw: res.company name_search: time:0.023s mem: 647264k -> 647264k (diff: 0k)

As you can see some calls are not very slow but others take seconds.

Do you have any hints?

Avatar
Discard
Zbik

Ty to use pgtune and compare result. See https://www.odoo.com/forum/help-1/question/how-to-tune-postgresql-for-openerp-v7-production-environment-25326

Michael Thomas

I am considering moving towards a setup like yours for a customer (with a load balancer). Were you able to resolve the issue?

Avatar
Pablo Fuentes
Best Answer

Hi Christoph, did you solved it? 

Thanks!

Avatar
Discard
Avatar
Olivier Dony (odo)
Best Answer

Extra details you could add to your question

  • The CPU specs of your vservers? (Strato's website is not quite clear on the clock speed/number of the vCPUs for linux vservers)

  • Was your DEBUG log taken during peak activity?

  • The config file / options of your Odoo servers processes?

  • Did you change anything in your deployment setup at the same time you upgraded to Odoo 8.0? (e.g upgraded anything except PG, like nginx, reinstalled the vservers or dist-upgraded the OS? In case some overlooked config issue introduced a new bottleneck somewhere)

  • What kind of "slowness" are you talking about exactly? Is it constant or random during the peak periods? And how do those timings compare between low usage periods (only one user working) and peak periods? (perhaps you can show debug logs at both times)

  • Your nginx config and nginx statistics (requests/minute at peaks)


Some possible clues

  • Odoo 8.0 is relatively more CPU intensive than Odoo 7.0, due to the new dynamic features of the new API. Make sure you're always up to date with the latest 8.0 code, as new performance optimizations are still being introduced today.

  • The volume of data and transactions/second you are quoting are reasonably small, and should run perfectly fine on a single modern bare-metal server without even breaking a sweat (say, an Intel E3 1230 v3 3.3GHz with 32GB RAM, the kind of low-end dedicated server you can get for 30EUR/month). So it should run fine on your multi-server setup.

  • Your DEBUG logs gives some indications:

    • Only a single process is logging (7225), so I assume you're running in multithreaded mode

    • The timings of the requests reveal very little overlap between requests, so either the number of incoming HTTP requests/seconds is indeed slow, or they are being queued at the entrance. 

  • Your system stats show very low activity on all machines, which seems to indicate that they're under-used (although system statistics on vservers are unreliable...)

  • Based on the PostgreSQL statistics it seems your PG config is doing just fine, and Postgres simply does not get a lot of work to do.

Things you can try

If you have several vCPUs on each vserver, you would definitely benefit from multi-process mode, in order to use all the virtual cores. Currently you seem to be working with a single core only, so there's no way you can get the load average above 1 with CPU-bound activity (due to Python's mono-process GIL), and you're probably starving requests in the queue. If you have 4 vCPUs per vserver, try starting Odoo with

 --workers=6

and see if it increases the performance or the load on the Odoo vservers.

Avatar
Discard
E.R. Spada

Running new HP server ntel(R) Xeon(R) CPU E5-2640 v3 @ 2.60GHz Processor (2) so 16 cores, 64GB ram, VERY SLOW, was running on VM on OSX was faster? Ran pgtune, config file: options] ; This is the password that allows database operations: admin_passwd = dfdfdfdfd db_host = localhost db_port = 5432 db_user = odoo db_password = dfdfdfdfd addons_path = /opt/odoo/addons,/opt/odoo/chris_coffee logfile = /var/log/odoo/odoo-server.log workers = 17 limit-time-cpu=700 limit-time-real=800 log-level=debug_rpc PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/bin max-cron-threads=2 limit-memory-soft=943718400 limit-memory-hard=1153433600 Seeing this in the logs: 2015-05-21 03:31:19,268 6601 DEBUG testdb openerp.http.rpc.request: call_kw: sale.order read_group: time:0.017s mem: 343468k -> 331076k (diff: -12392k)?

Avatar
Michael Thomas
Best Answer

You may be well beyond this already, but I would start looking for a bottleneck during your peak hours. That said, this is how I would proceed. 

1. If you are able to replicate the problem yourself during peak times (ie. you can see slow page load times), I would start by hitting both your odoo instances directly during those times and bypassing the load balancer.

2. If you still see a slow down on both computers, then you can be assured it is some janky code/update issue or a database/db server issue.

3. If you see on only one odoo server, you've found the problem.

4. If you don't see it at all, you know it is probably your load balancer or something to do with your host.

 

If none of that works, I would crank up my system resources. You could also try some PostgreSQL optimization: https://wiki.postgresql.org/wiki/Performance_Optimization. Lastly, have you verified it is not a network issue. Are all your users working in the same office and you've got a latency or packet loss issue? Or, does your host have any network problems?

Avatar
Discard