Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

  • Congratulations TouchToneTommy on being selected by the Tek-Tips community for having the most helpful posts in the forums last week. Way to Go!

Commvault Data Discrepancy

Status
Not open for further replies.

mrfokker

MIS
Aug 27, 2007
81
US
I do a full backup of all my clients every weekend and typically averages around 3.1 TB +/-. This past weekend the Backup summary report(s) showed I backed up that amount. However upon investigating my cloned tape copies my disk libary shows roughly 700G of more data on the drives. My tape clones are roughly 3.8 TB and my disk library reflects that amount. I looked over the drive contents and nothing out of the ordinary shows up on the contents. I am perplexed why there is such a discrepancy. Anyone have any ideas what I should look for?
 
Heres some more information I found looking through the logs.

Normal Weekend Backup for client.

Job Attempts:
Scan (1) [2007/11/02 19:00:20 - 2007/11/02 19:05:52 ]: (Data Size) 0; (Transfer Time) 0:00:00; (Throughput (GB/Hour)) 0; (MediaAgent) (null); (Library) (null); (Drive Pool) (null); (Drive) (null)
Backup (1) [2007/11/02 19:05:55 - 2007/11/03 22:13:40 ]: (Data Size) 1415.44 GB; (Transfer Time) 27:07:15; (Throughput (GB/Hour)) 52.190; (MediaAgent) commvault1; (Library) Disk_Library; (Drive Pool) (null); (Drive) E:\Commvault_Disk_Backup, F:\Commvault_Disk_Backup, g:\Commvault_Disk_Backup
Archive Index (1) [2007/11/03 22:13:40 - 2007/11/03 22:14:38 ]: (Data Size) 67.82 MB; (Transfer Time) 0:00:05; (Throughput (GB/Hour)) 47.683; (MediaAgent) commvault1; (Library) Disk_Library; (Drive Pool) (null); (Drive) E:\Commvault_Disk_Backup

Heres the problem one from the weekend

Job Attempts:
Scan (1) [2007/11/09 19:00:18 - 2007/11/09 19:05:48 ]: (Data Size) 0; (Transfer Time) 0:00:00; (Throughput (GB/Hour)) 0; (MediaAgent) (null); (Library) (null); (Drive Pool) (null); (Drive) (null)
Scan (2) [2007/11/10 07:15:45 - 2007/11/10 07:21:04 ]: (Data Size) 0; (Transfer Time) 0:00:00; (Throughput (GB/Hour)) 0; (MediaAgent) (null); (Library) (null); (Drive Pool) (null); (Drive) (null)
Backup (1) [2007/11/09 19:05:50 - 2007/11/10 06:54:33 ]: (Data Size) 742.71 GB; (Transfer Time) 11:48:16; (Throughput (GB/Hour)) 62.918; (MediaAgent) commvault1; (Library) Disk_Library; (Drive Pool) (null); (Drive) F:\Commvault_Disk_Backup, g:\Commvault_Disk_Backup
Backup (2) [2007/11/10 07:21:08 - 2007/11/11 05:00:18 ]: (Data Size) 1334.08 GB; (Transfer Time) 21:38:42; (Throughput (GB/Hour)) 61.635; (MediaAgent) commvault1; (Library) Disk_Library; (Drive Pool) (null); (Drive) E:\Commvault_Disk_Backup, g:\Commvault_Disk_Backup
Archive Index (1) [2007/11/10 06:54:33 - 2007/11/10 06:55:03 ]: (Data Size) 0; (Transfer Time) 0:00:00; (Throughput (GB/Hour)) 0; (MediaAgent) commvault1; (Library) Disk_Library; (Drive Pool) (null); (Drive) g:\Commvault_Disk_Backup
Archive Index (2) [2007/11/11 05:00:18 - 2007/11/11 05:01:16 ]: (Data Size) 67.82 MB; (Transfer Time) 0:00:04; (Throughput (GB/Hour)) 59.603; (MediaAgent) commvault1; (Library) Disk_Library; (Drive Pool) (null); (Drive) E:\Commvault_Disk_Backup

For some reason it attempted to backup this client twice and I have no idea why. A scheduled full is set to run every Friday at 7:00pm. For some reason it looks like Client job ran half way, stopped and started again from the begining giving me an added 742G. I guess now the question is why??


 
Here's the Client log from the time it looks like the job just stopped. Anyone see anything.

5624 c90 11/10 06:54:00 77165 ::HandleBackupReadError() - [G:\Photo\JF RGB\Fujis S3 RAW\102407-02\BDS-E0308_P08.RAF] Error [1450] during BackupRead. Err:[1450] Insufficient system resources exist to complete the requested service.

5624 c90 11/10 06:54:00 77165 ::sendEndOfFileMessage() - Sending bad file indicator for [G:\Photo\JF RGB\Fujis S3 RAW\102407-02\BDS-E0308_P08.RAF].
5624 c90 11/10 06:54:16 77165 FsBackupTw::Run() - In clbackup Object [1] after backup of [C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\iDataAgent\FileSystemAgent\2\2\NumColTot4.cvf]
5624 e60 11/10 06:54:16 77165 FsBackupCtlr::Run() - Wait for multiple semaphore completed...releasing one reservation used of object. [1]
5624 e60 11/10 06:54:16 77165 FsBackupCtlr::Run() - Saved local drive info for the backup once.
5624 e60 11/10 06:54:16 77165 In ClBackupFile::SaveLocalDriveInfo, a windows FS backup.
5624 e60 11/10 06:54:16 77165
C:\

5624 e60 11/10 06:54:16 77165 Bytes available to caller are [ 62635439616 ], bytes on disk are [ 72686798848 ], free bytes on disk are [ 62635439616 ]
5624 e60 11/10 06:54:16 77165
E:\

5624 e60 11/10 06:54:16 77165 Bytes available to caller are [ 82550374400 ], bytes on disk are [ 751617794048 ], free bytes on disk are [ 82550374400 ]
5624 e60 11/10 06:54:16 77165
F:\

5624 e60 11/10 06:54:16 77165 Bytes available to caller are [ 51459985408 ], bytes on disk are [ 805304197120 ], free bytes on disk are [ 51459985408 ]
5624 e60 11/10 06:54:16 77165
G:\

5624 e60 11/10 06:54:16 77165 Bytes available to caller are [ 55466610688 ], bytes on disk are [ 128847966208 ], free bytes on disk are [ 55466610688 ]
5624 e60 11/10 06:54:16 77165
H:\

5624 e60 11/10 06:54:16 77165 Bytes available to caller are [ 77556551680 ], bytes on disk are [ 107372769280 ], free bytes on disk are [ 77556551680 ]
5624 e60 11/10 06:54:16 77165 CCVAPipelayer::SetRestartContext() - Setting restart context to -1
5624 e60 11/10 06:54:16 77165 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 291 to MediaAgent, Waiting for Response...
5624 e60 11/10 06:54:16 77165 [PIPELAYER ] Tail response = Current Restart Context has been set to -1 Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 291 EventError = 0

5624 e60 11/10 06:54:16 77165 Updating the failed file and folder count. No. of failed files are [1338] and folders are [0]
5624 e60 11/10 06:54:16 77165 ::ClBackupBase::Close() - Could not backup [0] folders and [1338] files.
5624 e60 11/10 06:54:16 77165 ::ClBackupBase::Close() - [77165] Closing archive file
5624 e60 11/10 06:54:16 77165 CCVAPipelayer::CloseArchiveFile() - Closing archive file[afilenum=168340] in BACKUP
5624 e60 11/10 06:54:16 77165 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 132 to MediaAgent, Waiting for Response...
5624 e60 11/10 06:54:17 77165 [PIPELAYER ] Tail response = Close archive file succeeded Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 132 EventError = 0

5624 e60 11/10 06:54:17 77165 ::ClBackupBase::Close() - [77165] Closing pipeline.
5624 e60 11/10 06:54:17 77165 ::ClBackupBase::Close() - [77165] Sending PL_LAST to tail.
5624 e60 11/10 06:54:17 77165 ::ClBackupBase::Close() - [77165] backupState(1=good) = 0, closePlArgs.backupState = 0
5624 e60 11/10 06:54:17 77165 CVArchive::ClosePipeline() - Closing Pipeline
5624 e60 11/10 06:54:17 77165 CVArchive::ClosePipeline() - Reseting allocated stream
5624 e60 11/10 06:54:17 77165 CCVAPipelayer::ClosePipeline() - About to destroy Data Mover
5624 e60 11/10 06:54:17 77165 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 133 to MediaAgent, Waiting for Response...
5624 e60 11/10 06:54:17 77165 [PIPELAYER ] Tail response = DataMover destroyed Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 133 EventError = 0

5624 e60 11/10 06:54:17 77165 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 2 to MediaAgent, Waiting for Response...
5624 e60 11/10 06:54:18 77165 [PIPELAYER ] Tail response = Tail Generated STOP_PL and ready to Terminate Status = 0 dwCode = 0 MsgType = 4 MsgSubType = 2 EventError = 0

5624 e60 11/10 06:54:18 77165 CPipelayer::ShutdownPipeline() - Waiting for STOP_PL message
5624 e60 11/10 06:54:32 77165 [PIPELAYER ] Pipeline received STOP_PL
5624 e60 11/10 06:54:32 77165 [PIPELAYER ] Returning from waiting for pipeline shutdown because the pipeline is no longer running
5624 e60 11/10 06:54:32 77165 CPipelayer::ShutdownPipeline() - pipeline ShutDown completed for pipeline

5624 e60 11/10 06:54:32 ##### [CVD ] Stopping CVDAliveChecking
5624 15a8 11/10 06:54:32 ##### [CVD ] CVD Alive Check Quit Event Signaled
5624 15a8 11/10 06:54:32 ##### [CVD ] CVDAliveChecking Thread Stopping
5624 e60 11/10 06:54:32 ##### [CVD ] CVDAliveChecking Thread Stopped
5624 e60 11/10 06:54:32 ##### [CVD ] Closed CVD Alive Check Quit Event
5624 e60 11/10 06:54:32 ##### [CVD ] Closed CVD Alive Check Mutex
5624 e60 11/10 06:54:32 77165 ::ClBackupBase::Close() - [77165] back from closePipeline
5624 e60 11/10 06:54:32 77165 FsBackupCtlr::Run() - Completing the backup of assigned collect files.....
5624 e60 11/10 06:54:32 77165 FsBackupCtlr::Run() - Completed the backup.
5624 e60 11/10 06:54:32 77165 FsBackupCtlr::Close() - [77165] going to buResults.closeFile
5624 e60 11/10 06:54:32 77165 ICACHEDIR: cleanUp C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults cl=1, #Bl=0, rmOld=1, logEv=0, useAccTm=1, commCell=0, appNum=0
5624 e60 11/10 06:54:32 77165 CDIRARRAY: Sorting cache dirs, useAccessTime=1
5624 e60 11/10 06:54:32 77165 CDIRARRAY: Finished sorting cache dirs
5624 e60 11/10 06:54:32 77165 ICACHEDIR: removing all cache dirs in cacheFs C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults older than cutoff 1194094472 (currentTime = 1194699272, numDays=7, absCutoff=0, remove all old directories)
5624 e60 11/10 06:54:32 77165 ICACHEDIR: numBlocks=0, minFreePercent=10, freeBlocks=61167605, totBlocks=70983202, pad=976
5624 e60 11/10 06:54:32 77165 ICACHEDIR: UnCache 'C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\2\0\76509'
5624 e60 11/10 06:54:32 77165 ICACHEDIR: Discarding C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\2\0\76509 state '0' atime '1194048366 '
5624 e60 11/10 06:54:32 77165 DIRECTORY: removeFiles from C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\2\0\76509 (except State)
5624 e60 11/10 06:54:32 77165 ICACHEDIR: UnCache 'C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\2\0\76510'
5624 e60 11/10 06:54:32 77165 ICACHEDIR: Discarding C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\2\0\76510 state '0' atime '1194048387 '
5624 e60 11/10 06:54:32 77165 DIRECTORY: removeFiles from C:\Program Files\CommVault Systems\Galaxy\iDataAgent\JobResults\CV_JobResults\2\0\76510 (except State)
5624 e60 11/10 06:54:32 77165 ICACHEDIR: cleanUp: Done cleaning because we have enough free blocks and disk free
5624 e60 11/10 06:54:32 77165 FsBackupCtlr::exitHere() - [77165] Notifying Job Manager of backup phase success.
5624 e60 11/10 06:54:32 77165 BKP CALLED COMPLETE (PHASE Status::SUCCESS), 77165. Token [77165:7:1]
5624 e60 11/10 06:54:33 77165 FsBackupCtlr::exitHere() - [77165] back from notifying Job Manager of backup phase success.
5624 e60 11/10 06:54:33 77165 FsBackupCtlr::exitHere() - [77165] going to terminate events and exit
5624 e60 11/10 06:54:33 77165 terminateAppMgrConnections() calling terminateAllSessions
5624 e60 11/10 06:54:33 77165 AppMgrSessionPoolSingleton::terminateAllSessions() exit after single instance terminate
5624 e60 11/10 06:54:33 77165 finishedWorkWithOutExit() - Release control semaphor 77165:5624
5624 e60 11/10 06:54:33 77165 finishedWorkWithOutExit() - Waiting for control thread to Quit, 77165
5624 13c 11/10 06:54:33 77165 controlThread() - Normal termination, Job Id 77165
5624 13c 11/10 06:54:33 77165 controlThread() - Send unregister message to CVD, Job Id 77165
5624 13c 11/10 06:54:33 77165 unRegisterProcess() - Send Message to CVD 77165
5624 13c 11/10 06:54:33 77165 unRegisterProcess() - Send Message Successfully 77165
5624 13c 11/10 06:54:34 77165 CVJobCtrlLog::unregisterProcess(): successfuly removed file [C:\Program Files\CommVault Systems\Galaxy\Base\JobControl\5.624]
5624 13c 11/10 06:54:34 77165 controlThread() - Control thread done, Job Id 77165
5624 e60 11/10 06:54:34 77165 finishedWorkWithOutExit() - Control thread Done , ID : 77165
5624 e60 11/10 06:54:34 77165 Entering [CsVssBackupComponents::~CsVssBackupComponents]
5624 e60 11/10 06:54:34 77165 Entering [CsVssBackupComponents::Delete]
3396 1648 11/10 07:21:08 ### CV_ValidateHostEntry()() - Host entry validation will NOT be skipped
3396 1648 11/10 07:21:08 77165 ::logBackupArgs() - args parsed: backupType=1, commCellId=2, appId=2, jobId=77165, collectCount=0
3396 1648 11/10 07:21:08 77165 ::logBackupArgs() - [77165] Restart info: offsetIntoCollect=0, vm=ControlSet001(pageworkflow1)
3396 1648 11/10 07:21:08 77165 ::logBackupArgs() - [77165] Number of streams reserved is : numStreamsReserved=1
3396 1648 11/10 07:21:08 77165 ::logBackupArgs() - [77165] The force clean backup flag -fb is set to true
3396 1648 11/10 07:21:08 77165 ::ChooseAppType() - OS Version Info:
 
Many thanks birky. After yesterday's problem I reasserted the importance to fixing it to the necessary parties as unfortunately I am not authorized to make registry changes to production servers.
 
Status
Not open for further replies.

Part and Inventory Search

Sponsor

Back
Top