Oracle Scratchpad

April 14, 2010

Analysing Statspack 12

Filed under: AWR,Oracle,Statspack,Troubleshooting — Jonathan Lewis @ 6:54 pm BST Apr 14,2010

[Further Reading on Statspack]

Part 12 is about a 2-node RAC system.  Someone recently posted links to a matched pair of AWR reports in this thread on the OTN Database General forum and, after I had made a couple of quick comments on them, gave me permission to use them on my blog.

Because OTN threads get dropped occasionally and people’s web addresses can change, I’ve copied the original files up onto my blog area so that the comments I make below can still be read in context. There’s a Word format (2MB) and a pdf format file (600KB) for each report so you can choose your preferred download and search tool.

I’ve set the files to open in new windows to make it easier to compare them and look at my notes at the same time – the report for node 1 is here in Word format and here as a pdf, and the report for node2 is here in Word format and here as a pdf.

As ever, we start with a quick context check – size of machine, type of job etc. and then take a look at work done (Load Profile) and time spent (Top 5 Timed events).

The snapshots are for two hours (this is the sort of thing that confuses me from time to time – I always expect to see one hour duration and sometimes forget to adjust for different times as I’m working through a report), but we see that the DB time is only slightly larger than the elapsed time,  so the system is not too busy.  (DB time is a feature introduced in 10g but only reported in the AWR output, not in Statspack.) 

We note that the NUM_CPUS in the Operating System Statistics section is eight in one report – and 16 in the other  (an imbalance that I’m not keen on in RAC systems). In one case the BUSY_TIME is around 10% of the IDLE_TIME, and in the other it’s closer to 6% – so again we see that “the system” is not heavily loaded. If there’s a problem it seems likely that it’s a particular task that is taking too much time, and we should be using the extended trace (10046 at level 8 or level 12) to investigate it. But let’s carry on to see if we can pick up any oddments anyway.

Still in the OS statistics we note that the memory is 16GB for the smaller machine and 32GB for the larger – and comparing that with the cache sizes at the top of the report we note that the buffer cache is 5.5GB and the shared pool is 600MB – so we might wonder if there’s another database, or an application server, also using this machine. (That might also help to explain why the CPU Time recorded by the instance is significantly less than the BUSY_TIME recorded by the operating system.)

Looking at the Load Profiles then – there’s nothing particularly exciting to see. The volume of work is not large for machines of this size. There is an interesting little oddity that one machine has done twice the number of transaction of the other – so perhaps it’s worth considering what’s going on with the load balancing strategy (maybe different types of work have been isolated to different nodes).

Looking at the Top 5, though, there are a couple of items to pursue. Both instances have spent a significant fraction of their time in “gc buffer busy” waits – an indication that processes on different nodes are competing for the same data at the same time, and that’s something we might be able to address. We’ll take a look at “SQL ordered by Cluster Wait Time” in a moment, and at “Segments by Global Cache Buffer Busy” (as well as the other two “Segment by ..” for cluster wait time.

One instance is showing quite a lot of time on “enq: TX – row lock contention” – transactions competing with each other to modify (or create) the same data at the same time.  We’ll have a look at the “SQL ordered by elapsed time” and the “enqueue activity” in a moment.

We also note that both instances show quite a lot of time for “flashback buf free by RVWR”. This system is running the “flashback database” enabled, and these waits are due to the activity of the “recovery writer”.  When you are about to change a block the first time after it’s been read into the cache, the recovery writer has to copy the block into the “recovery log buffer” or “flashback buffer”. If the flashback buffer is too small then a foreground process may have to wait for the recovery writer to clear some space before it can proceed – this may help to explain some of the competition for buffers (gc buffer busy, and ordinary buffer busy waits) that we see elsewhere.

I believe the flashback buffer defaults to twice the redo log buffer (although it’s 15MB in this case). The way in which Oracle 10g sets the redo log buffer sizing is a little complex, depending on granule sizes and the setting for processes and transactions  - and things can go a little odd in RAC which then doesn’t use the “private redo thread” technology – which is why we see the log buffer reported as a slightly surprising 4MB (which turned out to be two shared threads of 2MB each).

The normal advice for setting the log_buffer parameter in 10.2 is “don’t” – but in this case I think we might want to set it to 16MB or 32MB to see if that eliminates the waits for the recovery log buffer and, consequentially, some of the buffer busy waits and gc buffer busy.  (Unfortuantely it means restarting the instances, of course – but apart from that it’s a quick and easy fix.)

Both instances show lots of fairly quick log file syncs – that says something about the nature of the application. One instance shows quite a lot of fairly fast db file sequential reads (and the other instance isn’t far behind when we check the main Wait Events section. It looks like I/O isn’t a problem on this system – but we do have a lot of O/S memory, which we are probably using as a secondary (file system) cache behind the db cache.

So where have we got to: there is a configuration detail that we may be able to fix quickly; we have a lot of little transactions, a lot of competition for the same buffers between nodes, and even (possibly) for the same rows.

Checking the “SQL ordered by Cluster Wait Time” we see lots of:

DELETE FROM JMS_TRANSACTIONS W...
INSERT INTO MESSAGECONTENTS (I...
INSERT INTO JMS_MESSAGES (MESS...
DELETE FROM JMS_MESSAGES WHERE...
UPDATE JMS_MESSAGES SET TXID
INSERT INTO MAILBOXITEM (MAILB...
UPDATE MAILBOXITEM SET LASTMOD

and in the “Segments by global cache buffer busy” we see asssociated segments like:


MAILBOXITEM			TABLE
JMS_TRANSACTIONS		TABLE
MAILBOXITEM_MBID_OWN_DATES	INDEX
COMPLIANCE_DETAILS_PK		INDEX
MAILBOXITEM_MAILBOX_SUBMSG_PK	INDEX
JMS_MESSAGES_DESTINATION_IB	INDEX
JMS_MESSAGES_TXID_TXOP_I	INDEX

Initially I suggested that the owner of this system might want to look at making all the processes that use this message system connect to a single instance. However, the object names and SQL led to observations from another reader of the forum (Timur Akhmadeev) that the system was using the JAVA_XA package (which I know nothing about) and suggested that the system should be using the newer JDBC drivers instead.

Clearly there’s an opportunity for a strategic step to be taken in this particular area before pursuing too much more detail – but however it’s done, once the easy fix to the flashback log is in place, the important thing it to minimise the competition across the interconnect for popular blocks.

[Further Reading on Statspack]

Footnote: Any advice about reading AWR reports is almost always  relevant when reading Statspack  reports (and vice versa).

5 Comments »

  1. Jonathan,

    to be clear: objects in “Segments by global cache buffer busy” and JAVA_XA package are not related. Mentioned tables/indexes are used by the application – and no matter what kind of connectivity to Oracle it uses, the objects and it’s usage pattern suggests that the application will not work well in RAC without taking additional steps. JMS_MESSAGES and JMS_TRANSACTIONS are JBoss MQ service tables (for ACID-ing JMS transactions). SQL queries from the link match SQLs in AWR (and there are DDLs for tables). JMS_TRANSACTION has no indexes (by default) – possibly developers were thinking it will be small enough and/or they were saving some space. Chances are high that it requires an index (maybe globally hash-partitioned) with increased PCTFREE on table, or table should be single-table hash cluster, or hash-partitioned, etc – there are options to decrease ‘gc buffer busy’. JMS_MESSAGES has a PK constraint with (I guess) increasing values which most likely the cause of cluster wait time for SQLs accessing the table.

    JAVA_XA is an internal Oracle package used by JDBC drivers version less then 10g when XA is needed. 10g JDBC Thin driver can do this natively, and as a result faster (this is Oracle claim; I don’t have numbers to compare performance). So, the calls to JAVA_XA are coming implicitly from the driver to demarcate transaction boundaries in a distributed environment (DBMS_XA in 11g has similar documented functionality). It is implemented using Oracle JVM – i.e. procedures are simple wrappers for Java methods inside the DB. This can be seen in AWR as ‘Java execution elapsed time’ – ~13%.

    Another bad habit of JDBC applications is a query which usually looks like ‘select 1 from dual’ (SELECT ‘x’ FROM DUAL in AWR), executed many times. This is a checking query to validate connection – is it alive or not. The fact is ‘select 1 from dual’ is not the cheapest query for such task (as probably expected by someone), but ‘begin null; end;’ is. Usually it is a configuration option somewhere in the application configuration for the data source and can be easily modified.

    Comment by Timur Akhmadeev — April 15, 2010 @ 8:13 am BST Apr 15,2010 | Reply

  2. Jonathan,
    I’m interested in your comment about ‘select 1 from dual’ in jdbc applications. We have such an app using Tomcat connection pooling, and AWR reports show ‘select 1 from dual’ being executed millions of times per hour. This is what is used as the jdbc validation query. Although an inexpensive query, when executed many millions times it does consume cpu and is responsible for significant soft parsing. Are you suggesting that we can improve the situation by replacing ‘select 1 from dual’ with ‘begin null; end;’? From some basic (non-java) tests i can see that running millions of ‘select 1 from dual’ in a loop is significantly slower then millions of ‘begin null; end;’ Am I missing something here? Your suggestion seems like a huge improvement, yet I can find no other reference to using this as a validation query.
    I’m interested to hear what you have to say.
    Thanks,
    Peter

    Comment by Peter — April 27, 2013 @ 2:31 pm BST Apr 27,2013 | Reply

    • Peter,

      It’s not my comment, it’s Timur’s. He is, however, one of the Oracle specialists I would tend to put in the category of “probably correct until shown otherwise”.

      It certainly makes sense to me that a null pl/sql block could be faster than a query; and it makes sense to me that you won’t find any other reference to this as a strategy – after all, someone has to be the first to suggest a new method, and end-users often come up with clever ideas while the Oracle manuals (and the authors that copy them) are very slow to change their suggestions.

      Comment by Jonathan Lewis — June 9, 2013 @ 11:55 am BST Jun 9,2013 | Reply

      • Jonathan,

        One of my clients is plagued with “select 1 from dual” statements issued by JDBC applications.
        I was curious about testing ‘select 1 from dual’ vs ‘begin null;end;’

        Here are the results, using a Java program triggering a ‘ALTER SESSION SET EVENTS ’10046 trace name context forever, level 12′ before executing 40k statements.

        The database version is a 11.2.0.2.0, running on AIX LPAR.

        With begin null;end;

        SQL ID: 781naujq6snau Plan Hash: 0

        begin null;end;

        call count cpu elapsed disk query current rows
        ——- —— ——– ———- ———- ———- ———- ———-
        Parse 40000 0.12 2.16 0 0 0 0
        Execute 40000 0.10 1.99 0 0 0 40000
        Fetch 0 0.00 0.00 0 0 0 0
        ——- —— ——– ———- ———- ———- ———- ———-
        total 80000 0.22 4.15 0 0 0 40000

        And with select 1 from dual

        SQL ID: 520mkxqpf15q8 Plan Hash: 1546270724

        select 1
        from
        dual

        call count cpu elapsed disk query current rows
        ——- —— ——– ———- ———- ———- ———- ———-
        Parse 40000 0.07 1.42 0 0 0 0
        Execute 40000 0.10 1.49 0 0 0 0
        Fetch 40000 0.03 0.71 0 0 0 40000
        ——- —— ——– ———- ———- ———- ———- ———-
        total 120000 0.20 3.62 0 0 0 40000

        Unfortunately, we can see that “select 1 from dual” is giving slightly better results, too bad !

        Best Regards,
        Vincent

        Comment by Vincent — October 15, 2013 @ 4:47 pm BST Oct 15,2013 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 3,514 other followers