Amarok 1.4.5 Solaris 10 x86
Edd Barrett
vext01 at gmail.com
Mon Mar 5 18:17:00 UTC 2007
Hi Guys,
Ok, so im still working on tracking this down. Without much luck :P
Heres what I have researched, hopefully it might spark some ideas,
because I'm running out.
I don't think its the thread model as suggested by Jeff. As far as I
know OpenBSD does not even have kernel threads (I seem to remember
reading?) , but amarok is able to run at a decent speed. Ofcourse I
could be wrong.
First of all I trussed amarokapp:
---- START TRUSS
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDEB0) = 0
/8: writev(19, 0xCCDDDF30, 2) = 4096
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDE74) = 0
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDEB0) = 0
/8: writev(19, 0xCCDDDF30, 2) = 4096
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDE74) = 0
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDEB0) = 0
/8: writev(19, 0xCCDDDF30, 2) = 2048
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDE74) = 0
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDEB0) = 0
/9: lwp_park(0xCCCDDE30, 0) = 0
/1: lwp_park(0x00000000, 0) = 0
/8: writev(19, 0xCCDDDF30, 2) = 1024
/8: ioctl(19, AUDIO_GETINFO, 0xCCDDDE74) = 0
/1: lwp_park(0x00000000, 0) = 0
/1: ioctl(19, AUDIO_SETINFO, 0x08046C60) = 0
/1: write(19, " 'FD0704B5FF r05B902B205".., 432) = 432
[ PAUSE BUTTON ON AMAROK IS PRESSED NEAR HERE ]
/8: lwp_unpark(1) = 0
/15: lwp_park(0x00000000, 0) (sleeping...)
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
[ SNIP ...etc for a long time]
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
/8: nanosleep(0xCCDDDF3C, 0xCCDDDF34) = 0
[ USER INTERFACE STARTS RESPONDING ABOUT HERE]
/1: close(19) = 0
/1: ioctl(6, FIONREAD, 0x0804690C) = 0
/1: write(7, "\0", 1) = 1
/1: write(3, "12\007\0 $\0\006ED01\0\0".., 804) = 804
/1: read(3, "06\0 WE4 wB6F7 ! ?\0\0\0".., 32) = 32
/1: read(3, "06\0 WE497B6F7 ! ?\0\0\0".., 32) = 32
/1: read(3, "06\0 WE4B7B6F7 ! ?\0\0\0".., 32) = 32
/1: read(3, "06\0 WE4D7B6F7 ! ?\0\0\0".., 32) = 32
/1: read(3, "06\0 WE4EFB6F7 ! ?\0\0\0".., 32) = 32
---- END TRUSS
As you can see something is nano-sleeping a whole lot. Is this a
busy-wait type affair???
My next trail of thought was that some kind of IO was waiting.
Unfortunately IO is done on behalf of processes by a process called
"sched" in solaris , which makes dtrace a whole bunch less useful.
Also lots of IO is accessing a file called "<none>", which is when a
file does not really apply. Such dtrace output is useless and I have
filtered it out.
Here is the dtrace source code that I used:
--- BEGIN D SOURCE
#!/usr/sbin/dtrace -s
#pragma D option quiet
BEGIN
{
printf("%10s %58s %2s %7s\n", "DEVICE", "FILE", "RW", "MS");
}
io:::start
/args[2]->fi_pathname != "<none>"/
{
printf("START %s\n", args[2]->fi_pathname);
start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
}
io:::done
/start[args[0]->b_edev, args[0]->b_blkno] && args[2]->fi_pathname != "<none>"/
{
this->elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
printf("%10s %58s %2s %3d.%03d - %s\n", args[1]->dev_statname,
args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W",
this->elapsed / 10000000, (this->elapsed / 1000) % 1000, execname);
start[args[0]->b_edev, args[0]->b_blkno] = 0;
}
----END D SOURCE
And heres the output:
---- BEGIN D OUTPUT
bash-3.00# ./amarok.d
DEVICE FILE RW MS
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.206 - sched
START /export/home/edd/.kde/share/apps/amarok/covershadow-cache/shadow_albumcover49x49.png
cmdk0 /export/home/edd/.kde/share/apps/amarok/covershadow-cache/shadow_albumcover49x49.png
W 0.215 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/100 at 419f3dc36d31aa9715d163adf07c378a@shadow
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/100 at 419f3dc36d31aa9715d163adf07c378a@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/100 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.276 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/100 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.273 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.275 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.291 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.377 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.284 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at 419f3dc36d31aa9715d163adf07c378a@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.211 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at 6f0ef3ee6dd5477a6cd27a2c94b505b4@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at 6f0ef3ee6dd5477a6cd27a2c94b505b4@shadow
W 0.216 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at a217f7278774d01d242e43bd91c7111f@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at a217f7278774d01d242e43bd91c7111f@shadow
W 0.232 - sched
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.262 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.272 - sched
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.397 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.524 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.654 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.631 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.423 - sched
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
START /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.245 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.264 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.426 - sched
cmdk0 /export/home/edd/.kde/share/apps/amarok/contextbrowser.html
W 0.572 - sched
[ PAUSE IS PRESSES]
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at a60a28e2ecf1ef75d9468ca5f728fabe@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at a60a28e2ecf1ef75d9468ca5f728fabe@shadow
W 0.230 - sched
[ INTERFACE STARTS RESPONDING]
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at c14a92447f2a6ba94a937a7d8ffde13c@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/50 at c14a92447f2a6ba94a937a7d8ffde13c@shadow
W 0.218 - sched
START /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
cmdk0 /export/home/edd/.kde/share/apps/amarok/albumcovers/cache/150 at 419f3dc36d31aa9715d163adf07c378a@shadow
W 0.218 - sched
^C
---- BEGIN D OUTPUT
So there is one IO request to a file (album cover) , suring this time
and it only takes 0.230 milliseconds. Either the problem is not IO
based, or it was a "<none>" file type.
Ho hum. Does anyone have an ideas?
--
Best Regards
Edd
More information about the Amarok
mailing list