Date: Sun, 15 Apr 2012 18:29:28 +0000 From: Alexander Best <arundel@freebsd.org> To: Alexander Leidinger <Alexander@Leidinger.net> Cc: freebsd-emulation@freebsd.org Subject: Re: [PATCH] pipe2 for Linuxulator Message-ID: <20120415182928.GA55270@freebsd.org> In-Reply-To: <20120415181613.GA52958@freebsd.org> References: <20120415000216.GA53624@freebsd.org> <20120415101157.GA67049@freebsd.org> <20120415112308.GA77985@freebsd.org> <20120415134444.000005cc@unknown> <20120415115112.GA83717@freebsd.org> <20120415143441.00000948@unknown> <20120415130306.GA95208@freebsd.org> <20120415163059.0000715d@unknown> <20120415144155.GA15993@freebsd.org> <20120415181613.GA52958@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On Sun Apr 15 12, Alexander Best wrote: > On Sun Apr 15 12, Alexander Best wrote: > > On Sun Apr 15 12, Alexander Leidinger wrote: > > > On Sun, 15 Apr 2012 13:03:06 +0000 Alexander Best <arundel@freebsd.org> > > > wrote: > > > > > > > On Sun Apr 15 12, Alexander Leidinger wrote: > > > > > On Sun, 15 Apr 2012 11:51:12 +0000 Alexander Best > > > > > <arundel@freebsd.org> wrote: > > > > > > > > > > > ahh ok. i've managed to get some stats via stats_timing.d. this > > > > > > is a snapshot during which a newly loaded tab in chromium was > > > > > > unresponsive for about 5 seconds. without the linux flash plugin > > > > > > running i never experienced such lock ups. > > > > > > > > > > > > i've attached the d-script stats. > > > > > > > > > > What about the trace_futexes script and the two check_* scripts? The > > > > > stats show that there is a lot of work spend in the futexes. > > > > > > > > i'm having problems with those scripts. they have a negative impact > > > > on the linux processes. when i have the player at www.mixcloud.com > > > > running and run those scripts the music stops and the flash graphics > > > > get all distorted. here's some output from the trace_futexes.d script: > > > > > > > > otaku% sudo ./trace_futexes.d > > > > dtrace: 808 dynamic variable drops with non-empty dirty list > > > > dtrace: 833 failed speculations (available buffer(s) still busy) > > > > > > You should increase the buffers in the scripts, they are overflowing. > > > > > > [...] > > > > ERROR: missing_access_check in linuxulator32:futex:futex_atomic_op > > > > > > This is missing code in the kernel... or a superfluous comment. > > > > > > > kernel`ia32_syscall+0x299 > > > > kernel`0xffffffff805b05e5 > > > > > > > > dtrace: ERROR: open failed: No such file or directory > > > > `0x287b6533 > > > > Fatal error 'mutex is on list' at line 424 in > > > > file /usr/github-freebsd-head/lib/libthr/thread/thr_mutex.c (errno = > > > > 0) > > > > > > No idea. > > > > > > > this is from the check_error.d script: > > > > > > > > otaku% sudo ./check_error.d > > > > ERROR: sleep_error in linuxulator32:futex:futex_sleep > > > > > > Well... the sx_sleep returned with a non-null value. I assume this > > > means a timeout fired. No idea if it is good or bad. > > > > > > > kernel`ia32_syscall+0x299 > > > > kernel`0xffffffff805b05e5 > > > > > > > > 0x287b6278 > > > > 0x2a12800029d5fa5c > > > > ERROR: sleep_error in linuxulator32:futex:futex_wait > > > > > > As above. > > > > > > > kernel`ia32_syscall+0x299 > > > > kernel`0xffffffff805b05e5 > > > > > > > > 0x287b6278 > > > > 0x2a12800029d5fa5c > > > > > > > the check_internal_locks.d scripts seems to work fine. i think we > > > > talked about the failed-speculation-warnings beforehand and that they > > > > aren't critical: > > > > > > Yes and no... you do not have enough buffers to store all the info the > > > script want to store. As such it does not work as intended. > > > > i've set > > > > #pragma D option dynvarsize=512m > > #pragma D option specsize=512m > > > > in check_internal_locks.d > > > > however i get a warning that the size got downgraded and still the buffers > > don't seem to be large enough: > > > > dtrace: dynamic variable size lowered to 256m > > dtrace: 220 failed speculations (available buffer(s) still busy) > > dtrace: 206 failed speculations (available buffer(s) still busy) > > dtrace: 205 failed speculations (available buffer(s) still busy) > > dtrace: 206 failed speculations (available buffer(s) still busy) > > dtrace: 182 failed speculations (available buffer(s) still busy) > > dtrace: 219 failed speculations (available buffer(s) still busy) > > dtrace: 194 failed speculations (available buffer(s) still busy) > > dtrace: 210 failed speculations (available buffer(s) still busy) > > dtrace: 218 failed speculations (available buffer(s) still busy) > > dtrace: 206 failed speculations (available buffer(s) still busy) > > dtrace: 222 failed speculations (available buffer(s) still busy) > > dtrace: 214 failed speculations (available buffer(s) still busy) > > dtrace: 213 failed speculations (available buffer(s) still busy) > > dtrace: 205 failed speculations (available buffer(s) still busy) > > dtrace: 216 failed speculations (available buffer(s) still busy) > > dtrace: 220 failed speculations (available buffer(s) still busy) > > dtrace: 210 failed speculations (available buffer(s) still busy) > > > > maybe the problem with the above errors was that my kernel got built with > > dtrace support, but my world didn't. i'm now rebuilding and installing world. > > maybe that fixes some of the issues. > > > > > > > > > > > > Number of locks per type: > > > > emul_shared_rlock 3 > > > > emul_shared_wlock 37 > > > > emul_lock 55 > > > > futex_mtx 31179 > > here are the results for a single flash instance: > > otaku% sudo time ./check_internal_locks.d > dtrace: 217 failed speculations (available buffer(s) still busy) > dtrace: 223 failed speculations (available buffer(s) still busy) > dtrace: 218 failed speculations (available buffer(s) still busy) > dtrace: 216 failed speculations (available buffer(s) still busy) > dtrace: 206 failed speculations (available buffer(s) still busy) > dtrace: 200 failed speculations (available buffer(s) still busy) > dtrace: 218 failed speculations (available buffer(s) still busy) > dtrace: 246 failed speculations (available buffer(s) still busy) > dtrace: 218 failed speculations (available buffer(s) still busy) > dtrace: 258 failed speculations (available buffer(s) still busy) > dtrace: 223 failed speculations (available buffer(s) still busy) > dtrace: 246 failed speculations (available buffer(s) still busy) > dtrace: 240 failed speculations (available buffer(s) still busy) > dtrace: 258 failed speculations (available buffer(s) still busy) > dtrace: 252 failed speculations (available buffer(s) still busy) > dtrace: 230 failed speculations (available buffer(s) still busy) > dtrace: 257 failed speculations (available buffer(s) still busy) > ^C > dtrace: 227 failed speculations (available buffer(s) still busy) > Number of locks per type: > futex_mtx 4585 > > 18,48 real 0,10 user 0,36 sys > > and here for two flash tabs: > > otaku% sudo time ./check_internal_locks.d > dtrace: 1148 failed speculations (available buffer(s) still busy) > dtrace: 1524 failed speculations (available buffer(s) still busy) > dtrace: 1604 failed speculations (available buffer(s) still busy) > dtrace: 1029 failed speculations (available buffer(s) still busy) > dtrace: 1471 failed speculations (available buffer(s) still busy) > dtrace: 1466 failed speculations (available buffer(s) still busy) > dtrace: 1720 failed speculations (available buffer(s) still busy) > dtrace: 1049 failed speculations (available buffer(s) still busy) > dtrace: 1549 failed speculations (available buffer(s) still busy) > dtrace: 1421 failed speculations (available buffer(s) still busy) > dtrace: 1595 failed speculations (available buffer(s) still busy) > dtrace: 1097 failed speculations (available buffer(s) still busy) > dtrace: 1853 failed speculations (available buffer(s) still busy) > dtrace: 1900 failed speculations (available buffer(s) still busy) > dtrace: 1729 failed speculations (available buffer(s) still busy) > dtrace: 1389 failed speculations (available buffer(s) still busy) > dtrace: 1314 failed speculations (available buffer(s) still busy) > dtrace: 1712 failed speculations (available buffer(s) still busy) > ^C > dtrace: 1615 failed speculations (available buffer(s) still busy) > Number of locks per type: > futex_mtx 29364 > > 19,41 real 0,09 user 0,32 sys > > ...and for three flash tabs: > > otaku% sudo time ./check_internal_locks.d > dtrace: 535 failed speculations (available buffer(s) still busy) > dtrace: 213 failed speculations (available buffer(s) still busy) > dtrace: 282 failed speculations (available buffer(s) still busy) > dtrace: 571 failed speculations (available buffer(s) still busy) > dtrace: 666 failed speculations (available buffer(s) still busy) > dtrace: 857 failed speculations (available buffer(s) still busy) > dtrace: 1310 failed speculations (available buffer(s) still busy) > dtrace: 1277 failed speculations (available buffer(s) still busy) > dtrace: 118 failed speculations (available buffer(s) still busy) > dtrace: 1503 failed speculations (available buffer(s) still busy) > dtrace: 2069 failed speculations (available buffer(s) still busy) > dtrace: 3562 failed speculations (available buffer(s) still busy) > dtrace: 6561 failed speculations (available buffer(s) still busy) > dtrace: 3750 failed speculations (available buffer(s) still busy) > dtrace: 2569 failed speculations (available buffer(s) still busy) > dtrace: 1362 failed speculations (available buffer(s) still busy) > dtrace: 2722 failed speculations (available buffer(s) still busy) > dtrace: 3461 failed speculations (available buffer(s) still busy) > dtrace: 2579 failed speculations (available buffer(s) still busy) > dtrace: 3451 failed speculations (available buffer(s) still busy) > dtrace: 2325 failed speculations (available buffer(s) still busy) > ^C > dtrace: 2632 failed speculations (available buffer(s) still busy) > Number of locks per type: > emul_shared_wlock 14 > emul_lock 20 > futex_mtx 45571 > > 22,46 real 0,11 user 0,35 sys running stats_timing.d revealed something strange...according to this section: Number of calls per provider/application/kernel function: linuxulator32 npviewer.bin linux_schedtail 2 linuxulator32 npviewer.bin linux_set_robust_list 2 linuxulator32 npviewer.bin proc_exit 2 linuxulator32 npviewer.bin proc_init 2 linuxulator32 npviewer.bin release_futexes 2 linuxulator32 npviewer.bin fetch_robust_entry 4 linuxulator32 npviewer.bin linux_get_osname 8 linuxulator32 npviewer.bin linux_get_osrelease 8 linuxulator32 npviewer.bin em_find 12 linuxulator32 npviewer.bin linux_get_prison 16 linuxulator32 npviewer.bin futex_atomic_op 734 linuxulator32 npviewer.bin futex_wake 1082 linuxulator32 npviewer.bin futex_sleep 1133 linuxulator32 npviewer.bin futex_wait 1133 linuxulator32 npviewer.bin linux_emul_convpath 2949 linuxulator32 npviewer.bin futex_put 2970 linuxulator32 npviewer.bin linux_sys_futex 3211 linuxulator32 npviewer.bin futex_get 3945 linuxulator32 npviewer.bin futex_get0 3945 linuxulator32 npviewer.bin linux_clock_gettime 75342 linuxulator32 npviewer.bin linux_to_native_clockid 75342 linuxulator32 npviewer.bin native_to_linux_timespec 75342 proc_exit only got callded twice. however according to this section: Longest running (CPU-time!) functions per provider (in ns): linuxulator32 proc_exit -16995 linuxulator32 linux_emul_convpath -11330 linuxulator32 futex_wait -3950 linuxulator32 futex_sleep -3535 linuxulator32 proc_init -3310 linuxulator32 release_futexes -2075 linuxulator32 linux_schedtail -1350 linuxulator32 linux_get_osname -1280 linuxulator32 linux_sys_futex -1090 linuxulator32 linux_set_robust_list -860 linuxulator32 futex_get -770 linuxulator32 linux_get_osrelease -760 linuxulator32 linux_clock_gettime -570 linuxulator32 futex_put -560 linuxulator32 futex_get0 -555 linuxulator32 futex_atomic_op -325 linuxulator32 em_find -190 linuxulator32 fetch_robust_entry -180 linuxulator32 linux_get_prison -155 linuxulator32 futex_wake -120 linuxulator32 linux_to_native_clockid -90 linuxulator32 native_to_linux_timespec -90 the CPU spent a lot of time for those two calls. cheers. alex > > > i've tuned the script to have the maximum buffer size of 256 megabyte via > > #pragma D option dynvarsize=256m > #pragma D option specsize=256m > > ...still the buffers seem to be too small. > > also...even after installing a fresh kernel and world with dtrace enabled, > the "check_error.d" and "trace_futexes.d" fail and sometimes even render > the flash instance unusable. > > cheers. > alex > > > > > > > Depending on how long you traced: that's a lot of futex operations. > > > > i traced for ~ 5 seconds. i'll make sure to prepend the time command to any > > dtrace script next time to give you more exact numbers. > > > > cheers. > > alex > > > > > > > > Bye, > > > Alexander. > > > > > > -- > > > http://www.Leidinger.net Alexander @ Leidinger.net: PGP ID = B0063FE7 > > > http://www.FreeBSD.org netchild @ FreeBSD.org : PGP ID = 72077137
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20120415182928.GA55270>