RSS Feed

Method R Discussion Group

I have 2 databases that perform the same query using the same execution path, but one does 150X more lathes than the other.  The LIOs are the same.  What would cause such a difference?
========================================
Database A
Statistics Snapshot for onlinehld:jlocalheld

Type  Statistic Name                                    Value
----- ---------------------------------------- --------------
Latch cache buffers chains                          2,203,728
      library cache                                    38,542
      row cache objects                                  668
      shared pool                                      15,838

Stats buffer is pinned count                          49,669
      consistent gets                                  3,779
      db block changes                                      0
      db block gets                                        0
      execute count                                        4
      index fast full scans (full)                          0
      parse count (hard)                                    1
      parse count (total)                                  4
      physical reads                                        0
      physical writes                                      0
      redo size                                            0
      session logical reads                            3,779
      session pga memory                                    0
      session pga memory max                                0
      session uga memory                                    0
      session uga memory max                                0
      sorts (disk)                                          0
      sorts (memory)                                        0
      sorts (rows)                                          0
      table fetch by rowid                            26,668
      table scan blocks gotten                              0
      table scans (long tables)                            0
      table scans (short tables)                            0

Time  elapsed time (centiseconds)                        623


Database B
Statistics Snapshot for ONLINEHLD:JLOCALHELD


Type  Statistic Name                                    Value
----- ---------------------------------------- --------------
Latch cache buffers chains                            15,513
      library cache                                    2,188
      row cache objects                                    36
      shared pool                                        818

Stats buffer is pinned count                          49,680
      consistent gets                                  3,749
      db block changes                                      0
      db block gets                                        0
      execute count                                        4
      index fast full scans (full)                          0
      parse count (hard)                                    2
      parse count (total)                                  4
      physical reads                                        0
      physical writes                                      0
      redo size                                            0
      session logical reads                            3,749
      session pga memory                                    0
      session pga memory max                                0
      session uga memory                                    0
      session uga memory max                                0
      sorts (disk)                                          0
      sorts (memory)                                        0
      sorts (rows)                                          0
      table fetch by rowid                            26,668
      table scan blocks gotten                              0
      table scans (long tables)                            0
      table scans (short tables)                            0

Time  elapsed time (centiseconds)                        267

Remember that the latch acquisitions you're seeing represent the latch acquisitions for the entire instance at the time you executed your test.  So, what you're seeing are *not* just latches your query is acquiring, but latches being acquired by all sessions during that time.

This is what's cool (and what can be frustrating as well) about this kind of test comparison.  It shows you the effect that other queries that are executing at the time your query executes has on your query's performance.  In other words, you get to see that there is likely another poorly performing query out there eating up resources that you need, so your query ends up waiting until those resources are available.  Therefore, your query runs slower than if it were running by itself.

You can check the extended SQL trace file (@horatrace or @hsctrace) to look for the timed event lines labeled WAIT for your query for more info.  If you have Perl installed, you can execute @hprof to get a response-time profile from the trace data that will show you the detailed breakdown as well.

The bottom-line is that your query isn't the problem.  It's not running slow because it's doing excess work.  It's running slow because some other query is doing excess work and your query is being forced to wait on the resources it needs so it can execute.

So, are all the stats instance specific?  I was under the impression that the stats such as "consistent gets" and "pinned count" were session/query/do specific.

- Rick

Only the latch statistics are instance specific.  And that's because Oracle doesn't capture latch statistics at a session level.  The session stats are listed separately from the latch stats to help differentiate them.  The session stats like consistent gets, etc. are just for your test execution whereas the latch stats show all latch acquisitions during the time your test was executed.

The way I used to get actual session-level latch stats for a query was to use a debugger.  I'd start up SQL*Plus, find the backend Oracle PID, and attach to it with a debugger.  Within the debugger itself, I'd create an output file, set a breakpoint on kslgetl, and an on-break script which automatically continued execution.  After the debugging environment was ready, I'd then run the command in SQL*Plus.

On completion of SQL execution, I'd detach from the process and count the number of breaks in the output file using grep and wc -l.

Of course, there are only a few uses for this.  In your case, I'd go with Karen's statement; that it's likely something else running on the system is causing your problem.