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]> 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]> 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]> >> > 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]> >> 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]> 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
SELECT * from lock_monitor;
locked_item | waiting_duration | blocked_pid | blocked_query| blocked_mode |
blocking_pid | blocking_query | blocking_mode
product_calculated_info | 00:00:04.423753 | 4864 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ExclusiveLock | 5326 |
UPDATE public.PRODUCT_CALCULATED_INFO SET TOTA
L_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
| ExclusiveLock
product_calculated_info | 00:00:04.308003 | 5322 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ExclusiveLock | 5326 |
UPDATE public.PRODUCT_CALCULATED_INFO SET TOTA
L_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
| ExclusiveLock
product_calculated_info | 00:00:04.410511 | 2594 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ExclusiveLock | 4864 |
UPDATE public.PRODUCT_CALCULATED_INFO SET TOTA
L_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
| ExclusiveLock
product_calculated_info | 00:00:04.308003 | 5322 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ExclusiveLock | 4864 |
UPDATE public.PRODUCT_CALCULATED_INFO SET TOTA
L_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
| ExclusiveLock
transactionid | 00:00:04.59874 | 5326 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ShareLock | 5324 |
SELECT INVENTORY_ITEM_ID, INVENTORY_ITEM_TYPE_
ID, PRODUCT_ID, PARTY_ID, OWNER_PARTY_ID, STATUS_ID, DATETIME_RECEIVED,
DATETIME_MANUFACTURED, EXPIRE_DATE, FACILITY_ID, C
ONTAINER_ID, LOT_ID, UOM_ID, BIN_NUMBER, LOCATION_SEQ_ID, COMMENTS,
QUANTITY_ON_HAND_TOTAL, AVAILABLE_TO_PROMISE_TOTAL, AC
COUNTING_QUANTITY_TOTAL, QUANTITY_ON_HAND, AVAILABLE_TO_PROMISE, SERIAL_NUMBER,
SOFT_IDENTIFIER, ACTIVATION_NUMBER, ACTIVA
TION_VALID_THRU, UNIT_COST, CURRENCY_UOM_ID, FIXED_ASSET_ID,
LAST_UPDATED_STAMP, LAST_UPDATED_TX_STAMP, CREATED_STAMP, CRE
ATED_TX_STAMP FROM public.INVENTORY_ITEM WHERE ((FACILITY_ID = $1 AND
PRODUCT_ID = $2)) | ExclusiveLock
product_calculated_info | 00:00:04.423753 | 4864 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ExclusiveLock | 2594 |
UPDATE public.PRODUCT_CALCULATED_INFO SET TOTA
L_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
| ExclusiveLock
product_calculated_info | 00:00:04.308003 | 5322 | UPDATE
public.PRODUCT_CALCULATED_INFO SET TOTAL_QUANTITY_ORDER
ED=$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 | ExclusiveLock | 2594 |
UPDATE public.PRODUCT_CALCULATED_INFO SET TOTA
L_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
Jmeter_Results.xlsx
Description: MS-Excel 2007 spreadsheet
