Date: Sun, 15 Apr 2012 18:46:43 +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: <20120415184643.GA59617@freebsd.org> In-Reply-To: <20120415182928.GA55270@freebsd.org> References: <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> <20120415182928.GA55270@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 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.
eventually after trying a lot of time i managed to gather some stats from the
"trace_futexes.d" script:
Number of locks per type:
futex_mtx 91
Number of maximum number of futexes in the futex list:
1
Number of futexes still existing: -9Number of calls per provider/application/kernel function:
linuxulator32 npviewer.bin futex_atomic_op 5
linuxulator32 npviewer.bin futex_wake 6
linuxulator32 npviewer.bin futex_sleep 14
linuxulator32 npviewer.bin futex_wait 14
linuxulator32 npviewer.bin linux_sys_futex 33
linuxulator32 npviewer.bin futex_put 34
linuxulator32 npviewer.bin futex_get 38
linuxulator32 npviewer.bin futex_get0 38
Wallclock-timing statistics per provider/application/kernel function (in ns):
linuxulator32 npviewer.bin linux_sys_futex
value ------------- Distribution ------------- count
-1073741824 | 0
-536870912 |@@@@@ 4
-268435456 | 0
-134217728 |@@@@@@@ 6
-67108864 |@ 1
-33554432 |@ 1
-16777216 |@ 1
-8388608 | 0
-4194304 | 0
-2097152 | 0
-1048576 | 0
-524288 | 0
-262144 |@ 1
-131072 |@@@@@@ 5
-65536 | 0
-32768 |@@@@@@@@@@@ 9
-16384 |@@@@@@ 5
-8192 | 0
linuxulator32 npviewer.bin futex_sleep
value ------------- Distribution ------------- count
-1073741824 | 0
-536870912 |@@@@@@@@@@@ 4
-268435456 | 0
-134217728 |@@@@@@@@@@@@@@@@@ 6
-67108864 |@@@ 1
-33554432 |@@@ 1
-16777216 |@@@ 1
-8388608 | 0
-4194304 | 0
-2097152 | 0
-1048576 | 0
-524288 | 0
-262144 | 0
-131072 | 0
-65536 |@@@ 1
-32768 | 0
linuxulator32 npviewer.bin futex_wait
value ------------- Distribution ------------- count
-1073741824 | 0
-536870912 |@@@@@@@@@@@ 4
-268435456 | 0
-134217728 |@@@@@@@@@@@@@@@@@ 6
-67108864 |@@@ 1
-33554432 |@@@ 1
-16777216 |@@@ 1
-8388608 | 0
-4194304 | 0
-2097152 | 0
-1048576 | 0
-524288 | 0
-262144 | 0
-131072 | 0
-65536 |@@@ 1
-32768 | 0
linuxulator32 npviewer.bin futex_put
value ------------- Distribution ------------- count
-524288 | 0
-262144 |@ 1
-131072 |@@ 2
-65536 | 0
-32768 |@@@@@@@ 6
-16384 |@@@@@@@@@@@ 9
-8192 |@@@@@@@@@@@@@@@@@@@ 16
-4096 | 0
linuxulator32 npviewer.bin futex_get
value ------------- Distribution ------------- count
-65536 | 0
-32768 |@@@@@@@@@@@@@ 12
-16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 26
-8192 | 0
linuxulator32 npviewer.bin futex_get0
value ------------- Distribution ------------- count
-32768 | 0
-16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 30
-8192 |@@@@@@@@ 8
-4096 | 0
linuxulator32 npviewer.bin futex_atomic_op
value ------------- Distribution ------------- count
-32768 | 0
-16384 |@@@@@@@@ 1
-8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
-4096 | 0
linuxulator32 npviewer.bin futex_wake
value ------------- Distribution ------------- count
-16384 | 0
-8192 |@@@@@@@ 1
-4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5
-2048 | 0
Longest running (wallclock!) functions per provider (in ns):
linuxulator32 futex_wait -100195
linuxulator32 futex_sleep -91565
linuxulator32 linux_sys_futex -30010
linuxulator32 futex_get -21060
linuxulator32 futex_atomic_op -15885
linuxulator32 futex_get0 -12540
linuxulator32 futex_put -11825
linuxulator32 futex_wake -5610
13,22 real 0,09 user 0,13 sys
cheers.
alex
> >
> > 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?20120415184643.GA59617>