Hello,
Two weeks ago I sent a mail to this list asking about some strange delays I was seeing between the EndTime as logged byt rdiff-backup and the actual end of the running process. Since then, I've been digging deeper and I'd like to ask once more if anyone can tell me what's going on and how I might be able to 'fix' this. See, I ran my backups using -v9 for a few days and this has shown in greater detail when the delay happens. 2013/08/12 06:00:56 Mon Aug 12 05:56:03 2013 Copying inc attrs from ... to ... 2013/08/12 06:00:56 Mon Aug 12 05:56:03 2013 Setting time of ... to 1376107515 2013/08/12 06:00:56 Mon Aug 12 05:57:36 2013 Renaming ... to .../backup/home/domino/data/webadmin.ntf ... 2013/08/12 06:00:56 Mon Aug 12 06:00:56 2013 Setting time of .../backup/tmp to 1376245594 2013/08/12 06:00:56 Mon Aug 12 06:00:56 2013 Copying attributes from () to .../backup 2013/08/12 07:17:03 Mon Aug 12 06:00:56 2013 Setting time of .../backup to 1371199946 2013/08/12 07:17:03 Mon Aug 12 06:01:07 2013 Touching .../backup/rdiff-backup-data/extended_attributes.2013-08-12T00:53:28+02:00.snapshot 2013/08/12 07:17:03 Mon Aug 12 06:02:41 2013 Touching .../backup/rdiff-backup-data/access_control_lists.2013-08-12T00:53:28+02:00.snapshot 2013/08/12 07:17:03 Mon Aug 12 06:03:26 2013 Writing mirror_metadata diff 2013/08/12 07:17:03 Mon Aug 12 06:04:00 2013 Deleting .../backup/rdiff-backup-data/mirror_metadata.2013-08-11T00:55:43+02:00.snapshot.gz 2013/08/12 07:17:03 --------------[ Session statistics ]-------------- 2013/08/12 07:17:03 StartTime 1376261608.00 (Mon Aug 12 00:53:28 2013) 2013/08/12 07:17:03 EndTime 1376280240.63 (Mon Aug 12 06:04:00 2013) 2013/08/12 07:17:03 ElapsedTime 18632.63 (5 hours 10 minutes 32.63 seconds) 2013/08/12 07:17:03 SourceFiles 48013 2013/08/12 07:17:03 SourceFileSize 25044835718 (23.3 GB) 2013/08/12 07:17:03 MirrorFiles 48009 2013/08/12 07:17:03 MirrorFileSize 25044292133 (23.3 GB) 2013/08/12 07:17:03 NewFiles 10 2013/08/12 07:17:03 NewFileSize 18465 (18.0 KB) 2013/08/12 07:17:03 DeletedFiles 6 2013/08/12 07:17:03 DeletedFileSize 2445 (2.39 KB) 2013/08/12 07:17:03 ChangedFiles 232 2013/08/12 07:17:03 ChangedSourceSize 22105168135 (20.6 GB) 2013/08/12 07:17:03 ChangedMirrorSize 22104640570 (20.6 GB) 2013/08/12 07:17:03 IncrementFiles 248 2013/08/12 07:17:03 IncrementFileSize 19794534 (18.9 MB) 2013/08/12 07:17:03 TotalDestinationSizeChange 20338119 (19.4 MB) 2013/08/12 07:17:03 Errors 0 2013/08/12 07:17:03 -------------------------------------------------- 2013/08/12 07:17:03 Mon Aug 12 07:17:02 2013 Deleting .../backup/rdiff-backup-data/current_mirror.2013-08-11T00:55:43+02:00.data 2013/08/12 07:17:03 Mon Aug 12 07:17:03 2013 Cleaning up 2013/08/12 07:17:03 Mon Aug 12 07:17:03 2013 Touching .../backup/rdiff-backup-data/error_log.2013-08-12T00:53:28+02:00.data 2013/08/12 07:17:03 Backup phase done Now, the first timestamp comes from the wrapper I'm using, while the second ones are from rdiff-backup. The first thing I've noticed even before is that output from rdiff-backup seems to come in bursts. You can see that it's doing things at 05:56 that only get logged at 06:00. This seems to be normal operational mode, I assume there's a cache involved somewhere. All of that runs smoothly, until it reaches the end... There, for some reason, instead of the usual 4-5 minutes, it takes more than an hour for the log to get written! I have numerous other examples where this delay varies between 20 minutes and multiple hours. Now, part of this is to blame on the server. I run quite a lot of rdiff-backup operations simultaneously and this issue appears most obviously when there are a lot of them running. They start staggered, so the first ones usually finish without any delay as do the last ones, with a rise, peak, and drop off in between. However, if it were purely a server load issue, you would see the delays happening all through an rdiff-backup operation. Here, the delay only occurs at the very end of the operation, so rdiff-backup itself must be doing something then that it doesn't do earlier... And as long as I don't know exactly what it is, I can't really get to work on this because I don't know if I need more ram, more CPU power, more CPU speed, faster disks, ... Any thoughts? Laurent De Buyst ICT - System Administrator GSM: 0473/58.34.33
_______________________________________________ rdiff-backup-users mailing list at rdiff-backup-users@nongnu.org https://lists.nongnu.org/mailman/listinfo/rdiff-backup-users Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
