AFP speed issues

[Wind_freak]

Since about two upgrades ago AFP has been performing like crap. I host my iTunes library on my NAS and I am only able to watch about one or two shows on my Apple TV before I have to close iTunes and dismount my share. After I remount my share and start iTunes it works fine again.

Looking at the console messages on my NAS I see the below errors. If I setup cifs it runs just fine but then some of my automated scripts stop working and my time machine backup stops as well.
You'll notice its a ton of messages in a short period of time.
May 7 21:47:52 NAS01 afpd[11105]: afp_disconnect: trying primary reconnect
May 7 21:47:52 NAS01 afpd[27380]: Reconnect: transfering session to child[10750]
May 7 21:47:52 NAS01 afpd[27380]: Reconnect: killing new session child[11105] after transfer
May 7 21:47:52 NAS01 afpd[10750]: afp_dsi_transfer_session: succesfull primary reconnect
May 7 21:47:52 NAS01 afpd[10750]: AFP Replay Cache match: id: 6151 / cmd: AFP_LISTEXTATTR
May 7 21:47:54 NAS01 afpd[11105]: afp_disconnect: primary reconnect succeeded
May 7 21:47:58 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:47:58 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:47:58 NAS01 afpd[10750]: dsi_disconnect: entering disconnected state
May 7 21:47:58 NAS01 afpd[11110]: Login by Steve (AFP3.4)
May 7 21:47:58 NAS01 afpd[11110]: afp_disconnect: trying primary reconnect
May 7 21:47:58 NAS01 afpd[27380]: Reconnect: transfering session to child[10750]
May 7 21:47:58 NAS01 afpd[27380]: Reconnect: killing new session child[11110] after transfer
May 7 21:47:58 NAS01 afpd[10750]: afp_dsi_transfer_session: succesfull primary reconnect
May 7 21:47:58 NAS01 afpd[10750]: AFP Replay Cache match: id: 6352 / cmd: AFP_LISTEXTATTR
May 7 21:48:00 NAS01 afpd[11110]: afp_disconnect: primary reconnect succeeded
May 7 21:48:03 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:03 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:03 NAS01 afpd[10750]: dsi_disconnect: entering disconnected state
May 7 21:48:03 NAS01 afpd[11115]: Login by Steve (AFP3.4)
May 7 21:48:03 NAS01 afpd[11115]: afp_disconnect: trying primary reconnect
May 7 21:48:03 NAS01 afpd[27380]: Reconnect: transfering session to child[10750]
May 7 21:48:03 NAS01 afpd[27380]: Reconnect: killing new session child[11115] after transfer
May 7 21:48:03 NAS01 afpd[10750]: afp_dsi_transfer_session: succesfull primary reconnect
May 7 21:48:03 NAS01 afpd[10750]: AFP Replay Cache match: id: 6499 / cmd: AFP_LISTEXTATTR
May 7 21:48:04 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:04 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:04 NAS01 afpd[10750]: dsi_disconnect: entering disconnected state
May 7 21:48:04 NAS01 afpd[11116]: Login by Steve (AFP3.4)
May 7 21:48:04 NAS01 afpd[11116]: afp_disconnect: trying primary reconnect
May 7 21:48:04 NAS01 afpd[27380]: Reconnect: transfering session to child[10750]
May 7 21:48:04 NAS01 afpd[27380]: Reconnect: killing new session child[11116] after transfer
May 7 21:48:04 NAS01 afpd[10750]: afp_dsi_transfer_session: succesfull primary reconnect
May 7 21:48:04 NAS01 afpd[10750]: AFP Replay Cache match: id: 6517 / cmd: AFP_LISTEXTATTR
May 7 21:48:05 NAS01 afpd[11115]: afp_disconnect: primary reconnect succeeded
May 7 21:48:06 NAS01 afpd[11116]: afp_disconnect: primary reconnect succeeded
May 7 21:48:10 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:10 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:10 NAS01 afpd[10750]: dsi_disconnect: entering disconnected state
May 7 21:48:10 NAS01 afpd[11121]: Login by Steve (AFP3.4)
May 7 21:48:10 NAS01 afpd[11121]: afp_disconnect: trying primary reconnect
May 7 21:48:10 NAS01 afpd[27380]: Reconnect: transfering session to child[10750]
May 7 21:48:10 NAS01 afpd[27380]: Reconnect: killing new session child[11121] after transfer
May 7 21:48:10 NAS01 afpd[10750]: afp_dsi_transfer_session: succesfull primary reconnect
May 7 21:48:10 NAS01 afpd[10750]: AFP Replay Cache match: id: 6797 / cmd: AFP_LISTEXTATTR
May 7 21:48:12 NAS01 afpd[11121]: afp_disconnect: primary reconnect succeeded
May 7 21:48:27 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:27 NAS01 afpd[10750]: dsi_stream_read: len:0, unexpected EOF
May 7 21:48:27 NAS01 afpd[10750]: dsi_disconnect: entering disconnected state
May 7 21:48:27 NAS01 afpd[11128]: Login by Steve (AFP
May 7 21:48:27 NAS01 afpd[11128]: afp_disconnect: trying primary reconnect
May 7 21:48:27 NAS01 afpd[27380]: Reconnect: transfering session to child[10750]
May 7 21:48:27 NAS01 afpd[27380]: Reconnect: killing new session child[11128] after transfer
May 7 21:48:27 NAS01 afpd[10750]: afp_dsi_transfer_session: succesfull primary reconnect
May 7 21:48:27 NAS01 afpd[10750]: AFP Replay Cache match: id: 7272 / cmd: AFP_LISTEXTATTR
May 7 21:48:29 NAS01 afpd[11128]: afp_disconnect: primary reconnect succeeded

 

[Bert Koot]

Same problem here. AFP is far to slow on FreeNAS. I switched to SMB a few weeks ago.

 

[Dennis.kulmosen]

What version of FreeNAS and Mac OS X are you both using??

 

[Bert Koot]

FreeNAS-9.2.1.5-RELEASE-x64 (80c1d35)
OS X 10.9.2 (13C1021)

Is there a way to suppress the logging? I am using TimeMachine by the way which works fine. But afp is slow compared to Samba.

....
....
May 11 08:57:11 proliant afpd[40353]: AFP statistics: 4581.11 KB read, 74688.16 KB written
May 11 08:57:11 proliant afpd[40353]: done
May 11 09:57:49 proliant afpd[41011]: Login by Bert (AFP3.4)
May 11 09:58:45 proliant afpd[41011]: AFP logout by Bert
May 11 09:58:45 proliant afpd[41011]: AFP statistics: 4885.22 KB read, 61421.38 KB written
May 11 09:58:45 proliant afpd[41011]: done
May 11 10:59:29 proliant afpd[41685]: Login by Bert (AFP3.4)
May 11 11:00:25 proliant afpd[41685]: AFP logout by Bert
May 11 11:00:25 proliant afpd[41685]: AFP statistics: 4698.05 KB read, 61479.14 KB written
May 11 11:00:25 proliant afpd[41685]: done
May 11 11:58:35 proliant afpd[42338]: Login by Bert (AFP3.4)
May 11 12:01:00 proliant afpd[42776]: Login by Bert (AFP3.4)
May 11 12:01:45 proliant afpd[42776]: AFP logout by Bert
May 11 12:01:45 proliant afpd[42776]: AFP statistics: 4810.57 KB read, 74678.68 KB written
May 11 12:01:45 proliant afpd[42776]: done
May 11 12:04:49 proliant kernel: arp: 192.168.178.47 moved from 02:b1:04:00:0b:0a to 00:9c:02:97:58:02 on epair0b
May 11 12:10:40 proliant afpd[42338]: AFP logout by Bert
May 11 12:10:40 proliant afpd[42338]: dsi_stream_read: len:0, unexpected EOF
May 11 12:10:40 proliant afpd[42338]: afp_over_dsi: client logged out, terminating DSI session
May 11 12:10:40 proliant afpd[42338]: AFP statistics: 1.02 KB read, 0.89 KB written
May 11 13:02:13 proliant afpd[43594]: Login by Bert (AFP3.4)
May 11 13:04:06 proliant afpd[43594]: AFP logout by Bert
May 11 13:04:06 proliant afpd[43594]: AFP statistics: 298019.18 KB read, 292799.94 KB written
May 11 13:04:06 proliant afpd[43594]: done
....
....

 

[Wind_freak]

I am using Mavericks with FreeNAS-9.2.1.5-RELEASE-x64 (80c1d35)

If I eject the nas drive and reconnect it will be fine for a tv show or two till it goes slow again.

If you haven't upgraded to the 9.2.1 series don't if you are running a mac. i think that is about where it broke with those rapid succession of broken updates.

 

[DaPlumber]

Maybe try taking netatalk (AFP) off line and rebuilding the CNID DB? Weird things happen if CNID DB is not quite right.

"sudo dbd -r -e -x -t /path/to/share" IIRC? It will lock the volume, rebuild the db and indexes, and show stats while running.

I don't think there's a way to do this from the GUI?

 

[Wind_freak]

I did do a DB rebuild and some things got better. But it's easy to get better from unusable. Now it is still unusable but less so. Thinking its time to try another nas software I just hope I can import in my zfs as AFP has become completely unusable. If I downgrade/upgrade back to 9.1 will it still see my zfs?

 

[DaPlumber]

The only other thing I can suggest is turn off AFP and anything else that's using that pool and scrub, baby, scrub!;)

Captain Obvious question: You don't have the same share exported via multiple protocols do you? AFP and CIFS for example.

The software is working fine for me and I'm almost exclusively an AFP user. Right now I have my iTunes server (old macbook) serving up 2 video streams from the store on the FreeNAS, a Time Machine backup in progress to another share from a family Mac mini and me browsing yet another from my Macbook. Nary a hiccup anywhere from afpd and the CPU on the FreeNAS is hardly breathing. Network's about saturated and the disks in the pool are chugging along nicely, but that's what they're FOR... <shrug>

 

[Wind_freak]

I only use AFP. And I've already scrubbed. Are you using the latest 9.2.1.5? All the problems started around 9.2

 

[DaPlumber]

Yup, Brand new freshly installed and pool formatted with 9.2.1.5-RELEASE. Still has the "new bytes" smell...

Did you scrub with the services disabled? It shouldn't make a difference, but I'm paranoid and I live longer that way.