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]> 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]>> 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 > > -- Thanks & Regards Vipin Nirwal
<<attachment: log.zip>>
