[rdiff-backup-users] Delay between EndTime and process end - followup

[Laurent De Buyst]

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