Hi Charlotte!
You can try rman with the debug flag. That should tell you where the
time is spent. Be aware, it's VERY verbose:
[oracle@callisto ~]$ rman target / debug
Recovery Manager: Release 12.2.0.1.0 - Production on Mon Nov 4 14:06:06 2019
Copyright (c) 1982, 2017, Oracle and/or its affiliates. All rights
reserved.
DBGMISC: ENTERED krmksimronly [14:06:06.744]
DBGSQL: CHANNEL> alter session set events '19737 trace name context
forever'
DBGSQL: sqlcode = 0
DBGSQL: CHANNEL> select decode(archiver, 'FAILED', 1, 0) into
:archstuck from v$instance
DBGSQL: sqlcode = 0
DBGSQL: D :archstuck = 0
DBGSQL: CHANNEL> alter session set events '19737 trace name context
off'
DBGSQL: sqlcode = 0
DBGMISC: EXITED krmksimronly [14:06:06.746] elapsed time
[00:00:00:00.002]
DBGSQL: CHANNEL> select sys_context('userenv', 'con_id'),
sys_context('userenv', 'cdb_name'), sys_context('userenv', 'con_name'),
case when sys_context('userenv', 'is_application_root') = 'YES' then 1
else 0 end into :pdbid, :cdbname, :pdbname, :approot from dual
DBGSQL: sqlcode = 0
DBGSQL: D :pdbid = 1
DBGSQL: D :cdbname = orcl
DBGSQL: D :pdbname = CDB$ROOT
DBGSQL: D :approot = 0
DBGMISC: ENTERED krmksimronly [14:06:06.784]
DBGMISC: EXITED krmksimronly [14:06:06.784] elapsed time
[00:00:00:00.000]
DBGSQL: CHANNEL> select sys_context('userenv', 'con_id'),
sys_context('userenv', 'cdb_name'), sys_context('userenv', 'con_name'),
case when sys_context('userenv', 'is_application_root') = 'YES' then 1
else 0 end into :pdbid, :cdbname, :pdbname, :approot from dual
DBGSQL: sqlcode = 0
DBGSQL: D :pdbid = 1
DBGSQL: D :cdbname = orcl
DBGSQL: D :pdbname = CDB$ROOT
DBGSQL: D :approot = 0
DBGMISC: ENTERED krmkgetdb [14:06:06.809]
DBGRPC: krmxcc - entering
DBGRPC: krmxcc - creating context for channel No-chid
DBGRPC: krmxcc - connecting using target default channel
DBGRPC: krmxcc - seting up for out-of-band
DBGRPC: krmxpos - setting up channel No-chid
DBGRPC: krmxpos - creating polling channel for channel No-chid
DBGMISC: ENTERED krmksimronly [14:06:06.845]
DBGMISC: EXITED krmksimronly [14:06:06.845] elapsed time
[00:00:00:00.000]
DBGSQL: CHANNEL> select sys_context('userenv', 'con_id'),
sys_context('userenv', 'cdb_name'), sys_context('userenv', 'con_name'),
case when sys_context('userenv', 'is_application_root') = 'YES' then 1
else 0 end into :pdbid, :cdbname, :pdbname, :approot from dual
DBGSQL: sqlcode = 0
DBGSQL: D :pdbid = 1
DBGSQL: D :cdbname = orcl
DBGSQL: D :pdbname = CDB$ROOT
DBGSQL: D :approot = 0
DBGRPC: krmxpos - channel No-chid polling channel created to instance 1
DBGRPC: krmxcc - using default sga_heap_size of 16777216
DBGRPC: krmxcc - created context for channel No-chid
DBGMISC: krmqopen: opening new channel context for channel default,
instid 1 [14:06:06.859]
DBGRPC: krmxcr - channel default resetted
DBGSQL: TARGET> select decode(open_mode, 'MOUNTED', 0, 'READ
WRITE', 1, 'READ ONLY', 1, 'READ ONLY WITH APPLY', 1, 0) into :isdbopen
from v$database
DBGSQL: sqlcode = 0
DBGSQL: D :isdbopen = 1
DBGMISC: krmqacen() [14:06:07.254]
DBGMISC: krmqacen() : Exit [14:06:07.254]
DBGRPC: krmxcd - removing context for channel default, keep=0
DBGRPC: krmxcd - closing target default connection
DBGMISC: ENTERED krmkmrsr [14:06:07.255]
DBGMISC: EXITED krmkmrsr [14:06:07.255] elapsed time [00:00:00:00.000]
DBGRPC: krmxpoc - clearing channel default
DBGRPC: krmxpocx - cleaning polling context for channel default
DBGRPC: krmxpocx - cleaning target polling channel
DBGRPC: krmxpocx - closing the cursor
DBGRPC: krmxpocx - logging off from oracle
DBGRPC: krmxpocx - freeing krmxpon
DBGRPC: krmxpocx - target polling channel cleaned up
DBGRPC: krmxpoc - channel default, freeing polling context
DBGRPC: krmxcd - disconnecting
DBGMISC: ENTERED krmksimronly [14:06:07.256]
DBGMISC: EXITED krmksimronly [14:06:07.256] elapsed time
[00:00:00:00.000]
DBGRPC: krmxcd - context removed
DBGMISC: ENTERED krmksimronly [14:06:07.294]
DBGMISC: EXITED krmksimronly [14:06:07.294] elapsed time
[00:00:00:00.000]
DBGSQL: CHANNEL> select sys_context('userenv', 'con_id'),
sys_context('userenv', 'cdb_name'), sys_context('userenv', 'con_name'),
case when sys_context('userenv', 'is_application_root') = 'YES' then 1
else 0 end into :pdbid, :cdbname, :pdbname, :approot from dual
DBGSQL: sqlcode = 0
DBGSQL: D :pdbid = 1
DBGSQL: D :cdbname = orcl
DBGSQL: D :pdbname = CDB$ROOT
DBGSQL: D :approot = 0
DBGMISC: ENTERED krmksimronly [14:06:07.331]
DBGMISC: EXITED krmksimronly [14:06:07.331] elapsed time
[00:00:00:00.000]
DBGSQL: CHANNEL> select sys_context('userenv', 'con_id'),
sys_context('userenv', 'cdb_name'), sys_context('userenv', 'con_name'),
case when sys_context('userenv', 'is_application_root') = 'YES' then 1
else 0 end into :pdbid, :cdbname, :pdbname, :approot from dual
DBGSQL: sqlcode = 0
DBGSQL: D :pdbid = 1
DBGSQL: D :cdbname = orcl
DBGSQL: D :pdbname = CDB$ROOT
DBGSQL: D :approot = 0
DBGMISC: ENTERED krmkcrsr [14:06:07.356]
DBGRPC: krmxcc - entering
DBGRPC: krmxcc - creating context for channel No-chid
DBGRPC: krmxcc - connecting using target default channel
DBGRPC: krmxcc - seting up for out-of-band
DBGRPC: krmxpos - setting up channel No-chid
DBGRPC: krmxpos - creating polling channel for channel No-chid
DBGMISC: ENTERED krmksimronly [14:06:07.391]
DBGMISC: EXITED krmksimronly [14:06:07.391] elapsed time
[00:00:00:00.000]
DBGSQL: CHANNEL> select sys_context('userenv', 'con_id'),
sys_context('userenv', 'cdb_name'), sys_context('userenv', 'con_name'),
case when sys_context('userenv', 'is_application_root') = 'YES' then 1
else 0 end into :pdbid, :cdbname, :pdbname, :approot from dual
DBGSQL: sqlcode = 0
DBGSQL: D :pdbid = 1
DBGSQL: D :cdbname = orcl
DBGSQL: D :pdbname = CDB$ROOT
DBGSQL: D :approot = 0
DBGRPC: krmxpos - channel No-chid polling channel created to
instance 1
DBGRPC: krmxcc - using default sga_heap_size of 16777216
DBGRPC: krmxcc - created context for channel No-chid
DBGMISC: krmqopen: opening new channel context for channel default,
instid 1 [14:06:07.405]
DBGRPC: krmxcr - channel default resetted
DBGSQL: TARGET> select decode(status, 'OPEN', 1, 0),
decode(archiver, 'FAILED', 1, 0), decode(database_status, 'SUSPENDED',
1, 0) into :status, :archstuck, :dbsuspended from v$instance
DBGSQL: sqlcode = 0
DBGSQL: D :status = 1
DBGSQL: D :archstuck = 0
DBGSQL: D :dbsuspended = 0
DBGSQL: TARGET> select decode(open_mode, 'READ WRITE', 1, 0) into
:read_write from v$database
DBGSQL: sqlcode = 0
DBGSQL: D :read_write = 1
DBGSQL: TARGET> select value into :vcomp_txt from v$parameter
where name = 'compatible'
DBGSQL: sqlcode = 0
DBGSQL: D :vcomp_txt = 12.2.0
DBGSQL: TARGET> declare dot1st number; dot2nd number; dot3rd
number; comptxt varchar2(255) := :vcomp_txt; begin comptxt := comptxt ||
'.0.0'; dot1st := instr(comptxt, '.', 1, 1); dot2nd := instr(comptxt,
'.', 1, 2); dot3rd := instr(comptxt, '.', 1, 3); comptxt :=
lpad(substr(comptxt, 1, dot1st - 1), 2, '0') || lpad(substr(comptxt,
dot1st + 1, dot2nd - dot1st - 1), 2, '0') || lpad(substr(comptxt,
dot2nd + 1, dot3rd - dot2nd - 1), 2, '0');:vcomp_ub4 :=
to_number(comptxt); end;
DBGSQL: sqlcode = 0
DBGSQL: B :vcomp_ub4 = 120200
DBGSQL: B :vcomp_txt = 12.2.0
DBGMISC: krmkpdbs(): vcomp_txt:12.2.0 vcomp_ub4:120200 flags:5
[14:06:07.797]
DBGSQL: TARGET> begin :vsn_min :=
dbms_backup_restore.protocol_version_number_min; :rel_min :=
dbms_backup_restore.protocol_release_number_min; :upd_min :=
dbms_backup_restore.protocol_update_number_min; :cmp_min := 0; :vsn_max
:= dbms_backup_restore.protocol_version_number_max; :rel_max :=
dbms_backup_restore.protocol_release_number_max; :upd_max :=
dbms_backup_restore.protocol_update_number_max; :cmp_max := 0; :pkg_vsn
:= to_char(:vsn_max, 'fm00')||'.'|| to_char(:rel_max, 'fm00')||'.'||
to_char(:upd_max, 'fm00')||'.'|| to_char(:cmp_max, 'fm00'); end;
DBGSQL: sqlcode = 0
DBGSQL: B :vsn_min = 8
DBGSQL: B :rel_min = 0
DBGSQL: B :upd_min = 4
DBGSQL: B :cmp_min = 0
DBGSQL: B :vsn_max = 12
DBGSQL: B :rel_max = 2
DBGSQL: B :upd_max = 0
DBGSQL: B :cmp_max = 0
DBGSQL: B :pkg_vsn = 12.02.00.00
DBGSQL: TARGET> begin :cmp_min :=
dbms_backup_restore.protocol_component_number_min; :cmp_max :=
dbms_backup_restore.protocol_component_number_max; :pkg_vsn :=
to_char(:vsn_max, 'fm00')||'.'|| to_char(:rel_max, 'fm00')||'.'||
to_char(:upd_max, 'fm00')||'.'|| to_char(:cmp_max, 'fm00'); end;
DBGSQL: sqlcode = 0
DBGSQL: B :cmp_min = 0
DBGSQL: B :cmp_max = 1
DBGSQL: B :pkg_vsn = 12.02.00.01
DBGSQL: B :vsn_max = 12
DBGSQL: B :rel_max = 2
DBGSQL: B :upd_max = 0
DBGSQL: B :cmp_max = 1
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 08.00.04.00
DBGSQL: B :pkg_vsnub4 = 8000400
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 08.00.05.00
DBGSQL: B :pkg_vsnub4 = 8000500
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 08.01.03.00
DBGSQL: B :pkg_vsnub4 = 8010300
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 08.01.05.00
DBGSQL: B :pkg_vsnub4 = 8010500
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 08.01.06.00
DBGSQL: B :pkg_vsnub4 = 8010600
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 08.01.07.00
DBGSQL: B :pkg_vsnub4 = 8010700
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 09.00.00.00
DBGSQL: B :pkg_vsnub4 = 9000000
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 09.02.00.00
DBGSQL: B :pkg_vsnub4 = 9020000
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 10.01.00.00
DBGSQL: B :pkg_vsnub4 = 10010000
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 10.02.00.00
DBGSQL: B :pkg_vsnub4 = 10020000
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 10.02.00.01
DBGSQL: B :pkg_vsnub4 = 10020001
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.00
DBGSQL: B :pkg_vsnub4 = 11010000
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.01
DBGSQL: B :pkg_vsnub4 = 11010001
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.02
DBGSQL: B :pkg_vsnub4 = 11010002
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.03
DBGSQL: B :pkg_vsnub4 = 11010003
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.04
DBGSQL: B :pkg_vsnub4 = 11010004
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.05
DBGSQL: B :pkg_vsnub4 = 11010005
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.06
DBGSQL: B :pkg_vsnub4 = 11010006
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.01.00.07
DBGSQL: B :pkg_vsnub4 = 11010007
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.02.00.00
DBGSQL: B :pkg_vsnub4 = 11020000
DBGSQL: TARGET> declare vsn varchar2(20); begin vsn :=
dbms_rcvman.getPackageVersion; :pkg_vsn := vsn; if vsn is not null then
:pkg_vsnub4 := to_number(substr(vsn,1,2) || substr(vsn,4,2) ||
substr(vsn,7,2) || nvl(substr(vsn,10,2),'00')); end if; end;
DBGSQL: sqlcode = 0
DBGSQL: B :pkg_vsn = 11.02.00.01
DBGSQL: B :pkg_vsnub4 = 11020001
And that is just connect. This should make it possible to see where the
time is spent. An alternative would be to connect and then activate the
trace in your connection. Which backup suite are you using?
Regards
On 11/4/19 9:22 AM, Charlotte Hammond (Redacted sender
charlottejanehammond for DMARC) wrote:
Hello All,
I'm trying to explain why my level 0 rman backups have suddenly jumped from 8hours to 12 hours. The size of the backup has barely changed and there has been no configuration changes. AWR and O/S statistics show that CPU for all the channels are maxed out at ~99% (presumably backup compression) for most of this time, both in the 8 hour case and 12 hour case. The server itself has no other activity during the backup window.
This is on 11.2.0.4 on AWS EC2 backing up to S3 storage.
I'm not looking for tuning advise here (thanks though!) - I'm really hoping for some advise on finding an explanation for the change in times. Given that all it's doing is sitting on CPU I'm not sure what else I can investigate - especially with limited ability to cross-reference it with the "good old" runs. It's been 8 hours for months and months, and has now been 12 hours for the last 3 weeks. There was no gradual increase - just a step change.
Thanks!
Charlotte