7 Replies Latest reply: Aug 2, 2012 3:56 AM by 952768 RSS

    Post Upgrade SQL Performance Issue

    Sky13
      Hello,
      I Just Upgraded/Migrated my database from 11.1.0.6 SE to 11.2.0.3 EE. I did this with datapump export/import out of the 11.1.0.6 and into a new 11.2.0.3 database. Both the old and the new database are on the same Linux server. The new database has 2GB more RAM assigned to its SGA then the old one. Both DB are using AMM.

      The strange part is I have a SQL statement that completes in 1 second in the Old DB and takes 30 seconds in the new one. I even moved the SQL Plan from the Old DB into the New DB so they are using the same plan.

      To sum up the issue. I have one SQL statement using the same SQL Plan running at dramatically different speeds on two different databases on the same server. The databases are 11.1.0.7 SE and 11.2.0.3 EE.

      Not sure what is going on or how to fix it, Any help would be great!

      I have included Explains and Auto Traces from both NEW and OLD databases.

      NEW DB Explain Plan (Slow)
      Plan hash value: 1046170788

      -------------------------------------------------------------------------------------------------------
      | Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
      -------------------------------------------------------------------------------------------------------
      | 0 | SELECT STATEMENT | | 94861 | 193M| | 74043 (1)| 00:18:52 |
      | 1 | SORT ORDER BY | | 94861 | 193M| 247M| 74043 (1)| 00:18:52 |
      | 2 | VIEW | PBM_MEMBER_INTAKE_VW | 94861 | 193M| | 31803 (1)| 00:08:07 |
      | 3 | UNION-ALL | | | | | | |
      | 4 | NESTED LOOPS OUTER | | 1889 | 173K| | 455 (1)| 00:00:07 |
      |* 5 | HASH JOIN | | 1889 | 164K| | 454 (1)| 00:00:07 |
      | 6 | TABLE ACCESS FULL| PBM_CODES | 2138 | 21380 | | 8 (0)| 00:00:01 |
      |* 7 | TABLE ACCESS FULL| PBM_MEMBER_INTAKE | 1889 | 145K| | 446 (1)| 00:00:07 |
      |* 8 | INDEX UNIQUE SCAN | ADJ_PK | 1 | 5 | | 1 (0)| 00:00:01 |
      | 9 | NESTED LOOPS | | 92972 | 9987K| | 31347 (1)| 00:08:00 |
      | 10 | NESTED LOOPS OUTER| | 92972 | 8443K| | 31346 (1)| 00:08:00 |
      |* 11 | TABLE ACCESS FULL| PBM_MEMBERS | 92972 | 7989K| | 31344 (1)| 00:08:00 |
      |* 12 | INDEX UNIQUE SCAN| ADJ_PK | 1 | 5 | | 1 (0)| 00:00:01 |
      |* 13 | INDEX UNIQUE SCAN | PBM_EMPLOYER_UK1 | 1 | 17 | | 1 (0)| 00:00:01 |
      -------------------------------------------------------------------------------------------------------

      Predicate Information (identified by operation id):
      ---------------------------------------------------

      5 - access("C"."CODE_ID"="MI"."STATUS_ID")
      7 - filter("MI"."CLAIM_NUMBER" LIKE '%A0000250%' AND "MI"."CLAIM_NUMBER" IS NOT NULL)
      8 - access("MI"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
      11 - filter("M"."THEIR_GROUP_ID" LIKE '%A0000250%' AND "M"."THEIR_GROUP_ID" IS NOT NULL)
      12 - access("M"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
      13 - access("M"."GROUP_CODE"="E"."GROUP_CODE" AND "M"."EMPLOYER_CODE"="E"."EMPLOYER_CODE")

      Note
      -----
      - SQL plan baseline "SYS_SQL_PLAN_a3c20fdcecd98dfe" used for this statement

      OLD DB Explain Plan (Fast)
      Plan hash value: 1046170788

      -------------------------------------------------------------------------------------------------------
      | Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
      -------------------------------------------------------------------------------------------------------
      | 0 | SELECT STATEMENT | | 95201 | 193M| | 74262 (1)| 00:14:52 |
      | 1 | SORT ORDER BY | | 95201 | 193M| 495M| 74262 (1)| 00:14:52 |
      | 2 | VIEW | PBM_MEMBER_INTAKE_VW | 95201 | 193M| | 31853 (1)| 00:06:23 |
      | 3 | UNION-ALL | | | | | | |
      | 4 | NESTED LOOPS OUTER | | 1943 | 178K| | 486 (1)| 00:00:06 |
      |* 5 | HASH JOIN | | 1943 | 168K| | 486 (1)| 00:00:06 |
      | 6 | TABLE ACCESS FULL| PBM_CODES | 2105 | 21050 | | 7 (0)| 00:00:01 |
      |* 7 | TABLE ACCESS FULL| PBM_MEMBER_INTAKE | 1943 | 149K| | 479 (1)| 00:00:06 |
      |* 8 | INDEX UNIQUE SCAN | ADJ_PK | 1 | 5 | | 0 (0)| 00:00:01 |
      | 9 | NESTED LOOPS | | 93258 | 9M| | 31367 (1)| 00:06:17 |
      | 10 | NESTED LOOPS OUTER| | 93258 | 8469K| | 31358 (1)| 00:06:17 |
      |* 11 | TABLE ACCESS FULL| PBM_MEMBERS | 93258 | 8014K| | 31352 (1)| 00:06:17 |
      |* 12 | INDEX UNIQUE SCAN| ADJ_PK | 1 | 5 | | 0 (0)| 00:00:01 |
      |* 13 | INDEX UNIQUE SCAN | PBM_EMPLOYER_UK1 | 1 | 17 | | 0 (0)| 00:00:01 |
      -------------------------------------------------------------------------------------------------------

      Predicate Information (identified by operation id):
      ---------------------------------------------------

      5 - access("C"."CODE_ID"="MI"."STATUS_ID")
      7 - filter("MI"."CLAIM_NUMBER" LIKE '%A0000250%')
      8 - access("MI"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
      11 - filter("M"."THEIR_GROUP_ID" LIKE '%A0000250%')
      12 - access("M"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
      13 - access("M"."GROUP_CODE"="E"."GROUP_CODE" AND "M"."EMPLOYER_CODE"="E"."EMPLOYER_CODE")

      NEW DB Auto trace (Slow)
      active txn count during cleanout     0
      blocks decrypted     0
      buffer is not pinned count     664129
      buffer is pinned count     3061793
      bytes received via SQL*Net from client     3339
      bytes sent via SQL*Net to client     28758
      Cached Commit SCN referenced     662366
      calls to get snapshot scn: kcmgss     3
      calls to kcmgas     0
      calls to kcmgcs     8
      CCursor + sql area evicted     0
      cell physical IO interconnect bytes     0
      cleanout - number of ktugct calls     0
      cleanouts only - consistent read gets     0
      cluster key scan block gets     0
      cluster key scans     0
      commit cleanout failures: block lost     0
      commit cleanout failures: callback failure      0
      commit cleanouts     0
      commit cleanouts successfully completed     0
      Commit SCN cached     0
      commit txn count during cleanout     0
      concurrency wait time     0
      consistent changes     0
      consistent gets     985371
      consistent gets - examination     2993
      consistent gets direct     0
      consistent gets from cache     985371
      consistent gets from cache (fastpath)     982093
      CPU used by this session     3551
      CPU used when call started     3551
      CR blocks created     0
      cursor authentications     1
      data blocks consistent reads - undo records applied     0
      db block changes     0
      db block gets     0
      db block gets direct     0
      db block gets from cache     0
      db block gets from cache (fastpath)     0
      DB time     3553
      deferred (CURRENT) block cleanout applications     0
      dirty buffers inspected     0
      Effective IO time     0
      enqueue releases     0
      enqueue requests     0
      execute count     3
      file io wait time     0
      free buffer inspected     0
      free buffer requested     0
      heap block compress     0
      Heap Segment Array Updates     0
      hot buffers moved to head of LRU     0
      HSC Heap Segment Block Changes     0
      immediate (CR) block cleanout applications     0
      immediate (CURRENT) block cleanout applications     0
      IMU Flushes     0
      IMU ktichg flush     0
      IMU Redo allocation size     0
      IMU undo allocation size     0
      index fast full scans (full)     2
      index fetch by key     0
      index scans kdiixs1     12944
      lob reads     0
      LOB table id lookup cache misses     0
      lob writes     0
      lob writes unaligned     0
      logical read bytes from cache     -517775360
      logons cumulative     0
      logons current     0
      messages sent     0
      no buffer to keep pinned count     10
      no work - consistent read gets     982086
      non-idle wait count     6
      non-idle wait time     0
      Number of read IOs issued     0
      opened cursors cumulative     4
      opened cursors current     1
      OS Involuntary context switches     853
      OS Maximum resident set size     0
      OS Page faults     0
      OS Page reclaims     2453
      OS System time used     9
      OS User time used     3549
      OS Voluntary context switches     238
      parse count (failures)     0
      parse count (hard)     0
      parse count (total)     1
      parse time cpu     0
      parse time elapsed     0
      physical read bytes     0
      physical read IO requests     0
      physical read total bytes     0
      physical read total IO requests     0
      physical read total multi block requests     0
      physical reads     0
      physical reads cache     0
      physical reads cache prefetch     0
      physical reads direct     0
      physical reads direct (lob)     0
      physical write bytes     0
      physical write IO requests     0
      physical write total bytes     0
      physical write total IO requests     0
      physical writes     0
      physical writes direct     0
      physical writes direct (lob)     0
      physical writes non checkpoint     0
      pinned buffers inspected     0
      pinned cursors current     0
      process last non-idle time     0
      recursive calls     0
      recursive cpu usage     0
      redo entries     0
      redo size     0
      redo size for direct writes     0
      redo subscn max counts     0
      redo synch time     0
      redo synch time (usec)     0
      redo synch writes     0
      Requests to/from client     3
      rollbacks only - consistent read gets     0
      RowCR - row contention     0
      RowCR attempts     0
      rows fetched via callback     0
      session connect time     0
      session cursor cache count     1
      session cursor cache hits     3
      session logical reads     985371
      session pga memory     131072
      session pga memory max     0
      session uga memory     392928
      session uga memory max     0
      shared hash latch upgrades - no wait     284
      shared hash latch upgrades - wait     0
      sorts (memory)     3
      sorts (rows)     243
      sql area evicted     0
      sql area purged     0
      SQL*Net roundtrips to/from client     4
      switch current to new buffer     0
      table fetch by rowid     1861456
      table fetch continued row     9
      table scan blocks gotten     0
      table scan rows gotten     0
      table scans (short tables)     0
      temp space allocated (bytes)     0
      undo change vector size     0
      user calls     7
      user commits     0
      user I/O wait time     0
      workarea executions - optimal     10
      workarea memory allocated     342

      OLD DB Auto trace (Fast)
      active txn count during cleanout     0
      buffer is not pinned count     4
      buffer is pinned count     101
      bytes received via SQL*Net from client     1322
      bytes sent via SQL*Net to client     9560
      calls to get snapshot scn: kcmgss     15
      calls to kcmgas     0
      calls to kcmgcs     0
      calls to kcmgrs     1
      cleanout - number of ktugct calls     0
      cluster key scan block gets     0
      cluster key scans     0
      commit cleanouts     0
      commit cleanouts successfully completed     0
      concurrency wait time     0
      consistent changes     0
      consistent gets     117149
      consistent gets - examination     56
      consistent gets direct     115301
      consistent gets from cache     1848
      consistent gets from cache (fastpath)     1792
      CPU used by this session     118
      CPU used when call started     119
      cursor authentications     1
      db block changes     0
      db block gets     0
      db block gets from cache     0
      db block gets from cache (fastpath)     0
      DB time     123
      deferred (CURRENT) block cleanout applications     0
      Effective IO time     2012
      enqueue conversions     3
      enqueue releases     2
      enqueue requests     2
      enqueue waits     1
      execute count     2
      free buffer requested     0
      HSC Heap Segment Block Changes     0
      IMU Flushes     0
      IMU ktichg flush     0
      index fast full scans (full)     0
      index fetch by key     101
      index scans kdiixs1     0
      lob writes     0
      lob writes unaligned     0
      logons cumulative     0
      logons current     0
      messages sent     0
      no work - consistent read gets     117080
      Number of read IOs issued     1019
      opened cursors cumulative     3
      opened cursors current     1
      OS Involuntary context switches     54
      OS Maximum resident set size     7868
      OS Page faults     12
      OS Page reclaims     2911
      OS System time used     57
      OS User time used     71
      OS Voluntary context switches     25
      parse count (failures)     0
      parse count (hard)     0
      parse count (total)     3
      parse time cpu     0
      parse time elapsed     0
      physical read bytes     944545792
      physical read IO requests     1019
      physical read total bytes     944545792
      physical read total IO requests     1019
      physical read total multi block requests     905
      physical reads     115301
      physical reads cache     0
      physical reads cache prefetch     0
      physical reads direct     115301
      physical reads prefetch warmup     0
      process last non-idle time     0
      recursive calls     0
      recursive cpu usage     0
      redo entries     0
      redo size     0
      redo synch writes     0
      rows fetched via callback     0
      session connect time     0
      session cursor cache count     1
      session cursor cache hits     2
      session logical reads     117149
      session pga memory     -983040
      session pga memory max     0
      session uga memory     0
      session uga memory max     0
      shared hash latch upgrades - no wait     0
      sorts (memory)     2
      sorts (rows)     157
      sql area purged     0
      SQL*Net roundtrips to/from client     3
      table fetch by rowid     0
      table fetch continued row     0
      table scan blocks gotten     117077
      table scan rows gotten     1972604
      table scans (direct read)     1
      table scans (long tables)     1
      table scans (short tables)     2
      undo change vector size     0
      user calls     5
      user I/O wait time     0
      workarea executions - optimal     4
        • 1. Re: Post Upgrade SQL Performance Issue
          Srini Chavali-Oracle
          Pl list any init.ora differences between the two databases. Pl also confirm that statistics on both instances are current. The explain plans show similar execution times and rows processed - 14 secs versus 18 secs.

          Pl see if this MOS Doc can help

          Things to Consider Before Upgrading to 11.2.0.3 to Avoid Poor Performance or Wrong Results [ID 1392633.1]

          HTH
          Srini
          • 2. Re: Post Upgrade SQL Performance Issue
            Sky13
            Hi Srini,

            Yes the stats on the tables and indexes are current in both DBs. However the NEW DB has "System Stats" in sys.aux_stats$ and the OLD DB does not. The old DB has optimizer_index_caching=0 and optimizer_index_cost_adj=100. The new DB as them at optimizer_index_caching=90 and optimizer_index_cost_adj=25 but should not be using them because of the "System Stats".

            Also I thought none of the SQL Optimize stuff would matter because I forced in my own SQL Plan using SPM.

            Differences in init.ora

            -----------------------------------------------------
            OLD-11     optimizerpush_pred_cost_based = FALSE
            -----------------------------------------------------
            NEW-15     audit_sys_operations = FALSE
                 audit_trail = "DB, EXTENDED"
                 awr_snapshot_time_offset = 0

            OLD-16     audit_sys_operations = TRUE
                 audit_trail = "XML, EXTENDED"
            -----------------------------------------------------
            NEW-22     cell_offload_compaction = "ADAPTIVE"
                 cell_offload_decryption = TRUE
                 cell_offload_plan_display = "AUTO"
                 cell_offload_processing = TRUE
            -----------------------------------------------------
            NEW-28     clonedb = FALSE
            -----------------------------------------------------
            NEW-32     compatible = "11.2.0.0.0"

            OLD-27     compatible = "11.1.0.0.0"
            -----------------------------------------------------
            NEW-37     cursor_bind_capture_destination = "memory+disk"
                 cursor_sharing = "FORCE"

            OLD-32     cursor_sharing = "EXACT"
            -----------------------------------------------------
            NEW-50     db_cache_size = 4294967296
                 db_domain = "my.com"

            OLD-44     db_cache_size = 0
            -----------------------------------------------------
            NEW-54     db_flash_cache_size = 0
            -----------------------------------------------------
            NEW-58     db_name = "NEWDB"
                 db_recovery_file_dest_size = 214748364800

            OLD-50     db_name = "OLDDB"
                 db_recovery_file_dest_size = 8438939648
            -----------------------------------------------------
            NEW-63     db_unique_name = "NEWDB"
                 db_unrecoverable_scn_tracking = TRUE
                 db_writer_processes = 2

            OLD-55     db_unique_name = "OLDDB"
                 db_writer_processes = 1
            -----------------------------------------------------
            NEW-68     deferred_segment_creation = TRUE
            -----------------------------------------------------
            NEW-71     dispatchers = "(PROTOCOL=TCP) (SERVICE=NEWDBXDB)"

            OLD-61     dispatchers = "(PROTOCOL=TCP) (SERVICE=OLDDBXDB)"
            -----------------------------------------------------
            NEW-73     dml_locks = 5068
                 dst_upgrade_insert_conv = TRUE

            OLD-63     dml_locks = 3652
                 drs_start = FALSE
            -----------------------------------------------------
            NEW-80     filesystemio_options = "SETALL"

            OLD-70     filesystemio_options = "none"
            -----------------------------------------------------
            NEW-87     instance_name = "NEWDB"

            OLD-77     instance_name = "OLDDB"
            -----------------------------------------------------
            NEW-94     job_queue_processes = 1000

            OLD-84     job_queue_processes = 100
            -----------------------------------------------------
            NEW-104     log_archive_dest_state_11 = "enable"
                 log_archive_dest_state_12 = "enable"
                 log_archive_dest_state_13 = "enable"
                 log_archive_dest_state_14 = "enable"
                 log_archive_dest_state_15 = "enable"
                 log_archive_dest_state_16 = "enable"
                 log_archive_dest_state_17 = "enable"
                 log_archive_dest_state_18 = "enable"
                 log_archive_dest_state_19 = "enable"
            -----------------------------------------------------
            NEW-114     log_archive_dest_state_20 = "enable"
                 log_archive_dest_state_21 = "enable"
                 log_archive_dest_state_22 = "enable"
                 log_archive_dest_state_23 = "enable"
                 log_archive_dest_state_24 = "enable"
                 log_archive_dest_state_25 = "enable"
                 log_archive_dest_state_26 = "enable"
                 log_archive_dest_state_27 = "enable"
                 log_archive_dest_state_28 = "enable"
                 log_archive_dest_state_29 = "enable"
            -----------------------------------------------------
            NEW-125     log_archive_dest_state_30 = "enable"
                 log_archive_dest_state_31 = "enable"
            -----------------------------------------------------
            NEW-139     log_buffer = 7012352

            OLD-108     log_buffer = 34412032
            -----------------------------------------------------
            OLD-112     max_commit_propagation_delay = 0
            -----------------------------------------------------
            NEW-144     max_enabled_roles = 150
                 memory_max_target = 12884901888
                 memory_target = 8589934592
                 nls_calendar = "GREGORIAN"

            OLD-114     max_enabled_roles = 140
                 memory_max_target = 6576668672
                 memory_target = 6576668672
            -----------------------------------------------------
            NEW-149     nls_currency = "$"
                 nls_date_format = "DD-MON-RR"
                 nls_date_language = "AMERICAN"
                 nls_dual_currency = "$"
                 nls_iso_currency = "AMERICA"
            -----------------------------------------------------
            NEW-157     nls_numeric_characters = ".,"
                 nls_sort = "BINARY"
            -----------------------------------------------------
            NEW-160     nls_time_format = "HH.MI.SSXFF AM"
                 nls_time_tz_format = "HH.MI.SSXFF AM TZR"
                 nls_timestamp_format = "DD-MON-RR HH.MI.SSXFF AM"
                 nls_timestamp_tz_format = "DD-MON-RR HH.MI.SSXFF AM TZR"
            -----------------------------------------------------
            NEW-172     optimizer_features_enable = "11.2.0.3"
                 optimizer_index_caching = 90
                 optimizer_index_cost_adj = 25

            OLD-130     optimizer_features_enable = "11.1.0.6"
                 optimizer_index_caching = 0
                 optimizer_index_cost_adj = 100
            -----------------------------------------------------
            NEW-184     parallel_degree_limit = "CPU"
                 parallel_degree_policy = "MANUAL"
                 parallel_execution_message_size = 16384
                 parallel_force_local = FALSE

            OLD-142     parallel_execution_message_size = 2152
            -----------------------------------------------------
            NEW-189     parallel_max_servers = 320

            OLD-144     parallel_max_servers = 0
            -----------------------------------------------------
            NEW-192     parallel_min_time_threshold = "AUTO"
            -----------------------------------------------------
            NEW-195     parallel_servers_target = 128
            -----------------------------------------------------
            NEW-197     permit_92_wrap_format = TRUE
            -----------------------------------------------------
            OLD-154     plsql_native_library_subdir_count = 0
            -----------------------------------------------------
            NEW-220     result_cache_max_size = 21495808

            OLD-173     result_cache_max_size = 0
            -----------------------------------------------------
            NEW-230     service_names = "NEWDB, NEWDB.my.com, NEW"

            OLD-183     service_names = "OLDDB, OLD.my.com"
            -----------------------------------------------------
            NEW-233     sessions = 1152
                 sga_max_size = 12884901888

            OLD-186     sessions = 830
                 sga_max_size = 6576668672
            -----------------------------------------------------
            NEW-238     shared_pool_reserved_size = 35232153

            OLD-191     shared_pool_reserved_size = 53687091
            -----------------------------------------------------
            OLD-199     sql_version = "NATIVE"
            -----------------------------------------------------
            NEW-248     star_transformation_enabled = "TRUE"

            OLD-202     star_transformation_enabled = "FALSE"
            -----------------------------------------------------
            NEW-253     timed_os_statistics = 60

            OLD-207     timed_os_statistics = 5
            -----------------------------------------------------
            NEW-256     transactions = 1267

            OLD-210     transactions = 913
            -----------------------------------------------------
            NEW-262     use_large_pages = "TRUE"
            • 3. Re: Post Upgrade SQL Performance Issue
              Srini Chavali-Oracle
              There are way too many init.ora parameter differences between the two databases, especially with optimizer settings :-) Plus the optimizer itself changes with each dot release. It is difficult to compare performance under such circumstances. The most you can do is compare explain plans after matching relevant init.ora parameters on the two databases.

              HTH
              Srini
              • 4. Re: Post Upgrade SQL Performance Issue
                rakesh_kumar
                Please post the output of DBMS_XPLAN.DISPLAY_CURSOR with 'ADVANCED' option for both the databases.

                Regards,
                Rakesh
                • 5. Re: Post Upgrade SQL Performance Issue
                  narentawar
                  You can consider using SQL Baseline feature of 11g, you may get some very good results.
                  • 6. Re: Post Upgrade SQL Performance Issue
                    Sky13
                    I was trying to use SPM/SQL Plan Baseline. At first when I posted this I thought the NEW DB was using my Plan Baseline I brought over from the OLD DB. However after running some traces I found it was not using the Plan Baseline so I opened a new thread to talk about why the Plan is not being used:
                    SQL Plan Management: SQL not using Plan Baseline
                    • 7. Re: Post Upgrade SQL Performance Issue
                      952768
                      When I look at your Auto trace values it seems that the optimizer is not working with the same plan. Can you perform a 10053 trace to see what is really going on?
                      You have to compare the choosen plans from both 10053 traces.