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 <[email protected]
<mailto:[email protected]>> 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 <[email protected]
<mailto:[email protected]>
<mailto:[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]>> <mailto:[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]>>
> <mailto:[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]>>
> <mailto:[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]>> <mailto:[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]>> <mailto:[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
--
Thanks & Regards
Vipin Nirwal
