[6.0.1][stock] very very slow (22 minutes!!!) to process a large picking

[Raphaël Valyi - http://www.akretion.com]

Hey guys,

<content randomly removed due to foul language, please respect the Etiquette!> full description + screenshot here (new bug because different concern):
https://bugs.launchpad.net/openobject-addons/+bug/709559

During that time, my server CPU usage shows roughly:
  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
32290 postgres 20 0 54388 38m 32m R 71 1.2 1:47.89 postgres
32284 akretion 20 0 186m 113m 23m S 21 3.5 0:49.00 python

So an SQL log analyzer will help us to find if there is some slow query. Fortunately here the case is almost daily, so we will be able to log the queries. But if you have an idea, be my guest, cause this would impact large companies very badly.

BTW, this is our hardware, the rest of the perf is pretty good:

root@audiolivroserver:~# cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 23
model name : Intel(R) Core(TM)2 Duo CPU E7500 @ 2.93GHz
stepping : 10
cpu MHz : 1603.000
cache size : 3072 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 2
apicid : 0
initial apicid : 0
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 13
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc arch_perfmon pebs bts aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm sse4_1 xsave lahf_lm tpr_shadow vnmi flexpriority
bogomips : 5852.43
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:

processor : 1
vendor_id : GenuineIntel
cpu family : 6
model : 23
model name : Intel(R) Core(TM)2 Duo CPU E7500 @ 2.93GHz
stepping : 10
cpu MHz : 1603.000
cache size : 3072 KB
physical id : 0
siblings : 2
core id : 1
cpu cores : 2
apicid : 1
initial apicid : 1
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 13
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc arch_perfmon pebs bts aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm sse4_1 xsave lahf_lm tpr_shadow vnmi flexpriority
bogomips : 5851.96
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

I don't understand why you flagged my 2 other reports as duplicate. Again, that sounds just an inconsistent policy.
In the past, we have always been told to open new bugs for different concerns, I really see 3 concerns here:
1) missing records due to harcoded limit being reached silently
2) useless + slow name_get RPC calls from the GTK client (this one)
3) server slowness.

Regards

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

err, that one is 3) in my list. bad copy/paste.

[Olivier Dony (Odoo) (odo-openerp)]

The other topics covered in the original bug 709559 are split into separate bugs, each addressing a specific concern.
This one is about the performance of picking processing in Warehouse management, and has medium priority.

The size and types of the queries involved my be useful to track the problem, but this is certainly not the only point to consider.

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Olivier,

I'll look at that perf to see if I can do something. Already, I can tell you that there isn't any very very slow queries. Instead, it looks, the 20 minutes to process our 315 items pickings is made out of a lot of lot of small ~150 ms queries + Python processing (although as I said, a top shows that Potgres is eating 70% of the CPU, Python 30%).

I should still analyse the log, but that's of any help, I'm attaching a log of the SQL requests longer than 100 ms during this process.

[Olivier Dony (Odoo) (odo-openerp)]

Just for info, here are some timings found out while investigating related bug 709567:

| # | A | B | C | D |
| 64 | 7 | 5 | 2 | 15 |
| 128 | 14 | 11 | 3 | 56 |
| 256 | 28 | 21 | 4 | 232 |

with:
#: lines in purchase.order
A: time to confirm po (seconds)
B: time to duplicate po (seconds)
C: time to open picking processing wizard (seconds)
D: time to process picking with wizard (seconds)

This not only confirms that step D has a total time in O(n2), which is too much (this is the current bug), but also shows that the name_get() calls from the client, counted in column C, are almost negligible, even if YMMV depending on the network speed (this is bug 709567).

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Olivier,

I agree that the name_get is negligible in front of the picking processing
slowness bug. Still, it's still a bug (even an inconsistency of the
osv.memory) and the main impact of the name_get calls is actually on small
pickings such as less than 20 moves with some network latency: it looks
sluggish on the GTK client.
Still no time to investigate more yet. What I can tell you:
in our specific case, our customer also did mi-use of OpenERP as they
entered several 1 lines moves instead of grouping moves, they could actually
re-do de 315 moves picking in around 120 moves. Also it doesn't sound a top
high priority bug (at least to us; say compared to the API consistency which
has impact on third parties development cycles), even it's important to get
it fixed one day, specially before attempting larger deployments of OpenERP.

On Wed, Feb 2, 2011 at 1:10 PM, Olivier Dony (OpenERP) <
<email address hidden>> wrote:

> Just for info, here are some timings found out while investigating
> related bug 709567:
>
> | # | A | B | C | D |
> | 64 | 7 | 5 | 2 | 15 |
> | 128 | 14 | 11 | 3 | 56 |
> | 256 | 28 | 21 | 4 | 232 |
>
> with:
> #: lines in purchase.order
> A: time to confirm po (seconds)
> B: time to duplicate po (seconds)
> C: time to open picking processing wizard (seconds)
> D: time to process picking with wizard (seconds)
>
> This not only confirms that step D has a total time in O(n2), which is
> too much (this is the current bug), but also shows that the name_get()
> calls from the client, counted in column C, are almost negligible, even
> if YMMV depending on the network speed (this is bug 709567).
>
> --
> You received this bug notification because you are a direct subscriber
> of the bug.
> https://bugs.launchpad.net/bugs/709575
>
> Title:
> [6.0.1][stock] very very slow (22 minutes!!!) to process a large
> picking
>
> Status in OpenERP Modules (addons):
> Confirmed
>
> Bug description:
> Hey guys,
>
> <content randomly removed due to foul language, please respect the
> Etiquette!> full description + screenshot here (new bug because different
> concern):
> https://bugs.launchpad.net/openobject-addons/+bug/709559
>
> During that time, my server CPU usage shows roughly:
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> 32290 postgres 20 0 54388 38m 32m R 71 1.2 1:47.89 postgres
> 32284 akretion 20 0 186m 113m 23m S 21 3.5 0:49.00 python
>
> So an SQL log analyzer will help us to find if there is some slow
> query. Fortunately here the case is almost daily, so we will be able
> to log the queries. But if you have an idea, be my guest, cause this
> would impact large companies very badly.
>
> BTW, this is our hardware, the rest of the perf is pretty good:
>
> root@audiolivroserver:~# cat /proc/cpuinfo
> processor : 0
> vendor_id : GenuineIntel
> cpu family : 6
> model : 23
> model name : Intel(R) Core(TM)2 Duo CPU E7500 @ 2.93GHz
> stepping : 10
> cpu MHz : 1603.000
> cache size : 3072 KB
> physical id : 0
> siblings : 2
> core id : 0
> cpu cores : 2
> apicid : 0...

[qdp (OpenERP) (qdp)]

hi,

we are currently investigating to find the reason why this part of the process is that slow. Thanks for your patience (it seems really appropriate this time ^^)

Quentin

[filsys (office-filsystem)]

Hi,
not only partial picking process is very very slow.
Paymen invoice (directly from invoice or from
Accounting/Customers/Customer Payment) is very, very, very ... slow. Is
inacceptable to wait for 2 min for every payment, whatever i have 200
invoice unpayed or 10 invoices unpayed.
I v.5 same workflow works very fine. seems to be from osv_memory?
Thanks

Pe 14.02.2011 17:48, qdp (OpenERP) a scris:
> hi,
>
> we are currently investigating to find the reason why this part of the
> process is that slow. Thanks for your patience (it seems really
> appropriate this time ^^)
>
> Quentin
>

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Quentin

as I said, don't bother for us, we found actual pickings are actually a bit
smaller than that and it doesn't occur every day, so it's usable. At the
same time I'm afraid, we have to deal with more urgent issues like the
Brazilian localization here.
We see folks suggesting OpenERP release policy should match expectations of
banking or other very large companies (I do not as I explained). In any case
this is the kind (not just that one in particular I mean) of issues that
will need to be fixed before trying to target those markets. But I think
their is no rush for that in the current market. In the meantime, please
just assume what OpenERP really is and have a release (fast enough) policy
that would one day make it possible to enter those larger markets. In that
particular case the server perf side can probably be fixed in the same
version, as for the osv mem read API, apparently not, that justify the fast
enough minor release policy IMHO.

Thank you again for your work.

On Mon, Feb 14, 2011 at 1:48 PM, qdp (OpenERP) <email address hidden>wrote:

> hi,
>
> we are currently investigating to find the reason why this part of the
> process is that slow. Thanks for your patience (it seems really
> appropriate this time ^^)
>
> Quentin
>
> --
> You received this bug notification because you are a direct subscriber
> of the bug.
> https://bugs.launchpad.net/bugs/709575
>
> Title:
> [6.0.1][stock] very very slow (22 minutes!!!) to process a large
> picking
>
> Status in OpenERP Modules (addons):
> Confirmed
>
> Bug description:
> Hey guys,
>
> <content randomly removed due to foul language, please respect the
> Etiquette!> full description + screenshot here (new bug because different
> concern):
> https://bugs.launchpad.net/openobject-addons/+bug/709559
>
> During that time, my server CPU usage shows roughly:
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> 32290 postgres 20 0 54388 38m 32m R 71 1.2 1:47.89 postgres
> 32284 akretion 20 0 186m 113m 23m S 21 3.5 0:49.00 python
>
> So an SQL log analyzer will help us to find if there is some slow
> query. Fortunately here the case is almost daily, so we will be able
> to log the queries. But if you have an idea, be my guest, cause this
> would impact large companies very badly.
>
> BTW, this is our hardware, the rest of the perf is pretty good:
>
> root@audiolivroserver:~# cat /proc/cpuinfo
> processor : 0
> vendor_id : GenuineIntel
> cpu family : 6
> model : 23
> model name : Intel(R) Core(TM)2 Duo CPU E7500 @ 2.93GHz
> stepping : 10
> cpu MHz : 1603.000
> cache size : 3072 KB
> physical id : 0
> siblings : 2
> core id : 0
> cpu cores : 2
> apicid : 0
> initial apicid : 0
> fdiv_bug : no
> hlt_bug : no
> f00f_bug : no
> coma_bug : no
> fpu : yes
> fpu_exception : yes
> cpuid level : 13
> wp : yes
> flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov
> pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc
> arch_perfmo...

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Did I tell on Launchpad that I tried to cancel our 315 lines invoice based
on that 315 lines picking? In Brazil, each invoice line has around 6
different line taxes among other bureaucratic stuff,
that also makes 1890 lines to computes global taxes (not OpenERP fault
here)...
Well, after running for 6 hours on the dual core hardware I mentioned, the
invoice was still not cancelled (from the SQL queries, it seems it had no
loop, though I didn't investigate them a lot). I dismissed, as we can
finally have 100+ invoice lines instead of 300, that's okay for now (as time
seems to explode exponentially with the number of lines). But there are
surely things to look at in the perf of the basic functional scope, further
than pickings.

On Mon, Feb 14, 2011 at 2:00 PM, filsys <email address hidden> wrote:

> Hi,
> not only partial picking process is very very slow.
> Paymen invoice (directly from invoice or from
> Accounting/Customers/Customer Payment) is very, very, very ... slow. Is
> inacceptable to wait for 2 min for every payment, whatever i have 200
> invoice unpayed or 10 invoices unpayed.
> I v.5 same workflow works very fine. seems to be from osv_memory?
> Thanks
>
> Pe 14.02.2011 17:48, qdp (OpenERP) a scris:
> > hi,
> >
> > we are currently investigating to find the reason why this part of the
> > process is that slow. Thanks for your patience (it seems really
> > appropriate this time ^^)
> >
> > Quentin
> >
>
> --
> You received this bug notification because you are a direct subscriber
> of the bug.
> https://bugs.launchpad.net/bugs/709575
>
> Title:
> [6.0.1][stock] very very slow (22 minutes!!!) to process a large
> picking
>
> Status in OpenERP Modules (addons):
> Confirmed
>
> Bug description:
> Hey guys,
>
> <content randomly removed due to foul language, please respect the
> Etiquette!> full description + screenshot here (new bug because different
> concern):
> https://bugs.launchpad.net/openobject-addons/+bug/709559
>
> During that time, my server CPU usage shows roughly:
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> 32290 postgres 20 0 54388 38m 32m R 71 1.2 1:47.89 postgres
> 32284 akretion 20 0 186m 113m 23m S 21 3.5 0:49.00 python
>
> So an SQL log analyzer will help us to find if there is some slow
> query. Fortunately here the case is almost daily, so we will be able
> to log the queries. But if you have an idea, be my guest, cause this
> would impact large companies very badly.
>
> BTW, this is our hardware, the rest of the perf is pretty good:
>
> root@audiolivroserver:~# cat /proc/cpuinfo
> processor : 0
> vendor_id : GenuineIntel
> cpu family : 6
> model : 23
> model name : Intel(R) Core(TM)2 Duo CPU E7500 @ 2.93GHz
> stepping : 10
> cpu MHz : 1603.000
> cache size : 3072 KB
> physical id : 0
> siblings : 2
> core id : 0
> cpu cores : 2
> apicid : 0
> initial apicid : 0
> fdiv_bug : no
> hlt_bug : no
> f00f_bug : no
> coma_bug : no
> fpu : yes
> fpu_exception : yes
> cpuid level : 13
> wp : yes...

[filsys (office-filsystem)]

We trying to deploy OpnERp 6 in a company with a warehouse and 2 point
of sales.
We manage around 2000 of products, most of them with tracking lots.
In warehouse we have to encode around of 5-10 purchases per day with
supplier invoices and incoming picking generated from purchases.
Purchases have 10-20 lines each.
Daily from the warehouse is processed 20-30 of sales with pickings and
invoices generated. The sales have also 10-20 lines each.
Apart those, we have to process 300 lines (50-100 pos orders) in both
point of sales.
Our infrastructure is a cabled network with one server xeon quad with
4GB RAM and with speed disks and clients is dual core, core 2 duo and i3
with 2GB RAM.
In terms of picking delay, because aur picking is not very large, we can
accept a small delay between start process and finalize, but when we
have process payment (in POS or on invoice) we waiting too too much. As
what you see, our customer is a small company, not a big one or banking
and we can't use adequated payment even if we use point of sales, bank
statement, customer/supplier payment/voucer or payment directly from
invoice.
Even if this is not a bug in common sense, we think that is very urgent
to fix this issue BEFORE expand OpenERP 6 on the EVERY kind of market.
Thanks

Pe 14.02.2011 18:20, Raphaël Valyi - http://www.akretion.com a scris:
> Did I tell on Launchpad that I tried to cancel our 315 lines invoice based
> on that 315 lines picking? In Brazil, each invoice line has around 6
> different line taxes among other bureaucratic stuff,
> that also makes 1890 lines to computes global taxes (not OpenERP fault
> here)...
> Well, after running for 6 hours on the dual core hardware I mentioned, the
> invoice was still not cancelled (from the SQL queries, it seems it had no
> loop, though I didn't investigate them a lot). I dismissed, as we can
> finally have 100+ invoice lines instead of 300, that's okay for now (as time
> seems to explode exponentially with the number of lines). But there are
> surely things to look at in the perf of the basic functional scope, further
> than pickings.
>
>
> On Mon, Feb 14, 2011 at 2:00 PM, filsys<email address hidden> wrote:
>
>> Hi,
>> not only partial picking process is very very slow.
>> Paymen invoice (directly from invoice or from
>> Accounting/Customers/Customer Payment) is very, very, very ... slow. Is
>> inacceptable to wait for 2 min for every payment, whatever i have 200
>> invoice unpayed or 10 invoices unpayed.
>> I v.5 same workflow works very fine. seems to be from osv_memory?
>> Thanks
>>
>> Pe 14.02.2011 17:48, qdp (OpenERP) a scris:
>>> hi,
>>>
>>> we are currently investigating to find the reason why this part of the
>>> process is that slow. Thanks for your patience (it seems really
>>> appropriate this time ^^)
>>>
>>> Quentin
>>>
>> --
>> You received this bug notification because you are a direct subscriber
>> of the bug.
>> https://bugs.launchpad.net/bugs/709575
>>
>> Title:
>> [6.0.1][stock] very very slow (22 minutes!!!) to process a large
>> picking
>>
>> Status in OpenERP Modules (addons):
>> Confirmed
>>
>> Bug description:
>> Hey guys,
>>
>> <content randomly removed due...

[xrg (xrg)]

On Monday 31 January 2011, you wrote:
> Olivier,
>
> I'll look at that perf to see if I can do something. Already, I can tell
> you that there isn't any very very slow queries. Instead, it looks, the
> 20 minutes to process our 315 items pickings is made out of a lot of lot
> of small ~150 ms queries + Python processing (although as I said, a top
> shows that Potgres is eating 70% of the CPU, Python 30%).
>
> I should still analyse the log, but that's of any help, I'm attaching a
> log of the SQL requests longer than 100 ms during this process.
>
> ** Attachment added: "postgresql-2011-01-29_230423.log"

Please, can you try the attached patch?
It seems to improve things for /one/ case so far.

[qdp (OpenERP) (qdp)]

Hi,
as the patch of xrg corrects the issue, i'm closing this bug. Some improvements should still be done when the branches for osv_memory name_get will be merged.

Thanks for the contribution,
Quentin

[qdp (OpenERP) (qdp)]

and i forgot to say: this patch has landed in trunk revision: 4439.

Thanks,