12 Replies Latest reply: Apr 17, 2012 1:27 AM by User396406 -Oracle RSS

    Statspack repot interpretation

    User396406 -Oracle
      Dear all,

      I have a customer who is using 9i and I am studying the performance issue from the statspack report. There are several points I would like to ask for your help:

      1. There are two events (CPU time; db file sequential read) usually shown in the "Top 5 Timed Events" in the reports (as below). Can I conclude that there is the CPU bound first then come with I/O bound?

      Top 5 Timed Events
      ~~~~~~~~~~~~~~~~~~ % Total
      Event Waits Time (s) Ela Time
      -------------------------------------------- ------------ ----------- --------
      CPU time 17,695 57.70
      db file sequential read 2,683,595 6,802 22.18
      db file scattered read 296,996 2,515 8.20
      log file sync 436,937 890 2.90
      log file parallel write 438,634 840 2.74

      2. When I study the Top SQL statements, it is found that the Elapsed time is much larger than CPU time (e.g. Elapsed time = 1500s ; CPU time = 60s). Does it mean that it implies I/O wait which cause long elapsed time? If not, how can I dig out the root cause?

      3. I usually find that there is either "Index range scan" or "Index full scan" in the big SQL queries. Are these big queries benefit if use Exadata (e.g. smart scan technology)?

      Thanks for your help.
      M.T.
        • 1. Re: Statspack repot interpretation
          Nikolay Savvinov
          Hi,

          1. no, you can't conclude that your database is CPU or I/O bound based on just that. The information you provided is not sufficient for that: you need NUM_CPUS and elapsed time of the report. I've made a detailed post on CPU usage analysis in AWR reports, I think you will find it helpful: http://savvinov.com/2012/04/06/awr-reports-interpreting-cpu-usage/

          2. once again, not enough information. what is the sum% for the top SQL by CPU or elapsed time? If it's significantly less than 100%, that may be an indication that bind variables are not used on the system, so every time you have a new set of inputs, you have a new sql_id. If that's the case, top SQL section is essentially useless.

          3. I don't think you can just "use Exadata technology" -- you'll have to purchase an Exadata server and migrate your database there. Before considering this expensive options, you should try performance tuning first.

          Best regards,
          Nikolay
          • 2. Re: Statspack repot interpretation
            Franck Pachot
            Hi,

            1. No. But you can say that is you want to decrease significantly the response time, you should address the top CPU consumers. See SQL ordered by CPU or logical read. But you already did it as you have found the index range and full scan

            2. Elapsed time includes idle time as well. It is used to know the database load: when you calculate (CPU time + wait event time) / Elapsed time it gives the average number of active sessions.

            3. smart scan will not help with that. You don't have an i/o throughput issue.
            But if you have a lot of index range scan and full scan, you should be able to decrease the CPU usage and sequential reads if you can avoid or improve the table lookup that are behind (table acess by rowid in the execution plan). The ideas are:
            - select only the required columns (no 'select *')
            - add those columns at the end of the index in order to avoid table access
            - try to improve clustering factor (reorg sorting physically the rows, IOT, ...)

            Regards,
            Franck.
            • 3. Re: Statspack repot interpretation
              baskar.l
              Hi,

              Its common to see sequential/scattered read in top 5 wait events. Are you trying to bring down the average wait(ms) of these events? Check your sga advisory too.

              Thanks,
              Baskar.l
              • 4. Re: Statspack repot interpretation
                User396406 -Oracle
                Dear Nikolay, Franck and experts,

                I cannot generate the AWR since this is a 9i database. I only can get the statspack report in this case.
                Double check the long-running SQL statements and it's found that the total elapsed time is far more longer than the total CPU time (e.g. 1000s vs 80s). Furthermore, I found the hard parse rate is quite high (not using bind variable we guess). Would it be one of the root causes of wait time event?
                In fact, we are planning to migrate the current system to Exadata but we would like to investigate the performance gain if we make this upgrade.

                As far as I know that Exadata can help a lot on I/O issue instead of CPU issue, we would like to ensure if Exadata can address the "right pain".

                Many thanks for your help.
                M.T.

                Here is part of the report for your reference:
                STATSPACK report for
                DB Name         DB Id    Instance     Inst Num Release     Cluster Host
                ------------ ----------- ------------ -------- ----------- ------- ------------
                XXX           4199214960 XXX                 1 9.2.0.8.0   NO      srv02
                
                              Snap Id     Snap Time      Sessions Curs/Sess Comment
                            --------- ------------------ -------- --------- -------------------
                Begin Snap:      2221 29-3? -12 06:15:01      87       7.0
                  End Snap:      2228 29-3? -12 08:00:02     124      12.9
                   Elapsed:              105.02 (mins)
                
                Cache Sizes (end)
                ~~~~~~~~~~~~~~~~~
                               Buffer Cache:     2,048M      Std Block Size:         32K
                           Shared Pool Size:     6,144M          Log Buffer:      1,536K
                
                Load Profile
                ~~~~~~~~~~~~                            Per Second       Per Transaction
                                                   ---------------       ---------------
                                  Redo size:            939,465.75              7,479.54
                              Logical reads:             78,270.14                623.15
                              Block changes:              4,029.28                 32.08
                             Physical reads:              1,538.06                 12.25
                            Physical writes:                136.75                  1.09
                                 User calls:             11,274.33                 89.76
                                     Parses:              4,131.71                 32.89
                                Hard parses:              1,014.76                  8.08
                                      Sorts:                 81.98                  0.65
                                     Logons:                  0.42                  0.00
                                   Executes:              4,616.99                 36.76
                               Transactions:                125.60
                
                  % Blocks changed per Read:    5.15    Recursive Call %:      4.98
                 Rollback per transaction %:    0.01       Rows per Sort:    834.71
                
                Instance Efficiency Percentages (Target 100%)
                ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                            Buffer Nowait %:  100.00       Redo NoWait %:    100.00
                            Buffer  Hit   %:   98.76    In-memory Sort %:     99.99
                            Library Hit   %:   86.15        Soft Parse %:     75.44
                         Execute to Parse %:   10.51         Latch Hit %:    104.78
                Parse CPU to Parse Elapsd %:   46.82     % Non-Parse CPU:     43.30
                
                 Shared Pool Statistics        Begin   End
                                               ------  ------
                             Memory Usage %:   93.61   94.02
                    % SQL with executions>1:   56.24   43.61
                  % Memory for SQL w/exec>1:   44.36   38.42
                
                Top 5 Timed Events
                ~~~~~~~~~~~~~~~~~~                                                     % Total
                Event                                               Waits    Time (s) Ela Time
                -------------------------------------------- ------------ ----------- --------
                CPU time                                                       36,501    46.28
                db file sequential read                         3,547,961      18,115    22.97
                latch free                                     14,075,780      13,671    17.33
                log file sync                                     793,985       2,820     3.58
                db file scattered read                            181,766       2,782     3.53
                          -------------------------------------------------------------
                Wait Events for DB: XXX  Instance: XXX  Snaps: 2221 -2228
                -> 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         3,547,961          0     18,115      5      4.5
                latch free                     14,075,780     32,003     13,671      1     17.8
                log file sync                     793,985          9      2,820      4      1.0
                db file scattered read            181,766          0      2,782     15      0.2
                log file parallel write           760,565          0      1,862      2      1.0
                SQL*Net more data to client    39,796,526          0      1,625      0     50.3
                log buffer space                   10,992          9        566     51      0.0
                wait list latch free               19,679          0        400     20      0.0
                log file sequential read            7,042          0        359     51      0.0
                buffer busy waits                   8,119          0         55      7      0.0
                process startup                     1,263          0         55     43      0.0
                db file parallel read                 828          0         16     19      0.0
                enqueue                                80          0         10    125      0.0
                control file parallel write         2,507          0          7      3      0.0
                direct path read (lob)          3,236,838          0          4      0      4.1
                LGWR wait for redo copy             9,622         10          3      0      0.0
                log file switch completion             70          0          3     42      0.0
                control file sequential read      120,614          0          3      0      0.2
                SQL*Net break/reset to clien       12,342          0          1      0      0.0
                local write wait                       10          0          1     80      0.0
                library cache pin                      31          0          0     10      0.0
                library cache lock                      3          0          0     48      0.0
                direct path read                   41,470          0          0      0      0.1
                log file single write                  28          0          0      3      0.0
                direct path write                   3,386          0          0      0      0.0
                async disk IO                       1,750          0          0      0      0.0
                direct path write (lob)               167          0          0      0      0.0
                buffer deadlock                         1          1          0      0      0.0
                SQL*Net message from client    70,366,763          0    148,518      2     88.9
                jobq slave wait                    29,280     29,082     86,016   2938      0.0
                virtual circuit status                210        210      6,116  29124      0.0
                wakeup time manager                   203        203      5,926  29190      0.0
                SQL*Net message to client      70,366,954          0         33      0     88.9
                SQL*Net more data from clien       16,177          0          1      0      0.0
                          -------------------------------------------------------------
                Background Wait Events for DB: XXX  Instance: XXX  Snaps: 2221 -2228
                -> 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           760,561          0      1,862      2      1.0
                log file sequential read            7,042          0        359     51      0.0
                log buffer space                      839          1         21     25      0.0
                control file parallel write         2,507          0          7      3      0.0
                LGWR wait for redo copy             9,622         10          3      0      0.0
                latch free                          2,194         34          2      1      0.0
                db file sequential read               344          0          2      5      0.0
                control file sequential read        3,234          0          0      0      0.0
                log file single write                  28          0          0      3      0.0
                buffer busy waits                       3          0          0     11      0.0
                db file scattered read                 17          0          0      1      0.0
                rdbms ipc reply                        72          0          0      0      0.0
                direct path read                    9,336          0          0      0      0.0
                async disk IO                       1,750          0          0      0      0.0
                direct path write                   2,042          0          0      0      0.0
                rdbms ipc message               2,232,580      4,930     37,812     17      2.8
                pmon timer                          2,171      2,167      6,146   2831      0.0
                smon timer                             94          2      6,040  64250      0.0
                          -------------------------------------------------------------
                SQL ordered by Gets for DB: XXX  Instance: XXX  Snaps: 2221 -2228
                -> 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
                   
                   Buffer Pool Advisory for DB: LP1  Instance: LP1  End Snap: 2228
                -> Only rows with estimated physical reads >0 are displayed
                -> ordered by Block Size, Buffers For Estimate (default block size first)
                
                        Size for  Size      Buffers for  Est Physical          Estimated
                P   Estimate (M) Factr         Estimate   Read Factor     Physical Reads
                --- ------------ ----- ---------------- ------------- ------------------
                D            208    .1            6,604          2.83      6,378,112,238
                D            416    .2           13,208          1.93      4,342,866,205
                D            624    .3           19,812          1.62      3,640,273,665
                D            832    .4           26,416          1.44      3,240,092,326
                D          1,040    .5           33,020          1.31      2,954,994,072
                D          1,248    .6           39,624          1.22      2,742,984,290
                D          1,456    .7           46,228          1.15      2,578,034,468
                D          1,664    .8           52,832          1.09      2,443,373,792
                D          1,872    .9           59,436          1.04      2,331,217,161
                D          2,048   1.0           65,024          1.00      2,250,083,589
                D          2,080   1.0           66,040          0.99      2,236,664,227
                D          2,288   1.1           72,644          0.96      2,155,416,041
                D          2,496   1.2           79,248          0.93      2,084,062,812
                D          2,704   1.3           85,852          0.90      2,022,719,526
                D          2,912   1.4           92,456          0.88      1,969,024,200
                D          3,120   1.5           99,060          0.85      1,921,525,625
                D          3,328   1.6          105,664          0.83      1,878,684,408
                D          3,536   1.7          112,268          0.82      1,838,867,003
                D          3,744   1.8          118,872          0.80      1,802,366,744
                D          3,952   1.9          125,476          0.79      1,769,514,453
                D          4,160   2.0          132,080          0.77      1,739,527,547
                          -------------------------------------------------------------
                Shared Pool Advisory for DB: LP1  Instance: LP1  End Snap: 2228
                -> Note there is often a 1:Many correlation between a single logical object
                   in the Library Cache, and the physical number of memory objects associated
                   with it.  Therefore comparing the number of Lib Cache objects (e.g. in
                   v$librarycache), with the number of Lib Cache Memory Objects is invalid
                
                                                                          Estd
                Shared Pool    SP       Estd         Estd     Estd Lib LC Time
                   Size for  Size  Lib Cache    Lib Cache   Cache Time   Saved  Estd Lib Cache
                  Estim (M) Factr   Size (M)      Mem Obj    Saved (s)   Factr    Mem Obj Hits
                ----------- ----- ---------- ------------ ------------ ------- ---------------
                      3,648    .6      3,159      155,827   21,111,272     1.0   3,852,304,826
                      4,272    .7      3,777      207,077   21,136,378     1.0   3,857,271,509
                      4,896    .8      4,399      258,583   21,156,197     1.0   3,861,231,174
                      5,520    .9      5,021      324,236   21,174,386     1.0   3,865,018,959
                      6,144   1.0      5,641      382,883   21,191,536     1.0   3,869,209,460
                      6,768   1.1      6,262      443,397   21,207,442     1.0   3,873,169,990
                      7,392   1.2      6,884      495,777   21,221,756     1.0   3,876,918,334
                      8,016   1.3      7,504      542,182   21,235,558     1.0   3,880,783,872
                      8,640   1.4      8,131      612,514   21,248,568     1.0   3,884,378,295
                      9,264   1.5      8,745      669,742   21,267,628     1.0   3,889,347,478
                      9,888   1.6      9,367      720,911   21,284,661     1.0   3,893,383,366
                     10,512   1.7      9,990      783,636   21,301,199     1.0   3,896,844,168
                     11,136   1.8     10,613      831,251   21,328,444     1.0   3,902,917,583
                     11,760   1.9     11,241      911,015   21,354,677     1.0   3,908,578,239
                     12,384   2.0     11,769      989,458   21,364,410     1.0   3,910,718,760
                          -------------------------------------------------------------
                SGA Memory Summary for DB: LP1  Instance: LP1  Snaps: 2221 -2228
                
                SGA regions                       Size in Bytes
                ------------------------------ ----------------
                Database Buffers                  2,147,483,648
                Fixed Size                              739,728
                Redo Buffers                          1,847,296
                Variable Size                     8,589,934,592
                                               ----------------
                sum                              10,740,005,264
                
                PGA Memory Advisory for DB: LP1  Instance: LP1  End Snap: 2228
                -> When using Auto Memory Mgmt, minimally choose a pga_aggregate_target value
                   where Estd PGA Overalloc Count is 0
                
                                                       Estd Extra    Estd PGA   Estd PGA
                PGA Target    Size           W/A MB   W/A MB Read/      Cache  Overalloc
                  Est (MB)   Factr        Processed Written to Disk     Hit %      Count
                ---------- ------- ---------------- ---------------- -------- ----------
                       384     0.1     15,537,685.0      5,537,057.3     74.0          2
                       768     0.3     15,537,685.0      5,141,850.4     75.0          0
                     1,536     0.5     15,537,685.0      3,996,029.6     80.0          0
                     2,304     0.8     15,537,685.0      2,993,976.3     84.0          0
                     3,072     1.0     15,537,685.0      2,411,515.4     87.0          0
                     3,686     1.2     15,537,685.0      1,472,254.8     91.0          0
                     4,301     1.4     15,537,685.0      1,472,254.8     91.0          0
                     4,915     1.6     15,537,685.0      1,472,254.8     91.0          0
                     5,530     1.8     15,537,685.0      1,472,254.8     91.0          0
                     6,144     2.0     15,537,685.0      1,472,254.8     91.0          0
                     9,216     3.0     15,537,685.0      1,472,254.8     91.0          0
                    12,288     4.0     15,537,685.0      1,472,254.8     91.0          0
                    18,432     6.0     15,537,685.0      1,472,254.8     91.0          0
                    24,576     8.0     15,537,685.0      1,472,254.8     91.0          0
                          -------------------------------------------------------------
                Edited by: 903714 on Apr 17, 2012 11:52 AM
                • 5. Re: Statspack repot interpretation
                  Nikolay Savvinov
                  Hi,

                  1) please use code tags
                  2) your biggest problem is this:
                  ...
                  per s per transaction
                  Hard parses: *1,014.76* 8.08
                  ...
                  ...

                  You're hard-parsing every 4th statement (probably because you're not using bind variables). That's responsible for high CPU usage and for high latch free waits. Fix that (use binds or set CURSOR_SHARING=FORCE or at least to SIMILAR), and that'll make all the differences in the world.

                  Best regards,
                  Nikolay
                  • 6. Re: Statspack repot interpretation
                    User396406 -Oracle
                    Dear Nikolay and experts,

                    Thanks for your information and it is very useful.
                    My finally question, how could I determine if there is any I/O issue/bottleneck from the report?

                    Thanks and Regards,
                    M.T.
                    • 7. Re: Statspack repot interpretation
                      Nikolay Savvinov
                      Hi,

                      I/O-related wait events belong to "User I/O" wait class (plus, most of them start with "db file..."), which make them quite easy to recognize. Just look for such events and see if they are responsible for a large percentage of DB time.

                      Keep in mind that even if they are, this doesn't necessarily mean a problem: all databases have to wait on something (if they're running). All it means that you'll get the biggest system-wide effect by reducing I/O-related waits (by tuning buffer cache, resolving OS-level I/O contention, buying faster disks etc.).

                      But these are just a few basic points. I/O tuning and interpreting AWR reports are huge topics, you can write volumes on that. I have a few posts in my blogs about interpreting AWR which you may find useful (I haven't gotten to the I/O part, but I'm planning to do so soon): savvinov.com/category/awr/

                      If you really want to dig deep into the subject, I recommend a great series of articles by J. Lewis, who's probably the best expert in the world on the subject: http://jonathanlewis.wordpress.com/statspack-examples/

                      Best regards,
                      Nikolay
                      • 8. Re: Statspack repot interpretation
                        Charles Hooper
                        903714 wrote:
                        Dear Nikolay and experts,

                        Thanks for your information and it is very useful.
                        My finally question, how could I determine if there is any I/O issue/bottleneck from the report?

                        Thanks and Regards,
                        M.T.
                        M.T.,

                        Nikolay has made several very good suggestions.

                        Did you post the full Statspack report? Typically, you should make the Statspack duration as short as possible (10 minutes for instance) to limit the effects of the averages being watered down due to short-term problems appearing in long duration snapshots. The exception, of course, is if the problem period really was 105 minutes long. The following is the formatted version of the Statspack section that you posted, with a couple of notes embedded:
                        STATSPACK report for
                        DB Name         DB Id    Instance     Inst Num Release     Cluster Host
                        ------------ ----------- ------------ -------- ----------- ------- ------------
                        XXX           4199214960 XXX                 1 9.2.0.8.0   NO      srv02
                         
                                      Snap Id     Snap Time      Sessions Curs/Sess Comment
                                    --------- ------------------ -------- --------- -------------------
                        Begin Snap:      2221 29-3? -12 06:15:01      87       7.0
                          End Snap:      2228 29-3? -12 08:00:02     124      12.9
                           Elapsed:              105.02 (mins)
                         
                        Cache Sizes (end)
                        ~~~~~~~~~~~~~~~~~
                                       Buffer Cache:     2,048M      Std Block Size:         32K
                                   Shared Pool Size:     6,144M          Log Buffer:      1,536K
                         
                        Load Profile
                        ~~~~~~~~~~~~                            Per Second       Per Transaction
                                                           ---------------       ---------------
                                          Redo size:            939,465.75              7,479.54
                                      Logical reads:             78,270.14                623.15
                                      Block changes:              4,029.28                 32.08
                                     Physical reads:              1,538.06                 12.25
                                    Physical writes:                136.75                  1.09
                                         User calls:             11,274.33                 89.76
                                             Parses:              4,131.71                 32.89
                                        Hard parses:              1,014.76                  8.08
                                              Sorts:                 81.98                  0.65
                                             Logons:                  0.42                  0.00
                                           Executes:              4,616.99                 36.76
                                       Transactions:                125.60
                         
                          % Blocks changed per Read:    5.15    Recursive Call %:      4.98
                         Rollback per transaction %:    0.01       Rows per Sort:    834.71
                         
                        Instance Efficiency Percentages (Target 100%)
                        ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                    Buffer Nowait %:  100.00       Redo NoWait %:    100.00
                                    Buffer  Hit   %:   98.76    In-memory Sort %:     99.99
                                    Library Hit   %:   86.15        Soft Parse %:     75.44
                                 Execute to Parse %:   10.51         Latch Hit %:    104.78
                        Parse CPU to Parse Elapsd %:   46.82     % Non-Parse CPU:     43.30
                         
                         Shared Pool Statistics        Begin   End
                                                       ------  ------
                                     Memory Usage %:   93.61   94.02
                            % SQL with executions>1:   56.24   43.61
                          % Memory for SQL w/exec>1:   44.36   38.42
                         
                        Top 5 Timed Events
                        ~~~~~~~~~~~~~~~~~~                                                     % Total
                        Event                                               Waits    Time (s) Ela Time
                        -------------------------------------------- ------------ ----------- --------
                        CPU time                                                       36,501    46.28    - 6301.2 elapsed seconds = 5.79 CPUs at 100% utilization, 96.5% util for 6 CPUs
                        db file sequential read                         3,547,961      18,115    22.97
                        latch free                                     14,075,780      13,671    17.33    - Average of 2.17 sessions waiting per second
                        log file sync                                     793,985       2,820     3.58
                        db file scattered read                            181,766       2,782     3.53
                                  -------------------------------------------------------------
                        Wait Events for DB: XXX  Instance: XXX  Snaps: 2221 -2228
                        -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         3,547,961          0     18,115      5      4.5
                        latch free                     14,075,780     32,003     13,671      1     17.8   - 32,000 timeouts
                        log file sync                     793,985          9      2,820      4      1.0   - nearly 1,000 seconds longer than log file parallel write
                                                                                                              with roughly the same number of waits, 126 commits/rollbacks per second
                        db file scattered read            181,766          0      2,782     15      0.2
                        log file parallel write           760,565          0      1,862      2      1.0
                        SQL*Net more data to client    39,796,526          0      1,625      0     50.3
                        log buffer space                   10,992          9        566     51      0.0
                        wait list latch free               19,679          0        400     20      0.0
                        log file sequential read            7,042          0        359     51      0.0
                        buffer busy waits                   8,119          0         55      7      0.0
                        process startup                     1,263          0         55     43      0.0
                        db file parallel read                 828          0         16     19      0.0
                        enqueue                                80          0         10    125      0.0
                        control file parallel write         2,507          0          7      3      0.0
                        direct path read (lob)          3,236,838          0          4      0      4.1
                        LGWR wait for redo copy             9,622         10          3      0      0.0
                        log file switch completion             70          0          3     42      0.0
                        control file sequential read      120,614          0          3      0      0.2
                        SQL*Net break/reset to clien       12,342          0          1      0      0.0
                        local write wait                       10          0          1     80      0.0
                        library cache pin                      31          0          0     10      0.0
                        library cache lock                      3          0          0     48      0.0
                        direct path read                   41,470          0          0      0      0.1
                        log file single write                  28          0          0      3      0.0
                        direct path write                   3,386          0          0      0      0.0
                        async disk IO                       1,750          0          0      0      0.0
                        direct path write (lob)               167          0          0      0      0.0
                        buffer deadlock                         1          1          0      0      0.0
                        SQL*Net message from client    70,366,763          0    148,518      2     88.9
                        jobq slave wait                    29,280     29,082     86,016   2938      0.0
                        virtual circuit status                210        210      6,116  29124      0.0
                        wakeup time manager                   203        203      5,926  29190      0.0
                        SQL*Net message to client      70,366,954          0         33      0     88.9
                        SQL*Net more data from clien       16,177          0          1      0      0.0
                                  -------------------------------------------------------------
                        Background Wait Events for DB: XXX  Instance: XXX  Snaps: 2221 -2228
                        -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           760,561          0      1,862      2      1.0
                        log file sequential read            7,042          0        359     51      0.0
                        log buffer space                      839          1         21     25      0.0
                        control file parallel write         2,507          0          7      3      0.0
                        LGWR wait for redo copy             9,622         10          3      0      0.0
                        latch free                          2,194         34          2      1      0.0
                        db file sequential read               344          0          2      5      0.0
                        control file sequential read        3,234          0          0      0      0.0
                        log file single write                  28          0          0      3      0.0
                        buffer busy waits                       3          0          0     11      0.0
                        db file scattered read                 17          0          0      1      0.0
                        rdbms ipc reply                        72          0          0      0      0.0
                        direct path read                    9,336          0          0      0      0.0
                        async disk IO                       1,750          0          0      0      0.0
                        direct path write                   2,042          0          0      0      0.0
                        rdbms ipc message               2,232,580      4,930     37,812     17      2.8
                        pmon timer                          2,171      2,167      6,146   2831      0.0
                        smon timer                             94          2      6,040  64250      0.0
                         
                                  -------------------------------------------------------------
                        SQL ordered by Gets for DB: XXX  Instance: XXX  Snaps: 2221 -2228
                        -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
                           
                           Buffer Pool Advisory for DB: LP1  Instance: LP1  End Snap: 2228
                        -Only rows with estimated physical reads >0 are displayed
                        -ordered by Block Size, Buffers For Estimate (default block size first)
                         
                                Size for  Size      Buffers for  Est Physical          Estimated
                        P   Estimate (M) Factr         Estimate   Read Factor     Physical Reads
                        --- ------------ ----- ---------------- ------------- ------------------
                        D            208    .1            6,604          2.83      6,378,112,238
                        D            416    .2           13,208          1.93      4,342,866,205
                        D            624    .3           19,812          1.62      3,640,273,665
                        D            832    .4           26,416          1.44      3,240,092,326
                        D          1,040    .5           33,020          1.31      2,954,994,072
                        D          1,248    .6           39,624          1.22      2,742,984,290
                        D          1,456    .7           46,228          1.15      2,578,034,468
                        D          1,664    .8           52,832          1.09      2,443,373,792
                        D          1,872    .9           59,436          1.04      2,331,217,161
                        D          2,048   1.0           65,024          1.00      2,250,083,589
                        D          2,080   1.0           66,040          0.99      2,236,664,227
                        D          2,288   1.1           72,644          0.96      2,155,416,041
                        D          2,496   1.2           79,248          0.93      2,084,062,812
                        D          2,704   1.3           85,852          0.90      2,022,719,526
                        D          2,912   1.4           92,456          0.88      1,969,024,200
                        D          3,120   1.5           99,060          0.85      1,921,525,625
                        D          3,328   1.6          105,664          0.83      1,878,684,408
                        D          3,536   1.7          112,268          0.82      1,838,867,003
                        D          3,744   1.8          118,872          0.80      1,802,366,744
                        D          3,952   1.9          125,476          0.79      1,769,514,453
                        D          4,160   2.0          132,080          0.77      1,739,527,547
                                  -------------------------------------------------------------
                        Shared Pool Advisory for DB: LP1  Instance: LP1  End Snap: 2228
                        -Note there is often a 1:Many correlation between a single logical object
                           in the Library Cache, and the physical number of memory objects associated
                           with it.  Therefore comparing the number of Lib Cache objects (e.g. in
                           v$librarycache), with the number of Lib Cache Memory Objects is invalid
                         
                                                                                   Estd
                        Shared Pool    SP       Estd         Estd     Estd Lib LC Time
                           Size for  Size  Lib Cache    Lib Cache   Cache Time   Saved  Estd Lib Cache
                          Estim (M) Factr   Size (M)      Mem Obj    Saved (s)   Factr    Mem Obj Hits
                        ----------- ----- ---------- ------------ ------------ ------- ---------------
                              3,648    .6      3,159      155,827   21,111,272     1.0   3,852,304,826
                              4,272    .7      3,777      207,077   21,136,378     1.0   3,857,271,509
                              4,896    .8      4,399      258,583   21,156,197     1.0   3,861,231,174
                              5,520    .9      5,021      324,236   21,174,386     1.0   3,865,018,959
                              6,144   1.0      5,641      382,883   21,191,536     1.0   3,869,209,460   - shared pool is 6,144M while buffer cache is 2048M
                              6,768   1.1      6,262      443,397   21,207,442     1.0   3,873,169,990
                              7,392   1.2      6,884      495,777   21,221,756     1.0   3,876,918,334
                              8,016   1.3      7,504      542,182   21,235,558     1.0   3,880,783,872
                              8,640   1.4      8,131      612,514   21,248,568     1.0   3,884,378,295
                              9,264   1.5      8,745      669,742   21,267,628     1.0   3,889,347,478
                              9,888   1.6      9,367      720,911   21,284,661     1.0   3,893,383,366
                             10,512   1.7      9,990      783,636   21,301,199     1.0   3,896,844,168
                             11,136   1.8     10,613      831,251   21,328,444     1.0   3,902,917,583
                             11,760   1.9     11,241      911,015   21,354,677     1.0   3,908,578,239
                             12,384   2.0     11,769      989,458   21,364,410     1.0   3,910,718,760
                                  -------------------------------------------------------------
                        SGA Memory Summary for DB: LP1  Instance: LP1  Snaps: 2221 -2228
                         
                        SGA regions                       Size in Bytes
                        ------------------------------ ----------------
                        Database Buffers                  2,147,483,648
                        Fixed Size                              739,728
                        Redo Buffers                          1,847,296
                        Variable Size                     8,589,934,592
                                                       ----------------
                        sum                              10,740,005,264
                         
                        PGA Memory Advisory for DB: LP1  Instance: LP1  End Snap: 2228
                        -When using Auto Memory Mgmt, minimally choose a pga_aggregate_target value
                           where Estd PGA Overalloc Count is 0
                         
                                                               Estd Extra    Estd PGA   Estd PGA
                        PGA Target    Size           W/A MB   W/A MB Read/      Cache  Overalloc
                          Est (MB)   Factr        Processed Written to Disk     Hit %      Count
                        ---------- ------- ---------------- ---------------- -------- ----------
                               384     0.1     15,537,685.0      5,537,057.3     74.0          2
                               768     0.3     15,537,685.0      5,141,850.4     75.0          0
                             1,536     0.5     15,537,685.0      3,996,029.6     80.0          0
                             2,304     0.8     15,537,685.0      2,993,976.3     84.0          0
                             3,072     1.0     15,537,685.0      2,411,515.4     87.0          0
                             3,686     1.2     15,537,685.0      1,472,254.8     91.0          0
                             4,301     1.4     15,537,685.0      1,472,254.8     91.0          0
                             4,915     1.6     15,537,685.0      1,472,254.8     91.0          0
                             5,530     1.8     15,537,685.0      1,472,254.8     91.0          0
                             6,144     2.0     15,537,685.0      1,472,254.8     91.0          0
                             9,216     3.0     15,537,685.0      1,472,254.8     91.0          0
                            12,288     4.0     15,537,685.0      1,472,254.8     91.0          0
                            18,432     6.0     15,537,685.0      1,472,254.8     91.0          0
                            24,576     8.0     15,537,685.0      1,472,254.8     91.0          0
                                  -------------------------------------------------------------
                        How many CPUs are in the server, and what else is running on the server? If the server has 6 CPUs (CPU cores), the database instance is CPU bound. If the server has 12 CPUs (CPU cores) and nothing else was running on the server, the database instance could still have been CPU bound, if the majority of the activity happened in just 50 of the 105 minutes (of course individual sessions could still be CPU bound if those sessions only used a single CPU at a time). One of the clues here is that at 2,820 seconds, the log file sync wait event is roughly 1,000 seconds longer than the log file parallel write wait event, but that time difference might have been a side effect of the 126 commits/rollbacks per second - even in a non-CPU constrained server, it could take a little while for the session to come back on the CPU (your system seems to require an average of 0.0012 seconds, which might be an operating system specific limitation).

                        Notice that the shared pool is roughly 3 times as large as the buffer cache. As Nikolay mentioned, roughly 25% of the parses are in fact hard parses. If those SQL statements are parsed and executed a single time, then it makes sense to significantly reduce the size of the shared pool so that the length of time that the shared pool related latches are held is minimized while scanning to determine if the SQL statement was previously parsed. Use caution with the suggestion to modify the CURSOR_CHARING parameter - check with MOS (My Oracle Support) for known bugs with your specific version of Oracle Database, and test with caution.

                        There were on average 2.17 sessions waiting on the latch free wait event for the duration of the Statspack snapshot - did the Statspack report include a breakdown of the various latch counters?

                        Were any SQL statements included in the report?

                        What parameters have been modified? Was the SPINCOUNT parameter adjusted?

                        Are you able to narrow the problem down to the activity of one or two sessions? If so, use a 10046 trace at level 8 or 12 for those sessions.

                        Charles Hooper
                        http://hoopercharles.wordpress.com/
                        IT Manager/Oracle DBA
                        K&M Machine-Fabricating, Inc.
                        • 9. Re: Statspack repot interpretation
                          User396406 -Oracle
                          Dear Nikolay, Charles and experts,

                          Many thanks for your help and analysis. It's really a fruitful sharing.
                          I try my best to get some long running SQL statements during the session:
                          ========================================================
                          select POLDATA.*, ROWID from POLDATA order by POLDATA_CONTRACT_N O
                          Total Elapsed Time: 239s
                          Total CPU Time: 141s
                          Execution Plan: Index full Scan

                          select POLDATA.*, ROWID from POLDATA where (POLDATA_CONTRACT_NO >= ' ') order by POLDATA_CONTRACT_NO
                          Total Elapsed Time: 427s
                          Total CPU Time: 120s
                          Execution Plan: Index Range Scan

                          select CONFUND.*, ROWID from CONFUND order by CONFUND_CONTRACT_N O, CONFUND_FUND_ID
                          Total Elapsed Time: 935s
                          Total CPU Time: 52s
                          Execution Plan: Index Full Scan

                          select b.object_name,a.session_id,c.serial#,decode(lmode,0,'None ',1,'Null',2,'Row-S (SS)',3,'Row-X (SX)',4,'Share (S)',5,'S/Row- X (SSX)',6,'Exclusive (X)',lmode),decode(l.request,0,'Blocker',' Waiting'),d.spid,to_char(c.logon_time,'dd mon yyyy hh24 mi ss'), c.last_call_et/60 from v$locked_object a, dba_objects b, v$sessi
                          Total Elapsed Time: 1450s
                          Total CPU Time: 1457s
                          Execution Plan: Fixed Table Full / Nested Loops / Union-All / Table Access By Index

                          ========================================================
                          As discussed with the apps team, there are huge number of SQL are generated by the application package which could be the root caused of hard-parses.

                          One thing I confuse is that there are several V$ table execution which takes pretty long. I still checking with apps/ops team at this stage and not sure the reason behind yet. Please feel free to comment.

                          On the other hand, I will check with MOS if the parameter CURSOR_SHARING could be modified.

                          Thanks again,
                          M.T.
                          • 10. Re: Statspack repot interpretation
                            User396406 -Oracle
                            Dear Nikolay and Charles,

                            I edit the statspack report (previous thread) more readable. This is the Latch breakdown in below.
                            Latch Sleep breakdown for DB: LP1  Instance: LP1  Snaps: 2221 -2228
                            -> ordered by misses desc
                            
                                                                  Get                            Spin &
                            Latch Name                       Requests      Misses      Sleeps Sleeps 1->4
                            -------------------------- -------------- ----------- ----------- ------------
                            hash table column usage la          1,369           7           6 1/6/0/0/0
                            archive process latch                 195           4           4 0/4/0/0/0
                                      -------------------------------------------------------------
                                        
                                        Latch Miss Sources for DB: LP1  Instance: LP1  Snaps: 2221 -2228
                            -> only latches with sleeps are shown
                            -> ordered by name, sleeps desc
                            
                                                                                 NoWait              Waiter
                            Latch Name               Where                       Misses     Sleeps   Sleeps
                            ------------------------ -------------------------- ------- ---------- --------
                            active checkpoint queue  kcbbacq: scan active check       0        168      168
                            archive process latch    kcrrpa                           0          4        0
                            cache buffers chains     kcbgtcr: kslbegin excl           0     14,865   15,159
                            cache buffers chains     kcbgtcr: fast path               0      7,559    6,147
                            cache buffers chains     kcbrls: kslbegin                 0      2,591    4,024
                            cache buffers chains     kcbchg: kslbegin: bufs not       0      1,163      759
                            cache buffers chains     kcbzgb: scan from tail. no       0        271        0
                            cache buffers chains     kcbgcur: kslbegin                0        141      174
                            cache buffers chains     kcbzwb                           0         72       44
                            cache buffers chains     kcbchg: kslbegin: call CR        0         58      289
                            cache buffers chains     kcbzib: multi-block read:        0         53        0
                            cache buffers chains     kcbget: pin buffer               0         44       79
                            cache buffers chains     kcbgtcr: kslbegin shared         0         34        3
                            cache buffers chains     kcbzib: finish free bufs         0         24      120
                            cache buffers chains     kcbgtcr                          0         17        0
                            cache buffers chains     kcbnlc                           0         16       83
                            cache buffers chains     kcbget: exchange rls             0          8        5
                            cache buffers chains     kcbbxsv                          0          7        8
                            cache buffers chains     kcbget: exchange                 0          5        4
                            cache buffers chains     kcbnew                           0          4        5
                            cache buffers chains     kcbbic2                          0          3        9
                            cache buffers chains     kcbclc                           0          1        1
                            cache buffers chains     kcbzib: exchange rls             0          1        1
                            cache buffers chains     kcbzsc                           0          1        1
                            cache buffers lru chain  kcbzgb: multiple sets nowa   2,301         63        0
                            cache buffers lru chain  kcbgtcr:CR Scan:KCBRSKIP        38          4        0
                            cache buffers lru chain  kcbzar: KSLNBEGIN              211          2        0
                            cache buffers lru chain  kcbzgb: posted for free bu       0          2       11
                            cache buffers lru chain  kcbbic2                         10          1       29
                            cache buffers lru chain  kcbzgm                          12          1        0
                            cache buffers lru chain  kcbbwlru                         1          1       10
                            checkpoint queue latch   kcbklbc: Link buffer into        0         45        0
                            checkpoint queue latch   kcbkllrba: compute lowest        0          2        1
                            checkpoint queue latch   kcbbwthc: thread checkpoin       0          1        1
                            checkpoint queue latch   kcbnlc: Link buffers into        0          1        0
                            child cursor hash table  kksfbc: new child                0     51,316   44,655
                            child cursor hash table  kksheqd: delete enqueue          0     30,276      159
                            child cursor hash table  kkslod: set parent info.         0     25,407      395
                            child cursor hash table  kkslod: mark kksb state          0     24,554    8,382
                            child cursor hash table  kksfbc: completing child         0      2,031   43,217
                            child cursor hash table  kkslod: set opcode               0      1,960   39,045
                            child cursor hash table  kkshmih: mov.to.hashtable        0        716      413
                            child cursor hash table  opiaba: set bbspbvnl             0         17        4
                            child cursor hash table  kksfbc: broken child             0         13        1
                            child cursor hash table  opiaba: bitset.                  0         12       18
                            child cursor hash table  kkssbt: allocate enqueue         0          5        4
                            child cursor hash table  kkshbsf: mark cursor state       0          1        8
                            child cursor hash table  opiaba: allocate kksbnump.       0          1        6
                            dml lock allocation      ktaiam                           0        110      103
                            dml lock allocation      ktaidm                           0         76       83
                            enqueue hash chains      ksqgtl3                          0      1,048      992
                            enqueue hash chains      ksqrcl                           0        670      726
                            enqueues                 ksqgel: create enqueue           0     13,642   13,072
                            Latch Miss Sources for DB: LP1  Instance: LP1  Snaps: 2221 -2228
                            -> only latches with sleeps are shown
                            -> ordered by name, sleeps desc
                            
                                                                                 NoWait              Waiter
                            Latch Name               Where                       Misses     Sleeps   Sleeps
                            ------------------------ -------------------------- ------- ---------- --------
                            enqueues                 ksqdel                           0     12,449   12,789
                            enqueues                 ksqies                           0        347      577
                            hash table column usage  KSXMMON_GETCELEM                 0          6        0
                            lgwr LWN SCN             kcs023                           0        301        0
                            library cache            kgllkdl: child: cleanup          0    742,835  143,648
                            library cache            kglobpn: child:                  0    314,580  183,263
                            library cache            kglpndl: child: before pro       0    304,346  616,841
                            library cache            kglupc: child                    0    145,748  169,594
                            library cache            kglhdgn: child:                  0    142,083  642,593
                            library cache            kglic                            0    123,136  204,758
                            library cache            kglhdgc: child:                  0    101,976   54,003
                            library cache            kglpin: child: heap proces       0     80,098   17,893
                            library cache            kgldti: 2child                   0     76,001   70,690
                            library cache            kglpin                           0     65,993   86,878
                            library cache            kglobld                          0     38,885  105,771
                            library cache            kglpnc: child                    0     32,176  232,010
                            library cache            kglpndl: child: after proc       0     22,564   12,261
                            library cache            kglati                           0      9,039    2,752
                            library cache            kglget: child: KGLDSBYD          0      3,756   48,765
                            library cache            kgldte: child 0                  0      3,228   11,840
                            library cache            kglpnp: child                    0      1,954    3,085
                            library cache            kgldtld: 2child                  0        104      147
                            library cache            kglini: child                    0         89       78
                            library cache            kglget: child: KGLDSBRD          0         67      416
                            library cache            kglrtl                           0         31       23
                            library cache            kglhfr: child                    0         14        8
                            library cache            kglnti                           0          1        0
                            library cache pin        kglpndl                          0      9,618    7,953
                            library cache pin        kglpnal: child: alloc spac       0      6,607    8,310
                            library cache pin        kglupc                           0      1,399    1,351
                            library cache pin        kglpnc: child                    0      1,202    1,883
                            library cache pin        kgldnp: child                    0        797      116
                            library cache pin        kglpnp: child                    0         38       48
                            library cache pin alloca kglpnal                          0     18,291   16,807
                            library cache pin alloca kgllkdl                          0     15,523   17,010
                            library cache pin alloca kglpndl                          0          3        0
                            loader state object free kcblgs                           0         73       68
                            loader state object free kcblfs                           0         24       29
                            messages                 ksarcv: after wait               0        442      402
                            messages                 ksaamb: after wakeup             0        234      165
                            messages                 ksarcv                           0        154      263
                            mostly latch-free SCN    kcslcu3                          0      1,264    1,636
                            mostly latch-free SCN    kcs024                           0         71        0
                            mostly latch-free SCN    kcsnew_scn_rba                   0          2        0
                            multiblock read objects  kcbzib: normal mbr free          0         29       12
                            multiblock read objects  kcbzib: mbr get                  0          8       25
                            post/wait queue          ksliwat:add:nowait               0         13        0
                            post/wait queue          ksliwat:remove                   0          1        0
                            redo allocation          kcrfwr                           0      1,605    1,373
                            redo allocation          kcrfwi: more space               0         82      237
                            redo allocation          kcrfwi: before write             0         68      146
                            redo allocation          kcrfwr: redo allocation 0        0          1        0
                            redo writing             kcrfwcr                          0        282      244
                            Latch Miss Sources for DB: LP1  Instance: LP1  Snaps: 2221 -2228
                            -> only latches with sleeps are shown
                            -> ordered by name, sleeps desc
                            
                                                                                 NoWait              Waiter
                            Latch Name               Where                       Misses     Sleeps   Sleeps
                            ------------------------ -------------------------- ------- ---------- --------
                            redo writing             kcrfwint: rba scn pair           0         16        0
                            redo writing             kcrfw_cal_target_rba             0          9        0
                            redo writing             kcrfwint: after write            0          8       72
                            redo writing             kcrfsr: rba scn pair             0          1        0
                            row cache enqueue latch  kqreqd                           0  1,041,468  668,141
                            row cache enqueue latch  kqreqa                           0    743,712 ########
                            row cache objects        kqrpfl: not dirty                0  3,084,373  411,984
                            row cache objects        kqrpre: find obj                 0  1,076,695 ########
                            row cache objects        kqrpre: init complete            0         28      184
                            row cache objects        kqrpup                           0          3        1
                            session allocation       ksuxds: not user session         0         48       62
                            session allocation       ksucri                           0         32       31
                            session allocation       ksuxds: KSUSFCLC not set         0          8        1
                            session allocation       ksufap: active sessions          0          4        0
                            session allocation       ksudlp                           0          1        0
                            session allocation       ksuprc                           0          1        0
                            session idle bit         ksupuc: set busy                 0      3,536    1,862
                            session idle bit         ksupuc: clear busy               0      1,495    3,151
                            session idle bit         ksuxds                           0         18       35
                            shared pool              kghalo                           0  3,008,188 ########
                            shared pool              kghupr1                          0    837,013 ########
                            shared pool              kghfrunp: alloc: wait            0    690,234  108,653
                            shared pool              kghfrunp: clatch: wait           0    512,394  534,581
                            shared pool              kghfrunp: clatch: nowait         0    420,654        0
                            shared pool              kghalp                           0    165,918   91,834
                            shared pool              kghfen: not perm alloc cla       0     31,790   57,529
                            shared pool              kghfre                           0        275      356
                            shared pool              kghfru                           0        134      198
                            simulator hash latch     kcbsacc: lookup dba              0          4        3
                            simulator hash latch     kcbs_lookup_setid: lookup        0          1        1
                            simulator lru latch      kcbs_simulate: simulate se       0         49       50
                            simulator lru latch      kcbs_lookup_setid                0          1        0
                            transaction allocation   ktcxbr                           0        205      205
                            undo global data         ktudba: KSLBEGIN                 0         74       78
                            undo global data         ktudnx:child                     0          8        2
                            undo global data         ktufrbs: child                   0          3        6
                            undo global data         ktusmstf: KSLBEGIN               0          1        0
                                      -------------------------------------------------------------
                            Edited by: 903714 on Apr 17, 2012 11:53 AM
                            • 11. Re: Statspack repot interpretation
                              Nikolay Savvinov
                              Hi Mike,

                              if I were you, I'd attack the problem from two angles:

                              1) I'd chose several SQL statements that cause the most trouble to the business (performance-wise) and look at them in detail (using dbms_xplan and/or event 10046 trace with waits enabled). Tune them (if possible) to bring an immediate relief to your users. I should stress here that I would pick those SQL statements based on their importance to the business, not on their ranking in statpack or any other reports
                              2) At the same time, I would start working on your hard parse problem. It's very serious because of two reasons:
                              -- it's hurting your performance, and it's hurting it a lot. I'm pretty sure that it's responsible for a large part of the CPU consumption by the database, as well as most (if not all) of the latching
                              -- just as importantly, it's hurting your ability to make a meaningful diagnosis, because it absence of cursor sharing, top-SQL sections of your statpack report are useless for identifying top resource consumers.

                              Best regards,
                              Nikolay
                              • 12. Re: Statspack repot interpretation
                                User396406 -Oracle
                                Dear Nikolay,

                                Thank you for your suggestion.
                                I would take your advice as the main direction of DB system tuning. I believe I got sufficient information and once again, thanks for your great help!

                                Cheers,
                                M.T.