On Monday, April 15, 2013 10:37:12 AM UTC-7, Cédric Krier wrote: > > On 15/04/13 09:36 -0700, Ian Wilson wrote: > > Hello people of Tryton, > > > > I'm experiencing performance problems and had some questions about them. > > > > I have a wizard that works like a sales register for retail sales. It > > works as follows: > > > > An employee enters in a list of products, their quantities and > optionally > > new prices and then clicks process. In the process method the sale and > its > > lines are created with taxes, payment method, warehouse, party, etc. > Then > > the invoice is paid and the shipment is sent by running their workflows. > > It looks like a POS but you do a lot of stuffs that could be skiped in > automatic process. For example, no need to get a shipment if the goods > are already out, you just have to do moves. Idem for invoice, if you > don't need the invoice, you can just register the accounting moves in a > journal. > > > This process method takes from 30 seconds to over a minute to complete > with > > one product in a sale. > > The sale workflow was also splitted in "confirm" and "process" to allow > processing it later. For example, with a ecommerce website, you can > process sales not inside the same transaction as the use but later with > a cron job or even better using a message queue. Also by processing > sales in group, you will benefit of the bunch API. >
If sales were merely marked confirmed would I still be able to print something for a receipt? > > > I have around 12000 products and 1000 stock locations (arranged in a > > hierarchy). > > That's probably slow down the assignation. > > > I also have a lot of custom modules but I don't customize anything in > > accounting that I know of and that is just as slow as the shipping > phase. > > That should be checked. > > > I'm running Tryton 2.6 with Postgresql 9.2 on a Gentoo machine (VPS) > with > > 2GB of ram and 8 cpus(2 priority). > > VPS are not always the best solution for performance. > And 8 cups doesn't help. > I figured the cpus would not help but I experienced a similar slow down on my computer and the VPS is typically much faster because it is running only server components and no desktop components. > > > I have inserted start/top print statements in my process method and > overall > > most of the parts seem to be contributing to the slowness. > > > > 1st run (fresh start of client): > > sale workflow took 0:00:30.055756 > > shipping took 0:00:24.810039 > > invoicing took 0:00:22.723529 > > do_process took 0:01:17.599376 > > > > 2nd run (in case of aching): > > sale workflow took 0:00:27.521843 > > shipping took 0:00:23:108033 > > invoicing took 0:00:20.545800 > > do_process took 0:01:11.184253 > > > > Here is the wizard code with the log/datetime.now statements: > > https://gist.github.com/ianjosephwilson/5389138 > > > > > > Is this performance expected for my magnitude of products and locations? > > Hard to say, we need more information: > > - number of SQL queries > - inside each workflow where is spend the time > > > Is there a better way to profile other than printing start/stop times? > I > > tried to splice in the python profiler but the output for a system as > > complex as tryton is pretty unhelpful. > > > > Are there changes in 2.7+ that I could backport to improve performance? > > Yes there are many improvements in coming 2.8, here are a few: > > http://hg.tryton.org/trytond/rev/c48089fa3ade (and all modules) > http://hg.tryton.org/trytond/rev/c7804c288ca3 (and all modules) > http://hg.tryton.org/modules/account/rev/5b61530991e1 > > > It seems that running through this process manually is a bit faster than > > using the wizard. Is it possible that running in the context of a > wizard > > is disabling some sort of server side caching or adding some new > overhead? > > Normally not. > > > Could I be missing a C extension for something like relatorio? > > Genshi has some C extension. > > -- > Cédric Krier > > B2CK SPRL > Rue de Rotterdam, 4 > 4000 Liège > Belgium > Tel: +32 472 54 46 59 > Email/Jabber: [email protected] <javascript:> > Website: http://www.b2ck.com/ > I tried to turn on sql logging with Transaction().cursor.sql_log = True at the start of my do_process method. I'm not sure if there is a better way and that will work. I modified the code to also track updates and keep track of queries that did not match. I printed them out and the only queries not matched are nextval() queries which are all very quick. So the most glaring thing I noticed is that there are a TON(~6000) of queries being executed. For example why do 1266 queries get executed against company_company? It seems like maybe I have something misconfigured or some sort of caching is not occurring. SELECT nextval('"ir_sequence_10"') 0.000555992126465 SELECT nextval('"ir_sequence_4"') 0.000364065170288 SELECT nextval('"ir_sequence_2"') 0.000426054000854 SELECT nextval('"ir_sequence_11"') 0.000318050384521 SELECT nextval('"ir_sequence_2"') 0.000288009643555 SELECT nextval('"ir_sequence_11"') 0.00042200088501 [Tue Apr 16 03:36:51 2013] INFO:sql:SQL LOG from: [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_session_wizard:0.000271/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_payment_term__history:0.000761/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_configuration:0.000919/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:store_store:0.000973/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:party_address__history:0.001213/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:product_category:0.001296/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line_invoice_lines_rel:0.001578/4 [Tue Apr 16 03:36:51 2013] INFO:sql:table:purchase_purchase:0.001625/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:party_contact_mechanism:0.001648/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_payment_term_line:0.001719/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_payment_term:0.001806/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line_account_tax:0.002059/7 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_model_button:0.002380/6 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_payment_term_line__history:0.002450/3 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_configuration:0.002591/6 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_line_account_tax:0.002599/7 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_sequence_strict:0.002938/6 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_invoices_rel:0.003500/7 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_action_report:0.003588/8 [Tue Apr 16 03:36:51 2013] INFO:sql:table:currency_currency:0.003629/7 [Tue Apr 16 03:36:51 2013] INFO:sql:table:company_employee:0.004207/13 [Tue Apr 16 03:36:51 2013] INFO:sql:table:party_party__history:0.004467/5 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_journal_period:0.005575/7 [Tue Apr 16 03:36:51 2013] INFO:sql:table:product_price_list:0.006922/14 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_translation:0.007618/8 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_period:0.008145/12 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_sequence:0.008560/10 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_fiscalyear:0.008664/7 [Tue Apr 16 03:36:51 2013] INFO:sql:table:store_product_listing:0.009159/24 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_property:0.009842/23 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_tax:0.011642/25 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_tax_group:0.012612/14 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_journal:0.014323/18 [Tue Apr 16 03:36:51 2013] INFO:sql:table:product_template:0.016649/34 [Tue Apr 16 03:36:51 2013] INFO:sql:table:res_group:0.022279/15 [Tue Apr 16 03:36:51 2013] INFO:sql:table:party_party:0.023906/61 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_move:0.024560/35 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_line:0.026484/45 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line:0.028816/70 [Tue Apr 16 03:36:51 2013] INFO:sql:table:product_product:0.029028/49 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_model_data:0.030144/44 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_model_access:0.032967/32 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_tax:0.034250/34 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_shipment_out:0.039976/82 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_model:0.040137/27 [Tue Apr 16 03:36:51 2013] INFO:sql:table:party_address:0.040266/50 [Tue Apr 16 03:36:51 2013] INFO:sql:table:product_uom:0.040510/69 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_sale:0.042303/80 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_model_field:0.046320/85 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_account:0.049907/68 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice:0.058342/84 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_move_line:0.059325/95 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_move:0.214646/255 [Tue Apr 16 03:36:51 2013] INFO:sql:table:res_user:0.246402/554 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_rule:0.286567/541 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_model_field_access:0.585538/536 [Tue Apr 16 03:36:51 2013] INFO:sql:table:company_company:0.899121/1266 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_location:1.029673/117 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_rule_group:1.573611/1355 [Tue Apr 16 03:36:51 2013] INFO:sql:SUM:5.67300724983/5939 [Tue Apr 16 03:36:51 2013] INFO:sql:SQL LOG into: [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line_invoice_lines_rel:0.000913/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line_account_tax:0.000922/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_line_account_tax:0.001257/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_invoices_rel:0.001434/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line:0.001725/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_tax:0.002222/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice_line:0.002226/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_shipment_out:0.002678/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice:0.003523/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_sale:0.003688/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_move:0.004338/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_move:0.005240/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_move_line:0.007302/5 [Tue Apr 16 03:36:51 2013] INFO:sql:SUM:0.0374677181244/20 [Tue Apr 16 03:36:51 2013] INFO:sql:SQL LOG update: [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_session_wizard":0.000404/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:ir_sequence_strict":0.000550/1 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_line":0.001807/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_move":0.002341/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_move_line":0.003289/2 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_shipment_out":0.004900/5 [Tue Apr 16 03:36:51 2013] INFO:sql:table:account_invoice":0.008794/6 [Tue Apr 16 03:36:51 2013] INFO:sql:table:sale_sale":0.014393/13 [Tue Apr 16 03:36:51 2013] INFO:sql:table:stock_move":0.024292/10 [Tue Apr 16 03:36:51 2013] INFO:sql:SUM:0.0607705116272/42 [Tue Apr 16 03:36:51 2013] INFO:sql:no match 6 Here is a diff of the sql log changes I made: https://gist.github.com/ianjosephwilson/5393211 I will work on getting more timing #s from deeper in the workflow. Does anyone have any suggestions after seeing these queries? Thanks, -Ian
