Re: [ADSM-L] Long delay between FileSpaces backups

This is perhaps the deleted file processing pass that happens at the end
of a standard incremental backup.  The server sends a list of all the
files it thinks it has back to the client so the client can compare them
to what it knows it has and then ask the server to mark the deleted
files inactive.  I've not seen this happen with the relatively small
number of files you show here but this is probably it.  To prove it, try
an incremental/fast on this server and see if the delay between file
spaces is eliminated.  The /fast tells the client to not do the deleted
file pass.

Kelly Lipp
CTO
STORServer, Inc.
485-B Elkton Drive
Colorado Springs, CO 80907
719-266-8777
www.storserver.com


-----Original Message-----
From: ADSM: Dist Stor Manager [mailto:ADSM-L AT VM.MARIST DOT EDU] On Behalf Of
Michael Green
Sent: Tuesday, April 08, 2008 12:59 AM
To: ADSM-L AT VM.MARIST DOT EDU
Subject: [ADSM-L] Long delay between FileSpaces backups

I have noticed that several nodes exhibit long delays between when
backup of one filespace ends and the next one starts.
Here is an excerpt from one dsmsched.log file that illustrates the
problem:

04/07/2008 21:00:12 --- SCHEDULEREC OBJECT BEGIN F2UX_INC_BKP1
04/07/2008 21:00:00
04/07/2008 21:00:12 Incremental backup of volume '/'
04/07/2008 21:00:12 Incremental backup of volume '/boot'
04/07/2008 21:00:12 Incremental backup of volume '/home'
04/07/2008 21:00:14 Successful incremental backup of '/boot'

04/07/2008 21:19:29 ANS1898I ***** Processed     3,000 files *****
04/07/2008 21:19:30 ANS1898I ***** Processed    22,000 files *****
04/07/2008 21:19:31 ANS1898I ***** Processed    40,000 files *****
04/07/2008 21:19:32 ANS1898I ***** Processed    56,500 files *****
04/07/2008 21:19:33 ANS1898I ***** Processed    73,000 files *****
04/07/2008 21:19:34 ANS1898I ***** Processed    89,000 files *****
04/07/2008 21:19:35 ANS1898I ***** Processed   107,000 files *****
04/07/2008 21:19:36 ANS1898I ***** Processed   125,500 files *****
04/07/2008 21:19:37 ANS1898I ***** Processed   143,500 files *****
04/07/2008 21:19:38 ANS1898I ***** Processed   161,500 files *****
04/07/2008 21:19:39 ANS1898I ***** Processed   176,500 files *****
04/07/2008 21:19:40 ANS1898I ***** Processed   180,000 files *****
04/07/2008 21:19:40 Normal File-->               445
/opt/tivoli/tsm/client/ba/bin/tsmstats.ini [Sent]
04/07/2008 21:19:40 Normal File-->           834,182
/var/cache/man/whatis [Sent]
04/07/2008 21:19:40 Normal File-->             1,282
/var/lib/logrotate.status [Sent]
04/07/2008 21:19:47 Normal File-->        87,070,388
/var/lib/mlocate/mlocate.db [Sent]
04/07/2008 21:19:47 Normal File-->                72
/var/lib/nfs/rmtab [Sent]
04/07/2008 21:19:47 Normal File-->                 6
/var/lib/ntp/drift [Sent]
04/07/2008 21:19:47 Normal File-->            23,040 /var/log/btmp
[Sent]
04/07/2008 21:19:47 Normal File-->             3,497 /var/log/cron
[Sent]
04/07/2008 21:19:47 Normal File-->               332
/var/log/dsmerror.log [Sent]
04/07/2008 21:19:47 Normal File-->        11,126,980
/var/log/dsmsched.log  Changed
04/07/2008 21:19:47 Retry # 1  Normal File-->                72
/var/lib/nfs/rmtab [Sent]
04/07/2008 21:19:47 Retry # 1  Normal File-->                 6
/var/lib/ntp/drift [Sent]
04/07/2008 21:19:47 Retry # 1  Normal File-->            23,040
/var/log/btmp [Sent]
04/07/2008 21:19:47 Retry # 1  Normal File-->             3,497
/var/log/cron [Sent]
04/07/2008 21:19:47 Retry # 1  Normal File-->               332
/var/log/dsmerror.log [Sent]
04/07/2008 21:19:48 Retry # 1  Normal File-->        11,128,049
/var/log/dsmsched.log  Changed
04/07/2008 21:19:49 Retry # 2  Normal File-->        11,128,144
/var/log/dsmsched.log  Changed
04/07/2008 21:19:49 Retry # 3  Normal File-->        11,128,144
/var/log/dsmsched.log [Sent]
04/07/2008 21:19:49 Normal File-->            41,712
/var/log/dsmwebcl.log [Sent]
04/07/2008 21:19:49 Normal File-->         5,250,452 /var/log/lastlog
[Sent]
04/07/2008 21:19:49 Normal File-->               881 /var/log/maillog
[Sent]
04/07/2008 21:19:49 Normal File-->               955 /var/log/messages
[Sent]
04/07/2008 21:19:49 Normal File-->            44,100 /var/log/rpmpkgs
[Sent]
04/07/2008 21:19:49 Normal File-->             2,354 /var/log/secure
[Sent]
04/07/2008 21:19:49 Normal File-->            12,672 /var/log/wtmp
[Sent]
04/07/2008 21:19:49 Normal File-->         4,419,337
/var/log/audit/audit.log [Sent]
04/07/2008 21:19:49 Normal File-->             1,448
/var/log/mail/statistics [Sent]
04/07/2008 21:19:49 Normal File-->            13,056 /var/run/utmp
[Sent]
04/07/2008 21:19:49 Normal File-->                 9
/var/spool/anacron/cron.daily [Sent]
04/07/2008 21:19:50 Normal File-->           599,856
/var/spool/mail/root [Sent]
04/07/2008 21:20:07 Successful incremental backup of '/'

04/08/2008 04:39:08 ANS1898I ***** Processed   180,500 files *****
04/08/2008 04:39:10 ANS1898I ***** Processed   181,000 files *****

Note the time difference between when backup of '/' end and next
filespace starts!

Is this a known bug or a performance problem I'm having here?
If this is  a performance problem, what are the initial steps should
be taken to address the issue?

Server: 5.3.6/Linux86 (SLES9)
Client: 5.4.1.5/Linux86 (RedHat EL 5.0)
--
Warm regards,
Michael Green