Skip to content

Instantly share code, notes, and snippets.

@ferebee

ferebee/netatalk performance, getcwd is slow?

Last active August 29, 2015 14:04
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save ferebee/99016ccd293b3f616c77 to your computer and use it in GitHub Desktop.
Save ferebee/99016ccd293b3f616c77 to your computer and use it in GitHub Desktop.
Download ZIP
Output of afp.d Dtrace script on netatalk with OS X 10.9 Finder issue
Raw
netatalk performance, getcwd is slow?
Debugging performance issue of OS X 10.9 Mavericks Finder vs. netatalk 3.1.2
[see <https://gist.github.com/ferebee/0f8169cd0ea19b656c51> for followup]
Server is 24-core (dual Xeon E5-2620) SmartOS joyent_20140613T024634Z
with 128 GB RAM, Intel X520 10GbE network card.
Client is iMac14,2 via 1GbE.
The Finder is extremely slow to display the contents of folders on the AFP
volume. Server load is currently very low.
On a Mac mini with OS X 10.6.8, the Finder is snappy, no performance issues
at all.
The OS X 10.9 Finder appears to continually loop through the AFP folder
hierarchy, calling fsgetpath, getxattr and/or getattrlist on files and folders
over and over again.
Question: why is getcwd sometimes taking so long?
=== afp.d Dtrace script provided by Ralph Böhme ===
# /root/afp.d -p 4702
Collecting data... (ctrl-c to stop)
^C
Ran for 35573331 us (35 s)
Sum of time spend
=================
... disk IO: 115787 us (0 s)
... network IO: 128457 us (0 s)
Sum of time spend in syscalls
=============================
lwp_sigmask 1
setcontext 4
setitimer 5
rmdir 189
getuid 263
sendfilev 336
fcntl 361
send 381
getdents 398
statvfs 406
fstat 479
seteuid 582
stat 629
unlink 1660
read 2716
close 2770
recv 4050
writev 5668
acl 6734
open 12941
chdir 15153
openat 24484
lstat 64230
pollsys 118022
getcwd 35153449
Total number of syscalls
========================
lwp_sigmask 1
setcontext 1
setitimer 1
sendfilev 8
rmdir 13
stat 13
statvfs 13
send 21
getdents 26
fcntl 118
unlink 148
read 198
fstat 223
pollsys 277
writev 293
seteuid 296
getcwd 373
chdir 374
getuid 444
acl 552
openat 664
open 740
close 807
recv 1145
lstat 1581
syscalls elapsed time average
=============================
getuid 0
lwp_sigmask 1
seteuid 1
fstat 2
close 3
fcntl 3
recv 3
setcontext 4
setitimer 5
unlink 11
acl 12
read 13
rmdir 14
getdents 15
open 17
send 18
writev 19
statvfs 31
openat 36
chdir 40
lstat 40
sendfilev 42
stat 48
pollsys 426
getcwd 94245
Elapsed time distribution
=========================
lwp_sigmask
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2 | 0
setcontext
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
setitimer
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
rmdir
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@ 3
8 |@@@@@@@@@@@@@@@@@@ 6
16 |@@@@@@@@@ 3
32 |@@@ 1
64 | 0
getuid
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 294
1 |@@@@@@@@@ 104
2 |@@@@ 44
4 | 0
8 | 0
16 | 1
32 | 1
64 | 0
sendfilev
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 4
32 |@@@@@@@@@@ 2
64 |@@@@@@@@@@ 2
128 | 0
send
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@ 12
16 |@@@@@@@@@@@@@ 7
32 |@@@@ 2
64 | 0
statvfs
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@ 8
32 |@@@@@@@@@@@@@@@ 5
64 | 0
getdents
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@ 4
4 |@@@@@@@@@@@ 7
8 |@@@@@@ 4
16 |@@@@@@@@@@@ 7
32 |@@@@@@ 4
64 | 0
fcntl
value ------------- Distribution ------------- count
-1 | 0
0 | 1
1 |@@@@@@@ 20
2 |@@@@@@@@@@@@@@@@@@@@ 59
4 |@@@@@@@@@@@ 33
8 |@@ 5
16 | 0
fstat
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@ 103
2 |@@@@@@@@@@@@@@@@@ 95
4 |@@@@ 23
8 | 1
16 | 1
32 | 0
stat
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@ 2
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 10
64 |@@@ 1
128 | 0
seteuid
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@ 154
2 |@@@@@@@@@@@@@@@@ 115
4 |@@@ 25
8 | 0
16 | 2
32 | 0
unlink
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@ 61
8 |@@@@@@@@@@@@@@@ 56
16 |@@@@@@@ 25
32 |@@ 6
64 | 0
read
value ------------- Distribution ------------- count
2 | 0
4 |@@ 12
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 141
16 |@@@@@@@@ 39
32 |@ 6
64 | 0
close
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@ 99
2 |@@@@@@@@@@@@@@@@@@@@ 394
4 |@@@@@@@@@@@@@@ 281
8 |@ 23
16 | 10
32 | 0
recv
value ------------- Distribution ------------- count
-1 | 0
0 | 10
1 |@@@@@@@@@@ 283
2 |@@@@@@@@@@@@@@ 410
4 |@@@@@@@@@@@@ 352
8 |@@ 69
16 |@ 20
32 | 1
64 | 0
writev
value ------------- Distribution ------------- count
1 | 0
2 | 1
4 | 0
8 |@@@@@@@@@@@ 83
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 191
32 |@@ 18
64 | 0
acl
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@ 72
4 |@@@@@@@@ 114
8 |@@@@@@@@@@@@@@@@ 220
16 |@@@@@@@@@ 130
32 |@ 16
64 | 0
open
value ------------- Distribution ------------- count
1 | 0
2 |@ 26
4 |@@@@@ 87
8 |@@@@@@@@@@@@@@ 253
16 |@@@@@@@@@@@@@@@@ 294
32 |@@@@ 80
64 | 0
chdir
value ------------- Distribution ------------- count
4 | 0
8 |@@ 19
16 |@@@@@@@@@@@@@@@@ 152
32 |@@@@@@@@@@@@@@@@ 152
64 |@@@@@ 47
128 | 4
256 | 0
openat
value ------------- Distribution ------------- count
1 | 0
2 | 3
4 | 8
8 |@@@ 45
16 |@@@@@@@@@@@@@@@@ 269
32 |@@@@@@@@@@@@@@@@ 272
64 |@@@@ 65
128 | 2
256 | 0
lstat
value ------------- Distribution ------------- count
0 | 0
1 | 1
2 |@ 58
4 |@@ 98
8 |@@@@@@ 236
16 |@@@@@@@@@@ 400
32 |@@@@@@@@@@@ 442
64 |@@@@@@@@ 315
128 |@ 31
256 | 0
pollsys
value ------------- Distribution ------------- count
8 | 0
16 | 1
32 | 1
64 |@ 4
128 |@@@@@@@ 48
256 |@@@@@@@@@@@@@@@@@@@ 133
512 |@@@@@@@@@@@@@ 90
1024 | 0
getcwd
value ------------- Distribution ------------- count
4 | 0
8 | 1
16 |@@@@@ 43
32 |@@@@@@@@@@@@@@ 127
64 |@@@@@@@@@@ 97
128 |@ 6
256 | 1
512 | 0
1024 | 0
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 2
262144 |@@@@@@@@@@ 91
524288 |@ 5
1048576 | 0
AFP functions called
====================
AFP_CLOSEFORK 8
AFP_OPENFORK 8
AFP_READ_EXT 8
AFP_GETVOLPARAM 13
AFP_ENUMERATE_EXT2 26
AFP_GETEXTATTR 126
AFP_GETFLDRPARAM 132
Sum of time spend in each AFP function
======================================
AFP_CLOSEFORK 486
AFP_READ_EXT 995
AFP_GETVOLPARAM 5085
AFP_ENUMERATE_EXT2 69777
AFP_OPENFORK 297334
AFP_GETEXTATTR 17179834
AFP_GETFLDRPARAM 17823421
Average service time per AFP function
=====================================
AFP_CLOSEFORK 60
AFP_READ_EXT 124
AFP_GETVOLPARAM 391
AFP_ENUMERATE_EXT2 2683
AFP_OPENFORK 37166
AFP_GETFLDRPARAM 135025
AFP_GETEXTATTR 136347
Service time distribution
=========================
AFP_CLOSEFORK
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6
64 |@@@@@@@@@@ 2
128 | 0
AFP_READ_EXT
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@ 1
64 |@@@@@@@@@@@@@@@@@@@@ 4
128 |@@@@@@@@@@@@@@@ 3
256 | 0
AFP_GETVOLPARAM
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 11
512 |@@@@@@ 2
1024 | 0
AFP_ENUMERATE_EXT2
value ------------- Distribution ------------- count
32 | 0
64 |@@ 1
128 |@@@@@@ 4
256 |@@@@@@@@@@@ 7
512 |@@ 1
1024 |@@@@@ 3
2048 |@@@@@ 3
4096 |@@@@@@@@ 5
8192 |@@@ 2
16384 | 0
AFP_OPENFORK
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@ 3
512 |@@@@@@@@@@@@@@@@@@@@ 4
1024 | 0
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 0
262144 |@@@@@ 1
524288 | 0
AFP_GETEXTATTR
value ------------- Distribution ------------- count
64 | 0
128 |@@@ 10
256 |@@@@@@@@@@@@@@@@@@@@ 64
512 |@@@@@@@ 21
1024 | 0
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 0
262144 |@@@@@ 15
524288 |@@@@ 14
1048576 |@ 2
2097152 | 0
AFP_GETFLDRPARAM
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@ 17
512 |@@@@@@@@@@@@@@@@@@@@ 66
1024 |@@@ 10
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 |@ 2
262144 |@@@@@@@ 24
524288 |@@@@ 13
1048576 | 0
Total number of CNID queries
===========================
CNID 61
Sum of time spend in CNID queries
=================================
CNID 4793
Elapsed time average for CNID queries
====================
CNID 78
Elapsed time distribution for CNID queries
==========================================
CNID
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 41
64 |@@@@@@@@ 12
128 |@@@@ 6
256 |@ 2
512 | 0
Sum of data read and written via AFP
====================================
read_fork.isra.5 116644
AFP read/write IO size distribution
===================================
read_fork.isra.5
value ------------- Distribution ------------- count
2 | 0
4 |@@@ 14
8 |@ 3
16 |@@ 13
32 |@@@@@ 26
64 | 0
128 | 0
256 |@@ 9
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 144
1024 |@ 4
2048 | 0
4096 |@ 3
8192 | 0
16384 | 1
32768 | 0
AFP read/write average IO size
==============================
read_fork.isra.5 537
Times are microseconds (1/1.000.000 s)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment