Hi Tim,
only a idea... did you use cleaning tapes?
Regards
Stefan
Am 21.08.2018 um 15:46 schrieb Tim
Banchi:
Hello,
I'm using Bareos 17.2 with the following pool, and device configuration:
Pool {
Name = tape_automated
Pool Type = Backup
Recycle = yes # Bareos can automatically recycle
Volumes
AutoPrune = yes # Prune expired volumes
#Recycle Oldest Volume = yes
RecyclePool = Scratch
Maximum Volume Bytes = 0
Job Retention = 365 days
Volume Retention = 4 weeks
Volume Use Duration = 12 days
Cleaning Prefix = "CLN"
Catalog Files = yes
Storage = delaunay_HP_G2_Autochanger #virtualfull test
# Next Pool = tape_automated
}
Device {
Name = "Ultrium920"
Media Type = LTO
Archive Device = /dev/st1
Autochanger = yes
LabelMedia = no
AutomaticMount = yes
AlwaysOpen = yes
RemovableMedia = yes
Maximum Spool Size = 50G
Spool Directory = /var/lib/bareos/spool
Maximum Block Size = 2097152
# Maximum Block Size = 4194304
Maximum Network Buffer Size = 32768
Maximum File Size = 50G
Alert Command = "/bin/bash -c '/usr/sbin/smartctl -H -l error %c'"
}
I'm closely monitoring tape performance (write speed + capacity marked as full
by bareos), and all tapes are losing capacity, and write speed, in an almost
linear way.
Over the period of roughly 8 months (I installed bareos early this year) and 3
to 4 write cycles per tape (=every 2 months a tape is rewritten), I've lost on
average 25% of the initial capacity per tape. E.g. some tapes started at
~400GB, and are now somewhere at 300GB. some started at 160GB, and are now
somewhere around 120GB.
Write-speed wise, I also lose speed: The fastest tapes (most often also the
tapes which have the highest capacity) started out at 50MB/s, and are now
somewhere at 42MB/s. The worst tapes are somewhere between 20MB/s, and are now
at 16MB/s.
Because most of the tapes were second-hand (we got tape drive, controller,
autoloader, and tapes as a gift, as our NGO doesn't have any money), I blamed
the bad state of tapes (I verify volume to catalog after each job, I assume I'm
still fine. Also there are no tape alerts).
But in the course of this year, I also introduced some brand new (never
written) tapes. And they are also losing capacity, and write speed to the same
amount.
Hardware compression, (software) encryption, and software compression is all ON
since the very beginning (so no configuration change). And I don't think this
can be relevant, because tapes are losing capacity over time, whether they
started off at ~406GB (new) or 160GB (used, and initial bad condition). It also
doesn't depend what I back up (everything is encrypted anyway, so compression
shouldn't work at all at the drive's side).
I don't know the logic how bareos recognises that a tape is full, so I thought I give it
a try to fill some tapes with zero/urandom to "realign" it. I could fully write
to those tapes (=400GB). But bareos continued to only partly use them as before. I then
tried to fill the tapes up with btape speed, but the same problem persists when using the
tape again in bareos.
Tape backups typically have job logs like:
....
*Joblog*
Connecting to Director localhost:9101
1000 OK: pavlov-dir Version: 17.2.4 (21 Sep 2017)
Enter a period to cancel a command.
list joblog jobid=7665
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
2018-08-18 06:37:51 pavlov-dir JobId 7665: Start Backup JobId 7665,
Job=edite_backup_automated.2018-08-18_05.30.00_34
2018-08-18 06:37:52 pavlov-dir JobId 7665: Using Device "Ultrium920" to write.
2018-08-18 06:37:53 delaunay-sd JobId 7665: 3307 Issuing autochanger "unload slot
2, drive 0" command.
2018-08-18 06:40:22 delaunay-sd JobId 7665: 3304 Issuing autochanger "load slot 1,
drive 0" command.
2018-08-18 06:41:06 delaunay-sd JobId 7665: 3305 Autochanger "load slot 1, drive
0", status is OK.
2018-08-18 06:41:15 delaunay-sd JobId 7665: Volume "XM2705L3" previously
written, moving to end of data.
2018-08-18 06:41:33 delaunay-sd JobId 7665: Ready to append to end of Volume
"XM2705L3" at file=5.
2018-08-18 06:41:33 delaunay-sd JobId 7665: Spooling data ...
2018-08-18 08:37:57 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,320 MaxDevSpoolSize=53,687,091,200
2018-08-18 08:37:57 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,320 bytes ...
2018-08-18 09:00:05 delaunay-sd JobId 7665: Despooling elapsed time =
00:22:08, Transfer rate = 40.42 M Bytes/second
2018-08-18 09:00:07 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 10:44:19 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,344 MaxDevSpoolSize=53,687,091,200
2018-08-18 10:44:19 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,344 bytes ...
2018-08-18 10:45:33 delaunay-sd JobId 7665: End of Volume "XM2705L3" at 6:1173 on
device "Ultrium920" (/dev/st1). Write of 2097152 bytes got -1.
2018-08-18 10:45:41 delaunay-sd JobId 7665: Re-read of last block succeeded.
2018-08-18 10:45:41 delaunay-sd JobId 7665: End of medium on Volume
"XM2705L3" Bytes=309,278,560,256 Blocks=147,476 at 18-Aug-2018 10:45.
2018-08-18 10:45:41 delaunay-sd JobId 7665: 3307 Issuing autochanger "unload slot
1, drive 0" command.
2018-08-18 10:46:50 pavlov-dir JobId 7665: Recycled volume "XM2770L3"
2018-08-18 10:46:50 pavlov-dir JobId 7665: Using Volume "XM2770L3" from
'Scratch' pool.
2018-08-18 10:46:51 delaunay-sd JobId 7665: 3304 Issuing autochanger "load slot 5,
drive 0" command.
2018-08-18 10:47:41 delaunay-sd JobId 7665: 3305 Autochanger "load slot 5, drive
0", status is OK.
2018-08-18 10:47:49 delaunay-sd JobId 7665: Recycled volume "XM2770L3" on device
"Ultrium920" (/dev/st1), all previous data lost.
2018-08-18 10:47:50 delaunay-sd JobId 7665: New volume "XM2770L3" mounted on device
"Ultrium920" (/dev/st1) at 18-Aug-2018 10:47.
2018-08-18 11:11:56 delaunay-sd JobId 7665: Despooling elapsed time =
00:25:28, Transfer rate = 35.13 M Bytes/second
2018-08-18 11:11:58 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 12:58:27 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,289 MaxDevSpoolSize=53,687,091,200
2018-08-18 12:58:27 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,289 bytes ...
2018-08-18 13:23:55 delaunay-sd JobId 7665: Despooling elapsed time =
00:25:28, Transfer rate = 35.13 M Bytes/second
2018-08-18 13:23:57 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 14:52:01 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,336 MaxDevSpoolSize=53,687,091,200
2018-08-18 14:52:01 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,336 bytes ...
2018-08-18 15:17:47 delaunay-sd JobId 7665: Despooling elapsed time =
00:25:46, Transfer rate = 34.72 M Bytes/second
2018-08-18 15:17:49 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 16:21:42 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,230 MaxDevSpoolSize=53,687,091,200
2018-08-18 16:21:42 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,230 bytes ...
2018-08-18 16:47:32 delaunay-sd JobId 7665: Despooling elapsed time =
00:25:50, Transfer rate = 34.63 M Bytes/second
2018-08-18 16:47:35 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 18:26:24 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,144 MaxDevSpoolSize=53,687,091,200
2018-08-18 18:26:24 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,144 bytes ...
2018-08-18 18:50:01 delaunay-sd JobId 7665: End of Volume "XM2770L3" at 4:22775 on
device "Ultrium920" (/dev/st1). Write of 2097152 bytes got -1.
2018-08-18 18:50:09 delaunay-sd JobId 7665: Re-read of last block succeeded.
2018-08-18 18:50:09 delaunay-sd JobId 7665: End of medium on Volume
"XM2770L3" Bytes=262,502,677,504 Blocks=125,171 at 18-Aug-2018 18:50.
2018-08-18 18:50:09 delaunay-sd JobId 7665: 3307 Issuing autochanger "unload slot
5, drive 0" command.
2018-08-18 18:51:18 pavlov-dir JobId 7665: Recycled volume "XM2728L3"
2018-08-18 18:51:18 pavlov-dir JobId 7665: Using Volume "XM2728L3" from
'Scratch' pool.
2018-08-18 18:51:18 delaunay-sd JobId 7665: 3304 Issuing autochanger "load slot 4,
drive 0" command.
2018-08-18 18:52:04 delaunay-sd JobId 7665: 3305 Autochanger "load slot 4, drive
0", status is OK.
2018-08-18 18:52:12 delaunay-sd JobId 7665: Recycled volume "XM2728L3" on device
"Ultrium920" (/dev/st1), all previous data lost.
2018-08-18 18:52:12 delaunay-sd JobId 7665: New volume "XM2728L3" mounted on device
"Ultrium920" (/dev/st1) at 18-Aug-2018 18:52.
2018-08-18 18:57:40 delaunay-sd JobId 7665: Despooling elapsed time =
00:29:13, Transfer rate = 30.62 M Bytes/second
2018-08-18 18:57:42 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 19:59:13 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,208 MaxDevSpoolSize=53,687,091,200
2018-08-18 19:59:13 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,208 bytes ...
2018-08-18 20:43:39 delaunay-sd JobId 7665: Despooling elapsed time =
00:44:26, Transfer rate = 20.13 M Bytes/second
2018-08-18 20:43:40 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 21:53:28 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,301 MaxDevSpoolSize=53,687,091,200
2018-08-18 21:53:28 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,301 bytes ...
2018-08-18 22:42:09 delaunay-sd JobId 7665: Despooling elapsed time =
00:48:41, Transfer rate = 18.37 M Bytes/second
2018-08-18 22:42:11 delaunay-sd JobId 7665: Spooling data again ...
2018-08-18 23:45:18 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,192 MaxDevSpoolSize=53,687,091,200
2018-08-18 23:45:18 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,192 bytes ...
2018-08-19 00:27:46 delaunay-sd JobId 7665: End of Volume "XM2728L3" at 2:22093 on
device "Ultrium920" (/dev/st1). Write of 2097152 bytes got -1.
2018-08-19 00:27:56 delaunay-sd JobId 7665: Re-read of last block succeeded.
2018-08-19 00:27:56 delaunay-sd JobId 7665: End of medium on Volume
"XM2728L3" Bytes=153,702,431,744 Blocks=73,291 at 19-Aug-2018 00:27.
2018-08-19 00:27:56 delaunay-sd JobId 7665: 3307 Issuing autochanger "unload slot
4, drive 0" command.
2018-08-19 00:29:01 pavlov-dir JobId 7665: Recycled volume "XM2589L3"
2018-08-19 00:29:01 pavlov-dir JobId 7665: Using Volume "XM2589L3" from
'Scratch' pool.
2018-08-19 00:29:02 delaunay-sd JobId 7665: 3304 Issuing autochanger "load slot 3,
drive 0" command.
2018-08-19 00:29:44 delaunay-sd JobId 7665: 3305 Autochanger "load slot 3, drive
0", status is OK.
2018-08-19 00:29:52 delaunay-sd JobId 7665: Recycled volume "XM2589L3" on device
"Ultrium920" (/dev/st1), all previous data lost.
2018-08-19 00:29:52 delaunay-sd JobId 7665: New volume "XM2589L3" mounted on device
"Ultrium920" (/dev/st1) at 19-Aug-2018 00:29.
2018-08-19 00:34:05 delaunay-sd JobId 7665: Despooling elapsed time =
00:46:51, Transfer rate = 19.09 M Bytes/second
2018-08-19 00:34:07 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 02:15:45 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,168 MaxDevSpoolSize=53,687,091,200
2018-08-19 02:15:45 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,168 bytes ...
2018-08-19 02:35:57 delaunay-sd JobId 7665: Despooling elapsed time =
00:20:12, Transfer rate = 44.29 M Bytes/second
2018-08-19 02:35:59 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 03:48:39 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,243 MaxDevSpoolSize=53,687,091,200
2018-08-19 03:48:39 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,243 bytes ...
2018-08-19 04:08:50 delaunay-sd JobId 7665: Despooling elapsed time =
00:20:11, Transfer rate = 44.33 M Bytes/second
2018-08-19 04:08:52 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 05:16:55 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,254 MaxDevSpoolSize=53,687,091,200
2018-08-19 05:16:55 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,254 bytes ...
2018-08-19 05:37:11 delaunay-sd JobId 7665: Despooling elapsed time =
00:20:16, Transfer rate = 44.15 M Bytes/second
2018-08-19 05:37:14 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 07:02:12 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,145 MaxDevSpoolSize=53,687,091,200
2018-08-19 07:02:12 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,145 bytes ...
2018-08-19 07:22:41 delaunay-sd JobId 7665: Despooling elapsed time =
00:20:29, Transfer rate = 43.68 M Bytes/second
2018-08-19 07:22:43 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 08:42:50 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,171 MaxDevSpoolSize=53,687,091,200
2018-08-19 08:42:50 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,171 bytes ...
2018-08-19 09:03:20 delaunay-sd JobId 7665: Despooling elapsed time =
00:20:30, Transfer rate = 43.64 M Bytes/second
2018-08-19 09:03:21 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 11:04:53 delaunay-sd JobId 7665: User specified Device spool size
reached: DevSpoolSize=53,687,398,236 MaxDevSpoolSize=53,687,091,200
2018-08-19 11:04:53 delaunay-sd JobId 7665: Writing spooled data to Volume.
Despooling 53,687,398,236 bytes ...
2018-08-19 11:25:02 delaunay-sd JobId 7665: Despooling elapsed time =
00:20:09, Transfer rate = 44.40 M Bytes/second
2018-08-19 11:25:04 delaunay-sd JobId 7665: Spooling data again ...
2018-08-19 13:09:41 delaunay-sd JobId 7665: Committing spooled data to Volume
"XM2589L3". Despooling 48,362,707,754 bytes ...
2018-08-19 13:21:48 delaunay-sd JobId 7665: End of Volume "XM2589L3" at 6:21058 on
device "Ultrium920" (/dev/st1). Write of 2097152 bytes got -1.
2018-08-19 13:21:55 delaunay-sd JobId 7665: Re-read of last block succeeded.
2018-08-19 13:21:55 delaunay-sd JobId 7665: End of medium on Volume
"XM2589L3" Bytes=366,271,855,616 Blocks=174,652 at 19-Aug-2018 13:21.
2018-08-19 13:21:55 delaunay-sd JobId 7665: 3307 Issuing autochanger "unload slot
3, drive 0" command.
2018-08-19 13:23:02 pavlov-dir JobId 7665: Recycled volume "XM2753L3"
2018-08-19 13:23:02 pavlov-dir JobId 7665: Using Volume "XM2753L3" from
'Scratch' pool.
2018-08-19 13:23:03 delaunay-sd JobId 7665: 3304 Issuing autochanger "load slot 6,
drive 0" command.
2018-08-19 13:23:48 delaunay-sd JobId 7665: 3305 Autochanger "load slot 6, drive
0", status is OK.
2018-08-19 13:23:56 delaunay-sd JobId 7665: Recycled volume "XM2753L3" on device
"Ultrium920" (/dev/st1), all previous data lost.
2018-08-19 13:23:56 delaunay-sd JobId 7665: New volume "XM2753L3" mounted on device
"Ultrium920" (/dev/st1) at 19-Aug-2018 13:23.
2018-08-19 13:29:30 delaunay-sd JobId 7665: Despooling elapsed time =
00:17:48, Transfer rate = 45.28 M Bytes/second
2018-08-19 13:29:31 delaunay-sd JobId 7665: Elapsed time=30:39:49, Transfer
rate=7.726 M Bytes/second
2018-08-19 13:29:37 delaunay-sd JobId 7665: Alert: smartctl 6.5 2016-01-24
r4214 [x86_64-linux-4.4.0-128-generic] (local build)
2018-08-19 13:29:37 delaunay-sd JobId 7665: Alert: Copyright (C) 2002-16,
Bruce Allen, Christian Franke, www.smartmontools.org
2018-08-19 13:29:37 delaunay-sd JobId 7665: Alert:
2018-08-19 13:29:37 delaunay-sd JobId 7665: Alert: === START OF READ SMART
DATA SECTION ===
2018-08-19 13:29:37 delaunay-sd JobId 7665: Alert: TapeAlert: OK
2018-08-19 13:29:37 delaunay-sd JobId 7665: Alert: Error Counter logging not
supported
2018-08-19 13:29:38 delaunay-sd JobId 7665: Alert:
2018-08-19 13:29:38 delaunay-sd JobId 7665: Alert: Last n error events log
page
2018-08-19 13:29:38 delaunay-sd JobId 7665: Alert:
2018-08-19 13:29:38 delaunay-sd JobId 7665: Sending spooled attrs to the
Director. Despooling 546,349 bytes ...
2018-08-19 13:29:41 pavlov-dir JobId 7665: sql_create.c:872 Insert of
attributes batch table done
2018-08-19 13:29:42 pavlov-dir JobId 7665: Bareos pavlov-dir 17.2.4 (21Sep17):
Build OS: x86_64-pc-linux-gnu ubuntu Ubuntu 16.04 LTS
JobId: 7665
Job: edite_backup_automated.2018-08-18_05.30.00_34
Backup Level: Full
Client: "edite-fd" 17.2.4 (21Sep17)
x86_64-pc-linux-gnu,ubuntu,Ubuntu 14.04 LTS,xUbuntu_14.04,x86_64
FileSet: "edite_backup_automated" 2017-11-09 17:30:00
Pool: "tape_automated" (From Job FullPool override)
Catalog: "MyCatalog" (From Client resource)
Storage: "delaunay_HP_G2_Autochanger" (From Pool resource)
Scheduled time: 18-Aug-2018 05:30:00
Start time: 18-Aug-2018 06:37:53
End time: 19-Aug-2018 13:29:41
Elapsed time: 1 day 6 hours 51 mins 48 secs
Priority: 10
FD Files Written: 1,477
SD Files Written: 1,477
FD Bytes Written: 852,961,750,064 (852.9 GB)
SD Bytes Written: 852,962,743,625 (852.9 GB)
Rate: 7676.9 KB/s
Software Compression: 52.7 % (lz4hc)
VSS: no
Encryption: yes
Accurate: no
Volume name(s): XM2705L3|XM2770L3|XM2728L3|XM2589L3|XM2753L3
Volume Session Id: 48
Volume Session Time: 1533895587
Last Volume Bytes: 15,015,682,048 (15.01 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
2018-08-19 13:29:42 pavlov-dir JobId 7665: shell command: run AfterJob "/bin/bash -c '/bin/echo
"run edite_backup_automated_v yes" | bconsole >/dev/null'"
You have messages.
Does anybody have an explanation or solution to that problem?
--
CaC, Computer and Communication
Inhaber Stefan Klatt
End-2-End Senior Security Consultant
CISSP / CISM / ISO27001 Lead Implementer / TOGAF9 /
VdS-anerkannter Berater für Cyber-Security
Badges: https://www.youracclaim.com/users/stefan-klatt
Triftstrasse 9
60528 Frankfurt
Germany
USt-IdNr.: DE260461592
Tel.: +49-(0)172-6807809
Tel.: +49-(0)69-67808-900
Fax: +49-(0)69-67808-837
Email: [email protected]
Profil: http://www.cac-netzwerk.de/profil
