Re: Sudden Backup Slowdown

From: Mladen Gogala <gogala.mladen_at_gmail.com>
Date: Mon, 4 Nov 2019 14:12:37 -0500
Message-ID: <2f0abadb-a1d5-d8fd-510a-5e3819d856af_at_gmail.com>

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_at_callisto ~]$ rman target / debug

Recovery Manager: Release 12.2.0.1.0 - Production on Mon Nov 4 14:06:06 2019

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:        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:         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:         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:         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:          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:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 08.00.05.00
DBGSQL:           B :pkg_vsnub4 = 8000500

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 08.01.03.00
DBGSQL:           B :pkg_vsnub4 = 8010300

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 08.01.05.00
DBGSQL:           B :pkg_vsnub4 = 8010500

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 08.01.06.00
DBGSQL:           B :pkg_vsnub4 = 8010600

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 08.01.07.00
DBGSQL:           B :pkg_vsnub4 = 8010700

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 09.00.00.00
DBGSQL:           B :pkg_vsnub4 = 9000000

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 09.02.00.00
DBGSQL:           B :pkg_vsnub4 = 9020000

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 10.01.00.00
DBGSQL:           B :pkg_vsnub4 = 10010000

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 10.02.00.00
DBGSQL:           B :pkg_vsnub4 = 10020000

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 10.02.00.01
DBGSQL:           B :pkg_vsnub4 = 10020001

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.00
DBGSQL:           B :pkg_vsnub4 = 11010000

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.01
DBGSQL:           B :pkg_vsnub4 = 11010001

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.02
DBGSQL:           B :pkg_vsnub4 = 11010002

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.03
DBGSQL:           B :pkg_vsnub4 = 11010003

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.04
DBGSQL:           B :pkg_vsnub4 = 11010004

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.05
DBGSQL:           B :pkg_vsnub4 = 11010005

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.06
DBGSQL:           B :pkg_vsnub4 = 11010006

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.01.00.07
DBGSQL:           B :pkg_vsnub4 = 11010007

DBGSQL:          sqlcode = 0
DBGSQL:           B :pkg_vsn = 11.02.00.00
DBGSQL:           B :pkg_vsnub4 = 11020000

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
>
>

--
http://www.freelists.org/webpage/oracle-l

Received on Mon Nov 04 2019 - 20:12:37 CET

This message: [ Message body ]
Next message: Stefan Knecht: "Re: Where is this Privilege coming from?"
Previous message: Jonathan Lewis: "Re: Where is this Privilege coming from?"
In reply to: Charlotte Hammond: "Sudden Backup Slowdown"
Next in thread: Radoulov, Dimitre: "Re: Sudden Backup Slowdown"

Contemporary messages sorted: [ by date ] [ by thread ] [ by subject ] [ by author ]

Original text of this message