{"id":867,"date":"2025-04-04T17:15:00","date_gmt":"2025-04-04T15:15:00","guid":{"rendered":"https:\/\/anjo.pt\/keyword-oracle\/?p=867"},"modified":"2025-08-25T13:30:11","modified_gmt":"2025-08-25T11:30:11","slug":"commvault-backup-timeout-and-too-many-objects-in-oracle-recycle-bin","status":"publish","type":"post","link":"https:\/\/anjo.pt\/keyword-oracle\/2025\/04\/04\/commvault-backup-timeout-and-too-many-objects-in-oracle-recycle-bin\/","title":{"rendered":"Commvault backup timeout and too many objects in Oracle recycle bin"},"content":{"rendered":"\n

Since a few weeks there was an error during backups of one of my clients databases. They use Commvault to trigger the backups. <\/p>\n\n\n\n

In the background, for some reason, Commvault asks the primary instance for some information about the free space in the tablespaces, using the following query:<\/p>\n\n\n

\nSELECT 'D,' || c.NAME || ':' || t.NAME || ':' || c.dbId  || ',' || d.STATUS || ',' || d.ENABLED || ',' || TO_CHAR(d.BYTES) || ',' || TO_CHAR(d.BYTES - NVL(ff.fbytes,0)) || ',' || TRIM(' ' FROM d.NAME) || ',' || TRIM(' ' FROM d.FILE#) AS PDB_TS_DF \nFROM v$datafile d, v$tablespace t, v$CONTAINERS c, (SELECT f.CON_ID CON_ID, f.file_id file_id, SUM(f.bytes) fbytes FROM CDB_FREE_SPACE f GROUP BY f.file_id,f.CON_ID) ff \nWHERE c.CON_ID = d.CON_ID and d.CON_ID = t.CON_ID and d.TS#=t.TS# AND ff.file_id (+)= d.FILE#  \nORDER BY PDB_TS_DF;\n<\/pre><\/div>\n\n\n
The important part is this one:<\/p>\n\n\n\n\n\n\n
\nSELECT f.CON_ID CON_ID, f.file_id file_id, SUM(f.bytes) fbytes \n  FROM CDB_FREE_SPACE f \n  GROUP BY f.file_id,f.CON_ID;\n<\/pre><\/div>\n\n\n
This query was taking quite some long time. This makes me suspicious about the Commvault error:<\/p>\n\n\n\n
22452 57b4 12\/19 04:57:58 992041 RacBrowser::DoBrowse() - Dataguard client with skip readonly\/data backup on standby refresh primary instance for data file status\n22452 57b4 12\/19 04:57:58 992041 RacBrowser::BrowsePrimaryInstanceForSchema() - commandLineArgs = BROWSE -a 2:640 -jm 1099511627776\n22452 57b4 12\/19 05:00:44 992041 CCvNetwork::Disconnect() - Error [0x80070306:{CCvNetwork::ReceiveXMLMessage(4236)} + {CCvNetwork::ReceiveXDRMessagePrivate(6032)\/W32.774.(One or more errors occurred while processing the request. (ERROR_ERRORS_ENCOUNTERED.774))-Unexpected message from RemoteHost=vm4375.myclient.com, RemoteProcess=cvd, Received Msg=150996226:CVS_PM_REMOTE_EXECUTE_RSP, Expected=150995458:CVS_PM_DISCONNECT_RSP. Connection string: vm4375\/vm4375.myclient.com\/SockIP(159.232.140.175)\/159.232.140.175:cvd\/8400\/8400 cvd(24022:3e21b700)}] receiving disconnect response Object\n22452 57b4 12\/19 05:00:44 992041 RacBrowser::BrowsePrimaryInstanceForSchema<\/strong>() - Error [0x80070102:{CCvNetwork::ExecRemoteCmdAndWait(2825)} + {CCvNetwork::ExecRemoteCmdAndWait<\/strong>(2792)} + {CCvNetwork::ReceiveXDRMessageInternal(5514)} + {CCvNetwork::CheckIfDataAvailable(5824)\/vm4375\/vm4375.myclient.com\/SockIP(159.232.140.175)\/159.232.140.175:cvd\/8400\/8400 cvd(24022:3e21b700)} + {CCvNetwork::CheckDataWaiting(6498)} + {CSessionConnectionSocket::CheckDataWaiting(668)\/W32.258.(The wait operation timed out<\/strong>. (WAIT_TIMEOUT<\/strong>.258))-Timed out}] returned from executeRemoteCommand [ClOraAgent] on RAC client 428\n22452 57b4 12\/19 05:00:44 992041 IDAError::SendMsg() - setting JPR for jobId 992041\n22452 57b4 12\/19 05:00:44 992041 JM Client  CVJobClient::getRemoteServer(): Got token [992041:4:11:0:0:15608].\n22452 57b4 12\/19 05:00:44 992041 JM Client  CVJobClient::getRemoteServer(): Got host [VM4435.myclient.com] from input.\n22452 57b4 12\/19 05:00:44 992041 JM Client  CVJobClient::connectToJM(): Got remote host [VM4435.myclient.com].\n22452 57b4 12\/19 05:00:44 992041 SetSocketOptions() - Couldn't set TCP keep-alive options. Return code:[95=EOPNOTSUPP].\n22452 57b4 12\/19 05:00:44 992041 SetSocketOptions() - Couldn't set TCP keep-alive options. Return code:[95=EOPNOTSUPP].\n22452 57b4 12\/19 05:00:44 992041 BrowsePrimaryInstanceForSchema() - errMsg=[Failed to query data file list and enabled status from Primary instance to skip read only tablespaces for standby backup.]\n22452 57b4 12\/19 05:00:44 992041 BrowsePrimaryInstanceForSchema() - IsSetJPR = [TRUE]\n22452 57b4 12\/19 05:00:44 992041 BrowsePrimaryInstanceForSchema() - IsAlreadySent = [FALSE]\n22452 57b4 12\/19 05:00:44 992041 BrowsePrimaryInstanceForSchema() - Error with Stack[0xECCC065B:{RacBrowser::BrowsePrimaryInstanceForSchema(198)\/ErrNo.1627.(Unknown error 1627)-Failed to query data file list and enabled status from Primary instance to skip read only tablespaces for standby backup.}]\n22452 57b4 12\/19 05:00:44 992041 ClOraAgent::Browse(1460) - Browse failed\n22452 57b4 12\/19 05:00:44 992041 ::Browse() - Browse failed:Failed to query data file list and enabled status from Primary instance to skip read only tablespaces for standby backup..\n22452 57b4 12\/19 05:00:44 992041 ::ExitHere() - enter: phase=6\n<\/code><\/pre>\n\n\n\n
When checking on Oracle support we see that “Queries on DBA_FREE_SPACE are Slow (Doc ID 271169.1)<\/a>” is mostly due to the recycle bin.<\/p>\n\n\n\n
I found out that the problem came only from the main PDB, where more than 200 thousand objects were in the recycle bin. Once I deleted them, the backup errors disappeared.<\/p>\n\n\n\n
As I was not sure I could simple disable the recycle bin, I took the chance to apply a scheduler job which deletes from the Oracle recycle bin everything older than X days:<\/p>\n\n\n
\nalter session set container=my_pdb;\n\ncreate or replace procedure clean_recyclebin as\n\/* Purge recyclebin objects in this PDB older than 1 hour *\/\n\nbegin\nfor obj in (select owner,object_name from dba_recyclebin where type='TABLE' and to_date(droptime,'YYYY-MM-DD:HH24:MI:SS')&lt;sysdate-1\/24) loop\nexecute immediate 'purge table '||obj.owner||'."'||obj.object_name||'"';\nend loop;\nend;\n\/\n\nbegin\n    dbms_scheduler.create_job(job_name        => 'PURGE_RECYCLEBIN_1_HOUR',\n                              job_type        => 'STORED_PROCEDURE',\n                              job_action      => 'clean_recyclebin',\n                              start_date      => systimestamp,\n                              end_date        => null,\n                              repeat_interval => 'freq=hourly; byminute=0; bysecond=0;',\n                              enabled         => true,\n                              auto_drop       => false,\n                              comments        => 'To avoid Commvault problems, due many objects drop, it purges recyclebin oltder than 1 hour');\nend;\n\/\n\nselect job_type,job_action,repeat_interval,enabled,state,next_run_date from dba_scheduler_jobs where job_name='PURGE_RECYCLEBIN_1_HOUR';\n<\/pre><\/div>\n\n\n
<\/p>\n","protected":false},"excerpt":{"rendered":"
Since a few weeks there was an error during backups of one of my clients databases. They use Commvault to trigger the backups. In the background, for some reason, Commvault asks the primary instance for some information about the free space in the tablespaces, using the following query: The important part is this one:<\/p>\n","protected":false},"author":3,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[6],"tags":[],"class_list":{"0":"post-867","1":"post","2":"type-post","3":"status-publish","4":"format-standard","6":"category-oracle","7":"czr-hentry"},"_links":{"self":[{"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/posts\/867","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/users\/3"}],"replies":[{"embeddable":true,"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/comments?post=867"}],"version-history":[{"count":2,"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/posts\/867\/revisions"}],"predecessor-version":[{"id":1044,"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/posts\/867\/revisions\/1044"}],"wp:attachment":[{"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/media?parent=867"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/categories?post=867"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/anjo.pt\/keyword-oracle\/wp-json\/wp\/v2\/tags?post=867"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}