Forum Stats

  • 3,824,755 Users
  • 2,260,414 Discussions
  • 7,896,306 Comments

Discussions

V$RMAN_BACKUP_JOB_DETAILS.START_TIME does not match with RMAN backup execution log

Mauro Guerra
Mauro Guerra Member Posts: 3
edited Jan 6, 2020 12:37PM in Recovery Manager (RMAN)

Hello,

A few days ago I have noticed an inconsistency between the timing of my scheduled backups on oracle user crontab, rman execution log and the information present in the view v$rman_backup_job_details in regular queries I perform.

Apparently the difference is between 1 or 2 hours, it occurs on random backups intermittently and is impacting my daily generated reports.

Below is an example of the case that is occurring in one of my databases:

My script scheduled on crontab to run daily at 3:00 am:

#!/bin/bash

. /home/oracle/.bash_profile

#rman script

#rman dir

rmandir=/Backup/rman

#log dir

log=/Backup/rman/log

#rman script

full=$rmandir/full.rmn

rman  target / @$full LOG $log/rmanlog_full_`date +"%Y_%m_%d_%T"`.out

Backup Script:

run {

backup as compressed backupset incremental level 0 database tag 'inc0-diario';

}

exit;

RMAN log output:

Recovery Manager: Release 11.2.0.3.0 - Production on Wed Jan 1 03:00:01 2020

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

connected to target database: NBPT00 (DBID=1235598201)

RMAN> run {

2> backup as compressed backupset incremental level 0 database tag 'inc0-diario';

3> }

4> exit;

Starting backup at 01-JAN-20

using target database control file instead of recovery catalog

allocated channel: ORA_DISK_1

channel ORA_DISK_1: SID=1504 device type=DISK

allocated channel: ORA_DISK_2

channel ORA_DISK_2: SID=273 device type=DISK

channel ORA_DISK_1: starting compressed incremental level 0 datafile backup set

channel ORA_DISK_1: specifying datafile(s) in backup set

input datafile file number=00012 name=+DATA/nbpt00/datafile/part_indexes.273.866665557

input datafile file number=00014 name=+DATA/nbpt00/datafile/part_tables.259.879678583

input datafile file number=00016 name=+DATA/nbpt00/datafile/part_tables.278.882443347

input datafile file number=00018 name=+DATA/nbpt00/datafile/part_indexes.280.882443653

input datafile file number=00020 name=+DATA/nbpt00/datafile/part_indexes.282.887744845

input datafile file number=00022 name=+DATA/nbpt00/datafile/part_indexes.284.894452139

input datafile file number=00024 name=+DATA/nbpt00/datafile/part_tables.286.894452751

input datafile file number=00011 name=+DATA/nbpt00/datafile/part_tables.272.866665487

input datafile file number=00005 name=+DATA/nbpt00/datafile/medium_tables.266.866665069

input datafile file number=00007 name=+DATA/nbpt00/datafile/small_tables.268.866665207

input datafile file number=00009 name=+DATA/nbpt00/datafile/big_tables.270.866665347

input datafile file number=00002 name=+DATA/nbpt00/datafile/sysaux.261.866662867

input datafile file number=00004 name=+DATA/nbpt00/datafile/users.264.866662877

channel ORA_DISK_1: starting piece 1 at 01-JAN-20

channel ORA_DISK_2: starting compressed incremental level 0 datafile backup set

channel ORA_DISK_2: specifying datafile(s) in backup set

input datafile file number=00013 name=+DATA/nbpt00/datafile/part_tables.258.879678439

input datafile file number=00015 name=+DATA/nbpt00/datafile/part_indexes.257.879678729

input datafile file number=00017 name=+DATA/nbpt00/datafile/part_tables.279.882443497

input datafile file number=00019 name=+DATA/nbpt00/datafile/part_indexes.281.882443805

input datafile file number=00021 name=+DATA/nbpt00/datafile/part_indexes.283.887745015

input datafile file number=00023 name=+DATA/nbpt00/datafile/part_indexes.285.894452403

input datafile file number=00025 name=+DATA/nbpt00/datafile/part_tables.287.894452939

input datafile file number=00001 name=+DATA/nbpt00/datafile/system.260.866662863

input datafile file number=00003 name=+DATA/nbpt00/datafile/undotbs1.262.866662871

input datafile file number=00006 name=+DATA/nbpt00/datafile/medium_indexes.267.866665139

input datafile file number=00008 name=+DATA/nbpt00/datafile/small_indexes.269.866665277

input datafile file number=00010 name=+DATA/nbpt00/datafile/big_indexes.271.866665419

channel ORA_DISK_2: starting piece 1 at 01-JAN-20

channel ORA_DISK_2: finished piece 1 at 01-JAN-20

piece handle=/Backup/rman/NBPT00/backupset/2020_01_01/o1_mf_nnnd0_INC0_DIARIO_h0rfc4sr_.bkp tag=INC0-DIARIO comment=NONE

channel ORA_DISK_2: backup set complete, elapsed time: 00:31:15

channel ORA_DISK_1: finished piece 1 at 01-JAN-20

piece handle=/Backup/rman/NBPT00/backupset/2020_01_01/o1_mf_nnnd0_INC0_DIARIO_h0rfc48o_.bkp tag=INC0-DIARIO comment=NONE

channel ORA_DISK_1: backup set complete, elapsed time: 00:39:25

Finished backup at 01-JAN-20

Starting Control File and SPFILE Autobackup at 01-JAN-20

piece handle=/Backup/rman/NBPT00/autobackup/2020_01_01/o1_mf_s_1028518769_h0rho225_.bkp comment=NONE

Finished Control File and SPFILE Autobackup at 01-JAN-20

Recovery Manager complete.

The result of V$RMAN_BACKUP_JOB_DETAILS query:

SQL> set linesize 500 pagesize 2000

col Hours format 9999.99

col STATUS format a10

select SESSION_KEY, INPUT_TYPE, OUTPUT_DEVICE_TYPE, STATUS,

to_char(START_TIME,'mm-dd-yyyy hh24:mi:ss') as RMAN_Bkup_start_time,

to_char(END_TIME,'mm-dd-yyyy hh24:mi:ss') as RMAN_Bkup_end_time,

elapsed_seconds/3600 Hours from V$RMAN_BACKUP_JOB_DETAILS

order by session_key desc;

pastedImage_0.png

RMAN Configuration:

Recovery Manager: Release 11.2.0.3.0 - Production on Thu Jan 2 15:43:56 2020

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

connected to target database: NBPT00 (DBID=1235598201)

RMAN> show all;

using target database control file instead of recovery catalog

RMAN configuration parameters for database with db_unique_name NBPT00 are:

CONFIGURE RETENTION POLICY TO REDUNDANCY 2;

CONFIGURE BACKUP OPTIMIZATION ON;

CONFIGURE DEFAULT DEVICE TYPE TO DISK; # default

CONFIGURE CONTROLFILE AUTOBACKUP ON;

CONFIGURE CONTROLFILE AUTOBACKUP FORMAT FOR DEVICE TYPE DISK TO '%F'; # default

CONFIGURE DEVICE TYPE DISK BACKUP TYPE TO COMPRESSED BACKUPSET PARALLELISM 2;

CONFIGURE DATAFILE BACKUP COPIES FOR DEVICE TYPE DISK TO 1; # default

CONFIGURE ARCHIVELOG BACKUP COPIES FOR DEVICE TYPE DISK TO 1; # default

CONFIGURE MAXSETSIZE TO UNLIMITED; # default

CONFIGURE ENCRYPTION FOR DATABASE OFF; # default

CONFIGURE ENCRYPTION ALGORITHM 'AES128'; # default

CONFIGURE COMPRESSION ALGORITHM 'BASIC' AS OF RELEASE 'DEFAULT' OPTIMIZE FOR LOAD TRUE ; # default

CONFIGURE ARCHIVELOG DELETION POLICY TO NONE; # default

CONFIGURE SNAPSHOT CONTROLFILE NAME TO '/u01/app/oracle/product/11.2.0/dbhome_1/dbs/snapcf_NBPT00.f'; # default

RMAN>

So I searched in various places including MOS for some information that could clarify this doubt but I was unsuccessful.

I thank you all in advance for your attention.

Mauro Guerra

Answers

  • Joerg.Sobottka
    Joerg.Sobottka Senior Consultant and Oracle Ace Member Posts: 597 Bronze Trophy
    edited Jan 2, 2020 3:38PM

    Hi,

    could it be that you have any timezone difference in the settings for SQL/RMAN? Different systems, different environments, different NLS settings?

    As you said, it is sometimes 1hour and sometimes 2 hours difference, sounds like daylight saving.

    Maybe you can set all sytems to GMT or CET and then compare the values?

    Regards

    Jörg

    Mauro Guerra
  • Adityanath Dewoolkar
    Adityanath Dewoolkar Member Posts: 346 Bronze Badge
    edited Jan 6, 2020 6:36AM

    Hello,

    Check if the following MOS notes help you:

    Difference in Log Time for Clusterware/Database Instance Alert Log Compare to Server Time (Doc ID 2312945.1)

    Regards,

    Adi

    Mauro GuerraMauro Guerra
  • Mauro Guerra
    Mauro Guerra Member Posts: 3
    edited Jan 6, 2020 12:37PM

    Adi, thanks! I didn't pay attention to the time in the alert.log of the databases.

    The only question I still have is not knowing why the information is written to the table v$_rman_backup_job_details inconsistently.

    For example, the same record from the same backup that I reported at the beginning of this conversation today is stating the correct scheduled execution time and, as it is intermittent, will probably be logged incorrectly sometime next.

    This intermittence that is driving me crazy about this subject. xD

    Again, thank you very much!