DTrace is now also available for Oracle Linux

Oracle has ported DTrace for Oracle Linux. DTrace is a very powerful performance analysis and troubleshooting tool that allows you to instrument all software. It’s name is short for Dynamic Tracing. I’m not a DTrace expert but some say it is that powerful that it allows you to reverse engineer any software…

New job – Welcome Oracle!

It’s been a long time since my last post on this blog and there were very good reasons for this. Since the last 6 and a half months I did not only move from the US to the UK but also switched from my previous company to Oracle. Of course it took a while to get into the new job but also to get approval for continuing this blog. You will notice a disclaimer at the right hand side saying that this blog is my private blog and has nothing to do with Oracle. So obviously nothing that I post here reflects any official view or statement of Oracle or its affiliates! That being said: time to catch up on some posts!

Oracle LogMiner

Oracle provides a powerful out of the box tool called LogMiner within the Oracle database. LogMiner enables you to query online and archived redo log files through simple SQL. The log files of the database contain all changes made to user data or to the database dictionary due to recovery purposes. Based on that LogMiner can be a powerful data auditing as well as a sophisticated data analysis tool. So here is a small example how to have an inside look into the redo data of your database (for a detailed cover of Oracle LogMiner have a look at Chapter 19 of the Oracle Database Utilities guide).

First of all you need to tell LogMiner which log files you want to examine. For this example I just going to use the 3 default redo log files that come with the default installation:


[oracle@localhost ~]$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.1.0 Production on Wed Jan 26 09:30:09 2011

Copyright (c) 1982, 2009, Oracle.  All rights reserved.

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> desc v$logfile;
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 GROUP#                                             NUMBER
 STATUS                                             VARCHAR2(7)
 TYPE                                               VARCHAR2(7)
 MEMBER                                             VARCHAR2(513)
 IS_RECOVERY_DEST_FILE                              VARCHAR2(3)

SQL> SELECT group#, status, member FROM v$LOGFILE;

 GROUP# STATUS
---------- -------
MEMBER
--------------------------------------------------------------------------------
 3
/home/oracle/app/oracle/oradata/orcl/redo03.log

 2
/home/oracle/app/oracle/oradata/orcl/redo02.log

 1
/home/oracle/app/oracle/oradata/orcl/redo01.log

Next I tell LogMiner to use those three redo log files:


SQL> exec DBMS_LOGMNR.ADD_LOGFILE('/home/oracle/app/oracle/oradata/orcl/redo03.log');

PL/SQL procedure successfully completed.

SQL> exec DBMS_LOGMNR.ADD_LOGFILE('/home/oracle/app/oracle/oradata/orcl/redo02.log');

PL/SQL procedure successfully completed.

SQL> exec DBMS_LOGMNR.ADD_LOGFILE('/home/oracle/app/oracle/oradata/orcl/redo01.log');

PL/SQL procedure successfully completed.

To verify that it worked I’ll query the V$LOGMNR_LOGS view which contains all log files that LogMiner will examine:


SQL> SELECT * FROM V$LOGMNR_LOGS;

 LOG_ID
----------
FILENAME
--------------------------------------------------------------------------------
LOW_TIME  HIGH_TIME      DB_ID DB_NAME   RESET_SCN RESET_SCN COMPATIBLE
--------- --------- ---------- -------- ---------- --------- -----------------
 THREAD_ID THREAD_SQN    LOW_SCN   NEXT_SCN DIC DIC TYPE     BLOCKSIZE
---------- ---------- ---------- ---------- --- --- ------- ----------
 FILESIZE INFO                                 STATUS
---------- -------------------------------- ----------
 32
/home/oracle/app/oracle/oradata/orcl/redo02.log
07-DEC-10 07-DEC-10 1229390655 ORCL         754488 30-OCT-09 11.2.0.0.0

 LOG_ID
----------
FILENAME
--------------------------------------------------------------------------------
LOW_TIME  HIGH_TIME      DB_ID DB_NAME   RESET_SCN RESET_SCN COMPATIBLE
--------- --------- ---------- -------- ---------- --------- -----------------
 THREAD_ID THREAD_SQN    LOW_SCN   NEXT_SCN DIC DIC TYPE     BLOCKSIZE
---------- ---------- ---------- ---------- --- --- ------- ----------
 FILESIZE INFO                                 STATUS
---------- -------------------------------- ----------
 1         32    2056780    2231224 NO  NO  ONLINE         512
 41424384                                           0

 LOG_ID
----------
FILENAME
--------------------------------------------------------------------------------
LOW_TIME  HIGH_TIME      DB_ID DB_NAME   RESET_SCN RESET_SCN COMPATIBLE
--------- --------- ---------- -------- ---------- --------- -----------------
 THREAD_ID THREAD_SQN    LOW_SCN   NEXT_SCN DIC DIC TYPE     BLOCKSIZE
---------- ---------- ---------- ---------- --- --- ------- ----------
 FILESIZE INFO                                 STATUS
---------- -------------------------------- ----------
 33
/home/oracle/app/oracle/oradata/orcl/redo03.log
07-DEC-10 26-JAN-11 1229390655 ORCL         754488 30-OCT-09 11.2.0.0.0

 LOG_ID
----------
FILENAME
--------------------------------------------------------------------------------
LOW_TIME  HIGH_TIME      DB_ID DB_NAME   RESET_SCN RESET_SCN COMPATIBLE
--------- --------- ---------- -------- ---------- --------- -----------------
 THREAD_ID THREAD_SQN    LOW_SCN   NEXT_SCN DIC DIC TYPE     BLOCKSIZE
---------- ---------- ---------- ---------- --- --- ------- ----------
 FILESIZE INFO                                 STATUS
---------- -------------------------------- ----------
 1         33    2231224    2252561 NO  NO  ONLINE         512
 7395840                                           0

 LOG_ID
----------
FILENAME
--------------------------------------------------------------------------------
LOW_TIME  HIGH_TIME      DB_ID DB_NAME   RESET_SCN RESET_SCN COMPATIBLE
--------- --------- ---------- -------- ---------- --------- -----------------
 THREAD_ID THREAD_SQN    LOW_SCN   NEXT_SCN DIC DIC TYPE     BLOCKSIZE
---------- ---------- ---------- ---------- --- --- ------- ----------
 FILESIZE INFO                                 STATUS
---------- -------------------------------- ----------
 34
/home/oracle/app/oracle/oradata/orcl/redo01.log
26-JAN-11 01-JAN-88 1229390655 ORCL         754488 30-OCT-09 11.2.0.0.0

 LOG_ID
----------
FILENAME
--------------------------------------------------------------------------------
LOW_TIME  HIGH_TIME      DB_ID DB_NAME   RESET_SCN RESET_SCN COMPATIBLE
--------- --------- ---------- -------- ---------- --------- -----------------
 THREAD_ID THREAD_SQN    LOW_SCN   NEXT_SCN DIC DIC TYPE     BLOCKSIZE
---------- ---------- ---------- ---------- --- --- ------- ----------
 FILESIZE INFO                                 STATUS
---------- -------------------------------- ----------
 1         34    2252561 2.8147E+14 NO  NO  ONLINE         512
 0                                           0

Now, after telling LogMiner which log files I want to examine I’m all set to start the mining process.


SQL> exec DBMS_LOGMNR.START_LOGMNR(options => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG);

PL/SQL procedure successfully completed.

The option “DICT_FROM_ONLINE_CATALOG” tells the LogMiner process to get the object information from the database dictionary directly. If I wouldn’t specify this option then Oracle wouldn’t translate the object ids into the given names. So instead of INSERT INTO TEST (id, text) VALUES… I would see something like INSERT INTO “UNKNOWN”.”OBJ# 96768″(“COL 1″,” COL 2″) VALUES… That of course is not very useful if you want to see what actually happened and so I’m going to use the dictionary to translate the ids into the given names.

So now let’s see how it works:


SQL> CREATE TABLE TEST (id NUMBER, text VARCHAR2(25))
TABLESPACE USERS
LOGGING;

Table created.

SQL> INSERT INTO TEST VALUES (1,'Test1');
INSERT INTO TEST VALUES (2,'Test2');
COMMIT;

1 row created.

SQL>
1 row created.

SQL>
Commit complete.

Note that I defined the LOGGING clause to make sure that LOGGING is enabled for that table. Redo log files are usually used for instance and/or media recovery. The data needed for such operations is automatically recorded in the redo log files. However, the recorded data might not be sufficient to make sense for the user. Specifying the LOGGING clause logs a little bit more information that should be enough for this scenario. For other scenarios however it might be also required to turn on supplemental logging.

All information that LogMiner has collected will be visible in the V$LOGMNR_CONTENTS view: The memory structure for V$LOGMNR_CONTENTS is held in the sessions PGA memory and not in the SGA. Therefore just the session which started LogMiner can also retrieve data from V$LOGMNR_CONTENTS:


SQL> SELECT timestamp, scn, start_scn, operation, seg_owner, seg_name, sql_redo
 FROM V$LOGMNR_CONTENTS
 ORDER BY timestamp, scn;

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419448            DDL
SYS
TEST
CREATE TABLE TEST (id NUMBER, text VARCHAR2(25))
TABLESPACE USERS
LOGGING ;

27-JAN-2011 09:56:50    125419451            UNSUPPORTED
SYS
SEG$
Unsupported

27-JAN-2011 09:56:50    125419451            UNSUPPORTED
SYS
SEG$
Unsupported

27-JAN-2011 09:56:50    125419452  125419441 COMMIT

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
commit;

27-JAN-2011 09:56:50    125419453            START

set transaction read write;

27-JAN-2011 09:56:50    125419453            INTERNAL

27-JAN-2011 09:56:50    125419454  125419453 COMMIT

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
commit;

27-JAN-2011 09:56:50    125419456            START

set transaction read write;

27-JAN-2011 09:56:50    125419456            INSERT
SYS
TEST
insert into "SYS"."TEST"("ID","TEXT") values ('1','Test1');

27-JAN-2011 09:56:50    125419456            INSERT
SYS
TEST

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
insert into "SYS"."TEST"("ID","TEXT") values ('2','Test2');

27-JAN-2011 09:56:50    125419457  125419456 COMMIT

commit;

As you can see the creation of the table as well as the INSERT statements can be retrieved from the redo log files. You can also see that the CREATE TABLE DDL issues 2 COMMITs internally. After that you see the two INSERT statements I executed. And that’s not everything. If I look a little bit further up I can also see what the database executed internally in order to create the table:


TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419441            START

set transaction read write;

27-JAN-2011 09:56:50    125419441            INSERT
SYS
OBJ$
insert into "SYS"."OBJ$"("OBJ#","DATAOBJ#","OWNER#","NAME","NAMESPACE","SUBNAME"
,"TYPE#","CTIME","MTIME","STIME","STATUS","REMOTEOWNER","LINKNAME","FLAGS","OID$
","SPARE1","SPARE2","SPARE3","SPARE4","SPARE5","SPARE6") values ('171359','17135
9','0','TEST','1',NULL,'2',TO_DATE('27-JAN-2011 09:56:50', 'DD-MON-YYYY HH24:MI:
SS'),TO_DATE('27-JAN-2011 09:56:50', 'DD-MON-YYYY HH24:MI:SS'),TO_DATE('27-JAN-2
011 09:56:50', 'DD-MON-YYYY HH24:MI:SS'),'1',NULL,NULL,'0',NULL,'6','1','0',NULL
,NULL,NULL);

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419441            INTERNAL

27-JAN-2011 09:56:50    125419441            START

set transaction read write;

27-JAN-2011 09:56:50    125419441            INTERNAL

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419444            START

set transaction read write;

27-JAN-2011 09:56:50    125419444            UNSUPPORTED
SYS
SEG$
Unsupported

27-JAN-2011 09:56:50    125419445  125419444 COMMIT

commit;

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419445            UNSUPPORTED
SYS
SEG$
Unsupported

27-JAN-2011 09:56:50    125419446            START

set transaction read write;

27-JAN-2011 09:56:50    125419446  125419441 COMMIT

commit;

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419446            UNSUPPORTED
SYS
TAB$
Unsupported

27-JAN-2011 09:56:50    125419447            UNSUPPORTED
SYS
TAB$
Unsupported

27-JAN-2011 09:56:50    125419447  125419446 COMMIT

commit;

TIMESTAMP                     SCN  START_SCN OPERATION
---------------------- ---------- ---------- --------------------------------
SEG_OWNER
--------------------------------
SEG_NAME
--------------------------------------------------------------------------------
SQL_REDO
--------------------------------------------------------------------------------
27-JAN-2011 09:56:50    125419447            UNSUPPORTED
SYS
COL$
Unsupported

27-JAN-2011 09:56:50    125419447            UNSUPPORTED
SYS
COL$
Unsupported

27-JAN-2011 09:56:50    125419448            DDL
SYS
TEST
CREATE TABLE TEST (id NUMBER, text VARCHAR2(25))
TABLESPACE USERS

As you can see even the INSERT into the internal OBJ$ table got recorded as well as some unsupported operations into SEG$, TAB$ and COL$.

Important to note again is that LogMiner runs just in the current session. The memory structure required runs within the sessions PGA. That means that no other session can retrieve the information from V$LOGMNR_CONTENTS. If you try it from another session you will get: ORA-01306: dbms_logmnr.start_logmnr() must be invoked before selecting from v$logmnr_contents

Also important is that you should always call DBMS_LOGMNR.END_LOGMNR(); before you log off. Otherwise you will get a silent ORA-600 [723]… as the bulletin article “The LogMiner utility” (Doc ID: 62508.1) on MOS says:

If you do not call end_logmnr, you will silently get ORA-00600 [723] …
on logoff. This OERI is triggered because the PGA is bigger at logoff than it was at logon, which is considered a space leak. The main problem from a support perspective is that it is silent, i.e. not signalled back to the user screen, because by then they have logged off.

The way to spot LogMiner leaks is that the trace file produced by the OERI 723 will have A PGA heap dumped with many Chunks of type ‘Freeable’ with a description of “KRVD:alh”

Ask Tom search engine

Today my boss asked me if I know how to fix the search engine for FireFox for AskTom.oracle.com since Tom Kyte has moved it to APEX. Actually I didn’t have the search engine even installed anymore (hope that means that I’m already so good with Oracle myself 😉 ) but thought that it would be nice to have it again.

Therefore I quickly build the search engine for the new Ask Tom site.

To install it, download this file by right-clicking on it and choosing “Save Link As”:

SearchEngineInstaller.png

Unfortunately – or better fortunately – WordPress doesn’t allow Javascript within posts nor xml files as media. Therefore I have to work with faked png files here.
After you download the file rename it to “SearchEngineInstaller.html” and open the file in your browser.
Then click on “Install Ask Tom search engine”, install the engine and “Mission accomplished”!

If you are interested in the “code” you can download the search engine file here: AskTomSearchEngine.png
Again with right click and “Save Link As”. Then rename it to “AskTomSearchEngine.xml”