Re: Sudden Backup Slowdown

  • From: Mladen Gogala <gogala.mladen@xxxxxxxxx>
  • To: oracle-l@xxxxxxxxxxxxx
  • Date: Mon, 4 Nov 2019 14:12:37 -0500

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


Other related posts: