CPU Queue Time as SQL*Net wait

I was testing a script that did a lot of very short SQL statements and running many of them at the same time to bog down the CPU on the database server.  I kept seeing high “SQL*Net message from client” waits from my profiling SQL code.

Normally a profile of a single long running statement when there is a large CPU queue looks like this:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             74        100
UNACCOUNTED_TIME                       37         50
CPU                                    37         50

This is a one CPU VM with two 100% CPU queries.  Each one’s CPU accounts for half of the total elapsed time leaving the other half unaccounted for.

But, take a high CPU load system and run a bunch of short sql statements the profile looks like this:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             13        100
SQL*Net message from client             8         62
log file sync                           5         38
CPU                                     1          8

This is a script with a bunch of insert/commit combinations like this:

insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;
insert into testtable values (1);
commit;

Without the high CPU load the profile is like this:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                              3        100
SQL*Net message from client             1         33
CPU                                     1         33
log file sync                           1         33

It looks like the SQL*Net message from client and log file sync times were both inflated by the high CPU load in the previous profile.

I tried this for shared and dedicated servers and for some reason shared servers reports even more SQL*Net waits for the same CPU load:

SUBSTR(TIMESOURCE,1,30)           SECONDS PERCENTAGE
------------------------------ ---------- ----------
TOTAL_TIME                             20        100
SQL*Net message from client            14         70
log file sync                           6         30
CPU                                     1          5

In further testing I was getting twice as many SQL*Net message from client waits for the same script with shared servers compared to dedicated so maybe that is why shared server connections are more sensitive to high CPU loads and report higher SQL*Net message from client waits.

Here is what the CPU looked like for the shared server example:

Notice the six loops – a simple C program with infinite loop.  These should be starving the other oracle processes for the CPU.  Note that this is the “c” option of top which is really helpful because it shows you the oracle process names like ora_lgwr_orcl similar to the default display on HP-UX’s glance tool.

So, I guess I was surprised that SQL*Net message from client waits were inflated by queuing on the CPU but it looks like they are.  This appears to be most visible when you have a lot of short run time SQL statements.

– Bobby