Hi.
In my small home network I use bacula on a Solaris 9 box to back up three
computers. Bacula spools data to local disk in 2 GB chunks before writing to
tape, and it has been humming along nicely for a year or so. Suddenly, a couple
of weeks ago, it started to spool less than configured, only about 260 MB.
There's plenty of space available on the spool disk.
Not a big problem really for me, but I thought it could be interesting for
someone out there? I havn't tried to solve this problem yet, but will do unless
someone wants more info from me.
Server: solaris 9 with bacula 1.36.1 and one DLT8000 tape, this is from bacula-
sd.conf:
Device {
Name = DLT1 #
Media Type = DLT8000
Archive Device = /dev/rmt/0cbn
AutomaticMount = yes # when device opened, read it
AlwaysOpen = yes
RemovableMedia = yes
RandomAccess = no
MaximumSpoolSize = 2G
SpoolDirectory = "/opt/packages/bacula/data/spool"
OfflineOnUnmount = yes
}
These examples are from a backup of a windows machine, but
the same happens when the bacula server backs up itself.
A completion report. Notice that it says "despooling 2G" 21 times, but "SD
bytes
written" is only 5GB (which is correct)
----------------------------------------------
24-Aug 09:46 aron-dir: Start Backup JobId 1040, Job=Alf.2005-08-24_07.07.00
24-Aug 09:46 aron-sd: Spooling data ...
24-Aug 09:49 alf-fd: Cannot open C:/Program
Files/Canon/MultiPASS/repos/Db/mpdata.dat: ERR=The process cannot access the
file
because it is being used by another process.
.
24-Aug 09:49 alf-fd: Cannot open C:/Program
Files/Canon/MultiPASS/repos/Db/mpdata.idx: ERR=The process cannot access the
file
because it is being used by another process.
.
24-Aug 09:49 aron-sd: User specified spool size reached.
24-Aug 09:49 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,926
bytes ...
24-Aug 09:50 aron-sd: Spooling data again ...
24-Aug 09:52 aron-sd: User specified spool size reached.
24-Aug 09:52 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,905
bytes ...
24-Aug 09:52 aron-sd: Spooling data again ...
24-Aug 09:54 aron-sd: User specified spool size reached.
24-Aug 09:54 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,924
bytes ...
24-Aug 09:55 aron-sd: End of Volume "Diff-0006" at 58:10738 on device
/dev/rmt/0cbn. Write of 64512 bytes got 0.
24-Aug 09:56 aron-sd: Re-read of last block succeeded.
24-Aug 09:56 aron-sd: End of medium on Volume "Diff-0006" Bytes=54,005,158,759
Blocks=837,139 at 24-Aug-2005 09:56.
24-Aug 09:56 aron-dir: Recycled volume "Diff-0007"
24-Aug 09:56 aron-sd: Please mount Volume "Diff-0007" on Storage Device "DLT1"
for Job Alf.2005-08-24_07.07.00
24-Aug 10:56 aron-sd: Please mount Volume "Diff-0007" on Storage Device "DLT1"
for Job Alf.2005-08-24_07.07.00
24-Aug 11:33 aron-sd: Recycled volume "Diff-0007" on device "/dev/rmt/0cbn",
all
previous data lost.
24-Aug 11:33 aron-sd: New volume "Diff-0007" mounted on device /dev/rmt/0cbn at
24-Aug-2005 11:33.
24-Aug 11:33 aron-sd: Spooling data again ...
24-Aug 11:35 aron-sd: User specified spool size reached.
24-Aug 11:35 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,909
bytes ...
24-Aug 11:36 aron-sd: Spooling data again ...
24-Aug 11:37 aron-sd: User specified spool size reached.
24-Aug 11:37 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,922
bytes ...
24-Aug 11:38 aron-sd: Spooling data again ...
24-Aug 11:39 aron-sd: User specified spool size reached.
24-Aug 11:39 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,926
bytes ...
24-Aug 11:41 aron-sd: Spooling data again ...
24-Aug 11:42 aron-sd: User specified spool size reached.
24-Aug 11:42 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,897
bytes ...
24-Aug 11:43 aron-sd: Spooling data again ...
24-Aug 11:44 aron-sd: User specified spool size reached.
24-Aug 11:44 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,878
bytes ...
24-Aug 11:45 aron-sd: Spooling data again ...
24-Aug 11:46 aron-sd: User specified spool size reached.
24-Aug 11:46 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,884
bytes ...
24-Aug 11:47 aron-sd: Spooling data again ...
24-Aug 11:47 aron-sd: User specified spool size reached.
24-Aug 11:47 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,886
bytes ...
24-Aug 11:48 aron-sd: Spooling data again ...
24-Aug 11:49 aron-sd: User specified spool size reached.
24-Aug 11:49 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,888
bytes ...
24-Aug 11:50 aron-sd: Spooling data again ...
24-Aug 11:51 aron-sd: User specified spool size reached.
24-Aug 11:51 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,878
bytes ...
24-Aug 11:52 aron-sd: Spooling data again ...
24-Aug 11:53 aron-sd: User specified spool size reached.
24-Aug 11:53 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,878
bytes ...
24-Aug 11:54 aron-sd: Spooling data again ...
24-Aug 11:55 aron-sd: User specified spool size reached.
24-Aug 11:55 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,886
bytes ...
24-Aug 11:56 aron-sd: Spooling data again ...
24-Aug 11:57 aron-sd: User specified spool size reached.
24-Aug 11:57 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,902
bytes ...
24-Aug 11:58 aron-sd: Spooling data again ...
24-Aug 11:59 aron-sd: User specified spool size reached.
24-Aug 11:59 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,901
bytes ...
24-Aug 12:00 aron-sd: Spooling data again ...
24-Aug 12:01 aron-sd: User specified spool size reached.
24-Aug 12:01 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,886
bytes ...
24-Aug 12:02 aron-sd: Spooling data again ...
24-Aug 12:03 aron-sd: User specified spool size reached.
24-Aug 12:03 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,878
bytes ...
24-Aug 12:04 aron-sd: Spooling data again ...
24-Aug 12:05 aron-sd: User specified spool size reached.
24-Aug 12:05 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,886
bytes ...
24-Aug 12:06 aron-sd: Spooling data again ...
24-Aug 12:07 aron-sd: User specified spool size reached.
24-Aug 12:07 aron-sd: Writing spooled data to Volume. Despooling 2,147,497,893
bytes ...
24-Aug 12:08 aron-sd: Spooling data again ...
24-Aug 12:09 aron-sd: Committing spooled data to Volume. Despooling
2,050,419,334
bytes ...
24-Aug 12:10 aron-sd: Sending spooled attrs to the Director. Despooling
2,586,536
bytes ...
24-Aug 12:11 aron-dir: Bacula 1.36.1 (26Nov04): 24-Aug-2005 12:11:00
JobId: 1040
Job: Alf.2005-08-24_07.07.00
Backup Level: Differential, since=2005-03-16 21:16:40
Client: alf-fd
FileSet: "Alf Files" 2004-12-19 18:24:41
Pool: "Diff"
Storage: "DLT1"
Start time: 24-Aug-2005 09:46:45
End time: 24-Aug-2005 12:11:00
FD Files Written: 7,974
SD Files Written: 7,974
FD Bytes Written: 5,572,580,207
SD Bytes Written: 5,573,990,439
Rate: 643.9 KB/s
Software Compression: None
Volume name(s): Diff-0006|Diff-0007
Volume Session Id: 81
Volume Session Time: 1123050581
Last Volume Bytes: 4,886,684,427
Non-fatal FD errors: 2
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK -- with warnings
24-Aug 12:11 aron-dir: Begin pruning Jobs.
24-Aug 12:11 aron-dir: Pruned 1 Job for client alf-fd from catalog.
24-Aug 12:11 aron-dir: Begin pruning Files.
24-Aug 12:11 aron-dir: Pruned 5,877 Files from 1 Jobs for client alf-fd from
catalog.
24-Aug 12:11 aron-dir: End auto prune.
----------------------------------------------------------
while the backup was running, I truss'ed bacula-sd:
----------------------------------------------------------
/161: read(7, " t M x q E8F , BE1E0 QE9".., 32768) = 32768
/161: read(7, "\0\080\0", 4) = 4
/161: read(7, "ACA018 5 yF697 [B0D29993".., 32768) = 32768
/161: write(8, "\0\01F12\0\01F12\0\0FC\0", 12) = 12
/161: write(8, " U U U U U U U U U U U U".., 64512) = 64512
/161: read(7, "\0\080\0", 4) = 4
/161: read(7, "C3 # B + p YD7FF ' R =C2".., 32768) = 32768
/161: read(7, "\0\080\0", 4) = 4
/161: read(7, "EDD202EBE5 t8BF0BCBBD6 Z".., 32768) = 32768
/161: write(8, "\0\01F12\0\01F12\0\0FC\0", 12) = 12
/161: write(8, " U U U U U U U U U U U U".., 64512) = 64512
/161: read(7, "\0\080\0", 4) = 4
/161: read(7, "C9 xB2 G9ED3 a k ' 6 x g".., 32768) = 32768
/161: read(7, "\0\080\0", 4) = 4
/161: read(7, "D7 BC r ; yF785F71B\n \".., 32768) = 32768
/161: time() = 1124876980
/161: write(6, "\0\0\0 e", 4) = 4
/161: write(6, 0x000733F0, 101) = 101
/161: J m s g J o b = A l f . 2 0 0 5 - 0 8 - 2 4 _ 0 7 . 0 7 . 0 0
/161: t y p e = 6 l e v e l = 1 1 2 4 8 7 6 9 8 0 a r o n - s d
/161: : U s e r s p e c i f i e d s p o o l s i z e r e a c
/161: h e d .\n
/161: time() = 1124876980
/161: write(6, "\0\0\085", 4) = 4
/161: write(6, 0x000733F0, 133) = 133
/161: J m s g J o b = A l f . 2 0 0 5 - 0 8 - 2 4 _ 0 7 . 0 7 . 0 0
/161: t y p e = 6 l e v e l = 1 1 2 4 8 7 6 9 8 0 a r o n - s d
/161: : W r i t i n g s p o o l e d d a t a t o V o l u m e
/161: . D e s p o o l i n g 2 , 1 4 7 , 4 9 7 , 8 8 8 b y t e s
/161: . . .\n
/161: llseek(8, 0, SEEK_SET) = 0
/161: read(8, "\0\01F10\0\01F10\0\0FC\0", 12) = 12
/161: read(8, " U U U U U U U U U U U U".., 64512) = 64512
/161: write(3, " ADEBD9E\0\0FC\0\0\0\0\0".., 64512) = 64512
/161: read(8, "\0\01F10\0\01F10\0\0FC\0", 12) = 12
/161: read(8, " U U U U U U U U U U U U".., 64512) = 64512
/161: write(3, "9B\012EE\0\0FC\0\0\0\001".., 64512) = 64512
/161: read(8, "\0\01F10\0\01F10\0\0FC\0", 12) = 12
/161: read(8, " U U U U U U U U U U U U".., 64512) = 64512
/161: write(3, " N PDDF9\0\0FC\0\0\0\002".., 64512) = 64512
/161: read(8, "\0\01F10\0\01F10\0\0FC\0", 12) = 12
/161: read(8, " U U U U U U U U U U U U".., 64512) = 64512
/161: write(3, "DDF9EE U\0\0FC\0\0\0\003".., 64512) = 64512
/161: read(8, "\0\01F10\0\01F10\0\0FC\0", 12) = 12
----------------------------------------------------------------
and lastly, a few commands from when the backup was running.
----------------------------------------------------------------
# ll
total 528336
-rw-r----- 1 root root 270355520 Aug 19 20:17 aron-
sd.data.spool.Alf.2005-08-19_07.07.00.DLT1
# df -k
Filesystem kbytes used avail capacity Mounted on
/dev/md/dsk/d0 5041230 4018076 972742 81% /
/proc 0 0 0 0% /proc
mnttab 0 0 0 0% /etc/mnttab
fd 0 0 0 0% /dev/fd
/dev/md/dsk/d3 577391 269110 250542 52% /var
swap 459888 56 459832 1% /var/run
swap 489536 29704 459832 7% /tmp
/dev/md/dsk/d4 110004472 38612674 70291754 36% /.d4
# ll
total 528336
-rw-r----- 1 root root 270355520 Aug 19 20:17 aron-
sd.data.spool.Alf.2005-08-19_07.07.00.DLT1
# du -h
258M .
# df -k .
Filesystem kbytes used avail capacity Mounted on
/dev/md/dsk/d4 110004472 38612674 70291754 36% /.d4
#
# pwd
/opt/packages/bacula/data/spool
# ll
total 528336
-rw-r----- 1 root root 270355543 Aug 24 11:35 aron-
sd.data.spool.Alf.2005-08-24_07.07.00.DLT1
# df -k .
Filesystem kbytes used avail capacity Mounted on
/dev/md/dsk/d4 110004472 38862174 70042254 36% /.d4
# du
258M .
# ll
total 88160
-rw-r----- 1 root root 45102276 Aug 24 11:36 aron-
sd.data.spool.Alf.2005-08-24_07.07.00.DLT1
# ll
total 528336
-rw-r----- 1 root root 270355556 Aug 24 11:37
aron-sd.data.spool.Alf.2005-08-24_07.07.00.DLT1
# df -h .
Filesystem size used avail capacity Mounted on
/dev/md/dsk/d4 105G 37G 67G 36% /.d4
# ll
total 528336
-rw-r----- 1 root root 270355560 Aug 24 11:39 aron-
sd.data.spool.Alf.2005-08-24_07.07.00.DLT1
# ll
total 528336
-rw-r----- 1 root root 270355531 Aug 24 11:42 aron-
sd.data.spool.Alf.2005-08-24_07.07.00.DLT1
# df -h .
Filesystem size used avail capacity Mounted on
/dev/md/dsk/d4 105G 37G 67G 36% /.d4
# ll
total 528336
-rw-r----- 1 root root 270355512 Aug 24 11:44
aron-sd.data.spool.Alf.2005-08-24_07.07.00.DLT1
-------------------------------------------------------
SF.Net email is Sponsored by the Better Software Conference & EXPO
September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices
Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA
Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
