Who's online

There are currently 0 users and 33 guests online.

Recent comments

Oakies Blog Aggregator

Truncate – 2

Following on from my earlier comments about how a truncate works in Oracle, the second oldest question about truncate (and other DDL) appeared on the OTN database forum“Why isn’t a commit required for DDL?”

Sometimes the answer to “Why” is simply “that’s just the way it is” – and that’s what it is in this case, I think.  There may have been some historic reason why Oracle Corp. implemented DDL the way they did (commit any existing transaction the session is running, then auto-commit when complete), but once the code has been around for a few years – and accumulated lots of variations – it can be very difficult to change a historic decision, no matter how silly it may now seem.

This posting isn’t about answering the question “why”, though; it’s about a little script I wrote in 2003 in response to a complaint from someone who wanted to truncate a table in the middle of a transaction without committing the transaction. Don’t ask why – you really shouldn’t be executing DDL as part of a transactional process (though tasks like dropping and recreating indexes as part of a batch process is a reasonable strategy).

So if DDL always commits the current transaction how do you truncate a table without committing ? Easy – use an autonomous transaction. First a couple of tables with a little data, then a little procedure to do my truncate:

create table t1 (n1 number);
insert into t1 values(1);

create table t2 (n1 number);
insert into t2 values(1);

create or replace procedure truncate_t1
        pragma autonomous_transaction;
        execute immediate 'truncate table t1';

Then the code to demonstrate the effect:

prompt  ======================================
prompt  In this example we end up with no rows
prompt  in t1 and only the original row in t2,
prompt  the truncate didn't commit the insert.
prompt  ======================================

insert into t2 values(2);

execute truncate_t1;

select * from t1;
select * from t2;

According to my notes, the last time I ran this code was on but I’ve just tested it on and it behaves in exactly the same way.

I’ve only tested the approach with “truncate” and “create table” apparently, and I haven’t made any attempt to see if it’s possible to cause major distruption with cunningly timed concurrent activity; but if you want to experiment you have a mechanism which Oracle could have used to avoid committing the current transaction – and you may be able to find out why it doesn’t, and why DDL is best “auto-committed”.

Fedora 22/23 and Oracle 11gR2/12cR1

linux-tuxAs always, installations of Oracle server products on Fedora are not a great idea, as explained here.

I was reading some stuff about the Fedora 23 Alpha and realised Fedora 22 had passed me by. Not sure how I missed that. :)

Anyway, I did a run through of the usual play stuff.

While I was at it, I thought I would get the heads-up on Fedora 23 Alpha.

The F23 stuff will have to be revised once the final version is out, but I’m less likely to forget now. :)

I guess the only change in F22 upward that really affects me is the deprecation of YUM in F22 in favour of the DNF fork. For the most part, you just switch the command.

yum install my-package -y
yum groupinstall my-package-group -y
yum update -y

dnf install my-package -y
dnf groupinstall  my-package-group -y
dnf group install  my-package-group -y
dnf update -y

This did cause one really annoying problem in F23 though. The “MATE Desktop” had a single documentation package that was causing a problem. Usually I would use the following.

yum groupinstall "MATE Desktop" -y --skip-broken

Unfortunately, DNF doesn’t support “–skip-broken”, so I was left to either manually install the pieces, or give up. I chose the latter and use LXDE instead. :) F23 is an Alpha, so you expect issues, but DNF has been in since F22 and still no “–skip-broken”, which I find myself using a lot. Pity.



Fedora 22/23 and Oracle 11gR2/12cR1 was first posted on August 25, 2015 at 3:53 pm.
©2012 "The ORACLE-BASE Blog". Use of this feed is for personal non-commercial use only. If you are not reading this article in your feed reader, then the site is guilty of copyright infringement.

Oracle Midlands : Event #11

Just a quick note to say Oracle Midlands Event #11 is nearly here.




Oracle Midlands : Event #11 was first posted on August 25, 2015 at 2:36 pm.
©2012 "The ORACLE-BASE Blog". Use of this feed is for personal non-commercial use only. If you are not reading this article in your feed reader, then the site is guilty of copyright infringement.


The old question about truncate and undo (“does a truncate generate undo or not”) appeared on the OTN database forum over the week-end, and then devolved into “what really happens on a truncate”, and then carried on.

The quick answer to the traditional question is essentially this: the actual truncate activity typically generates very little undo (and redo) compared to a full delete of all the data because all it does is tidy up any space management blocks and update the data dictionary; the undo and redo generated is only about the metadata, not about the data itself.

Of course, a reasonable response to the quick answer is: “how do you prove that?” – so I suggested that all you had to do was “switch logfile, truncate a table, dump logfile”. Unfortunately I realised that I had never bothered to do this myself and, despite having far more useful things to do, I couldn’t resist wasting some of my evening doing it. Here’s the little script I wrote to help

create table t2 (v1 varchar2(32));
insert into t2 values (rpad('A',32));

create table t1
with generator as (
        select  --+ materialize
                rownum id
        from dual
        connect by
                level <= 1e4
        rownum                  id, 
        rpad('x',100)           padding
        generator       v1,
        generator       v2
        rownum <= 1e5

create index t1_i1 on t1(id);
alter system flush buffer_cache;
execute dbms_lock.sleep(3)

alter system switch logfile;

insert into t2 values(rpad('X',32));

truncate table t1;and t

insert into t2 values(rpad('Y',32));

execute dump_log

Procedure dump_log simply dumps the current log file. The call to switch logfile keeps the dumped log file as small as possible; and I’ve flushed the buffer cache with a three second sleep to minimise the number of misleading “Block Written Record” entries that might otherwise appear in the log file after the truncate. There were all sorts of interesting little details in the resulting activity when I tested this on – here’s one that’s easy to spot before you even look at the trace file:

SQL> select object_id, data_object_id, object_name from user_objects where object_name like 'T1%';

---------- -------------- --------------------
    108705         108706 T1_I1
    108704         108707 T1

Notice how the data_object_id of the index is smaller than that of the table after the truncate ? Oracle truncates (and renumbers) the index before truncating the table.

The truncate activity was pretty much as as I had assumed it would be – with one significant variation. The total number of change vectors report was 272 in 183 redo record (your numbers may vary slightly if you try to reproduce the example), and here’s a summary of the redo OP codes that showed up in those change vectors in order of frequency:

Change operations
  1 OP:10.25    Format root block
  1 OP:11.11    Insert multiple rows (table)
  1 OP:24.1     DDL
  1 OP:4.1      Block cleanout record
  2 OP:10.4     Delete leaf row
  2 OP:13.28    HWM on segment header block
  3 OP:10.2     Insert leaf row
  3 OP:17.28    standby metadata cache invalidation
  4 OP:11.19    Array update (index)
  4 OP:11.5     Update row (index)
 10 OP:13.24    Bitmap Block state change (Level 2)
 11 OP:23.1     Block written record
 12 OP:14.1     redo: clear extent control lock
 12 OP:22.5     File BitMap Block Redo
 14 OP:14.2     redo - lock extent (map)
 14 OP:14.4     redo - redo operation on extent map
 14 OP:5.4      Commit / Rollback
 15 OP:18.3     Reuse record (object or range)
 15 OP:22.16    File Property Map Block (FPM)
 22 OP:13.22    State on Level 1 bitmap block
 24 OP:22.2     File Space Header Redo
 29 OP:5.2      Get undo header
 58 OP:5.1      Update undo block

The line that surprised me was the 14 commit/rollback codes – a single truncate appears to have operated as 14 separate (recursive) transactions. I did start to walk through the trace file to work out the exact order of operation, but it’s really messy, and a tedious task, so I just did a quick scan to get the picture. I may have made a couple of mistakes in the following, but I think the steps were:

  • Start transaction
  • Lock the extent map for the index — no undo needed
  • Lock each bitmap (space management) block  — no undo needed
  • Reset each bitmap block — undo needed to preserve space management information
  • Reset highwater marks where relevant on bitmap and segment header block — undo needed
  • Clear segment header block — undo needed
  • Write all the updated space management blocks to disc (local write waits)
    • Log file records “Block Written Record”.
  • For each space management block in turn
    • Update space management blocks with new data object_id — undo needed
    • Write the updated block to disc (local write wait)
    • Log file records one “Block Written Record” for each block
  • Repeat all the above for the TABLE segment.
  • Start a recursive transacion
    • Insert a row into mon_mod$ — undo needed
    • recursive commit
  • Set DDL marker in redo log (possibly holding the text of the DDL statement, but it’s not visible in the dump)
  • Set object reuse markers in the redo log
  • update tab$  — needs undo, it’s just DML
  • update ind$ — needs undo, it’s just DML
  • update seg$  — needs undo, it’s just DML (twice – once for table once for index)
  • update obj$ — needs undo, it’s just DML (twice – ditto)
  • COMMIT — at last, with a change vector for a “Standby metadata cache invalidation” marker

The remaining 12 transactions look like things that could be delayed to tidy up things like space management blocks for the files and tablespaces and releasing “block locks”.

This first, long, transaction, is the thing that has to happen as an atomic event to truncate the table – and you can imagine that if the database crashed (or you crashed the session) in the middle of a very slow truncate then there seems to be enough information being recorded in the undo to allow the database to roll forward an incomplete truncate, and then roll back to before the truncate.

It would be possible to test whether or not this would actually work – but I wouldn’t want to do it on a database that anyone else was using.

Less calls…more performance (part 2)

In the previous post, I mentioned that for a programming environment fetching rows from the database, then the method of

  • open a ref cursor
  • issue a fetch call
  • close the ref cursor

might not be appropriate for those situations where the result set is known be a single row (eg primary key lookup).

A better option might be to call a procedure and get those outputs as parameters.

And I broke a cardinal rule… I effectively said “Here’s something that I know to be true…so you should just trust me“.

Dear oh dear oh dear. That’s not good. So without further ado, it’s time to put together a test case.

We’re need to come up with a way to test this across a “fast” network, the aim being that even with a best network latency we can obtain, there will still  be a demonstratable benefit to using a PL/SQL procedure over the ref cursor method.

One way of doing this is, is to have two databases running on the same box. One database will be the “real” database server, ie, it will hold our data. The other database will actually be a client to this database, and we will access the data via a database link. So we never go out across the true physical network – we are simply getting the smallest latency we can by going (in my case)  localhost to localhost.

So firstly on our “real” database, we create a table with a primary key. This database is called “NP12” on my machine

SQL> drop table T purge;

Table dropped.

SQL> create table T (
  2    x int primary key,
  3    y int ,
  4    z char(100));

Table created.

SQL> insert into T
  2  select rownum, rownum, rownum
  3  from dual
  4  connect by level <= 1000;

1000 rows created.

SQL> commit;

Commit complete.

SQL> exec dbms_stats.gather_table_stats('','T');

PL/SQL procedure successfully completed.

Now I’ve created a second database, so we’ll connect to that and that create some routines to access the table T on NP12

SQL> create database link np12 using 'np12';

Database link created.

These are our two procedure we will use for the test. One is our REF CURSOR procedure, which opens a cursor and passes it back to the client. The second does the whole job in the procedure but issuing the query and passing the fetched value back as a parameter.

SQL> create or replace
  2  procedure ref_cursor_open(p_i int, rc in out sys_refcursor) is
  3  begin
  4    open rc for select y from t@np12 where x = p_i;
  5  end;
  6  /

Procedure created.

SQL> create or replace
  2  procedure single_row_fetch(p_i int, p_y out int) is
  3  begin
  4    select y into p_y from t@np12 where x = p_i;
  5  end;
  6  /

Procedure created.

And now its time to test them for speed using a simple looping script. I’m using the INLINE pragma to reduce the overhead of PL/SQL calls so that we have a better accuracy with respect to the cost of the extra calls when using REF CURSOR.

SQL> set timing on
SQL> declare
  2    rc sys_refcursor;
  3    res int;
  4  begin
  5    for j in 1 .. 10 loop
  6      for i in 1 .. 1000 loop
  7        pragma inline(ref_cursor_open,'YES');
  8        ref_cursor_open(i,rc);
  9        fetch rc into res;
 10        close rc;
 11      end loop;
 12    end loop;
 13  end;
 14  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:05.55

SQL> declare
  2    rc sys_refcursor;
  3    res int;
  4  begin
  5    for j in 1 .. 10 loop
  6      for i in 1 .. 1000 loop
  7        pragma inline(single_row_fetch,'YES');
  8        single_row_fetch(i,res);
  9      end loop;
 10    end loop;
 11  end;
 12  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:02.80

And there you have it. Almost twice as fast. If you just trusted what I said from the first post…then that’s great. But in general, if you read something in someone’s blog, either challenge them to prove their assertion or just whip up a script to prove it for yourself.

Less calls…more performance

In various programming environments, a common metaphor is to open a cursor on the database (a REF CURSOR in Oracle parlance), return that cursor handle to the calling environment, and then that cursor is used to fetch or “fill” a data object, which may map to a grid on screen, or just to an array in memory.

And that’s totally fine – its an effective means to obtain a result set from the database to the calling environment.

For example, a typical PLSQL routine might look like:

PROCEDURE my_proc(p_resultset IN OUT sys_refcursor) IS
   OPEN p_resultset FOR
     SELECT col1, col2, col3, ...
     FROM   my_table
     WHERE  status = 'Unprocessed';

That’s fine when you want a set of rows, and luckily, most programming environments have evolved to the state nowadays where they will perform that retrieval with an array fetch, rather than single row fetches.

Because as a result, we’ve become attuned to always using the REF CURSOR method, so we tend to use this method for all database access.

But what about when we are returning a single row?  For example, if the SQL in the example above was:

SELECT col1, col2, col3, ...
FROM   my_table
WHERE  primary_key_col = 123;

then perhaps fetching from a ref cursor is not the most appropriate course of action. 

Why ?  Because it (typically) will require the programmer to issue two calls to the database:

  • call the PL/SQL routine to open the cursor
  • issue a local “fetch” call, which will then visit the database again to fetch the results

[Depending on the environment, there may even be a third call to close the cursor to ensure cursors dont leak and consume endless amounts of memory]

When retrieving a single row, perhaps think about the efficiency gains of wrapping the SQL within a PLSQL program and pass parameters in and out accordingly. The example above might then become something like:

PROCEDURE my_proc(p_prim_key IN int, p_col1 OUT int, p_col2 OUT int, p_col3 OUT int) IS
     SELECT col1, col2, col3, ...
     INTO   p_col1, p_col2, p_col3
     FROM   my_table
     WHERE  primary_key_col = 123;

The whole operation is done with a single call, and you get the PLSQL cursor caching benefit for free as well.

For high volume calls, this might be a significant performance boost.  Let’s face it – nowadays there is a good chance that your database server is just insanely fast at processing data, whether it be fetching it or storing it.  The speeds and core counts just continue to boggle the mind.  But all of that will count for little if you are jumping back and forth across the network between your middle tier program and the database.  Less calls = less trips = more performance.

Enhancing A Moving Art Project to Beginning Robotics with Raspberry Pi

Back on August 7th, the RMOUG’s Quarterly Education Workshop, I walked everyone through using a Pibrella board to create an art or flyer project that was powered with a python script and a motor.

Today, we’re going to take that same code and reuse it with a simple robotics kit to control power and rotation speeds/time to the Insectoid.  This kit, puchased from the Go! store in Flat Irons Crossing mall, was $16 and can be built in less than an hour, even for a small child. If you’re interested, you can also purchase the kit online at Amazon, but it was cheaper for me in the store to get him than online…


It requires only a small screw driver and is powered by a AAA 1.5 volt battery.  With the power required to the motor, I recommend leaving the battery wired in and the device off, (Raspberry Pi will be glad to supplement the power and you’ll know if you’ve overwhelmed your power requirements to a secondary project just by the sudden cycle of the OS,  so keep this in mind….)

After following the instructions and assembling the gears, the body and legs to complete the robotic insectoid, test it out with the battery and power switch.  Once he tests successfully, then comes the fun part of wiring him to the Pibrella board to control him from our Raspberry Pi.

Using red and black female/male breadboard jumper wires like the ones below-


Create a long black and long red “extension” to connect the insectoid to the Pibrella board.  Now, undo the cap that is connecting the battery and motor wires to the top of the Insectoid.  If the battery is wired into the motor wire in a way that makes the motor wire inseparable from it, re-wrap the battery wire to the motor wire at the base, leaving just the motor battery straight.  Take the motor battery, matching black to black and red to red, inserting the motor wire into the female jumper wire “extension” and ensure it’s tight.  You shouldn’t need any electrical tape to secure it and it should look like the following picture when you’re finished.


You can re-secure the connections under the cap after you’ve added the connection to the female jumper, (as seen for the red, (negative) connector.

Once this is done, it’s time to “recycle” our python script.  Log into the Raspberry Pi and open up a Terminal window.  Review your Python script from the earlier project OR just create a new python script, (.py) in your favorite text editor and type in the following-

 import pibrella
 import time
while true:

You must have a Pibrella card connected to your Raspberry Pi or you’ll need to follow instructions for controlling a motor with GPIO commands, etc. that can be found here.

The Python code does the following:

  1. imports the Pibrella module to use the Pibrella board, (you can do this with a bread board and the Raspberry Pi directly, just love the Pibrella, makes it so much easier.)
  2. import the TIME module to instruct our code how long to perform a specific function.
  3. Then-  after the button on the Pibrella is pushed
    1. turn the pibrella GPIO on and the wires attached are to run the motor.
    2. for TEN seconds
    3. Then shut off and break out.

You execute the script as we do any of our python scripts, using Python 3-

>sudo python3 .py

A video of the run with the robotics project can be seen on YouTube.

The next step is to enhance our script and have our robot do more than just walk forward and/or stop at a certain time.  We’ll want to build out a robot to have a Raspberry Pi control board ON BOARD and control his movements to turn, go in reverse and so forth.

Until next time-



Tags:  ,





Copyright © DBA Kevlar [Enhancing A Moving Art Project to Beginning Robotics with Raspberry Pi], All Right Reserved. 2015.

When Is An Idle Wait Not An Idle Wait?

 In general, performance tuning is quite straightforward. You work out how much time is spent doing what, and follow the numbers to the things that are taking the most time. If you are fortunate to the have the Diagnostics Pack on Enterprise Edition of Oracle you Active Session History will report the active database sessions. If you can measure the overall response time of a batch or application server you have merely to deduct the DB reported in ASH, and difference is client/middleware time.
While that is an over-simplification, it is substantially true. The rest of this blog is about an exception to the general rule.

A War Story 

I've been working with a system that makes extensive, and probably excessive, use of database links. There is a constellation of 3 Oracle databases and there are database links between them. There is also a soon-to-be legacy DB2 database, and one of the Oracle database uses Oracle Transparent Gateway to create Heterogeneous Database Links over which the application running on Oracle references data in the DB2 database.
During a load test, nearly all of the 64 application server processes are reported as busy handling requests, yet ASH reports than usually less than 2 database sessions are concurrently busy. You would expect to see 60 application server processes consuming CPU, but CPU does not appear to be as highly utilised as we should expect.

Application Server Activity
Database Activity

An application SQL trace reports that while the majority of the time is indeed spent on client CPU, about 20% is spent on a few SQL statements that reference synonyms that refer to tables or views in a DB2 database. Why didn't these show up in ASH?

A Simple Test Script 

I wrote a simple test script that just executes the SQL statements that refer to the DB2 objects, but it collects AWR snapshots at the beginning and end of the script, and it also enables Oracle session trace. 

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">set verify on head on timi on feedback on lines 200 trimspool on
spool otg_db2

variable b1 VARCHAR2(10)
variable b2 VARCHAR2(10)

:b1 := '123456789';
:b2 := '42';

ALTER SESSION SET tracefile_identifier='OTG_DB2';

EXEC dbms_workload_repository.create_snapshot;
EXEC dbms_application_info.set_action('OTG_DB2');
EXEC dbms_monitor.session_trace_enable;

FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2
FROM db2_object2 a
WHERE a.field1 = :b1 AND a.field2 = :b2

exec dbms_application_info.set_action('NONE');
exec dbms_monitor.session_Trace_disable;
exec dbms_workload_repository.create_snapshot;

select sample_id, sample_time, sql_id, sql_plan_hash_value, sql_plan_line_id, sql_exec_id, event
from v$active_session_history
where action = 'OTG_DB2';

spool off

The first interesting output is that although some of the queries on DB2 objects took several seconds, I didn't get any rows in the query on ASH buffer for this session.
So, now let's look at the trace file. This is the output for the longest SQL statement having profiled it in TKPROF. We can see that nearly all the time is spent on an event called HS message to agent.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.04 0 0 1 0
Fetch 1 0.00 2.73 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 2.77 0 0 1 0

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 35

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
DFS lock handle 1 0.00 0.00
rdbms ipc reply 2 0.00 0.00
HS message to agent 5 2.73 2.77
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00

And this is the corresponding section of the raw trace. The execution took just under 42ms, and then the fetch took 2.73 seconds.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">PARSING IN CURSOR #4579254328 len=171 dep=0 uid=35 oct=3 lid=0 tim=14984112395546 hv=1291470523 ad='700010b2204a518' sqlid='xxxxxxxxxxxxx'
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2
PARSE #4579254328:c=106,e=172,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=14984112395545
WAIT #4579254328: nam='Disk file operations I/O' ela= 23 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=14984112395633
WAIT #4579254328: nam='DFS lock handle' ela= 5205 type|mode=1146617861 id1=3569868743 id2=0 obj#=-1 tim=14984112401137
WAIT #4579254328: nam='rdbms ipc reply' ela= 75 from_process=46 timeout=900 p3=0 obj#=-1 tim=14984112401291
WAIT #4579254328: nam='rdbms ipc reply' ela= 710 from_process=46 timeout=900 p3=0 obj#=-1 tim=14984112402047
WAIT #4579254328: nam='HS message to agent' ela= 3464 p1=0 p2=0 p3=0 obj#=-1 tim=14984112405590
WAIT #4579254328: nam='HS message to agent' ela= 38459 p1=0 p2=0 p3=0 obj#=-1 tim=14984112444724
WAIT #4579254328: nam='HS message to agent' ela= 17 p1=0 p2=0 p3=0 obj#=-1 tim=14984112444791
EXEC #4579254328:c=932,e=49215,p=0,cr=0,cu=1,mis=1,r=0,dep=0,og=1,plh=0,tim=14984112444865
WAIT #4579254328: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=14984112444958
WAIT #4579254328: nam='HS message to agent' ela= 2730045 p1=0 p2=0 p3=0 obj#=-1 tim=14984115175093
WAIT #4579254328: nam='HS message to agent' ela= 8 p1=0 p2=0 p3=0 obj#=-1 tim=14984115175165
FETCH #4579254328:c=206,e=2730295,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=14984115175285
WAIT #4579254328: nam='SQL*Net message from client' ela= 895 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=14984115176264
CLOSE #4579254328:c=10,e=16,dep=0,type=0,tim=14984115176343

Across the whole of my test I have 29 waits on this event totalling 5.3s. Why I am not seeing this event in ASH?

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 9 0.00 0.00 0 0 0 0
Execute 10 0.00 0.21 0 0 1 3
Fetch 7 0.00 5.10 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 26 0.01 5.32 0 0 1 3

Misses in library cache during parse: 3
Misses in library cache during execute: 4

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 9 0.00 0.00
SQL*Net message from client 9 0.00 0.00
Disk file operations I/O 9 0.00 0.00
DFS lock handle 1 0.00 0.00
rdbms ipc reply 2 0.00 0.00
HS message to agent 29 2.73 5.30
library cache pin 2 0.00 0.00

If I generate an ASH report on the two snapshots created in this test and look at the Foreground events I might start to see why. AWR reports 29 waits totalling 5 seconds, so that agrees. However, note that this is at the bottom of the report with 'SQL*Net message from client' and there is no '%DB Time'.

AWR Foreground Events

We (should) know that 'SQL*Net message from client' is an idle event. So we can understand that there are 806 seconds reported on this event in this AWR report because there were 151 sessions connect to the database, most of which were mostly idle for the 6 seconds between the AWR snapshots. That is perfectly normal.
However, HS message to agent is classed as an idle wait, although the user was not idle. During this event the application is not busy, it is waiting for the Oracle database to respond, which is in turn waiting for the remote non-Oracle database to respond.
 This is in contrast to Oracle-to-Oracle (homogeneous) database links which report time to 'SQL*Net message from dblink' which is not an idle wait, but is part of the 'Network' wait class. I think the difference is an anomaly.
The next question is how much time my application spent on this event. For that I must look at the AWR data, either by generating an AWR report that corresponds to the load test, or directly in dba_hist_system_event.

Waits from AWR snspshots


  1. I am not the first person to call this out, just the latest person to get caught by it. It may be an idle wait, but the user is waiting for the database to respond. 
    Database Link Wait Event Wait Class
    Heterogeneous HS message to agent Idle
    Homogeneous SQL*Net message from dblink Network
  2. I got as far as starting to write an e-mail to a colleague asking for help, but before sending it I realised that I could do more to find out what was happening. Perhaps just the act of try to explain the problem helped me to think more clearly about it.

Oaktable World 2015 San Francisco, Oct 26 & 27

Agenda for Oaktable World 2015, located at Creativity Museum, is

 time Monday Oct 26 Tuesday Oct 27
8  8:30 – Welcome with Mogens  Toon Koppelaars – hash joins and Bloom filters
9 Mark W. Farnham – Minimizing the concurrency footprint of transactions with Logical Units of Work stored in PL/SQL Kyle Hailey – Virtual Data

Kerry Osborne – SQL Translation Framework

Kellyn Pot’Vin-Gorman, AWR Warehouse Trending and Analysis with OBIEE
11 Greg Rahn – Taming JSON with SQL: From Raw to Results

Marco Gralike – Improving XML performance with the 12c In-Memory Column Store

12 ted talks ted talks

Dan Norris – Exadata Database Machine Security

Cary Millsap – Performance

2  John Beresniwicz – AWR Ambiguity: What do do when the numbers don’t add up?

Gwen Shapira – Real-time data integration

3 Kevin Closson – Modern Platform Topics for Modern DBAs

Alex Gorbachev – Big Data 

4 Tanel Poder – Connecting Oracle with Hadoop  Chris Antognini – Adaptive Dynamic Sampling

Ted Talks between noon and 1pm

 Monday  Tuesday
 Eric Grancher – graphing outliers Jonah H. Harris – Manipulating the Oracle Call Interface

Greg Rahn- What Cloud Can Offer For A DBMS

Kellyn Pot’Vin-Gorman – TBD

Jonathan Lewis – indexes, column groups and 12c

Jonathan Lewis Virtual columns


            gluent            pythian


Web Pages Not Databases – Part 2: Fail2ban, Apache, IP Addresses, Linux, SELinux

August 23, 2015 (Modified August 31, 2015, September 14, 2015) (Back to the Previous Article in this Series) I started using Linux in 1999, specifically Red Hat Linux 6.0, and I recall upgrading to Red Hat Linux 6.1 after downloading the files over a 56k modem – the good old days.  I was a little […]