Packaging Python With My Application

To try and keep a longer story as short as possible I needed to package up the Python run time environment to ship along with a Python based application I had written. And in this case the target platform was Windows, though the solution will also work for Linux or any other platform (however most Linux distributions will already have Python on them). I needed to ship Python itself with my application to guarantee that the application would be able to run (had everything it needed), and to avoid complications of requiring the customer to download and install Python themselves (potential issues over version compatibility).

Through a number of blog posts by other people about different "packaging" techniques (see References later) I came up with the following solution that works. This is not the only method of packaging a Python application, and indeed it is quite surprising how many different techniques there are. But this worked for me, and was what I wanted i.e. including Python itself with my Python based application. One of the neat benefits of this for me is that the whole Python run time I need is only 7.5 MB in size, and the main ZIP file of the run time environment is only 2.5 MB in size, which shows how compressable it all is.

Packaging Python with my application

First I create a directory (folder for Windows people) for my application, and put all my application's Python files in there.

Then I create a sub-directory in this to put Python itself into e.g. Python33_Win.

Into this I put the following files:

_socket.pyd
cx_Oracle.pyd
msvcr100.dll
pyexpat.pyd
python.exe
python33.dll
python33.zip
LICENSE.txt

Note that "cx_Oracle.pyd" is needed because my application makes a connection to an Oracle database to do its work. Also "msvcr100.dll" is technically a Microsoft DLL that is needed by programs written in C, which the Python interpreter is. Microsoft allows this DLL to be copied for the purpose of running such C based programs.

The "python33.zip" is something I created, and into which I put the rest of the necessary Python run time files. There are quite a lot of these, all taken from the directory where you installed Python on your own system:

• All the ".py" files in the top level Python folder
• The following folders including any sub-folders:-
  • collections
  • concurrent
  • ctypes
  • curses
  • dbm
  • distutils
  • email
  • encodings
  • html
  • http
  • importlib
  • logging
  • pydoc_data
  • site-packages
  • unittest
  • urllib
  • venv
  • wsgiref
  • xml

Then I wrote a wrapper script to run my application via the Python run time included. In this case it is a Windows batch script, and it exists in the folder above my application source code. My application needs two command line arguments provided e.g. user name and password.

MyAppName\Python33_Win\python MyAppName\myappname.py %1 %2

That's it, and it works.

How does it work.

Built into the Python interpreter i.e. into "python.exe", is clearly the functionality to dynamically load into itself various libraries it needs at run time. An example of these are the "*.pyd" files explicitly included in the Python directory. However, it also has the functionality to open up a ZIP file and look inside that for the libraries it needs. Thus we can take most of the Python run time environment files and put them into a PYTHON33.ZIP file, and Python will look in here to find the files it needs. Which makes packaging up Python pretty simple.

The exceptions to this are the "python33.dll" and Microsoft C DLL, and a few PYD files (which are Python Dynamic libraries, a bit like Windows DLL's). These will not be found in the ZIP file, as they seem to be needed before Python gets around to opening such a ZIP file.

Further Notes

• These files and directories are what I needed to make my application work. The particular set needed can be different for each Python based application, depending on what modules you import into your program at run time.
• I tried using the "modulefinder" module to report on which files were actually being referenced at run time when my application was being run. This helped reduce down the total number of files I needed to include in the ZIP file.
• The ZIP file is named "python33.zip" because I am using Python version 3.3, and its DLL is named "python33.dll" i.e. it looks for a ZIP file with a matching name of its version.

References

The main articles I found that helped me and pointed out this way of packaging up Python were:

• Distributing a Python Embedding Program which states that everything can be put into a ZIP file, except for some special files, and gives an example where those files are listed.
• How to Distribute Commercial Python Applications which describes the different packaging options available for Python based applications, and concludes that "For complex scenarios, my recommendation is to go with bundling CPython yourself and steer clear of the freezers".
  • It does not however tell you how to "bundle CPython yourself" - it just states that it is possible to do it.

RAC high block sharing causes high log sync times

Some time ago I dealt with a system that was experiencing high "log file sync" times, as well as other RAC related waits ("gc buffer busy" and "gc cr block busy"). Initially I assumed that the "log file sync" waits and the RAC Global Cache waits were independent of each other, but it turned out that they were interlinked. This post is mainly to make other people aware that on a RAC system there is a relationship between high inter-node block sharing traffic (Global Cache) and "log file sync", and that the log file sync events are a direct side effect of the high inter-node block sharing that is occurring. I'll also provide some evidence to support this in terms of AWR reports from the system.

The system was a 2 node RAC cluster running 10.2.0.4.0. An AWR report from an hour of peak day time activity showed:

Elapsed:   59.58 (mins)    
DB Time:  469.97 (mins)

So a database busy time of nearly 480 minutes in an elapsed period of nearly 60 minutes, meaning an average of almost 8 active sessions during that period. This is high for a system with only 4 CPUs. Theoretically there would only be 240 minutes of CPU capacity available on a 4 CPU node in a 60 minute period.

The top 5 wait events were:

Event                     Waits  Time(s)  Avg Wait(ms) % Total Call Time  Wait Class
CPU time                          8,450                              30.0  
log file sync            77,234   4,930         64                   17.5  Commit
gc buffer busy           45,532   4,902        108                   17.4  Cluster
db file sequential read 269,971   1,587          6                    5.6  User I/O
gc cr block busy         45,388   1,401         31                    5.0  Cluster

8,450 seconds is about 140 minutes. This is just over half of the 240 minutes of CPU capacity available on the 4 CPU node, indicating that waiting is excessive i.e. the total Database Time is made up of more waiting than actively executing SQL statements. And we can see that the other 4 top wait events add to over 12,800 seconds, which is far more than the CPU time - again more waiting than doing real work.

As I said I initially focussed on trying to tune the "log file sync" events, but this lead nowhere. However a blog post I read when Googling this combination (sorry I cannot seem to find the link now) stated that in fact the log file sync is a consequence of the "gc buffer busy" event, and that there are other clues in the RAC specific section of the AWR report. And indeed on looking in the "RAC Statistics" under "Global Cache and Enqueue Services - Workload Characteristics" I saw the following:

Avg global enqueue get time (ms):                       0.6
Avg global cache cr block receive time (ms):           11.2
Avg global cache current block receive time (ms):       7.2
Avg global cache cr block build time (ms):              0.0
Avg global cache cr block send time (ms):               0.2
Global cache log flushes for cr blocks served %:       10.8
Avg global cache cr block flush time (ms):             72.4
Avg global cache current block pin time (ms):           0.1
Avg global cache current block send time (ms):          0.2
Global cache log flushes for current blocks served %:   0.5
Avg global cache current block flush time (ms):       227.5

The stand out statistic is the last one - 227.5 milliseconds on average to flush a "global cache current block". This is way too high. I would expect an inter-node network message to be of the order of a few milliseconds, and anything involving disk writes to be of the order of tens of milliseconds. So hundreds of milliseconds is way too high.

Further digging around revealed that in some cases a Global Cache request for a block from another node may cause that node to flush its work so far to its redo log before the block is copied across to the other node i.e. a "gc buffer" request from one node may cause a "log file sync" to occur on the other node. And I found this confirmed in this Pythian Blog post on Tuning "log file sync" Event Waits

In a RAC cluster, this problem is magnified, since both CR- and CUR-mode buffers need the log flush to complete before these blocks can be transferred to another instance’s cache.

At this point I switched focus onto the causes of those Global Cache requests and the high inter-node traffic.

In the "SQL Statistics" section of the AWR report is "SQL Ordered by Cluster Wait Time", and I could see a set of SQL statements all acting on the same table and with very high Cluster Wait Times as a percentage of elapsed execution time (CWT%). The percentage cluster wait time was around 85% for all of these related SQL statements i.e. it was spending almost 6 times longer waiting than doing the actual work of the SQL statement.

All of these SQL statements acted on one table that was being both heavily inserted into, and selected from. This is kind of the classic "hot table" or "hot block" problem seen in some OLTP applications on RAC databases. This was further confirmed by the "Segments Statistics" section of the AWR report, in "Segments by Global Cache Buffer Busy". The only objects mentioned are the one table and some of the indexes on it.

In this case there were 2 suggestions I could make:

1. Make the primary key unique index a Reverse Key index, so that new records would not be inserted into the same last index leaf block.
   • The primary key on this table was a generated sequential number, so it will always be increasing in value, and inserted at the end of a normal index.
2. Create a new multi-column index on the table that would better satisfy most of the queries being run.
   • The current execution plan used a less selective index and had to also retrieve a number of data blocks from the table to further filter the data according to the constraints in the "WHERE" clause.

These 2 changes reduced both the number of data blocks being accessed in the table for each query execution, and reduced specific contention on the last block in the primary key index. The net effect was to reduce the total number of blocks being continually shared between the nodes in the Global Cache for these SQL statements.

Suffice it to say that performance improved significantly and the users were happy after these changes. The "Avg global cache current block flush time" came down to under 5 milliseconds, which is a significant reduction. The original high wait events all but disappeared, so that disk I/O became the top wait event, and the total Database Time went down significantly because it was no longer waiting so much and so was executing more efficiently.

The key lesson for me was that on a RAC database high inter-node global cache traffic can give rise to redo log buffer flushes and consequently high "log file sync" wait times. And this is primarily due to a high volume of blocks being continually shared between the nodes in the cluster. Rather than trying to directly address the log file sync event, you instead need to address the global cache buffer sharing and reduce the total number of blocks being shared somehow. In my case I was able to create a better index that enabled the execution to access fewer data blocks in total, reducing the global cache traffic volume and contention for hot blocks.

Oracle VM on VirtualBox

I needed to "play" with Oracle VM and learn how to use it for some upcoming work involving virtual machines. Oracle VM (not VirtualBox) is virtualization software that installs directly onto a system i.e. it installs onto "bare metal" and does not need a host operating system. The problem I had was that I had no "spare" unused system on which I could install Oracle VM. I really wanted to be able to install it within a host environment as a kind of test sandpit. Which lead me to thinking about VirtualBox - Oracle's other virtualization software. VirtualBox runs inside a host operating system and creates virtual machines in which you can then install other operating systems i.e. it provides virtual machines that each look like an x86 system. Which means that in principle I could use VirtualBox to create a virtual machine, in which I would them install Oracle VM.

And indeed this does work, but there are a couple of important gotchas to be aware of:

• I was using Oracle VM 3.2 which also needs a separate system for Oracle VM Manager to run on
  • So I created 2 virtual machines in VirtualBox
• The Oracle VM virtual machine should be quite large e.g. 8 GB of memory
  • As you will then want to create virtual machines within this
• The Oracle VM virtual machine will need additional disk storage which can be used for its virtual machines
  • I created the VirtualBox VM with a 5 GB disk for installing Oracle VM itself onto
  • And a second 100 GB virtual disk to use for Oracle VM virtual machines later on
• Oracle VM and Oracle VM Manager must be on the same network as each other for communication
  • I added a second network adaptor to each virtual machine on an Internal Network (vmnet)
• This second network adaptor must have Promiscuous Mode enabled i.e set to "Allow All"
  • The default of "Deny" will not allow Oracle VM to communicate successfully with Oracle VM Manager
• VirtualBox does not emulate the Intel VT-x virtualization instructions in its virtual machines
  • So within Oracle VM you can only do Paravirtualized Machines (PVM)
  • So I used Oracle Enterprise Linux has it has suitable paravirtualized drivers in it for use in a PVM
  • You cannot create a Hardware Virtualized Machine (HVM) as this requires the Intel VT-x in the CPU used
  • This is a limitation of VirtualBox, and nothing to do with the real CPU in your physical system on which your host operating system is running
• If you want a virtual machine running under Oracle VM to be able to network to the outside world you need to configure something else in the network somewhere. There are different options for doing this, depending on what you want and how much change you can do at your network level.
  • You could use the Bridged Adaptor type of network adaptor in VirtualBox, but this means that each virtual machine is visible on your public network and its IP address and hostname must not clash with any other existing system.
  • If you only want internet access for web browsing and downloading operating system updates then you can use the Oracle VM Manager system as an intermediate. It may seem complicated but it worked for me. There are 2 parts:
    • Configure and run some DNS (Domain Name System) software on the Oracle VM Manager system, to let it act as a DNS server to the Oracle VM virtual machines. I used "Dnsmasq" which is simple and straightforward, and can act as a bridge out to cascade out to another DNS server. On the Oracle VM virtual machine configure it to use your Oracle VM Manager system as its DNS server.
    • Configure the Oracle VM Manager to do NAT (Network Address Translation), which involves a few steps to configure "iptables" to do packet forwarding. Then configure the Oracle VM virtual machine to use the Oracle VM Manager as a network gateway (using "route").

The most important point is probably the one about the network adaptor setting in VirtualBox. This caused me no ends of problems as I could successfully install both Oracle VM and Oracle VM Manager on the VirtualBox virtual machines, and I could get Oracle VM Manager to discover and see the Oracle VM system. Which meant that the network between the two systems was definitely working. But whenever I tried to create a new virtual machine in Oracle VM and boot it, it always failed at the Oracle Enterprise Linux installation stage after entering a URL to install from. There is something special done at that point of the installation procedure that requires the network adaptors to be in promiscuous mode. After some digging I came across this "Promiscuous Mode" and tried its alternative setting, and it all worked then.

Basic Performance Analysis using AWR data

I've previously covered a number of queries that can be combined together to pull out key statistics from the Oracle AWR data for each snapshot it makes, which you could use to analyse the performance of a system. One example would be to use this to look at how the workload changes during the day, and to identify the period of peak activity. Another use would be to see if there were any periods experiencing significantly higher waits than at other times.

I'll now go through how you can use some of the AWR data to do an overall performance analysis of a system. But before we do that, we need to review some basics on performance tuning, just to clarify some things and avoid potential confusion.

Performance Tuning Basics

I'm of the same school of tuning as people like Cary Millsap and Jeff Holt and others - generally speaking you should be tuning specific performance problems as experienced by individual Oracle sessions, and not tuning the system as a whole. This is because any "improvements" you make to the system that do not benefit the slow sessions are completely wasted and pointless. For instance, the system may be experiencing slow disk I/O's, but it might be that the reported slow interactive response time by some users is due to very high CPU usage resulting from a poor execution plan for the particular SQL statement that session is executing. Making the disk I/O's happen quicker might "improve" things for the system as a whole, but it will have no impact at all on the CPU bound SQL statement that is the cause of slow response times on an end user's screen.

That said, there are times where system level tuning is appropriate or when you can only do system level tuning, and that is where AWR can help as it gathers system wide activity data. For session level tuning you need to look elsewhere - such as ASH (Active Session History) or using SQL Trace.

There are some big assumptions being made when we do system level tuning:

• All sessions are executing the same or similar SQL statements
  • So a system wide "average" view across all sessions is valid
• Any "poor performance" on the system impacts all sessions equally
  • So even one rogue SQL statement can slow down all other SQL statements being executed from other sessions
• The system is under a high enough load that performance problems are due to interactions between the SQL statements
  • It is assumed that poorly performing individual SQL statements would have been identified earlier under initial testing

Providing these assumptions or similar are true, then you can do system level tuning.

System Level Tuning Measurements

A computer system exists to do work, and its performance is really about how long it takes to to that work and which resources it uses while doing it. Performance is an issue when a task takes too long to complete.

We need to measure both sides of this – the input work requests, and the output usage of the system resources that results. We can only do performance tuning properly when we know both of these, as this lets us see the impact of any changes we make - does resource usage go down or not for the same input workload?

Measuring the input workload is best done at business or application level transactions. And this is best achieved by instrumenting the application software itself to record both the type of transaction it is performing and the elapsed time it takes when submitted. However, very few applications if any are instrumented this way.

This leaves a database level measurement as the only viable and consistently available way of recording the input workload, and in my view the best available measurement is the number of SQL statements executed per second. While this is very imperfect as a measure of the input workload, it is the nearest we are going to get to it, and all input application transactions result in SQL statements being executed. So it does correlate with input workload.

For a measurement of workload on the system - the output resulting from the execution of the SQL statements - the best measurement is probably Average Active Sessions. AAS is simply the Database Time ("DB Time" from System Time Model) divided by elapsed time for the period over which Database Time was measured. The Database Time value is a measurement of the amount of elapsed time sessions were active executing SQL statements, and includes both active execution time (running on a CPU) and waiting time (for disk I/O or any other wait event). AAS indicates how many sessions were active at the same time executing SQL statements i.e. the level of concurrency on your system.

AAS correlates with the number of CPU's on your system - if all SQL statements executed with no waiting at all they would only use up CPU resource and your transaction rate would be limited by the number of CPU's in the system. If AAS is less than the number of CPU's in your system then you are not reaching capacity. If AAS is close to or more than the number of CPU's then you have an overloaded system and waiting of some form or another is occurring.

To make real use of the AAS value we also want to know the percentage of time spent waiting during each period i.e. total wait time as a percentage of database active time (DB time again). The Percentage Wait (which I label Wait%) indicates the efficiency of the SQL statement execution - if this waiting was eliminated then that wait time would be removed from the elapsed time of each SQL statement executed. This is only relevant when AAS is high enough. When the level of concurrency is very low you can get various anomalies, and there will always be some waiting somewhere. Again remember the assumptions I stated earlier - the system must be under a high enough load to experience performance problems due to the combined workload itself.

That's it - 3 simple measurements should be enough to tell you whether your system is overloaded or not, and whether it is performing efficiently. These can be easily extracted from AWR (see later in this post), and can graphed in your favourite spreadsheet tool to spot trends and anomalies.

Using these measurements

If you have a system wide bottleneck / capacity limit then checking on the total system resource usage during a period of time will hopefully identify any such bottlenecks. As stated, if AAS is high enough (I would say more than half of the number of CPU's), and the Wait% is also high (say 50% or more), then you have poor performance and it can be improved.

At this point I would use the expanded version of the AWR query that I have built up over the previous posts to get all of the data out of AWR for each snapshot, and again into a spreadsheet or something else. Within this AWR data is a breakdown of the Oracle Wait Time by Wait Class, which tells you which "type" of wait was consuming most of the wait time. This can either primarily be Disk (I/O), Network, Cluster, Commit (Redo), or Concurrency (locking).

Knowing the wait class you can then query AWR for SQL statement execution and sum them over the wait class identified earlier, and sort by the wait class time summed. I showed how to do this in my previous post, summing the number of disk reads per SQL statement executed in each snapshot. This way you easily get to see the top SQL by that wait type, and see how much time they spent waiting relative to the total wait time.

Equally you could just do all SQL statements by their total wait time, to see those that experienced the worst waits whatever type of wait they were. Wait time for a SQL statement would be calculated as its Elapsed time minus the CPU time.

AWR System Performance Query

Here is a query that gives you just the 3 key measurements mentioned before for a system from the AWR data. It reports all the measurements for yesterday - modify the date range constraint to report on different periods.

set feedback off
set verify off
set linesize 1000
set trimout on
set trimspool on
--
col snap_time           format a15      heading 'SNAP TIME'
col user_calls_sec      format 9,990    heading 'UCALL/S'
col aas                 format 90.0     heading 'AAS'
col wait_pct            format 990.0    heading 'WAIT%'
--
with
snaps as 
(select snap_id
      , dbid
      , end_snap_time
      , snap_interval
      , extract (second from snap_interval) 
       + (extract (minute from snap_interval) 
          + (extract (hour from snap_interval)
             + (extract (day from snap_interval) * 24)
             ) * 60
          ) * 60 snap_duration
  from (select csnaps.snap_id
             , csnaps.dbid
             , min (csnaps.end_interval_time) end_snap_time
             , min (csnaps.end_interval_time) - min (csnaps.begin_interval_time) snap_interval
          from dba_hist_snapshot csnaps
         group by csnaps.snap_id, csnaps.dbid
       )
) -- snaps
, systimes as 
-- One row per Database Time Model with change in value between snapshots
(select systime.snap_id
      , systime.dbid
      , systime.stat_name
      , sum (systime.value - psystime.value) value
         from dba_hist_sys_time_model systime, dba_hist_sys_time_model psystime
        where systime.snap_id = psystime.snap_id + 1
          and systime.dbid = psystime.dbid
          and systime.instance_number = psystime.instance_number
          and systime.stat_id = psystime.stat_id
-- Assume if stat_id the same so is the stat_name
        group by systime.snap_id, systime.dbid, systime.stat_name
) -- systimes
, sysstats as 
-- One row per System Statistic with change in value between snapshots
(select sysstat.snap_id
      , sysstat.dbid
      , sysstat.stat_name
      , sum (sysstat.value - psysstat.value) value
         from dba_hist_sysstat sysstat, dba_hist_sysstat psysstat
        where sysstat.snap_id = psysstat.snap_id + 1
          and sysstat.dbid = psysstat.dbid
          and sysstat.instance_number = psysstat.instance_number
          and sysstat.stat_id = psysstat.stat_id
-- Assume if stat_id the same so is the stat_name
        group by sysstat.snap_id, sysstat.dbid, sysstat.stat_name
) -- sysstats
, syswaits as 
-- One row for total wait time, plus break down into major wait classes, and events
(select sysevent.snap_id
      , sysevent.dbid
      , sum (sysevent.time_waited_micro - psysevent.time_waited_micro) time_waited_micro
      , sum (sysevent.total_waits - psysevent.total_waits) wait_count
   from dba_hist_system_event sysevent, dba_hist_system_event psysevent
  where sysevent.snap_id = psysevent.snap_id + 1
    and sysevent.dbid = psysevent.dbid
    and sysevent.instance_number = psysevent.instance_number
    and sysevent.event_id = psysevent.event_id
    and sysevent.wait_class != 'Idle'  -- Ignore Idle wait events
  group by sysevent.snap_id
      , sysevent.dbid
) -- syswaits
select to_char (snaps.end_snap_time, 'DD/MM/YY HH24:MI') snap_time
     , (user_calls_st.value / snaps.snap_duration)              user_calls_sec
     , (dbtime.value / 1000000)       / snaps.snap_duration     aas
     , (100 * syswaits.time_waited_micro / dbtime.value)        wait_pct
  from snaps
     join (select * from systimes where stat_name = 'DB time') dbtime
       on snaps.snap_id = dbtime.snap_id and snaps.dbid = dbtime.dbid
     join syswaits
       on snaps.snap_id = syswaits.snap_id and snaps.dbid = syswaits.dbid
     join (select * from sysstats where stat_name = 'user calls') user_calls_st
       on snaps.snap_id = user_calls_st.snap_id and snaps.dbid = user_calls_st.dbid
 where snaps.end_snap_time between 
       (trunc (sysdate) - 1) and (trunc (sysdate))
 order by snaps.end_snap_time
/
--
set feedback on
set lines 80

AWR Reporting #6 - SQL Statements

This is the last of the main set of posts on this topic. As for the last post, I'll try and keep this brief and post the SQL involved.

Another data set we can look at is on SQL statements i.e. statistics collected by AWR on individual SQL statements, not overall totals. AWR snapshots SQL statements from V$SQLSTAT to DBA_HIST_SQLSTAT for per SQL statement statistics.

As before we could use the technique of subtracting the values from the previous snapshot from the values of the current snapshot to get the change in value between the snapshots. Unfortunately this runs into issues as not all SQL statements may be present in both snapshots, and SQL statements can be flushed out of the library cache in the SGA and then added back in again later so their statistics have been reset in-between.

Luckily Oracle has solved this problem for us and provided a set of DELTA columns for the most important statistics giving us just what we want. Also this avoids the need to join back to the previous snapshot to calculate the change between the snapshots - the DELTA columns are already the change in value from the previous snapshot.

The main query then to extract useful statistics per SQL statement per database per snapshot is:

select sqlstat.snap_id
     , sqlstat.dbid
     , sqlstat.sql_id
     , sum (sqlstat.elapsed_time_delta)  sql_time
     , sum (sqlstat.executions_delta) sql_execs
     , sum (sqlstat.disk_reads_delta) sql_reads
  from dba_hist_sqlstat sqlstat
 group by sqlstat.snap_id
     , sqlstat.dbid
     , sqlstat.sql_id

We cannot use this query directly in our current main AWR summary query as we are getting multiple data rows per snapshot - one per SQL statement captured by that snapshot. The obvious thing to do is to sum the values over all of the SQL statements executed in that snapshot to produce one set of values per snapshot. Unfortunately this doesn't really give us anything that useful - we already have data values from AWR for these statistics across the whole system (SQL execution time, number of SQL statements executed, and number of disk reads), and when added up across all the SQL statements it doesn't help us see if there are any anomalies within the SQL statement themselves.

A better use for this query is to run it separately within another query that instead groups by SQL_ID and sums over multiple snaphots e.g. all snapshots in one day. This is a useful way of seeing which particular SQL statements put a greater load on the system than other SQL statements. "Load" could be number of executions, CPU used, disk reads, or some other measurement.

For example, one system I was looking at recently was doing a lot of disk reads and I could see that there were a number of table scans occurring. So I wanted to identify the SQL statements causing these table scans i.e. the SQL statements with the highest disk reads. By summarising over a whole day I could ensure that I was looking at the worst offenders who were executed multiple times during the day, and not a bad query only executed once.

The following query reports SQL statements captured by AWR yesterday ("sysdate - 1" truncated to midnight) sorted by total number of disk reads. The "sql_reads > 100000" is a filter so that not all SQL statements are listed, only those with a significant number of disk reads - you can increase or decrease this threshold based on how active your system is. You may want to start higher at a million and then reduce it by a factor of 10 until you get enough SQL statements listed.

with 
snaps as 
(select csnaps.snap_id
      , csnaps.dbid
      , min (csnaps.end_interval_time) end_snap_time
      , min (csnaps.end_interval_time) - min (csnaps.begin_interval_time) snap_interval
   from dba_hist_snapshot csnaps
  group by csnaps.snap_id, csnaps.dbid
) -- snaps
, sqlstats as
(
[insert previous query here]
)
select sqlstats.sql_id
     , sum (sqlstats.sql_reads)  sql_reads
     , sum (sqlstats.sql_execs)  sql_execs
     , sum (sqlstats.sql_time) / 1000000 sql_time
  from snaps
     join sqlstats
       on snaps.snap_id = sqlstats.snap_id and snaps.dbid = sqlstats.dbid
 where snaps.end_snap_time between 
       (trunc (sysdate) - 1) and (trunc (sysdate))
   and sql_reads > 100000
 group by sqlstats.sql_id
 order by sql_reads desc
/

Note that the time values are in microseconds and so must be divided by one million to output them as seconds.

A further optimization to this query is to restrict it to the main working hours, say 8am to 6pm:

   and extract (hour from snaps.end_snap_time) between 8 and 17 -- 8:00 to 17:59

This avoids issues with any overnight batch jobs you may be running or the Oracle default job to update stale statistics on database objects (which does do a lot of disk reads).

When I used this I was able to identify about 4 SQL statements responsible for about 25% of the disk reads on the system, each having a relatively low execution count - under 100 each for millions of disk reads in total. Each was clearly doing full table scans, which was validated by checking the execution plans of each - there is an AWR report supplied with Oracle that reports this information for a SQL statement across a number of snapshots (awrsqrpt.sql).

Now that I knew the top contributors to disk reads on the system I was able to investigate each SQL statement individually and work out changes to improve their execution. This was a mixture of extra indexes, SQL rewrites and other database changes.

AWR Summary Reporting #5 - System Statistics

So far our AWR report query shows overall duration between two consecutive snapshots, database time (i.e. doing work), SQL execution time (may be lower), total wait time, wait time by class, and some common specific wait events. We know how busy the database was and how much time it spent waiting and on what. Now I want to add in some more data captured by the AWR on system activity. This series is dragging on a bit, so I'm going to try and keep this one shorert and just get it posted out.

AWR snapshots V$SYSSTAT into DBA_HIST_SYSSTAT. This contains individual system statistics with cumulative running totals for each. These are stored as Name / Value pairs in each table. Most statistics are just counts of event occurrences e.g. "physical reads", "physical writes", but some have been added that are time values. This lets you calculate average time per event when you have the corresponding event count as well. Beware that many of the "time" values are in odd units, such as hundredths of seconds (1/100 second), and will need to be adjusted if you want to report in standard units of time.

Statistics recorded include the following, which I've tried to group together into related sets. The details don't really matter on these, as the point of these AWR Summary Reports is to pull out as much as we can at once from a database for later analysis. Some of these statistics might only be relevant in specific scenarios - but by pulling them out at the same time as others, we already have them when they are needed.

• SQL statement execution - how many? Elapsed Time is in the Database Time Model data set
  • "execute count" - SQL statements executed, both user and recursive
  • "user calls" = Number of user calls such as login, parse, fetch, or execute.
  • "recursive calls"
• Transactions = units of work = groups of related SQL statements
  • "user commits" = commit count
  • "user rollbacks" = rollback count = abandoned transactions
• Average Redo Write Time - how long to write to the redo log?
  • "redo write time" = Total write time in 100'ths of seconds aka. 10's of milliseconds
  • "redo writes" = Number of redo writes that occurred
  • Also "redo blocks written" - Divide by "redo writes" to get average blocks per write
  • Can break redo writes down into those due to a "commit" and others (log buffer full enough to warrant a write)
  • Commit == Redo Synch -> "redo synch time" / "redo synch writes"
• Disk I/O - how many disk operations? Elapsed time is in the Wait Events data set
  • "physical reads" = Physical Reads
  • "physical writes" - Physical Writes
• Logical reads = "consistent gets" + "db block gets"
  • Note that "session logical reads" is defined as 'The sum of "db block gets" plus "consistent gets"', but might also include logical reads from 'process private memory'.

Because the statistics are stored as Name / Value pairs, each statistic is in a separate row rather than a separate column in the same row as other statistics. We can use a sub-query that retrieves each change in statistic value for each AWR snapshot, and then use this within the main query in an in-line view for each statistic with an appropriate alias name.

, sysstats as 
-- One row per System Statistic with change in value between snapshots
(select sysstat.snap_id
      , sysstat.dbid
      , sysstat.stat_name
      , sum (sysstat.value - psysstat.value) value
         from dba_hist_sysstat sysstat, dba_hist_sysstat psysstat
        where sysstat.snap_id = psysstat.snap_id + 1
          and sysstat.dbid = psysstat.dbid
          and sysstat.instance_number = psysstat.instance_number
          and sysstat.stat_id = psysstat.stat_id
-- Assume if stat_id the same so is the stat_name
        group by sysstat.snap_id, sysstat.dbid, sysstat.stat_name
) -- sysstats

select to_char (snaps.end_snap_time, 'DD/MM/YY HH24:MI') snap_time
...
     , execs.value executions
     , user_calls_st.value user_calls
     , user_commits_st.value user_commits
     , redo_write_st.value redo_writes
     , redo_time_st.value / 100 redo_write_time
     , phys_reads.value physical_reads
     , phys_writes.value physical_writes
     , table_scans_st.value table_scans
from
...
     join (select * from sysstats where stat_name = 'execute count') execs
       on snaps.snap_id = execs.snap_id and snaps.dbid    = execs.dbid
     join (select * from sysstats where stat_name = 'user calls') user_calls_st
       on snaps.snap_id = user_calls_st.snap_id and snaps.dbid = user_calls_st.dbid
     join (select * from sysstats where stat_name = 'user commits') user_commits_st
       on snaps.snap_id = user_commits_st.snap_id and snaps.dbid  = user_commits_st.dbid
     join (select * from sysstats where stat_name = 'redo writes') redo_write_st
       on snaps.snap_id = redo_write_st.snap_id and snaps.dbid  = redo_write_st.dbid
     join (select * from sysstats where stat_name = 'redo write time') redo_time_st
       on snaps.snap_id = redo_time_st.snap_id and snaps.dbid  = redo_time_st.dbid
     join (select * from sysstats where stat_name = 'physical reads') phys_reads
       on snaps.snap_id = phys_reads.snap_id and snaps.dbid    = phys_reads.dbid
     join (select * from sysstats where stat_name = 'physical writes') phys_writes
       on snaps.snap_id = phys_writes.snap_id and snaps.dbid  = phys_writes.dbid
     join (select * from sysstats where stat_name = 'table scans (long tables)') table_scans_st
       on snaps.snap_id = table_scans_st.snap_id and snaps.dbid  = table_scans_st.dbid
...

This means that we can now correlate overall system performance (Database Time and Wait Time) against other activities on the system and drill down further. Using the template given above you can extract any System Statistic you are interested in, and it is easy to add other ones in the future when you need them.

AWR Summary Reporting #4 - More Waits

Given the previous sub-query for total wait times including class level waits from the AWR snapshot data, we are going to extend that particular sub-query in order to add some extra wait event data items to it. This will give us a further breakdown of what the major wait events were, and how much time was spent waiting versus doing real work. The upside to these changes are that we will be able to pull out some other wait event times from the AWR snapshots in the same query, for little extra cost or increase in complexity. The downside is that the number of data items being selected for output will increase a lot, and this may start to look like a "mother of all database monitoring queries". However, the query itself is not more complex, and the intention is to get as much data as we can from each AWR snapshot in one hit to allow us to analyse it later outside Oracle (typically in a spreadsheet).

But before we do that I want to refactor that sub-query to make some of the later additions to it easier and simpler. Remember that we had just one sub-query, with the wait time always being calculated by subtracting the current snapshot's wait time from the previous snapshot's time. I want to refactor this by pushing this subtraction down into a nested sub-query, so that the rest of the wait sub-query becomes simpler.

So before we had elements like:

, sum (sysevent.time_waited_micro - psysevent.time_waited_micro) all_wait_time
, sum (decode (sysevent.wait_class, 'Commit', (sysevent.time_waited_micro - psysevent.time_waited_micro), 0)) commit_time

The refactor changes this to:

, syswaits as 
-- One row for total wait time, plus break down into major wait classes, and events
(select syswaitevents.snap_id
      , syswaitevents.dbid
      , sum (syswaitevents.time_waited_micro) all_wait_time
      , sum (decode (syswaitevents.wait_class, 'Commit', syswaitevents.time_waited_micro, 0)) commit_time
...
   from 
        (select sysevent.snap_id
              , sysevent.dbid
              , sysevent.wait_class
              , sysevent.event_name
              , sum (sysevent.time_waited_micro - psysevent.time_waited_micro) time_waited_micro
              , sum (sysevent.total_waits - psysevent.total_waits) wait_count
           from dba_hist_system_event sysevent, dba_hist_system_event psysevent
          where sysevent.snap_id = psysevent.snap_id + 1
...
            group by sysevent.snap_id, sysevent.dbid, sysevent.wait_class, sysevent.event_name
        ) syswaitevents
  group by syswaitevents.snap_id
         , syswaitevents.dbid
) -- syswaits

The key points are:

• The inner sub-query groups by wait class and individual event name, as well as by snapshot and database id, and sums the wait time to this granularity.
• It also sums the total occurrences of each wait event, for further use in the outer query.
• The outer sub-query can now just refer to "syswaitevents.time_waited_micro" as the elapsed wait time, as the subtraction between the current and previous snapshot values are done in the inner sub-query.
• The outer sub-query still does the "decode" of the class name to extract individual sums for each class desired

Previously I said that there were too many individual events to report them all - around 100 individual wait events. However, experienced DBA's find that they do tend to run across a very common set of wait events that occur most often on "slow" systems. There is a strong enough argument for extracting and reporting the wait times for some individual wait events that you consider to be the "most common" wait events.

The benefit is that if any one of these particular wait event times is very high, then we already have extracted it and reported it for analysis and can see it in the output. If all of these particular wait event times are low, then there was almost no extra cost involved in retrieving them at the same time as the other wait event times (there is no extra disk I/O, only some extra CPU to process the wait time data). It avoids the need to run another query afterwards to drill down into the wait event data, and if the extra wait data is irrelevant then we can just ignore it. And the mechanism is the same one as for the wait classes, using "decode" against the event name.

The top wait events that I am going to include are listed below. It's not a large list as I want to focus on the query, not the specific wait events. You can disagree with some of these, or want to add some others of your own. You can do this just by modifying the query I give below and changing the event names used in the "decode" functions.

• db file sequential read
• db file scattered read
• direct path read
• log file sync
• log file parallel write
• gc buffer busy
• gc cr block busy

As well as the total wait time for each event, we would also want to know the number of waits that occurred so we can calculate the average time per wait. This is important as it might not be the number of waits that is the problem but the average time per wait. We can achieve a "count" by doing a "sum" using one (1) when the wait event name matches, and zero (0) otherwise. This keeps it uniform with the wait time per event.

The only changes to the refactored sub-query given earlier are the addition of these extra data items to the "select" output list:

      , sum (decode (syswaitevents.event_name, 'db file sequential read', syswaitevents.time_waited_micro, 0)) db_file_sqrd_time
      , sum (decode (syswaitevents.event_name, 'db file sequential read', 1, 0)) db_file_sqrd_count
      , sum (decode (syswaitevents.event_name, 'db file scattered read',  syswaitevents.time_waited_micro, 0)) db_file_sctrd_time
      , sum (decode (syswaitevents.event_name, 'db file scattered read',  1, 0)) db_file_sctrd_count
      , sum (decode (syswaitevents.event_name, 'direct path read',        syswaitevents.time_waited_micro, 0)) direct_path_read_time
      , sum (decode (syswaitevents.event_name, 'direct path read',        1, 0)) direct_path_read_count
      , sum (decode (syswaitevents.event_name, 'log file sync',           syswaitevents.time_waited_micro, 0)) log_file_sync_time
      , sum (decode (syswaitevents.event_name, 'log file sync',           1, 0)) log_file_sync_count
      , sum (decode (syswaitevents.event_name, 'log file parallel write', syswaitevents.time_waited_micro, 0)) log_file_prl_wr_time
      , sum (decode (syswaitevents.event_name, 'log file parallel write', 1, 0)) log_file_prl_wr_count
      , sum (decode (syswaitevents.event_name, 'gc buffer busy',          syswaitevents.time_waited_micro, 0)) gc_buff_busy_time
      , sum (decode (syswaitevents.event_name, 'gc buffer busy',          1, 0)) gc_buff_busy_count
      , sum (decode (syswaitevents.event_name, 'gc cr block busy',        syswaitevents.time_waited_micro, 0)) gc_cr_blk_busy_time
      , sum (decode (syswaitevents.event_name, 'gc cr block busy',        1, 0)) gc_cr_blk_busy_count

Then we need to add these extra columns to the output of the main "select", remembering to divide times in microseconds by one million:

     , syswaits.db_file_sqrd_time     / 1000000 db_file_sqrd_time
     , syswaits.db_file_sctrd_time    / 1000000 db_file_sctrd_time
     , syswaits.direct_path_read_time / 1000000 direct_path_read_time
     , syswaits.log_file_sync_time    / 1000000 log_file_sync_time
     , syswaits.log_file_prl_wr_time  / 1000000 log_file_prl_wr_time
     , syswaits.gc_buff_busy_time     / 1000000 gc_buff_busy_time
     , syswaits.gc_cr_blk_busy_time   / 1000000 gc_cr_blk_busy_time
     , syswaits.db_file_sqrd_count     db_file_sqrd_count
     , syswaits.db_file_sctrd_count    db_file_sctrd_count
     , syswaits.direct_path_read_count direct_path_read_count
     , syswaits.log_file_sync_count    log_file_sync_count
     , syswaits.log_file_prl_wr_count  log_file_prl_wr_count
     , syswaits.gc_buff_busy_count     gc_buff_busy_count
     , syswaits.gc_cr_blk_busy_count   gc_cr_blk_busy_count

Note that I have chosen to keep the times together and the counts together, rather than alternate between them for each event in turn. This particular ordering makes it easier to copy an "average wait time" formula from one cell to another in a spreadsheet, as each referenced column shifts by one column in each case.

With these columns added, the output from my AWR summary report becomes:

SNAP                SNAP       DB SQL EXEC ALL WAIT  BG WAIT   COMMIT  CLUSTER CONCRNCY  NETWORK   SYS IO  USER IO  DBF SEQ DF SCTRD DRCT PTH  LOG FILE LG FL PR  GC BUFF GC CRBLK    DBF SEQ   DF SCTRD   DRCT PTH   LOG FILE   LG FL PR    GC BUFF   GC CRBLK
TIME            DURATION     TIME     TIME     TIME     TIME  WAIT TM  WAIT TM  WAIT TM  WAIT TM  WAIT TM  WAIT TM  RD TIME  RD TIME  RD TIME SYNC TIME  WR TIME BSY TIME BSY TIME     RD CNT     RD CNT     RD CNT   SYNC CNT     WR CNT    BSY CNT    BSY CNT
--------------- -------- -------- -------- -------- -------- -------- -------- -------- -------- -------- -------- -------- -------- -------- --------- -------- -------- -------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
11/09/13 06:00     3,615    1,594    1,292      894      154      104       61        6      482       52      114       85        3       24       104       22        0       18     20,096        880     31,531     45,162     47,067         18      1,390
11/09/13 07:00     3,591    1,638    1,352      907      190       71       38        8      491       98      119       53        9       53        71       49        0        2     13,934      2,584     51,890     47,190     49,327         30        232
11/09/13 08:00     3,589    2,149    1,869    1,324      188       64       70        8      503       86      518      388       14       98        64       41        0        2    199,512      5,722     74,116     49,184     51,518         28        849
11/09/13 09:00     3,640    5,516    5,062    3,344      223       83      382       24      582       94    2,081    1,681       38      218        83       50      146        3    635,825     10,174    147,400     80,669     85,350     65,098      2,136 
11/09/13 10:00     3,558   11,193   10,150    6,625      326      264    1,040      146      670      161    4,007    2,980      227      710       264       87      106       34    744,366     90,168    415,035    129,443    136,572    116,076      8,471
11/09/13 11:00     3,630   16,981   15,578   10,260      486      371    1,294      116      865      255    7,116    5,804      368      495       371      144       14       18  1,346,338    162,856    274,090    191,730    201,510        834      4,778
11/09/13 12:00     3,609   15,954   14,349    9,516      497      508    1,456      143      876      231    5,887    4,979      185      579       508      125       70       68  1,230,115     92,290    317,980    186,878    197,001      3,207      8,931
11/09/13 13:00     3,602   10,800    9,651    6,013      383      278      774       81      747      181    3,665    3,191       87      323       278      102       18       21    954,932     32,045    200,258    173,877    184,167        661      9,443
11/09/13 14:00     3,562    8,532    7,562    4,359      319      203      488       55      698      158    2,566    2,364       25      149       203       92       22       12    553,064      6,607    133,380    159,407    169,369        388      6,391
11/09/13 15:00     3,601   11,486   10,210    6,721      402      374      899      111      751      189    4,102    3,485      157      304       374      109       42       50    814,112     79,733    214,011    172,358    181,824      1,944      7,554

As I said at the beginning this is a lot more columns of data than before. But the whole point is that we can now cut and paste this into a spreadsheet and do further analysis of the data to identify high values of one form or another. Now we not only have a break down of wait time by wait class, we also have the times and counts for the most common wait events.

Previously we saw that from 9am to 10am the major wait time was User I/O at 4,007 seconds out of 6,625 seconds for all waits. Now we can see that the one wait event of "db file sequential read" accounted for almost 3,000 seconds (2,980) out of the 4,000 for User I/O. We can also see that the next longest wait is probably "direct path read" at 710 seconds. So we now know which wait event contributed the most wait time, and how many times it occurred. And this lets us calculate the average "db file sequential read" for that period as being 0.004 seconds i.e. 4 milliseconds. Depending on your particular situation you may view this as being a high average time, or normal and acceptable. If the average wait time is acceptable then you would look at the number of such reads and try and find which SQL statements are causing them and tune those.