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

[Laurent De Buyst]

Hello again and thanks for the repsonse yesterday.


One other issue we're having that has us
a bit baffled is that the EndTime as reported by the script (--stats option)
does not seem to correspond to the end of the process.

We're calling rdiff-backup through a python
subprocess call which gives us timestamped logs and, well, some examples
should make it clear:


2013/07/30 08:47:50 STOP    
  Operation log:
--------------[ Session statistics ]--------------
StartTime 1375145098.00 (Tue Jul 30 02:44:58
2013)
EndTime 1375166863.38 (Tue Jul 30 08:47:43
2013)

Here we have a delay of 7 seconds between
the reported EndTime and the end of the subprocess call.


2013/07/30 08:41:11 STOP    
  Operation log:
--------------[ Session statistics ]--------------
StartTime 1375140698.00 (Tue Jul 30 01:31:38
2013)
EndTime 1375160443.17 (Tue Jul 30 07:00:43
2013)

An hour and 40 minutes difference...


2013/07/30 07:01:52 STOP    
  Operation log:
--------------[ Session statistics ]--------------
StartTime 1375127531.00 (Mon Jul 29 21:52:11
2013)
EndTime 1375129267.41 (Mon Jul 29 22:21:07
2013)

Almost 9 hours of difference!


Now my question is: is there anything in
rdiff-backup itself that could explain this? Some part of the script that
still runs after the stats are printed and that could suffer big delays?
If that's not it, then we clearly need to look into our I/O, possibly our
write cache, but I'd like to eliminate the easy possibilities first.

Thanks in advance

---

Laurent De Buyst
ICT - System Administrator