1 2 Previous Next 18 Replies Latest reply on Apr 11, 2019 8:46 AM by Ramaraju

    Concurrent Program Trace File

    Ramaraju

      Hi All,

      Concurrent program taking very long time to complete and I have generated the trace and tkprof file for that program. Can anyone please guide how to understand this tkprof file?

      The following is the tkprof file.

       

      TKPROF: Release 12.1.0.2.0 - Development on Thu Apr 4 16:17:00 2019

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

       

      Trace file: TEST_ora_13205.trc

      Sort options: 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: 9j7scbm4n2xqq Plan Hash: 2097519442

       

       

      SELECT MEANING

      FROM

      FND_LOOKUP_VALUES_VL FLV WHERE FLV.LOOKUP_TYPE = 'XXFASCOR_WAREHOUSE_LKUP'

        AND FLV.ENABLED_FLAG = 'Y' AND SYSDATE BETWEEN NVL (START_DATE_ACTIVE,

        SYSDATE - 1) AND NVL (END_DATE_ACTIVE, SYSDATE + 1) AND LOOKUP_CODE = :B1

       

       

      call     count       cpu    elapsed       disk      query    current        rows

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

      Parse        0      0.00       0.00          0          0          0           0

      Execute    420      0.12       0.04          0          0          0           0

      Fetch      420      0.00       0.00          0       1260          0           0

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

      total      840      0.12       0.05          0       1260          0           0

       

       

      Misses in library cache during parse: 0

      Optimizer mode: ALL_ROWS

      Parsing user id: 229     (recursive depth: 2)

       

       

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

       

       

      OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

       

       

      call     count       cpu    elapsed       disk      query    current        rows

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

      Parse        0      0.00       0.00          0          0          0           0

      Execute      0      0.00       0.00          0          0          0           0

      Fetch        0      0.00       0.00          0          0          0           0

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

      total        0      0.00       0.00          0          0          0           0

       

       

      Misses in library cache during parse: 0

       

       

      Elapsed times include waiting on following events:

        Event waited on                             Times   Max. Wait  Total Waited

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

        db file sequential read                       293        0.01          0.22

       

       

      OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

       

       

      call     count       cpu    elapsed       disk      query    current        rows

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

      Parse        0      0.00       0.00          0          0          0           0

      Execute    420      0.12       0.04          0          0          0           0

      Fetch      420      0.00       0.00          0       1260          0           0

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

      total      840      0.12       0.05          0       1260          0           0

       

       

      Misses in library cache during parse: 0

       

       

          1  user  SQL statements in session.

          0  internal SQL statements in session.

          1  SQL statements in session.

          0  statements EXPLAINed in this session.

       

       

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

       

       

      Trace file: TEST_ora_13205.trc

      Trace file compatibility: 11.1.0.7

      Sort options: fchela

       

       

             1  session in tracefile.

             1  user  SQL statements in trace file.

             0  internal SQL statements in trace file.

             1  SQL statements in trace file.

             1  unique SQL statements in trace file.

          4794  lines in trace file.

           848  elapsed seconds in trace file.

        • 1. Re: Concurrent Program Trace File
          John_K

          Doesn't look like the full trace as been posted. Can you attach it as a text file?

          • 2. Re: Concurrent Program Trace File
            Kanda-Oracle

            Hi Ramaraj,

             

             

            1. Found "OVERALL TOTALS" not showing any elapsed time. So this trace may not help.

             

            2. Please mention whether request stayed in Pending/standby pending/normal (or) Running/normal for longer time ?

             

            3. Can you check request log file if there any issue with Post Processing(OPP).

             

            Thanks


            N Kandasamy

            • 3. Re: Concurrent Program Trace File
              Ramaraju

              Hi,

              It is Running/normal for longer time and now completed with warning

              XXFASCOR_SKU_API 04-APR-19

              Orders Exception ORA-01555: snapshot too old: rollback segment number 3 with name "_SYSSMU3_2097677531$" too small

               

              Didn't see any issues in OPP.

              • 4. Re: Concurrent Program Trace File
                Ramaraju

                I have copy paste the full log file

                • 5. Re: Concurrent Program Trace File
                  J Reinhart

                  Hi Ramaraju,

                   

                  Snapshot too old and rollback too small are system issues that you can discuss with your DBA.   If they have space they may be able to make the rollback segment larger, or they may have other ideas on how to handle it.

                   

                  Is this a new concurrent program or one that has run fine before but is now having issues?   That may provide extra information for your DBA.

                   

                  Regards,

                   

                  J

                  • 6. Re: Concurrent Program Trace File
                    Ramaraju

                    Program took 833.65 mins. Previously it is good.

                    • 7. Re: Concurrent Program Trace File
                      Ramaraju

                      Run the AWR report and found the following sql is taking very long time.

                       

                      SELECT  xxfascor_sku_stg_s.nextval,

                                       xxfascor_wms_utils.get_fas_whse(ood.organization_code) facility_nbr,

                                       xxfascor_wms_utils.get_message_type('SKU') message_type,

                                       'C' mode_status,

                                       msb.segment1 sku,

                                       '' upc,

                                       '' class,

                                       '' environment_code,

                                       '' storage_velocity_code,

                                       '' cycle_count_velocity_code,

                                       nvl(substr(msb.description,1,119),'')description1,

                                       nvl(substr(msb.description,120,239),'') description2,

                                       '' bulk_loc_type,

                                       '' unit_loc_type,

                                       nvl(round(msb.unit_length,2),0) length,

                                       nvl(round(msb.unit_width,2),0) width,

                                       nvl(round(msb.unit_height,2),0) height,

                                       nvl(round(msb.unit_volume,2),0) cube,

                                       nvl(round(msb.unit_weight,2),0) weight,

                                       decode(msb.serial_number_control_code,1,'N','5','Y',6,'Y') serial_no_flag,

                                       '' vendor_part_1,

                                       '' vendor_id_1,

                                       '' vendor_part_2,

                                       '' vendor_id_2,

                                       '' vendor_part_3,

                                       '' vendor_id_3,

                                       '' high_quantity,

                                       '' tie_quantity,

                                       '' master_pack,

                                       '' master_pack_uom,

                                       '' shippable_unit,

                                       xxfascor_wms_utils.get_default_value ('PREEMPTIVE_PUTAWAY_FLAG') preemptive_putaway_flag,

                                       nvl(round(msb.attribute3,2),0) cost,

                                       '' substitute_sku,

                                       upper(msb.primary_uom_code) unit_of_measure,

                                       xxfascor_wms_utils.get_default_value ('BULK_PICK_FLAG') bulk_pick_flag,

                                       decode(msb.location_control_code,6,'Y','N') lot_tracking,

                                       xxfascor_wms_utils.get_default_value ('NEW_SKU') new_sku,

                                       xxfascor_wms_utils.get_default_value ('AGE_CONTROL') age_control,

                                       '' rule_id,

                                       '' preferred_zone,

                                       xxfascor_wms_utils.get_default_value ('TRACK_MANUFACTURING_DATE') track_manufacturing_date,

                                       xxfascor_wms_utils.get_default_value ('TRACK_EXPIRATION_DATE') track_expiration_date

                                       ,'' error_code

                                       ,'' error_message

                                       , fnd_global.user_id created_by

                                       , sysdate creation_date

                                       ,sysdate last_update_date

                                       ,fnd_global.user_id last_upadated_by

                                       ,'N' processed_flag

                               FROM   mtl_system_items_b  msb,

                                      mtl_system_items_tl mtl,

                                      org_organization_definitions ood,

                                      xxfascor_sku_stg xss,

                                      fnd_lookup_values_vl flv

                               WHERE  1=1

                                 AND  msb.inventory_item_id=mtl.inventory_item_id

                                 AND  msb.organization_id=mtl.organization_id

                                 AND  msb.organization_id=ood.organization_id

                                 AND  mtl.language='US'

                                 AND  ood.organization_code =flv.lookup_code

                                 AND flv.lookup_type = 'XXFASCOR_WAREHOUSE_LKUP'

                                 AND flv.enabled_flag = 'Y'

                                 AND SYSDATE BETWEEN NVL (flv.start_date_active, SYSDATE - 1) AND NVL (flv.end_date_active, SYSDATE + 1)

                                 AND  msb.inventory_item_status_code in ('Active','Retiring')

                                 AND  msb.segment1 = xss.sku

                                 AND  xss.record_id = (SELECT max(record_id) FROM xxfascor_sku_stg where sku = xss.sku and facility_nbr = xxfascor_wms_utils.get_fas_whse(ood.organization_code))

                                 AND (NVL(ROUND(msb.unit_length,2),0) != NVL(xss.length,0)

                                 OR NVL(ROUND(msb.unit_width,2),0) != NVL(xss.width,0)

                                 OR NVL(ROUND(msb.unit_height,2),0) != NVL(xss.height,0)

                                 OR NVL(ROUND(msb.unit_volume,2),0) != NVL(xss.cube,0)

                                 OR NVL(ROUND(msb.unit_weight,2),0) != NVL(xss.weight,0)

                                 OR NVL(DECODE(msb.serial_number_control_code,1,'N','5','Y',6,'Y'),'x') != NVL(xss.serial_no_flag,'x')

                                 OR NVL(upper(msb.primary_uom_code),'x') != NVL(upper(xss.unit_of_measure),'x')

                                 OR NVL(ROUND(msb.attribute3,2),0) != NVL(upper(xss.cost),0)

                                 OR NVL(DECODE(msb.location_control_code,6,'Y','N'),'x') != NVL(xss.lot_tracking,'x'));

                      • 8. Re: Concurrent Program Trace File
                        Ramaraju

                        Execution plan for above sql_id:

                         

                        Plan hash value: 1321627111

                         

                        • 9. Re: Concurrent Program Trace File
                          VishnuVinnakota

                          Hi,

                           

                            Did you run the SQL Tuning Advisor? Whats the recommendation given by it and how much is the benefit?

                           

                          Thanks,

                          Vishnu

                          • 10. Re: Concurrent Program Trace File
                            Kanda-Oracle

                            Hi,

                             

                            The slowness could be due to a full table scan going on this object XXFASCOR_SKU_STG . Is this a custom table ?

                             

                            SQL> select count(1) from XXFASCOR_SKU_STG ;

                             

                            SQL> select SEGMENT_NAME "Table Name",sum(BLOCKS)  "Total blocks" , sum(bytes/1024/1024) "Size in MB" from dba_segments

                                     where segment_name in ('XXFASCOR_SKU_STG')

                                    group by segment_name;

                             

                             

                            Hope this helps!

                             

                            Thanks


                            N Kandasamy

                            • 11. Re: Concurrent Program Trace File
                              John_K

                              Can you run the query with the following hint:

                               

                              SELECT /*+gather_plan_statistics XX12345*/ xxfascor_sku_stg_s.nextval,

                               

                               

                              Then select the SQL ID from v$sql using sql_text like '%XX12345%', then generate the plan using:

                               

                              select  * from table(dbms_xplan.display_cursor(sqlid=>'SQL_ID_FROM_ABOVE',format=>'ALLSTATS LAST'));

                               

                              Thanks

                              • 12. Re: Concurrent Program Trace File
                                Ramaraju

                                Yes, it is custom table.

                                 

                                select count(1) from XXFASCOR_SKU_STG;

                                89818

                                 

                                select SEGMENT_NAME "Table Name",sum(BLOCKS)  "Total blocks" , sum(bytes/1024/1024) "Size in MB" from dba_segments

                                         where segment_name in ('XXFASCOR_SKU_STG')

                                        group by segment_name;

                                 

                                     Table Name                         Total blocks     Size in MB

                                XXFASCOR_SKU_STG     399072          3117.75

                                • 13. Re: Concurrent Program Trace File
                                  Ramaraju

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

                                  FINDINGS SECTION (3 findings)

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

                                   

                                   

                                  1- Statistics Finding

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

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                    Optimizer statistics for table "XBSI"."XXFASCOR_SKU_STG" and its indices are

                                    stale.

                                   

                                   

                                    Recommendation

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

                                    - Consider collecting optimizer statistics for this table.

                                      execute dbms_stats.gather_table_stats(ownname => 'XBSI', tabname =>

                                              'XXFASCOR_SKU_STG', estimate_percent =>

                                              DBMS_STATS.AUTO_SAMPLE_SIZE, method_opt => 'FOR ALL COLUMNS SIZE

                                              AUTO');

                                   

                                   

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                    Rationale

                                    ---------

                                      The optimizer requires up-to-date statistics for the table in order to

                                      select a good execution plan.

                                   

                                   

                                  2- SQL Profile Finding (see explain plans section below)

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

                                    A potentially better execution plan was found for this statement.

                                   

                                   

                                    Recommendation (estimated benefit: 68.2%)

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

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                    - Consider accepting the recommended SQL profile.

                                      execute dbms_sqltune.accept_sql_profile(task_name =>

                                              '0frpj87ws2b3u_tuning_task11', task_owner => 'SYS', replace =>

                                              TRUE);

                                   

                                   

                                    Validation results

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

                                    The SQL profile was tested by executing both its plan and the original plan

                                    and measuring their respective execution statistics. A plan may have been

                                    only partially executed if the other could be run to completion in less time.

                                   

                                   

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                                             Original Plan  With SQL Profile  % Improved

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

                                    Completion Status:             PARTIAL          COMPLETE

                                    Elapsed Time (s):           15.344327          6.306181       58.9 %

                                    CPU Time (s):               15.351586          6.307908      58.91 %

                                    User I/O Time (s):                  0           .001329

                                    Buffer Gets:                  4920244           1564233       68.2 %

                                    Physical Read Requests:             0                 2

                                    Physical Write Requests:            0                 0

                                    Physical Read Bytes:                0             16384

                                    Physical Write Bytes:               0                 0

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                    Rows Processed:                     0                 7

                                    Fetches:                            0                 7

                                    Executions:                         0                 1

                                   

                                   

                                  3- Index Finding (see explain plans section below)

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

                                    The execution plan of this statement can be improved by creating one or more

                                    indices.

                                   

                                   

                                    Recommendation (estimated benefit: 79.83%)

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

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                    - Consider running the Access Advisor to improve the physical schema design

                                      or creating the recommended index.

                                      create index APPLSYS.IDX$$_31CB10001 on

                                      APPLSYS.FND_LOOKUP_VALUES("LOOKUP_TYPE","LANGUAGE","ENABLED_FLAG","ZD_EDITI

                                      ON_NAME");

                                   

                                   

                                    - Consider running the Access Advisor to improve the physical schema design

                                      or creating the recommended index.

                                      create index XBSI.IDX$$_31CB10002 on XBSI.XXFASCOR_SKU_STG("MODE_STATUS","S

                                      KU","FACILITY_NBR");

                                   

                                   

                                   

                                   

                                  DBMS_SQLTUNE.REPORT_TUNING_TASK('0FRPJ87WS2B3U_TUNING_TASK11')

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

                                    Rationale

                                    ---------

                                      Creating the recommended indices significantly improves the execution plan

                                      of this statement. However, it might be preferable to run "Access Advisor"

                                      using a representative SQL workload as opposed to a single statement. This

                                      will allow to get comprehensive index recommendations which takes into

                                      account index maintenance overhead and additional space consumption.

                                  • 14. Re: Concurrent Program Trace File
                                    VishnuVinnakota

                                    Hi,

                                     

                                        I think you should go ahead and accept the SQL Profile as the benefit is significantly good. Let me know once applied. Since its a custom query, we need not worry about it.

                                     

                                    Thanks,

                                    Vishnu

                                    1 person found this helpful
                                    1 2 Previous Next