Project

General

Profile

Bug #39932

Restore ports build optimization while retaining debug symbols

Added by Noel Miller about 2 years ago. Updated almost 2 years ago.

Status:
Done
Priority:
No priority
Assignee:
Alexander Motin
Category:
OS
Target version:
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
No
Needs Doc:
No
Needs Merging:
No
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:

Motherboard: Super X10SDV-8C-TLN4F CPU: Intel Xeon D-1541 2.10 GHz Memory: 65403MB DDR4 Drives: FreeNAS installed on SuperMicro Sata dom, unsure of model. Volumes are hosted in a SuperMicro JBOD(SC847E26-RJBOD1) linked to FreeNAS box with SAS cable and are Seagate Constellation ES SAS(ST32000444SS), 12 of them,

ChangeLog Required:
No

Description

Original ticket:
Rsync is writing at half speed between local volumes after upgrade from 9.10.2-U5 to 11.0-U1. We run Rsync through a script sitting on FreeNAS.

The screen captures are still accurate in the previous ticket that we have submitted for this issue.

You have said on multiple occasions that this has been fixed in updates, but we are running the beta and still seeing the issue.

Let us know if you need any additional information or testing that needs to be done.

DR-NAS2.PNG (36.6 KB) DR-NAS2.PNG Test from NAS Noel Miller, 07/30/2018 06:52 AM
rsync_9.10.2u5 (446 KB) rsync_9.10.2u5 old binary Ryan McKenzie, 08/24/2018 10:13 AM
rsync_11.0u1 (639 KB) rsync_11.0u1 standard binary Ryan McKenzie, 08/24/2018 10:13 AM
Copy of a 2.976 GiB ISO File (bandwidth).png (18.5 KB) Copy of a 2.976 GiB ISO File (bandwidth).png Ryan McKenzie, 09/05/2018 09:37 AM
python_benchmarks.png (87.5 KB) python_benchmarks.png Ryan McKenzie, 09/10/2018 01:50 PM
11.1u5 vs. 11.2 Stable - 4KiB Random OPS.png (16.8 KB) 11.1u5 vs. 11.2 Stable - 4KiB Random OPS.png Ryan McKenzie, 10/19/2018 11:18 AM
23131
28444
29320
35385

Subtasks

Bug #25343: Rsync writing at half speed after upgrade from 9.10.2U5 to 11.0-U1ClosedAlexander Motin

Related issues

Related to FreeNAS - Bug #47459: Restore ports build optimization while retaining debug symbolsDone

Associated revisions

Revision 4af883d1 (diff)
Added by Alexander Motin about 2 years ago

Set DESTDIR=${STAGEDIR} instead of prepending ${STAGEDIR} to paths. It makes freenas-sysctl install debug files in proper place. Ticket: #39932

Revision 665e5797 (diff)
Added by Alexander Motin about 2 years ago

Set DESTDIR=${STAGEDIR} instead of prepending ${STAGEDIR} to paths. (#1810) It makes freenas-sysctl install debug files in proper place. Ticket: #39932

Revision 65394ccf (diff)
Added by John Hixson about 2 years ago

Kill forced Samba debug flags Ticket: #39932

Revision a4eb4d7c (diff)
Added by Alexander Motin about 2 years ago

Polish debug information generation for base OS. Modern FreeBSD can generate separate debug information files on its own for both kernel and world. Use it where possible, and do things manually only for ports, since they have no such functionality AFAIK. Before this the debug package was no including kernel symbols at all. Ticket: #39932

Revision a09755ce (diff)
Added by Alexander Motin about 2 years ago

Remove unneeded nestind level (world) in debug package. Ticket: #39932

Revision 71aec7b6 (diff)
Added by John Hixson about 2 years ago

Kill forced Samba debug flags Ticket: #39932

Revision 2d29b079 (diff)
Added by Alexander Motin about 2 years ago

Remove one more debug enable from Samba. After this change I do finally see that binary is getting smaller, while there are still some debug symbols produced. Ticket: #39932

Revision 0d63f546 (diff)
Added by Alexander Motin about 2 years ago

Polish debug information generation for base OS. Modern FreeBSD can generate separate debug information files on its own for both kernel and world. Use it where possible, and do things manually only for ports, since they have no such functionality AFAIK. Before this the debug package was no including kernel symbols at all. Ticket: #39932 (cherry picked from commit a4eb4d7c90f14ca896ea915289fb67b4d0469ab2)

Revision ea7ed535 (diff)
Added by Alexander Motin about 2 years ago

Remove unneeded nestind level (world) in debug package. Ticket: #39932 (cherry picked from commit a09755ce1e306fe34d4ea36c4fe1e794693ba12c)

Revision 70795065 (diff)
Added by Alexander Motin about 2 years ago

Remove one more debug enable from Samba. After this change I do finally see that binary is getting smaller, while there are still some debug symbols produced. Ticket: #39932 (cherry picked from commit 2d29b0793ce376859833b90b5adf2c27167044c9)

Revision 46730a0e (diff)
Added by John Hixson about 2 years ago

Kill forced Samba debug flags Ticket: #39932

Revision 93710671 (diff)
Added by John Hixson about 2 years ago

Kill forced Samba debug flags Ticket: #39932

Revision e9485b40 (diff)
Added by William Grzybowski about 2 years ago

Do not disable optimizations Ticket: #39932 (cherry picked from commit 9f5b6be49233ea720750508be864645c1a17ecb2)

Revision 8132abc3 (diff)
Added by William Grzybowski about 2 years ago

Do not disable optimizations Ticket: #39932

Revision 1d6328c5 (diff)
Added by John Hixson about 2 years ago

Kill forced Samba debug flags Ticket: #39932

Revision fb3edff4 (diff)
Added by William Grzybowski about 2 years ago

Do not disable optimizations Ticket: #39932 (cherry picked from commit 9f5b6be49233ea720750508be864645c1a17ecb2)

Revision ae3e0a98 (diff)
Added by William Grzybowski almost 2 years ago

Do not explicitly force debug and no optimization Ticket: #39932 (cherry picked from commit ef43da9ad21248a66f6735ce9b0d875f40702728)

Revision 5ecc6ef7 (diff)
Added by William Grzybowski almost 2 years ago

Do not explicitly force debug and no optimization Ticket: #39932

Revision 2544604b (diff)
Added by William Grzybowski almost 2 years ago

Do not explicitly force debug and no optimization Ticket: #39932

Revision 314652f1 (diff)
Added by William Grzybowski almost 2 years ago

Do not explicitly force debug and no optimization Ticket: #39932 (cherry picked from commit ef43da9ad21248a66f6735ce9b0d875f40702728)

History

#1 Updated by Dru Lavigne about 2 years ago

  • Private changed from No to Yes
  • Reason for Blocked set to Need additional information from Author

Noel: please attach a debug created on the BETA1 system to this ticket. Thanks!

#2 Updated by Dru Lavigne about 2 years ago

  • Related to Bug #25343: Rsync writing at half speed after upgrade from 9.10.2U5 to 11.0-U1 added

#3 Updated by Noel Miller about 2 years ago

Dru Lavigne wrote:

Noel: please attach a debug created on the BETA1 system to this ticket. Thanks!

Dru,

It is the same behavior as seen in the original ticket, but we will plan on doing the test Monday and I will send you the results. Do you need any other debug information besides the write speeds on the jobs?

Thanks,

Noel

#4 Updated by Dru Lavigne about 2 years ago

The dev will need the full debug to diagnose why this is still an issue.

#5 Updated by Noel Miller about 2 years ago

Dru Lavigne wrote:

The dev will need the full debug to diagnose why this is still an issue.

Dru,

Before we run the tests on Monday, here is the script that is run (Destination and Source changed from each NAS we do it on)

  1. This script is used to rsync the backup working repository as created by Veeam and syncs it to the rotated disk repository called
  2. Source: /mnt/datavol/BackupRepository/Veeam
  3. Destination: /mnt/backup
    START=$(date +%s)
    rsync -avP --delete /mnt/datavol/BackupRepository/Veeam /mnt/backup
    END=$(date +%s)
    DIFF=$(($END - $START))
    echo $(($DIFF/3600)) hr $(($DIFF%3600/60)) min $(($DIFF%60)) sec
    #echo $(($DIFF/60)) min $(($DIFF%60)) sec
    #echo "It took $DIFF seconds"

We are basically rsyncing to a set of backup disks which are then transported to a NAS in a remote location of the same model.

The only difference between the 2 NASes is the version of FreeNAS running on them.

One of them runs the rsync at the correct full speed and the other runs at nearly half the speed.

Is there anything you will need for debugging in this script that you will need to see?

Thanks,

Noel

#6 Updated by Dru Lavigne about 2 years ago

The debug from the 1/2 speed one should suffice. It might turn out to be a hardware issue, a config issue, something else? Hard to tell without a debug.

#7 Updated by Noel Miller about 2 years ago

Dru Lavigne wrote:

The debug from the 1/2 speed one should suffice. It might turn out to be a hardware issue, a config issue, something else? Hard to tell without a debug.

I apologize, but I am not super familiar with submitting bugs to you guys. Do you have a specific command you would like me to run to get you the information you need? Or do you want me to run a more verbose version of the script?

I just want to make sure I get you guys the information you need.

Thanks,

Noel

#8 Updated by Dru Lavigne about 2 years ago

On the slow system, run System -> Advanced -> Save Debug. That will create a file you can attach to this ticket.

#9 Updated by Noel Miller about 2 years ago

23131

Dru Lavigne wrote:

On the slow system, run System -> Advanced -> Save Debug. That will create a file you can attach to this ticket.

Hello Dru,

I managed to get the information you asked for. I got a debug log during the time the issue was occurring.

Let me know if you need any other information!

Thanks,

Noel

#10 Updated by Dru Lavigne about 2 years ago

  • Assignee changed from Release Council to Alexander Motin
  • Reason for Blocked deleted (Need additional information from Author)

#11 Updated by Alexander Motin about 2 years ago

  • Assignee changed from Alexander Motin to Ryan McKenzie

#13 Updated by Noel Miller about 2 years ago

Noel Miller wrote:

Dru Lavigne wrote:

On the slow system, run System -> Advanced -> Save Debug. That will create a file you can attach to this ticket.

Hello Dru,

I managed to get the information you asked for. I got a debug log during the time the issue was occurring.

Let me know if you need any other information!

Thanks,

Noel

Hi Ryan,

Do you have any update for us regarding this issue? I am happy to provide more information if needed!

Thanks,

Noel

#14 Updated by Ryan McKenzie about 2 years ago

I got a FreeNAS system on 11.1u5 to try and reproduce this on. I have a few questions.

1) It looks like you are rsync-ing between two top level volumes (/mnt/datavol and /mnt/backup), residing on different disk pools, correct?
1a) What is the RAID type on the volume(s)?
1b) Do you have encryption enabled on all/any of the volume(s)?
2) What is the dataset size you are moving from the datavol backup repository to the backup volume?
3) What was the typical/expected speed of the rsync on the "old" fast system and what are you seeing now?

Thanks!

#15 Updated by Dru Lavigne about 2 years ago

  • Status changed from Unscreened to Blocked
  • Reason for Blocked set to Need additional information from Author

#16 Updated by Noel Miller about 2 years ago

Ryan McKenzie wrote:

I got a FreeNAS system on 11.1u5 to try and reproduce this on. I have a few questions.

1) It looks like you are rsync-ing between two top level volumes (/mnt/datavol and /mnt/backup), residing on different disk pools, correct?
1a) What is the RAID type on the volume(s)?
1b) Do you have encryption enabled on all/any of the volume(s)?
2) What is the dataset size you are moving from the datavol backup repository to the backup volume?
3) What was the typical/expected speed of the rsync on the "old" fast system and what are you seeing now?

Thanks!

1. Yes
1a. Datavol has a set of mirrors. See zpool status below for both NAS4 and DR-NAS2
1b. Encryption is not enabled
2. 16TB Total Size, 13.5TB of data for backups
3. 180MB/s, getting about 90MB/s on slow system

NAS4 zpool status
pool: backup
state: ONLINE
scan: none requested
config:

NAME                                            STATE     READ WRITE CKSUM
backup ONLINE 0 0 0
raidz2-0 ONLINE 0 0 0
gptid/65c6839c-9741-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/668d1eed-9741-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/67564cbc-9741-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/680b1279-9741-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/68cf1e1c-9741-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/6981b20f-9741-11e8-af46-0090fa849e88 ONLINE 0 0 0

errors: No known data errors

pool: datavol
state: ONLINE
scan: resilvered 1.93T in 8h29m with 0 errors on Wed Aug 15 21:06:35 2018
config:
NAME                                            STATE     READ WRITE CKSUM
datavol ONLINE 0 0 0
mirror-0 ONLINE 0 0 0
gptid/c2a323ee-8d1e-11e8-86e4-0090fa849e88 ONLINE 0 0 0
gptid/c2d1cdbc-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-1 ONLINE 0 0 0
gptid/c39bf4f5-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/c468b5a3-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-2 ONLINE 0 0 0
gptid/c5315a51-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/c5ff047d-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-3 ONLINE 0 0 0
gptid/ca4cf485-a0b1-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/c78fb9bf-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-4 ONLINE 0 0 0
gptid/c85c0837-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/c92ccd0f-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-5 ONLINE 0 0 0
gptid/c9ff584d-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/cac46b56-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-6 ONLINE 0 0 0
gptid/cb8e33e7-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/cc596298-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-7 ONLINE 0 0 0
gptid/cd25942a-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/cdee306e-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-8 ONLINE 0 0 0
gptid/2f4c3f87-8d1e-11e8-86e4-0090fa849e88 ONLINE 0 0 0
gptid/cf90c74f-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-9 ONLINE 0 0 0
gptid/d05e1173-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/d134bc8f-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-10 ONLINE 0 0 0
gptid/d2053df5-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/d2d2e453-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-11 ONLINE 0 0 0
gptid/d3aa5bc6-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/d475fe61-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-12 ONLINE 0 0 0
gptid/d5469d27-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/d619f749-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-13 ONLINE 0 0 0
gptid/d6f53555-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/d7c0814e-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
mirror-14 ONLINE 0 0 0
gptid/d889e9e1-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
gptid/d95816fa-7767-11e5-a06e-0090fa849e88 ONLINE 0 0 0
logs
gptid/68aa4483-8d1a-11e8-86e4-0090fa849e88 ONLINE 0 0 0

errors: No known data errors

DR-NAS2 zpool status
pool: backup
state: ONLINE
status: Some supported features are not enabled on the pool. The pool can
still be used, but some features are unavailable.
action: Enable all features using 'zpool upgrade'. Once this is done,
the pool may no longer be accessible by software that does not support
the features. See zpool-features(7) for details.
scan: none requested
config:

NAME                                            STATE     READ WRITE CKSUM
backup ONLINE 0 0 0
raidz2-0 ONLINE 0 0 0
gptid/1f95670e-9cd9-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/205d5d15-9cd9-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/210496f4-9cd9-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/21c0f1b4-9cd9-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/227fb52a-9cd9-11e8-af46-0090fa849e88 ONLINE 0 0 0
gptid/23301f8c-9cd9-11e8-af46-0090fa849e88 ONLINE 0 0 0

errors: No known data errors

I apologize for delay in getting information.

Let me know if you have any insights!

Thanks,

Noel

#17 Updated by Dru Lavigne about 2 years ago

  • Status changed from Blocked to Unscreened
  • Reason for Blocked deleted (Need additional information from Author)

#18 Updated by Ryan McKenzie about 2 years ago

I have done some basic investigations on this. I tested rsync performance to same zvol and to a different zvol on different mirrored pool. The test data is an actual backup of performance data files from our lab, size around 28GiB total with a good mix of large files like ISOs and lots of small files like CSVs. I used the customer script to perform the rsync and measure the time so our data would be comparable. WHen I did the upgrade I saved a copy of the OLD rsync binary and luckily it did run on the upgraded system.

Fresh install to 9.10.2u5 gives me:

same pool diff pool
zfs send 269.16 MiB/s 317.55 MiB/s
rsync 98.73 MiB/s 99.34 MiB/s

Upgrade to 11.0u1 gives me:

same pool diff pool
rsync 51.17 MiB/s 58.12 MiB/s
rsync_OLDBIN 105.64 MiB/s 105.24 MiB/s

So as you can see, I also reproduce the roughly 50% drop in rsync performance. Even though my system baseline is slower (FreeNAS mini 4 drives running on our office network), the performance drop is reproduced. However, the "old" rsync binary still performs well on the upgraded system.

I also ran a test on another system using zfs snap, zfs send and zfs recv to accomplish the same backup as a sanity check. The zfs-based backup method has similar (even slightly improving) performance from the old to the new FreeNAS version.

11.1u5 Fresh Install

same pool diff pool
zfs send 306.08 MiB/s 352.00 MiB/s
rsync 45.67 MiB/s 51.01 MiB/s

#19 Updated by Noel Miller about 2 years ago

Ryan McKenzie wrote:

I have done some basic investigations on this. I tested rsync performance to same zvol and to a different zvol on different mirrored pool. The test data is an actual backup of performance data files from our lab, size around 28GiB total with a good mix of large files like ISOs and lots of small files like CSVs. I used the customer script to perform the rsync and measure the time so our data would be comparable. WHen I did the upgrade I saved a copy of the OLD rsync binary and luckily it did run on the upgraded system.

Fresh install to 9.10.2u5 gives me:

same pool diff pool
zfs send 269.16 MiB/s 317.55 MiB/s
rsync 98.73 MiB/s 99.34 MiB/s

Upgrade to 11.0u1 gives me:

same pool diff pool
rsync 51.17 MiB/s 58.12 MiB/s
rsync_OLDBIN 105.64 MiB/s 105.24 MiB/s

So as you can see, I also reproduce the roughly 50% drop in rsync performance. Even though my system baseline is slower (FreeNAS mini 4 drives running on our office network), the performance drop is reproduced. However, the "old" rsync binary still performs well on the upgraded system.

I also ran a test on another system using zfs snap, zfs send and zfs recv to accomplish the same backup as a sanity check. The zfs-based backup method has similar (even slightly improving) performance from the old to the new FreeNAS version.

11.1u5 Fresh Install

same pool diff pool
zfs send 306.08 MiB/s 352.00 MiB/s
rsync 45.67 MiB/s 51.01 MiB/s

Ryan,

I appreciate the feedback and extensive testing that was done on this!

What would be your suggestion moving forward regarding putting a solution in place?

Would you suggest trying to get a copy of the old binary and using it until you guys fix the bug on your side? If so, how would we go about doing that?

Any insight on this issue would be highly appreciated!

Thanks,

Noel

#20 Updated by Noel Miller about 2 years ago

Noel Miller wrote:

Ryan McKenzie wrote:

I have done some basic investigations on this. I tested rsync performance to same zvol and to a different zvol on different mirrored pool. The test data is an actual backup of performance data files from our lab, size around 28GiB total with a good mix of large files like ISOs and lots of small files like CSVs. I used the customer script to perform the rsync and measure the time so our data would be comparable. WHen I did the upgrade I saved a copy of the OLD rsync binary and luckily it did run on the upgraded system.

Fresh install to 9.10.2u5 gives me:

same pool diff pool
zfs send 269.16 MiB/s 317.55 MiB/s
rsync 98.73 MiB/s 99.34 MiB/s

Upgrade to 11.0u1 gives me:

same pool diff pool
rsync 51.17 MiB/s 58.12 MiB/s
rsync_OLDBIN 105.64 MiB/s 105.24 MiB/s

So as you can see, I also reproduce the roughly 50% drop in rsync performance. Even though my system baseline is slower (FreeNAS mini 4 drives running on our office network), the performance drop is reproduced. However, the "old" rsync binary still performs well on the upgraded system.

I also ran a test on another system using zfs snap, zfs send and zfs recv to accomplish the same backup as a sanity check. The zfs-based backup method has similar (even slightly improving) performance from the old to the new FreeNAS version.

11.1u5 Fresh Install

same pool diff pool
zfs send 306.08 MiB/s 352.00 MiB/s
rsync 45.67 MiB/s 51.01 MiB/s

Ryan,

I appreciate the feedback and extensive testing that was done on this!

What would be your suggestion moving forward regarding putting a solution in place?

Would you suggest trying to get a copy of the old binary and using it until you guys fix the bug on your side? If so, how would we go about doing that?

Any insight on this issue would be highly appreciated!

Thanks,

Noel

One other thing, would you suggest we use zfs send vs using rsync? I unfortunately am not super familiar with the ZFS command set in regards to moving files back and forth, so I would appreciate some help regarding that!

Thanks,

Noel

#21 Updated by Ryan McKenzie about 2 years ago

  • Status changed from Unscreened to Screened

Conclusions:
Because the old rsync binary still gets expected performance on the new FreeNAS code, and the fact that the zfs-based backup methodology performance stays steady, we can conclude that there was a change in rsync causing this performance reduction.

Next Steps:
I will run a dtrace on the old vs new rsync binaries to see if they are producing a different IO profile so investigation will continue.

In the mean time, a possible workaround seems to be copy an old rsync binary from another system or build one from older source. If your environment allows you to do so, the zfs-based solution for this backup would also be helpful for you in that they would accomplish the backup task AND give you some snapshots to act as restore points for your data.

Here is the modified script (based on your script) I was running to perform the backups, that might give you a good starting point on the zfs-based method. Note that when using the zfs method, the root folder you back up has to be created as a dataset under that zvol in the FreeNAS UI (it can't just be a directory you created under there on the client side).

START=$(date +%s)

#ZFS SEND same pool
#zfs snap -r datavol/perfdata@snap${START}
#zfs send -Rv datavol/perfdata@snap${START} | zfs recv -Fd datavol/BackupRepository

#ZFS SEND cross pool
#zfs snap -r datavol/BackupRepository@snap${START}
#zfs send -Rv datavol/BackupRepository@snap${START} | zfs recv -Fd backup

#RSYNC same pool
#rsync -avP /mnt/datavol/perfdata/ /mnt/datavol/BackupRepository/

#OLD RSYNC same pool
#/usr/local/bin/rsync_9.10.2u5 -avP /mnt/datavol/perfdata/ /mnt/datavol/BackupRepository/

#RSYNC cross pool   
#rsync -avP /mnt/datavol/BackupRepository/ /mnt/backup/

#OLD RSYNC cross pool
#/usr/local/bin/rsync_9.10.2u5 -avP /mnt/datavol/BackupRepository/ /mnt/backup/

END=$(date +%s)
DIFF=$(($END - $START))
echo $(($DIFF/3600)) hr $(($DIFF%3600/60)) min $(($DIFF%60)) sec
#echo $(($DIFF/60)) min $(($DIFF%60)) sec
#echo "It took $DIFF seconds" 

And here is a related forum article:
https://forums.freenas.org/index.php?threads/how-to-use-zfs-send-zfs-receive-to-back-up-my-current-pools-to-a-10tb-transfer-disk.59852/

#22 Updated by Ryan McKenzie about 2 years ago

Checked the rsync --version on old vs new binary, they are the same version.

Looked at github for the history of the rsync port. FreeNAS 9.10.2u5 took it's last commit to the port on June 3, 2016. For FreeNAS 11.0 stable there was one more commit on March 16, 2017.
https://github.com/freenas/ports/commit/99d22d6510ab7a64ab16d4121ebe48d06677e47d#diff-ad55c0f9be48c5bff2957b314374e889

I'm going to read through it quickly before I start the dtrace testing to see if anything jumps out.

#23 Updated by Ryan McKenzie about 2 years ago

That checkin is very benign, just moving ports from one location to another and doing some command line parsing stuff (popt).

Noel, can you please run "uname -a; pkg info rsync" on the 9.10 system you have so we can see if the package was built with different options?

root@freenas:~ # uname -a; pkg info rsync
FreeBSD freenas.local 11.0-STABLE FreeBSD 11.0-STABLE #0 r313908+b3722b04944(freenas/11.0-stable): Sat Jul  1 02:44:49 UTC 2017     root@gauntlet:/freenas-11-releng/freenas/_BE/objs/freenas-11-releng/freenas/_BE/os/sys/FreeNAS.amd64  amd64
rsync-3.1.2_2
Name           : rsync
Version        : 3.1.2_2
Installed on   : Fri Jun 30 20:42:05 2017 PDT
Origin         : net/rsync
Architecture   : freebsd:11:x86:64
Prefix         : /usr/local
Categories     : net ipv6
Licenses       : GPLv3
Maintainer     : ehaupt@FreeBSD.org
WWW            : http://rsync.samba.org/
Comment        : Network file distribution/synchronization utility
Options        :
        ACL            : on
        ATIMES         : off
        DOCS           : off
        FLAGS          : off
        ICONV          : on
        POPT_PORT      : off
        RENAMED        : off
        SSH            : on
        TIMELIMIT      : off
        ZLIB_BASE      : off
Annotations    :
        cpe            : cpe:2.3:a:samba:rsync:3.1.2:::::freebsd11:x64:2
        repo_type      : binary
        repository     : local
Flat size      : 1.29MiB
Description    :
rsync is a replacement for rcp that has many more features.

rsync uses the "rsync algorithm" which provides a very fast method for
bringing remote files into sync. It does this by sending just the
differences in the files across the link, without requiring that both
sets of files are present at one of the ends of the link beforehand.
This makes rsync a good remote file distribution/synchronization utility
in a dialup PPP/SLIP environment.

Note, requires rsync on the destination machine.

There is a Computer Science Technical Report on the rsync algorithm is
included in the distribution, and is available as
ftp://samba.anu.edu.au/pub/rsync/tech_report.ps

WWW: http://rsync.samba.org/

#24 Updated by Ryan McKenzie about 2 years ago

  • Status changed from Screened to Blocked
  • Assignee changed from Ryan McKenzie to Alexander Motin
  • Reason for Blocked set to Need additional information from Author
  • Needs QA changed from Yes to No

I did dtrace of the old vs new binaries. The IO histogram and average IO latency is not significantly different. The amount of time spent in the syscall "select" is significantly higher in the new binary vs the old binary so we may look into that.

The CPU utilization for both binaries is very similar also.

I'm going to bounce this ticket over to another team member who is going to take a final look at the issue before we declare it an rsync problem.

We would still like to see your output from "uname -a; pkg info rsync" on the 9.10 system you have.

#25 Updated by Ryan McKenzie about 2 years ago

#26 Updated by Noel Miller about 2 years ago

Ryan McKenzie wrote:

I did dtrace of the old vs new binaries. The IO histogram and average IO latency is not significantly different. The amount of time spent in the syscall "select" is significantly higher in the new binary vs the old binary so we may look into that.

The CPU utilization for both binaries is very similar also.

I'm going to bounce this ticket over to another team member who is going to take a final look at the issue before we declare it an rsync problem.

We would still like to see your output from "uname -a; pkg info rsync" on the 9.10 system you have.

Ryan,

Here is the output:

rsync-3.1.2_2
Name : rsync
Version : 3.1.2_2
Installed on : Mon Jul 24 19:34:30 2017 CDT
Origin : net/rsync
Architecture : freebsd:10:x86:64
Prefix : /usr/local
Categories : net ipv6
Licenses : GPLv3
Maintainer :
WWW : http://rsync.samba.org/
Comment : Network file distribution/synchronization utility
Options :
ACL : on
ATIMES : off
DOCS : off
FLAGS : off
ICONV : on
POPT_PORT : off
RENAMED : off
SSH : on
TIMELIMIT : off
ZLIB_BASE : off
Annotations :
cpe : cpe:2.3:a:samba:rsync:3.1.2:::::freebsd10:x64:2
repo_type : binary
repository : local
Flat size : 520KiB
Description :
rsync is a replacement for rcp that has many more features.

rsync uses the "rsync algorithm" which provides a very fast method for
bringing remote files into sync. It does this by sending just the
differences in the files across the link, without requiring that both
sets of files are present at one of the ends of the link beforehand.
This makes rsync a good remote file distribution/synchronization utility
in a dialup PPP/SLIP environment.

Note, requires rsync on the destination machine.

There is a Computer Science Technical Report on the rsync algorithm is
included in the distribution, and is available as
ftp://samba.anu.edu.au/pub/rsync/tech_report.ps

WWW: http://rsync.samba.org/

Thanks,

Noel

#27 Updated by Alexander Motin about 2 years ago

  • Status changed from Blocked to In Progress
  • Reason for Blocked deleted (Need additional information from Author)

I suspect I found the problem in excessive debugging enabled in FreeNAS during package build, possibly exactly in times of between FreeNAS 9.10 and 11. At least rsync from standard FreeBSD packages, and one I build myself are not affected, while built with that debug shows the reduced performance. I'll test it more.

#28 Updated by Alexander Motin about 2 years ago

  • Assignee changed from Alexander Motin to Ryan McKenzie

I've confirmed that disabled debugging helps rsync. Pushing to Ryan to benchmark other services built from ports: SMB, AFP, SSH (scp?), etc.

#29 Updated by Alexander Motin about 2 years ago

  • Target version changed from Backlog to 11.2-RC1

#30 Updated by Ryan McKenzie about 2 years ago

28444

We have found that rsync regains it's better bandwidth performance with the nodebug/optimized ports build. We also found that SCP gets a good performance benefit both with and without encryption during transfer. The results are inconclusive with SMB and AFP file sharing so I am running a more comprehensive set of benchmarks for those use cases.

#31 Updated by Noel Miller about 2 years ago

Ryan McKenzie wrote:

We have found that rsync regains it's better bandwidth performance with the nodebug/optimized ports build. We also found that SCP gets a good performance benefit both with and without encryption during transfer. The results are inconclusive with SMB and AFP file sharing so I am running a more comprehensive set of benchmarks for those use cases.

Ryan,

Thank you for all the assistance on this and reaching out regarding updates. We have decided that copying the old binary over and using that is going to be the temporary solution until your solution is integrated into a new build. Even if this is implemented in a beta release, we'd like to know as soon as possible.

Feel free to continue to provide updates on this, I'm very curious as to what is the ultimate root cause is and what the solution ends up being!

Thanks,

Noel

#32 Updated by Ryan McKenzie about 2 years ago

  • Subject changed from Follow up to Bug #25343: Rsync writing at half speed after upgrade from 9.10.2U5 to 11.0-U1 to Ports built with debug on and optimizations disabled causing performance issues with various userspace applications

CHanged the name of this issue, it was:
Follow up to Bug #25343: Rsync writing at half speed after upgrade from 9.10.2U5 to 11.0-U1

The root cause of this issue is that the ports are now being built with debug symbols and the option used to do so also disabled compile time optimizations.

So far we have tested/identified the following:

-2x increase in rsync bandwidth by building the old way
-3x increase in scp bandwidth (compression on) by building the old way
-2x increase in scp bandwidth (compression off after authentication) by building the old way

APF copy and crosscopy of large file was tested, results inconclusive
AFP benchmarking with VDBENCH showed up to a 10% increase in 128k sequential write bandwidth (other read/write mixes and access patterns were inconclusive)

SMB copy and crosscopy of large file was tested, results inconclusive

Python benchmarking via pyperformance is underway. SMB benchmarking with VDBENCH will be done when more equipment becomes available again.

#33 Updated by Ryan McKenzie about 2 years ago

29320

Python benchmarks show a significant increase in performance from debug off and optimizations on. 2x-3x speedup on each benchmark. See attached graphs.

test time (ms) 11.1u5 11.2 nightly 11.2 NODEBUG
2to3 1740 1700 762
json_dumps 77.3 77.4 37
json_loads 0.156 0.155 0.0719
pickle 0.0589 0.0603 0.0281
pickle_dict 0.149 0.147 0.0712
pickle_list 0.0207 0.0205 0.00956
pickle_pure_python 3.59 3.13 1.33
regex_compile 1100 1100 492
unpickle 0.098 0.0976 0.0384
unpickle_lisk 0.0253 0.0252 0.0105
unpickle_pure_python 2.26 2.29 1.01

#34 Updated by Alexander Motin about 2 years ago

  • Assignee changed from Ryan McKenzie to Alexander Motin

I'll take this to finally disable debugging. Thank you, Ryan.

#35 Updated by Bug Clerk about 2 years ago

  • Status changed from In Progress to Ready for Testing

#36 Updated by Alexander Motin about 2 years ago

  • Status changed from Ready for Testing to In Progress

Not so fast, it was only a minor part. ;)

#37 Updated by Dru Lavigne about 2 years ago

  • File deleted (debug.tgz)

#38 Updated by Dru Lavigne about 2 years ago

  • Private changed from Yes to No

#40 Updated by Alexander Motin about 2 years ago

  • Status changed from In Progress to Ready for Testing

PRs are merged. On my test builds I've finally observed that Samba binaries got smaller, hopefully due to debug disabled, so some new benchmarks would be interesting aside.

#41 Updated by Dru Lavigne about 2 years ago

  • Subject changed from Ports built with debug on and optimizations disabled causing performance issues with various userspace applications to Restore ports build optimization while retaining debug symbols
  • Status changed from Ready for Testing to Done
  • Needs Doc changed from Yes to No
  • Needs Merging changed from Yes to No

#42 Updated by Dru Lavigne about 2 years ago

  • Status changed from Done to In Progress

#43 Updated by Alexander Motin about 2 years ago

  • Related to Bug #47459: Restore ports build optimization while retaining debug symbols added

#44 Updated by Alexander Motin almost 2 years ago

  • Status changed from In Progress to Ready for Testing

#46 Updated by Dru Lavigne almost 2 years ago

  • Status changed from Ready for Testing to Done

#47 Updated by Ryan McKenzie almost 2 years ago

35385

Finally had some time on windows and iMac clients to do this testing.

SMB
-the most significant change was a decrease in small block random reads by 10%, attached chart
-small block random writes saw smoother thread scaling and lower latency in 11.2, and the OPS difference was less than +/-5% and in margin or error
-streaming read performance was no different between the versions
-streaming write performance was better in 11.2 for each run, but less than +5% and in margin of error

AFP
-small block random performance was no different between the versions regardless off read/write mix
-streaming performance saw an across the board increase in bandwidth for all read/write mixes, but less than +5% and in margin of error

Also available in: Atom PDF