1 2 3 4 Previous Next 54 Replies Latest reply: Jan 15, 2013 6:29 PM by jgarry RSS

    Performance Issue

    yxes2013
      Hi All

      OEL 5.6
      Oracle 9.2.0.6

      Our applications are running intermittently from slow and ok performance. There are days that the processing from 8am to 5pm is okay and there are days that it is very slow and hanging.
      The users are just doing the same thing daily from 8am-5pm.

      Yesterday the users did not encounter any performance issues from 8am-5pm. But today they hit again the problem starting 1pm up to evening, until we cancel what they are doing because
      they are all hanging and decided to shutdown the database and the reboot machine itself hoping it might help. But then again after the database was restarted and the user started to run their process again it still very slow. Could it be hardware problem anymore?

      This is the statspack report yesterday from 2pm-3pm where the performance is good. And the next is the statspack report today from 2pm-2:30pm where the performance problem occurs.
      Please help me find the difference or the problem on the 2nd statspack. Your help is very much appreciated. Thanks a lot.

      http://www.datafilehost.com/download-49750b9f.html (normal performance)
      http://www.datafilehost.com/download-f6c8ebbe.html (bad performance)
      If downloading this file...
      Uncheck [ ] Use our download manager and get recommended download
      Partial display of normal performace statspack report:
      STATSPACK report for
      
      DB Name         DB Id    Instance     Inst Num Release     Cluster Host
      ------------ ----------- ------------ -------- ----------- ------- ------------
      OAPROD        4204192100 OAPROD              1 9.2.0.6.0   NO      oel5.unitrad
                                                                         e.local
      
                    Snap Id     Snap Time      Sessions Curs/Sess Comment
                  --------- ------------------ -------- --------- -------------------
      Begin Snap:       781 07-Jan-13 14:00:02      205      49.2
        End Snap:       782 07-Jan-13 14:30:03      206      55.5
         Elapsed:               30.02 (mins)
      
      Cache Sizes (end)
      ~~~~~~~~~~~~~~~~~
                     Buffer Cache:       288M      Std Block Size:          8K
                 Shared Pool Size:       288M          Log Buffer:     10,240K
      
      Load Profile
      ~~~~~~~~~~~~                            Per Second       Per Transaction
                                         ---------------       ---------------
                        Redo size:             28,913.12             17,857.52
                    Logical reads:            147,316.27             90,986.49
                    Block changes:                208.57                128.82
                   Physical reads:             77,818.67             48,062.91
                  Physical writes:                  7.28                  4.50
                       User calls:                108.83                 67.22
                           Parses:                103.67                 64.03
                      Hard parses:                  2.68                  1.65
                            Sorts:                 47.02                 29.04
                           Logons:                  0.17                  0.10
                         Executes:                516.70                319.13
                     Transactions:                  1.62
      
        % Blocks changed per Read:    0.14    Recursive Call %:     91.28
       Rollback per transaction %:    4.36       Rows per Sort:     23.20
      
      Instance Efficiency Percentages (Target 100%)
      ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                  Buffer Nowait %:   99.48       Redo NoWait %:    100.00
                  Buffer  Hit   %:   47.18    In-memory Sort %:    100.00
                  Library Hit   %:   99.77        Soft Parse %:     97.42
               Execute to Parse %:   79.94         Latch Hit %:     99.91
      Parse CPU to Parse Elapsd %:   43.83     % Non-Parse CPU:     99.66
      
       Shared Pool Statistics        Begin   End
                                     ------  ------
                   Memory Usage %:   91.30   91.40
          % SQL with executions>1:   92.30   97.31
        % Memory for SQL w/exec>1:   90.15   95.15
      
      Top 5 Timed Events
      ~~~~~~~~~~~~~~~~~~                                                     % Total
      Event                                               Waits    Time (s) Ela Time
      -------------------------------------------- ------------ ----------- --------
      CPU time                                                        5,152    71.73
      db file scattered read                         24,697,470       1,152    16.05
      db file sequential read                        12,905,526         733    10.21
      log file parallel write                             3,682          48      .66
      buffer busy waits                               1,375,553          46      .64
                -------------------------------------------------------------
      ^LWait Events for DB: OAPROD  Instance: OAPROD  Snaps: 781 -782
      -> s  - second
      -> cs - centisecond -     100th of a second
      -> ms - millisecond -    1000th of a second
      -> us - microsecond - 1000000th of a second
      -> ordered by wait time desc, waits desc (idle events last)
      
                                                                         Avg
                                                           Total Wait   wait    Waits
      Event                               Waits   Timeouts   Time (s)   (ms)     /txn
      ---------------------------- ------------ ---------- ---------- ------ --------
      db file scattered read         24,697,470          0      1,152      0  8,469.6
      db file sequential read        12,905,526          0        733      0  4,425.8
      log file parallel write             3,682          0         48     13      1.3
      buffer busy waits               1,375,553          0         46      0    471.7
      log file sync                       2,109          0         35     17      0.7
      db file parallel read                  77          0          7     89      0.0
      latch free                          1,210        771          4      3      0.4
      control file parallel write           641          0          4      6      0.2
      SQL*Net break/reset to clien        3,700          0          1      0      1.3
      SQL*Net more data to client        31,307          0          0      0     10.7
      library cache pin                      13          0          0     19      0.0
      enqueue                                 1          0          0    141      0.0
      process startup                        12          0          0      8      0.0
      control file sequential read          688          0          0      0      0.2
      log file switch completion              3          0          0      4      0.0
      db file parallel write              1,626          0          0      0      0.6
      db file single write                   14          0          0      0      0.0
      undo segment extension              2,151      2,151          0      0      0.7
      LGWR wait for redo copy                92          0          0      0      0.0
      log file single write                   4          0          0      0      0.0
      direct path write                      66          0          0      0      0.0
      direct path read                       47          0          0      0      0.0
      async disk IO                          14          0          0      0      0.0
      log file sequential read                4          0          0      0      0.0
      SQL*Net message from client       204,344          0    177,547    869     70.1
      queue messages                      4,200      4,200     28,128   6697      1.4
      pipe get                            1,349      1,314      5,274   3910      0.5
      wakeup time manager                    59         59      1,693  28690      0.0
      jobq slave wait                       240        240        703   2930      0.1
      SQL*Net more data from clien       54,199          0          2      0     18.6
      SQL*Net message to client         204,341          0          0      0     70.1
                -------------------------------------------------------------
      ^LBackground Wait Events for DB: OAPROD  Instance: OAPROD  Snaps: 781 -782
      -> ordered by wait time desc, waits desc (idle events last)
      
                                                                         Avg
                                                           Total Wait   wait    Waits
      Event                               Waits   Timeouts   Time (s)   (ms)     /txn
      ---------------------------- ------------ ---------- ---------- ------ --------
      log file parallel write             3,682          0         48     13      1.3
      db file sequential read               399          0          4     10      0.1
      control file parallel write           613          0          4      6      0.2
      rdbms ipc reply                        55          0          0      1      0.0
      control file sequential read          339          0          0      0      0.1
      db file parallel write              1,626          0          0      0      0.6
      LGWR wait for redo copy                92          0          0      0      0.0
      buffer busy waits                       6          0          0      0      0.0
      log file single write                   4          0          0      0      0.0
      direct path read                       47          0          0      0      0.0
      latch free                              2          1          0      0      0.0
      direct path write                      47          0          0      0      0.0
      log file sequential read                4          0          0      0      0.0
      rdbms ipc message                  16,695      2,366      8,731    523      5.7
      smon timer                            457          0      1,781   3898      0.2
      pmon timer                            611        611      1,758   2877      0.2
                -------------------------------------------------------------
      ^LSQL ordered by Gets for DB: OAPROD  Instance: OAPROD  Snaps: 781 -782
      -> End Buffer Gets Threshold:     10000
      -> Note that resources reported for PL/SQL includes the resources used by
         all SQL statements called within the PL/SQL code.  As individual SQL
         statements are also reported, it is possible and valid for the summed
         total % to exceed 100
      
                                                           CPU      Elapsd
        Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
      --------------- ------------ -------------- ------ -------- --------- ----------
          170,415,700            7   24,345,100.0   64.2  2293.46   2335.60  205460129
      Module: JDBC Thin Client
      select  TRANSACTION_BRANCH , BRANCH_ADDRESS_1 , BRANCH_ADDRESS_2
       , BRANCH_PHONES , BRANCH_FAX , BRANCH_TIN , TRX_NUMBER , TRX_NU
      MBER_DISP , TRX_DATE , TRX_DATE_DISP , BILL_TO_CUSTOMER_ID , BIL
      L_TO_CUSTOMER_NAME , SHIP_DATE_ACTUAL_DISP , SHIP_TO_NAME , SHIP
      _TO_ADDRESS1 , SHIP_TO_ADDRESS2 , SHIP_TO_ADDRESS3 , SHIP_TO_ADD
      
           46,298,646        3,452       13,412.1   17.5   828.53    834.22 3761220362
      Module: JDBC Thin Client
      SELECT DELV_ADDR.ADDRESS1 FROM APPS.OE_ORDER_HEADERS_ALL OE_HEAD
      ERS , APPS.RA_SITE_USES_ALL DELV_SITE , APPS.RA_ADDRESSES_ALL DE
      LV_ADDR WHERE TO_CHAR(ORDER_NUMBER) = :B1 AND DELV_SITE.SITE_USE
      _ID(+) = OE_HEADERS.DELIVER_TO_ORG_ID AND DELV_ADDR.ADDRESS_ID(+
      ) = DELV_SITE.ADDRESS_ID
      
           46,298,632        3,440       13,458.9   17.5   814.25    835.98 4273350236
      Module: JDBC Thin Client
      SELECT DELV_ADDR.ADDRESS2 FROM APPS.OE_ORDER_HEADERS_ALL OE_HEAD
      ERS , APPS.RA_SITE_USES_ALL DELV_SITE , APPS.RA_ADDRESSES_ALL DE
      LV_ADDR WHERE TO_CHAR(ORDER_NUMBER) = :B1 AND DELV_SITE.SITE_USE
      _ID(+) = OE_HEADERS.DELIVER_TO_ORG_ID AND DELV_ADDR.ADDRESS_ID(+
      ) = DELV_SITE.ADDRESS_ID
      
           46,271,968        3,452       13,404.4   17.4   815.70    835.14  803969757
      Module: JDBC Thin Client
      SELECT COALESCE(DELV_ADDR.CITY, DELV_ADDR.PROVINCE) FROM APPS.OE
      _ORDER_HEADERS_ALL OE_HEADERS , APPS.RA_SITE_USES_ALL DELV_SITE
      , APPS.RA_ADDRESSES_ALL DELV_ADDR WHERE TO_CHAR(ORDER_NUMBER) =
      :B1 AND DELV_SITE.SITE_USE_ID(+) = OE_HEADERS.DELIVER_TO_ORG_ID
      AND DELV_ADDR.ADDRESS_ID(+) = DELV_SITE.ADDRESS_ID
      
           40,281,049        3,008       13,391.3   15.2   867.23    857.26 3960143944
      Module: EXCEL.EXE
      SELECT CASE WHEN ORDER_CATEGORY_CODE = 'MIXED' THEN TO_CHAR(ORDE
      R_NUMBER) WHEN ORDER_CATEGORY_CODE = 'RETURN' THEN TO_CHAR(CUST_
      PO_NUMBER) END REFERENCE_NUMBER FROM APPS.OE_ORDER_HEADERS_ALL W
      HERE TO_CHAR(ORDER_NUMBER) = :B1
      
           23,112,200            1   23,112,200.0    8.7   412.43    416.11 2208319477
      Module: JDBC Thin Client
      select  TRANSACTION_BRANCH , BRANCH_ADDRESS_1 , BRANCH_ADDRESS_2
       , BRANCH_PHONES , BRANCH_FAX , BRANCH_TIN , TRX_NUMBER , TRX_NU
      MBER_DISP , TRX_DATE , TRX_DATE_DISP , BILL_TO_CUSTOMER_ID , BIL
      L_TO_CUSTOMER_NAME , SHIP_DATE_ACTUAL_DISP , SHIP_TO_NAME , SHIP
      _TO_ADDRESS1 , SHIP_TO_ADDRESS2 , SHIP_TO_ADDRESS3 , SHIP_TO_ADD
      
            6,719,590            2    3,359,795.0    2.5    12.82    332.71 2258492566
      Module: Scheduler.vshost.exe
      select  om_trx.header_id header_id ,       om_trx.order_number o
      ^LSQL ordered by Gets for DB: OAPROD  Instance: OAPROD  Snaps: 781 -782
      -> End Buffer Gets Threshold:     10000
      -> Note that resources reported for PL/SQL includes the resources used by
         all SQL statements called within the PL/SQL code.  As individual SQL
         statements are also reported, it is possible and valid for the summed
      Bad performance statspack report
      STATSPACK report for
      
      DB Name         DB Id    Instance     Inst Num Release     Cluster Host
      ------------ ----------- ------------ -------- ----------- ------- ------------
      OAPROD        4204192100 OAPROD              1 9.2.0.6.0   NO      oel5.unitrad
                                                                         e.local
      
                    Snap Id     Snap Time      Sessions Curs/Sess Comment
                  --------- ------------------ -------- --------- -------------------
      Begin Snap:       848 08-Jan-13 14:00:15      191      58.0
        End Snap:       849 08-Jan-13 14:30:16      189      53.5
         Elapsed:               30.02 (mins)
      
      Cache Sizes (end)
      ~~~~~~~~~~~~~~~~~
                     Buffer Cache:       288M      Std Block Size:          8K
                 Shared Pool Size:       288M          Log Buffer:     10,240K
      
      Load Profile
      ~~~~~~~~~~~~                            Per Second       Per Transaction
                                         ---------------       ---------------
                        Redo size:             15,339.00             18,115.11
                    Logical reads:             48,006.97             56,695.45
                    Block changes:                129.73                153.21
                   Physical reads:             21,322.15             25,181.11
                  Physical writes:                453.54                535.63
                       User calls:                105.47                124.56
                           Parses:                 51.61                 60.95
                      Hard parses:                  0.35                  0.41
                            Sorts:                152.73                180.37
                           Logons:                  0.09                  0.10
                         Executes:                280.08                330.77
                     Transactions:                  0.85
      
        % Blocks changed per Read:    0.27    Recursive Call %:     82.69
       Rollback per transaction %:    7.28       Rows per Sort:    642.74
      
      Instance Efficiency Percentages (Target 100%)
      ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                  Buffer Nowait %:   99.78       Redo NoWait %:    100.00
                  Buffer  Hit   %:   56.53    In-memory Sort %:    100.00
                  Library Hit   %:   99.88        Soft Parse %:     99.32
               Execute to Parse %:   81.57         Latch Hit %:     99.96
      Parse CPU to Parse Elapsd %:    1.83     % Non-Parse CPU:     99.35
      
       Shared Pool Statistics        Begin   End
                                     ------  ------
                   Memory Usage %:   93.02   92.88
          % SQL with executions>1:   91.97   86.95
        % Memory for SQL w/exec>1:   87.44   82.90
      
      Top 5 Timed Events
      ~~~~~~~~~~~~~~~~~~                                                     % Total
      Event                                               Waits    Time (s) Ela Time
      -------------------------------------------- ------------ ----------- --------
      db file sequential read                         4,716,349      11,481    63.42
      buffer busy waits                                 191,973       3,879    21.43
      db file scattered read                          8,123,555       1,824    10.07
      CPU time                                                          422     2.33
      log file parallel write                             1,755         238     1.32
                -------------------------------------------------------------
      ^LWait Events for DB: OAPROD  Instance: OAPROD  Snaps: 848 -849
      -> s  - second
      -> cs - centisecond -     100th of a second
      -> ms - millisecond -    1000th of a second
      -> us - microsecond - 1000000th of a second
      -> ordered by wait time desc, waits desc (idle events last)
      
                                                                         Avg
                                                           Total Wait   wait    Waits
      Event                               Waits   Timeouts   Time (s)   (ms)     /txn
      ---------------------------- ------------ ---------- ---------- ------ --------
      db file sequential read         4,716,349          0     11,481      2  3,092.7
      buffer busy waits                 191,973         11      3,879     20    125.9
      db file scattered read          8,123,555          0      1,824      0  5,326.9
      log file parallel write             1,755          0        238    136      1.2
      log file sync                       1,208          2        174    144      0.8
      control file parallel write           586          0         62    106      0.4
      db file parallel read                  36          0         17    479      0.0
      latch free                          1,111        723          5      5      0.7
      SQL*Net break/reset to clien        4,298          0          0      0      2.8
      enqueue                                 3          0          0     83      0.0
      SQL*Net more data to client        18,913          0          0      0     12.4
      direct path write                  66,717          0          0      0     43.7
      control file sequential read          370          0          0      0      0.2
      process startup                        12          0          0     11      0.0
      direct path read                   72,482          0          0      0     47.5
      direct path write (lob)                 1          0          0      9      0.0
      db file parallel write                858          0          0      0      0.6
      db file single write                    1          0          0      1      0.0
      LGWR wait for redo copy                10          0          0      0      0.0
      direct path read (lob)                  9          0          0      0      0.0
      async disk IO                           1          0          0      0      0.0
      SQL*Net message from client       194,370          0    158,285    814    127.5
      queue messages                        924        924      7,023   7600      0.6
      pipe get                            1,328      1,322      5,267   3966      0.9
      wakeup time manager                    60         60      1,678  27967      0.0
      jobq slave wait                       238        238        697   2931      0.2
      SQL*Net more data from clien       39,093          0          1      0     25.6
      SQL*Net message to client         194,377          0          0      0    127.5
                -------------------------------------------------------------
      ^LBackground Wait Events for DB: OAPROD  Instance: OAPROD  Snaps: 848 -849
      -> ordered by wait time desc, waits desc (idle events last)
      
                                                                         Avg
                                                           Total Wait   wait    Waits
      Event                               Waits   Timeouts   Time (s)   (ms)     /txn
      ---------------------------- ------------ ---------- ---------- ------ --------
      log file parallel write             1,755          0        238    136      1.2
      db file scattered read              1,470          0         83     56      1.0
      control file parallel write           584          0         61    105      0.4
      db file sequential read               786          0         44     56      0.5
      control file sequential read          253          0          0      0      0.2
      latch free                              7          2          0      2      0.0
      db file parallel write                858          0          0      0      0.6
      rdbms ipc reply                        10          0          0      0      0.0
      LGWR wait for redo copy                10          0          0      0      0.0
      direct path read                       47          0          0      0      0.0
      buffer busy waits                       2          0          0      0      0.0
      direct path write                      47          0          0      0      0.0
      rdbms ipc message                   9,487      2,212      6,577    693      6.2
      pmon timer                            604        604      1,755   2906      0.4
      smon timer                            144          0      1,618  11238      0.1
                -------------------------------------------------------------
      ^LSQL ordered by Gets for DB: OAPROD  Instance: OAPROD  Snaps: 848 -849
      -> End Buffer Gets Threshold:     10000
      -> Note that resources reported for PL/SQL includes the resources used by
         all SQL statements called within the PL/SQL code.  As individual SQL
         statements are also reported, it is possible and valid for the summed
         total % to exceed 100
      
                                                           CPU      Elapsd
        Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
      --------------- ------------ -------------- ------ -------- --------- ----------
           53,507,965        3,993       13,400.4   61.9  1198.56   1248.98 3960143944
      Module: EXCEL.EXE
      SELECT CASE WHEN ORDER_CATEGORY_CODE = 'MIXED' THEN TO_CHAR(ORDE
      R_NUMBER) WHEN ORDER_CATEGORY_CODE = 'RETURN' THEN TO_CHAR(CUST_
      PO_NUMBER) END REFERENCE_NUMBER FROM APPS.OE_ORDER_HEADERS_ALL W
      HERE TO_CHAR(ORDER_NUMBER) = :B1
      
           11,925,524            1   11,925,524.0   13.8   144.55   3413.42 2663139152
      Module: EXCEL.EXE
      SELECT VW_USR_SL_CUSTOMER_PERFORMANCE.HEADER_ID, VW_USR_SL_CUSTO
      MER_PERFORMANCE.ORDER_NUMBER, VW_USR_SL_CUSTOMER_PERFORMANCE.CUS
      TOMER_PO_NUMBER, VW_USR_SL_CUSTOMER_PERFORMANCE.AR_TRX_NUMBER, V
      W_USR_SL_CUSTOMER_PERFORMANCE.ORDERED_DATE, VW_USR_SL_CUSTOMER_P
      ERFORMANCE.PERPOST, VW_USR_SL_CUSTOMER_PERFORMANCE.SALES_PERIOD,
      
            9,884,668      214,884           46.0   11.4    66.35     82.39 2827770190
      Module: oracle@misdata.unitrade.local (TNS V1-V3)
      SELECT CHAIN_ID FROM JSCUS.USR_SL_SOLOMON_LKUP_CUST_REF@OAPROD W
      HERE SOLOMON_CUST_ID = :B1 GROUP BY CHAIN_ID
      
            6,023,418            6    1,003,903.0    7.0     9.83    198.32 2076298416
      Module: FNDWFBG
      BEGIN WF_ENGINE.BACKGROUNDCONCURRENT( :errbuf, :rc,:A0,:A1,:A2,:
      A3,:A4,:A5); END;
      
            5,793,148            6      965,524.7    6.7     7.04    101.65 2881611387
      Module: FNDWFBG
      SELECT /*+ ORDERED USE_NL (WIASP WI WPAP WAP)                 IN
      DEX (WIASP WF_ITEM_ACTIVITY_STATUSES_N1) */ WIASP.ROWID ROW_ID F
      ROM WF_ITEM_ACTIVITY_STATUSES WIASP, WF_ITEMS WI, WF_PROCESS_ACT
      IVITIES WPAP, WF_ACTIVITIES WAP WHERE WIASP.PROCESS_ACTIVITY = W
      PAP.INSTANCE_ID AND WPAP.ACTIVITY_ITEM_TYPE = WAP.ITEM_TYPE AND
      
            4,397,623            4    1,099,405.8    5.1    15.56    840.30 3547482375
      Module: JDBC Thin Client
      SELECT * FROM JSCUS.VW_USR_AP_VOUCHER_UNACCOUNTED WHERE REFERENC
      E_NUMBER BETWEEN :1 AND COALESCE(:2,:3) AND ORG_ID = :4 ORDER BY
       INVOICE_ID , NATURAL_ACCOUNT
      
            2,349,056            1    2,349,056.0    2.7     5.38     54.28 3437302100
      Module: APXIWALL
      SELECT ROW_ID,INVOICE_ID,VENDOR_ID,VENDOR_SITE_ID,SET_OF_BOOKS_I
      D,VENDOR_NAME,VENDOR_SITE_CODE,VENDOR_NUMBER,NUM_1099,INVOICE_NU
      M,INVOICE_TYPE,INVOICE_DATE,BATCH_NAME,INVOICE_TYPE_LOOKUP_CODE,
      INVOICE_CURRENCY_CODE,PAYMENT_CURRENCY_CODE,ACTUAL_INVOICE_AMOUN
      T,INVOICE_AMOUNT,ORIGINAL_PREPAYMENT_AMOUNT,VOUCHER_NUM,DOC_SEQU
      
            2,001,035            1    2,001,035.0    2.3     7.40     46.65  824154294
      Module: JDBC Thin Client
      SELECT *^M FROM JSCUS.VW_USR_AP_VOUCHER_ACCTG^M WHERE VOUCHER_NUMB
      ^LSQL ordered by Gets for DB: OAPROD  Instance: OAPROD  Snaps: 848 -849
      -> End Buffer Gets Threshold:     10000
      -> Note that resources reported for PL/SQL includes the resources used by
         all SQL statements called within the PL/SQL code.  As individual SQL
         statements are also reported, it is possible and valid for the summed
      Edited by: yxes2013 on 8.1.2013 8:45
        • 1. Re: Performance Issue
          Rob_J
          I can't see those reports because the it's blocked at my work :(

          Care the post the top timed events sections and important bits?

          Also, didn't you ask a question the other day about this same subject? Where there were many recommendations, such as increasing REDO logs and tuning some of the SQL? Was that resolved?
          • 2. Re: Performance Issue
            Aman....
            I am on my phone so can't download and read the reports but from this,
            But then again after the database was restarted and the user started to run their process again it still very slow.
            It seems that you have undersized your memory parameters or you have an application which is somehow consuming the entire memory areas of yours and finally, when there is a memory crunch , system seems to be crawling. That's just a guess though as I haven't seen the report.

            Aman....
            • 3. Re: Performance Issue
              Rob_J
              This is the same DB we were looking at in the previous post, right?

              1. Did you change the REDO log size?
              2. Did you look at the SQL Jonathan Lewis pointed out?

              The report shows that you are OK on CPU for that time period.
              The next biggest wait is db file scattered reads, so most likely full table scans from your queries
              Your db_cache is tiny, 288MB, how much data are you selecting? If more than 288MB, can you increase your cache?
              You'll then need to look at the SQL statements in order of time taken/resources used and try to optimize them if you can

              And your bad performance time shows that the db file sequenital reads are the bottleneck, along with buffer busy waits. I'd say this is because your queries are waiting for one another to read the blocks from disk into your buffer cache because it's too small to hold enough data and has to keep swapping them in and out of the cache.

              My answer would be to first increase db_cache_size in order to alleviate the problems if it's causing you such an issue, then look at the SQL queries which are running and try to improve them. 288MB is incredibly small for a database. What kind of data volumes are you working with?

              Edited by: Rob_J on Jan 8, 2013 4:56 PM
              • 4. Re: Performance Issue
                yxes2013
                Thanks,
                It seems that you have undersized your memory parameters or you have an application which is somehow consuming the entire memory areas of yours and finally, when there is a memory crunch , system seems to be crawling. That's just a guess though as I haven't seen the report.
                But why is it okay yesterday? The user is processing same number of transaction. or maybe they are not telling the truth or maybe there are hidden jobs being activated? But the operators
                said they just run same thing.
                • 5. Re: Performance Issue
                  Rob_J
                  Look at the queries in the report, they are different. One day, good day, they are all from JDBC clients. Bad day they are from EXCEL.exe.
                  • 6. Re: Performance Issue
                    jgarry
                    [url http://tkyte.blogspot.com/2012/05/another-debugging-story.html]Was it raining on Monday?
                    • 7. Re: Performance Issue
                      sb92075
                      yxes2013 wrote:
                      Thanks,
                      It seems that you have undersized your memory parameters or you have an application which is somehow consuming the entire memory areas of yours and finally, when there is a memory crunch , system seems to be crawling. That's just a guess though as I haven't seen the report.
                      But why is it okay yesterday? The user is processing same number of transaction. or maybe they are not telling the truth or maybe there are hidden jobs being activated? But the operators
                      said they just run same thing.
                      since you decide to not answer any of our questions, we can decide to not answer any of your questions!
                      • 8. Re: Performance Issue
                        yxes2013
                        Thanks,

                        Yes this is the same issue last Jan 2. Its happening internittently.

                        I already increased the redo to 100Mb and the undo_retention from 1800 to 3600 but I still get ORA-01555

                        The logswitching seem not to fast now:
                        Thread 1 opened at log sequence 136562
                          Current log# 3 seq# 136562 mem# 0: /u02/oracle/oaproddata/log03a.dbf
                          Current log# 3 seq# 136562 mem# 1: /u02/oracle/oaproddata/log03b.dbf
                        Successful open of redo thread 1
                        Tue Jan  8 11:59:23 2013
                        MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
                        Tue Jan  8 11:59:23 2013
                        SMON: enabling cache recovery
                        Tue Jan  8 11:59:23 2013
                        Successfully onlined Undo Tablespace 368.
                        Tue Jan  8 11:59:23 2013
                        SMON: enabling tx recovery
                        Tue Jan  8 11:59:23 2013
                        Database Characterset is UTF8
                        replication_dependency_tracking turned off (no async multimaster replication found)
                        Completed: ALTER DATABASE OPEN
                        Tue Jan  8 12:02:18 2013
                        Beginning log switch checkpoint up to RBA [0x21573.2.10], SCN: 0x056e.7521cc0e
                        Thread 1 advanced to log sequence 136563
                          Current log# 4 seq# 136563 mem# 0: /u02/oracle/oaproddata/log04a.dbf
                          Current log# 4 seq# 136563 mem# 1: /u02/oracle/oaproddata/log04b.dbf
                        Tue Jan  8 12:22:33 2013
                        Completed checkpoint up to RBA [0x21573.2.10], SCN: 0x056e.7521cc0e
                        Tue Jan  8 12:50:04 2013
                        Beginning log switch checkpoint up to RBA [0x21574.2.10], SCN: 0x056e.752326a7
                        Thread 1 advanced to log sequence 136564
                          Current log# 3 seq# 136564 mem# 0: /u02/oracle/oaproddata/log03a.dbf
                          Current log# 3 seq# 136564 mem# 1: /u02/oracle/oaproddata/log03b.dbf
                        Tue Jan  8 13:10:19 2013
                        Completed checkpoint up to RBA [0x21574.2.10], SCN: 0x056e.752326a7
                        Tue Jan  8 13:49:16 2013
                        Beginning log switch checkpoint up to RBA [0x21575.2.10], SCN: 0x056e.7524a192
                        Thread 1 advanced to log sequence 136565
                          Current log# 4 seq# 136565 mem# 0: /u02/oracle/oaproddata/log04a.dbf
                          Current log# 4 seq# 136565 mem# 1: /u02/oracle/oaproddata/log04b.dbf
                        Tue Jan  8 14:10:16 2013
                        Completed checkpoint up to RBA [0x21575.2.10], SCN: 0x056e.7524a192
                        Tue Jan  8 14:58:52 2013
                        Errors in file /u02/oracle/oaproddb/9.2.0/admin/OAPROD_oel5/udump/oaprod_ora_8774.trc:
                        ORA-12570: TNS:packet reader failure
                        ORA-06512: at "JSCUS.FUNC_GET_MTL_SRC", line 23
                        Tue Jan  8 15:03:27 2013
                        Beginning log switch checkpoint up to RBA [0x21576.2.10], SCN: 0x056e.7527328b
                        Thread 1 advanced to log sequence 136566
                          Current log# 3 seq# 136566 mem# 0: /u02/oracle/oaproddata/log03a.dbf
                          Current log# 3 seq# 136566 mem# 1: /u02/oracle/oaproddata/log03b.dbf
                        Tue Jan  8 15:23:42 2013
                        Completed checkpoint up to RBA [0x21576.2.10], SCN: 0x056e.7527328b
                        Tue Jan  8 15:42:24 2013
                        I mean I got tns packet failer at the time when the problem hits at 2pm
                        and also ORA-01555

                        ORA-12570: TNS:packet reader failure
                        ORA-06512: at "JSCUS.FUNC_GET_MTL_SRC", line 23
                        Tue Jan 8 15:03:27 2013
                        Beginning log switch checkpoint up to RBA [0x21576.2.10], SCN: 0x056e.7527328b


                        Then after we restarted the server and database after 1 hours Ora-01555 occurs again but no more tns packet error.

                        Edited by: yxes2013 on 8.1.2013 9:24
                        • 9. Re: Performance Issue
                          sb92075
                          [oracle@localhost dbs]$ oerr ora 12570
                          12570, 00000, "TNS:packet reader failure"
                          // *Cause: An error occurred during a data receive.
                          // *Action: Not normally visible to the user. For further details, turn
                          // on tracing and reexecute the operation. If error persists, contact
                          // Oracle Customer Support.
                          • 10. Re: Performance Issue
                            Aman....
                            100mb size for a production db is actually a little small. How about you set it to something really large, for example like 1gb and along with set the parameter archive_lag_target to control the log switching?

                            Aman....
                            • 11. Re: Performance Issue
                              Rob_J
                              We were looking at a different time period, though. Your issue previously was from 22:00 to 00:00. How is the log switching then?

                              What did you base the 1800 to 3600 decision on? You need to look at how long your longest running query is, in seconds, and set the undo to at least that value. How long is the query which runs running for before you get the ORA-01555 error?

                              Also take note of what process is receiving the error, as sb pointed out before if I remember correctly it can also be caused by committing inside of a pl/sql loop

                              Your second issue is related to poor performance of SQL queries, so answer the following questions:

                              1. Are the queries optimal?
                              2. If so, how much data are they dealing with? KBs, MBs, GBs?
                              3. Can you increase your SGA to handle more appropriately the volume required by the queries?
                              4. Also note that the queries in your good and bay days are different so the load pattern is not comparable
                              • 12. Re: Performance Issue
                                Jonathan Lewis
                                yxes2013 wrote:

                                This is the statspack report yesterday from 2pm-3pm where the performance is good. And the next is the statspack report today from 2pm-2:30pm where the performance problem occurs.
                                Please help me find the difference or the problem on the 2nd statspack. Your help is very much appreciated. Thanks a lot.

                                http://www.datafilehost.com/download-49750b9f.html (normal performance)
                                http://www.datafilehost.com/download-f6c8ebbe.html (bad performance)
                                Top 5 Timed Events
                                ~~~~~~~~~~~~~~~~~~                                                     % Total
                                Event                                               Waits    Time (s) Ela Time
                                -------------------------------------------- ------------ ----------- --------
                                CPU time                                                        5,152    71.73
                                
                                Event                               Waits   Timeouts   Time (s)   (ms)     /txn
                                ---------------------------- ------------ ---------- ---------- ------ --------
                                db file scattered read         24,697,470          0      1,152      0  8,469.6
                                db file sequential read        12,905,526          0        733      0  4,425.8
                                log file parallel write             3,682          0         48     13      1.3
                                buffer busy waits               1,375,553          0         46      0    471.7
                                log file sync                       2,109          0         35     17      0.7
                                
                                
                                Event                                               Waits    Time (s) Ela Time
                                -------------------------------------------- ------------ ----------- --------
                                CPU time                                                          422     2.33
                                Avg
                                Total Wait wait Waits
                                Event Waits Timeouts Time (s) (ms) /txn
                                ---------------------------- ------------ ---------- ---------- ------ --------
                                db file sequential read 4,716,349 0 11,481 2 3,092.7
                                buffer busy waits 191,973 11 3,879 20 125.9
                                db file scattered read 8,123,555 0 1,824 0 5,326.9
                                log file parallel write 1,755 0 238 136 1.2
                                log file sync 1,208 2 174 144 0.8

                                Counterintuitively you say that your performance is good in the first case where the machine is doing a ludicrous amount of extremely inefficient work. This is an indication that your machine is massively overpowered and you could possibly save a fortune on Oracle licences.

                                When performance is bad, the machine is doing much less work - which means that something is introducing contention which stops your (inefficient) processes from being able to work. One question worth asking is, are there other things on the machine outside oracle which suddenly steal the filesystem cache and leave a large number of your "physical reads" actually going to disc rather than coming from memory ?

                                The other check is simply to find something that gets bigger when the performance gets worse. The only thing I can see on a quick glance through the reports is the number of direct path writes (which report as physical writes - for a total of about 800,000 blocks written. These writes may be enough to interfere with your extravagent rate of reads.

                                Since the redo size DROPs, these writes may be to the temporary tablespace (sprt/hash) or they may be the result of NOLOGGING operations such as direct path loads or table moves or index rebuilds. When you look at the tablespace I/O stats, they look like workarea operations - so you may be able to find the driving SQL in v$sql_workarea.

                                (If you got rid of the half dozen massively inefficient SQL statements it's possible that whatever causes the slow-down wouldn't have anything that could be slowed down, though.

                                Regards
                                Jonathan Lewis
                                • 13. Re: Performance Issue
                                  yxes2013
                                  I thank you all,


                                  1. Are the queries optimal?
                                  I dont know :( do I need to show you the explain plan. How do I know if its optimal?
                                  2. If so, how much data are they dealing with? KBs, MBs, GBs?
                                  They said if just around 200 invoices. Compared to others I see in metalink that logs issue whiich has 10,000 PO's invioces.
                                  3. Can you increase your SGA to handle more appropriately the volume required by the queries?
                                  Is it already 1.7 which is the limit of 32 bit Oracle. which we have.
                                  4. Also note that the queries in your good and bay days are different so the load pattern is not comparable.
                                  It maybe that that queries has finished fast and they have done other programs being caught in that time range. Do I need generate statspack starting 8am to 5pm? so that everything is captured?
                                  5. What did you base the 1800 to 3600 decision on? You need to look at how long your longest running query is, in seconds, and set the undo to at least that value. How long is the query which runs running for before you get the ORA-01555 error?
                                  The logical thing is just to test it by increasing, but it seems does not matter as "sbt" has mentioned.
                                  6. Your db_cache is tiny, 288MB, how much data are you selecting? If more than 288MB, can you increase your cache?

                                  How do I increase my cache size?

                                  Edited by: yxes2013 on 8.1.2013 15:45
                                  • 14. Re: Performance Issue
                                    yxes2013
                                    Was it raining on Monday?
                                    No rains here only sometime dizzles. Or is this a joke?
                                    1 2 3 4 Previous Next