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
On 21.08.2018 15:46, Tim Banchi wrote:
> 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+unsubscr...@googlegroups.com.
To post to this group, send email to bareos-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
