Project

General

Profile

Bug #23200

Replication is writing to the configuration database for every replication

Added by Philip Spigelmire over 4 years ago. Updated about 4 years ago.

Status:
Resolved
Priority:
Nice to have
Assignee:
William Grzybowski
Category:
Middleware
Target version:
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

I was seeing excessive writes to my flash storage in disk reporting. System dataset and RRD graphs are not on the boot volume. Tracked this down to writes to /data/freenas-v1.db. Ran an sqldiff on this file at two different intervals and found the following sql statements were being sent:

UPDATE storage_replication SET repl_lastsnapshot='auto-20170407.1745-1y' WHERE id=1;
UPDATE storage_replication SET repl_lastsnapshot='auto-20170407.1745-4w' WHERE id=9;
UPDATE storage_replication SET repl_lastsnapshot='auto-20170407.1745-1y' WHERE id=10;

This is running FreeNAS-9.10.2-U2 (e1497f2)

Forum post: https://forums.freenas.org/index.php?threads/mystery-writes-to-boot-volume-on-9-10-2-u1-and-u2-possibly-linked-to-snapshots-replication.53255/

boot io.png (16.9 KB) boot io.png Philip Spigelmire, 04/10/2017 02:06 PM
boot data.png (13.5 KB) boot data.png Philip Spigelmire, 04/10/2017 02:06 PM
10606
10607

Related issues

Related to FreeNAS - Bug #23285: Alert system writes to database too often if there is an issueResolved2017-04-11
Copied to FreeNAS - Bug #23304: /.rnd file being written very oftenResolved2017-04-07

Associated revisions

Revision 0efdb689 (diff)
Added by William Grzybowski over 4 years ago

fix(repl): do not write last snapshot to database Ticket: #23200

Revision 867d26b2 (diff)
Added by William Grzybowski over 4 years ago

fix(repl): use defaultdict for results Ticket: #23200

History

#1 Avatar?id=14398&size=24x24 Updated by Kris Moore over 4 years ago

  • Assignee set to William Grzybowski

I'm not sure this is avoidable, since we do have to record replication states. Over to William for comment.

#2 Updated by William Grzybowski over 4 years ago

  • Status changed from Unscreened to 15

IIRC recording last snapshot sent is simply for user information.

We could remove that from the database but user would not be able to see it after a reboot. Would that be acceptable? What do you guys think?

#3 Updated by Philip Spigelmire over 4 years ago

I personally wouldn't care if they are not there after a reboot - as I take snapshots often enough, they will show back up pretty quickly.
Any ideas on why there are so many writes? I have almost 1GB/day with 60,000 write IO operations on one of my systems. I could see this killing USB flash pretty quick - fortunately, I'm using SATA DOMs.

#4 Avatar?id=14398&size=24x24 Updated by Kris Moore over 4 years ago

  • Target version set to 9.10.3

If its only done for cosmetic tracking, then I'd be in favor of shutting it down. Best to save the writes if at all possible

#5 Updated by William Grzybowski over 4 years ago

  • Priority changed from No priority to Nice to have

Philip Spigelmire wrote:

I personally wouldn't care if they are not there after a reboot - as I take snapshots often enough, they will show back up pretty quickly.
Any ideas on why there are so many writes? I have almost 1GB/day with 60,000 write IO operations on one of my systems. I could see this killing USB flash pretty quick - fortunately, I'm using SATA DOMs.

Where is your system dataset located?

#6 Updated by Philip Spigelmire over 4 years ago

William Grzybowski wrote:

Where is your system dataset located?

On my pool, RRD data is on the pool as well.

#7 Updated by William Grzybowski over 4 years ago

Philip Spigelmire wrote:

William Grzybowski wrote:

Where is your system dataset located?

On my pool, RRD data is on the pool as well.

That is fairly unusual then. I would really like to find out why you are having so many writes. How are you measuring these?

#8 Updated by Philip Spigelmire over 4 years ago

10606
10607

William Grzybowski wrote:

Philip Spigelmire wrote:

William Grzybowski wrote:

Where is your system dataset located?

On my pool, RRD data is on the pool as well.

That is fairly unusual then. I would really like to find out why you are having so many writes. How are you measuring these?

I'm looking at the RRD graphs. Attached images from the heaviest used system, last 24 hours - yesterday our operation was closed so it is lower than normal. I have systems that are replication targets that are configured identically, they just don't take snapshots or perform zfs sends and they have zero IO to the boot volume.

#9 Updated by William Grzybowski over 4 years ago

Philip Spigelmire wrote:

William Grzybowski wrote:

Philip Spigelmire wrote:

William Grzybowski wrote:

Where is your system dataset located?

On my pool, RRD data is on the pool as well.

That is fairly unusual then. I would really like to find out why you are having so many writes. How are you measuring these?

I'm looking at the RRD graphs. Attached images from the heaviest used system, last 24 hours - yesterday our operation was closed so it is lower than normal. I have systems that are replication targets that are configured identically, they just don't take snapshots or perform zfs sends and they have zero IO to the boot volume.

Interesting so being a source for the replication is the only thing different?
How familiar are you with ZFS snapshot diff? I was wondering if you take a snapshot of the boot zfs filesystem in a date range of 1 day and use "zfs diff" to make sure the database is the only thing being written.

#10 Updated by Philip Spigelmire over 4 years ago

William Grzybowski wrote:

Interesting so being a source for the replication is the only thing different?
How familiar are you with ZFS snapshot diff? I was wondering if you take a snapshot of the boot zfs filesystem in a date range of 1 day and use "zfs diff" to make sure the database is the only thing being written.

I took a recursive snapshot of freenas-boot. Will wait a bit and check zfs diff.

#11 Updated by Philip Spigelmire over 4 years ago

Looks like /.rnd is getting touched.

#12 Updated by William Grzybowski over 4 years ago

Philip Spigelmire wrote:

Looks like /.rnd is getting touched.

Very intriguing. How often does that file change?

#13 Updated by Philip Spigelmire over 4 years ago

William Grzybowski wrote:

Philip Spigelmire wrote:

Looks like /.rnd is getting touched.

Very intriguing. How often does that file change?

Looks to be pretty frequent, I see the modified time change almost every minute. Do you think SSH writing to this file every time it is executed?

Edit: I ran

rm .rnd ; ln -s /mnt/tank/.rnd .rnd

and I will wait and see what happens to the writes to the boot volume.

#14 Updated by Philip Spigelmire over 4 years ago

Moving /.rnd off the boot volume reduced the number of write/delete IOs from 10k last hour to 1.3k now. Data transfer writes dropped from 223MB last hour to 35MB. This system is running 9.10.2-U1.
zfs diff:

/# zfs diff -Ft freenas-boot/ROOT/default@second
1491866445.161013711    M       /       /data
1491866445.158919360    M       F       /data/freenas-v1.db

My other system that performs replications is running 9.10.2-U2 and it's last write to /.rnd was 6 hours ago. This machine shows 257MB of boot volume writes in 24 hours and they are on a fairly consistent 15 minute interval which correspondes to my snapshot schedule.

#15 Updated by William Grzybowski over 4 years ago

Strange... So it is only happening on 9.10.2-U1 and not U2?

I have U2 and latest nightly and see no changes to /.rnd file.
Any chance you can update that one to U2 to see if it goes away and was indeed a problem with U1?

257MB still seems a lot for changes only to a single row in the database. I'll do some measurements on my end.

#16 Updated by Philip Spigelmire over 4 years ago

William Grzybowski wrote:

Strange... So it is only happening on 9.10.2-U1 and not U2?

I have U2 and latest nightly and see no changes to /.rnd file.
Any chance you can update that one to U2 to see if it goes away and was indeed a problem with U1?

257MB still seems a lot for changes only to a single row in the database. I'll do some measurements on my end.

I'll see if I can get that one updated to U2. I agree that 257MB seems like a lot of writes - not sure if those are all to freenas-v1.db since the /.rnd file gets modified as well, just hasn't been changed in a while. I can tell you that after moving the /.rnd file on the U1 system, all the writes have only been to freenas-v1.db (checking zfs diff) and there have been 61MB in the last hour - so quite high. This system has 11 replication tasks setup on it sending to two different systems - one LAN and one WAN.

#17 Updated by William Grzybowski over 4 years ago

Philip Spigelmire wrote:

William Grzybowski wrote:

Strange... So it is only happening on 9.10.2-U1 and not U2?

I have U2 and latest nightly and see no changes to /.rnd file.
Any chance you can update that one to U2 to see if it goes away and was indeed a problem with U1?

257MB still seems a lot for changes only to a single row in the database. I'll do some measurements on my end.

I'll see if I can get that one updated to U2. I agree that 257MB seems like a lot of writes - not sure if those are all to freenas-v1.db since the /.rnd file gets modified as well, just hasn't been changed in a while. I can tell you that after moving the /.rnd file on the U1 system, all the writes have only been to freenas-v1.db (checking zfs diff) and there have been 61MB in the last hour - so quite high. This system has 11 replication tasks setup on it sending to two different systems - one LAN and one WAN.

Would you care to test a patch which stops writing the lastest snapshot sent to database?

#18 Updated by Philip Spigelmire over 4 years ago

Sure, I can do that.

#19 Updated by William Grzybowski over 4 years ago

http://sprunge.us/gUAW

This should be applied to /usr/local/www/freenasUI/tools/autorepl.py

#20 Updated by Philip Spigelmire over 4 years ago

William Grzybowski wrote:

http://sprunge.us/gUAW

This should be applied to /usr/local/www/freenasUI/tools/autorepl.py

I applied the patch to the U1 system, I will monitor and report back tomorrow. Thank you.

#21 Updated by Philip Spigelmire over 4 years ago

I can confirm that the patch and symbolic linking .rnd off the boot volume stopped all writes to the boot volume. Removing the symlink to .rnd, and the writes come back for that. I will update this system to U2 and see if this is reduced. I do see .rnd being updated on my system with the U2 release, but less frequently (however the load on that system is much lower).

I notice that the Replication Task UI gets updated with the last snapshot while the replication is in progress, but once it completes it goes back to the snapshot that was listed prior to the patch being applied. Also, the API (/api/v1.0/storage/replication/) returns the old snapshot. I use the API to run a script once a day that e-mails me the status of my replication tasks so that I have confirmation that everything is working okay.

#22 Updated by William Grzybowski over 4 years ago

Philip Spigelmire wrote:

I can confirm that the patch and symbolic linking .rnd off the boot volume stopped all writes to the boot volume. Removing the symlink to .rnd, and the writes come back for that. I will update this system to U2 and see if this is reduced. I do see .rnd being updated on my system with the U2 release, but less frequently (however the load on that system is much lower).

I notice that the Replication Task UI gets updated with the last snapshot while the replication is in progress, but once it completes it goes back to the snapshot that was listed prior to the patch being applied. Also, the API (/api/v1.0/storage/replication/) returns the old snapshot. I use the API to run a script once a day that e-mails me the status of my replication tasks so that I have confirmation that everything is working okay.

Correct, the patch I sent you is not supposed to be the final version. I have committed a different fix.

Keep us updated with the /.rnd issue. It could not make it behave the same as you with 9.10.2-U1.

#23 Updated by Philip Spigelmire over 4 years ago

I disabled replication and saw that /.rnd was still being written- so some other process is writing to this file. I checked one of my backup servers (running 9.10.2-U2) and it had not been written to since early March. I browsed to an SMB share on the backup server and saw that .rnd was written to. So it looks like samba is the culprit here. Can you verify this? Thank you for all your help.

BTW, these are active directory members, if that makes a difference.

#24 Updated by William Grzybowski over 4 years ago

Philip Spigelmire wrote:

I disabled replication and saw that /.rnd was still being written- so some other process is writing to this file. I checked one of my backup servers (running 9.10.2-U2) and it had not been written to since early March. I browsed to an SMB share on the backup server and saw that .rnd was written to. So it looks like samba is the culprit here. Can you verify this? Thank you for all your help.

BTW, these are active directory members, if that makes a difference.

I have accessed a share and copied files, my /.rnd has not changed. I'll try with AD next.

#25 Updated by William Grzybowski over 4 years ago

William Grzybowski wrote:

Philip Spigelmire wrote:

I disabled replication and saw that /.rnd was still being written- so some other process is writing to this file. I checked one of my backup servers (running 9.10.2-U2) and it had not been written to since early March. I browsed to an SMB share on the backup server and saw that .rnd was written to. So it looks like samba is the culprit here. Can you verify this? Thank you for all your help.

BTW, these are active directory members, if that makes a difference.

I have accessed a share and copied files, my /.rnd has not changed. I'll try with AD next.

Nope, my /.rnd is not regenerated either way.
This seems to be the random seed used in openssl. Now what is using openssl so frequently is the question.
Can you try changing /etc/ssl/openssl.cnf, replacing RANDFILE to RANDFILE = /tmp/.rnd ?

#26 Updated by Philip Spigelmire over 4 years ago

Do you have a Kerberos realm configured? Browsing through the samba source, it looks like the samba writes to /.rnd for several kerberos operations.

Edit: I can confirm that keberos is the cause, I removed the kerberos realm from my backup server and the /.rnd doesn't update when browsing shares on that machine now.

#27 Updated by John Hixson over 4 years ago

Can you attach a debug please? system->advanced->save debug

#28 Updated by Philip Spigelmire over 4 years ago

  • File debug-FreeNASLA1-20170411150101.tgz added

#29 Updated by William Grzybowski over 4 years ago

  • Related to Bug #23285: Alert system writes to database too often if there is an issue added

#30 Updated by William Grzybowski over 4 years ago

We can't seem to reproduce that issue no matter what. We have AD enabled and everything.

Were you able to pinpoint the specific action that triggers the update of .rnd file? Just the act of accessing a share does it?

#32 Updated by Philip Spigelmire over 4 years ago

I went to my backup system to put the Kerberos realm back, and it looks like FreeNAS already did it for me... (It gets this from DNS or the DC??)
I browsed a folder on it from my windows client (same one as earlier) and the /.rnd doesn't get updated (check klist and it still has a valid authentication ticket from earlier).
I browsed a folder on it from a different windows client, and the /.rnd gets updated.
I ran smbstatus and killed the process for my original session and purged the klist on the windows client, then browsed the share and the /.rnd file is updated again.

So removing the Kerberos realm did nothing since it was automatically put back, but the initial authentication when accessing the shares is triggering an update to the /.rnd file.

Not sure what to check next other than see if I can configure samba to use a different location for the /.rnd file

#33 Updated by Philip Spigelmire over 4 years ago

  • File deleted (debug-FreeNASLA1-20170411150101.tgz)

#34 Updated by John Hixson over 4 years ago

Philip Spigelmire wrote:

I went to my backup system to put the Kerberos realm back, and it looks like FreeNAS already did it for me... (It gets this from DNS or the DC??)
I browsed a folder on it from my windows client (same one as earlier) and the /.rnd doesn't get updated (check klist and it still has a valid authentication ticket from earlier).
I browsed a folder on it from a different windows client, and the /.rnd gets updated.
I ran smbstatus and killed the process for my original session and purged the klist on the windows client, then browsed the share and the /.rnd file is updated again.

So removing the Kerberos realm did nothing since it was automatically put back, but the initial authentication when accessing the shares is triggering an update to the /.rnd file.

Not sure what to check next other than see if I can configure samba to use a different location for the /.rnd file

Can you please try what William suggested with editing /etc/ssl/openssl.cnf and setting RANDFILE to /tmp/.rnd ? This is not a kerberos or a samba issue, this is an openssl issue. We need confirmation that this fixes the issue so we can get it in the next release.

#35 Updated by Philip Spigelmire over 4 years ago

John Hixson wrote:

Can you please try what William suggested with editing /etc/ssl/openssl.cnf and setting RANDFILE to /tmp/.rnd ? This is not a kerberos or a samba issue, this is an openssl issue. We need confirmation that this fixes the issue so we can get it in the next release.

Yes, I have done that - and there was no change. I'm fairly certain this is coming from samba, and as far as I can tell, samba does not depend on openssl. My backup servers do not have users connecting to them, so it is easy link the /.rnd modification with the first smb session.

The github mirror for samba has this source file that determines the location of .rnd: https://github.com/samba-team/samba/blob/d8a5565ae647352d11d622bd4e73ff4568678a7c/source4/heimdal/lib/hcrypto/rand.c

There are several kerberos functions in samba that have dependencies on that code.

#36 Updated by William Grzybowski over 4 years ago

  • Copied to Bug #23304: /.rnd file being written very often added

#37 Updated by William Grzybowski over 4 years ago

  • Status changed from 15 to Resolved

Since there are two different bugs here and one of them has already been resolved I have split it.
Lets continue the .rnd discussion in #23304

#38 Updated by John Hixson over 4 years ago

Philip Spigelmire wrote:

John Hixson wrote:

Can you please try what William suggested with editing /etc/ssl/openssl.cnf and setting RANDFILE to /tmp/.rnd ? This is not a kerberos or a samba issue, this is an openssl issue. We need confirmation that this fixes the issue so we can get it in the next release.

Yes, I have done that - and there was no change. I'm fairly certain this is coming from samba, and as far as I can tell, samba does not depend on openssl. My backup servers do not have users connecting to them, so it is easy link the /.rnd modification with the first smb session.

The github mirror for samba has this source file that determines the location of .rnd: https://github.com/samba-team/samba/blob/d8a5565ae647352d11d622bd4e73ff4568678a7c/source4/heimdal/lib/hcrypto/rand.c

There are several kerberos functions in samba that have dependencies on that code.

These are functions when running samba as a DC. Are you running samba as a DC?

#39 Avatar?id=14398&size=24x24 Updated by Kris Moore over 4 years ago

  • Target version changed from 9.10.3 to 11.0

#41 Updated by Vaibhav Chauhan about 4 years ago

  • Target version changed from 11.0 to 11.0-RC

Also available in: Atom PDF