Login at Kodi Home

jmarshall · 2005-05-10, 23:16

you should be looking for all output with paplayer written in it.

loglevel must be 0. other than that, it doesn't matter.

at the very least you should get information stating that the output buffer is empty at the start of the file.

the key is that we need to isolate where the fault is. we use a lot of output buffers (capable of withstanding at least a second of no audio fed to them at all) so if they're dropping it means a long length of inactivity either from the decoders or from the file reading stuff. it needs to be isolated, and unfortunately that isn't easy (as when the glitch occurs, the buffers have likely caught up).

that's why i need you to try with the various options i gave above and with files both locally and off the network.

cheers,
jonathan

axavier · 2005-05-10, 23:35

(jmarshall @ may 10 2005,16:16 Wrote:you should be looking for all output with paplayer written in it.

loglevel must be 0. other than that, it doesn't matter.

at the very least you should get information stating that the output buffer is empty at the start of the file.

the key is that we need to isolate where the fault is. we use a lot of output buffers (capable of withstanding at least a second of no audio fed to them at all) so if they're dropping it means a long length of inactivity either from the decoders or from the file reading stuff. it needs to be isolated, and unfortunately that isn't easy (as when the glitch occurs, the buffers have likely caught up).

that's why i need you to try with the various options i gave above and with files both locally and off the network.

cheers,
jonathan

yes captain!!

also jonathan, could it be an issue with vbr enconded mp3's. most of myine are encoded using lame extreme setting.

i'll get you a log tonight for this issue....

Nuka1195 · 2005-05-10, 23:39

jonathan,

do you want any info for streaming from itunes yet?

may 6th build is flawless, but with the newer builds i'm having trouble.

edit: sp?

jmarshall · 2005-05-10, 23:48

if it's using paplayer, then sure. in particular comparisons to other protocols (smb, localdisk etc.) would be handy.

btw: can you confirm that replacing with the may 6th build reverts to perfect playback? if so, then we may be able to find the reason by analysing the code changes.

Nuka1195 · 2005-05-11, 00:01

yes, i can confirm reverting to the may 6th build works perfectly, been streaming for a couple hours.

this is the last change: - 06-05-2005 added: sf patch [1196174] make trailing fill characters be part of tag in music template - thanks to spiff

i've tried may 8th and 9th and reverted each time and not had any issues.

i'll download a new cvs and get some logs.

edit: for the may 6th build, i should note that the seeking with the right thumbstick advances songs. i forgot about that, but the playback is perfect.

axavier · 2005-05-11, 01:20

this is the log of 2 songs playin from the xbox hard drive jonathan
there were encoded with lame alt preset extreme (vbr)

Quote:10-05-2005 18:10:32 info pap player: loaded decoder at 00a88010
10-05-2005 18:10:32 info pap player: playing f:\music\the expedition\kamelot - 01 - until kingdom come.mp3
10-05-2005 18:10:32 info pap player: channels 2 : sample rate 44100
10-05-2005 18:10:32 info pap player: chunklen 4120
10-05-2005 18:10:32 notice start led control
10-05-2005 18:10:32 notice dim lcd on playback
10-05-2005 18:13:32 info activating window id: 12900
10-05-2005 18:15:54 notice start led control
10-05-2005 18:15:54 notice dim lcd on playback
10-05-2005 18:15:54 info pap player: loaded decoder at 00a81010
10-05-2005 18:15:54 info pap player: playing f:\music\the expedition\kamelot - 02 - expedition.mp3
10-05-2005 18:15:55 info pap player: channels 2 : sample rate 44100
10-05-2005 18:15:55 info pap player: chunklen 4120

as you can see there is no mention at all of buffers in the logs. no hiccups in this case.

axavier · 2005-05-11, 01:38

here is the log doign streaming via wireless g network (same 2 songs)

Quote:10-05-2005 18:19:27 info pap player: loaded decoder at 00aec010
10-05-2005 18:19:27 info pap player: playing smb://workgroup;username:[email protected]/music/1/kamelot/the expedition/kamelot - 01 - until kingdom come.mp3
10-05-2005 18:19:27 info pap player: channels 2 : sample rate 44100
10-05-2005 18:19:27 info pap player: chunklen 4120
10-05-2005 18:19:28 notice start led control
10-05-2005 18:19:28 notice dim lcd on playback
10-05-2005 18:22:28 info activating window id: 12900
10-05-2005 18:24:54 notice start led control
10-05-2005 18:24:54 notice dim lcd on playback
10-05-2005 18:24:54 info pap player: loaded decoder at 00abca30
10-05-2005 18:24:54 info pap player: playing smb://workgroup;username:[email protected]/music/1/kamelot/the expedition/kamelot - 02 - expedition.mp3
10-05-2005 18:24:54 info pap player: channels 2 : sample rate 44100
10-05-2005 18:24:54 info pap player: chunklen 4120
10-05-2005 18:24:55 notice start led control
10-05-2005 18:24:55 notice dim lcd on playback

both sogns experienced hiccups. again there is no mention in t he logs about buffer issues. the location of the hiccups is not consistent (it will not happen in then same place in the same song).

i have checked my wireless logs and there is no collisions also the link between the wireless game adapter and the router is at 72%

jonathan, i do not have the may 6th build but if you guys can put some type of buffer status logging that we can check maybe it can help us.

Nuka1195 · 2005-05-11, 02:50

i started at log level 1 then switched it to 0, then i switched it to 7. i did this because i remembered with log level set to 0, i could at least get some playback. with log level to 7 it locked everytime i selected a song.

not sure if this will help, i can upload the full logs if you want.

Quote:i get two logs, since my xbox boots to e/dashboard/default.xbe. here is that log at loglevel 0.
10-05-2005 20:17:47 notice -----------------------------------------------------------------------
10-05-2005 20:17:47 notice starting...
10-05-2005 20:17:47 notice q is mapped to:harddisk0\partition1\dashboard
10-05-2005 20:17:47 notice load settings...
10-05-2005 20:17:47 notice loading t:\settings.xml
10-05-2005 20:17:47 notice getting hardware information now...
10-05-2005 20:17:47 notice checking resolution 10
10-05-2005 20:17:47 notice av pack: hdtv
10-05-2005 20:17:47 notice av flags:
10-05-2005 20:17:47 notice setting autoresolution mode 4
10-05-2005 20:17:47 notice loading q:\xboxmediacenter.xml

the other log is in e/xbmc/

using itunes 4.7.1 on a pc running xp pro (only mp3's) <loglevel>1</loglevel> 2-channel pcm passthrough unchecked

fresh build (kept original settings and database): selected a song, it highlighted but did not play.
10-05-2005 19:05:52 notice running the application...
10-05-2005 19:06:02 info activating window id: 10501
10-05-2005 19:06:02 info attempting to default to:
10-05-2005 19:06:05 info creating thumb from: daap://192.168.1.50/nukas music/folder.jpg as: e:\data\albums\thumbs\temp\21bbc784.tbn
10-05-2005 19:06:05 error picture::docreatethumbnail: unable to cache file: daap://192.168.1.50/nukas music/folder.jpg
..
10-05-2005 19:06:08 info mp3codec: loaded decoder at 00b16e20
10-05-2005 19:06:08 error tag loader mp3: exception in file daap://192.168.1.50/1612.mp3
10-05-2005 19:06:08 error exception in capplication::framemove()

selected other songs:
10-05-2005 19:10:36 info mp3codec: loaded decoder at 00b16e20
10-05-2005 19:10:36 error tag loader mp3: exception in file daap://192.168.1.50/1612.mp3
10-05-2005 19:10:36 error exception in capplication::framemove()
10-05-2005 19:10:40 info mp3codec: loaded decoder at 00b16e20
10-05-2005 19:10:40 error tag loader mp3: exception in file daap://192.168.1.50/1613.mp3
10-05-2005 19:10:40 error exception in capplication::framemove()
10-05-2005 19:11:18 info mp3codec: loaded decoder at 00b16e20
10-05-2005 19:11:18 error tag loader mp3: exception in file daap://192.168.1.50/1755.mp3
10-05-2005 19:11:18 error exception in capplication::framemove()

rebooted (4 finger salute), in old log these additional entries.:
10-05-2005 19:11:18 error exception in capplication::framemove()
10-05-2005 19:13:54 info activating window id: 10000
10-05-2005 19:14:00 info activating window id: 10020

selected song, it played with some glitches (skips), the song stopped 3 seconds early and stayed there. the xbox did not lock:
10-05-2005 19:14:16 notice running the application...
10-05-2005 19:14:25 info activating window id: 10501
10-05-2005 19:14:25 info attempting to default to:
10-05-2005 19:14:29 info creating thumb from: daap://192.168.1.50/nukas music/folder.jpg as: e:\data\albums\thumbs\temp\21bbc784.tbn
10-05-2005 19:14:29 error picture::docreatethumbnail: unable to cache file: daap://192.168.1.50/nukas music/folder.jpg
..
10-05-2005 19:14:33 info mp3codec: loaded decoder at 00b16ca0
10-05-2005 19:14:33 info pap player: new audiodevice created. chunklen 4120
10-05-2005 19:14:33 info pap player: playing daap://192.168.1.50/1612.mp3
10-05-2005 19:14:33 notice start led control
10-05-2005 19:14:33 notice dim lcd on playback

selected another song. xbox became unreponsive, but could still ftp in. had to power off.:
no new entry's in log.

rebooted <loglevel>0</loglevel> restarted itunes:

selected song, it played, some glitching, again it quit 3 seconds early.
10-05-2005 19:28:49 info activating window id: 10501
10-05-2005 19:28:49 info attempting to default to:
10-05-2005 19:28:49 debug initializing fs_seg..
10-05-2005 19:28:49 debug fs segment @ 0x8e4910
10-05-2005 19:28:50 info creating thumb from: daap://192.168.1.50/nukas music/folder.jpg as: e:\data\albums\thumbs\temp\21bbc784.tbn
10-05-2005 19:28:50 error picture::docreatethumbnail: unable to cache file: daap://192.168.1.50/nukas music/folder.jpg
..
10-05-2005 19:28:54 info mp3codec: loaded decoder at 00b31590
10-05-2005 19:28:54 info pap player: new audiodevice created. chunklen 4120
10-05-2005 19:28:54 info pap player: playing daap://192.168.1.50/1612.mp3
10-05-2005 19:28:54 debug paplayer: thread started
10-05-2005 19:28:54 debug playback has started
10-05-2005 19:28:54 notice start led control
10-05-2005 19:28:54 notice dim lcd on playback
10-05-2005 19:28:54 debug paplayer::output buffer size only 0 bytes. pcm buffer size 179712

selected another song. xbox became unreponsive, but could still ftp in. had to power off.:
no new entry's in log.

rebooted <loglevel>0</loglevel> restarted itunes: deleted 0face008 in udata & tdata, renamed albums and thumbs so xbmc created new. kept default settings.

selected song, played with glitches, quit 2 seconds early, hit stop on remote and the xbox became unresponsive. powered off.
10-05-2005 19:40:22 debug freevisualisation() started
10-05-2005 19:40:22 debug freevisualisation() done
10-05-2005 19:40:22 info activating window id: 10501
10-05-2005 19:40:22 info attempting to default to:
10-05-2005 19:40:22 debug initializing fs_seg..
10-05-2005 19:40:22 debug fs segment @ 0x8ef010
10-05-2005 19:40:22 info creating version table
10-05-2005 19:40:23 info create artist table
10-05-2005 19:40:23 info create album table
10-05-2005 19:40:23 info create genre table
10-05-2005 19:40:23 info create path table
10-05-2005 19:40:23 info create song table
10-05-2005 19:40:23 info create albuminfo table
10-05-2005 19:40:23 info create albuminfosong table
10-05-2005 19:40:24 info create thumb table
10-05-2005 19:40:24 info create exartistsong table
10-05-2005 19:40:24 info create extragenresong table
10-05-2005 19:40:24 info create exartistalbum table
10-05-2005 19:40:24 info create exgenrealbum table
10-05-2005 19:40:24 info create exartistsong index
10-05-2005 19:40:25 info create exgenresong index
10-05-2005 19:40:25 info create exartistalbum index
10-05-2005 19:40:25 info create exgenrealbum index
10-05-2005 19:40:25 info create album index
10-05-2005 19:40:26 info create genre index
10-05-2005 19:40:26 info create artist index
10-05-2005 19:40:26 info create path index
10-05-2005 19:40:26 info create song index
10-05-2005 19:40:26 info create thumb index
10-05-2005 19:40:26 info create albuminfo trigger
10-05-2005 19:40:28 info creating thumb from: daap://192.168.1.50/nukas music/folder.jpg as: e:\data\albums\thumbs\temp\21bbc784.tbn
10-05-2005 19:40:28 error picture::docreatethumbnail: unable to cache file: daap://192.168.1.50/nukas music/folder.jpg
..
10-05-2005 19:40:31 debug paplayer: starting next track whilst already playing - killing our output buffers
10-05-2005 19:40:31 info mp3codec: loaded decoder at 00a3f910
10-05-2005 19:40:31 info pap player: new audiodevice created. chunklen 4120
10-05-2005 19:40:31 info pap player: playing daap://192.168.1.50/1612.mp3
10-05-2005 19:40:31 debug paplayer: thread started
10-05-2005 19:40:31 debug playback has started
10-05-2005 19:40:31 notice start led control
10-05-2005 19:40:31 notice dim lcd on playback
10-05-2005 19:40:31 debug paplayer::output buffer size only 0 bytes. pcm buffer size 179712

tried again, with different song. it quit 2 seconds early, no new entries in log. just rebooted. (4 finger salute)

copied two mp3's to xbox, played them. switched to the second song 2 seconds early. i didn't notice any glitches. the last song quit 2 seconds early. selected the second song again, played fine, quit 2 seconds early.

10-05-2005 19:57:11 info activating window id: 10501
10-05-2005 19:57:11 info attempting to default to:
10-05-2005 19:57:11 debug initializing fs_seg..
10-05-2005 19:57:11 debug fs segment @ 0x8e55d0
10-05-2005 19:57:16 debug paplayer: starting next track whilst already playing - killing our output buffers
10-05-2005 19:57:16 info mp3codec: loaded decoder at 00a20070
10-05-2005 19:57:17 info pap player: new audiodevice created. chunklen 4120
10-05-2005 19:57:17 info pap player: playing f:\music\depeche mode - personal jesus.mp3
10-05-2005 19:57:17 debug paplayer: thread started
10-05-2005 19:57:17 debug playback has started
10-05-2005 19:57:17 notice start led control
10-05-2005 19:57:17 notice dim lcd on playback
10-05-2005 19:57:17 debug paplayer::output buffer size only 0 bytes. pcm buffer size 179712
10-05-2005 20:01:01 debug playback has finished
10-05-2005 20:01:01 notice start led control
10-05-2005 20:01:01 notice dim lcd on playback
10-05-2005 20:01:01 info mp3codec: loaded decoder at 009c4240
10-05-2005 20:01:01 info pap player: playing f:\music\black eyed peas - let's get it started.mp3
10-05-2005 20:01:01 debug paplayer: thread started
10-05-2005 20:01:01 debug playback has started
10-05-2005 20:01:01 notice start led control
10-05-2005 20:01:01 notice dim lcd on playback
10-05-2005 20:04:38 debug playback has finished
10-05-2005 20:04:38 notice start led control
10-05-2005 20:04:38 notice dim lcd on playback
10-05-2005 20:04:50 debug paplayer: starting next track whilst already playing - killing our output buffers
10-05-2005 20:04:50 info mp3codec: loaded decoder at 009c4240
10-05-2005 20:04:51 info pap player: new audiodevice created. chunklen 4120
10-05-2005 20:04:51 info pap player: playing f:\music\black eyed peas - let's get it started.mp3
10-05-2005 20:04:51 debug paplayer: thread started
10-05-2005 20:04:51 debug playback has started
10-05-2005 20:04:51 notice start led control
10-05-2005 20:04:51 notice dim lcd on playback
10-05-2005 20:04:51 debug paplayer::output buffer size only 0 bytes. pcm buffer size 179712

rebooted <loglevel>7</loglevel> restarted itunes. selected song from itunes, xbox locked, eject button rebooted.

tried again same result. no logs though.

after reboot, played mp3's on xbox. some glitches on first song, mainly at the beginning. no logs.

axavier · 2005-05-11, 03:02

the thing that gets me is that even at level 0 i do not get any information on the buffers....

Nuka1195 · 2005-05-11, 03:08

reverted to may 6th build, kept default settings and new database created with the may 10th build. played a few songs, they played flawlessly.

petergillett · 2005-05-11, 11:27

snippet of log during mp3 playback from smb over 54g. obviously there was a 5 second pause. meanwhile remote desktop was continuously running without pause to same machine. data seems to go in 60k ish chunks (difficult to see with rd overhead) every 2.5 seconds other than during the pause. no pattern to pause time - has played for a whole minute, then next track goes 1 second. (9th may build)

Quote:11-05-2005 10:10:42 debug paplayer: starting next track whilst already playing - killing our output buffers
11-05-2005 10:10:42 info mp3codec: loaded decoder at 00aa8010
11-05-2005 10:10:49 info pap player: new audiodevice created. chunklen 4120
11-05-2005 10:10:49 info pap player: playing smb://pg-server/music/2pac/greatest hits disc 1/01 keep ya head up.mp3
11-05-2005 10:10:49 debug paplayer: thread started
11-05-2005 10:10:49 debug playback has started
11-05-2005 10:10:49 notice start led control
11-05-2005 10:10:49 notice dim lcd on playback
11-05-2005 10:10:49 debug paplayer::output buffer size only 0 bytes. pcm buffer size 179712
11-05-2005 10:10:49 debug paplayer::output buffer size only 15648 bytes. pcm buffer size 166748
11-05-2005 10:10:49 debug paplayer::output buffer size only 15968 bytes. pcm buffer size 165084
11-05-2005 10:10:49 debug paplayer::output buffer size only 15456 bytes. pcm buffer size 165928
....
11-05-2005 10:12:07 debug paplayer::output buffer size only 15648 bytes. pcm buffer size 314152
11-05-2005 10:12:07 debug paplayer::output buffer size only 15456 bytes. pcm buffer size 318760
11-05-2005 10:12:07 debug paplayer::output buffer size only 12800 bytes. pcm buffer size 318760
11-05-2005 10:12:13 debug paplayer::output buffer size only 0 bytes. pcm buffer size 319604
11-05-2005 10:12:13 debug paplayer::output buffer size only 15968 bytes. pcm buffer size 306652
11-05-2005 10:12:13 debug paplayer::output buffer size only 15744 bytes. pcm buffer size 311260
11-05-2005 10:12:13 debug paplayer::output buffer size only 15520 bytes. pcm buffer size 315868

snipped as the line is repeated about 30 times per second. shout if you want the whole log.

edit - been paused for 3 minutes now. nothing in the log at all from the moment of the pause. server running smb is up and running rd fine. last entry was

Quote:11-05-2005 10:22:24 debug paplayer::output buffer size only 13440 bytes. pcm buffer size 247616

edit 2 - won't reboot. switched on, 2 tracks, ftp to get log, sat on a "pause", tried to reboot, hung. not a one-off, was doing this last night when testing this build. old log says

Quote:11-05-2005 10:28:19 info activating window id: 10000
11-05-2005 10:28:20 debug loadvisualisation() started
11-05-2005 10:28:20 debug oninitialize() started
11-05-2005 10:28:20 debug oninitialize() done
11-05-2005 10:28:20 debug loadvisualisation() done
11-05-2005 10:28:34 notice stop all
11-05-2005 10:28:34 notice stop time server
11-05-2005 10:28:34 notice stop dvd detect media
11-05-2005 10:28:34 notice stop fancontroller
11-05-2005 10:28:34 notice stop mplayer

scoMal · 2005-05-11, 12:26

(vnm @ may 03 2005,09:44 Wrote:i've got another problem too with paplayer. when it's about the play the next song, the playback hangs. i'll try to describe it in details:

1. song 1 is playing
2. song 1 is ending and it's time to begin playing song 2
3. song 1 finishes as supposed to, and xbmc seems to start playing song 2 but there's no sound
(the display in the bottom left corner now correctly displays song 2 and its cover, and the play symbol is showing, but the time constantly shows 0.00.)

unfortainly i've not had the time to test wether this happens randomly or allways on spesific files. i have some wma's is my collection, and it might be them cousing the problems.

it would be nice is someone else did this, as i probably won't have time in over a week (i'll try me best though)

for the record, i have all my music on a smb share.

has the problem in the quoted post been fixed - or does it require us to manually fix our mp3 files?

petergillett · 2005-05-11, 14:02

not the player but back to a comment about file copying from the smb share over 54g that i made earlier. done some more tests.

copy to xbox, goes in "blips". start copy to laptop, throughput from server goes to max. cancel copy to laptop, back to "blips".

351mb file. could copy 3-4 times to laptop in time copying to xbox.

xbox wired to hub, hub to access point. laptop and server on wireless.

as said before copy from laptop smb share to xbox - fine Huh

??

something must be different on the server (xp pro 2, not true server), though don't know what - it's a brand new fresh install that i did personally, not a bought butchered version with a million things installed! nothing on it, not even a virus scanner getting in the way. it's got a 20db snr link and barely drops off 54m.

petergillett · 2005-05-11, 14:13

nothing to do with firewalls of the smb server. have disabled and makes no difference.

axavier · 2005-05-11, 14:22

(petergillett @ may 11 2005,04:27 Wrote:snippet of log during mp3 playback from smb over 54g. obviously there was a 5 second pause. meanwhile remote desktop was continuously running without pause to same machine. data seems to go in 60k ish chunks (difficult to see with rd overhead) every 2.5 seconds other than during the pause. no pattern to pause time - has played for a whole minute, then next track goes 1 second. (9th may build)

Quote:11-05-2005 10:10:42 debug paplayer: starting next track whilst already playing - killing our output buffers
11-05-2005 10:10:42 info mp3codec: loaded decoder at 00aa8010
11-05-2005 10:10:49 info pap player: new audiodevice created. chunklen 4120
11-05-2005 10:10:49 info pap player: playing smb://pg-server/music/2pac/greatest hits disc 1/01 keep ya head up.mp3
11-05-2005 10:10:49 debug paplayer: thread started
11-05-2005 10:10:49 debug playback has started
11-05-2005 10:10:49 notice start led control
11-05-2005 10:10:49 notice dim lcd on playback
11-05-2005 10:10:49 debug paplayer::output buffer size only 0 bytes. pcm buffer size 179712
11-05-2005 10:10:49 debug paplayer::output buffer size only 15648 bytes. pcm buffer size 166748
11-05-2005 10:10:49 debug paplayer::output buffer size only 15968 bytes. pcm buffer size 165084
11-05-2005 10:10:49 debug paplayer::output buffer size only 15456 bytes. pcm buffer size 165928
....
11-05-2005 10:12:07 debug paplayer::output buffer size only 15648 bytes. pcm buffer size 314152
11-05-2005 10:12:07 debug paplayer::output buffer size only 15456 bytes. pcm buffer size 318760
11-05-2005 10:12:07 debug paplayer::output buffer size only 12800 bytes. pcm buffer size 318760
11-05-2005 10:12:13 debug paplayer::output buffer size only 0 bytes. pcm buffer size 319604
11-05-2005 10:12:13 debug paplayer::output buffer size only 15968 bytes. pcm buffer size 306652
11-05-2005 10:12:13 debug paplayer::output buffer size only 15744 bytes. pcm buffer size 311260
11-05-2005 10:12:13 debug paplayer::output buffer size only 15520 bytes. pcm buffer size 315868
snipped as the line is repeated about 30 times per second. shout if you want the whole log.

edit - been paused for 3 minutes now. nothing in the log at all from the moment of the pause. server running smb is up and running rd fine. last entry was

Quote:11-05-2005 10:22:24 debug paplayer::output buffer size only 13440 bytes. pcm buffer size 247616

edit 2 - won't reboot. switched on, 2 tracks, ftp to get log, sat on a "pause", tried to reboot, hung. not a one-off, was doing this last night when testing this build. old log says

Quote:11-05-2005 10:28:19 info activating window id: 10000
11-05-2005 10:28:20 debug loadvisualisation() started
11-05-2005 10:28:20 debug oninitialize() started
11-05-2005 10:28:20 debug oninitialize() done
11-05-2005 10:28:20 debug loadvisualisation() done
11-05-2005 10:28:34 notice stop all
11-05-2005 10:28:34 notice stop time server
11-05-2005 10:28:34 notice stop dvd detect media
11-05-2005 10:28:34 notice stop fancontroller
11-05-2005 10:28:34 notice stop mplayer

peter are you using pcm passthrough in the sound options? also, what is your debug level. i have mine set up at 0 and i do not get any buffer information in the logs. i'm not using pcm output to 2 speakers option though, could that be the difference?