39:スチーム・ハーツ/停まる

最終状態:修正済
report#39.1
投稿者:na6ko
時刻:2018-02-28 03:32:41
状態:新規
頻度:必ず起きる
再現方法:
その1. ゲームを開始する
その2. ゲームを開始せずにデモのビジュアルシーンを停まる
停まります.
report#39.2
投稿者:na6ko
時刻:2018-02-28 03:40:17
状態:受付済
頻度:必ず起きる
00] 00 00 00 00 00 00
disc #004D
DE.00]x01
DE.01]x01
DE.02]x02
08> 001097 02->6280
08> 001099 02->6280
08> 00109B 03->6280
08> 0010E5 0C->6280
08> 0010F1 03->6280
08> 0010F4 0E->6280
08> 001102 04->6280
08> 001106 04->6280
08> 00110A 09->6280
08> 001113 06->6280
08> 001119 08->6280
08> 001121 06->6280
08> 001127 02->6280
D8> track05
D9> track06 play
audio play
D8> track06
drive stop
D9> track07 play
audio play
drive stop
08> 0018BB 0C.6280
*0xff*
08> 00193F 02->6280
08> 001941 01->6280
08> 001945 04->6280
08> 001949 03->6280
08> 00194D 04->6280
08> 001951 03->6280
08> 001955 03->6280
08> 001959 03->6280
08> 00195D 04->6280
08> 001961 02->6280
08> 001965 04->6280
08> 001969 01->6280
08> 00196D 04->6280
08> 001971 20->6280
08> 001C21 08->6280
08> 001C29 0D->6280
08> 001D4F 04->6280
08> 001C05 04->6280
08> 001BB5 04->6280
08> 001BB9 04->6280
08> 001D2B 04->6280
08> 001D53 04->6280
*0xff*
08> 001D8B 20->ADPCM RAM 02
report#39.3
投稿者:na6ko
時刻:2018-02-28 03:46:52
状態:受付済
頻度:必ず起きる
ゲームを開始してキャラ選択したあとの抜粋.
08> 0018BB 0C.6280
*0xff*
08> 00193F 02->6280
08> 001941 01->6280
08> 001945 04->6280
08> 001949 03->6280
08> 00194D 04->6280
08> 001951 03->6280
08> 001955 03->6280
08> 001959 03->6280
08> 00195D 04->6280
08> 001961 02->6280
08> 001965 04->6280
08> 001969 01->6280
08> 00196D 04->6280
08> 001971 20->6280
08> 001C21 08->6280
08> 001C29 0D->6280
08> 001D4F 04->6280
08> 001C05 04->6280
08> 001BB5 04->6280
08> 001BB9 04->6280
08> 001D2B 04->6280
08> 001D53 04->6280
*0xff*
08> 001D8B 20->ADPCM RAM 02

*0xff* は scsi_command_req() で下記の条件に発生し、通常のソフトで発生するをはじめて確認した.
	if(command_count == 0 && data == 0xff){
		tx_puts("*0xff*");
		sequence_init(s);
		return;
	}
report#39.4
投稿者:na6ko
時刻:2018-03-29 00:11:25
状態:受付済
頻度:必ず起きる
ADPCM RAM への読み込みに停まるのではなくて、それ以後の何かの同期で停まっていることを確認. CDDA 再生関連だと思われる.
report#39.5
投稿者:na6ko
時刻:2018-03-29 00:37:47
状態:受付済
頻度:必ず起きる
前述の CDDA 再生は間違い.
CPUがADPCM再生完了の同期あたりで停まっている. おそらくADPCMの再生をしたところで再生できずに停まっている様子.
report#39.6
投稿者:na6ko
時刻:2018-03-29 00:45:47
状態:受付済
頻度:必ず起きる
ADPCM制御自前コードを発見...
4859: stx  $1808
485C: sty  $1809
485F: lda  #$08
4861: tsb  $180D
4864: lda  $180A
4867: ldx  #$04
4869: dex
486A: bne  $4869
486C: lda  #$08
486E: trb  $180D
4871: rts
4872: stx  $1808
4875: sty  $1809
4878: lda  #$10
487A: tsb  $180D
487D: trb  $180D
4880: rts
4881: sta  $180E
4884: rts
4885: lda  #$40
4887: tsb  $180D
488A: rts
488B: lda  #$40
488D: trb  $180D
4890: rts
4891: lda  #$20
4893: tsb  $180D
4896: rts
4897: lda  #$20
4899: trb  $180D
489C: rts
489D: lda  #$80
489F: tsb  $180D
48A2: trb  $180D
48A5: rts
48A6: lda  $180C
48A9: and  #$8D
48AB: rts
48AC: stx  $1808
48AF: sty  $1809
48B2: lda  #$03
48B4: tsb  $180D
48B7: lda  #$01
48B9: trb  $180D
48BC: lda  #$02
48BE: trb  $180D
48C1: rts
48C2: lda  #$04
48C4: tsb  $1802
48C7: rts
48C8: lda  #$04
48CA: trb  $1802
48CD: rts
48CE: lda  #$08
48D0: tsb  $1802
48D3: rts
48D4: lda  #$08
48D6: trb  $1802
48D9: rts
48DA: lda  $22A4
48DD: rts
report#39.7
投稿者:na6ko
時刻:2018-03-29 01:27:44
状態:受付済
頻度:必ず起きる
READ6+ADPCM再生の準備後, IRQ2 が3度発生すると ADPCM 再生になるが、
IRQ2 の発生回数が少ないことが判明.
report#39.8
投稿者:na6ko
時刻:2018-07-25 22:15:46
状態:受付済
頻度:必ず起きる
タイトル画面放置で始まるデモで, STEAM HEARTS の文字が出るところで停まっていたのでそこを解析した.
address 0x1ff80d に書かれる data は 0x20 で, bit5 を ADPCM 再生にすべきであることにいまさら気付く. 現状の実装が bit6 が ADPCM 再生, bit5 が length == 0 で無限ループのところをコメントアウトになっていた.
mednafen のソースから bit6 を無限ループ, bit5 を ADPCM 再生にして実装.
この状態で STREAM HEARTS の曲が ADPCM RAM にして 0x10000 byte 再生されたところで無限ループとなった. つまり追記されていない. 追記されていない理由は現在未調査.

解釈が間違っていたが、影響範囲がかなり大きいのでかなりの数のソフトの動作確認のし直しが必要.
report#39.9
投稿者:na6ko
時刻:2018-07-26 23:07:33
状態:保留
頻度:必ず起きる
ゲーム開始直後に音が出ない部分は IRQ2 の割り込み処理が発生していないことを確認した. CD drive ready と CD drive done の IRQ2 の線を L にする条件を下記に変更.
処理前
- 0x1ff802.w.6 & drive_ready の立ち上がりで 1 にする. 
- drive_ready == 0 でその線を 0 にする.
- 0x1ff802.w.5 & drive_done で (以下 drive_ready と同じ)
処理後
- 0x1ff802.w.6 & drive_ready を IRQ2 にいれる
- 0x1ff802.w.5 & drive_done を IRQ2 にいれる

以上で IRQ2 は発生しボイスがでて少し進んだが別の場所ですぐ停まった.

おそらく仮想 CD 読み込みが早すぎる関係で IRQ2 の許可フラグの設定が間に合っていないために生じるバグだと思われる. 今回の一連の修正はロード時間やシーク時間を調整することは考えていないので保留とする.

パッチを当てれば直る可能性はあるが、もとのプログラムがかなり汚いので簡単に直る可能性は低い.
report#39.10
投稿者:na6ko
時刻:2018-09-14 13:44:49
状態:保留
頻度:必ず起きる
<BTS:80> の対応後の確認.
ゲーム最初の会話は進むようになった. ゲーム開始前から絵がおかしくなったり動作が遅かったりCDの曲が鳴らないなど未だ不安定.
report#39.11
投稿者:Dave Shadoff
時刻:2019-01-27 02:08:02
状態:保留
頻度:必ず起きる
I think the SCSI command returns too quickly with "Data xfer ready" status.  Please look at this log from my special mednafen (pce module)... at the end of the log.

- A SCSI command is started at time 0465193872
- The interrupt vector is redirected at time 0465194106
- The interrupt is finally raised at time 0466241151

If the interrupt occurs too early, it won't go to the new interrupt handler.  This might be the situation.

In any case, the interesting time period is from 0465193872 to 0477156705.

All times are recorded in "master clocks" (~21.48 MHz).
report#39.12
投稿者:na6ko
時刻:2019-02-19 12:57:42
状態:保留
頻度:必ず起きる
問題に挙げてくださった部分ですが、下記の時間は確かにわたしの実装は雑に最低限の時間(2msぐらい)でしたので変更してみました.

0465193872:SCSI:Command: 08, Read(6)  08 00 1d 8b 20 00 
0465193872:SCSI:Read: start=0x00001d8b(track=2, offs=0x00000cf4), cnt=0x00000020
0465194106:BIOS:Call EX_SETVEC from $4FCB, Set IRQ2 to $4FDD (Bank $68)
0466241151:CD-IRQ:IRQ raised: SCSICD_DATA_XFER_READY 

これは PCE の master clock count だということですので下記の計算から 50 ms の待ち時間を試しに入れました. 結果はスチームハーツは不安定でととらべらーずはおかしいままです.
ruby -e 'c = 466241151 - 465193872; p c / (21.48*10**6)'
0.048756005586592176

実機側でデバッグログをとれればいいんですけど signaltap だととれるのは 0x200 clock の波形だけですからよくわかってないことがおおいですね...
report#39.13
投稿者:na6ko
時刻:2019-02-28 22:51:07
状態:受付済
頻度:必ず起きる
<BTS:17> の対応で改善.
スタートボタンを押さずに回るデモは止まらなくなった.
ゲーム本編前の会話も止まらなくなった.
ゲーム本編開始直後の CDDA の再生がおかしくなるらしい.

08> 001D2B 04[+016E:014Dms]-> 6280
08> 001D53 04[+24:014Dms]-> 6280
*0xff*
08> 001D8B 20[+34:014Dms]-> ADPCM RAM 02
*0xff*
08> 00202F 20[+0284:014Dms]-> ADPCM RAM 02
08> 00204F 10[0:32ms]-> ADPCM RAM 02
08> 00205F 10[0:32ms]-> ADPCM RAM 02
*0xff*
08> 005226 20[+31B7:0287ms]-> ADPCM RAM 02
D8> 14:08:74 seek[+A5DE:034Dms]
D9> 16:58:29 IRQ2
audio play
D8> 14:08:74drive stop seek[-06:0161ms]
D9> 16:58:29 IRQ2
audio play
D8> 14:08:74drive stop seek[-06:0161ms]
D9> 16:58:29 IRQ2
audio play
D8> 14:08:74drive stop seek[-06:0161ms]
D9> 16:58:29 IRQ2
audio play
D8> 14:08:74drive stop seek[-06:0161ms]
D9> 16:58:29 IRQ2
audio play
report#39.14
投稿者:na6ko
時刻:2019-02-28 23:58:38
状態:受付済
頻度:必ず起きる
現状を録画した.
https://youtu.be/PWVLN8WAXT8
report#39.15
投稿者:na6ko
時刻:2019-03-01 02:05:15
状態:受付済
頻度:必ず起きる
command 0xd8 と 同 0xd9 が無限に発行されるのはこのプログラムにとって正常. ドラビアンナイト(CD)のように seek をしない特別な処理が必要.

mednafen はこれを適用するには下記の if となっている.
if(
	(cdda.CDDAStatus == CDDASTATUS_PLAYING) && 
	(new_read_sec_start == read_sec_start) && 
	(((int64)(monotonic_timestamp - pce_lastsapsp_timestamp) * 1000 / System_Clock) < 190)
){
CDDAStatus と new_read_sec_start は対応できるので同じようにした. timestamp は得られないのでこの条件は抜いた. timestamp はおそらく問題のソフトが無難に動くように場当たり的にいれている対応だろうから、根拠のある説明がほしい.

以上の対応処理をいれたが処理落ちするらしくスクロールがぶれる. 予想以上のひどいプログラムで再び直す気力がなくなった...
https://youtu.be/RCgkJHPqR7M
report#39.16
投稿者:na6ko
時刻:2019-03-01 02:11:08
状態:保留
頻度:必ず起きる
不具合の動き方がドラビアンナイトとそっくりであるので開発元(つまり使い回したひどいソースコード)が同じだと予想される. よって <BTS:98><BTS:17> の対応で直っているかもしれない.

無駄な command 0xd8 と 0xd9 を発行する理由は、プログラマが正しいループ再生の方法をしらないのかなぜか動かなかったのでその場しのぎに再生コマンドを無限発行したと思われる. そうすればループ再生と大体同じになる.
BIOS のルーチンを使わずに自前でレジスタ制御しているのもここらへんが原因なのかもしれない.

再度保留にいたします.
report#39.17
投稿者:na6ko
時刻:2019-07-28 07:24:43
状態:修正済
頻度:必ず起きる
最近の <BTS:78> <BTS:101> の修正、CD 再生途中のフラグ管理を直した過程でこのゲームのスクロールレジスタの更新がおかしい問題が直ってしまったらしい.
状態を変更する.