[bareos-users] losing LTO3 tape capacity with bareos. But full tape length can be written with dd or btape speed

Discussion:

Tim Banchi

2018-08-21 13:46:33 UTC

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?

--
You received this message because you are subscribed to the Google Groups "bareos-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bareos-users+***@googlegroups.com.
To post to this group, send email to bareos-***@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Stefan Klatt

2018-08-21 20:38:24 UTC

Permalink

Hi Tim,

only a idea... did you use cleaning tapes?

Regards

Stefan

Post by Tim Banchi
Hello,
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.
....
*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: === 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: Last n error events log page
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
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: ***@cac-netzwerk.de
Profil: http://www.cac-netzwerk.de/profil

Tim Banchi

2018-08-22 07:40:11 UTC

Permalink

Hi Stefan,

yes, I use newly purchased ones when the autoloader/drive requested it. I got clean requests when getting I/O errors with really bad tapes (which I then dumped right away). Otherwise there have been so far no cleaning requests (which is normal to my experience), and the status of the drive is OK. I also looked up regularly logged warnings/errors, and there is nothing (except the aforementioned I/O errors)

Post by Stefan Klatt
Hi Tim,
only a idea... did you use cleaning tapes?
Regards
Stefan
Am 21.08.2018 um 15:46 schrieb Tim
Hello,
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.
....
*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: === 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: Last n error events log page
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
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
Profil: http://www.cac-netzwerk.de/profil

Kai Zimmer

2018-08-22 08:12:38 UTC

Permalink

Hi Tim,

does the drive have a self test function in the firmware? If so, try it.
If not, maybe there is a test software from the vendor available?

Best regards,
Kai

Post by Tim Banchi
Hi Stefan,
yes, I use newly purchased ones when the autoloader/drive requested it. I got clean requests when getting I/O errors with really bad tapes (which I then dumped right away). Otherwise there have been so far no cleaning requests (which is normal to my experience), and the status of the drive is OK. I also looked up regularly logged warnings/errors, and there is nothing (except the aforementioned I/O errors)

Post by Stefan Klatt
Hi Tim,
only a idea... did you use cleaning tapes?
Regards
Stefan
Am 21.08.2018 um 15:46 schrieb Tim
Hello,
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.
....
*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: === 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: Last n error events log page
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
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
Profil: http://www.cac-netzwerk.de/profil

Tim Banchi

2018-08-22 12:08:58 UTC

Permalink

Hi Kai,

thanks, the HP LTT tools contain a diagnostic test (my drive is a HP Ultrium920 SCSI LTO3 drive). There should also be a 5-second self test on every power up. So far, this always succeeded (I never got a error message on the autoloader display or in the logs).

I remember, that I did this LTT diagnostic when configuring the drive in January. However, right now, I don't have a access to a physical Windows Server any more where I could try that quickly out.

Post by Stefan Klatt
Hi Tim,
does the drive have a self test function in the firmware? If so, try it.
If not, maybe there is a test software from the vendor available?
Best regards,
Kai

Stefan Klatt

2018-08-22 10:22:16 UTC

Permalink

Hi Tim,

hmmm..... "Hardware compression, (software) encryption, and software
compression"
That's probably overkill. Could you disable hardware compression? This
can slow down backup if the data is encrypted (and compressed).

Stefan

Tim Banchi

2018-08-22 12:29:42 UTC

Permalink

Hi Kai,

I thought about disabling hardware compression, but doing that in a permanent way, I think I would have had to re-install a OS which runs LTT (other ways via Linux seemed to me not conclusive enough, or I didn't find that information).

I also read at numerous occasions that >= LTO-2 drives handle hardware compression quite well (e.g. not increasing data usage when compressing uncompressable data like encrypted data).

ad software compression: we (have to) use quite a slow internal network, so software compression at the client seemed reasonable to me.

Post by Stefan Klatt
Hi Tim,
hmmm..... "Hardware compression, (software) encryption, and software
compression"
That's probably overkill. Could you disable hardware compression?
This can slow down backup if the data is encrypted (and compressed).
Stefan
Am 22.08.2018 um 09:40 schrieb Tim
Hi Stefan,
yes, I use newly purchased ones when the autoloader/drive requested it. I got clean requests when getting I/O errors with really bad tapes (which I then dumped right away). Otherwise there have been so far no cleaning requests (which is normal to my experience), and the status of the drive is OK. I also looked up regularly logged warnings/errors, and there is nothing (except the aforementioned I/O errors)
Hi Tim,
only a idea... did you use cleaning tapes?
Regards
Stefan
Am 21.08.2018 um 15:46 schrieb Tim
Hello,
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.
....
*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: === 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: Last n error events log page
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
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
Profil: http://www.cac-netzwerk.de/profil
--
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
Profil: http://www.cac-netzwerk.de/profil

Udo Lembke

2018-08-23 03:09:07 UTC

Permalink

Hi Tim,
if dd use the full speed instead of bareos, whats about an IO-limitation
on the source - the spool-disk?
In your example, the first 50-gb spoolfile was transferred with 40MB/s
the later ones with 35MB/s.
Does the spool-disks was filled with other backup-jobs (writes) during
the despooling?

What kind of spool-disks are in use (raid level, how much disks, what
kind of disks/ssd)?

I had an high load on the backup-server with an spooldisk (for 3 lto-4
drives) with raid10 on 6*SAS 15k disks.
With raid0 (the spool disks only) the load was ok.

Udo

Tim Banchi

2018-08-23 08:42:56 UTC

Permalink

Hi Udo,

it's not only about decreasing write-speed, but also about decreasing capacity. Also, when a good tape follows a bad tape, write speed is back again around 40MB/s. A tape normally keeps it's write speed over the full length of the tape (be it either ~20MB/s or ~40MB/s).

to the hardware: it's 2 normal SATA disks in dm-Raid 1, The spool directory is on a separate volume of ~100GB to prevent fragmentation. I tested the disks before, and they easily deliver 80MB/s sequential.

Beside running the bareos-storage daemon for tape backup, there is nothing else going on on this server (bareos-director and disk backup is on a another server).

It seems the only way to find out is buying another LTO-3 drive?

Post by Stefan Klatt
Hi Tim,
if dd use the full speed instead of bareos, whats about an IO-limitation
on the source - the spool-disk?
In your example, the first 50-gb spoolfile was transferred with 40MB/s
the later ones with 35MB/s.
Does the spool-disks was filled with other backup-jobs (writes) during
the despooling?
What kind of spool-disks are in use (raid level, how much disks, what
kind of disks/ssd)?
I had an high load on the backup-server with an spooldisk (for 3 lto-4
drives) with raid10 on 6*SAS 15k disks.
With raid0 (the spool disks only) the load was ok.
Udo

Tim Banchi

2018-11-05 10:29:15 UTC

Permalink

Hello,

Last week I managed to get another drive (LTO4 SAS HP 1760), and it seems it's drive related.

So far I tested 4 tapes in the LTO4 drive, and all tapes are fully written written (407GB) and with "full" speed (~55MB/s). Verify volumetocatalog is OK, I haven't restored yet, but will test this as well.

Post by Tim Banchi
Hi Udo,
it's not only about decreasing write-speed, but also about decreasing capacity. Also, when a good tape follows a bad tape, write speed is back again around 40MB/s. A tape normally keeps it's write speed over the full length of the tape (be it either ~20MB/s or ~40MB/s).
to the hardware: it's 2 normal SATA disks in dm-Raid 1, The spool directory is on a separate volume of ~100GB to prevent fragmentation. I tested the disks before, and they easily deliver 80MB/s sequential.
Beside running the bareos-storage daemon for tape backup, there is nothing else going on on this server (bareos-director and disk backup is on a another server).
It seems the only way to find out is buying another LTO-3 drive?