You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ofbiz.apache.org by vipin nirwal <ni...@gmail.com> on 2019/12/18 05:19:05 UTC
Submit order taking longer and afterwards failing.
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
Re: Submit order taking longer and afterwards failing.
Posted by Ankush Upadhyay <an...@hotwaxsystems.com>.
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 <ni...@gmail.com> 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 <
> jacques.le.roux@les7arts.com> 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 <
> > jacques.le.roux@les7arts.com <ma...@les7arts.com>>
> 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 <
> > jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > > <mailto:jacques.le.roux@les7arts.com <mailto:
> > jacques.le.roux@les7arts.com>>> 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 <
> > nirwal.ims@gmail.com <ma...@gmail.com> <mailto:
> > nirwal.ims@gmail.com
> > > <ma...@gmail.com>> <mailto:nirwal.ims@gmail.com
> <mailto:
> > nirwal.ims@gmail.com>
> > > > <mailto:nirwal.ims@gmail.com <mailto:nirwal.ims@gmail.com
> >>>>
> > wrote:
> > > > >
> > > > > Hi Jacques,
> > > > >
> > > > > I am using 18.12 release.
> > > > >
> > > > > BR//
> > > > > Vipin Nirwal
> > > > >
> > > > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> > jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > > <mailto:jacques.le.roux@les7arts.com <mailto:
> > jacques.le.roux@les7arts.com>>
> > > > <mailto:jacques.le.roux@les7arts.com <mailto:
> > jacques.le.roux@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> > > <ma...@les7arts.com>>>> 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 <
> > humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>
> > > <mailto:humera.khan@hotwaxsystems.com <mailto:
> > humera.khan@hotwaxsystems.com>>
> > > > <mailto:humera.khan@hotwaxsystems.com <mailto:
> > humera.khan@hotwaxsystems.com> <mailto:humera.khan@hotwaxsystems.com
> > > <ma...@hotwaxsystems.com>>>>
> > > > > > 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 <
> > nirwal.ims@gmail.com <ma...@gmail.com> <mailto:
> > nirwal.ims@gmail.com
> > > <ma...@gmail.com>> <mailto:nirwal.ims@gmail.com
> <mailto:
> > nirwal.ims@gmail.com>
> > > > <mailto:nirwal.ims@gmail.com <mailto:nirwal.ims@gmail.com
> >>>>
> > 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 <
> > > > > >>> jacques.le.roux@les7arts.com <mailto:
> > jacques.le.roux@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> > > <ma...@les7arts.com>> <mailto:
> > jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > > > <mailto:jacques.le.roux@les7arts.com <mailto:
> > jacques.le.roux@les7arts.com>>>> 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
>
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
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 <
jacques.le.roux@les7arts.com> 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 <
> jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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 <
> jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > <mailto:jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com>>> 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 <
> nirwal.ims@gmail.com <ma...@gmail.com> <mailto:
> nirwal.ims@gmail.com
> > <ma...@gmail.com>> <mailto:nirwal.ims@gmail.com <mailto:
> nirwal.ims@gmail.com>
> > > <mailto:nirwal.ims@gmail.com <ma...@gmail.com>>>>
> wrote:
> > > >
> > > > Hi Jacques,
> > > >
> > > > I am using 18.12 release.
> > > >
> > > > BR//
> > > > Vipin Nirwal
> > > >
> > > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > <mailto:jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com>>
> > > <mailto:jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> > <ma...@les7arts.com>>>> 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 <
> humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>
> > <mailto:humera.khan@hotwaxsystems.com <mailto:
> humera.khan@hotwaxsystems.com>>
> > > <mailto:humera.khan@hotwaxsystems.com <mailto:
> humera.khan@hotwaxsystems.com> <mailto:humera.khan@hotwaxsystems.com
> > <ma...@hotwaxsystems.com>>>>
> > > > > 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 <
> nirwal.ims@gmail.com <ma...@gmail.com> <mailto:
> nirwal.ims@gmail.com
> > <ma...@gmail.com>> <mailto:nirwal.ims@gmail.com <mailto:
> nirwal.ims@gmail.com>
> > > <mailto:nirwal.ims@gmail.com <ma...@gmail.com>>>>
> 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 <
> > > > >>> jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> > <ma...@les7arts.com>> <mailto:
> jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > > <mailto:jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com>>>> 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
Re: Submit order taking longer and afterwards failing.
Posted by Jacques Le Roux <ja...@les7arts.com>.
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 <jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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 <jacques.le.roux@les7arts.com <ma...@les7arts.com>
> <mailto:jacques.le.roux@les7arts.com <ma...@les7arts.com>>> 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 <nirwal.ims@gmail.com <ma...@gmail.com> <mailto:nirwal.ims@gmail.com
> <ma...@gmail.com>> <mailto:nirwal.ims@gmail.com <ma...@gmail.com>
> > <mailto:nirwal.ims@gmail.com <ma...@gmail.com>>>> wrote:
> > >
> > > Hi Jacques,
> > >
> > > I am using 18.12 release.
> > >
> > > BR//
> > > Vipin Nirwal
> > >
> > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <jacques.le.roux@les7arts.com <ma...@les7arts.com>
> <mailto:jacques.le.roux@les7arts.com <ma...@les7arts.com>>
> > <mailto:jacques.le.roux@les7arts.com <ma...@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> <ma...@les7arts.com>>>> 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 <humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>
> <mailto:humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>>
> > <mailto:humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com> <mailto:humera.khan@hotwaxsystems.com
> <ma...@hotwaxsystems.com>>>>
> > > > 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 <nirwal.ims@gmail.com <ma...@gmail.com> <mailto:nirwal.ims@gmail.com
> <ma...@gmail.com>> <mailto:nirwal.ims@gmail.com <ma...@gmail.com>
> > <mailto:nirwal.ims@gmail.com <ma...@gmail.com>>>> 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 <
> > > >>> jacques.le.roux@les7arts.com <ma...@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> <ma...@les7arts.com>> <mailto:jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > <mailto:jacques.le.roux@les7arts.com <ma...@les7arts.com>>>> 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
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
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 <
jacques.le.roux@les7arts.com> 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 <
> jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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 <nirwal.ims@gmail.com
> <ma...@gmail.com> <mailto:nirwal.ims@gmail.com
> > <ma...@gmail.com>>> wrote:
> > >
> > > Hi Jacques,
> > >
> > > I am using 18.12 release.
> > >
> > > BR//
> > > Vipin Nirwal
> > >
> > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> jacques.le.roux@les7arts.com <ma...@les7arts.com>
> > <mailto:jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com>>> 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 <
> humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>
> > <mailto:humera.khan@hotwaxsystems.com <mailto:
> humera.khan@hotwaxsystems.com>>>
> > > > 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 <
> nirwal.ims@gmail.com <ma...@gmail.com> <mailto:
> nirwal.ims@gmail.com
> > <ma...@gmail.com>>> 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 <
> > > >>> jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> > <ma...@les7arts.com>>> 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
Re: Submit order taking longer and afterwards failing.
Posted by Jacques Le Roux <ja...@les7arts.com>.
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 <jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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 <nirwal.ims@gmail.com <ma...@gmail.com> <mailto:nirwal.ims@gmail.com
> <ma...@gmail.com>>> wrote:
> >
> > Hi Jacques,
> >
> > I am using 18.12 release.
> >
> > BR//
> > Vipin Nirwal
> >
> > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <jacques.le.roux@les7arts.com <ma...@les7arts.com>
> <mailto:jacques.le.roux@les7arts.com <ma...@les7arts.com>>> 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 <humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>
> <mailto:humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>>>
> > > 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 <nirwal.ims@gmail.com <ma...@gmail.com> <mailto:nirwal.ims@gmail.com
> <ma...@gmail.com>>> 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 <
> > >>> jacques.le.roux@les7arts.com <ma...@les7arts.com> <mailto:jacques.le.roux@les7arts.com
> <ma...@les7arts.com>>> 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
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
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 <
jacques.le.roux@les7arts.com> 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 <nirwal.ims@gmail.com
> <ma...@gmail.com>> wrote:
> >
> > Hi Jacques,
> >
> > I am using 18.12 release.
> >
> > BR//
> > Vipin Nirwal
> >
> > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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 <
> humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>>
> > > 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 <
> nirwal.ims@gmail.com <ma...@gmail.com>> 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 <
> > >>> jacques.le.roux@les7arts.com <mailto:
> jacques.le.roux@les7arts.com>> 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
Re: Submit order taking longer and afterwards failing.
Posted by Jacques Le Roux <ja...@les7arts.com>.
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 <nirwal.ims@gmail.com <ma...@gmail.com>> wrote:
>
> Hi Jacques,
>
> I am using 18.12 release.
>
> BR//
> Vipin Nirwal
>
> On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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 <humera.khan@hotwaxsystems.com <ma...@hotwaxsystems.com>>
> > 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 <nirwal.ims@gmail.com <ma...@gmail.com>> 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 <
> >>> jacques.le.roux@les7arts.com <ma...@les7arts.com>> 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
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
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 <ni...@gmail.com> wrote:
> Hi Jacques,
>
> I am using 18.12 release.
>
> BR//
> Vipin Nirwal
>
> On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
> jacques.le.roux@les7arts.com> 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 <
>> humera.khan@hotwaxsystems.com>
>> > 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 <ni...@gmail.com>
>> 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 <
>> >>> jacques.le.roux@les7arts.com> 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
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
Hi Jacques,
I am using 18.12 release.
BR//
Vipin Nirwal
On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <
jacques.le.roux@les7arts.com> 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 <
> humera.khan@hotwaxsystems.com>
> > 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 <ni...@gmail.com>
> 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 <
> >>> jacques.le.roux@les7arts.com> 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
Re: Submit order taking longer and afterwards failing.
Posted by Jacques Le Roux <ja...@les7arts.com>.
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 <hu...@hotwaxsystems.com>
> 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 <ni...@gmail.com> 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 <
>>> jacques.le.roux@les7arts.com> 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
>>>
>
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
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 <hu...@hotwaxsystems.com>
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 <ni...@gmail.com> 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 <
> > jacques.le.roux@les7arts.com> 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
Re: Submit order taking longer and afterwards failing.
Posted by Humera Khan <hu...@hotwaxsystems.com>.
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 <ni...@gmail.com> 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 <
> jacques.le.roux@les7arts.com> 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
>
Re: Submit order taking longer and afterwards failing.
Posted by vipin nirwal <ni...@gmail.com>.
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 <
jacques.le.roux@les7arts.com> 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
Re: Submit order taking longer and afterwards failing.
Posted by Jacques Le Roux <ja...@les7arts.com>.
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
>
>