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 |
Administrator
|
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 > > |
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 <[hidden email]> wrote: Hi Vipin, Thanks & Regards
Vipin Nirwal Jmeter_Results.xlsx (31K) Download Attachment |
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 <[hidden email]> 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 < > [hidden email]> 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 > |
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 <[hidden email]> 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 <[hidden email]> 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 < > > [hidden email]> 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 |
Administrator
|
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 <[hidden email]> > 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 <[hidden email]> 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 < >>> [hidden email]> 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 >>> > |
Hi Jacques,
I am using 18.12 release. BR// Vipin Nirwal On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux < [hidden email]> 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 < > [hidden email]> > > 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 <[hidden email]> > 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 < > >>> [hidden email]> 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 |
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 <[hidden email]> wrote:
Thanks & Regards
Vipin Nirwal |
Administrator
|
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 <[hidden email] <mailto:[hidden email]>> wrote: > > Hi Jacques, > > I am using 18.12 release. > > BR// > Vipin Nirwal > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]>> 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 <[hidden email] <mailto:[hidden email]>> > > 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 <[hidden email] <mailto:[hidden email]>> 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 < > >>> [hidden email] <mailto:[hidden email]>> 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 |
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 <[hidden email]> wrote: Hi Wipin, Thanks & Regards
Vipin Nirwal log.zip (150K) Download Attachment |
Administrator
|
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 <[hidden email] <mailto:[hidden email]>> 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 <[hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>>> wrote: > > > > Hi Jacques, > > > > I am using 18.12 release. > > > > BR// > > Vipin Nirwal > > > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]> > <mailto:[hidden email] <mailto:[hidden email]>>> 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 <[hidden email] <mailto:[hidden email]> > <mailto:[hidden email] <mailto:[hidden email]>>> > > > 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 <[hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>>> 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 < > > >>> [hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>>> 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 |
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 <[hidden email]> wrote: Hi Vipin, Thanks & Regards
Vipin Nirwal log.zip (72K) Download Attachment |
Administrator
|
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 <[hidden email] <mailto:[hidden email]>> 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 <[hidden email] <mailto:[hidden email]> > <mailto:[hidden email] <mailto:[hidden email]>>> 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 <[hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>> <mailto:[hidden email] <mailto:[hidden email]> > > <mailto:[hidden email] <mailto:[hidden email]>>>> wrote: > > > > > > Hi Jacques, > > > > > > I am using 18.12 release. > > > > > > BR// > > > Vipin Nirwal > > > > > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux <[hidden email] <mailto:[hidden email]> > <mailto:[hidden email] <mailto:[hidden email]>> > > <mailto:[hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>>>> 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 <[hidden email] <mailto:[hidden email]> > <mailto:[hidden email] <mailto:[hidden email]>> > > <mailto:[hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>>>> > > > > 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 <[hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>> <mailto:[hidden email] <mailto:[hidden email]> > > <mailto:[hidden email] <mailto:[hidden email]>>>> 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 < > > > >>> [hidden email] <mailto:[hidden email]> <mailto:[hidden email] > <mailto:[hidden email]>> <mailto:[hidden email] <mailto:[hidden email]> > > <mailto:[hidden email] <mailto:[hidden email]>>>> 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 |
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 < [hidden email]> 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 < > [hidden email] <mailto:[hidden email]>> 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 < > [hidden email] <mailto:[hidden email]> > > <mailto:[hidden email] <mailto: > [hidden email]>>> 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 < > [hidden email] <mailto:[hidden email]> <mailto: > [hidden email] > > <mailto:[hidden email]>> <mailto:[hidden email] <mailto: > [hidden email]> > > > <mailto:[hidden email] <mailto:[hidden email]>>>> > wrote: > > > > > > > > Hi Jacques, > > > > > > > > I am using 18.12 release. > > > > > > > > BR// > > > > Vipin Nirwal > > > > > > > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux < > [hidden email] <mailto:[hidden email]> > > <mailto:[hidden email] <mailto: > [hidden email]>> > > > <mailto:[hidden email] <mailto: > [hidden email]> <mailto:[hidden email] > > <mailto:[hidden email]>>>> 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 < > [hidden email] <mailto:[hidden email]> > > <mailto:[hidden email] <mailto: > [hidden email]>> > > > <mailto:[hidden email] <mailto: > [hidden email]> <mailto:[hidden email] > > <mailto:[hidden email]>>>> > > > > > 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 < > [hidden email] <mailto:[hidden email]> <mailto: > [hidden email] > > <mailto:[hidden email]>> <mailto:[hidden email] <mailto: > [hidden email]> > > > <mailto:[hidden email] <mailto:[hidden email]>>>> > 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 < > > > > >>> [hidden email] <mailto: > [hidden email]> <mailto:[hidden email] > > <mailto:[hidden email]>> <mailto: > [hidden email] <mailto:[hidden email]> > > > <mailto:[hidden email] <mailto: > [hidden email]>>>> 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 |
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 <[hidden email]> 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 < > [hidden email]> 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 < > > [hidden email] <mailto:[hidden email]>> > 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 < > > [hidden email] <mailto:[hidden email]> > > > <mailto:[hidden email] <mailto: > > [hidden email]>>> 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 < > > [hidden email] <mailto:[hidden email]> <mailto: > > [hidden email] > > > <mailto:[hidden email]>> <mailto:[hidden email] > <mailto: > > [hidden email]> > > > > <mailto:[hidden email] <mailto:[hidden email] > >>>> > > wrote: > > > > > > > > > > Hi Jacques, > > > > > > > > > > I am using 18.12 release. > > > > > > > > > > BR// > > > > > Vipin Nirwal > > > > > > > > > > On Fri, Dec 20, 2019 at 2:07 PM Jacques Le Roux < > > [hidden email] <mailto:[hidden email]> > > > <mailto:[hidden email] <mailto: > > [hidden email]>> > > > > <mailto:[hidden email] <mailto: > > [hidden email]> <mailto:[hidden email] > > > <mailto:[hidden email]>>>> 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 < > > [hidden email] <mailto:[hidden email]> > > > <mailto:[hidden email] <mailto: > > [hidden email]>> > > > > <mailto:[hidden email] <mailto: > > [hidden email]> <mailto:[hidden email] > > > <mailto:[hidden email]>>>> > > > > > > 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 < > > [hidden email] <mailto:[hidden email]> <mailto: > > [hidden email] > > > <mailto:[hidden email]>> <mailto:[hidden email] > <mailto: > > [hidden email]> > > > > <mailto:[hidden email] <mailto:[hidden email] > >>>> > > 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 < > > > > > >>> [hidden email] <mailto: > > [hidden email]> <mailto:[hidden email] > > > <mailto:[hidden email]>> <mailto: > > [hidden email] <mailto:[hidden email]> > > > > <mailto:[hidden email] <mailto: > > [hidden email]>>>> 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 > |
Free forum by Nabble | Edit this page |