Using Perfsheet and TPT scripts for solving real life performance problems

Karl Arao has written a nice blog entry where he used also some of my tools for visualizing and understanding performance of a RAC cluster suddenly gone slow. He presents a systematic approach he used for gathering evidence and also hopefully you notice that having the ability to easily visualize performance data (with PerfSheet for example) can be very helpful and time saving when troubleshooting non-trivial problems.

Check his blog entry out here:

http://karlarao.wordpress.com/2009/06/07/diagnosing-and-resolving-gc-block-lost/

Identifying shared memory segment users using lsof

Lsof (list open files) is a really useful tool for troubleshooting open file decriptors which prevent a deleted file from being released or a shared memory segment from being removed.

Here’s a little situation on Linux where an Oracle shared memory segment was not released as someone was still using it.

$ ipcs -ma

------ Shared Memory Segments --------
key        shmid      owner      perms      bytes      nattch     status
0x00000000 393216     oracle    640        289406976  1          dest
0xbfb94e30 425985     oracle    640        289406976  18
0x3cf13430 557058     oracle    660        423624704  22

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0xe2260ff0 1409024    oracle    640        154
0x9df96b74 1671169    oracle    660        154

------ Message Queues --------
key        msqid      owner      perms      used-bytes   messages

The bold line should have disappeared after instance shutdown, but it didn’t. From “natcch” (number of attached processes) column I see there is still some process using the shared memory segment. Thus the segment was not released and even ipcrm command did not remove it (just like with normal files if someone has them open).

So, I needed to identify which process was still using the memory segment. If that had been a normal existing file, I’d could have used /sbin/fuser command to see which process still holds it open, but this only works for existing files with existing directory entries.

However for deleted files, sockets and shared memory segments, you can use lsof command (it’s normally installed by default on Linux, but for Unixes you need to separately download and install).

The SHM ID of that segment was 393216 as ipcs -ma showed, so I simply run lsof to show all open file descriptors and grep for that SHM ID:

$ lsof | egrep "393216|COMMAND"
COMMAND     PID      USER   FD      TYPE     DEVICE       SIZE       NODE NAME
python    18811    oracle  DEL       REG        0,8                393216 /SYSVbfb94e30

See how the NODE column corresponds to SHM ID in ipcs output.

So I kill the PID 18811 which is still attached to the SHM segment:

$ kill 18811

$ ipcs -ma

------ Shared Memory Segments --------
key        shmid      owner      perms      bytes      nattch     status
0xbfb94e30 425985     oracle    640        289406976  18
0x3cf13430 557058     oracle    660        423624704  25

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0xe2260ff0 1409024    oracle    640        154
0x9df96b74 1671169    oracle    660        154

------ Message Queues --------
key        msqid      owner      perms      used-bytes   messages


Now the shared memory segment is gone and its memory released.

Note that the lsof command is very useful for many other tasks as well. For example it allows you to list open sockets by network protocol, IP, port etc. For example you can determine to which client some server process is talking to, from OS level:

$ lsof -i:1521
COMMAND   PID   USER   FD   TYPE DEVICE SIZE NODE NAME
tnslsnr  6212 oracle   11u  IPv4  49486       TCP *:1521 (LISTEN)
tnslsnr  6212 oracle   13u  IPv4 276708       TCP linux03:1521->linux03:37277 (ESTABLISHED)
tnslsnr  6212 oracle   14u  IPv4 264894       TCP linux03:1521->linux03:41122 (ESTABLISHED)
oracle  22687 oracle   20u  IPv4 264893       TCP linux03:41122->linux03:1521 (ESTABLISHED)
oracle  25250 oracle   15u  IPv4 276707       TCP linux03:37277->linux03:1521 (ESTABLISHED)
oracle  25530 oracle   15u  IPv4 279910       TCP linux03:1521->192.168.247.1:nimsh (ESTABLISHED)

Unfortunately lsof is not installed by default in classic Unixes, but in some shops the sysadmins have chosen to install it. But even then, it may not work for regular users as lsof requires access to kernel memory structures through /dev/kmem or similar. If you can’t get access to lsof then there may be other tools available which can do some tricks lsof can do. For example on Solaris, there’s an useful command pfiles which can show open files of a process and since Solaris 9 ( I think ) it can also report the TCP connection endpoints of network sockets…

SQL*Net break/reset to client

There was a question in Oracle-L mailinglist recently, regarding excessive SQL*Net break/reset to client waiting by a session.

A quote is below:

We are seeing an insert statement reporting “SQL*Net break/reset to client” as over 1/3 of its time.
On the face of it this event suggests network issues but nothing else backs this up as the cause.
So I looked at the Java code in question and a trace of one of the sessions.
What is happening is that an attempt is made to insert a row, most of the time a duplicate error results, the code catches this exception and does an update.
I was wondering if its the duplicate error and the exception handling which results in this wait event showing up.

My answer to that was following:

Yes, a SQL*Net break/reset happens when an error/unhandled exception is raised during a call (which means that the call executed didn’t complete normally, thus the call state must be reset).

The approach of “insert -> if failed then update” is basically what MERGE does.

You need to change the application to use MERGE command. Alternatively you could use an “update -> if no-rows-updated then insert” approach, but MERGE makes much more sense nowadays.

So, these waits aren’t really indicating any network bottleneck, but rather just the fact that the client needs to be notified if it’s call has failed and Oracle has to clean up after the failed call. Apparently on some (network protocol) architectures or in some scenarios these operations have taken significant time (and may have required a system call), so a kernel developer has decided to wait instrument them.

In this blog entry I want to share a small test case which illustrates the point. First lets check how many times my session has waited for a SQL*Net break/reset wait event:

SQL> select event, total_waits from v$session_event where event like '%reset%' and sid = (select sid from v$mystat where rownum = 1);

no rows selected

As V$SESSION_EVENT (like also V$SYSTEM_EVENT) doesn’t display events for which nobody has waited yet, I see that my session’s wait count for that event is zero.

Now let’s create an error, but also let’s handle it in a PL/SQL exception handler:

[Read more...]

SQL*Net message to client vs SQL*Net more data to client

After my last post about SQL*Net message to client wait event I had a follow-up question about what’s the difference between SQL*Net message to client and SQL*Net more data to client wait events. I’ll post the answer here:

The first session data unit (SDU) bufferful of return data is written to TCP socket buffer under “SQL*Net message to client” wait event.

If Oracle needs to write more data for a call than fits into the “first” SDU buffer, then further writes for that call are done under SQL*Net more data to client event.

So, whether and how much of the “SQL*Net more data to client” vs “SQL*Net message to client” waits you see depends on two things:

  • Amount of data returned to client per call
  • Oracle Net SDU size

A quick test with my Snapper performance tool illustrates this:

In one session run following:

SQL> set arraysize 1
SQL>
SQL> select rownum from dba_source;

    ROWNUM
----------
         1
         2
         3
         4
         5
         6
...many rows returned...

And I measure the waits in the other session:

SQL> @snapper out,gather=w 5 1 141

-- Session Snapper v1.06 by Tanel Poder ( http://www.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------
HEAD,     SID, SNAPSHOT START   ,  SECONDS, TYPE, STATISTIC                               ,         DELTA,      D/SEC,     HDELTA,     HD/SEC
---------------------------------------------------------------------------------------------------------------------------------------------
DATA,     141, 20080210 14:59:55,        5, WAIT, SQL*Net message to client               ,          6750,       1350,     6.75ms,     1.35ms
DATA,     141, 20080210 14:59:55,        5, WAIT, SQL*Net message from client             ,       4668258,     933652,      4.67s,   933.65ms
--  End of snap 1

No SQL*Net more data to client is evidenced above as due the arraysize = 1 setting Oracle fetches only 2 rows at a time. Therefore the returned resultset per fetch call always fits into the first SDU sized packet. Note that the reason why Oracle fetches 2 rows when arraysize is 1 is due an OCI optimization which tries to be clever and proactively detect end-of-resultset conditions when fetching a single row – that way there’s a chance to automatically cancel a cursor and release its pins without an explicit cursor cancel or close call. This should have positive effect reducing shared pool fragmentation in some conditions.

Anyway, now I set arraysize to 5000 and run the same SQL again:

[Read more...]