Submit order taking longer and afterwards failing.

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
15 messages Options
Reply | Threaded
Open this post in threaded view
|

Submit order taking longer and afterwards failing.

vipin nirwal
Hi,

I am facing a weird issue. First submit order is taking longer like 12-20sec . Afterwards each order takes quite longer to submit. If processing time is being increased more than 1 minutes then all order start failing. I am getting below error message for failed order.

<div id="content-messages" class="content-messages errorMessage"
        onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
      <p>The Following Errors Occurred:</p>
          <p>Problems getting order header. Cannot check external gateways!</p>
    </div>

This error is coming from CheckOutEvents.checkExternalPayment method. Though few orders are submitted successfully.
Please let me know if someone faced this issue or any solution for this. Is there any

PS. I am using apache jmeter to submit order.

BR//
Vipin Nirwal

Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Jacques Le Roux
Administrator
Hi Vipin,

I can see only a reason: an issue to access your OFBiz database. I don't remember such problems reported earlier. Maybe you are forcing too much with
Jmeter and you get deadlocks in the DB.

Jacques

Le 18/12/2019 à 06:19, vipin nirwal a écrit :

> Hi,
>
> I am facing a weird issue. First submit order is taking longer like 12-20sec . Afterwards each order takes quite longer to submit. If processing time is being increased more than 1 minutes then all order start failing. I am getting below error message for failed order.
>
> <div id="content-messages" class="content-messages errorMessage"
>          onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>        <p>The Following Errors Occurred:</p>
>            <p>Problems getting order header. Cannot check external gateways!</p>
>      </div>
>
> This error is coming from CheckOutEvents.checkExternalPayment method. Though few orders are submitted successfully.
> Please let me know if someone faced this issue or any solution for this. Is there any
>
> PS. I am using apache jmeter to submit order.
>
> BR//
> Vipin Nirwal
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Jacques,

Thanks for your response.
I tried with out of the box derby DB too. I am trying with only 5 concurrent user but still submit order is giving hard time to me.

Looking at jmeter result, it seems submit order API is running in sequence. Taking longer time in each submit call. Attached is jmeter result.

I debug a bit more. CheckOutEvents.createOrder is taking longer time in execution. Due to this , we are not able to get OrderHeader in CheckOutHelper.checkExternalPayment method. Thats why i was getting above error. Is there any other setting i am missing? 

PS. If i am trying to submit order in UI, then its not taking more than 10 sec. I tried to increase the transaction time out( you suggested in some thread , modify TransactionUtil class. Then all order were successful but again taking more time).
I am trying this, if there will be any other finding, will update.

BR//
Vipin Nirwal

On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <[hidden email]> wrote:
Hi Vipin,

I can see only a reason: an issue to access your OFBiz database. I don't remember such problems reported earlier. Maybe you are forcing too much with
Jmeter and you get deadlocks in the DB.

Jacques

Le 18/12/2019 à 06:19, vipin nirwal a écrit :
> Hi,
>
> I am facing a weird issue. First submit order is taking longer like 12-20sec . Afterwards each order takes quite longer to submit. If processing time is being increased more than 1 minutes then all order start failing. I am getting below error message for failed order.
>
> <div id="content-messages" class="content-messages errorMessage"
>          onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>        <p>The Following Errors Occurred:</p>
>            <p>Problems getting order header. Cannot check external gateways!</p>
>      </div>
>
> This error is coming from CheckOutEvents.checkExternalPayment method. Though few orders are submitted successfully.
> Please let me know if someone faced this issue or any solution for this. Is there any
>
> PS. I am using apache jmeter to submit order.
>
> BR//
> Vipin Nirwal
>
>


--
Thanks & Regards
Vipin Nirwal

Jmeter_Results.xlsx (31K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Humera Khan
Hi Vipin,

As per the attached JMeter result, status for the submit_order request is a
warning. There may be an issue related to the cookie or any other request
header. Please compare the HTTP request of JMeter with the request in
browser.

HTH!

Best Regards,
Humera Khan


On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email]> wrote:

> Hi Jacques,
>
> Thanks for your response.
> I tried with out of the box derby DB too. I am trying with only 5
> concurrent user but still submit order is giving hard time to me.
>
> Looking at jmeter result, it seems submit order API is running in
> sequence. Taking longer time in each submit call. Attached is jmeter result.
>
> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
> execution. Due to this , we are not able to get OrderHeader in
> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
> error. Is there any other setting i am missing?
>
> PS. If i am trying to submit order in UI, then its not taking more than 10
> sec. I tried to increase the transaction time out( you suggested in some
> thread , modify TransactionUtil class. Then all order were successful but
> again taking more time).
> I am trying this, if there will be any other finding, will update.
>
> BR//
> Vipin Nirwal
>
> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
> [hidden email]> wrote:
>
>> Hi Vipin,
>>
>> I can see only a reason: an issue to access your OFBiz database. I don't
>> remember such problems reported earlier. Maybe you are forcing too much
>> with
>> Jmeter and you get deadlocks in the DB.
>>
>> Jacques
>>
>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>> > Hi,
>> >
>> > I am facing a weird issue. First submit order is taking longer like
>> 12-20sec . Afterwards each order takes quite longer to submit. If
>> processing time is being increased more than 1 minutes then all order start
>> failing. I am getting below error message for failed order.
>> >
>> > <div id="content-messages" class="content-messages errorMessage"
>> >
>> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>> >        <p>The Following Errors Occurred:</p>
>> >            <p>Problems getting order header. Cannot check external
>> gateways!</p>
>> >      </div>
>> >
>> > This error is coming from CheckOutEvents.checkExternalPayment method.
>> Though few orders are submitted successfully.
>> > Please let me know if someone faced this issue or any solution for
>> this. Is there any
>> >
>> > PS. I am using apache jmeter to submit order.
>> >
>> > BR//
>> > Vipin Nirwal
>> >
>> >
>>
>
>
> --
> Thanks & Regards
> Vipin Nirwal
>
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Humera,

Thanks for your reply.

I compared  both HTTP request and did not find any difference. Seems ok to
me. When i am running concurrent user from jmeter (only 5 threads) and same
time, i am trying to submit order from UI, its taking around 30-40 sec or
even more from UI too.

I logged the queries which are taking longer in postgres and found this
query every time. But when i am doing explain on this query then its very
quickly updating.

2019-12-20 06:41:12.772 UTC [13411] LOG:  duration: 96233.642 ms  execute
<unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
PRODUCT_ID=$8
2019-12-20 06:41:12.772 UTC [13411] DETAIL:  parameters: $1 = '84.000000',
$2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
12:33:35.901+00', $8 = 'WG-5569'
2019-12-20 06:42:48.667 UTC [12179] LOG:  duration: 192255.312 ms  execute
<unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
PRODUCT_ID=$8
2019-12-20 06:42:48.667 UTC [12179] DETAIL:  parameters: $1 = '84.000000',
$2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
12:33:35.901+00', $8 = 'WG-5569'
2019-12-20 06:43:36.832 UTC [12180] LOG:  duration: 240242.603 ms  execute
<unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
PRODUCT_ID=$8
2019-12-20 06:43:36.832 UTC [12180] DETAIL:  parameters: $1 = '84.000000',
$2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
12:33:35.901+00', $8 = 'WG-5569'

BR//
Vipin Nirwal



On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email]>
wrote:

> Hi Vipin,
>
> As per the attached JMeter result, status for the submit_order request is a
> warning. There may be an issue related to the cookie or any other request
> header. Please compare the HTTP request of JMeter with the request in
> browser.
>
> HTH!
>
> Best Regards,
> Humera Khan
>
>
> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email]> wrote:
>
> > Hi Jacques,
> >
> > Thanks for your response.
> > I tried with out of the box derby DB too. I am trying with only 5
> > concurrent user but still submit order is giving hard time to me.
> >
> > Looking at jmeter result, it seems submit order API is running in
> > sequence. Taking longer time in each submit call. Attached is jmeter
> result.
> >
> > I debug a bit more. CheckOutEvents.createOrder is taking longer time in
> > execution. Due to this , we are not able to get OrderHeader in
> > CheckOutHelper.checkExternalPayment method. Thats why i was getting above
> > error. Is there any other setting i am missing?
> >
> > PS. If i am trying to submit order in UI, then its not taking more than
> 10
> > sec. I tried to increase the transaction time out( you suggested in some
> > thread , modify TransactionUtil class. Then all order were successful but
> > again taking more time).
> > I am trying this, if there will be any other finding, will update.
> >
> > BR//
> > Vipin Nirwal
> >
> > On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
> > [hidden email]> wrote:
> >
> >> Hi Vipin,
> >>
> >> I can see only a reason: an issue to access your OFBiz database. I don't
> >> remember such problems reported earlier. Maybe you are forcing too much
> >> with
> >> Jmeter and you get deadlocks in the DB.
> >>
> >> Jacques
> >>
> >> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
> >> > Hi,
> >> >
> >> > I am facing a weird issue. First submit order is taking longer like
> >> 12-20sec . Afterwards each order takes quite longer to submit. If
> >> processing time is being increased more than 1 minutes then all order
> start
> >> failing. I am getting below error message for failed order.
> >> >
> >> > <div id="content-messages" class="content-messages errorMessage"
> >> >
> >>
> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
> >> >        <p>The Following Errors Occurred:</p>
> >> >            <p>Problems getting order header. Cannot check external
> >> gateways!</p>
> >> >      </div>
> >> >
> >> > This error is coming from CheckOutEvents.checkExternalPayment method.
> >> Though few orders are submitted successfully.
> >> > Please let me know if someone faced this issue or any solution for
> >> this. Is there any
> >> >
> >> > PS. I am using apache jmeter to submit order.
> >> >
> >> > BR//
> >> > Vipin Nirwal
> >> >
> >> >
> >>
> >
> >
> > --
> > Thanks & Regards
> > Vipin Nirwal
> >
>


--
Thanks & Regards
Vipin Nirwal
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Jacques Le Roux
Administrator
Hi Vipin,

Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?

Thanks

Jacques

Le 20/12/2019 à 07:53, vipin nirwal a écrit :

> Hi Humera,
>
> Thanks for your reply.
>
> I compared  both HTTP request and did not find any difference. Seems ok to
> me. When i am running concurrent user from jmeter (only 5 threads) and same
> time, i am trying to submit order from UI, its taking around 30-40 sec or
> even more from UI too.
>
> I logged the queries which are taking longer in postgres and found this
> query every time. But when i am doing explain on this query then its very
> quickly updating.
>
> 2019-12-20 06:41:12.772 UTC [13411] LOG:  duration: 96233.642 ms  execute
> <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> PRODUCT_ID=$8
> 2019-12-20 06:41:12.772 UTC [13411] DETAIL:  parameters: $1 = '84.000000',
> $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
> 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> 12:33:35.901+00', $8 = 'WG-5569'
> 2019-12-20 06:42:48.667 UTC [12179] LOG:  duration: 192255.312 ms  execute
> <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> PRODUCT_ID=$8
> 2019-12-20 06:42:48.667 UTC [12179] DETAIL:  parameters: $1 = '84.000000',
> $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
> 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> 12:33:35.901+00', $8 = 'WG-5569'
> 2019-12-20 06:43:36.832 UTC [12180] LOG:  duration: 240242.603 ms  execute
> <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> PRODUCT_ID=$8
> 2019-12-20 06:43:36.832 UTC [12180] DETAIL:  parameters: $1 = '84.000000',
> $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
> 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> 12:33:35.901+00', $8 = 'WG-5569'
>
> BR//
> Vipin Nirwal
>
>
>
> On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email]>
> wrote:
>
>> Hi Vipin,
>>
>> As per the attached JMeter result, status for the submit_order request is a
>> warning. There may be an issue related to the cookie or any other request
>> header. Please compare the HTTP request of JMeter with the request in
>> browser.
>>
>> HTH!
>>
>> Best Regards,
>> Humera Khan
>>
>>
>> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email]> wrote:
>>
>>> Hi Jacques,
>>>
>>> Thanks for your response.
>>> I tried with out of the box derby DB too. I am trying with only 5
>>> concurrent user but still submit order is giving hard time to me.
>>>
>>> Looking at jmeter result, it seems submit order API is running in
>>> sequence. Taking longer time in each submit call. Attached is jmeter
>> result.
>>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>>> execution. Due to this , we are not able to get OrderHeader in
>>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>>> error. Is there any other setting i am missing?
>>>
>>> PS. If i am trying to submit order in UI, then its not taking more than
>> 10
>>> sec. I tried to increase the transaction time out( you suggested in some
>>> thread , modify TransactionUtil class. Then all order were successful but
>>> again taking more time).
>>> I am trying this, if there will be any other finding, will update.
>>>
>>> BR//
>>> Vipin Nirwal
>>>
>>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>>> [hidden email]> wrote:
>>>
>>>> Hi Vipin,
>>>>
>>>> I can see only a reason: an issue to access your OFBiz database. I don't
>>>> remember such problems reported earlier. Maybe you are forcing too much
>>>> with
>>>> Jmeter and you get deadlocks in the DB.
>>>>
>>>> Jacques
>>>>
>>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>>>>> Hi,
>>>>>
>>>>> I am facing a weird issue. First submit order is taking longer like
>>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>>>> processing time is being increased more than 1 minutes then all order
>> start
>>>> failing. I am getting below error message for failed order.
>>>>> <div id="content-messages" class="content-messages errorMessage"
>>>>>
>> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>>>>>         <p>The Following Errors Occurred:</p>
>>>>>             <p>Problems getting order header. Cannot check external
>>>> gateways!</p>
>>>>>       </div>
>>>>>
>>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>>>> Though few orders are submitted successfully.
>>>>> Please let me know if someone faced this issue or any solution for
>>>> this. Is there any
>>>>> PS. I am using apache jmeter to submit order.
>>>>>
>>>>> BR//
>>>>> Vipin Nirwal
>>>>>
>>>>>
>>>
>>> --
>>> Thanks & Regards
>>> Vipin Nirwal
>>>
>
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Jacques,

I am using 18.12 release.

BR//
Vipin Nirwal

On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
[hidden email]> wrote:

> Hi Vipin,
>
> Since, AFAIK, we did not ask yet and that's pretty needed as this stage,
> which version are you using?
>
> Thanks
>
> Jacques
>
> Le 20/12/2019 à 07:53, vipin nirwal a écrit :
> > Hi Humera,
> >
> > Thanks for your reply.
> >
> > I compared  both HTTP request and did not find any difference. Seems ok
> to
> > me. When i am running concurrent user from jmeter (only 5 threads) and
> same
> > time, i am trying to submit order from UI, its taking around 30-40 sec or
> > even more from UI too.
> >
> > I logged the queries which are taking longer in postgres and found this
> > query every time. But when i am doing explain on this query then its very
> > quickly updating.
> >
> > 2019-12-20 06:41:12.772 UTC [13411] LOG:  duration: 96233.642 ms  execute
> > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> > PRODUCT_ID=$8
> > 2019-12-20 06:41:12.772 UTC [13411] DETAIL:  parameters: $1 =
> '84.000000',
> > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
> > 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> > 12:33:35.901+00', $8 = 'WG-5569'
> > 2019-12-20 06:42:48.667 UTC [12179] LOG:  duration: 192255.312 ms
> execute
> > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> > PRODUCT_ID=$8
> > 2019-12-20 06:42:48.667 UTC [12179] DETAIL:  parameters: $1 =
> '84.000000',
> > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
> > 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> > 12:33:35.901+00', $8 = 'WG-5569'
> > 2019-12-20 06:43:36.832 UTC [12180] LOG:  duration: 240242.603 ms
> execute
> > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> > PRODUCT_ID=$8
> > 2019-12-20 06:43:36.832 UTC [12180] DETAIL:  parameters: $1 =
> '84.000000',
> > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
> > 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> > 12:33:35.901+00', $8 = 'WG-5569'
> >
> > BR//
> > Vipin Nirwal
> >
> >
> >
> > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <
> [hidden email]>
> > wrote:
> >
> >> Hi Vipin,
> >>
> >> As per the attached JMeter result, status for the submit_order request
> is a
> >> warning. There may be an issue related to the cookie or any other
> request
> >> header. Please compare the HTTP request of JMeter with the request in
> >> browser.
> >>
> >> HTH!
> >>
> >> Best Regards,
> >> Humera Khan
> >>
> >>
> >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email]>
> wrote:
> >>
> >>> Hi Jacques,
> >>>
> >>> Thanks for your response.
> >>> I tried with out of the box derby DB too. I am trying with only 5
> >>> concurrent user but still submit order is giving hard time to me.
> >>>
> >>> Looking at jmeter result, it seems submit order API is running in
> >>> sequence. Taking longer time in each submit call. Attached is jmeter
> >> result.
> >>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
> >>> execution. Due to this , we are not able to get OrderHeader in
> >>> CheckOutHelper.checkExternalPayment method. Thats why i was getting
> above
> >>> error. Is there any other setting i am missing?
> >>>
> >>> PS. If i am trying to submit order in UI, then its not taking more than
> >> 10
> >>> sec. I tried to increase the transaction time out( you suggested in
> some
> >>> thread , modify TransactionUtil class. Then all order were successful
> but
> >>> again taking more time).
> >>> I am trying this, if there will be any other finding, will update.
> >>>
> >>> BR//
> >>> Vipin Nirwal
> >>>
> >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
> >>> [hidden email]> wrote:
> >>>
> >>>> Hi Vipin,
> >>>>
> >>>> I can see only a reason: an issue to access your OFBiz database. I
> don't
> >>>> remember such problems reported earlier. Maybe you are forcing too
> much
> >>>> with
> >>>> Jmeter and you get deadlocks in the DB.
> >>>>
> >>>> Jacques
> >>>>
> >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
> >>>>> Hi,
> >>>>>
> >>>>> I am facing a weird issue. First submit order is taking longer like
> >>>> 12-20sec . Afterwards each order takes quite longer to submit. If
> >>>> processing time is being increased more than 1 minutes then all order
> >> start
> >>>> failing. I am getting below error message for failed order.
> >>>>> <div id="content-messages" class="content-messages errorMessage"
> >>>>>
> >>
> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
> >>>>>         <p>The Following Errors Occurred:</p>
> >>>>>             <p>Problems getting order header. Cannot check external
> >>>> gateways!</p>
> >>>>>       </div>
> >>>>>
> >>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
> >>>> Though few orders are submitted successfully.
> >>>>> Please let me know if someone faced this issue or any solution for
> >>>> this. Is there any
> >>>>> PS. I am using apache jmeter to submit order.
> >>>>>
> >>>>> BR//
> >>>>> Vipin Nirwal
> >>>>>
> >>>>>
> >>>
> >>> --
> >>> Thanks & Regards
> >>> Vipin Nirwal
> >>>
> >
>


--
Thanks & Regards
Vipin Nirwal
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Jacques/Humera,

Thanks for your support.

When I ran flow with a different product, I did not see any latency in submit order. See attached jmeter log.

But when I am running flow with product id “WG-5569’, I am getting latency while submitting order.  See attached txt file for query which is taking exclusive lock.
Any pointer/hint why this is happening, is really appreciable.

BR//
Vipin Nirwal

On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <[hidden email]> wrote:
Hi Jacques,

I am using 18.12 release.

BR//
Vipin Nirwal

On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email]> wrote:
Hi Vipin,

Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?

Thanks

Jacques

Le 20/12/2019 à 07:53, vipin nirwal a écrit :
> Hi Humera,
>
> Thanks for your reply.
>
> I compared  both HTTP request and did not find any difference. Seems ok to
> me. When i am running concurrent user from jmeter (only 5 threads) and same
> time, i am trying to submit order from UI, its taking around 30-40 sec or
> even more from UI too.
>
> I logged the queries which are taking longer in postgres and found this
> query every time. But when i am doing explain on this query then its very
> quickly updating.
>
> 2019-12-20 06:41:12.772 UTC [13411] LOG:  duration: 96233.642 ms  execute
> <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> PRODUCT_ID=$8
> 2019-12-20 06:41:12.772 UTC [13411] DETAIL:  parameters: $1 = '84.000000',
> $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
> 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> 12:33:35.901+00', $8 = 'WG-5569'
> 2019-12-20 06:42:48.667 UTC [12179] LOG:  duration: 192255.312 ms  execute
> <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> PRODUCT_ID=$8
> 2019-12-20 06:42:48.667 UTC [12179] DETAIL:  parameters: $1 = '84.000000',
> $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
> 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> 12:33:35.901+00', $8 = 'WG-5569'
> 2019-12-20 06:43:36.832 UTC [12180] LOG:  duration: 240242.603 ms  execute
> <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
> TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
> PRODUCT_ID=$8
> 2019-12-20 06:43:36.832 UTC [12180] DETAIL:  parameters: $1 = '84.000000',
> $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
> 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
> 12:33:35.901+00', $8 = 'WG-5569'
>
> BR//
> Vipin Nirwal
>
>
>
> On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email]>
> wrote:
>
>> Hi Vipin,
>>
>> As per the attached JMeter result, status for the submit_order request is a
>> warning. There may be an issue related to the cookie or any other request
>> header. Please compare the HTTP request of JMeter with the request in
>> browser.
>>
>> HTH!
>>
>> Best Regards,
>> Humera Khan
>>
>>
>> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email]> wrote:
>>
>>> Hi Jacques,
>>>
>>> Thanks for your response.
>>> I tried with out of the box derby DB too. I am trying with only 5
>>> concurrent user but still submit order is giving hard time to me.
>>>
>>> Looking at jmeter result, it seems submit order API is running in
>>> sequence. Taking longer time in each submit call. Attached is jmeter
>> result.
>>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>>> execution. Due to this , we are not able to get OrderHeader in
>>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>>> error. Is there any other setting i am missing?
>>>
>>> PS. If i am trying to submit order in UI, then its not taking more than
>> 10
>>> sec. I tried to increase the transaction time out( you suggested in some
>>> thread , modify TransactionUtil class. Then all order were successful but
>>> again taking more time).
>>> I am trying this, if there will be any other finding, will update.
>>>
>>> BR//
>>> Vipin Nirwal
>>>
>>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>>> [hidden email]> wrote:
>>>
>>>> Hi Vipin,
>>>>
>>>> I can see only a reason: an issue to access your OFBiz database. I don't
>>>> remember such problems reported earlier. Maybe you are forcing too much
>>>> with
>>>> Jmeter and you get deadlocks in the DB.
>>>>
>>>> Jacques
>>>>
>>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>>>>> Hi,
>>>>>
>>>>> I am facing a weird issue. First submit order is taking longer like
>>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>>>> processing time is being increased more than 1 minutes then all order
>> start
>>>> failing. I am getting below error message for failed order.
>>>>> <div id="content-messages" class="content-messages errorMessage"
>>>>>
>> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>>>>>         <p>The Following Errors Occurred:</p>
>>>>>             <p>Problems getting order header. Cannot check external
>>>> gateways!</p>
>>>>>       </div>
>>>>>
>>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>>>> Though few orders are submitted successfully.
>>>>> Please let me know if someone faced this issue or any solution for
>>>> this. Is there any
>>>>> PS. I am using apache jmeter to submit order.
>>>>>
>>>>> BR//
>>>>> Vipin Nirwal
>>>>>
>>>>>
>>>
>>> --
>>> Thanks & Regards
>>> Vipin Nirwal
>>>
>


--
Thanks & Regards
Vipin Nirwal


--
Thanks & Regards
Vipin Nirwal

query_lock.txt (6K) Download Attachment
Jmeter_Results.xlsx (57K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Jacques Le Roux
Administrator
Hi Wipin,

One thing we know now is that the issue is related to "WG-5569". That's an interesting point. Unfortunately I did not find query_lock.txt very useful.

As it could be a lot of things, I think a look at the log is needed. It would help if you could extract relevant parts... I mean those related with
the lock and a bit around...

Thanks

Jacques

Le 20/12/2019 à 15:19, vipin nirwal a écrit :

> Hi Jacques/Humera,
>
> Thanks for your support.
>
> When I ran flow with a different product, I did not see any latency in submit order. See attached jmeter log.
>
> But when I am running flow with product id “WG-5569’, I am getting latency while submitting order.  See attached txt file for query which is taking
> exclusive lock.
> Any pointer/hint why this is happening, is really appreciable.
>
> BR//
> Vipin Nirwal
>
> On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <[hidden email] <mailto:[hidden email]>> wrote:
>
>     Hi Jacques,
>
>     I am using 18.12 release.
>
>     BR//
>     Vipin Nirwal
>
>     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>> wrote:
>
>         Hi Vipin,
>
>         Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?
>
>         Thanks
>
>         Jacques
>
>         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
>         > Hi Humera,
>         >
>         > Thanks for your reply.
>         >
>         > I compared  both HTTP request and did not find any difference. Seems ok to
>         > me. When i am running concurrent user from jmeter (only 5 threads) and same
>         > time, i am trying to submit order from UI, its taking around 30-40 sec or
>         > even more from UI too.
>         >
>         > I logged the queries which are taking longer in postgres and found this
>         > query every time. But when i am doing explain on this query then its very
>         > quickly updating.
>         >
>         > 2019-12-20 06:41:12.772 UTC [13411] LOG:  duration: 96233.642 ms  execute
>         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>         > PRODUCT_ID=$8
>         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL: parameters: $1 = '84.000000',
>         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
>         > 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>         > 12:33:35.901+00', $8 = 'WG-5569'
>         > 2019-12-20 06:42:48.667 UTC [12179] LOG:  duration: 192255.312 ms  execute
>         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>         > PRODUCT_ID=$8
>         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL: parameters: $1 = '84.000000',
>         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
>         > 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>         > 12:33:35.901+00', $8 = 'WG-5569'
>         > 2019-12-20 06:43:36.832 UTC [12180] LOG:  duration: 240242.603 ms  execute
>         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>         > PRODUCT_ID=$8
>         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL: parameters: $1 = '84.000000',
>         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
>         > 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>         > 12:33:35.901+00', $8 = 'WG-5569'
>         >
>         > BR//
>         > Vipin Nirwal
>         >
>         >
>         >
>         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email] <mailto:[hidden email]>>
>         > wrote:
>         >
>         >> Hi Vipin,
>         >>
>         >> As per the attached JMeter result, status for the submit_order request is a
>         >> warning. There may be an issue related to the cookie or any other request
>         >> header. Please compare the HTTP request of JMeter with the request in
>         >> browser.
>         >>
>         >> HTH!
>         >>
>         >> Best Regards,
>         >> Humera Khan
>         >>
>         >>
>         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email] <mailto:[hidden email]>> wrote:
>         >>
>         >>> Hi Jacques,
>         >>>
>         >>> Thanks for your response.
>         >>> I tried with out of the box derby DB too. I am trying with only 5
>         >>> concurrent user but still submit order is giving hard time to me.
>         >>>
>         >>> Looking at jmeter result, it seems submit order API is running in
>         >>> sequence. Taking longer time in each submit call. Attached is jmeter
>         >> result.
>         >>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>         >>> execution. Due to this , we are not able to get OrderHeader in
>         >>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>         >>> error. Is there any other setting i am missing?
>         >>>
>         >>> PS. If i am trying to submit order in UI, then its not taking more than
>         >> 10
>         >>> sec. I tried to increase the transaction time out( you suggested in some
>         >>> thread , modify TransactionUtil class. Then all order were successful but
>         >>> again taking more time).
>         >>> I am trying this, if there will be any other finding, will update.
>         >>>
>         >>> BR//
>         >>> Vipin Nirwal
>         >>>
>         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>         >>> [hidden email] <mailto:[hidden email]>> wrote:
>         >>>
>         >>>> Hi Vipin,
>         >>>>
>         >>>> I can see only a reason: an issue to access your OFBiz database. I don't
>         >>>> remember such problems reported earlier. Maybe you are forcing too much
>         >>>> with
>         >>>> Jmeter and you get deadlocks in the DB.
>         >>>>
>         >>>> Jacques
>         >>>>
>         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>         >>>>> Hi,
>         >>>>>
>         >>>>> I am facing a weird issue. First submit order is taking longer like
>         >>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>         >>>> processing time is being increased more than 1 minutes then all order
>         >> start
>         >>>> failing. I am getting below error message for failed order.
>         >>>>> <div id="content-messages" class="content-messages errorMessage"
>         >>>>>
>         >> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>         >>>>>         <p>The Following Errors Occurred:</p>
>         >>>>>             <p>Problems getting order header. Cannot check external
>         >>>> gateways!</p>
>         >>>>>       </div>
>         >>>>>
>         >>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>         >>>> Though few orders are submitted successfully.
>         >>>>> Please let me know if someone faced this issue or any solution for
>         >>>> this. Is there any
>         >>>>> PS. I am using apache jmeter to submit order.
>         >>>>>
>         >>>>> BR//
>         >>>>> Vipin Nirwal
>         >>>>>
>         >>>>>
>         >>>
>         >>> --
>         >>> Thanks & Regards
>         >>> Vipin Nirwal
>         >>>
>         >
>
>
>
>     --
>     Thanks & Regards
>     Vipin Nirwal
>
>
>
> --
> Thanks & Regards
> Vipin Nirwal

Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Jacques,

Attaching the logs.
I restarted the postgres DB and submit order was quick for both products. But as i am testing again and again, GZ-2644 is going with same latency(very quick, 2-3 sec). But WG-5569 starts taking time in submit order slowly and eventually will start failing.

I am comparing both products and trying to see if any difference that is causing this issue.

BR//
Vipin Nirwal



On Sat, Dec 21, 2019 at 6:36 PM Jacques Le Roux <[hidden email]> wrote:
Hi Wipin,

One thing we know now is that the issue is related to "WG-5569". That's an interesting point. Unfortunately I did not find query_lock.txt very useful.

As it could be a lot of things, I think a look at the log is needed. It would help if you could extract relevant parts... I mean those related with
the lock and a bit around...

Thanks

Jacques

Le 20/12/2019 à 15:19, vipin nirwal a écrit :
> Hi Jacques/Humera,
>
> Thanks for your support.
>
> When I ran flow with a different product, I did not see any latency in submit order. See attached jmeter log.
>
> But when I am running flow with product id “WG-5569’, I am getting latency while submitting order.  See attached txt file for query which is taking
> exclusive lock.
> Any pointer/hint why this is happening, is really appreciable.
>
> BR//
> Vipin Nirwal
>
> On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <[hidden email] <mailto:[hidden email]>> wrote:
>
>     Hi Jacques,
>
>     I am using 18.12 release.
>
>     BR//
>     Vipin Nirwal
>
>     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>> wrote:
>
>         Hi Vipin,
>
>         Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?
>
>         Thanks
>
>         Jacques
>
>         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
>         > Hi Humera,
>         >
>         > Thanks for your reply.
>         >
>         > I compared  both HTTP request and did not find any difference. Seems ok to
>         > me. When i am running concurrent user from jmeter (only 5 threads) and same
>         > time, i am trying to submit order from UI, its taking around 30-40 sec or
>         > even more from UI too.
>         >
>         > I logged the queries which are taking longer in postgres and found this
>         > query every time. But when i am doing explain on this query then its very
>         > quickly updating.
>         >
>         > 2019-12-20 06:41:12.772 UTC [13411] LOG:  duration: 96233.642 ms  execute
>         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>         > PRODUCT_ID=$8
>         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL: parameters: $1 = '84.000000',
>         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
>         > 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>         > 12:33:35.901+00', $8 = 'WG-5569'
>         > 2019-12-20 06:42:48.667 UTC [12179] LOG:  duration: 192255.312 ms  execute
>         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>         > PRODUCT_ID=$8
>         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL: parameters: $1 = '84.000000',
>         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
>         > 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>         > 12:33:35.901+00', $8 = 'WG-5569'
>         > 2019-12-20 06:43:36.832 UTC [12180] LOG:  duration: 240242.603 ms  execute
>         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>         > PRODUCT_ID=$8
>         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL: parameters: $1 = '84.000000',
>         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
>         > 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>         > 12:33:35.901+00', $8 = 'WG-5569'
>         >
>         > BR//
>         > Vipin Nirwal
>         >
>         >
>         >
>         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email] <mailto:[hidden email]>>
>         > wrote:
>         >
>         >> Hi Vipin,
>         >>
>         >> As per the attached JMeter result, status for the submit_order request is a
>         >> warning. There may be an issue related to the cookie or any other request
>         >> header. Please compare the HTTP request of JMeter with the request in
>         >> browser.
>         >>
>         >> HTH!
>         >>
>         >> Best Regards,
>         >> Humera Khan
>         >>
>         >>
>         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email] <mailto:[hidden email]>> wrote:
>         >>
>         >>> Hi Jacques,
>         >>>
>         >>> Thanks for your response.
>         >>> I tried with out of the box derby DB too. I am trying with only 5
>         >>> concurrent user but still submit order is giving hard time to me.
>         >>>
>         >>> Looking at jmeter result, it seems submit order API is running in
>         >>> sequence. Taking longer time in each submit call. Attached is jmeter
>         >> result.
>         >>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>         >>> execution. Due to this , we are not able to get OrderHeader in
>         >>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>         >>> error. Is there any other setting i am missing?
>         >>>
>         >>> PS. If i am trying to submit order in UI, then its not taking more than
>         >> 10
>         >>> sec. I tried to increase the transaction time out( you suggested in some
>         >>> thread , modify TransactionUtil class. Then all order were successful but
>         >>> again taking more time).
>         >>> I am trying this, if there will be any other finding, will update.
>         >>>
>         >>> BR//
>         >>> Vipin Nirwal
>         >>>
>         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>         >>> [hidden email] <mailto:[hidden email]>> wrote:
>         >>>
>         >>>> Hi Vipin,
>         >>>>
>         >>>> I can see only a reason: an issue to access your OFBiz database. I don't
>         >>>> remember such problems reported earlier. Maybe you are forcing too much
>         >>>> with
>         >>>> Jmeter and you get deadlocks in the DB.
>         >>>>
>         >>>> Jacques
>         >>>>
>         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>         >>>>> Hi,
>         >>>>>
>         >>>>> I am facing a weird issue. First submit order is taking longer like
>         >>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>         >>>> processing time is being increased more than 1 minutes then all order
>         >> start
>         >>>> failing. I am getting below error message for failed order.
>         >>>>> <div id="content-messages" class="content-messages errorMessage"
>         >>>>>
>         >> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>         >>>>>         <p>The Following Errors Occurred:</p>
>         >>>>>             <p>Problems getting order header. Cannot check external
>         >>>> gateways!</p>
>         >>>>>       </div>
>         >>>>>
>         >>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>         >>>> Though few orders are submitted successfully.
>         >>>>> Please let me know if someone faced this issue or any solution for
>         >>>> this. Is there any
>         >>>>> PS. I am using apache jmeter to submit order.
>         >>>>>
>         >>>>> BR//
>         >>>>> Vipin Nirwal
>         >>>>>
>         >>>>>
>         >>>
>         >>> --
>         >>> Thanks & Regards
>         >>> Vipin Nirwal
>         >>>
>         >
>
>
>
>     --
>     Thanks & Regards
>     Vipin Nirwal
>
>
>
> --
> Thanks & Regards
> Vipin Nirwal



--
Thanks & Regards
Vipin Nirwal

log.zip (150K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Jacques Le Roux
Administrator
Hi Vipin,

If you look at the error.log it's crystal clear:

2019-12-23 05:57:38,307 |sse-nio-8443-exec-21 |TransactionUtil               |E| [TransactionUtil.rollback]
java.lang.Exception: Stack Trace
     at org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:314) [ofbiz.jar:?]
     at org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:290) [ofbiz.jar:?]
     at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:559) [ofbiz.jar:?]
     at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:240) [ofbiz.jar:?]
     at org.apache.ofbiz.service.GenericDispatcherFactory$GenericDispatcher.runSync(GenericDispatcherFactory.java:103) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getExternalShipEstimate(ShippingEvents.java:354) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getShipGroupEstimate(ShippingEvents.java:238) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.loadEstimates(ShippingEstimateWrapper.java:119) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.<init>(ShippingEstimateWrapper.java:96) [ofbiz.jar:?]
[....]
2019-12-23 05:57:38,308 |sse-nio-8443-exec-21 |ShippingEvents                |E| Error getting external shipment cost estimate: Rate inquiry is only
valid for US destinations.
2019-12-23 05:57:38,308 |sse-nio-8443-exec-21 |ServiceUtil                   |E| {errorMessage=A problem occurred calculating shipping. Fees will be
calculated offline., responseMessage=error}
2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |ServiceUtil                   |E| {errorMessage=Rate inquiry is only valid for US destinations.,
responseMessage=error}
2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |ServiceDispatcher             |E| Error in Service [uspsRateInquire]: Rate inquiry is only valid for US
destinations.
2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |TransactionUtil               |E| [TransactionUtil.rollback]
[....]

You get this error multiple times (72 exactly) it cumulates and the DB can't handle it.

You need 1st to fix this issue. I suggest you use no external shipment cost estimates for you profiling

Jacques

Le 23/12/2019 à 07:32, vipin nirwal a écrit :

> Hi Jacques,
>
> Attaching the logs.
> I restarted the postgres DB and submit order was quick for both products. But as i am testing again and again, GZ-2644 is going with same
> latency(very quick, 2-3 sec). But WG-5569 starts taking time in submit order slowly and eventually will start failing.
>
> I am comparing both products and trying to see if any difference that is causing this issue.
>
> BR//
> Vipin Nirwal
>
>
>
> On Sat, Dec 21, 2019 at 6:36 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>> wrote:
>
>     Hi Wipin,
>
>     One thing we know now is that the issue is related to "WG-5569". That's an interesting point. Unfortunately I did not find query_lock.txt very
>     useful.
>
>     As it could be a lot of things, I think a look at the log is needed. It would help if you could extract relevant parts... I mean those related with
>     the lock and a bit around...
>
>     Thanks
>
>     Jacques
>
>     Le 20/12/2019 à 15:19, vipin nirwal a écrit :
>     > Hi Jacques/Humera,
>     >
>     > Thanks for your support.
>     >
>     > When I ran flow with a different product, I did not see any latency in submit order. See attached jmeter log.
>     >
>     > But when I am running flow with product id “WG-5569’, I am getting latency while submitting order.  See attached txt file for query which is
>     taking
>     > exclusive lock.
>     > Any pointer/hint why this is happening, is really appreciable.
>     >
>     > BR//
>     > Vipin Nirwal
>     >
>     > On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >
>     >     Hi Jacques,
>     >
>     >     I am using 18.12 release.
>     >
>     >     BR//
>     >     Vipin Nirwal
>     >
>     >     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>> wrote:
>     >
>     >         Hi Vipin,
>     >
>     >         Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?
>     >
>     >         Thanks
>     >
>     >         Jacques
>     >
>     >         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
>     >         > Hi Humera,
>     >         >
>     >         > Thanks for your reply.
>     >         >
>     >         > I compared  both HTTP request and did not find any difference. Seems ok to
>     >         > me. When i am running concurrent user from jmeter (only 5 threads) and same
>     >         > time, i am trying to submit order from UI, its taking around 30-40 sec or
>     >         > even more from UI too.
>     >         >
>     >         > I logged the queries which are taking longer in postgres and found this
>     >         > query every time. But when i am doing explain on this query then its very
>     >         > quickly updating.
>     >         >
>     >         > 2019-12-20 06:41:12.772 UTC [13411] LOG: duration: 96233.642 ms  execute
>     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >         > PRODUCT_ID=$8
>     >         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL: parameters: $1 = '84.000000',
>     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
>     >         > 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >         > 2019-12-20 06:42:48.667 UTC [12179] LOG: duration: 192255.312 ms  execute
>     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >         > PRODUCT_ID=$8
>     >         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL: parameters: $1 = '84.000000',
>     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
>     >         > 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >         > 2019-12-20 06:43:36.832 UTC [12180] LOG: duration: 240242.603 ms  execute
>     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >         > PRODUCT_ID=$8
>     >         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL: parameters: $1 = '84.000000',
>     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
>     >         > 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >         >
>     >         > BR//
>     >         > Vipin Nirwal
>     >         >
>     >         >
>     >         >
>     >         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>>
>     >         > wrote:
>     >         >
>     >         >> Hi Vipin,
>     >         >>
>     >         >> As per the attached JMeter result, status for the submit_order request is a
>     >         >> warning. There may be an issue related to the cookie or any other request
>     >         >> header. Please compare the HTTP request of JMeter with the request in
>     >         >> browser.
>     >         >>
>     >         >> HTH!
>     >         >>
>     >         >> Best Regards,
>     >         >> Humera Khan
>     >         >>
>     >         >>
>     >         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >         >>
>     >         >>> Hi Jacques,
>     >         >>>
>     >         >>> Thanks for your response.
>     >         >>> I tried with out of the box derby DB too. I am trying with only 5
>     >         >>> concurrent user but still submit order is giving hard time to me.
>     >         >>>
>     >         >>> Looking at jmeter result, it seems submit order API is running in
>     >         >>> sequence. Taking longer time in each submit call. Attached is jmeter
>     >         >> result.
>     >         >>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>     >         >>> execution. Due to this , we are not able to get OrderHeader in
>     >         >>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>     >         >>> error. Is there any other setting i am missing?
>     >         >>>
>     >         >>> PS. If i am trying to submit order in UI, then its not taking more than
>     >         >> 10
>     >         >>> sec. I tried to increase the transaction time out( you suggested in some
>     >         >>> thread , modify TransactionUtil class. Then all order were successful but
>     >         >>> again taking more time).
>     >         >>> I am trying this, if there will be any other finding, will update.
>     >         >>>
>     >         >>> BR//
>     >         >>> Vipin Nirwal
>     >         >>>
>     >         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>     >         >>> [hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >         >>>
>     >         >>>> Hi Vipin,
>     >         >>>>
>     >         >>>> I can see only a reason: an issue to access your OFBiz database. I don't
>     >         >>>> remember such problems reported earlier. Maybe you are forcing too much
>     >         >>>> with
>     >         >>>> Jmeter and you get deadlocks in the DB.
>     >         >>>>
>     >         >>>> Jacques
>     >         >>>>
>     >         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>     >         >>>>> Hi,
>     >         >>>>>
>     >         >>>>> I am facing a weird issue. First submit order is taking longer like
>     >         >>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>     >         >>>> processing time is being increased more than 1 minutes then all order
>     >         >> start
>     >         >>>> failing. I am getting below error message for failed order.
>     >         >>>>> <div id="content-messages" class="content-messages errorMessage"
>     >         >>>>>
>     >         >> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>     >         >>>>>         <p>The Following Errors Occurred:</p>
>     >         >>>>>  <p>Problems getting order header. Cannot check external
>     >         >>>> gateways!</p>
>     >         >>>>>       </div>
>     >         >>>>>
>     >         >>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>     >         >>>> Though few orders are submitted successfully.
>     >         >>>>> Please let me know if someone faced this issue or any solution for
>     >         >>>> this. Is there any
>     >         >>>>> PS. I am using apache jmeter to submit order.
>     >         >>>>>
>     >         >>>>> BR//
>     >         >>>>> Vipin Nirwal
>     >         >>>>>
>     >         >>>>>
>     >         >>>
>     >         >>> --
>     >         >>> Thanks & Regards
>     >         >>> Vipin Nirwal
>     >         >>>
>     >         >
>     >
>     >
>     >
>     >     --
>     >     Thanks & Regards
>     >     Vipin Nirwal
>     >
>     >
>     >
>     > --
>     > Thanks & Regards
>     > Vipin Nirwal
>
>
>
> --
> Thanks & Regards
> Vipin Nirwal

Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Jacques,

I forwarded you the wrong logs. I had these error when i put shipping address country as India but when i changed it to USA then there were no errors. Thanks for your suggestion.
I am attaching the correct logs. It is showing transaction time out. But i am not able to figure out the reason of time out.

On Mon, Dec 23, 2019 at 3:48 PM Jacques Le Roux <[hidden email]> wrote:
Hi Vipin,

If you look at the error.log it's crystal clear:

2019-12-23 05:57:38,307 |sse-nio-8443-exec-21 |TransactionUtil               |E| [TransactionUtil.rollback]
java.lang.Exception: Stack Trace
     at org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:314) [ofbiz.jar:?]
     at org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:290) [ofbiz.jar:?]
     at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:559) [ofbiz.jar:?]
     at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:240) [ofbiz.jar:?]
     at org.apache.ofbiz.service.GenericDispatcherFactory$GenericDispatcher.runSync(GenericDispatcherFactory.java:103) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getExternalShipEstimate(ShippingEvents.java:354) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getShipGroupEstimate(ShippingEvents.java:238) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.loadEstimates(ShippingEstimateWrapper.java:119) [ofbiz.jar:?]
     at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.<init>(ShippingEstimateWrapper.java:96) [ofbiz.jar:?]
[....]
2019-12-23 05:57:38,308 |sse-nio-8443-exec-21 |ShippingEvents                |E| Error getting external shipment cost estimate: Rate inquiry is only
valid for US destinations.
2019-12-23 05:57:38,308 |sse-nio-8443-exec-21 |ServiceUtil                   |E| {errorMessage=A problem occurred calculating shipping. Fees will be
calculated offline., responseMessage=error}
2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |ServiceUtil                   |E| {errorMessage=Rate inquiry is only valid for US destinations.,
responseMessage=error}
2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |ServiceDispatcher             |E| Error in Service [uspsRateInquire]: Rate inquiry is only valid for US
destinations.
2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |TransactionUtil               |E| [TransactionUtil.rollback]
[....]

You get this error multiple times (72 exactly) it cumulates and the DB can't handle it.

You need 1st to fix this issue. I suggest you use no external shipment cost estimates for you profiling

Jacques

Le 23/12/2019 à 07:32, vipin nirwal a écrit :
> Hi Jacques,
>
> Attaching the logs.
> I restarted the postgres DB and submit order was quick for both products. But as i am testing again and again, GZ-2644 is going with same
> latency(very quick, 2-3 sec). But WG-5569 starts taking time in submit order slowly and eventually will start failing.
>
> I am comparing both products and trying to see if any difference that is causing this issue.
>
> BR//
> Vipin Nirwal
>
>
>
> On Sat, Dec 21, 2019 at 6:36 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>> wrote:
>
>     Hi Wipin,
>
>     One thing we know now is that the issue is related to "WG-5569". That's an interesting point. Unfortunately I did not find query_lock.txt very
>     useful.
>
>     As it could be a lot of things, I think a look at the log is needed. It would help if you could extract relevant parts... I mean those related with
>     the lock and a bit around...
>
>     Thanks
>
>     Jacques
>
>     Le 20/12/2019 à 15:19, vipin nirwal a écrit :
>     > Hi Jacques/Humera,
>     >
>     > Thanks for your support.
>     >
>     > When I ran flow with a different product, I did not see any latency in submit order. See attached jmeter log.
>     >
>     > But when I am running flow with product id “WG-5569’, I am getting latency while submitting order.  See attached txt file for query which is
>     taking
>     > exclusive lock.
>     > Any pointer/hint why this is happening, is really appreciable.
>     >
>     > BR//
>     > Vipin Nirwal
>     >
>     > On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >
>     >     Hi Jacques,
>     >
>     >     I am using 18.12 release.
>     >
>     >     BR//
>     >     Vipin Nirwal
>     >
>     >     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>> wrote:
>     >
>     >         Hi Vipin,
>     >
>     >         Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?
>     >
>     >         Thanks
>     >
>     >         Jacques
>     >
>     >         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
>     >         > Hi Humera,
>     >         >
>     >         > Thanks for your reply.
>     >         >
>     >         > I compared  both HTTP request and did not find any difference. Seems ok to
>     >         > me. When i am running concurrent user from jmeter (only 5 threads) and same
>     >         > time, i am trying to submit order from UI, its taking around 30-40 sec or
>     >         > even more from UI too.
>     >         >
>     >         > I logged the queries which are taking longer in postgres and found this
>     >         > query every time. But when i am doing explain on this query then its very
>     >         > quickly updating.
>     >         >
>     >         > 2019-12-20 06:41:12.772 UTC [13411] LOG: duration: 96233.642 ms  execute
>     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >         > PRODUCT_ID=$8
>     >         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL: parameters: $1 = '84.000000',
>     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
>     >         > 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >         > 2019-12-20 06:42:48.667 UTC [12179] LOG: duration: 192255.312 ms  execute
>     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >         > PRODUCT_ID=$8
>     >         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL: parameters: $1 = '84.000000',
>     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
>     >         > 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >         > 2019-12-20 06:43:36.832 UTC [12180] LOG: duration: 240242.603 ms  execute
>     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >         > PRODUCT_ID=$8
>     >         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL: parameters: $1 = '84.000000',
>     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
>     >         > 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >         >
>     >         > BR//
>     >         > Vipin Nirwal
>     >         >
>     >         >
>     >         >
>     >         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>>
>     >         > wrote:
>     >         >
>     >         >> Hi Vipin,
>     >         >>
>     >         >> As per the attached JMeter result, status for the submit_order request is a
>     >         >> warning. There may be an issue related to the cookie or any other request
>     >         >> header. Please compare the HTTP request of JMeter with the request in
>     >         >> browser.
>     >         >>
>     >         >> HTH!
>     >         >>
>     >         >> Best Regards,
>     >         >> Humera Khan
>     >         >>
>     >         >>
>     >         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >         >>
>     >         >>> Hi Jacques,
>     >         >>>
>     >         >>> Thanks for your response.
>     >         >>> I tried with out of the box derby DB too. I am trying with only 5
>     >         >>> concurrent user but still submit order is giving hard time to me.
>     >         >>>
>     >         >>> Looking at jmeter result, it seems submit order API is running in
>     >         >>> sequence. Taking longer time in each submit call. Attached is jmeter
>     >         >> result.
>     >         >>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>     >         >>> execution. Due to this , we are not able to get OrderHeader in
>     >         >>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>     >         >>> error. Is there any other setting i am missing?
>     >         >>>
>     >         >>> PS. If i am trying to submit order in UI, then its not taking more than
>     >         >> 10
>     >         >>> sec. I tried to increase the transaction time out( you suggested in some
>     >         >>> thread , modify TransactionUtil class. Then all order were successful but
>     >         >>> again taking more time).
>     >         >>> I am trying this, if there will be any other finding, will update.
>     >         >>>
>     >         >>> BR//
>     >         >>> Vipin Nirwal
>     >         >>>
>     >         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>     >         >>> [hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >         >>>
>     >         >>>> Hi Vipin,
>     >         >>>>
>     >         >>>> I can see only a reason: an issue to access your OFBiz database. I don't
>     >         >>>> remember such problems reported earlier. Maybe you are forcing too much
>     >         >>>> with
>     >         >>>> Jmeter and you get deadlocks in the DB.
>     >         >>>>
>     >         >>>> Jacques
>     >         >>>>
>     >         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>     >         >>>>> Hi,
>     >         >>>>>
>     >         >>>>> I am facing a weird issue. First submit order is taking longer like
>     >         >>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>     >         >>>> processing time is being increased more than 1 minutes then all order
>     >         >> start
>     >         >>>> failing. I am getting below error message for failed order.
>     >         >>>>> <div id="content-messages" class="content-messages errorMessage"
>     >         >>>>>
>     >         >> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>     >         >>>>>         <p>The Following Errors Occurred:</p>
>     >         >>>>>  <p>Problems getting order header. Cannot check external
>     >         >>>> gateways!</p>
>     >         >>>>>       </div>
>     >         >>>>>
>     >         >>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>     >         >>>> Though few orders are submitted successfully.
>     >         >>>>> Please let me know if someone faced this issue or any solution for
>     >         >>>> this. Is there any
>     >         >>>>> PS. I am using apache jmeter to submit order.
>     >         >>>>>
>     >         >>>>> BR//
>     >         >>>>> Vipin Nirwal
>     >         >>>>>
>     >         >>>>>
>     >         >>>
>     >         >>> --
>     >         >>> Thanks & Regards
>     >         >>> Vipin Nirwal
>     >         >>>
>     >         >
>     >
>     >
>     >
>     >     --
>     >     Thanks & Regards
>     >     Vipin Nirwal
>     >
>     >
>     >
>     > --
>     > Thanks & Regards
>     > Vipin Nirwal
>
>
>
> --
> Thanks & Regards
> Vipin Nirwal



--
Thanks & Regards
Vipin Nirwal

log.zip (72K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Jacques Le Roux
Administrator
I guess you noticed the 1st issue:

2019-12-23 16:22:24,850 |sse-nio-8443-exec-20 |ServiceUtil                   |E| {errorMessage=Problems getting order header. Cannot check external
gateways!:WSCO10034, responseMessage=error}

I  guess this is the error which starts the time-out.

Check CheckOutHelper::checkExternalPayment, it can be 2 types of errors:

  * Not able to  retrieve the OrderHeader (weird)
  * Able to  retrieve the OrderHeader but another error occurs then

Debug by adding log statement in CheckOutHelper::checkExternalPayment...

HTH

Jacques


Le 23/12/2019 à 17:42, vipin nirwal a écrit :

> Hi Jacques,
>
> I forwarded you the wrong logs. I had these error when i put shipping address country as India but when i changed it to USA then there were no
> errors. Thanks for your suggestion.
> I am attaching the correct logs. It is showing transaction time out. But i am not able to figure out the reason of time out.
>
> On Mon, Dec 23, 2019 at 3:48 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>> wrote:
>
>     Hi Vipin,
>
>     If you look at the error.log it's crystal clear:
>
>     2019-12-23 05:57:38,307 |sse-nio-8443-exec-21 |TransactionUtil               |E| [TransactionUtil.rollback]
>     java.lang.Exception: Stack Trace
>          at org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:314) [ofbiz.jar:?]
>          at org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:290) [ofbiz.jar:?]
>          at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:559) [ofbiz.jar:?]
>          at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:240) [ofbiz.jar:?]
>          at org.apache.ofbiz.service.GenericDispatcherFactory$GenericDispatcher.runSync(GenericDispatcherFactory.java:103) [ofbiz.jar:?]
>          at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getExternalShipEstimate(ShippingEvents.java:354) [ofbiz.jar:?]
>          at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getShipGroupEstimate(ShippingEvents.java:238) [ofbiz.jar:?]
>          at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.loadEstimates(ShippingEstimateWrapper.java:119) [ofbiz.jar:?]
>          at org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.<init>(ShippingEstimateWrapper.java:96) [ofbiz.jar:?]
>     [....]
>     2019-12-23 05:57:38,308 |sse-nio-8443-exec-21 |ShippingEvents                |E| Error getting external shipment cost estimate: Rate inquiry is
>     only
>     valid for US destinations.
>     2019-12-23 05:57:38,308 |sse-nio-8443-exec-21 |ServiceUtil                   |E| {errorMessage=A problem occurred calculating shipping. Fees
>     will be
>     calculated offline., responseMessage=error}
>     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |ServiceUtil                   |E| {errorMessage=Rate inquiry is only valid for US destinations.,
>     responseMessage=error}
>     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |ServiceDispatcher             |E| Error in Service [uspsRateInquire]: Rate inquiry is only valid
>     for US
>     destinations.
>     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21 |TransactionUtil               |E| [TransactionUtil.rollback]
>     [....]
>
>     You get this error multiple times (72 exactly) it cumulates and the DB can't handle it.
>
>     You need 1st to fix this issue. I suggest you use no external shipment cost estimates for you profiling
>
>     Jacques
>
>     Le 23/12/2019 à 07:32, vipin nirwal a écrit :
>     > Hi Jacques,
>     >
>     > Attaching the logs.
>     > I restarted the postgres DB and submit order was quick for both products. But as i am testing again and again, GZ-2644 is going with same
>     > latency(very quick, 2-3 sec). But WG-5569 starts taking time in submit order slowly and eventually will start failing.
>     >
>     > I am comparing both products and trying to see if any difference that is causing this issue.
>     >
>     > BR//
>     > Vipin Nirwal
>     >
>     >
>     >
>     > On Sat, Dec 21, 2019 at 6:36 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>> wrote:
>     >
>     >     Hi Wipin,
>     >
>     >     One thing we know now is that the issue is related to "WG-5569". That's an interesting point. Unfortunately I did not find query_lock.txt very
>     >     useful.
>     >
>     >     As it could be a lot of things, I think a look at the log is needed. It would help if you could extract relevant parts... I mean those
>     related with
>     >     the lock and a bit around...
>     >
>     >     Thanks
>     >
>     >     Jacques
>     >
>     >     Le 20/12/2019 à 15:19, vipin nirwal a écrit :
>     >     > Hi Jacques/Humera,
>     >     >
>     >     > Thanks for your support.
>     >     >
>     >     > When I ran flow with a different product, I did not see any latency in submit order. See attached jmeter log.
>     >     >
>     >     > But when I am running flow with product id “WG-5569’, I am getting latency while submitting order.  See attached txt file for query which is
>     >     taking
>     >     > exclusive lock.
>     >     > Any pointer/hint why this is happening, is really appreciable.
>     >     >
>     >     > BR//
>     >     > Vipin Nirwal
>     >     >
>     >     > On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>> <mailto:[hidden email] <mailto:[hidden email]>
>     >     <mailto:[hidden email] <mailto:[hidden email]>>>> wrote:
>     >     >
>     >     >     Hi Jacques,
>     >     >
>     >     >     I am using 18.12 release.
>     >     >
>     >     >     BR//
>     >     >     Vipin Nirwal
>     >     >
>     >     >     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>
>     >     <mailto:[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>>> wrote:
>     >     >
>     >     >         Hi Vipin,
>     >     >
>     >     >         Since, AFAIK, we did not ask yet and that's pretty needed as this stage, which version are you using?
>     >     >
>     >     >         Thanks
>     >     >
>     >     >         Jacques
>     >     >
>     >     >         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
>     >     >         > Hi Humera,
>     >     >         >
>     >     >         > Thanks for your reply.
>     >     >         >
>     >     >         > I compared  both HTTP request and did not find any difference. Seems ok to
>     >     >         > me. When i am running concurrent user from jmeter (only 5 threads) and same
>     >     >         > time, i am trying to submit order from UI, its taking around 30-40 sec or
>     >     >         > even more from UI too.
>     >     >         >
>     >     >         > I logged the queries which are taking longer in postgres and found this
>     >     >         > query every time. But when i am doing explain on this query then its very
>     >     >         > quickly updating.
>     >     >         >
>     >     >         > 2019-12-20 06:41:12.772 UTC [13411] LOG: duration: 96233.642 ms  execute
>     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >     >         > PRODUCT_ID=$8
>     >     >         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL: parameters: $1 = '84.000000',
>     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.537+00', $5 = '2019-12-20
>     >     >         > 06:39:36.527+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >     >         > 2019-12-20 06:42:48.667 UTC [12179] LOG: duration: 192255.312 ms  execute
>     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >     >         > PRODUCT_ID=$8
>     >     >         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL: parameters: $1 = '84.000000',
>     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.41+00', $5 = '2019-12-20
>     >     >         > 06:39:36.403+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >     >         > 2019-12-20 06:43:36.832 UTC [12180] LOG: duration: 240242.603 ms  execute
>     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO SET
>     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
>     >     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
>     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6, CREATED_TX_STAMP=$7 WHERE
>     >     >         > PRODUCT_ID=$8
>     >     >         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL: parameters: $1 = '84.000000',
>     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20 06:39:36.588+00', $5 = '2019-12-20
>     >     >         > 06:39:36.582+00', $6 = '2019-12-18 12:33:35.924+00', $7 = '2019-12-18
>     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
>     >     >         >
>     >     >         > BR//
>     >     >         > Vipin Nirwal
>     >     >         >
>     >     >         >
>     >     >         >
>     >     >         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>
>     >     <mailto:[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>>>>
>     >     >         > wrote:
>     >     >         >
>     >     >         >> Hi Vipin,
>     >     >         >>
>     >     >         >> As per the attached JMeter result, status for the submit_order request is a
>     >     >         >> warning. There may be an issue related to the cookie or any other request
>     >     >         >> header. Please compare the HTTP request of JMeter with the request in
>     >     >         >> browser.
>     >     >         >>
>     >     >         >> HTH!
>     >     >         >>
>     >     >         >> Best Regards,
>     >     >         >> Humera Khan
>     >     >         >>
>     >     >         >>
>     >     >         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <[hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>> <mailto:[hidden email] <mailto:[hidden email]>
>     >     <mailto:[hidden email] <mailto:[hidden email]>>>> wrote:
>     >     >         >>
>     >     >         >>> Hi Jacques,
>     >     >         >>>
>     >     >         >>> Thanks for your response.
>     >     >         >>> I tried with out of the box derby DB too. I am trying with only 5
>     >     >         >>> concurrent user but still submit order is giving hard time to me.
>     >     >         >>>
>     >     >         >>> Looking at jmeter result, it seems submit order API is running in
>     >     >         >>> sequence. Taking longer time in each submit call. Attached is jmeter
>     >     >         >> result.
>     >     >         >>> I debug a bit more. CheckOutEvents.createOrder is taking longer time in
>     >     >         >>> execution. Due to this , we are not able to get OrderHeader in
>     >     >         >>> CheckOutHelper.checkExternalPayment method. Thats why i was getting above
>     >     >         >>> error. Is there any other setting i am missing?
>     >     >         >>>
>     >     >         >>> PS. If i am trying to submit order in UI, then its not taking more than
>     >     >         >> 10
>     >     >         >>> sec. I tried to increase the transaction time out( you suggested in some
>     >     >         >>> thread , modify TransactionUtil class. Then all order were successful but
>     >     >         >>> again taking more time).
>     >     >         >>> I am trying this, if there will be any other finding, will update.
>     >     >         >>>
>     >     >         >>> BR//
>     >     >         >>> Vipin Nirwal
>     >     >         >>>
>     >     >         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
>     >     >         >>> [hidden email] <mailto:[hidden email]> <mailto:[hidden email]
>     <mailto:[hidden email]>> <mailto:[hidden email] <mailto:[hidden email]>
>     >     <mailto:[hidden email] <mailto:[hidden email]>>>> wrote:
>     >     >         >>>
>     >     >         >>>> Hi Vipin,
>     >     >         >>>>
>     >     >         >>>> I can see only a reason: an issue to access your OFBiz database. I don't
>     >     >         >>>> remember such problems reported earlier. Maybe you are forcing too much
>     >     >         >>>> with
>     >     >         >>>> Jmeter and you get deadlocks in the DB.
>     >     >         >>>>
>     >     >         >>>> Jacques
>     >     >         >>>>
>     >     >         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
>     >     >         >>>>> Hi,
>     >     >         >>>>>
>     >     >         >>>>> I am facing a weird issue. First submit order is taking longer like
>     >     >         >>>> 12-20sec . Afterwards each order takes quite longer to submit. If
>     >     >         >>>> processing time is being increased more than 1 minutes then all order
>     >     >         >> start
>     >     >         >>>> failing. I am getting below error message for failed order.
>     >     >         >>>>> <div id="content-messages" class="content-messages errorMessage"
>     >     >         >>>>>
>     >     >         >> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
>     >     >         >>>>>  <p>The Following Errors Occurred:</p>
>     >     >         >>>>>  <p>Problems getting order header. Cannot check external
>     >     >         >>>> gateways!</p>
>     >     >         >>>>>       </div>
>     >     >         >>>>>
>     >     >         >>>>> This error is coming from CheckOutEvents.checkExternalPayment method.
>     >     >         >>>> Though few orders are submitted successfully.
>     >     >         >>>>> Please let me know if someone faced this issue or any solution for
>     >     >         >>>> this. Is there any
>     >     >         >>>>> PS. I am using apache jmeter to submit order.
>     >     >         >>>>>
>     >     >         >>>>> BR//
>     >     >         >>>>> Vipin Nirwal
>     >     >         >>>>>
>     >     >         >>>>>
>     >     >         >>>
>     >     >         >>> --
>     >     >         >>> Thanks & Regards
>     >     >         >>> Vipin Nirwal
>     >     >         >>>
>     >     >         >
>     >     >
>     >     >
>     >     >
>     >     >     --
>     >     >     Thanks & Regards
>     >     >     Vipin Nirwal
>     >     >
>     >     >
>     >     >
>     >     > --
>     >     > Thanks & Regards
>     >     > Vipin Nirwal
>     >
>     >
>     >
>     > --
>     > Thanks & Regards
>     > Vipin Nirwal
>
>
>
> --
> Thanks & Regards
> Vipin Nirwal
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

vipin nirwal
Hi Jacques,

Thanks for the pointer.
I will try to check by putting more debug log. Will let you know if there
is any finding which could be helpful.

BR//
Vipin Nirwal

On Mon, Dec 30, 2019 at 1:55 PM Jacques Le Roux <
[hidden email]> wrote:

> I guess you noticed the 1st issue:
>
> 2019-12-23 16:22:24,850 |sse-nio-8443-exec-20
> |ServiceUtil                   |E| {errorMessage=Problems getting order
> header. Cannot check external
> gateways!:WSCO10034, responseMessage=error}
>
> I  guess this is the error which starts the time-out.
>
> Check CheckOutHelper::checkExternalPayment, it can be 2 types of errors:
>
>   * Not able to  retrieve the OrderHeader (weird)
>   * Able to  retrieve the OrderHeader but another error occurs then
>
> Debug by adding log statement in CheckOutHelper::checkExternalPayment...
>
> HTH
>
> Jacques
>
>
> Le 23/12/2019 à 17:42, vipin nirwal a écrit :
> > Hi Jacques,
> >
> > I forwarded you the wrong logs. I had these error when i put shipping
> address country as India but when i changed it to USA then there were no
> > errors. Thanks for your suggestion.
> > I am attaching the correct logs. It is showing transaction time out. But
> i am not able to figure out the reason of time out.
> >
> > On Mon, Dec 23, 2019 at 3:48 PM Jacques Le Roux <
> [hidden email] <mailto:[hidden email]>> wrote:
> >
> >     Hi Vipin,
> >
> >     If you look at the error.log it's crystal clear:
> >
> >     2019-12-23 05:57:38,307 |sse-nio-8443-exec-21
> |TransactionUtil               |E| [TransactionUtil.rollback]
> >     java.lang.Exception: Stack Trace
> >          at
> org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:314)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:290)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:559)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:240)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.service.GenericDispatcherFactory$GenericDispatcher.runSync(GenericDispatcherFactory.java:103)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getExternalShipEstimate(ShippingEvents.java:354)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getShipGroupEstimate(ShippingEvents.java:238)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.loadEstimates(ShippingEstimateWrapper.java:119)
> [ofbiz.jar:?]
> >          at
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.<init>(ShippingEstimateWrapper.java:96)
> [ofbiz.jar:?]
> >     [....]
> >     2019-12-23 05:57:38,308 |sse-nio-8443-exec-21
> |ShippingEvents                |E| Error getting external shipment cost
> estimate: Rate inquiry is
> >     only
> >     valid for US destinations.
> >     2019-12-23 05:57:38,308 |sse-nio-8443-exec-21
> |ServiceUtil                   |E| {errorMessage=A problem occurred
> calculating shipping. Fees
> >     will be
> >     calculated offline., responseMessage=error}
> >     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21
> |ServiceUtil                   |E| {errorMessage=Rate inquiry is only valid
> for US destinations.,
> >     responseMessage=error}
> >     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21
> |ServiceDispatcher             |E| Error in Service [uspsRateInquire]: Rate
> inquiry is only valid
> >     for US
> >     destinations.
> >     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21
> |TransactionUtil               |E| [TransactionUtil.rollback]
> >     [....]
> >
> >     You get this error multiple times (72 exactly) it cumulates and the
> DB can't handle it.
> >
> >     You need 1st to fix this issue. I suggest you use no external
> shipment cost estimates for you profiling
> >
> >     Jacques
> >
> >     Le 23/12/2019 à 07:32, vipin nirwal a écrit :
> >     > Hi Jacques,
> >     >
> >     > Attaching the logs.
> >     > I restarted the postgres DB and submit order was quick for both
> products. But as i am testing again and again, GZ-2644 is going with same
> >     > latency(very quick, 2-3 sec). But WG-5569 starts taking time in
> submit order slowly and eventually will start failing.
> >     >
> >     > I am comparing both products and trying to see if any difference
> that is causing this issue.
> >     >
> >     > BR//
> >     > Vipin Nirwal
> >     >
> >     >
> >     >
> >     > On Sat, Dec 21, 2019 at 6:36 PM Jacques Le Roux <
> [hidden email] <mailto:[hidden email]>
> >     <mailto:[hidden email] <mailto:
> [hidden email]>>> wrote:
> >     >
> >     >     Hi Wipin,
> >     >
> >     >     One thing we know now is that the issue is related to
> "WG-5569". That's an interesting point. Unfortunately I did not find
> query_lock.txt very
> >     >     useful.
> >     >
> >     >     As it could be a lot of things, I think a look at the log is
> needed. It would help if you could extract relevant parts... I mean those
> >     related with
> >     >     the lock and a bit around...
> >     >
> >     >     Thanks
> >     >
> >     >     Jacques
> >     >
> >     >     Le 20/12/2019 à 15:19, vipin nirwal a écrit :
> >     >     > Hi Jacques/Humera,
> >     >     >
> >     >     > Thanks for your support.
> >     >     >
> >     >     > When I ran flow with a different product, I did not see any
> latency in submit order. See attached jmeter log.
> >     >     >
> >     >     > But when I am running flow with product id “WG-5569’, I am
> getting latency while submitting order.  See attached txt file for query
> which is
> >     >     taking
> >     >     > exclusive lock.
> >     >     > Any pointer/hint why this is happening, is really
> appreciable.
> >     >     >
> >     >     > BR//
> >     >     > Vipin Nirwal
> >     >     >
> >     >     > On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <
> [hidden email] <mailto:[hidden email]> <mailto:
> [hidden email]
> >     <mailto:[hidden email]>> <mailto:[hidden email] <mailto:
> [hidden email]>
> >     >     <mailto:[hidden email] <mailto:[hidden email]>>>>
> wrote:
> >     >     >
> >     >     >     Hi Jacques,
> >     >     >
> >     >     >     I am using 18.12 release.
> >     >     >
> >     >     >     BR//
> >     >     >     Vipin Nirwal
> >     >     >
> >     >     >     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> [hidden email] <mailto:[hidden email]>
> >     <mailto:[hidden email] <mailto:
> [hidden email]>>
> >     >     <mailto:[hidden email] <mailto:
> [hidden email]> <mailto:[hidden email]
> >     <mailto:[hidden email]>>>> wrote:
> >     >     >
> >     >     >         Hi Vipin,
> >     >     >
> >     >     >         Since, AFAIK, we did not ask yet and that's pretty
> needed as this stage, which version are you using?
> >     >     >
> >     >     >         Thanks
> >     >     >
> >     >     >         Jacques
> >     >     >
> >     >     >         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
> >     >     >         > Hi Humera,
> >     >     >         >
> >     >     >         > Thanks for your reply.
> >     >     >         >
> >     >     >         > I compared  both HTTP request and did not find any
> difference. Seems ok to
> >     >     >         > me. When i am running concurrent user from jmeter
> (only 5 threads) and same
> >     >     >         > time, i am trying to submit order from UI, its
> taking around 30-40 sec or
> >     >     >         > even more from UI too.
> >     >     >         >
> >     >     >         > I logged the queries which are taking longer in
> postgres and found this
> >     >     >         > query every time. But when i am doing explain on
> this query then its very
> >     >     >         > quickly updating.
> >     >     >         >
> >     >     >         > 2019-12-20 06:41:12.772 UTC [13411] LOG: duration:
> 96233.642 ms  execute
> >     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO
> SET
> >     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> >     >     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> >     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6,
> CREATED_TX_STAMP=$7 WHERE
> >     >     >         > PRODUCT_ID=$8
> >     >     >         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL:
> parameters: $1 = '84.000000',
> >     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20
> 06:39:36.537+00', $5 = '2019-12-20
> >     >     >         > 06:39:36.527+00', $6 = '2019-12-18
> 12:33:35.924+00', $7 = '2019-12-18
> >     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
> >     >     >         > 2019-12-20 06:42:48.667 UTC [12179] LOG: duration:
> 192255.312 ms  execute
> >     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO
> SET
> >     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> >     >     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> >     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6,
> CREATED_TX_STAMP=$7 WHERE
> >     >     >         > PRODUCT_ID=$8
> >     >     >         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL:
> parameters: $1 = '84.000000',
> >     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20
> 06:39:36.41+00', $5 = '2019-12-20
> >     >     >         > 06:39:36.403+00', $6 = '2019-12-18
> 12:33:35.924+00', $7 = '2019-12-18
> >     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
> >     >     >         > 2019-12-20 06:43:36.832 UTC [12180] LOG: duration:
> 240242.603 ms  execute
> >     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO
> SET
> >     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> >     >     >         > AVERAGE_CUSTOMER_RATING=$3, LAST_UPDATED_STAMP=$4,
> >     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6,
> CREATED_TX_STAMP=$7 WHERE
> >     >     >         > PRODUCT_ID=$8
> >     >     >         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL:
> parameters: $1 = '84.000000',
> >     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20
> 06:39:36.588+00', $5 = '2019-12-20
> >     >     >         > 06:39:36.582+00', $6 = '2019-12-18
> 12:33:35.924+00', $7 = '2019-12-18
> >     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
> >     >     >         >
> >     >     >         > BR//
> >     >     >         > Vipin Nirwal
> >     >     >         >
> >     >     >         >
> >     >     >         >
> >     >     >         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <
> [hidden email] <mailto:[hidden email]>
> >     <mailto:[hidden email] <mailto:
> [hidden email]>>
> >     >     <mailto:[hidden email] <mailto:
> [hidden email]> <mailto:[hidden email]
> >     <mailto:[hidden email]>>>>
> >     >     >         > wrote:
> >     >     >         >
> >     >     >         >> Hi Vipin,
> >     >     >         >>
> >     >     >         >> As per the attached JMeter result, status for the
> submit_order request is a
> >     >     >         >> warning. There may be an issue related to the
> cookie or any other request
> >     >     >         >> header. Please compare the HTTP request of JMeter
> with the request in
> >     >     >         >> browser.
> >     >     >         >>
> >     >     >         >> HTH!
> >     >     >         >>
> >     >     >         >> Best Regards,
> >     >     >         >> Humera Khan
> >     >     >         >>
> >     >     >         >>
> >     >     >         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <
> [hidden email] <mailto:[hidden email]> <mailto:
> [hidden email]
> >     <mailto:[hidden email]>> <mailto:[hidden email] <mailto:
> [hidden email]>
> >     >     <mailto:[hidden email] <mailto:[hidden email]>>>>
> wrote:
> >     >     >         >>
> >     >     >         >>> Hi Jacques,
> >     >     >         >>>
> >     >     >         >>> Thanks for your response.
> >     >     >         >>> I tried with out of the box derby DB too. I am
> trying with only 5
> >     >     >         >>> concurrent user but still submit order is giving
> hard time to me.
> >     >     >         >>>
> >     >     >         >>> Looking at jmeter result, it seems submit order
> API is running in
> >     >     >         >>> sequence. Taking longer time in each submit
> call. Attached is jmeter
> >     >     >         >> result.
> >     >     >         >>> I debug a bit more. CheckOutEvents.createOrder
> is taking longer time in
> >     >     >         >>> execution. Due to this , we are not able to get
> OrderHeader in
> >     >     >         >>> CheckOutHelper.checkExternalPayment method.
> Thats why i was getting above
> >     >     >         >>> error. Is there any other setting i am missing?
> >     >     >         >>>
> >     >     >         >>> PS. If i am trying to submit order in UI, then
> its not taking more than
> >     >     >         >> 10
> >     >     >         >>> sec. I tried to increase the transaction time
> out( you suggested in some
> >     >     >         >>> thread , modify TransactionUtil class. Then all
> order were successful but
> >     >     >         >>> again taking more time).
> >     >     >         >>> I am trying this, if there will be any other
> finding, will update.
> >     >     >         >>>
> >     >     >         >>> BR//
> >     >     >         >>> Vipin Nirwal
> >     >     >         >>>
> >     >     >         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le Roux <
> >     >     >         >>> [hidden email] <mailto:
> [hidden email]> <mailto:[hidden email]
> >     <mailto:[hidden email]>> <mailto:
> [hidden email] <mailto:[hidden email]>
> >     >     <mailto:[hidden email] <mailto:
> [hidden email]>>>> wrote:
> >     >     >         >>>
> >     >     >         >>>> Hi Vipin,
> >     >     >         >>>>
> >     >     >         >>>> I can see only a reason: an issue to access
> your OFBiz database. I don't
> >     >     >         >>>> remember such problems reported earlier. Maybe
> you are forcing too much
> >     >     >         >>>> with
> >     >     >         >>>> Jmeter and you get deadlocks in the DB.
> >     >     >         >>>>
> >     >     >         >>>> Jacques
> >     >     >         >>>>
> >     >     >         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
> >     >     >         >>>>> Hi,
> >     >     >         >>>>>
> >     >     >         >>>>> I am facing a weird issue. First submit order
> is taking longer like
> >     >     >         >>>> 12-20sec . Afterwards each order takes quite
> longer to submit. If
> >     >     >         >>>> processing time is being increased more than 1
> minutes then all order
> >     >     >         >> start
> >     >     >         >>>> failing. I am getting below error message for
> failed order.
> >     >     >         >>>>> <div id="content-messages"
> class="content-messages errorMessage"
> >     >     >         >>>>>
> >     >     >         >>
> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
> >     >     >         >>>>>  <p>The Following Errors Occurred:</p>
> >     >     >         >>>>>  <p>Problems getting order header. Cannot
> check external
> >     >     >         >>>> gateways!</p>
> >     >     >         >>>>>       </div>
> >     >     >         >>>>>
> >     >     >         >>>>> This error is coming from
> CheckOutEvents.checkExternalPayment method.
> >     >     >         >>>> Though few orders are submitted successfully.
> >     >     >         >>>>> Please let me know if someone faced this issue
> or any solution for
> >     >     >         >>>> this. Is there any
> >     >     >         >>>>> PS. I am using apache jmeter to submit order.
> >     >     >         >>>>>
> >     >     >         >>>>> BR//
> >     >     >         >>>>> Vipin Nirwal
> >     >     >         >>>>>
> >     >     >         >>>>>
> >     >     >         >>>
> >     >     >         >>> --
> >     >     >         >>> Thanks & Regards
> >     >     >         >>> Vipin Nirwal
> >     >     >         >>>
> >     >     >         >
> >     >     >
> >     >     >
> >     >     >
> >     >     >     --
> >     >     >     Thanks & Regards
> >     >     >     Vipin Nirwal
> >     >     >
> >     >     >
> >     >     >
> >     >     > --
> >     >     > Thanks & Regards
> >     >     > Vipin Nirwal
> >     >
> >     >
> >     >
> >     > --
> >     > Thanks & Regards
> >     > Vipin Nirwal
> >
> >
> >
> > --
> > Thanks & Regards
> > Vipin Nirwal
>


--
Thanks & Regards
Vipin Nirwal
Reply | Threaded
Open this post in threaded view
|

Re: Submit order taking longer and afterwards failing.

Ankush Upadhyay-2
Hello Vipin,
Can you please check CheckoutEvents.createOrder() is setting orderId in
request attribute on *checkOutHelper.createOrder* success.
It seems that orderId is null for some reason in request attribute that end
up with error *Problems getting order header. Cannot check external
gateways*.

Kind Regards,
Ankush Upadhyay
Senior Technical Consultant

*HotWax Systems*
*Enterprise open source experts*
cell: +91-8109201285
office: 0731-409-3684
http://www.hotwaxsystems.com


On Tue, Dec 31, 2019 at 10:58 AM vipin nirwal <[hidden email]> wrote:

> Hi Jacques,
>
> Thanks for the pointer.
> I will try to check by putting more debug log. Will let you know if there
> is any finding which could be helpful.
>
> BR//
> Vipin Nirwal
>
> On Mon, Dec 30, 2019 at 1:55 PM Jacques Le Roux <
> [hidden email]> wrote:
>
> > I guess you noticed the 1st issue:
> >
> > 2019-12-23 16:22:24,850 |sse-nio-8443-exec-20
> > |ServiceUtil                   |E| {errorMessage=Problems getting order
> > header. Cannot check external
> > gateways!:WSCO10034, responseMessage=error}
> >
> > I  guess this is the error which starts the time-out.
> >
> > Check CheckOutHelper::checkExternalPayment, it can be 2 types of errors:
> >
> >   * Not able to  retrieve the OrderHeader (weird)
> >   * Able to  retrieve the OrderHeader but another error occurs then
> >
> > Debug by adding log statement in CheckOutHelper::checkExternalPayment...
> >
> > HTH
> >
> > Jacques
> >
> >
> > Le 23/12/2019 à 17:42, vipin nirwal a écrit :
> > > Hi Jacques,
> > >
> > > I forwarded you the wrong logs. I had these error when i put shipping
> > address country as India but when i changed it to USA then there were no
> > > errors. Thanks for your suggestion.
> > > I am attaching the correct logs. It is showing transaction time out.
> But
> > i am not able to figure out the reason of time out.
> > >
> > > On Mon, Dec 23, 2019 at 3:48 PM Jacques Le Roux <
> > [hidden email] <mailto:[hidden email]>>
> wrote:
> > >
> > >     Hi Vipin,
> > >
> > >     If you look at the error.log it's crystal clear:
> > >
> > >     2019-12-23 05:57:38,307 |sse-nio-8443-exec-21
> > |TransactionUtil               |E| [TransactionUtil.rollback]
> > >     java.lang.Exception: Stack Trace
> > >          at
> >
> org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:314)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.entity.transaction.TransactionUtil.rollback(TransactionUtil.java:290)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:559)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:240)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.service.GenericDispatcherFactory$GenericDispatcher.runSync(GenericDispatcherFactory.java:103)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getExternalShipEstimate(ShippingEvents.java:354)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEvents.getShipGroupEstimate(ShippingEvents.java:238)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.loadEstimates(ShippingEstimateWrapper.java:119)
> > [ofbiz.jar:?]
> > >          at
> >
> org.apache.ofbiz.order.shoppingcart.shipping.ShippingEstimateWrapper.<init>(ShippingEstimateWrapper.java:96)
> > [ofbiz.jar:?]
> > >     [....]
> > >     2019-12-23 05:57:38,308 |sse-nio-8443-exec-21
> > |ShippingEvents                |E| Error getting external shipment cost
> > estimate: Rate inquiry is
> > >     only
> > >     valid for US destinations.
> > >     2019-12-23 05:57:38,308 |sse-nio-8443-exec-21
> > |ServiceUtil                   |E| {errorMessage=A problem occurred
> > calculating shipping. Fees
> > >     will be
> > >     calculated offline., responseMessage=error}
> > >     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21
> > |ServiceUtil                   |E| {errorMessage=Rate inquiry is only
> valid
> > for US destinations.,
> > >     responseMessage=error}
> > >     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21
> > |ServiceDispatcher             |E| Error in Service [uspsRateInquire]:
> Rate
> > inquiry is only valid
> > >     for US
> > >     destinations.
> > >     2019-12-23 05:57:38,310 |sse-nio-8443-exec-21
> > |TransactionUtil               |E| [TransactionUtil.rollback]
> > >     [....]
> > >
> > >     You get this error multiple times (72 exactly) it cumulates and the
> > DB can't handle it.
> > >
> > >     You need 1st to fix this issue. I suggest you use no external
> > shipment cost estimates for you profiling
> > >
> > >     Jacques
> > >
> > >     Le 23/12/2019 à 07:32, vipin nirwal a écrit :
> > >     > Hi Jacques,
> > >     >
> > >     > Attaching the logs.
> > >     > I restarted the postgres DB and submit order was quick for both
> > products. But as i am testing again and again, GZ-2644 is going with same
> > >     > latency(very quick, 2-3 sec). But WG-5569 starts taking time in
> > submit order slowly and eventually will start failing.
> > >     >
> > >     > I am comparing both products and trying to see if any difference
> > that is causing this issue.
> > >     >
> > >     > BR//
> > >     > Vipin Nirwal
> > >     >
> > >     >
> > >     >
> > >     > On Sat, Dec 21, 2019 at 6:36 PM Jacques Le Roux <
> > [hidden email] <mailto:[hidden email]>
> > >     <mailto:[hidden email] <mailto:
> > [hidden email]>>> wrote:
> > >     >
> > >     >     Hi Wipin,
> > >     >
> > >     >     One thing we know now is that the issue is related to
> > "WG-5569". That's an interesting point. Unfortunately I did not find
> > query_lock.txt very
> > >     >     useful.
> > >     >
> > >     >     As it could be a lot of things, I think a look at the log is
> > needed. It would help if you could extract relevant parts... I mean those
> > >     related with
> > >     >     the lock and a bit around...
> > >     >
> > >     >     Thanks
> > >     >
> > >     >     Jacques
> > >     >
> > >     >     Le 20/12/2019 à 15:19, vipin nirwal a écrit :
> > >     >     > Hi Jacques/Humera,
> > >     >     >
> > >     >     > Thanks for your support.
> > >     >     >
> > >     >     > When I ran flow with a different product, I did not see any
> > latency in submit order. See attached jmeter log.
> > >     >     >
> > >     >     > But when I am running flow with product id “WG-5569’, I am
> > getting latency while submitting order.  See attached txt file for query
> > which is
> > >     >     taking
> > >     >     > exclusive lock.
> > >     >     > Any pointer/hint why this is happening, is really
> > appreciable.
> > >     >     >
> > >     >     > BR//
> > >     >     > Vipin Nirwal
> > >     >     >
> > >     >     > On Fri, Dec 20, 2019 at 2:23 PM vipin nirwal <
> > [hidden email] <mailto:[hidden email]> <mailto:
> > [hidden email]
> > >     <mailto:[hidden email]>> <mailto:[hidden email]
> <mailto:
> > [hidden email]>
> > >     >     <mailto:[hidden email] <mailto:[hidden email]
> >>>>
> > wrote:
> > >     >     >
> > >     >     >     Hi Jacques,
> > >     >     >
> > >     >     >     I am using 18.12 release.
> > >     >     >
> > >     >     >     BR//
> > >     >     >     Vipin Nirwal
> > >     >     >
> > >     >     >     On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> > [hidden email] <mailto:[hidden email]>
> > >     <mailto:[hidden email] <mailto:
> > [hidden email]>>
> > >     >     <mailto:[hidden email] <mailto:
> > [hidden email]> <mailto:[hidden email]
> > >     <mailto:[hidden email]>>>> wrote:
> > >     >     >
> > >     >     >         Hi Vipin,
> > >     >     >
> > >     >     >         Since, AFAIK, we did not ask yet and that's pretty
> > needed as this stage, which version are you using?
> > >     >     >
> > >     >     >         Thanks
> > >     >     >
> > >     >     >         Jacques
> > >     >     >
> > >     >     >         Le 20/12/2019 à 07:53, vipin nirwal a écrit :
> > >     >     >         > Hi Humera,
> > >     >     >         >
> > >     >     >         > Thanks for your reply.
> > >     >     >         >
> > >     >     >         > I compared  both HTTP request and did not find
> any
> > difference. Seems ok to
> > >     >     >         > me. When i am running concurrent user from jmeter
> > (only 5 threads) and same
> > >     >     >         > time, i am trying to submit order from UI, its
> > taking around 30-40 sec or
> > >     >     >         > even more from UI too.
> > >     >     >         >
> > >     >     >         > I logged the queries which are taking longer in
> > postgres and found this
> > >     >     >         > query every time. But when i am doing explain on
> > this query then its very
> > >     >     >         > quickly updating.
> > >     >     >         >
> > >     >     >         > 2019-12-20 06:41:12.772 UTC [13411] LOG:
> duration:
> > 96233.642 ms  execute
> > >     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO
> > SET
> > >     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> > >     >     >         > AVERAGE_CUSTOMER_RATING=$3,
> LAST_UPDATED_STAMP=$4,
> > >     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6,
> > CREATED_TX_STAMP=$7 WHERE
> > >     >     >         > PRODUCT_ID=$8
> > >     >     >         > 2019-12-20 06:41:12.772 UTC [13411] DETAIL:
> > parameters: $1 = '84.000000',
> > >     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20
> > 06:39:36.537+00', $5 = '2019-12-20
> > >     >     >         > 06:39:36.527+00', $6 = '2019-12-18
> > 12:33:35.924+00', $7 = '2019-12-18
> > >     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
> > >     >     >         > 2019-12-20 06:42:48.667 UTC [12179] LOG:
> duration:
> > 192255.312 ms  execute
> > >     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO
> > SET
> > >     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> > >     >     >         > AVERAGE_CUSTOMER_RATING=$3,
> LAST_UPDATED_STAMP=$4,
> > >     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6,
> > CREATED_TX_STAMP=$7 WHERE
> > >     >     >         > PRODUCT_ID=$8
> > >     >     >         > 2019-12-20 06:42:48.667 UTC [12179] DETAIL:
> > parameters: $1 = '84.000000',
> > >     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20
> > 06:39:36.41+00', $5 = '2019-12-20
> > >     >     >         > 06:39:36.403+00', $6 = '2019-12-18
> > 12:33:35.924+00', $7 = '2019-12-18
> > >     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
> > >     >     >         > 2019-12-20 06:43:36.832 UTC [12180] LOG:
> duration:
> > 240242.603 ms  execute
> > >     >     >         > <unnamed>: UPDATE public.PRODUCT_CALCULATED_INFO
> > SET
> > >     >     >         > TOTAL_QUANTITY_ORDERED=$1, TOTAL_TIMES_VIEWED=$2,
> > >     >     >         > AVERAGE_CUSTOMER_RATING=$3,
> LAST_UPDATED_STAMP=$4,
> > >     >     >         > LAST_UPDATED_TX_STAMP=$5, CREATED_STAMP=$6,
> > CREATED_TX_STAMP=$7 WHERE
> > >     >     >         > PRODUCT_ID=$8
> > >     >     >         > 2019-12-20 06:43:36.832 UTC [12180] DETAIL:
> > parameters: $1 = '84.000000',
> > >     >     >         > $2 = NULL, $3 = NULL, $4 = '2019-12-20
> > 06:39:36.588+00', $5 = '2019-12-20
> > >     >     >         > 06:39:36.582+00', $6 = '2019-12-18
> > 12:33:35.924+00', $7 = '2019-12-18
> > >     >     >         > 12:33:35.901+00', $8 = 'WG-5569'
> > >     >     >         >
> > >     >     >         > BR//
> > >     >     >         > Vipin Nirwal
> > >     >     >         >
> > >     >     >         >
> > >     >     >         >
> > >     >     >         > On Fri, Dec 20, 2019 at 10:38 AM Humera Khan <
> > [hidden email] <mailto:[hidden email]>
> > >     <mailto:[hidden email] <mailto:
> > [hidden email]>>
> > >     >     <mailto:[hidden email] <mailto:
> > [hidden email]> <mailto:[hidden email]
> > >     <mailto:[hidden email]>>>>
> > >     >     >         > wrote:
> > >     >     >         >
> > >     >     >         >> Hi Vipin,
> > >     >     >         >>
> > >     >     >         >> As per the attached JMeter result, status for
> the
> > submit_order request is a
> > >     >     >         >> warning. There may be an issue related to the
> > cookie or any other request
> > >     >     >         >> header. Please compare the HTTP request of
> JMeter
> > with the request in
> > >     >     >         >> browser.
> > >     >     >         >>
> > >     >     >         >> HTH!
> > >     >     >         >>
> > >     >     >         >> Best Regards,
> > >     >     >         >> Humera Khan
> > >     >     >         >>
> > >     >     >         >>
> > >     >     >         >> On Thu, Dec 19, 2019 at 9:55 PM vipin nirwal <
> > [hidden email] <mailto:[hidden email]> <mailto:
> > [hidden email]
> > >     <mailto:[hidden email]>> <mailto:[hidden email]
> <mailto:
> > [hidden email]>
> > >     >     <mailto:[hidden email] <mailto:[hidden email]
> >>>>
> > wrote:
> > >     >     >         >>
> > >     >     >         >>> Hi Jacques,
> > >     >     >         >>>
> > >     >     >         >>> Thanks for your response.
> > >     >     >         >>> I tried with out of the box derby DB too. I am
> > trying with only 5
> > >     >     >         >>> concurrent user but still submit order is
> giving
> > hard time to me.
> > >     >     >         >>>
> > >     >     >         >>> Looking at jmeter result, it seems submit order
> > API is running in
> > >     >     >         >>> sequence. Taking longer time in each submit
> > call. Attached is jmeter
> > >     >     >         >> result.
> > >     >     >         >>> I debug a bit more. CheckOutEvents.createOrder
> > is taking longer time in
> > >     >     >         >>> execution. Due to this , we are not able to get
> > OrderHeader in
> > >     >     >         >>> CheckOutHelper.checkExternalPayment method.
> > Thats why i was getting above
> > >     >     >         >>> error. Is there any other setting i am missing?
> > >     >     >         >>>
> > >     >     >         >>> PS. If i am trying to submit order in UI, then
> > its not taking more than
> > >     >     >         >> 10
> > >     >     >         >>> sec. I tried to increase the transaction time
> > out( you suggested in some
> > >     >     >         >>> thread , modify TransactionUtil class. Then all
> > order were successful but
> > >     >     >         >>> again taking more time).
> > >     >     >         >>> I am trying this, if there will be any other
> > finding, will update.
> > >     >     >         >>>
> > >     >     >         >>> BR//
> > >     >     >         >>> Vipin Nirwal
> > >     >     >         >>>
> > >     >     >         >>> On Thu, Dec 19, 2019 at 6:46 PM Jacques Le
> Roux <
> > >     >     >         >>> [hidden email] <mailto:
> > [hidden email]> <mailto:[hidden email]
> > >     <mailto:[hidden email]>> <mailto:
> > [hidden email] <mailto:[hidden email]>
> > >     >     <mailto:[hidden email] <mailto:
> > [hidden email]>>>> wrote:
> > >     >     >         >>>
> > >     >     >         >>>> Hi Vipin,
> > >     >     >         >>>>
> > >     >     >         >>>> I can see only a reason: an issue to access
> > your OFBiz database. I don't
> > >     >     >         >>>> remember such problems reported earlier. Maybe
> > you are forcing too much
> > >     >     >         >>>> with
> > >     >     >         >>>> Jmeter and you get deadlocks in the DB.
> > >     >     >         >>>>
> > >     >     >         >>>> Jacques
> > >     >     >         >>>>
> > >     >     >         >>>> Le 18/12/2019 à 06:19, vipin nirwal a écrit :
> > >     >     >         >>>>> Hi,
> > >     >     >         >>>>>
> > >     >     >         >>>>> I am facing a weird issue. First submit order
> > is taking longer like
> > >     >     >         >>>> 12-20sec . Afterwards each order takes quite
> > longer to submit. If
> > >     >     >         >>>> processing time is being increased more than 1
> > minutes then all order
> > >     >     >         >> start
> > >     >     >         >>>> failing. I am getting below error message for
> > failed order.
> > >     >     >         >>>>> <div id="content-messages"
> > class="content-messages errorMessage"
> > >     >     >         >>>>>
> > >     >     >         >>
> >
> onclick="document.getElementById('content-messages').parentNode.removeChild(this)">
> > >     >     >         >>>>>  <p>The Following Errors Occurred:</p>
> > >     >     >         >>>>>  <p>Problems getting order header. Cannot
> > check external
> > >     >     >         >>>> gateways!</p>
> > >     >     >         >>>>>       </div>
> > >     >     >         >>>>>
> > >     >     >         >>>>> This error is coming from
> > CheckOutEvents.checkExternalPayment method.
> > >     >     >         >>>> Though few orders are submitted successfully.
> > >     >     >         >>>>> Please let me know if someone faced this
> issue
> > or any solution for
> > >     >     >         >>>> this. Is there any
> > >     >     >         >>>>> PS. I am using apache jmeter to submit order.
> > >     >     >         >>>>>
> > >     >     >         >>>>> BR//
> > >     >     >         >>>>> Vipin Nirwal
> > >     >     >         >>>>>
> > >     >     >         >>>>>
> > >     >     >         >>>
> > >     >     >         >>> --
> > >     >     >         >>> Thanks & Regards
> > >     >     >         >>> Vipin Nirwal
> > >     >     >         >>>
> > >     >     >         >
> > >     >     >
> > >     >     >
> > >     >     >
> > >     >     >     --
> > >     >     >     Thanks & Regards
> > >     >     >     Vipin Nirwal
> > >     >     >
> > >     >     >
> > >     >     >
> > >     >     > --
> > >     >     > Thanks & Regards
> > >     >     > Vipin Nirwal
> > >     >
> > >     >
> > >     >
> > >     > --
> > >     > Thanks & Regards
> > >     > Vipin Nirwal
> > >
> > >
> > >
> > > --
> > > Thanks & Regards
> > > Vipin Nirwal
> >
>
>
> --
> Thanks & Regards
> Vipin Nirwal
>