KRB tracing and background
On our Exadata Cloud Service system running 18c GI and DB, we have been running into issues with /u02 filesystem filling up. This was primarily imposed and generated by one component – RMAN. As it turns out we had just enabled ExaCS automated backups via the tooling (bkup_api) .
Firstly, krb.c code refers to RMAN code layer, and tracing is generally produced when user specifies krbitrc via the event tracing. Note this is not the same as rman debugging ( debug=all).
Starting in DB 18.3 , the event tracing is generating tracing regardless of event being set or not, and worse, its gen’ing trace files for every command. This why the the /u02 is getting filled up
Here’s a sample of the trace data:
2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165134 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165134 2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165135 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165135 2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165136 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165136 2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165137 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165137 2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165138 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165138 2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165139 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165139 2019-06-02 18:17:16.933*:KRB:krbr.c@15486:krbr2b1(): ; f->krfil_krbrf=0 op1=2 lbno=1165140 f->seq_krbrf=11981 2019-06-02 18:17:16.933*:KRB:krbr.c@15908:krbr9b2(): Entering; f->seq_krbrf=11981 f->thread_krbrf=2 bno=1165140
And
…………
Redo thread mounted by this instance: 1 Oracle process number: 284 Unix process pid: 8448, image: oracle@***** (TNS V1-V3) *** 2019-06-02T19:00:03.444793+00:00 (CDB$ROOT(1)) *** SESSION ID:(1723.45910) 2019-06-19T19:00:03.444828+00:00 *** CLIENT ID:() 2019-06-02T19:00:03.444835+00:00 *** SERVICE NAME:(SYS$USERS) 2019-06-02T19:00:03.444841+00:00 *** MODULE NAME:(rman@***** (TNS V1-V3)) 2019-06-02T19:00:03.444848+00:00 *** ACTION NAME:() 2019-06-02T19:00:03.444855+00:00 *** CLIENT DRIVER:() 2019-06-02T19:00:03.444861+00:00 *** CONTAINER ID:(1) 2019-06-02T19:00:03.444868+00:00 2019-06-02 19:00:03.444*:KRB:krbi.c@8857:krbitrc(): Got krbitrc 2019-06-02 19:00:03.444*:KRB:krbi.c@8887:krbiwtrc(): (bkrsmain - Action is NULL) *** ACTION NAME:(0000001 STARTED70) 2019-06-02T19:00:03.444998+00:00 2019-06-02 19:00:03.444*:KRB:krbi.c@8887:krbiwtrc(): (icdstart - Action set to 0000001 STARTED70) *** ACTION NAME:(0000001 FINISHED70) 2019-06-02T19:00:03.445209+00:00 2019-06-02 19:00:03.445*:KRB:krbi.c@8887:krbiwtrc(): (icdfinish - Action set to 0000001 FINISHED70)
Doc ID 28390273.8 mentions that the fix is included in “18.4.0.0.181016 (Oct 2018) Database Release Update (DB RU)” but issue is still seen in latest RU.
You can either wait for the fix, or manually disable kbr tracing.
To fix this issue permanently set below parameter at DB level
if using spfile
Alter system set events ‘trace[krb.*] disk disable, memory disable’;
If using pfile
event=’trace[krb.*] disk disable, memory disable’
MOS Note – Excessive MMON, KRB Traces Causing Trace File Location (/u01) Overflow in DBaaS (Doc ID 2442656.1) does a decent job describing this issue