[Scummvm-devel] ScummVM PS2 & Trunk : compressed buns

sunmax at libero.it sunmax at libero.it
Sun Feb 7 09:06:59 CET 2010


Hi Max,

>> Ah, you are so modest to leave out
>>
>> c) We broke something in the vorbis code during the recent
>> refactoring ;)

Ehm, of course, the PS2 backend is technically perfect, the ur-port
from which (cough, cough) all other ScummVM ports were derived ;-)

Which is the latest svn revision before the refactoring?

>> Did you try to use the same data files on your desktop machine?
>> Do they work correctly there?

Yes. Here is what I did:

I recompiled the same tremor src code I'm using for PS2 on my Linux
workstation and linked my ScummVM SDL flavor to that. I'm using the
very same games data and saved games, since PS2 access them through
the network.

I noticed that "tremor" uses some 'fread' while the PS2 requires (if
you want to consistently access data on different media [USB, DVD, MC
and NET]) an overlay of abstraction which is ours ps2_fread, etc.

So I made those "C" extern in ScummVM and replaced the ones in tremor
with the ps2_* variants. And -TADA- ...it did not help :-(

So even with no stack and memaligned allocations and our safe files
handling, with hit this annoying issue with vorbis compressed bun on PS2.

I then enabled some output on my Linux workstation and PlayStation 2,
and now we see:

SDL backend

1. boundary=400 off=0
2. more=0
3a. _get_next_page -> more=0 boundary=400 off=0 ret=1024
1. boundary=400 off=0
2. more=3a
3b. _get_next_page -> more=3a boundary=400 off=0 ret=0
1. boundary=43a off=3a
2. more=0
3a. _get_next_page -> more=0 boundary=43a off=3a ret=1024
1. boundary=43a off=3a
2. more=0
3a. _get_next_page -> more=0 boundary=43a off=3a ret=1024
1. boundary=43a off=3a
2. more=0
3a. _get_next_page -> more=0 boundary=43a off=3a ret=1024
1. boundary=43a off=3a
2. more=e65   <--- good


PS2 backend

1. boundary=400 off=0
2. more=0
3a. _get_next_page -> more=0 boundary=400 off=0 ret=1024
1. boundary=400 off=0
2. more=3a
3b. _get_next_page -> more=3a boundary=400 off=0 ret=0
1. boundary=43a off=3a
2. more=0
3a. _get_next_page -> more=0 boundary=43a off=3a ret=1024
1. boundary=43a off=3a
2. more=0
3a. _get_next_page -> more=0 boundary=43a off=3a ret=1024
1. boundary=43a off=3a
2. more=0
3a. _get_next_page -> more=0 boundary=43a off=3a ret=1024
1. boundary=43a off=3a
2. more=ffffffc5  <--- not so good


As you can see _get_next_page in tremor on PS2 goes bananas at a
certain stage, and instead of returning a "more" of 0xe65 spits
an ungodly 0xffffffc5, which later triggers the bail out and the
assert.


It always happens in the same spot trying to access the first ogg
used in the bun : ASTERO~1.IMU_reg002.ogg

I have 3 suspects:

a) memory corruption

b) PS2 file implementation

c) thread issue


Whatever it is, it's just triggered by vorbis compressed bun, maybe
it's just a coincidence, but a big one because all scumm games are
stable (I left them on for hours, playing once in a while) with mp3
compression or with vanilla buns.

Is there anything special in the design of tremor that might be
causing this?

Why are we not encountering this issue in branch 1.0.x ?


For (a) we saw in the past that the code affected is not necessarily
the faulty one, but the victim...


For (b) I saw that Max did some clean-up, but maybe there is a bug
which was dormant in 1.0.x and we are just now triggering it


For (c) this issue happens in a separate thread

#4  0x0000000000165994 in Scumm::ImuseDigiSndMgr::getDataFromRegion (
    this=0x4f5690, soundDesc=0x4f5708, region=0, buf=0x4d07c8, offset=0, 
    size=8820) at ../../../engines/scumm/imuse_digi/dimuse_sndmgr.cpp:718
#5  0x000000000015ecb4 in Scumm::IMuseDigital::callback (this=0x4f52e0)
    at ../../../engines/scumm/imuse_digi/dimuse.cpp:303
#6  0x000000000015d72c in Scumm::IMuseDigital::timer_handler (refCon=0x4f52e0)
    at ../../../engines/scumm/imuse_digi/dimuse.cpp:44
#7  0x00000000002fb144 in DefaultTimerManager::handler (this=0x4a0f50)
    at ../../../backends/timer/default/default-timer.cpp:108
#8  0x000000000010ee88 in OSystem_PS2::timerThreadCallback (this=0x48f250)
    at ../../../backends/platform/ps2/systemps2.cpp:433
#9  0x000000000010d95c in systemTimerThread (system=0x48f250)  <---
    at ../../../backends/platform/ps2/systemps2.cpp:170


For (b) I'm adding here some more notes out of my latest debug session:

My first suspect were tremor "callbacks", which defaults to fread,
fseek, etc.

In "_get_data"

 long bytes=(vf->callbacks.read_func)(buffer,1,CHUNKSIZE,vf->datasource);

 that fallbacks on "fread" 

And in "_seek_helper"

 vf->callbacks.seek_func)(vf->datasource, offset, SEEK_SET)

 that fallbacks on "fseek"

The common 'fread' and 'fseek' in the normal ps2sdk C libs are not
multimedia (litterally: hd, dvd, net, mc) safe - so we have to use
our own wrappers.

Beside the standard C libs are not aware or our read-ahead caching 
system, so we actually read much more than they expect.

Then I realized that we use "ov_open_callbacks" and pass g_stream_wrap 
;-)

Now, why we are not triggering this in 1.0.0 stays the deepest mystery to me!

Assuming my interpretation is correct, Max, I saw we made some cleanup
in PS2 File handling. Do you know if anything we changed might trigger
this ?

btw: I noticed that we no longer redefine "open" as "ps2_fopen", 
etc. in  backends/fs/stdiostream.cpp

Should I assume we no longer allow direct "fread" in engines et alia?

Good!


Now comparing libmad to tremor:

"mad" uses 'read()' vs. 'fread()' which appears to be safe.


I saw there were no change between 1.0.x and trunk to BundleMgr.

Ditto for ScummFile. Whose ::open method I assume ends up to be
(going through createReadStreamForMember) a Ps2File::open on a
Ps2File, or else?

I'm just trying to understand how the bun is opened and how the
data is accessed to track the mismatch (if this is the issue).

Do we only open the file and pass the stream to the vorbis decoder
without reading any data, right?

If that's the case, simply changing the fread / fseek in tremor to
ps2_fread and ps2_fseek would seem to sort the issue out, but from
my first experiments it didn't work as expected...

Comparing 1.0.0 sound/vorbis.cpp with trunk sound/decoders/vorbis.cpp
I see that VorbisInputStream (AudioStream) turned into a VorbisStream
(SeekableAudioStream), so I wonder if we are hitting some shortcoming
in PS2 backend that might cause the new class ctr to fail.

The only difference I spot between 1.0.0 and trunk before the tremor
calls fails is that we have a Timestamp in the new class and then we
instantiate a _lenght(0, 1000); before the failing point, but then
looking at their implementation I don't really think they can harm ;-)


So here comes a list of the relevant file calls on DIG startup.

open host:games/dig/dig.la1 [4]
  _mode = 1
  _fileSize = 88673344

open host:games/dig/video/sq1.san [5] // intro video
  _mode = 1
  _fileSize = 11695382

close [5] - sync'd = 0 //  we skip intro, so it closes

 [some stuff is read from dig.la1 here ]

Ok, ready for the buns? ;-)

open host:games/dig/digmusic.bun [5]
  _mode = 1
  _fileSize = 64236304
open host:games/dig/digmusic.bun [6]
  _mode = 1
  _fileSize = 64236304

It actually gets opened twice!!!

(fd 5, fd 6)

read (6) : _filePos = 0
read (6) : _filePos = 4
read (6) : _filePos = 8
read (6) : _filePos = 64224048
read (6) : _filePos = 64224072
read (6) : _filePos = 64224076
...
read (6) : _filePos = 64236296
read (6) : _filePos = 64236300
close [6] - sync'd = 0

After closing 6, it starts reading from 5.

(we are now in ImuseDigiSndMgr::prepareSoundFromRMAP)

read (5) : _filePos = 12
read (5) : _filePos = 16
read (5) : _filePos = 20
read (5) : _filePos = 24
read (5) : _filePos = 28
read (5) : _filePos = 32
read (5) : _filePos = 36
read (5) : _filePos = 40
read (5) : _filePos = 44
read (5) : _filePos = 48
read (5) : _filePos = 52
read (5) : _filePos = 56
read (5) : _filePos = 60
read (5) : _filePos = 64
read (5) : _filePos = 68
read (5) : _filePos = 72
read (5) : _filePos = 76
read (5) : _filePos = 80
read (5) : _filePos = 84

fileName = ASTERO~1.IMU_reg000.ogg, tmp = 0x006AD020 

 ^--- that's just before we are going to call Audio::makeVorbisStream
      in ImuseDigiSndMgr::getDataFromRegion

>From now on, even if we use our scummvm callback wrapper, the ps2_*
file implementation is no longer called (since there are no more
"read" in the dbg output) - but if we are using regular fread, etc.
they are likely to fail since they are not aware of our read-ahead
caching policy.

On the other hand the ps2_* were not called in 1.0.0 either and 
everything works fine there, so this is really a wild guess...

The only tangible difference is that in trunk _filePos increment are
DW, while in 1.0.0 they were bytes, so we are reading more data each
time, which makes think faster and I do not think is causing this
issue.

Struck by desperation, I then inspected by hand the content of the 
cache, and the content is correct:

(gdb) print /x * (uint8[64] *) _cacheBuf

$59 = {0x4c, 0x42, 0x32, 0x33, 0x3, 0xd3, 0xfb, 0x30, 0x0, 0x0, 0x1, 0x7f, 
 0x52, 0x4d, 0x41, 0x50, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0, 0x0, 0x10, 0x0, 0x0, 
 0x56, 0x22, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, 0x0, 0x1, 0x0, 
 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x9b, 0xaa, 0xa0, 0x0, 0x9b, 0xaa, 
 0xa0, 0x0, 0xd7, 0xa1, 0x40, 0x1, 0x73, 0x4b, 0xe0}


It matches the hexdump of digmusic.bun :

00000000  4c 42 32 33 03 d3 fb 30  00 00 01 7f 52 4d 41 50  |LB23...0....RMAP|
00000010  00 00 00 02 00 00 00 10  00 00 56 22 00 00 00 02  |..........V"....|
00000020  00 00 00 03 00 00 00 01  00 00 00 00 00 00 00 00  |................|
00000030  00 9b aa a0 00 9b aa a0  00 d7 a1 40 01 73 4b e0  |........... at .sK.|
00000040  00 03 42 20 01 73 4b e0  00 9b aa a0 00 00 00 00  |..B .sK.........|
00000050  00 00 05 dc 4f 67 67 53  00 02 00 00 00 00 00 00  |....OggS........|
00000060  00 00 01 1b 00 00 00 00  00 00 89 df b3 fb 01 1e  |................|
00000070  01 76 6f 72 62 69 73 00  00 00 00 02 22 56 00 00  |.vorbis....."V..|
00000080  00 00 00 00 15 2e 01 00  00 00 00 00 a9 01 4f 67  |..............Og|
00000090  67 53 00 00 00 00 00 00  00 00 00 00 01 1b 00 00  |gS..............|


Even the Oggs signature :

(gdb) print /x * (_cacheBuf+0x8e)
$62 = 0x4f
(gdb) print /x * (_cacheBuf+0x8f)
$63 = 0x67
(gdb) print /x * (_cacheBuf+0x90)
$64 = 0x67
(gdb) print /x * (_cacheBuf+0x91)
$65 = 0x53

All suggestions welcome.

Thanks!
 -max





More information about the Scummvm-devel mailing list