deleting orphaned CommVault backups

In the current environment Commvault is used as a central backup solution. The setup is not very common, as CommVaults scheduler is not used for any activities. All backups are scheduled by a system which also takes some infrastructural limitations into consideration. These are (among others): shared IO resources of consolidated data­bases on a cluster, shared backup network resources of clusters, shared media agents in different datacenters, and some other constraints as well.
Also retention policies are handled only by RMAN, the retention policy of CommVaults Storage Pools is set to infinite.
Unfortunately, for some (yet not 100% clear) reasons, there are some orphaned backup pieces in CommVault which are not visible in RMAN catalog anymore. Still they need to be deleted to regain storage (and reduce number of entries in the precious Dedup DataBase).
Unfortunately, RMAN can not delete a backup piece which it doesn't know about. So we must mimic it's activities regarding the SBT_TAPE interface to send the information to delete - again.

First it's needed to get the list of backup pieces from CommVault. To do so, a query on CommVaults SQLServer DB is required:

select cbi.clientname
     , cbi.instance
  , cbi.startdate
  , cbi.enddate
  , cbi.jobid
  , ora.archFileName
--  , obi.storagePolicy
--  , obi.isAged
--  , obi.Copyname
from [CommServ].[dbo].[CommCellBackupInfo] cbi
  join [CommServ].[dbo].[archFileOracle] ora on cbi.jobid = ora.jobId
  join [CommServ].[dbo].[CommCellOracleBackupInfo] obi on cbi.jobid= obi.jobid
where cbi.isAged = 0
  and obi.isAged = 0 
  and cbi.enddate <= getdate()-60
--  and cbi.jobid = &jobid
order by cbi.clientname, cbi.instance, cbi.startdate

In this query some lines are commented but they might be useful for different questions. cbi.enddate is filtered to <= getdate()-60. RMAN retention is set to 40 days in this context and some spare days are used in the query.
Every archFileName must be crosschecked with RMAN catalogs RC_BACKUP_PIECE.HANDLE first. If it is still known by RMAN, there is no need to delete the corresponding CommVault Job.
(A Job in Commvault can contain several RMAN backup pieces. But the Job is/can only deleted if all BPs are send to be deleted by RMAN).

As I wrote earlier, an unknown backup piece can not be deleted by RMAN. There is no officially supported way to do so, but in Bug 1419888 : BACKUP ON ERROR DOES NOT DELETE PIECES GENERATED there is a clue how it can be done:

connect / as sysdba;
declare
  dn varchar2(255);
begin
  dn := dbms_backup_restore.deviceAllocate(type=>'sbt_tape', noio=>TRUE);
  dbms_backup_restore.deleteBackupPiece(0,0,'04c9av2p', 0,0,1);
  dbms_backup_restore.devicedeAllocate();
end;

There is also a params parameter to DBMS_BACKUP_RESTORE.DeviceAllocate which can be used to set exactly those SBT_TAPE parameters which otherwise would be used in RMAN script.


In a perfect world, this post would end here as the backup pieces would disappear.
Unfortunately it doesn't.

For any (yet not clear at all) reason, these backup pieces still exist on CommVault. All logs in $ORACLE_HOME/rdbms/log/sbtio.log looks ok:

440786 6b9d2 05/23 11:29:21 ### sbtinit: define trace file name=~~~ORACLE_HOME~~~/rdbms/log/sbtio.log
440786 6b9d2 05/23 11:29:21 ### sbtinit2: changing a trace level to: 0
440786 6b9d2 05/23 11:29:21 ### sbtinit2: API Client supports Oracle MM API Version: 2.0
440786 6b9d2 05/23 11:29:21 ### sbtinit2: Got argc=0.
440786 6b9d2 05/23 11:29:21 ### sbtinit2: exit - PID:440784, TID:440786; retVal=0
440786 6b9d2 05/23 11:29:21 ### sbtremove2: enter - PID:440784, TID:440786.
440786 6b9d2 05/23 11:29:21 ### sbtremove2: removing file: [~~~DBNAME~~~_1113069663_DF0_20181219_dbtl6i8l_1_1]...
440786 6b9d2 05/23 11:29:21 ### sbtremove2: exit - PID:440784, TID:440786; retVal=0
440786 6b9d2 05/23 11:29:21 ### sbtremove2: enter - PID:440784, TID:440786.
440786 6b9d2 05/23 11:29:21 ### sbtremove2: removing file: [~~~DBNAME~~~_1113069663_DF0_20181219_d6tl6i8g_1_1]...
440786 6b9d2 05/23 11:29:21 ### sbtremove2: exit - PID:440784, TID:440786; retVal=0
440786 6b9d2 05/23 11:29:21 ### sbtremove2: enter - PID:440784, TID:440786.
440786 6b9d2 05/23 11:29:21 ### sbtremove2: removing file: ~~~DBNAME~~~_1113069663_DF0_20181219_d8tl6i8i_1_1]...
440786 6b9d2 05/23 11:29:21 ### sbtremove2: exit - PID:440784, TID:440786; retVal=0
440786 6b9d2 05/23 11:29:21 ### sbtremove2: enter - PID:440784, TID:440786.
440786 6b9d2 05/23 11:29:21 ### sbtremove2: removing file: [~~~DBNAME~~~_1113069663_DF0_20181219_dbtl6i8l_2_1]...
440786 6b9d2 05/23 11:29:21 ### sbtremove2: exit - PID:440784, TID:440786; retVal=0
440786 6b9d2 05/23 11:29:21 ### CvHandleClean: before clean cv_handle=c2113170 ThreadNumber=1
440786 6b9d2 05/23 11:29:21 ### CvHandleClean: ThreadDeleteTidN [440786]
440786 6b9d2 05/23 11:29:21 ### sbtend: exit  - PID:440784, TID:440786; retVal=0 ThreadNumber=0>
<.........
440786 6b9d2 05/23 11:29:21 ### sbtend: ***** BEGIN SBT PERFORMANCE STATISTICS(SBTPS) for Client API Session: PID:440784, TID:440786   ********

(I'm sorry for the redacted entries - easily visible by ~~~)

So back to the 1^st query in this post, the one to run on CommVault SQL server. It contains a JOBID as well.

As dbms_backup_restore.deleteBackupPiece and CommVault are no friends, I still need to get rid of the orphaned backups. CommVault has a command to delete a specific backup job:
/opt/commvault/Base64/qoperation agedata -delbyjobid ‑j <JOBID> ‑delJobsOnAllCopies ‑ft Q_DATA_LOG
Unfortunately this command requires quite high privileges (the owner/creator of the job is not sufficient):

(Full) Administrative Management permission - but this is another story.

Beside these complications which makes any security manager will go crazy, the tool itself still tries to make life harder than required. When deleting a specific job, these answers must be given:

This command deletes the job on all copies, do you want to continue (y/n) ? [n] : y
To confim this action, type "Delete jobs on all copies"  : Delete jobs on all copies

Obviously, (beside the typo in confim) there are no parameter to qoperation to claim "yes, I'm an adult". It needs to ask (!?)
But for every problem, there is a solution. In this case it's called expect. It literally can simulate any input-output conversation with a uncooperative program. In this case, the script for expect looks like:
#!/usr/bin/expect -f

set job_id [lindex $argv 0];

set timeout -1
spawn /opt/commvault/Base64/qoperation agedata -delbyjobid -j $job_id -delJobsOnAllCopies -ft Q_DATA_LOG

match_max 100000

expect -exact "This command deletes the job on all copies, do you want to continue (y/n) ? \[n\] : "
send -- "y\r"
expect -exact "y\r
To confim this action, type \"Delete jobs on all copies\"  : "
send -- "Delete jobs on all copies\r"
expect eof

It takes the Job_ID as first parameter and steers qoperation through all its demands.

At the bottom of this post, it shows how to circumvent complications which should not exist, based on problems which should not exist also.
This says a lot about IT in 2019.

Backup stalled due to ASM rebalance stuck

I hit an issue where a full backup took much longer than normal.
In this case there was no alarm yet as no threshold was reached. But I worked on the DB for some other reason and out of a habit I most often start a ASH viewer whenever I work on a system - even if I only check data, it's worth to have an eye on the system.
In this case I saw some top session in waits 'ASM file metadata operation' & 'KSV master wait'.
It wasn't my query session (so I didn't break anything) but some RMAN worker processes.

That's worth to investigate. After some research (Google & MetaLink) I saw some links between ASM rebalance and 'ASM file metadata operation'.

Checking the ASM instance, there was really a ASM rebalance ongoing, but no progress (no change in v$asm_operation.SOFAR over some minutes). It was initiated the other evening by a colleague which added a disk to the DG. I agree with Kevin this is a bad habit, but in this environment it's not enough pain (and multiple teams involved) to re-work all the processes. The RBAL process was waiting in 'enq: RB - contention'.

As ASM rebalance can be stopped or re-started wit othe rpriority easily, I gave this a chance and run ALTER DISKGROUP dg REBALANCE POWER 2 - the power is not important here, ony to stop the current (stalled) rebalance and issue another.

The ASH viewer immediately showed the uncommon waits disappear and in RMAN logs I saw ordinary progress immediately.

To be honest I did not much analysis here, so it might be worth to do better, but in this case it was sufficient and the issue solved even before there was an alarm regarding the blocked backup.

Once again, ASH (and my curiosity) helped solving the issue. 

bzip2 twice?

To check the performance of RMAN backup I recently started to trace it a little bit. As most of the time was not spent in any reading from disk or writing to media manager library event, it was on CPU. It's good to know the CPUs are of any good, but as I still want to know what's going on I tried to dig any deeper. CPU cycles are not just a magic black box where we put in a problem and the answer comes out after some times. At an abstraction layer it's a chain of functions where one is called by another, and only the last is the one doing anything. There is not much information in that fact per se, but developers are humans also, and they are giving the functions they code meaningful names.


So I had just to find these names (and where most of the time is spent) to figure out what's going on. To save my time I remembered Tanel Poders Advanced Oracle Troubleshooting Guide, Part 9 – Process stack profiling from sqlplus using OStackProf. There he described his tool ostackprof. This did all the job for me, I just had to find a rman session.

Here's the shortstack where most of the time was spent:
(This backup was done with COMPRESSION ALGORITHM ‘BASIC’)
->__libc_start_main()->main()->ssthrdmain()->opimai_real()->sou2o()->opidrv()->opiodr()->opiino()->opitsk()->ttcpip()->opiodr()->kporpc()->kkxrpc()->prient()->prient2()->pricbr()->pricar()->plsql_run()->pfrrun()->pfrrun_no_tool()->pfrinstr_ICAL()->pevm_icd_call_common()->krbibpc()->krbbpc()->krbb3crw()->krbbcdo()->kgccdo()->kgccbz2pseudodo()->kgccbz2do()->kgccm()->kgccbuf()->kgccgmtf()->__sighandler()->->

The naming convention for functions is not public documented by oracle, but for some reasons I'm sure functions starting with krb are related to backup, whereas kgcc is used for compression. Especially the working function kgccgmtf reads like generate Move To Front.

At that point I had a lot more information than before, still I had no way how to improve the backup speed. As we have licensed advanced compression for that particular node, we tested with different other compression methods. LOW and MEDIUM where faster, with less compression than our previous BASIC. But HIGH was even slower!

So again I used ostackprof and that's the topmost stack trace - for HIGH:
->__libc_start_main()->main()->ssthrdmain()->opimai_real()->sou2o()->opidrv()->opiodr()->opiino()->opitsk()->ttcpip()->opiodr()->kporpc()->kkxrpc()->prient()->prient2()->pricbr()->pricar()->plsql_run()->pfrrun()->pfrrun_no_tool()->pfrinstr_ICAL()->pevm_icd_call_common()->krbibpc()->krbbpc()->krbb3crw()->krbbcdo()->kgccdo()->__PGOSF209_kgccbzip2pseudodo()->kgccbzip2do()->BZ2_bzCompress()->handle_compress()->BZ2_compressBlock()->generateMTFValues()->__sighandler()->->


Do you see the difference? Until kgccdo there is no! And even afterwards, the functions are somewhat similar. One more thing is worth to mention: the bzip2 implementation for HIGH does not use oracle internal naming convention. So it's worth to search for these names on the internet. one of my best hits was a compress.c File Reference.

Did Oracle reinvent the wheel? No. For me it looks as if they tried their best first (by doing their own kgcc implementation) and afterwards preferred simple copy&paste. Maybe they should just skip either of these 2 - they still can use parameters to achieve different compression quality. 


If someone is interested in our results:
for a single datafile of 30GB (with 100% usage) we achieved on a production system - with all it ongoing tasks:

Type	min	backup-size
BASIC	13:32	5.8
LOW	5:17	8
MEDIUM	8:52	6.14
HIGH	65:29	4.25

We decided to choose MEDIUM.