1

we have a SAP instance that runs on Oracle 11.2.0.4.0 DB. Since a while full online backups are failing every time. Full online backups are scheduled in SAP tcode DB13 (or DBACOCKPIT) and use BR*Tools (BRBACKUP) to execute the full backup every Sat at 22:00. The backup reaches ~93% and then fails with the following log error:

BR0280I BRBACKUP time stamp: 2018-07-22 23.34.45
BR0301E SQL error -1146 at location BrTspBackAlter-3, SQL statement:
'/* BRBACKUP */ ALTER TABLESPACE "PSAPUNDO" BEGIN BACKUP'
ORA-01146: cannot start online backup - file 3 is already in backup
ORA-01110: data file 3: 'G:\ORACLE\BWP\SAPDATA2\UNDO_1\UNDO.DATA1'
BR0280I BRBACKUP time stamp: 2018-07-22 23.34.45
BR0316E 'Alter tablespace PSAPUNDO begin backup' failed

When we investigated the Oracle alert log, we found out that since a certain time in the past, the following ALTER TABLESPACE % BEGIN/END BACKUP commands are run every 4:30 hours:

Beginning log switch checkpoint up to RBA [0x2c0ce.2.10], SCN: 3437554174
Thread 1 advanced to log sequence 180430 (LGWR switch)
  Current log# 2 seq# 180430 mem# 0: G:\ORACLE\BWP\ORIGLOGB\LOG_G12M1.DBF
  Current log# 2 seq# 180430 mem# 1: G:\ORACLE\BWP\MIRRLOGB\LOG_G12M2.DBF
Archived Log entry 176451 added for thread 1 sequence 180429 ID 0xa9e620d2 dest 1:
Beginning global checkpoint up to RBA [0x2c0ce.2f.10], SCN: 3437554234
Completed checkpoint up to RBA [0x2c0ce.2f.10], SCN: 3437554234
ALTER SYSTEM ARCHIVE LOG
Completed checkpoint up to RBA [0x2c0ce.2.10], SCN: 3437554174
Beginning log switch checkpoint up to RBA [0x2c0cf.2.10], SCN: 3437554243
Thread 1 advanced to log sequence 180431 (LGWR switch)
  Current log# 3 seq# 180431 mem# 0: G:\ORACLE\BWP\ORIGLOGA\LOG_G13M1.DBF
  Current log# 3 seq# 180431 mem# 1: G:\ORACLE\BWP\MIRRLOGA\LOG_G13M2.DBF
Archived Log entry 176452 added for thread 1 sequence 180430 ID 0xa9e620d2 dest 1:
ALTER TABLESPACE SYSTEM BEGIN BACKUP
Completed: ALTER TABLESPACE SYSTEM BEGIN BACKUP
ALTER TABLESPACE SYSAUX BEGIN BACKUP
Completed: ALTER TABLESPACE SYSAUX BEGIN BACKUP
ALTER TABLESPACE PSAPUNDO BEGIN BACKUP
Completed checkpoint up to RBA [0x2c0cf.2.10], SCN: 3437554243
Completed: ALTER TABLESPACE PSAPUNDO BEGIN BACKUP
ALTER TABLESPACE PSAPBWP BEGIN BACKUP
Completed: ALTER TABLESPACE PSAPBWP BEGIN BACKUP
ALTER TABLESPACE PSAPBWP640 BEGIN BACKUP
Completed: ALTER TABLESPACE PSAPBWP640 BEGIN BACKUP
ALTER TABLESPACE PSAPBWPUSR BEGIN BACKUP
Completed: ALTER TABLESPACE PSAPBWPUSR BEGIN BACKUP
ALTER TABLESPACE PSAPBWP702 BEGIN BACKUP
Completed: ALTER TABLESPACE PSAPBWP702 BEGIN BACKUP
ALTER TABLESPACE SYSTEM END BACKUP
Completed: ALTER TABLESPACE SYSTEM END BACKUP
ALTER TABLESPACE SYSAUX END BACKUP
Completed: ALTER TABLESPACE SYSAUX END BACKUP
ALTER TABLESPACE PSAPUNDO END BACKUP
Completed: ALTER TABLESPACE PSAPUNDO END BACKUP
ALTER TABLESPACE PSAPBWP END BACKUP
Completed: ALTER TABLESPACE PSAPBWP END BACKUP
ALTER TABLESPACE PSAPBWP640 END BACKUP
Completed: ALTER TABLESPACE PSAPBWP640 END BACKUP
ALTER TABLESPACE PSAPBWPUSR END BACKUP
Completed: ALTER TABLESPACE PSAPBWPUSR END BACKUP
ALTER TABLESPACE PSAPBWP702 END BACKUP
Completed: ALTER TABLESPACE PSAPBWP702 END BACKUP
ALTER SYSTEM ARCHIVE LOG
Beginning log switch checkpoint up to RBA [0x2c0d0.2.10], SCN: 3437555050
Thread 1 advanced to log sequence 180432 (LGWR switch)
  Current log# 4 seq# 180432 mem# 0: G:\ORACLE\BWP\ORIGLOGB\LOG_G14M1.DBF
  Current log# 4 seq# 180432 mem# 1: G:\ORACLE\BWP\MIRRLOGB\LOG_G14M2.DBF
Archived Log entry 176453 added for thread 1 sequence 180431 ID 0xa9e620d2 dest 1:

So when we initiate a full backup in Sat 22:00, it starts successfully by putting PSAPBWP tablespace in backup mode:

Sat Jul 21 22:00:14 2018
/* BRBACKUP */ ALTER DATABASE BACKUP CONTROLFILE TO 'G:\oracle\BWP\sapbackup\CNTRLBWP.DBF'
Completed: /* BRBACKUP */ ALTER DATABASE BACKUP CONTROLFILE TO 'G:\oracle\BWP\sapbackup\CNTRLBWP.DBF'
Sat Jul 21 22:00:17 2018
/* BRBACKUP */ ALTER TABLESPACE "PSAPBWP" BEGIN BACKUP
Completed: /* BRBACKUP */ ALTER TABLESPACE "PSAPBWP" BEGIN BACKUP
Sat Jul 21 22:28:43 2018
Incremental checkpoint up to RBA [0x3656b.3c45.0], current log tail at RBA [0x3656b.3ead.0]
Sat Jul 21 22:58:49 2018
Incremental checkpoint up to RBA [0x3656b.4fc1.0], current log tail at RBA [0x3656b.5241.0]
Sat Jul 21 23:28:55 2018
Incremental checkpoint up to RBA [0x3656b.7a63.0], current log tail at RBA [0x3656b.7ce8.0]
Sat Jul 21 23:59:01 2018
Incremental checkpoint up to RBA [0x3656b.8a41.0], current log tail at RBA [0x3656b.8cac.0]
Sun Jul 22 00:29:39 2018
Incremental checkpoint up to RBA [0x3656b.cc7e.0], current log tail at RBA [0x3656b.cefa.0]
Sun Jul 22 00:30:26 2018
Beginning log switch checkpoint up to RBA [0x3656c.2.10], SCN: 5314576207
Thread 1 advanced to log sequence 222572 (LGWR switch)
  Current log# 4 seq# 222572 mem# 0: G:\ORACLE\BWP\ORIGLOGB\LOG_G14M1.DBF
  Current log# 4 seq# 222572 mem# 1: G:\ORACLE\BWP\MIRRLOGB\LOG_G14M2.DBF

...and then continues backing up files. At some point, the ALTER TABLESPACE% commands are initiated and one of them fails:

Sun Jul 22 01:59:58 2018
Beginning log switch checkpoint up to RBA [0x36571.2.10], SCN: 5314602626
Thread 1 advanced to log sequence 222577 (LGWR switch)
  Current log# 1 seq# 222577 mem# 0: G:\ORACLE\BWP\ORIGLOGA\LOG_G11M1.DBF
  Current log# 1 seq# 222577 mem# 1: G:\ORACLE\BWP\MIRRLOGA\LOG_G11M2.DBF
Archived Log entry 218598 added for thread 1 sequence 222576 ID 0xa9e620d2 dest 1:
Beginning global checkpoint up to RBA [0x36571.2.10], SCN: 5314602627
Completed checkpoint up to RBA [0x36571.2.10], SCN: 5314602627
ALTER SYSTEM ARCHIVE LOG
Completed checkpoint up to RBA [0x36571.2.10], SCN: 5314602626
Beginning log switch checkpoint up to RBA [0x36572.2.10], SCN: 5314602631
Thread 1 advanced to log sequence 222578 (LGWR switch)
  Current log# 2 seq# 222578 mem# 0: G:\ORACLE\BWP\ORIGLOGB\LOG_G12M1.DBF
  Current log# 2 seq# 222578 mem# 1: G:\ORACLE\BWP\MIRRLOGB\LOG_G12M2.DBF
Archived Log entry 218599 added for thread 1 sequence 222577 ID 0xa9e620d2 dest 1:
ALTER TABLESPACE SYSTEM BEGIN BACKUP
Completed checkpoint up to RBA [0x36572.2.10], SCN: 5314602631
Completed: ALTER TABLESPACE SYSTEM BEGIN BACKUP
ALTER TABLESPACE SYSAUX BEGIN BACKUP
Completed: ALTER TABLESPACE SYSAUX BEGIN BACKUP
ALTER TABLESPACE PSAPUNDO BEGIN BACKUP
Completed: ALTER TABLESPACE PSAPUNDO BEGIN BACKUP
ALTER TABLESPACE PSAPBWP BEGIN BACKUP
ORA-1146 signalled during: ALTER TABLESPACE PSAPBWP BEGIN BACKUP...
Sun Jul 22 02:00:00 2018
Closing scheduler window
Closing Resource Manager plan via scheduler window
Clearing Resource Manager plan via parameter

The system puts SYSTEM, SUSAUX and PSAPUNDO tablespaces in backup mode, but fails when trying to do so with PSAPBWP as it's already being backed up by the full backup job. As a result, these 3 tablespaces remain in backup mode and when the full backup job tries to back them up, it fails:

Sun Jul 22 23:15:04 2018
Checker run found 2 new persistent data failures
Sun Jul 22 23:34:21 2018
/* BRBACKUP */ ALTER TABLESPACE "PSAPBWP702" END BACKUP
Completed: /* BRBACKUP */ ALTER TABLESPACE "PSAPBWP702" END BACKUP
/* BRBACKUP */ ALTER TABLESPACE "PSAPBWPUSR" BEGIN BACKUP
Completed: /* BRBACKUP */ ALTER TABLESPACE "PSAPBWPUSR" BEGIN BACKUP
Sun Jul 22 23:34:45 2018
/* BRBACKUP */ ALTER TABLESPACE "PSAPBWPUSR" END BACKUP
Completed: /* BRBACKUP */ ALTER TABLESPACE "PSAPBWPUSR" END BACKUP
/* BRBACKUP */ ALTER TABLESPACE "PSAPUNDO" BEGIN BACKUP
ORA-1146 signalled during: /* BRBACKUP */ ALTER TABLESPACE "PSAPUNDO" BEGIN BACKUP...

Full online backups were pretty fine before. At some point, however, something happened and the colleague who was in charge of this, doesn't remember anything particular. The fact is that we can't get the DB backed up because of this situation. Checked for scheduled DBA jobs in SAP (SM37) and in Oracle itself, but got nothing there - no jobs defined. The question is why are those ALTER TABLESPACE % BEGIN/END BACKUP commands running every 4 and a half hours? Are they part of some system maintenance? How to stop them or at least make them not interfere with the BRBACKUP job?

Improve this question
4
  • 2
    Sounds like the length of time required for the full backup has been creeping up over time, and you hit a point where it's taking longer the 4.5 hours, thus running afoul of the ALTER TABLESPACE command. Can't say if the command should or shouldn't be there, but it might suffice for now to change that job to run (say) every 5.5 hours.
    – RDFozz
    Commented Jul 24, 2018 at 16:31
  • The weird part is that ALTER TABLESPACE commands do not run under any job, that we have defined. There is no DBA job that runs every 4.5 hours - neither in SAP, nor in Oracle. This means I can't play with the job schedule time - it seems like some internal Oracle maintenance, but started running some time ago. For more than 3 years that DB had no issues at all.
    – plamenbv
    Commented Jul 24, 2018 at 18:33
  • 1
    Seems like a good time to switch from SAP's backups to using RMAN.
    – Mark Stewart
    Commented Jul 24, 2018 at 19:50
  • Maybe it is - will check what SAP docs say. But anyway - if there is something going wrong with Oracle DB, will RMAN just solve our problems? Can't understand why the DB executes BEGIN BACKUP and right after it END BACKUP for all the tablespaces? Also why the ALTER SYSTEM ARCHIVE LOG command?
    – plamenbv
    Commented Jul 24, 2018 at 20:16

1 Answer 1

Reset to default
-1

This is probably due to the Oracle VSS writer. (possibly snapshot as part of an OS backup?) Examine the Windows ApplicationLog for "VSS-00048: failed to put the datafile into backup mode".

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.