SkillBuilders | Oracle 10g: RMAN | Lesson 8: Debugging RMAN

Instructor's Notes

(If applicable)

Lesson 8 – Debugging Oracle RMAN Jobs
Author: Dave Anderson, SkillBuilders
www.skillbuilders.com
Last Update: October 17, 2007

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

The primary objective of this lesson is to learn how to determine how your RMAN operation fared. We will learn how to answer these questions about an RMAN operation:

Did it succeed?
Did it fail? If so, why?
Is it still running? If so, is it doing anything?

Specifically, we will learn how to:

locate and read messages related to RMAN operations
use dynamic performance views to find RMAN server sessions and monitor their progress
cancel RMAN commands
use the RMAN “debug” mode to generate a trace of all RMAN calls made in response to an RMAN command
instruct the tape media manager software to generate a log file of its actions.

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

Let’s first discuss where messages related to RMAN jobs are found. This includes:

The RMAN log file. If a log file is not specified either with the LOG startup option or the SPOOL LOG command (see example later in this lesson), the log is written to the RMAN console.
The Oracle database alert log will also be a source of important backup and recovery-related messages. Things you will see in the alert log include RMAN controlfile autobackup messages (the 9i Release 2 autobackup includes the SPFILE). For example, note the autobackup performed here because the DBA took the USERS tablespace offline:

Tue Feb 3 10:06:35 2004
alter tablespace users offline
Tue Feb 3 10:06:35 2004
Starting control autobackup
Control autobackup written to DISK device
handle '/opt/oracle/product/9.2.0/dbs/c-1808373586-20040203-00'
Completed: alter tablespace users offline

Any block corruption messages will also be logged in the alert log.

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

During a backup operation RMAN checks data and index blocks for physical corruption and, if corruption is found, records that information to the control file (and the alert log, as previously noted). Query V$BACKUP_CORRUPTION to check for any corruption:

system@TEST> select * from v$backup_corruption;
no rows selected

Note that if the CHECK LOGICAL option of the BACKUP command is used, RMAN will also check for logical corruption of rows and index entries.
If you are backing up to tape devices, the media manager (Legato, Veritas, etc) will generate log files. These log files are written to vendor-specific locations. For example, Legato writes its log, by default, to /nsr/logs/daemon.log on the Legato server (which is not necessarily the Oracle server).
Supplemental Notes on Corruption
If the number of physical and logical corruptions exceeds the MAXCORRUPT setting, the RMAN operation terminates. The default MAXCORRUPT is 0, meaning that no corruption is tolerated, i.e. RMAN terminates with an error if any corrupt blocks are discovered.
Refer to the Oracle9i Recovery Manager Reference for more information on the SET MAXCORRUPT FOR DATAFILE command. Refer to the Oracle9i Database Reference for more information on the V$BACKUP_CORRUPTION view.
Finally, note that physical or logical corruption should not be confused with IO errors. IO errors are not tolerated – the RMAN job terminates with errors.

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

Use the SPOOL LOG TO x command or the LOG startup option to write a log file of the RMAN job to the file system on the RMAN client. The log is written to the working directory (i.e. the current directory at RMAN startup). Alternatively, you can add the path in the SPOOL command:

RMAN> spool log to c:\x.log
RMAN> list backup summary;
RMAN> spool log off

Notes for this slide continue on the next page…

Other Text:
(Examples or comments displayed on slide, if any).

RMAN> spool log to test.log RMAN> run { 2> allocate channel d1 type disk maxopenfiles 1 format 3> backup tag='spool_test' tablespace ts1; } RMAN> RMAN> spool log off C:\>rman log=weeklyfull.log cmdfile=weeklyfull.rman RMAN> 2> 3> C:\>

Instructor's Notes

(If applicable)

After executing the commands in the first example shown above, the log might contain something like:
Spooling started in log file: test.log

Recovery Manager: Release 9.2.0.4.0 - Production
RMAN> 2> 3>
allocated channel: d1
channel d1: sid=12 devtype=DISK

Starting backup at 29-NOV-03
channel d1: starting full datafile backupset
channel d1: specifying datafile(s) in backupset
input datafile fno=00011 name=/opt/oracle/oradata/test/ts1.dbf
channel d1: starting piece 1 at 29-NOV-03
channel d1: finished piece 1 at 29-NOV-03
piece handle=/mnt/disk2/75f7lqtm_1_1 comment=NONE
channel d1: backup set complete, elapsed time: 00:00:01
Finished backup at 29-NOV-03
released channel: d1

The second example in the slide illustrates the use of the LOG parameter upon startup of the RMAN client. Like the SPOOL command, the LOG parameter will cause RMAN to write the log to the current working directory or the path specified in the LOG parameter. Note that the second example in the slide also uses the CMDFILE parameter, which might contain something like this:
connect target system/dave
backup database;
exit;

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

Workshop – Capturing Logs
Capture the output messages from the supplied RMAN script “WEEKLYFULL.RMAN” into a log file. Adjust the CONNECT command within the script according to the needs of your environment. Add a CONNECT CATALOG command if necessary or desired.

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

The RMAN error message stack is aptly named – it really is a stack of error messages! The messages that RMAN issues first (chronologically) are found at the bottom of the stack – it snowballs from there. Thus, often the most critical messages are found at the bottom of the stack. Reading the stack from the bottom up will often help you locate the most important error message more quickly (more quickly than reading from the top down).
In the example shown above, the DBA attempts a tape backup (“type sbt”) and, in an tuning effort, attempts to override the blocksize used by the tape drive (PARMS=“BLOCKSIZE=16000”). The ORA-27018 error message informs the DBA that 16000 is not a multiple of the platforms default blocksize. The “Additional information” message informs us that the minimum blocksize is 16384 – we must use a multiple of this value.
Refer to the lessons Getting Started with Tapes and Tuning RMAN for more information about backing up to tape devices.
Refer to the Oracle9i Database Error Messages for explanations of Oracle or RMAN messages (ORA-xxxxx or RMAN-xxxxx).

Other Text:
(Examples or comments displayed on slide, if any).

RMAN> run { 2> allocate channel t1 type sbt MAXOPENFILES 1 3> PARMS="BLKSIZE=16000"; 4> set command id to 'daves test'; 5> backup force tag='pgatest' tablespace ts5; } RMAN-00571: =========================================================== RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS =============== RMAN-00571: =========================================================== RMAN-03009: failure of allocate command on t1 channel at 11/29/2003 16:11:51 ORA-19554: error allocating device, device type: SBT_TAPE, device name: ORA-27018: BLKSIZE is not a multiple of the minimum physical block size Additional information: 16000 Additional information: 16384

Instructor's Notes

(If applicable)

These views can help monitor RMAN jobs and determine why a job may be hung.

V$PROCESS – Query to see currently active processes. It also contains the amount of PGA the process is using; this can be helpful with tuning RMAN operations.
V$SESSION – Query to see currently active sessions. “Use this view to determine which Oracle database server sessions correspond to which RMAN allocated channels.” Source: Metalink Note 144640.1.
V$SESSION_LONGOPS – Query to see the progress (or lack of) long-running processes, including RMAN operations.
V$SESSION_WAIT – Query to find what resources (or events) sessions are waiting for.

Demonstrations of using these views are found on the following pages.

Other Text:
(Examples or comments displayed on slide, if any).

See the RMAN Tuning lesson for additional uses of these views.

Instructor's Notes

(If applicable)

Oracle10g adds 18 new backup and recovery-related views. Refer to the Oracle Database Reference manual (Release 2) for details on these views:
V$BACKUP_ARCHIVELOG_DETAILS
V$BACKUP_ARCHIVELOG_SUMMARY
V$BACKUP_CONTROLFILE_DETAILS
V$BACKUP_CONTROLFILE_SUMMARY
V$BACKUP_COPY_DETAILS
V$BACKUP_COPY_SUMMARY
V$BACKUP_DATAFILE_DETAILS
V$BACKUP_DATAFILE_SUMMARY
V$BACKUP_PIECE_DETAILS
V$RMAN_OUTPUT
V$RMAN_STATUS
V$BACKUP_SET_DETAILS
V$BACKUP_SET_SUMMARY
V$BACKUP_SPFILE_DETAILS
V$BACKUP_SPFILE_SUMMARY
V$RMAN_BACKUP_JOB_DETAILS
V$RMAN_BACKUP_SUBJOB_DETAILS
V$RMAN_BACKUP_TYPE
V$FLASH_RECOVERY_AREA_USAGE
V$RMAN_ENCRYPTION_ALGORITHMS

Other Text:
(Examples or comments displayed on slide, if any).

R2

Instructor's Notes

(If applicable)

Connecting to the target creates a session on the target server. The process created on behalf of the target connection will invoke calls to the DBMS_RCVMAN and DBMS_BACKUP_RESTORE packages (to initiate backup and restore jobs). When you initiate an operation (e.g. backup, restore, even connecting to the catalog database), RMAN will spawn a second process, often called a “shadow” process. This second process will monitor the progress of these operations and record the progress in the V$SESSION_LONGOPS view. We will see examples of querying this view later in this lesson and again in the “Tuning RMAN” lesson. One additional process for each channel allocated will also be created.
See the supplied script “MONITORING_RMAN_SESSIONS.SQL” for more examples of using V$PROCESS and V$SESSION to monitor RMAN connections.
Supplemental Notes
- The allocated processes remain even after an RMAN command (e.g. BACKUP) has finished. The processes exist until the RMAN session is terminated. This is simply to prevent unnecessary recreation of processes if another RMAN command is executed.

Other Text:
(Examples or comments displayed on slide, if any).

system@TEST> select p.pid, p.spid, s.program 2 from v$process p, v$session s 3 where p.addr = s.paddr 4 / PID SPID PROGRAM ---------- ------------ ---------------------- 8 1743 oracle@beatles (CJQ0) 9 1745 oracle@beatles (QMN0) 14 2257 sqlplus.exe PID SPID PROGRAM ---------- ------------ ----------------------- 8 1743 oracle@beatles (CJQ0) 9 1745 oracle@beatles (QMN0) 14 2257 sqlplus.exe 15 2288 RMAN.EXE 16 2290 RMAN.EXE One process to run RMAN ops; One “shadow” process to log progress

Instructor's Notes

(If applicable)

As stated earlier, one addition session is created for every channel allocated by the RMAN session. The sessions can be displayed with this query:

select p.pid, p.spid, s.program,
- pga_used_mem, pga_max_mem
from v$process p, v$session s
where p.addr = s.paddr;

See the supplied script V$PROCESS.SQL for this query. In the output shown in the slide we see an additional session (PID 17) created on behalf of an ALLOCATE CHANNEL command. (See the next page for an example of how to identify which process is which.)
Supplemental Notes
- We can easily see the PGA memory requirements for each process. With Oracle9i automatic PGA memory management, this is less of an issue, but could be helpful. See the “Tuning RMAN lesson for more information on PGA memory usage.
- The UNIX ps command can be used to view the processes from the UNIX command prompt. This can be helpful in situations where killing an orphaned RMAN process is required. More on this concept will be presented later in this lesson.

Other Text:
(Examples or comments displayed on slide, if any).

system@TEST> / PID SPID PROGRAM ---------- ------------ -------------------- 8 1743 oracle@beatles (CJQ0) 9 1745 oracle@beatles (QMN0) 14 2257 sqlplus.exe 15 2288 RMAN.EXE 16 2290 RMAN.EXE 17 2334 RMAN.EXE PGA_USED_MEM PGA_MAX_MEM ------------ ----------- 142721 471245 337573 737781 344857 685365 411697 931881 276581 687441 17149857 21769153 One session started for every channel Use Unix “ps” command to see process 2334

Instructor's Notes

(If applicable)

To help identify RMAN processes, use the SET COMMAND ID command to populate the CLIENT_INFO column of the V$SESSION view. By default, the active sessions as contained in V$PROCESS/V$SESSION might look like this:

SID SERIAL# OSID PROGRAM CLIENT_INFO
---- ---------- ----- ---------- ---------------
16 346 10392 RMAN.EXE
17 157 10394 RMAN.EXE
18 383 10396 RMAN.EXE rman channel=d1

The additional information identifying the jobs processes can be very helpful if the database is running multiple RMAN jobs. The OSID can also be useful to locate the operating system process (with the UNIX PS command) related to this RMAN process.
See the supplied script SET_COMMAND_ID.RMAN for this code.
Warning
- On my RMAN 9.2.0.4 Windows client, placing the SET command before the ALLOCATE command caused a fatal RMAN error on the client.

Other Text:
(Examples or comments displayed on slide, if any).

RMAN> run { 2> allocate channel d1 type disk; 3> set command id to 'dave test'; 4> backup tablespace users;} 1 select p.pid as sid, s.serial#, p.spid as osid, 2 s.program, s.client_info 3 from v$process p, v$session s 4 where p.addr = s.paddr 5* and (s.program like '%RMAN%' or s.program is null) SID SERIAL# OSID PROGRAM CLIENT_INFO ---------- ---------- ----- ---------- ----------------------------- 16 375 10338 RMAN.EXE id=daves test 17 147 10340 RMAN.EXE 18 341 10342 RMAN.EXE id=daves test,rman channel=d1 Helps identify processes OSID is the Linux process id

Instructor's Notes

(If applicable)

RMAN reports on its progress in the V$SESSION_LONGOPS view (specifically, this is the job of the “shadow” process started when an RMAN job is started). This example shows that by querying V$SESSION_LONGOPS while the job is active we can easily determine how far along the channel is in creating the current backup set. Keep in mind that a channel might finish one backup set, then start another. The percent complete reveals the percent complete on the current backup set.
In this example, SID 15, SERIAL# 383 is the channel (only one channel was allocated for this job). I not certain why RMAN also reports on SID 19, which will not reveal any obviously useful information.
By re-executing the query, we can see the progress – or lack of. If the SOFAR and “% Complete” values do not change, your job is waiting for something (perhaps a tape mount).
See Metalink Note: 144640.1 for more information on tracking the progress of RMAN operations.
See the supplied script V$SESSION_LONGOPS.SQL for a working sample of this code.

Other Text:
(Examples or comments displayed on slide, if any).

system@TEST> SELECT sid, serial#, context, sofar, totalwork, 2 round(sofar/totalwork*100,2) "% Complete" 3 FROM v$session_longops 4 WHERE totalwork != 0 5 AND sofar <> totalwork; SID SERIAL# CONTEXT SOFAR TOTALWORK % Complete ---------- ---------- ---------- ---------- ---------- ---------- 19 346 4 0 124960 0 15 383 1 49805 124960 39.86 system@TEST> / SID SERIAL# CONTEXT SOFAR TOTALWORK % Complete ---------- ---------- ---------- ---------- ---------- ---------- 19 346 4 0 124960 0 15 383 1 100063 124960 80.08 re-execute query Total for all channels if multiple channels are allocated

Instructor's Notes

(If applicable)

We see in this example the Oracle reports the wait event as “sbtbackup”. “sbtbackup” is a tape related event. I can deduct that, because I have not seen any progress for quite a while (see the previous page), and I have been waiting for 1006 seconds (just over 16 minutes), my job is waiting for a tape to be mounted.
Chapter 15 of the Oracle9i Recovery Manager User’s Guide lists all the possible tape-related events: sbtinit sbtopen sbtread sbtwrite sbtbackup.
Note that the meaning of the WAIT_TIME column can be counter-intuitive. The Oracle9i Database Reference contains this description of the column, which clears things up: “A nonzero value is the session's last wait time. A zero value means the session is currently waiting.” So, this is why I include “WHERE wait_time = 0” in the query.
See the supplied script V$SESSION_LONGOPS.SQL for a working sample of this code.

Other Text:
(Examples or comments displayed on slide, if any).

system@TEST> SELECT sid, seconds_in_wait AS sec_wait, event 2 FROM v$session_wait 3 WHERE wait_time = 0 4 ORDER BY sid; SID SEC_WAIT EVENT ---------- ---------- ------------------------------------- 1 82491 pmon timer . . . 12 1006 SQL*Net message from client 16 0 SQL*Net message from client 17 1006 imm op 18 1006 sbtbackup

Instructor's Notes

(If applicable)

Workshop – Monitoring Jobs
Perform a full backup of your database. Monitor the progress of the job with the supplied script V$SESSION_LONGOPS.SQL while the job is running.

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

RMAN operations (e.g. BACKUP, RESTORE) can be canceled by pressing the attention key from the RMAN client (CTRL+C on a Windows client).
With disk-based operations, this is a clean cancel. The RMAN client session ends and the RMAN processes (sessions) are terminated. If a backup job is canceled before the job completes a backup set, no output is created. Completed backup sets will remain – and in fact can be used in recovery operations (use the LIST BACKUPSET command to display available backupsets and the VALIDATE BACKUPSET command to determine if they can be used).
Under some tests, the only “hangover” is temporary: the information in V$SESSION_LONGOPS will remain for some period of time (I have not determined who cleans this up, but it eventually disappears – without restarting the database).
Important Note
Canceling RMAN jobs involving tapes is not always so clean. See the lesson Getting Started with Tapes for more information.

Other Text:
(Examples or comments displayed on slide, if any).

RMAN> run { 2> allocate channel t1 type sbt MAXOPENFILES 8 parms= 3> backup tag='test' tablespace ts6; } allocated channel: t1 channel t1: sid=17 devtype=SBT_TAPE channel t1: NMO v3.5.0.1 Starting backup at 29-NOV-03 . . . channel t1: starting piece 1 at 29-NOV-03 ^C C:\OracleScripts\RMAN> CTRL+C on Windows client terminates RMAN

Instructor's Notes

(If applicable)

Debug mode causes RMAN to externalize all calls to the RMAN packages – either at the RMAN console or in the log if the SPOOL LOG TO x command was used. The latter is preferred because of the volume of output you will receive. This might be useful for Oracle support or, if you are very motivated, to learn more about the way RMAN works.

Other Text:
(Examples or comments displayed on slide, if any).

C:\OracleScripts\RMAN>rman debug RMAN> backup tablespace order_tbs; DBGMISC: ENTERED krmice on [02/10/2004 14:49:49] DBGMISC: command to be compiled and executed is: spool DBGMISC: command after this command is: NONE (krmice) Spooling started in log file: debug.log Recovery Manager: Release 9.2.0.4.0 - Production DBGMISC: EXITED krmice on [02/10/2004 14:49:49]

Instructor's Notes

(If applicable)

Author’s Note
This section of the lesson – “Media Manager Debugging” – is intentionally repeated in the lesson “Getting Started with Tapes”. You may want (need) to cover the lesson Getting Started with Tapes – and these pages – later in this course.
Media management software is an additional piece of software – provided by Oracle (Oracle Secure Backup) or 3rd party vendors such as Legato or Veritas – required to backup to or restore from tape. (Refer to the lesson Getting Started with Tapes for more information.) If you are having trouble backing up to or restoring from tape, it can be very helpful to capture diagnostic (debugging) messages issued by the media manager software. How this is accomplished is specific to the software you have purchased. (Remember that Legato Single Server Version writes its log, by default, to /nsr/logs/daemon.log on the Legato server. (See the section “RMAN Messages” in this lesson.) This is the standard log – not the “debugging” log.)

Notes for this slide continue on the next page…

Other Text:
(Examples or comments displayed on slide, if any).

RMAN> run { 2> allocate channel t1 type sbt MAXOPENFILES 8; 3> send 'NSR_ENV=( NSR_CLIENT=beatles, 4> NSR_COMPRESSION=TRUE, 5> NSR_DEBUG=/opt/oracle/admin/test/udump)'; 6> set command id to 'dave test'; 7> backup tag='debug' tablespace ts1; } allocated channel: t1 channel t1: sid=17 devtype=SBT_TAPE channel t1: NMO v3.5.0.1 sent command to channel: t1 executing command: SET COMMAND ID Starting backup at 29-NOV-03

Instructor's Notes

(If applicable)

In my environment I use the Legato Single Server Version (LSSV). Turning on the LSSV debugging log is accomplished by using the RMAN SEND command. Specifically, as the example illustrates, I send NSR_DEBUG environment variable with the path for the log file to LSSV. The name of the LSSV log file is “sbtio.log”. An excerpt from an LSSV log is shown here:
[oracle@beatles udump]$ more sbtio.log
SBT-2776 11/19/2003 01:29:01 PM nwora_remove: Error removing ssid 28984882 from the media database:
nsrmm: RAP error: user oracle on machine beatles is not on administrator list

I received this error (SBT-2776) when I attempted to remove a tape catalog entry with an RMAN command (DELETE EXPIRED or DELETE OBSOLETE). LSSV reports that I need to add user “oracle” to the LSSV administrator list. (Note that the slide example is not the example that generated the log message shown here.)
See the supplied script “NSR_DEBUG.RMAN” for a working copy of this code.

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

In this lesson we discussed:

How to find and read RMAN messages

Use LOG parameter or SPOOL LOG TO command
Also see database Alert log
V$BACKUP_CORRUPTION

Reading RMAN message stacks – Read from the bottom up
Check status of jobs with V$SESSION_LONGOPS, V$SESSION, V$PROCESS (to see active jobs).
Using the SET COMMAND ID to help identify RMAN processes

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

In this lesson we discussed (continued):

Terminating Jobs wth Attention key (CRTL+C)
RMAN DEBUG option
Media manager Debugging – using the NSR_DEBUG environment variable for Legato

Other Text:
(Examples or comments displayed on slide, if any).

Instructor's Notes

(If applicable)

Workshop – Media Manager Debugging
If you have a tape device available to backup to, backup the USERS tablespace and create a media manager debugging log file. Compare the difference (if any, varies by product) between the standard log and the debugging log.

Other Text:
(Examples or comments displayed on slide, if any).