CreateOrderFromShoppingList processing time anomaly

[Dave Tenerowicz]

We are seeing some issues in creating large volumes of Orders from
shopping lists. In the production environment, we can see as many as
10,000 shopping list entries processed in a single run, and we are
seeing extremely long processing times.

To try to find the bottleneck we have logged times for each processing
step, and found a weird anomaly. As you would expect, most of the
processing time is spent in the Create Order step.Here's the weird part
- in a small sample the first Order was created in 3.704 seconds. By the
12th shopping list entry, the order creation step took 12.258 seconds.
By the 39th shopping list record, the order creation step took 27.062
seconds!! This pattern of increasing processing time for each successive
order appears to continue throughout the run.

We are baffled as to why this is occurring. Has anyone else noticed this
- or does anyone have an idea what could be causing this?

Any suggestions would be appreciated.

--
Dave Tenerowicz
[hidden email]

Office: 303.493.6727
Mobile [phone]
Fax [phone]

Visit us at http://www.salmonllc.com
For ERP Information: http://www.salmonllc.com/Jsp/vanity/ERP_CRM.jsp?nav=2&NavBarId=ERP_CRMServices

[David E Jones]

A couple of thoughts:

My first guess would be that you are running the entire thing in a  
single transaction. I don't know if that is the case, but that would  
explain why subsequent orders are taking longer to process. The more  
that is involved in a transaction, the longer processes related to it  
will take (because of temporary information the database must process,  
etc).

To pin this down better you should also find out how much time is  
being spent in the database versus the app server.

As a general recommendation you might code this so that it runs these  
10 at a time, ie 10 parallel threads. This can be done by having a  
parent service that goes through the list and a sub-service that  
processes each, and have the parent service do 10 sub-service calls  
asynchronously, wait for all 10 to finish, and then do the next ten  
(until there are less than 10, then do whatever is left). There is a  
lot of waiting among threads and chances are doing one at a time your  
system resource utilization will be really low (ie small CPU  
utilization percentage). I think doing this would touch OFBiz code, as  
both parts are in there, but where the code is doesn't matter. If you  
want to contribute it back chances are someone will help review and  
test it and get it into the trunk.

-David


On Jun 18, 2008, at 9:50 AM, Dave Tenerowicz wrote:

> We are seeing some issues in creating large volumes of Orders from  
> shopping lists. In the production environment, we can see as many as  
> 10,000 shopping list entries processed in a single run, and we are  
> seeing extremely long processing times.
>
> To try to find the bottleneck we have logged times for each  
> processing step, and found a weird anomaly. As you would expect,  
> most of the processing time is spent in the Create Order step.Here's  
> the weird part - in a small sample the first Order was created in  
> 3.704 seconds. By the 12th shopping list entry, the order creation  
> step took 12.258 seconds. By the 39th shopping list record, the  
> order creation step took 27.062 seconds!! This pattern of increasing  
> processing time for each successive order appears to continue  
> throughout the run.
>
> We are baffled as to why this is occurring. Has anyone else noticed  
> this - or does anyone have an idea what could be causing this?
>
> Any suggestions would be appreciated.
>
> --
> Dave Tenerowicz
> [hidden email]
>
> Office: 303.493.6727
> Mobile [phone]
> Fax [phone]
>
> Visit us at http://www.salmonllc.com
> For ERP Information: http://www.salmonllc.com/Jsp/vanity/ERP_CRM.jsp?nav=2&NavBarId=ERP_CRMServices
>

[Dave Tenerowicz]

Thanks David. You are correct in the first case - it is being handled as
a single transaction. We are re-coding now and will update this thread
with the results
-Dave

David E Jones wrote:

>
> A couple of thoughts:
>
> My first guess would be that you are running the entire thing in a
> single transaction. I don't know if that is the case, but that would
> explain why subsequent orders are taking longer to process. The more
> that is involved in a transaction, the longer processes related to it
> will take (because of temporary information the database must process,
> etc).
>
> To pin this down better you should also find out how much time is
> being spent in the database versus the app server.
>
> As a general recommendation you might code this so that it runs these
> 10 at a time, ie 10 parallel threads. This can be done by having a
> parent service that goes through the list and a sub-service that
> processes each, and have the parent service do 10 sub-service calls
> asynchronously, wait for all 10 to finish, and then do the next ten
> (until there are less than 10, then do whatever is left). There is a
> lot of waiting among threads and chances are doing one at a time your
> system resource utilization will be really low (ie small CPU
> utilization percentage). I think doing this would touch OFBiz code, as
> both parts are in there, but where the code is doesn't matter. If you
> want to contribute it back chances are someone will help review and
> test it and get it into the trunk.
>
> -David
>
>
> On Jun 18, 2008, at 9:50 AM, Dave Tenerowicz wrote:
>
>> We are seeing some issues in creating large volumes of Orders from
>> shopping lists. In the production environment, we can see as many as
>> 10,000 shopping list entries processed in a single run, and we are
>> seeing extremely long processing times.
>>
>> To try to find the bottleneck we have logged times for each
>> processing step, and found a weird anomaly. As you would expect, most
>> of the processing time is spent in the Create Order step.Here's the
>> weird part - in a small sample the first Order was created in 3.704
>> seconds. By the 12th shopping list entry, the order creation step
>> took 12.258 seconds. By the 39th shopping list record, the order
>> creation step took 27.062 seconds!! This pattern of increasing
>> processing time for each successive order appears to continue
>> throughout the run.
>>
>> We are baffled as to why this is occurring. Has anyone else noticed
>> this - or does anyone have an idea what could be causing this?
>>
>> Any suggestions would be appreciated.
>>
>> --
>> Dave Tenerowicz
>> [hidden email]
>>
>> Office: 303.493.6727
>> Mobile [phone]
>> Fax [phone]
>>
>> Visit us at http://www.salmonllc.com
>> For ERP Information:
>> http://www.salmonllc.com/Jsp/vanity/ERP_CRM.jsp?nav=2&NavBarId=ERP_CRMServices 
>>
>>
>
>
>

--
Dave Tenerowicz
[hidden email]

Office: 303.493.6727
Mobile [phone]
Fax [phone]

Visit us at http://www.salmonllc.com
For ERP Information: http://www.salmonllc.com/Jsp/vanity/ERP_CRM.jsp?nav=2&NavBarId=ERP_CRMServices

[Dave Tenerowicz]

Just a followup on this. We also found that we could bypass workeffort
processing overhead by changing the productTypeId from
MARKETING_PKG_AUTO to MARKETING_PKG_PICK. This seemed to reduce order
creation times by 2 or more seconds.

In our case,  all marketing packages are simply agregations of other off
the shelf products with no additional handling, configuration or
assembly. As a result I thinks the the pick version of marketing
packages is a better fit.

Can anyone on the list confirm that this is the only impact. We do need
the QOH/ATP values for the sub products to be reduced as each package is
fulfilled, but that seems to be happening. Are we missing anything else
that is inherent in MARKETING_PKG_AUTO??

-Dave

Dave Tenerowicz wrote:

> Thanks David. You are correct in the first case - it is being handled
> as a single transaction. We are re-coding now and will update this
> thread with the results
> -Dave
>
> David E Jones wrote:
>>
>> A couple of thoughts:
>>
>> My first guess would be that you are running the entire thing in a
>> single transaction. I don't know if that is the case, but that would
>> explain why subsequent orders are taking longer to process. The more
>> that is involved in a transaction, the longer processes related to it
>> will take (because of temporary information the database must
>> process, etc).
>>
>> To pin this down better you should also find out how much time is
>> being spent in the database versus the app server.
>>
>> As a general recommendation you might code this so that it runs these
>> 10 at a time, ie 10 parallel threads. This can be done by having a
>> parent service that goes through the list and a sub-service that
>> processes each, and have the parent service do 10 sub-service calls
>> asynchronously, wait for all 10 to finish, and then do the next ten
>> (until there are less than 10, then do whatever is left). There is a
>> lot of waiting among threads and chances are doing one at a time your
>> system resource utilization will be really low (ie small CPU
>> utilization percentage). I think doing this would touch OFBiz code,
>> as both parts are in there, but where the code is doesn't matter. If
>> you want to contribute it back chances are someone will help review
>> and test it and get it into the trunk.
>>
>> -David
>>
>>
>> On Jun 18, 2008, at 9:50 AM, Dave Tenerowicz wrote:
>>
>>> We are seeing some issues in creating large volumes of Orders from
>>> shopping lists. In the production environment, we can see as many as
>>> 10,000 shopping list entries processed in a single run, and we are
>>> seeing extremely long processing times.
>>>
>>> To try to find the bottleneck we have logged times for each
>>> processing step, and found a weird anomaly. As you would expect,
>>> most of the processing time is spent in the Create Order step.Here's
>>> the weird part - in a small sample the first Order was created in
>>> 3.704 seconds. By the 12th shopping list entry, the order creation
>>> step took 12.258 seconds. By the 39th shopping list record, the
>>> order creation step took 27.062 seconds!! This pattern of increasing
>>> processing time for each successive order appears to continue
>>> throughout the run.
>>>
>>> We are baffled as to why this is occurring. Has anyone else noticed
>>> this - or does anyone have an idea what could be causing this?
>>>
>>> Any suggestions would be appreciated.
>>>
>>> --
>>> Dave Tenerowicz
>>> [hidden email]
>>>
>>> Office: 303.493.6727
>>> Mobile [phone]
>>> Fax [phone]
>>>
>>> Visit us at http://www.salmonllc.com
>>> For ERP Information:
>>> http://www.salmonllc.com/Jsp/vanity/ERP_CRM.jsp?nav=2&NavBarId=ERP_CRMServices 
>>>
>>>
>>
>>
>>
>

--
Dave Tenerowicz
[hidden email]

Office: 303.493.6727
Mobile [phone]
Fax [phone]

Visit us at http://www.salmonllc.com
For ERP Information: http://www.salmonllc.com/Jsp/vanity/ERP_CRM.jsp?nav=2&NavBarId=ERP_CRMServices