On Monday, April 15, 2013 9:00:25 PM UTC-7, Ian Wilson wrote: > > > > 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 >> > Forgot to ask before, are any of these back portable?
> >> > 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] >> 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 >
