So, I decided to take a bit of a look.
Firstly, 'vmstat -a' - a good top level peek.
procs memory page disks faults cpu
r b w avm fre flt re pi po fr sr ad0 cd0 in sy cs us sy id
3 0 0 21G 180M 30403 0 2 0 21520 976 27 0 598 462567 10061 25 31 44
1 0 0 21G 174M 10389 0 0 0 3320 980 0 0 913 1203071 11892 15 24 61
3 0 0 21G 192M 4028 0 0 0 4763 983 14 0 563 1246314 8166 15 23 62
1 0 0 21G 192M 2305 0 0 0 334 988 1 0 390 1165396 10784 18 20 62
2 0 0 21G 202M 30493 0 0 0 3154 983 4 0 340 1072100 13287 28 23 49
2 0 0 21G 202M 8440 0 0 0 646 979 1 0 391 1071166 8802 32 20 48
1 0 0 21G 204M 3608 0 0 0 1841 1954 31 0 516 1041635 11319 33 21 46
3 0 0 20G 212M 67782 0 0 0 2895 973 1 0 387 1053575 10995 28 26 46
2 0 0 21G 187M 25368 0 0 0 2483 989 7 0 475 1047031 12056 29 23 48
.. ok, a million syscalls a second. Fine.Let's ask dtrace what's going on:
root@victoria:/home/adrian # dtrace -n 'syscall:::entry { @[probefunc] = count(); }'
dtrace: description 'syscall:::entry ' matched 1082 probes
^C
gettimeofday 305
lstat 336
kevent 598
recvfrom 1018
__sysctl 1384
getpid 2158
sigprocmask 5189
select 5443
writev 6215
madvise 6606
setitimer 6729
recvmsg 17556
_umtx_op 40740
ppoll 853940
read 1152896
poll 1158669
write 2159990
ioctl 2170830
root@victoria:/home/adrian # dtrace -n 'syscall::read:return /execname == "firefox"/ { @["rval (bytes)"] =
quantize(arg1); }'
dtrace: description 'syscall::read:return ' matched 2 probes
^C
rval (bytes)
value ------------- Distribution ------------- count
-2 | 0
-1 | 1
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 496294
2 | 5
4 | 0
8 | 0
16 | 0
32 | 0
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 | 0
4096 | 6
8192 | 0
16384 | 0
32768 | 36
65536 | 0
root@victoria:/home/adrian # dtrace -n 'syscall::write:return /execname == "firefox"/ { @["rval (bytes)"] = quantize(arg1); }'
dtrace: description 'syscall::write:return ' matched 2 probes
^C
rval (bytes)
value ------------- Distribution ------------- count
-2 | 0
-1 |@@@@@@@@@@@@@@@@@@@@ 875025
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@ 876075
2 | 0
4 | 0
8 | 0
16 | 14
32 | 1
64 | 0
128 | 15
256 | 8
512 | 8
1024 | 29
2048 | 563
4096 | 0
8192 | 0
16384 | 0
32768 | 14
65536 | 0
... ok, so read and write is doing single byte transactions, and write is actually failing as often as it's succeeding.
so, what's actually going on? I decided to run truss briefly, and I get a lot of this:
_umtx_op(0x82efa2e80,UMTX_OP_MUTEX_WAIT,0x0,0x0,0x0) = 0 (0x0)
ioctl(68,SNDCTL_DSP_GETOPTR,0xce0c5ac0) = 0 (0x0)
_umtx_op(0x82b16fb70,UMTX_OP_MUTEX_WAIT,0x0,0x0,0x0) = 0 (0x0)
_umtx_op(0x8d6a57e58,UMTX_OP_NWAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
write(158,"x",1) ERR#35 'Resource temporarily unavailable'
_umtx_op(0x8006bd4b8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffbde44c88) = 0 (0x0)
So I'm guessing there's a lot of inefficient single byte read/write syscalls to wake up a remote thread, along with a lot of inefficient use of the sound API.
For sound ioctls:
ioctl(68,SNDCTL_DSP_GETOSPACE,0xd7d54e10) = 0 (0x0)
ioctl(68,SNDCTL_DSP_GETOPTR,0xd7d54e00) = 0 (0x0)
ioctl(68,SNDCTL_DSP_GETOSPACE,0xd7d54df0) = 0 (0x0)
ioctl(68,SNDCTL_DSP_GETOPTR,0xd7d54d50) = 0 (0x0)
.. so i'm guessing it's doing it every thread wakeup or something stupid, even if it doesn't need to yet.
No comments:
Post a Comment