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 <arun...@freebsd.org>
> > > > wrote:
> > > >
> > > > > On Sun Apr 15 12, Alexander Leidinger wrote:
> > > > > > On Sun, 15 Apr 2012 11:51:12 +0000 Alexander Best
> > > > > > <arun...@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
_______________________________________________
freebsd-emulation@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-emulation
To unsubscribe, send any mail to "freebsd-emulation-unsubscr...@freebsd.org"
