Sometimes things are easy (Part 1): How to fix wrapped execution plan text?

January 18, 2010 by 1 Comment

What you see below is a common problem. Someone sends you (or posts to a forum) a wide execution plan, which is unreadable because of wrapped lines. For example, this one below:

--------------------------------------------------------------------------------
-------------------

| Id  | Operation                   | Name                    | E-Rows |  OMem |
 1Mem | Used-Mem |

--------------------------------------------------------------------------------
-------------------

|   0 | SELECT STATEMENT            |                         |        |       |
 |          |

|   1 |  SORT AGGREGATE             |                         |      1 |       |
 |          |

|*  2 |   HASH JOIN                 |                         |     13 |  1102K|
 1102K|  355K (0)|

|*  3 |    HASH JOIN                |                         |     13 |   988K|
 988K|  367K (0)|

|*  4 |     HASH JOIN               |                         |     13 |   921K|
 921K|  621K (0)|

|*  5 |      HASH JOIN OUTER        |                         |     13 |   836K|
 836K| 1224K (0)|

|*  6 |       HASH JOIN             |                         |     13 |   821K|
 821K|  501K (0)|

|*  7 |        HASH JOIN            |                         |     13 |  1102K|
 1102K|  501K (0)|

|   8 |         MERGE JOIN CARTESIAN|                         |      1 |       |
 |          |

|*  9 |          TABLE ACCESS FULL  | PROFILE$                |      1 |       |
 |          |

|  10 |          BUFFER SORT        |                         |      1 | 73728 |
 73728 |          |

|* 11 |           TABLE ACCESS FULL | PROFILE$                |      1 |       |
 |          |

|* 12 |         TABLE ACCESS FULL   | USER$                   |     36 |       |
 |          |

|  13 |        TABLE ACCESS FULL    | PROFNAME$               |      1 |       |
 |          |

|* 14 |       TABLE ACCESS FULL     | RESOURCE_GROUP_MAPPING$ |      1 |       |
 |          |

|  15 |      TABLE ACCESS FULL      | TS$                     |      7 |       |
 |          |

|  16 |     TABLE ACCESS FULL       | TS$                     |      7 |       |
 |          |

|  17 |    TABLE ACCESS FULL        | USER_ASTATUS_MAP        |      9 |       |
 |          |

--------------------------------------------------------------------------------
-------------------

So now you either try to manually edit and fix the execution plan text so you could read it or ask the developer to send the execution plan again. Both approaches take time.

Well, sometimes things are easy – in this particular case I saved the above into a file called /tmp/x and ran the following command:

$ cat /tmp/x | awk '{ printf "%s", $0 ; if (NR % 3 == 0) print } END { print }'
---------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name                    | E-Rows |  OMem | 1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                         |        |       | |          |
|   1 |  SORT AGGREGATE             |                         |      1 |       | |          |
|*  2 |   HASH JOIN                 |                         |     13 |  1102K| 1102K|  355K (0)|
|*  3 |    HASH JOIN                |                         |     13 |   988K| 988K|  367K (0)|
|*  4 |     HASH JOIN               |                         |     13 |   921K| 921K|  621K (0)|
|*  5 |      HASH JOIN OUTER        |                         |     13 |   836K| 836K| 1224K (0)|
|*  6 |       HASH JOIN             |                         |     13 |   821K| 821K|  501K (0)|
|*  7 |        HASH JOIN            |                         |     13 |  1102K| 1102K|  501K (0)|
|   8 |         MERGE JOIN CARTESIAN|                         |      1 |       | |          |
|*  9 |          TABLE ACCESS FULL  | PROFILE$                |      1 |       | |          |
|  10 |          BUFFER SORT        |                         |      1 | 73728 | 73728 |          |
|* 11 |           TABLE ACCESS FULL | PROFILE$                |      1 |       | |          |
|* 12 |         TABLE ACCESS FULL   | USER$                   |     36 |       | |          |
|  13 |        TABLE ACCESS FULL    | PROFNAME$               |      1 |       | |          |
|* 14 |       TABLE ACCESS FULL     | RESOURCE_GROUP_MAPPING$ |      1 |       | |          |
|  15 |      TABLE ACCESS FULL      | TS$                     |      7 |       | |          |
|  16 |     TABLE ACCESS FULL       | TS$                     |      7 |       | |          |
|  17 |    TABLE ACCESS FULL        | USER_ASTATUS_MAP        |      9 |       | |          |
---------------------------------------------------------------------------------------------------

All I did here was that I stripped out line feeds from all lines except every 3rd line (which is the real end of the original line).

Note that if your linesize is very wide (and trimspool/trimout settings are ON) then this script would need some adjustment…

I’m sure this trivial approach doesn’t work in all situations, but with this article I wanted to illustrate that sometimes things which seem hard can be made much easier with a little scripting knowledge. If you are thinking which technology you should learn next – then better check out a Perl, Python or some shell+AWK book :)

By the way, if you want real flexibility displaying your execution plans (from library cache), then check this out:

http://blog.tanelpoder.com/2009/05/26/scripts-for-showing-execution-plans-via-plain-sql-and-also-in-oracle-9i/

Filed Under: Oracle, Productivity Tagged With: , ,

latch: cache buffers chains latch contention – a better way for finding the hot block

August 27, 2009 by 37 Comments

Here’s a treat for Oracle performance professionals and geeks who are looking for more systematic ways for cache buffers chains (CBC) latch contention troubleshooting. Cache buffers chains latches are taken when a process wants to walk through a cache buffer hash chain, looking if the block with required DBA (data block address) is in buffer cache. If the block happens to be in cache, then in most cases it has to be pinned first before use and unpinned after use, to make sure no-one else can perform an incompatible operation on that block at the same time. The modification of pin structures (pinning/unpinning) is also protected by CBC latches.

CBC latch contention can happen for multiple reasons, but one reason is that there is some really hot block in a SMP system with high number of CPUs (or CMT system with high number of threads like Sun T-series servers). Sometimes there happen to be multiple moderately hot blocks “under” the same CBC latch, which can result in latch contention again.

Traditionally DBAs used to look up the child latch address from V$SESSION_WAIT, sql_trace output or ASH and then look up all buffers protected by that latch from X$BH, using HLADDR column (HLADDR stands for Hash Latch Address). I also have a script for that, bhla.sql (Buffer Headers by Latch Address), which reports me all blocks currently in buffer cache, “under” that particular latch and the corresponding data block addresses and object names:

Filed Under: Cool stuff, Oracle Tagged With: , , ,

Scripts for showing execution plans via plain SQL and also in Oracle 9i

May 26, 2009 by 20 Comments

Hi all,

Here are few scripts which allow you to query SQL execution plans and their execution statistics out from V$SQL_PLAN and V$SQL_PLAN_STATISTICS yourself.

Why would you want to do this as there’s the DBMS_XPLAN.DISPLAY_CURSOR() function in Oracle 10g?

Well, my scripts work also on Oracle 9.2. Also they give you better detail (and flexibility) compared to DBMS_XPLAN.DISPLAY_CURSOR.

Of course in 9i there’s the DBMS_XPLAN.DISPLAY function which you can use in conjuction with EXPLAIN PLAN FOR command, but that approach has problems. EXPLAIN PLAN treats all bind variables as varchar2 datatype, possibly causing the reported execution plan to be different from reality. Also, if you have a long running report from last night and you run explain plan today morning, then if optimizer statistics have changed meanwhile, the explain plan command might come up with a different execution plan again, which is different from reality.

So that’s why in 10g we have the DBMS_XPLAN.DISPLAY_CURSOR which goes directly to required library cache child cursor and extracts (unparses) the execution plan from there. The function uses V$SQL_PLAN% views as its data source. And guess what – these views are there in version 9.2 already! And thats’ where my scripts come in:

Here’s an example. Let’s set statistics_level=all so we get rowsource level execution stats for the cursor (note that this parameter makes your query consume much more CPU so it should only be used at session level for troubleshooting a specific performance issue):

SQL> alter session set statistics_level = all;

Session altered.

SQL> select count(*) from all_users;

  COUNT(*)
----------
        36

I know the hash value of this query, so lets report its execution plan, directly from library cache. This is the REAL execution plan inside that child cursor, not some estimate like EXPLAIN PLAN command gives:

[Read more...]

Filed Under: Oracle Tagged With: , , ,

Another LatchProfX use case

March 20, 2009 by 12 Comments

Riyaj Shamsudeen wrote an excellent article about systematic latch contention troubleshooting.

Especially if the latch contention problem is ongoing, looking into system wide stats (like v$latch.sleep columns) is not the best idea in busy systems. This may sometimes lead you to fixing the wrong problem.

This is because sometimes the latch contention is not caused by some system wide inefficiency but rather by one or few sessions.

The right approach would be to measure the following things:

  1. Which latch (and exact child latches) the problem session is waiting for (query v$session_wait, ASH, sql_trace)
  2. Why is the problem session trying to get that latch so often (query v$sesstat counters for problem session and check execution plan if only single/few statements executed)
  3. Why this latch is busy: who’s holding it (query v$latchholder, LatchProf)
  4. Why is that someone holding the latch so much (query v$sesstat counters for that session or run LatchProfX)

Riyaj used this approach and successfully found out the troublemaker causing heavy library cache latch contention. He used my LatchProfX tool for part of the diagnosis (and I’m very happy to see that my advanced oracle troubleshooting tools find real world use in hands of other troubleshooters/tuners too!).

Here’s an excerpt from latchprofx output (from a little test case I put together), showing which session is holding which library cache latch how much, hold mode (shared/exclusive) and also the actual reason (function name) why the latch is held:

SQL> @latchprofx sid,name,laddr,ksllwnam,ksllwlbl,hmode 159 % 100000

-- LatchProfX 1.08 by Tanel Poder ( http://www.tanelpoder.com )

 SID NAME           LADDR            KSLLWNAM  KSLLWLBL  HMODE        Held  Gets  Held %  Held ms Avg hold ms
---- -------------- ---------------- --------- --------- ---------- ------ ----- ------- -------- -----------
 159 library cache  00000003A93513E0 kglic     child     exclusive   10044  9314   10.04  301.320        .032
 159 library cache  00000003A9351340 kglic     child     exclusive    9895  8458    9.90  296.850        .035
 159 library cache  00000003A9351660 kglic     child     exclusive    9761  8440    9.76  292.830        .035
 159 library cache  00000003A9351700 kglic     child     exclusive    9737  8924    9.74  292.110        .033
 159 library cache  00000003A9351480 kglic     child     exclusive    8999  7765    9.00  269.970        .035
 159 library cache  00000003A93515C0 kglic     child     exclusive    8553  7832    8.55  256.590        .033
 159 library cache  00000003A9351520 kglic     child     exclusive    6852  6828    6.85  205.560        .030

7 rows selected.

kglic means Kernel Generic Library cache Iterate Chain (AFAIK), it’s the function which is executed when you access most X$KGL tables. And this is where Riyaj got the evidence that the latch contention comes from inefficient scanning of library cache, caused by a session running queries against V$SQL_PLAN views with a bad plan.

So, check out Riyaj’s articele, my LatchProfX script, then my Advanced Oracle Troubleshooting Seminar :)

Filed Under: Oracle Tagged With: , , ,

Performance Visualization, Capacity planning and Hotsos Symposium

February 14, 2009 by 3 Comments

I have slowly moved towards performance visualization and system capacity planning world. Or at least this is my main focus (in addition to deep Oracle internals of course ;)

I’ve published an easy Oracle performance visualization tool, which is based on Excel and can visualize the resultset of any SQL query. It’s called PerfSheet (and I’ve blogged about it here).

Last December I spoke at CMG Conference in Las Vegas about a new method for visualizing database-wide performance while still being able to see session level performance profile. Having session level performance overview is important when diagnosing performance problems which only some users of the whole system are experiencing.

The paper I was talking about is accessible from here: http://arxiv.org/pdf/0809.2532

We wrote it together with Dr. Neil Gunther, the theoretical part was his idea and I helped to apply it in Oracle.

Neil received the prestigious A.A. Michelson’s award during that CMG event, so I was pretty honoured to even be at the same stage with him :)

 

I will be presenting some further peformance visualization and capacity planning related work during my “No slides” session at Hotsos Symposium this year. I’m excited as I will be showing some really cool (and useful!) things there ;)

Filed Under: Cool stuff, Oracle Tagged With: ,

When was a table last changed?

February 7, 2009 by 22 Comments

I frequently get a question about how to find out when was a table last modified. I’m talking about table data, not table structure, the latter would be detectable from dba_objects.last_ddl_time.

Unless you have some table level DML auditing already turned on, then as one option you could use LogMiner and “just” work through the redo/archivelogs in the range of interest with it. This could be very time consuming (especially if the last change was done a while back), so here’s another option for getting last table modification info very easily, however it comes with some restrictions.

http://www.tanelpoder.com/files/scripts/lastchanged.sql

(read instructions and limitations from the script header).

The idea is following:

  1. Oracle has an ORA_ROWSCN pseudocolumn which reports the last known change time for a row in a table. The “time” shows a commit SCN number of last transaction modifying the row, not a real timestamp though. It is important to note that unless the ROWDEPENDECIES are enabled, then the last SCN is known only at data block level, not row level, rowscn’s for all rows in a block would report whatever SCN is in the last change SCN in block header.
  2. SCN is ever-increasing internal “time” used by Oracle recovery and transaction layers and it is possible to map this to real time with reasonable accuracy using few Oracle’s tables which store SCN to wallclock time mappings. My script reports the time range in which the last change to datablock/row occurred so you’ll know how accurate it is.
    I use sys.smon_scn_time and v$log_history views for SCN to real time mapping. So my script reports two times, first one may be more accurate, second one has longer history on the other hand.You can use whatever other datasource for doing this mapping, as long as it has SCNs and corresponding timestamps in it. For example, if you have log_checkpoints_to_alert parameter set to true, you can grep the SCN/timestamp pairs out with command like this:

    cat alert_win10g.log | egrep -e "^Beginning.*checkpoint|[[:alpha:]]{3} [[:alpha:]]{3} [[:digit:]]{2} "

Here are few usage examples.

First I’ll check some data which was probably last changed a long time ago:

SQL> @lastchanged sys.obj$ name='DBMS_STANDARD'

-- LastChanged.sql v1.0 by Tanel Poder ( http://www.tanelpoder.com )

Running this query:

.   select MAX(ora_rowscn)
.   from sys.obj$
.   where name='DBMS_STANDARD';

DATA_SOURCE       LAST_CHANGED
----------------- -------------------------------------------------------
sys.smon_scn_time Before  2008-12-31 16:05:25 (earlier than 21 days ago)
v$log_history     Before  2008-10-27 03:58:16 (earlier than 86 days ago)

2 rows analyzed.

As both sys.smon_scn_time and v$log_history don’t have records dating back to that old time when the database was created (when DBMS_STANDARD and other object records in that datablock were created), they just show that the change happened before the oldest SCN to time mapping they have.

Here’s a check on a regular table, but we are only interested in rows/datablocks where the “sal” column is bigger than 1000:

[Read more...]

Filed Under: Oracle Tagged With: , ,

Multipart cursor subexecution and PRECOMPUTE_SUBQUERY hint

January 23, 2009 by 14 Comments

There was a question about PRECOMPUTE_SUBQUERY hint in an Oracle Forums thread.

Here I will post the answer I gave there and also elaborate it more as it explains a little known interesting fact about Oracle cursor management. Also it allows me to introduce few advanced Oracle troubleshooting scripts by example. This is a fairly long post, but if you are interested in some Oracle cursor management and SQL execution internals, keep on reading ;)

Consider the following test case with two tables, T1 and T2:

SQL> create table t1 as select rownum a from dual connect by level < 10;

Table created.

SQL> create table t2 as select rownum+10 b from dual connect by level < 10;

Table created.

SQL>
SQL> select * from t1;

         A
----------
         1
         2
         3
         4
         5
         6
         7
         8
         9

9 rows selected.

SQL>
SQL> select * from t2;

         B
----------
        11
        12
        13
        14
        15
        16
        17
        18
        19

9 rows selected.

Now lets run a query with a simple subquery in it:

SQL> select a
  2  from   t1
  3  where  a in (select b from t2);

no rows selected

SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------
SQL_ID  aucw6byq3d5q8, child number 0
-------------------------------------
select a from   t1 where  a in (select b from t2)

Plan hash value: 561629455

----------------------------------------------------------------------------
| Id  | Operation           | Name     | E-Rows |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |          |        |       |       |          |
|*  1 |  HASH JOIN SEMI     |          |      1 |  1066K|  1066K| 1056K (0)|
|   2 |   TABLE ACCESS FULL | T1       |      9 |       |       |          |
|   3 |   VIEW              | VW_NSO_1 |      9 |       |       |          |
|   4 |    TABLE ACCESS FULL| T2       |      9 |       |       |          |
----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("A"="B")

Note that a hash semijoin was performed which semijoined two of its child rowsources with join condition “A=B”.

Now lets run exactly the same query with PRECOMPUTE_SUBQUERY hint in subquery block:

SQL> select a
  2  from   t1
  3  where  a in (select /*+ PRECOMPUTE_SUBQUERY */b from t2);

no rows selected

SQL>
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------
SQL_ID  fvnqhjkcjnybx, child number 0
-------------------------------------
select a from   t1 where  a in (select /*+ PRECOMPUTE_SUBQUERY */b from
t2)

Plan hash value: 3617692013

-------------------------------------------
| Id  | Operation         | Name | E-Rows |
-------------------------------------------
|   0 | SELECT STATEMENT  |      |        |
|*  1 |  TABLE ACCESS FULL| T1   |      5 |
-------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(("A"=11 OR "A"=12 OR "A"=13 OR "A"=14 OR "A"=15 OR "A"=16
              OR "A"=17 OR "A"=18 OR "A"=19))

See what happened! The join is gone and it looks like table T2 is not accessed at all (as there is only one TABLE ACCESS rowsource which reads from table T1 ).

However, there has appeared a filter condition which has all the values from T2 in it! How are these values retrieved?

A simple sql_trace reveals this:

[Read more...]

Filed Under: Cool stuff, Oracle Tagged With: , , ,

Identifying shared memory segment users using lsof

January 22, 2009 by 7 Comments

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…

Filed Under: Oracle Tagged With: , , , ,

Oracle memory troubleshooting, Part 1: Heapdump Analyzer

January 2, 2009 by 7 Comments

When troubleshooting Oracle process memory issues like ORA-4030′s or just excessive memory usage, you may want to get a detailed breakdown of PGA, UGA and Call heaps to see which component in there is the largest one.

The same goes for shared pool memory issues and ORA-4031′s – sometimes you need to dump the shared pool heap metadata for understanding what kind of allocations take most of space in there.

The heap dumping can be done using a HEAPDUMP event, see http://www.juliandyke.com/Diagnostics/Dumps/Dumps.html for syntax.

NB! Note that when dumping SGA heaps (like shared, large, java and streams pools), your process holds shared pool latches for the entire dump duration so this should be used only as a last resort in busy production instances. Dumping a big shared pool could hang your instance for quite some time. Dumping private process heaps is safer as that way only the target process is affected.

The heapdump output file structure is actually very simple, all you need to look at is the HEAP DUMP header to see in which heap the following chunks of memory belong (as there may be multiple heaps dumped into a single tracefile).

HEAP DUMP heap name="sga heap(1,1)"  desc=04EA22D0
 extent sz=0xfc4 alt=108 het=32767 rec=9 flg=-125 opc=0
 parent=00000000 owner=00000000 nex=00000000 xsz=0x400000
EXTENT 0 addr=20800000
  Chunk 20800038 sz=   374904    free      "               "
  Chunk 2085b8b0 sz=      540    recreate  "KGL handles    "  latch=00000000
  Chunk 2085bacc sz=      540    recreate  "KGL handles    "  latch=00000000
  Chunk 2085bce8 sz=     1036    freeable  "parameter table"
  Chunk 2085c0f4 sz=     1036    freeable  "parameter table"
  Chunk 2085c500 sz=     1036    freeable  "parameter table"
  Chunk 2085c90c sz=     1036    freeable  "parameter table"
  Chunk 2085cd18 sz=     1036    freeable  "parameter table"
  Chunk 2085d124 sz=      228    recreate  "KGL handles    "  latch=00000000
  Chunk 2085d208 sz=      228    recreate  "KGL handles    "  latch=00000000
  Chunk 2085d2ec sz=      228    recreate  "KGL handles    "  latch=00000000
  Chunk 2085d3d0 sz=      228    recreate  "KGL handles    "  latch=00000000
  Chunk 2085d4b4 sz=      228    recreate  "KGL handles    "  latch=00000000
  Chunk 2085d598 sz=      540    recreate  "KQR PO         "  latch=2734AA00
  Chunk 2085d7b4 sz=      540    recreate  "KQR PO         "  latch=2734AA00
  Chunk 2085d9d0 sz=      228    recreate  "KGL handles    "  latch=00000000
...

The first list of chunks after HEAP DUMP (the list above) is the list of all chunks in the heap. There are more lists such as freelists and LRU lists in a regular heap, but lets ignore those for now, I’ll write more about heaps in an upcoming post.

After identifying heap name from HEAP DUMP line, you can see all individual chunks from the “Chunk” lines. The second column after Chunk shows the start address of a chunk, sz= means chunk size, the next column shows the type of a chunk (free, freeable, recreate, perm, R-free, R-freeable).

The next column is important one for troublehsooting, it shows the reason why a chunk was allocated (such KGL handles for library cache handles, KGR PO for dictionary cache parent objects etc). Every chunk in a heap has a fixed 16 byte area in the chunk header which stores the allocation reason (comment) of a chunk. Whenever a client layer (calling a kghal* chunk allocation function) allocates heap memory, it needs to pass in a comment up to 16 bytes and it’s stored in the newly allocated chunk header.

This is a trivial technique for troubleshooting memory leaks and other memory allocation problems. When having memory issues you can just dump all the heap’s chunks sizes and aggregate these by allocation reason/comment. That would show you the biggest heap occupier and give further hints where to look next.

As there can be lots of chunks in large heaps, aggregating the data manually would be time consuming (and boring). Here’s a little shell script which can summarize Oracle heapdump output tracefile contents for you:

[Read more...]

Filed Under: Oracle Tagged With: , , ,

Oracle hidden costs revealed, Part2 – Using DTrace to find why writes in SYSTEM tablespace are slower than in others

September 2, 2008 by 29 Comments

I have written two posts in one, about a performance issue with writes in system tablespace and introduction of a little DTrace stack sampling script.

Have you noticed that DML on tables residing in SYSTEM tablespace is slower than tables in other tablespaces?

Here’s an example, I’ll create two similar tables, one in USERS tablespace, other in SYSTEM, and inset into the first one (Oracle 10.2.0.3 on Solaris x64):

SQL> create table t1(a int) tablespace USERS;

Table created.

SQL> create table t2(a int) tablespace SYSTEM;

Table created.

SQL> exec for i in 1..100000 loop insert into t1 values(i); end loop;

PL/SQL procedure successfully completed.

Elapsed: 00:00:03.09

Insert into table in USERS tablespace took 3 seconds.

Ok, let’s commit and flush dirty buffers that they wouldn’t get on the way of next insert.

SQL> commit;

Commit complete.

Elapsed: 00:00:00.02

SQL> alter system checkpoint; -- checkpointing to flush dirty buffers from previous inserts

System altered.

Elapsed: 00:00:01.34
SQL>

And now to the insert into the SYSTEM tablespace table:

SQL> exec for i in 1..100000 loop insert into t2 values(i); end loop;

PL/SQL procedure successfully completed.

Elapsed: 00:00:08.98
SQL>

What?! The same insert took 3 times longer, almost 9 seconds?

Fine! Let’s troubleshoot it!

[Read more...]

Filed Under: Oracle Tagged With: , , , ,
«Older Posts
Newer Posts»