Skip to content

Instantly share code, notes, and snippets.

@ferebee

ferebee/gist:0f8169cd0ea19b656c51

Created August 6, 2014 13:50
Show Gist options
  • Save ferebee/0f8169cd0ea19b656c51 to your computer and use it in GitHub Desktop.
Save ferebee/0f8169cd0ea19b656c51 to your computer and use it in GitHub Desktop.
Download ZIP
SmartOS getcwd() vs. netatalk (part 2)
Raw
gistfile1.txt
Debugging performance issue of OS X 10.9 Mavericks Finder vs. netatalk 3.1.2 on SmartOS
Part 2 - kernel DNLC cache size increased from 450,000 (default) to 10,000,000 entries
This is a followup to <https://gist.github.com/ferebee/99016ccd293b3f616c77> which shows
behavior with the DNLC at its default size of 450,000.
Server is 24-core (dual Xeon E5-2620) SmartOS joyent_20140613T024634Z
with 128 GB RAM, Intel X520 10GbE network card.
Client is a MacBookPro10,1 via 1GbE.
The OS X 10.9 Finder is extremely slow to display the contents of folders on the AFP
volume. Server load is still very low, perhaps somewhat higher than on the first test.
=== afp.d Dtrace script provided by Ralph Böhme ===
./afp.d -n afpd
Collecting data... (ctrl-c to stop)
^C
Ran for 32828026 us (32 s)
Sum of time spend
=================
... disk IO: 5372358 us (5 s)
... network IO: 215871190 us (215 s)
Sum of time spend in syscalls
=============================
gtime 0
getpid 1
lwp_sigmask 30
setcontext 51
setitimer 57
readlink 60
fdsync 208
write 445
getuid 549
statvfs 2134
stat 3309
rmdir 3435
fstat 17679
seteuid 20077
pwrite 32601
send 36176
fcntl 57557
unlink 60284
read 70595
getdents 74952
close 85387
recv 89711
sendfilev 142045
writev 191392
acl 257123
open 501228
openat 761476
chdir 909476
lstat 3567252
getcwd 63834762
pollsys 215412330
Total number of syscalls
========================
readlink 8
fdsync 10
lwp_sigmask 16
setcontext 16
setitimer 16
getpid 20
gtime 20
write 40
statvfs 115
stat 127
sendfilev 491
rmdir 711
pwrite 1302
getdents 2794
send 4428
read 10784
unlink 11546
fstat 15422
pollsys 16003
writev 20868
seteuid 23092
chdir 24176
getcwd 24194
fcntl 27173
getuid 34638
acl 38006
openat 54704
open 57420
close 58050
recv 70787
lstat 116735
syscalls elapsed time average
=============================
getpid 0
getuid 0
gtime 0
seteuid 0
close 1
fstat 1
lwp_sigmask 1
recv 1
fcntl 2
setcontext 3
setitimer 3
rmdir 4
unlink 5
acl 6
read 6
readlink 7
open 8
send 8
writev 9
write 11
openat 13
statvfs 18
fdsync 20
pwrite 25
getdents 26
stat 26
lstat 30
chdir 37
sendfilev 289
getcwd 2638
pollsys 13460
Elapsed time distribution
=========================
gtime
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 20
1 | 0
getpid
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 19
1 |@@ 1
2 | 0
lwp_sigmask
value ------------- Distribution ------------- count
-1 | 0
0 |@@@ 1
1 |@@@@@@@@@@@@@@@@@@@@ 8
2 |@@@@@@@@ 3
4 |@@@@@@@@@@ 4
8 | 0
setcontext
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12
4 |@@@@@@@@@@ 4
8 | 0
setitimer
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@ 9
4 |@@@@@@@@@@@@@@@@@@ 7
8 | 0
readlink
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@ 4
8 |@@@@@@@@@@@@@@@@@@@@ 4
16 | 0
fdsync
value ------------- Distribution ------------- count
0 | 0
1 |@@@@ 1
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 7
4 |@@@@ 1
8 | 0
16 | 0
32 | 0
64 | 0
128 |@@@@ 1
256 | 0
write
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@ 17
8 |@@@@@@@@@@@@@@@@@@@@ 20
16 |@@ 2
32 |@ 1
64 | 0
getuid
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 34343
1 | 181
2 | 95
4 | 7
8 | 12
16 | 0
statvfs
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@ 13
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 99
32 |@ 3
64 | 0
stat
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 107
32 |@@@@@ 16
64 |@ 4
128 | 0
rmdir
value ------------- Distribution ------------- count
1 | 0
2 | 4
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 693
8 |@ 9
16 | 3
32 | 2
64 | 0
fstat
value ------------- Distribution ------------- count
-1 | 0
0 | 14
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 13567
2 |@@@@@ 1759
4 | 65
8 | 17
16 | 0
seteuid
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@ 3478
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 19323
2 | 269
4 | 13
8 | 9
16 | 0
pwrite
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1073
32 |@@@@@@@ 229
64 | 0
send
value ------------- Distribution ------------- count
0 | 0
1 | 1
2 | 11
4 |@@@@@@@@ 912
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3480
16 | 24
32 | 0
getdents
value ------------- Distribution ------------- count
0 | 0
1 | 1
2 |@@@@@@@@@@@ 748
4 |@@@@@@@ 492
8 |@@@@ 286
16 |@@ 110
32 |@@@@@@@@@@@@@@@ 1079
64 |@ 77
128 | 1
256 | 0
read
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9495
8 |@@@@ 1206
16 | 82
32 | 1
64 | 0
fcntl
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@ 5519
1 |@@@@@@@@@@@@@@@@@@@@ 13624
2 |@@@@@@@@@ 6389
4 | 332
8 | 164
16 |@ 851
32 | 294
64 | 0
unlink
value ------------- Distribution ------------- count
1 | 0
2 |@ 307
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9312
8 |@@@@@@ 1810
16 | 110
32 | 5
64 | 2
128 | 0
close
value ------------- Distribution ------------- count
-1 | 0
0 | 124
1 |@@@@@@@@@@@@@@@@@@@@@@@ 32690
2 |@@@@@@@@@@@@@@@@@ 24928
4 | 267
8 | 39
16 | 1
32 | 1
64 | 0
recv
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@ 16256
1 |@@@@@@@@@@@@@@@@@ 29460
2 |@@@@@@@@@@@@@ 23357
4 |@ 1492
8 | 161
16 | 61
32 | 0
sendfilev
value ------------- Distribution ------------- count
4 | 0
8 | 4
16 |@@@@@@@@@ 111
32 |@@@@@ 57
64 |@@@@ 55
128 |@@@@@@@@@@ 125
256 |@@@@@ 58
512 |@@@@@@ 78
1024 | 1
2048 | 0
4096 | 0
8192 | 1
16384 | 1
32768 | 0
writev
value ------------- Distribution ------------- count
1 | 0
2 | 43
4 |@@@ 1574
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 18695
16 |@ 472
32 | 81
64 | 3
128 | 0
acl
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@ 4388
2 |@@@@@@@ 6246
4 |@@@@@@@@ 7431
8 |@@@@@@@@@@@@@@@@@@@@@ 19604
16 | 117
32 | 10
64 | 200
128 | 10
256 | 0
open
value ------------- Distribution ------------- count
1 | 0
2 |@@@@ 6059
4 |@@@@@@@ 10648
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39585
16 | 532
32 | 292
64 | 242
128 | 62
256 | 0
openat
value ------------- Distribution ------------- count
1 | 0
2 |@ 801
4 | 26
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 42862
16 |@@@@@@@ 10080
32 |@ 911
64 | 21
128 | 3
256 | 0
chdir
value ------------- Distribution ------------- count
4 | 0
8 |@ 370
16 |@@@@@@@@@@@@@@@@@@@@@ 12807
32 |@@@@@@@@@@@@@@@@ 9715
64 |@@ 1246
128 | 38
256 | 0
lstat
value ------------- Distribution ------------- count
0 | 0
1 |@@ 5406
2 |@@ 5220
4 |@@ 5349
8 |@@@@@@@@@@@ 33160
16 |@@@@@@ 17299
32 |@@@@@@@@@@@@ 35070
64 |@@@@@ 14903
128 | 328
256 | 0
getcwd
value ------------- Distribution ------------- count
4 | 0
8 | 67
16 |@@@@@@@@@@@@ 7352
32 |@@@@@@@@@@@@@@@@@@ 10768
64 |@@@@@@@@ 5104
128 |@ 794
256 | 27
512 | 0
1024 | 0
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 0
262144 | 1
524288 | 78
1048576 | 3
2097152 | 0
pollsys
value ------------- Distribution ------------- count
0 | 0
1 | 177
2 | 51
4 | 57
8 |@@ 931
16 |@ 465
32 |@ 221
64 |@ 213
128 |@@@@@@@@@@@@@ 5335
256 |@@@@@@@@@@@@@@@@ 6238
512 |@ 588
1024 |@ 202
2048 | 74
4096 | 64
8192 |@@@ 1230
16384 | 24
32768 | 13
65536 | 25
131072 | 30
262144 | 18
524288 | 8
1048576 | 11
2097152 | 12
4194304 | 13
8388608 | 2
16777216 | 1
33554432 | 0
AFP functions called
====================
AFP_FLUSHFORK 10
AFP_GETVOLPARAM 115
AFP_RESOLVEID 156
AFP_READ_EXT 504
AFP_SETFORKPARAM 1301
AFP_WRITE_EXT 1302
AFP_ENUMERATE_EXT2 1403
AFP_CLOSEFORK 2053
AFP_OPENFORK 2076
AFP_GETFLDRPARAM 5665
AFP_GETEXTATTR 10848
Sum of time spend in each AFP function
======================================
AFP_GETVOLATTR 217
AFP_GETEXTATARAM 220
AFP_FLUSHFORK 298
AFP_RESOLVEID 9295
AFP_GETVOLPARAM 26411
AFP_WRITE_EXT 107377
AFP_READ_EXT 159016
AFP_CLOSEFORK 263338
AFP_SETFORKPARAM 423136
AFP_OPENFORK 1223950
AFP_ENUMERATE_EXT2 9068065
AFP_GETFLDRPARAM 15749447
AFP_GETEXTATTR 46613661
Average service time per AFP function
=====================================
AFP_FLUSHFORK 29
AFP_RESOLVEID 59
AFP_WRITE_EXT 82
AFP_CLOSEFORK 128
AFP_GETVOLPARAM 231
AFP_READ_EXT 315
AFP_SETFORKPARAM 324
AFP_OPENFORK 589
AFP_GETFLDRPARAM 2781
AFP_GETEXTATTR 4294
AFP_ENUMERATE_EXT2 6463
Service time distribution
=========================
AFP_FLUSHFORK
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 8
16 |@@@@ 1
32 | 0
64 | 0
128 |@@@@ 1
256 | 0
AFP_GEAEXTAT
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
512 | 0
AFP_RESOLVEID
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 147
64 |@@ 9
128 | 0
AFP_GETVOLPARAM
value ------------- Distribution ------------- count
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 96
256 |@@@@@@ 18
512 | 0
AFP_WRITE_EXT
value ------------- Distribution ------------- count
16 | 0
32 |@@ 67
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1221
128 | 13
256 | 0
AFP_READ_EXT
value ------------- Distribution ------------- count
4 | 0
8 |@ 14
16 | 4
32 |@@@@@@@@@ 117
64 |@@@@@@@ 91
128 |@@@@@@@@@@ 120
256 |@@@@@ 61
512 |@@@@@@@ 93
1024 | 1
2048 | 0
4096 | 0
8192 | 1
16384 | 1
32768 | 0
AFP_CLOSEFORK
value ------------- Distribution ------------- count
1 | 0
2 | 4
4 | 0
8 | 0
16 |@@@@@@@@@@@ 546
32 |@ 32
64 |@@@ 167
128 |@@@@@@@@@@@@@@@@@@@@@@@@@ 1292
256 | 10
512 | 0
AFP_SETFORKPARAM
value ------------- Distribution ------------- count
64 | 0
128 | 2
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1293
512 | 7
1024 | 0
AFP_OPENFORK
value ------------- Distribution ------------- count
128 | 0
256 |@@@@ 203
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1865
1024 | 6
2048 | 0
4096 | 0
8192 | 1
16384 | 0
AFP_ENUMERATE_EXT2
value ------------- Distribution ------------- count
16 | 0
32 | 4
64 |@ 26
128 |@@@@@ 183
256 |@@@@@@@@@@@@@@ 502
512 |@@@@ 135
1024 |@@@@@ 192
2048 |@@ 83
4096 |@@ 74
8192 |@@@@@ 189
16384 | 6
32768 | 2
65536 | 0
131072 | 0
262144 | 0
524288 | 7
1048576 | 0
AFP_GETFLDRPARAM
value ------------- Distribution ------------- count
16 | 0
32 |@ 130
64 | 23
128 | 44
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4212
512 |@@@@@@@@@ 1204
1024 | 32
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 0
262144 | 1
524288 | 17
1048576 | 1
2097152 | 0
AFP_GETEXTATTR
value ------------- Distribution ------------- count
16 | 0
32 | 2
64 | 30
128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 7668
256 |@@@@@@@@@@ 2719
512 |@ 368
1024 | 12
2048 | 0
4096 | 0
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 0
262144 | 0
524288 | 50
1048576 | 4
2097152 | 0
Total number of CNID queries
===========================
CNID 341
Sum of time spend in CNID queries
=================================
CNID 21922
Elapsed time average for CNID queries
====================
CNID 64
Elapsed time distribution for CNID queries
==========================================
CNID
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 296
64 |@@ 21
128 |@@@ 23
256 | 1
512 | 0
Sum of data read and written via AFP
====================================
write_fork.isra.2 1626088
read_fork.isra.5 32832422
AFP read/write IO size distribution
===================================
write_fork.isra.2
value ------------- Distribution ------------- count
32 | 0
64 | 1
128 | 4
256 | 1
512 | 0
1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1296
2048 | 0
read_fork.isra.5
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@ 61
1024 | 4
2048 | 0
4096 |@@@@@ 66
8192 |@ 12
16384 |@@@ 37
32768 |@@@@@@@@@@@@@ 157
65536 |@@@ 31
131072 |@@@@@@@@ 95
262144 |@@ 27
524288 | 0
AFP read/write average IO size
==============================
write_fork.isra.2 1248
read_fork.isra.5 67004
Times are microseconds (1/1.000.000 s)
A kernel Flame Graph taken in the same environment is available at
<http://fere.be/p/netatalk-flamegraph-2.svg>
The kernel is still spending a lot of time in dnlc_reverse_lookup, with most of the rest
dedicated to mutex_enter() and mutex_exit().
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment