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 <[email protected]
<mailto:[email protected]>> 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 <[email protected]
<mailto:[email protected]> <mailto:[email protected]
<mailto:[email protected]>>> wrote:
>
> Hi Jacques,
>
> I am using 18.12 release.
>
> BR//
> Vipin Nirwal
>
> On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux
<[email protected] <mailto:[email protected]>
<mailto:[email protected]
<mailto:[email protected]>>> 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
<[email protected] <mailto:[email protected]>
<mailto:[email protected]
<mailto:[email protected]>>>
> > 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 <[email protected]
<mailto:[email protected]> <mailto:[email protected]
<mailto:[email protected]>>> 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 <
> >>> [email protected]
<mailto:[email protected]> <mailto:[email protected]
<mailto:[email protected]>>> 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
