2 Replies Latest reply on Sep 3, 2016 4:20 AM by Ramaraju

    Concurrent Program Taking Long Time to Complete

    Ramaraju

      Hi,

      Concurrent program taking very long time to complete. Same program completed in 10 mins in Prod but in Test instance it is taking 10 to 15 hours.

      EBS 11i

      Please help me on this.

       

      Thanks,

      Ramaraju

        • 1. Re: Concurrent Program Taking Long Time to Complete
          J Reinhart

          Hi Ramaraju,

           

          Have your DBA check what its doing, they can see running statements

           

          Hopefully, its something simple, like someone has the data locked and the job is waiting for the lock to be released.   The DBA can see if the job has been waiting a long time, and what (if anything) is locking it.  Then they can find the job or form that has the lock and you can call that person to tell them to finish/exit or allow the DBA to kill the session.    Note that sometimes processes deadlock each other, if they both need tables A and B and one job has the record in A locked and is waiting for table B while the second job has the record in B locked and is waiting for table A.  Usually, one times out and quits, but if both are written to wait, then you can kill the less important one, and also set the jobs as incompatible with each other to prevent recurrences.

           

          A less simple answer is that the job is running a different way.   This can happen if statistics haven't run, or if they failed.  It can also happen when data in a table reaches a point where the CBO believes another approach is cheaper when its not.   If the DBA shows you the explain plan, check first for full table scans (fine on a very small table but a problem on very large ones) then check what indexes are in use.  Over time, the values in the table can change so that CBO chooses a different index which turns out to be very inefficient.

           

          If statistics haven't run, try running them (it may not help for the job that's currently running, though)   If its started running another way, you may need to add hints or such to push it to run a better way.

           

          One last point -- you mention that it ran in 10 minutes in a test instance.  It could be that in the test instance, there were fewer users and no one locked the data it uses while  you tested.  If your job is custom, you can update it to run with NoWait, if locking is the issue and the data will be often locked, or you could run it at night when there are fewer users.  But if the data is much larger or different in production, that can also make the Optimizer choose different ways to execute the same query. 

           

          If you get more info on it, post it here and we can try to assist further,

           

          J

          • 2. Re: Concurrent Program Taking Long Time to Complete
            Ramaraju

            Hi,

            I din't find any locks for that concurrent program.

            SQL> select * from v$locked_object where session_id='977';

            no rows selected

             

            And I have generated tkproof file concurrent program trace file. Please help on this

             

             

             

            TKPROF: Release 11.2.0.4.0 - Development on Fri Sep 2 23:32:02 2016

             

             

            Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

             

             

            Trace file: /u01/app/oracle/diag/rdbms/dev/DEV/trace/DEV_ora_29882_SYSADMIN_CR48272225.trc

            Sort options: prsela  exeela  fchela 

            ********************************************************************************

            count    = number of times OCI procedure was executed

            cpu      = cpu time in seconds executing

            elapsed  = elapsed time in seconds executing

            disk     = number of physical reads of buffers from disk

            query    = number of buffers gotten for consistent read

            current  = number of buffers gotten in current mode (usually for update)

            rows     = number of rows processed by the fetch or execute call

            ********************************************************************************

             

             

            Error in CREATE TABLE of EXPLAIN PLAN table: APPS.prof$plan_table

            ORA-00955: name is already used by an existing object

             

             

            parse error offset: 18

            EXPLAIN PLAN option disabled.

            ********************************************************************************

             

             

            SQL ID: 6rkgv6h95u1pv Plan Hash: 2699106737

             

             

            SELECT L.SHIP_FROM_ORG_ID ORG_ID, ORG.ORGANIZATION_CODE, RCTA.CUSTOMER_TRX_ID,

               RCTLA.CUSTOMER_TRX_LINE_ID, RCTLA.PREVIOUS_CUSTOMER_TRX_LINE_ID,

              RCTA.TRX_NUMBER, RCTA.TRX_DATE, RCTLA.CREATION_DATE, HCA.ACCOUNT_NUMBER,

              HCA.ORIG_SYSTEM_REFERENCE, HPTY.PARTY_NAME CUST_NAME,

              HCASA.CUSTOMER_CATEGORY_CODE PRICE_LEVEL, H.HEADER_ID, L.LINE_ID,

              H.ORDER_NUMBER, H.CUST_PO_NUMBER, L.LINE_NUMBER ||'.' || L.SHIPMENT_NUMBER

              LINE_NUMBER, L.INVENTORY_ITEM_ID, L.SHIP_FROM_ORG_ID, L.ORDERED_ITEM

              ITEM_NUMBER, L.ITEM_TYPE_CODE, L.SOURCE_TYPE_CODE, MSIB.DESCRIPTION,

              NVL(RCTLA.QUANTITY_INVOICED, RCTLA.QUANTITY_CREDITED) QUANTITY_INVOICED,

              RCTLA.UOM_CODE, L.FULFILLMENT_DATE, NVL(L.ACTUAL_SHIPMENT_DATE,

              L.FULFILLMENT_DATE) ACTUAL_SHIPMENT_DATE, TO_NUMBER(REPLACE(L.ATTRIBUTE1,',

              ','')) MSRP, NVL(RCTLA.UNIT_SELLING_PRICE,0) UNIT_SELLING_PRICE,

              RCTLA.EXTENDED_AMOUNT, COALESCE(TO_NUMBER(L.ATTRIBUTE5), (SELECT DISTINCT

              ITEM_COST

            FROM

            CST_ITEM_COSTS CST WHERE CST.INVENTORY_ITEM_ID=L.INVENTORY_ITEM_ID AND

              CST.ORGANIZATION_ID =L.SHIP_FROM_ORG_ID AND L.ITEM_TYPE_CODE ='KIT' AND

              CST.COST_TYPE_ID =3 ),0) UNIT_COST, RCTA.INVOICE_CURRENCY_CODE,

              NVL(RCTA.EXCHANGE_RATE,1) EXCHANGE_RATE, NVL(L.ATTRIBUTE7,1) SALES_RATE,

              TRUNC(L.CREATION_DATE) LINE_CREATION_DATE, L.PRICING_DATE, RCTA.ORG_ID

              OU_ID, HOU.NAME OU_NAME, L.LINE_CATEGORY_CODE, L.INVOICE_TO_ORG_ID,

              NVL(L.SHIP_TO_ORG_ID,H.SHIP_TO_ORG_ID) SHIP_TO_ORG_ID, L.PRICE_LIST_ID,

              RCTA.BILL_TO_SITE_USE_ID, HZLOC.ADDRESS2 BILL_TO_ADDR1, HZLOC.ADDRESS3

              BILL_TO_ADDR2, HZLOC.CITY BILL_TO_CITY, NVL(HZLOC.STATE, HZLOC.PROVINCE)

              BILL_TO_STATE, HZLOC.POSTAL_CODE BILL_TO_POSTAL_CODE, HZLOC.COUNTRY

              BILL_TO_COUNTRY, RCTA.SHIP_TO_SITE_USE_ID, HZLOC2.ADDRESS1 SHIP_TO_NAME,

              HZLOC2.ADDRESS2 SHIP_TO_ADDR1, HZLOC2.ADDRESS3 SHIP_TO_ADDR2, HZLOC2.CITY

              SHIP_TO_CITY, NVL(HZLOC2.STATE, HZLOC2.PROVINCE) SHIP_TO_STATE ,

              HZLOC2.POSTAL_CODE SHIP_TO_POSTAL_CODE, HZLOC2.COUNTRY SHIP_TO_COUNTRY,

              H.END_CUSTOMER_SITE_USE_ID, HZLOC3.ADDRESS1 END_CUST_NAME, HZLOC3.ADDRESS2

              END_CUST_ADDR1, HZLOC3.ADDRESS3 END_CUST_ADDR2, HZLOC3.CITY END_CUST_CITY,

              NVL(HZLOC3.STATE, HZLOC3.PROVINCE) END_CUST_STATE , HZLOC3.POSTAL_CODE

              END_CUST_POSTAL_CODE, HZLOC3.COUNTRY END_CUST_COUNTRY,

              RCTA.PRIMARY_SALESREP_ID, SREP.NAME SALESREP_NAME, RCTTA.NAME

              TRAN_TYPE_NAME, RCTTA.TYPE TRAN_TYPE, HCSUA.TERRITORY_ID, TERR.SEGMENT1

              TERRITORY_NAME, H.FREIGHT_TERMS_CODE, FLV.MEANING FREIGHT_TERMS,

              H.SHIPPING_METHOD_CODE, WCS.SHIP_METHOD_MEANING , PTRM.NAME TERM_NAME ,

              RCTA.TERM_ID FROM APPS.OE_ORDER_LINES_ALL L , APPS.OE_ORDER_HEADERS_ALL H ,

              APPS.MTL_SYSTEM_ITEMS_B MSIB , APPS.RA_CUSTOMER_TRX_LINES_ALL RCTLA ,

              APPS.RA_CUSTOMER_TRX_ALL RCTA , APPS.RA_CUST_TRX_TYPES_ALL RCTTA ,

              APPS.HZ_CUST_ACCOUNTS HCA , APPS.HZ_PARTIES HPTY ,

              APPS.HZ_CUST_SITE_USES_ALL HCSUA , APPS.HZ_CUST_ACCT_SITES_ALL HCASA ,

              APPS.HZ_LOCATIONS HZLOC , APPS.HZ_PARTY_SITES HZPSI ,

              APPS.HZ_CUST_SITE_USES_ALL HCSUA2 , APPS.HZ_CUST_ACCT_SITES_ALL HCASA2 ,

              APPS.HZ_LOCATIONS HZLOC2 , APPS.HZ_PARTY_SITES HZPSI2 ,

              APPS.HZ_CUST_SITE_USES_ALL HCSUA3 , APPS.HZ_CUST_ACCT_SITES_ALL HCASA3 ,

              APPS.HZ_LOCATIONS HZLOC3 , APPS.HZ_PARTY_SITES HZPSI3 , APPS.RA_TERRITORIES

              TERR , AR.RA_TERMS_TL PTRM , APPS.JTF_RS_SALESREPS SREP ,

              APPS.ORG_ORGANIZATION_DEFINITIONS ORG , HR.HR_ALL_ORGANIZATION_UNITS HOU ,

              APPS.FND_LOOKUP_VALUES_VL FLV , WSH.WSH_CARRIER_SERVICES WCS WHERE

              L.HEADER_ID = H.HEADER_ID AND L.INVENTORY_ITEM_ID = MSIB.INVENTORY_ITEM_ID

              AND L.SHIP_FROM_ORG_ID = MSIB.ORGANIZATION_ID AND L.SHIP_FROM_ORG_ID =

              ORG.ORGANIZATION_ID AND TO_NUMBER(RCTLA.INTERFACE_LINE_ATTRIBUTE6) =

              L.LINE_ID AND RCTLA.CUSTOMER_TRX_ID = RCTA.CUSTOMER_TRX_ID AND

              RCTA.BILL_TO_CUSTOMER_ID = HCA.CUST_ACCOUNT_ID AND RCTA.CUST_TRX_TYPE_ID =

              RCTTA.CUST_TRX_TYPE_ID AND HCA.PARTY_ID = HPTY.PARTY_ID AND

              RCTA.BILL_TO_SITE_USE_ID = HCSUA.SITE_USE_ID AND HCSUA.CUST_ACCT_SITE_ID =

              HCASA.CUST_ACCT_SITE_ID AND HCSUA.TERRITORY_ID = TERR.TERRITORY_ID(+) AND

              HCASA.PARTY_SITE_ID = HZPSI.PARTY_SITE_ID AND HZPSI.LOCATION_ID =

              HZLOC.LOCATION_ID AND RCTA.SHIP_TO_SITE_USE_ID = HCSUA2.SITE_USE_ID AND

              HCSUA2.CUST_ACCT_SITE_ID = HCASA2.CUST_ACCT_SITE_ID AND

              HCASA2.PARTY_SITE_ID = HZPSI2.PARTY_SITE_ID AND HZPSI2.LOCATION_ID =

              HZLOC2.LOCATION_ID AND H.END_CUSTOMER_SITE_USE_ID = HCSUA3.SITE_USE_ID(+)

              AND HCSUA3.CUST_ACCT_SITE_ID = HCASA3.CUST_ACCT_SITE_ID(+) AND

              HCASA3.PARTY_SITE_ID = HZPSI3.PARTY_SITE_ID(+) AND HZPSI3.LOCATION_ID =

              HZLOC3.LOCATION_ID(+) AND RCTA.PRIMARY_SALESREP_ID = SREP.SALESREP_ID(+)

              AND RCTA.ORG_ID = HOU.ORGANIZATION_ID AND RCTA.TERM_ID = PTRM.TERM_ID(+)

              AND 'US' = PTRM.LANGUAGE(+) AND FLV.LOOKUP_TYPE(+) = 'FREIGHT_TERMS' AND

              H.FREIGHT_TERMS_CODE = FLV.LOOKUP_CODE(+) AND H.SHIPPING_METHOD_CODE =

              WCS.SHIP_METHOD_CODE(+) AND RCTA.ORG_ID = SREP.ORG_ID(+) AND

              RCTLA.WH_UPDATE_DATE IS NULL

             

             

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse        1      0.92       0.93          0          0          0           0

            Execute      1      0.00       0.00          0          0          0           0

            Fetch        0      0.00       0.00          0          0          0           0

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total        2      0.92       0.93          0          0          0           0

             

             

            Misses in library cache during parse: 1

            Optimizer mode: ALL_ROWS

            Parsing user id: 229     (recursive depth: 1)

             

             

            Elapsed times include waiting on following events:

              Event waited on                             Times   Max. Wait  Total Waited

              ----------------------------------------   Waited  ----------  ------------

              reliable message                                1        0.00          0.00

              enq: KO - fast object checkpoint                1        0.00          0.00

              Disk file operations I/O                       64        0.00          0.02

              direct path read                             7878        0.89         91.87

              db file sequential read                   5847499        4.07      18769.02

              direct path write temp                        719        0.06          2.28

              latch free                                      1        0.00          0.00

            ********************************************************************************

             

             

            SQL ID: 5vbbcp6pd58b8 Plan Hash: 0

             

             

            begin Fnd_Concurrent.Init_Request; end;

             

             

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse        0      0.00       0.00          0          0          0           0

            Execute      1      0.02       0.14          9         86          4           1

            Fetch        0      0.00       0.00          0          0          0           0

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total        1      0.02       0.14          9         86          4           1

             

             

            Misses in library cache during parse: 0

            Optimizer mode: ALL_ROWS

            Parsing user id: 229 

            ********************************************************************************

             

             

            SQL ID: 8s4mcv72w2nr4 Plan Hash: 599750161

             

             

            SELECT NVL(MAX(DRO.REPEATION_COUNTER),0)

            FROM

            FND_DEBUG_RULE_EXECUTIONS DRO, FND_DEBUG_OPTION_VALUES DOV WHERE

              DRO.DEBUG_OPTION_NAME=DOV.DEBUG_OPTION_NAME AND DRO.DEBUG_OPTION_VALUE=

              DOV.DEBUG_OPTION_VALUE AND DOV.DEBUG_OPTION_NAME=:B3 AND

              DOV.DEBUG_OPTION_VALUE=:B2 AND DRO.RULE_ID=:B1

             

             

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse        1      0.00       0.00          0          0          0           0

            Execute      1      0.00       0.00          0          0          0           0

            Fetch        1      0.00       0.01         29         31          0           1

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total        3      0.00       0.02         29         31          0           1

             

             

            Misses in library cache during parse: 1

            Misses in library cache during execute: 1

            Optimizer mode: ALL_ROWS

            Parsing user id: 229     (recursive depth: 1)

            Number of plan statistics captured: 1

             

             

            Rows (1st) Rows (avg) Rows (max)  Row Source Operation

            ---------- ---------- ----------  ---------------------------------------------------

                     1          1          1  SORT AGGREGATE (cr=31 pr=29 pw=0 time=14296 us)

                     0          0          0   NESTED LOOPS  (cr=31 pr=29 pw=0 time=14281 us cost=19 size=240 card=5)

                     1          1          1    INDEX UNIQUE SCAN FND_DEBUG_OPTION_VALUES_U1 (cr=1 pr=0 pw=0 time=13 us cost=0 size=18 card=1)(object id 85464)

                     0          0          0    TABLE ACCESS FULL FND_DEBUG_RULE_EXECUTIONS (cr=30 pr=29 pw=0 time=14259 us cost=19 size=150 card=5)

             

             

            ********************************************************************************

             

             

            SQL ID: 4d3gf1a0yswbz Plan Hash: 3282453722

             

             

            INSERT INTO FND_LOG_TRANSACTION_CONTEXT (TRANSACTION_CONTEXT_ID, SESSION_ID,

              TRANSACTION_TYPE, TRANSACTION_ID, USER_ID, RESP_APPL_ID, RESPONSIBILITY_ID,

              SECURITY_GROUP_ID, COMPONENT_TYPE, COMPONENT_APPL_ID, COMPONENT_ID,

              CREATION_DATE, PARENT_CONTEXT_ID )

            VALUES

            (FND_LOG_TRANSACTION_CTX_ID_S.NEXTVAL, NVL(:B11 , -1), :B10 , NVL(:B9 , -1),

              NVL(:B8 , -1), NVL(:B7 , -1), NVL(:B6 , -1), NVL(:B5 , -1), :B4 , NVL(:B3 ,

              -1), NVL(:B2 , -1), SYSDATE, :B1 ) RETURNING TRANSACTION_CONTEXT_ID INTO

              :O0

             

             

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse        1      0.00       0.00          0          0          0           0

            Execute      1      0.00       0.01          1          1         18           1

            Fetch        0      0.00       0.00          0          0          0           0

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total        2      0.00       0.02          1          1         18           1

             

             

            Misses in library cache during parse: 1

            Misses in library cache during execute: 1

            Optimizer mode: ALL_ROWS

            Parsing user id: 229     (recursive depth: 1)

            Number of plan statistics captured: 1

             

             

            Rows (1st) Rows (avg) Rows (max)  Row Source Operation

            ---------- ---------- ----------  ---------------------------------------------------

                     1          1          1  LOAD TABLE CONVENTIONAL  (cr=1 pr=1 pw=0 time=16701 us)

                     1          1          1   SEQUENCE  FND_LOG_TRANSACTION_CTX_ID_S (cr=0 pr=0 pw=0 time=47 us)

             

             

            ********************************************************************************

             

             

            SQL ID: 2up9nxdqz9651 Plan Hash: 0

             

             

            begin :1 := fnd_debug_util.get_trace_file_name; end;

             

             

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse        1      0.00       0.00          0          0          0           0

            Execute      1      0.00       0.01          1          1          0           2

            Fetch        0      0.00       0.00          0          0          0           0

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total        2      0.00       0.01          1          1          0           2

             

             

            Misses in library cache during parse: 1

            Misses in library cache during execute: 1

            Optimizer mode: ALL_ROWS

            Parsing user id: 229     (recursive depth: 1)

             

             

             

             

             

             

            ********************************************************************************

             

             

            OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse        6      0.00       0.00          0          0          0           0

            Execute      6      0.03       0.14          9         86          4           6

            Fetch        0      0.00       0.00          0          0          0           0

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total       12      0.03       0.15          9         86          4           6

             

             

            Misses in library cache during parse: 2

             

             

            Elapsed times include waiting on following events:

              Event waited on                             Times   Max. Wait  Total Waited

              ----------------------------------------   Waited  ----------  ------------

              SQL*Net message to client                       5        0.00          0.00

              SQL*Net message from client                     4        0.00          0.00

              utl_file I/O                                   21        0.00          0.00

             

             

             

             

            OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

             

             

            call     count       cpu    elapsed       disk      query    current        rows

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            Parse       66      0.95       0.96          0          0          0           0

            Execute    121      0.03       0.08          4        111         37           9

            Fetch      261      0.03       0.31         52        494          0         206

            ------- ------  -------- ---------- ---------- ---------- ----------  ----------

            total      448      1.02       1.35         56        605         37         215

             

             

            Misses in library cache during parse: 14

            Misses in library cache during execute: 9

             

             

            Elapsed times include waiting on following events:

              Event waited on                             Times   Max. Wait  Total Waited

              ----------------------------------------   Waited  ----------  ------------

              reliable message                                1        0.00          0.00

              enq: KO - fast object checkpoint                1        0.00          0.00

              Disk file operations I/O                       64        0.00          0.02

              direct path read                             7878        0.89         91.87

              db file sequential read                   5847499        4.07      18769.02

              direct path write temp                        719        0.06          2.28

              latch free                                      1        0.00          0.00

             

             

               37  user  SQL statements in session.

               23  internal SQL statements in session.

               60  SQL statements in session.

                0  statements EXPLAINed in this session.

            ********************************************************************************

            Trace file: /u01/app/oracle/diag/rdbms/dev/DEV/trace/DEV_ora_29882_SYSADMIN_CR48272225.trc

            Trace file compatibility: 11.1.0.7

            Sort options: prsela  exeela  fchela 

                   1  session in tracefile.

                  37  user  SQL statements in trace file.

                  23  internal SQL statements in trace file.

                  60  SQL statements in trace file.

                  59  unique SQL statements in trace file.

            5895701  lines in trace file.

                  16  elapsed seconds in trace file.

             

            Thanks,

            Ramaraju