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