ppsspp icon indicating copy to clipboard operation
ppsspp copied to clipboard

bug in SimpleAudio::Decode ffmpeg logic

Open rofl0r opened this issue 1 year ago • 5 comments

Game or games this happens in

homebrew using mp3 api

What area of the game / PPSSPP

N/A

What should happen

according to https://ffmpeg.org/doxygen/trunk/group__lavc__decoding.html#ga58bc4bf1e0ac59e27362597e467efff3 avcodec_send_packet() has a 1:n relation to avcodec_receive_frame()

it states:

the packet is always fully consumed, and if it contains multiple frames (e.g. some audio codecs), will require you to call avcodec_receive_frame() multiple times afterwards before you can send a new packet

currently the code sends one packet, then receives one frame, which is wrong. i noticed this because PPSSPP kept spamming the terminal about EAGAIN received from avcodec_send_packet instead of playing music from the pspsdk mp3 sample code.

here's a patch that does the conceptually right thing: drain ffmpeg of all frames after sending a packet. however, after applying it i now get

36:15:781 user_main    E[SCEAUDIO]: HLE/__sceAudio.cpp:360 Channel 8 buffer underrun at 32 of 64
36:15:873 user_main    E[SCEAUDIO]: HLE/__sceAudio.cpp:360 Channel 8 buffer underrun at 16 of 64
36:15:873 user_main    E[ME]: HW/SimpleAudioDec.cpp:268 Error decoding Audio frame (14776 bytes): -1094995529 (bebbb1b7)
36:16:089 user_main    E[ME]: HW/SimpleAudioDec.cpp:249 Error sending audio frame to decoder (14632 bytes): -1094995529 (bebbb1b7)

and i'm lacking the nerve to further debug/fix the issue.

patch:

diff --git a/Core/HW/SimpleAudioDec.cpp b/Core/HW/SimpleAudioDec.cpp
index 80397bf6d..50aa66fe8 100644
--- a/Core/HW/SimpleAudioDec.cpp
+++ b/Core/HW/SimpleAudioDec.cpp
@@ -179,7 +179,55 @@ bool SimpleAudio::IsOK() const {
 #endif
 }
 
+#ifdef USE_FFMPEG
+bool SimpleAudio::ProcessFrame(uint8_t **outbuf, int *outbytes) {
+	// Initializing the sample rate convert. We will use it to convert float output into int.
+	int64_t wanted_channel_layout = AV_CH_LAYOUT_STEREO; // we want stereo output layout
+	int64_t dec_channel_layout = frame_->channel_layout; // decoded channel layout
+
+	if (!swrCtx_) {
+		swrCtx_ = swr_alloc_set_opts(
+			swrCtx_,
+			wanted_channel_layout,
+			AV_SAMPLE_FMT_S16,
+			wanted_resample_freq,
+			dec_channel_layout,
+			codecCtx_->sample_fmt,
+			codecCtx_->sample_rate,
+			0,
+			NULL);
+
+		if (!swrCtx_ || swr_init(swrCtx_) < 0) {
+			ERROR_LOG(ME, "swr_init: Failed to initialize the resampling context");
+			avcodec_close(codecCtx_);
+			codec_ = 0;
+			return false;
+		}
+	}
+
+	// convert audio to AV_SAMPLE_FMT_S16
+	int swrRet = 0;
+	if (*outbuf != nullptr) {
+		swrRet = swr_convert(swrCtx_, &(*outbuf), frame_->nb_samples, (const u8 **)frame_->extended_data, frame_->nb_samples);
+	}
+	if (swrRet < 0) {
+		ERROR_LOG(ME, "swr_convert: Error while converting: %d", swrRet);
+		return false;
+	}
+	// output samples per frame, we should *2 since we have two channels
+	outSamples = swrRet * 2;
+	// each sample occupies 2 bytes
+	*outbytes += outSamples * 2;
+	*outbuf += outSamples * 2;
+
+	// Save outbuf into pcm audio, you can uncomment this line to save and check the decoded audio into pcm file.
+	// SaveAudio("dump.pcm", outbuf, *outbytes);
+	return true;
+}
+#endif
+
 bool SimpleAudio::Decode(const uint8_t *inbuf, int inbytes, uint8_t *outbuf, int *outbytes) {
+	bool ret = true;
 #ifdef USE_FFMPEG
 	if (!codecOpen_) {
 		OpenCodec(inbytes);
@@ -196,82 +244,49 @@ bool SimpleAudio::Decode(const uint8_t *inbuf, int inbytes, uint8_t *outbuf, int
 	*outbytes = 0;
 	srcPos = 0;
 #if LIBAVCODEC_VERSION_INT >= AV_VERSION_INT(57, 48, 101)
+	int err = 0;
 	if (inbytes != 0) {
 		int err = avcodec_send_packet(codecCtx_, &packet);
-		if (err < 0) {
+		if (err < 0 && err != AVERROR(EAGAIN)) {
 			ERROR_LOG(ME, "Error sending audio frame to decoder (%d bytes): %d (%08x)", inbytes, err, err);
 			return false;
 		}
 	}
-	int err = avcodec_receive_frame(codecCtx_, frame_);
-	int len = 0;
-	if (err >= 0) {
-		len = frame_->pkt_size;
-		got_frame = 1;
-	} else if (err != AVERROR(EAGAIN)) {
-		len = err;
-	}
+	while(1) {
+		int err = avcodec_receive_frame(codecCtx_, frame_);
+		int len = 0;
+		if (err == AVERROR(EAGAIN) || err == AVERROR_EOF)
+			break;
+		if (err >= 0) {
+			len = frame_->pkt_size;
+			got_frame = 1;
+		} else if (err != AVERROR(EAGAIN)) {
+			len = err;
+		}
 #else
-	int len = avcodec_decode_audio4(codecCtx_, frame_, &got_frame, &packet);
+		int len = avcodec_decode_audio4(codecCtx_, frame_, &got_frame, &packet);
 #endif
+		if (len < 0) {
+			ERROR_LOG(ME, "Error decoding Audio frame (%i bytes): %i (%08x)", inbytes, len, len);
+			ret = false;
+			break;
+		}
+		// get bytes consumed in source
+		if(len > 0 && !srcPos) {
+			srcPos = len;
+		}
+
+		if (got_frame) {
+			if(!ProcessFrame(&outbuf, outbytes)) break;
+		}
+	}
+
 #if LIBAVCODEC_VERSION_INT >= AV_VERSION_INT(57, 12, 100)
 	av_packet_unref(&packet);
 #else
 	av_free_packet(&packet);
 #endif
-
-	if (len < 0) {
-		ERROR_LOG(ME, "Error decoding Audio frame (%i bytes): %i (%08x)", inbytes, len, len);
-		return false;
-	}
-	
-	// get bytes consumed in source
-	srcPos = len;
-
-	if (got_frame) {
-		// Initializing the sample rate convert. We will use it to convert float output into int.
-		int64_t wanted_channel_layout = AV_CH_LAYOUT_STEREO; // we want stereo output layout
-		int64_t dec_channel_layout = frame_->channel_layout; // decoded channel layout
-
-		if (!swrCtx_) {
-			swrCtx_ = swr_alloc_set_opts(
-				swrCtx_,
-				wanted_channel_layout,
-				AV_SAMPLE_FMT_S16,
-				wanted_resample_freq,
-				dec_channel_layout,
-				codecCtx_->sample_fmt,
-				codecCtx_->sample_rate,
-				0,
-				NULL);
-
-			if (!swrCtx_ || swr_init(swrCtx_) < 0) {
-				ERROR_LOG(ME, "swr_init: Failed to initialize the resampling context");
-				avcodec_close(codecCtx_);
-				codec_ = 0;
-				return false;
-			}
-		}
-
-		// convert audio to AV_SAMPLE_FMT_S16
-		int swrRet = 0;
-		if (outbuf != nullptr) {
-			swrRet = swr_convert(swrCtx_, &outbuf, frame_->nb_samples, (const u8 **)frame_->extended_data, frame_->nb_samples);
-		}
-		if (swrRet < 0) {
-			ERROR_LOG(ME, "swr_convert: Error while converting: %d", swrRet);
-			return false;
-		}
-		// output samples per frame, we should *2 since we have two channels
-		outSamples = swrRet * 2;
-
-		// each sample occupies 2 bytes
-		*outbytes = outSamples * 2;
-
-		// Save outbuf into pcm audio, you can uncomment this line to save and check the decoded audio into pcm file.
-		// SaveAudio("dump.pcm", outbuf, *outbytes);
-	}
-	return true;
+	return ret;
 #else
 	// Zero bytes output. No need to memset.
 	*outbytes = 0;
diff --git a/Core/HW/SimpleAudioDec.h b/Core/HW/SimpleAudioDec.h
index 9bf2427a4..18083526c 100644
--- a/Core/HW/SimpleAudioDec.h
+++ b/Core/HW/SimpleAudioDec.h
@@ -94,6 +94,9 @@ class SimpleAudio {
 	SwrContext      *swrCtx_;
 
 	bool codecOpen_;
+#ifdef USE_FFMPEG
+	bool ProcessFrame(uint8_t **outbuf, int *outbytes);
+#endif
 };
 
 void AudioClose(SimpleAudio **ctx);

my ffmpeg version is ffmpeg-4.3.5

Logs

No response

Platform

Linux / BSD

Mobile device model or graphics card (GPU)

n/a

PPSSPP version affected

git

Last working version

n/a

Graphics backend (3D API)

OpenGL / GLES

Checklist

  • [X] Test in the latest git build in case it's already fixed.
  • [X] Search for other reports of the same issue.
  • [ ] Try resetting settings or older versions and include if the issue is related.
  • [ ] Try without any cheats and without loading any save states.
  • [ ] Include logs or screenshots of issue.

rofl0r avatar Feb 26 '24 16:02 rofl0r

here's my code to trigger the bug:

/*
 * PSP Software Development Kit - https://github.com/pspdev
 * -----------------------------------------------------------------------
 * Licensed under the BSD license, see LICENSE in PSPSDK root for details.
 *
 * main.c - Sample to demonstrate proper use of the mp3 library
 *
 * Copyright (c) 2008 Alexander Berl <[email protected]>
 *
 */
#include <pspkernel.h>
#include <pspdebug.h>
#include <pspctrl.h>
#include <pspdisplay.h>
#include <stdio.h>
#include <pspaudio.h>
#include <pspmp3.h>
#include <psputility.h>
#include <string.h>

/* Define the module info section */
PSP_MODULE_INFO("Mp3Test", 0, 0, 1);
PSP_MAIN_THREAD_ATTR(THREAD_ATTR_USER);
PSP_HEAP_SIZE_KB(-1024);

#define MP3FILE "ms0:/MUSIC/test.mp3"

// Input and Output buffers
unsigned char mp3Buf[16 * 1024] __attribute__ ((aligned(64)));
unsigned short pcmBuf[16 * (1152 / 2)] __attribute__ ((aligned(64)));


/* Define printf, just to make typing easier */
#define printf  pspDebugScreenPrintf

static int isrunning = 1;
/* Exit callback */
int exit_callback(int arg1, int arg2, void *common)
{
	isrunning = 0;
	return 0;
}

/* Callback thread */
int CallbackThread(SceSize args, void *argp)
{
	int cbid;
	cbid = sceKernelCreateCallback("Exit Callback", exit_callback, NULL);
	sceKernelRegisterExitCallback(cbid);
	sceKernelSleepThreadCB();
	return 0;
}

/* Sets up the callback thread and returns its thread id */
int SetupCallbacks(void)
{
	int thid = 0;
	thid =
	    sceKernelCreateThread("update_thread", CallbackThread, 0x11, 0xFA0,
				  0, 0);
	if (thid >= 0)
		sceKernelStartThread(thid, 0, 0);
	return thid;
}

// Macro to allow formatted input without having to use stdargs.h
#define ERRORMSG(...) { char msg[128]; sprintf(msg,__VA_ARGS__); error(msg); }

// Print out an error message and quit after user input
void error(char *msg)
{
	SceCtrlData pad;
	pspDebugScreenClear();
	pspDebugScreenSetXY(0, 0);
	printf(msg);
	printf("Press X to quit.\n");
	while (isrunning) {
		sceCtrlReadBufferPositive(&pad, 1);
		if (pad.Buttons & PSP_CTRL_CROSS)
			break;
		sceDisplayWaitVblankStart();
	}
	sceKernelExitGame();
}

int fillStreamBuffer(int fd, int handle)
{
	char *dst;
	int towrite, nread, pos;
	// Get Info on the stream (where to fill to, how much to fill, where to fill from)
	int status = sceMp3GetInfoToAddStreamData(handle, &dst, &towrite, &pos);
	if (status < 0) {
		ERRORMSG
		    ("ERROR: sceMp3GetInfoToAddStreamData returned 0x%08X\n",
		     status);
	}
	// Seek file to position requested
	status = sceIoLseek32(fd, pos, SEEK_SET);
	if (status < 0) {
		ERRORMSG("ERROR: sceIoLseek32 returned 0x%08X\n", status);
	}
	// Read the amount of data
	nread = sceIoRead(fd, dst, towrite);
	if (nread < 0) {
		ERRORMSG("ERROR: Could not read from file - 0x%08X\n", nread);
	}

	if (nread == 0) {
		// End of file?
		return 0;
	}
	// Notify mp3 library about how much we really wrote to the stream buffer
	status = sceMp3NotifyAddStreamData(handle, nread);
	if (status < 0) {
		ERRORMSG("ERROR: sceMp3NotifyAddStreamData returned 0x%08X\n",
			 status);
	}

	return (pos > 0);
}

// skip ID3 header.
static int find_mp3_frame(int fd) {
	int status, start = 0;
	unsigned char buf[4096];
	status = sceIoRead(fd, buf, sizeof(buf));
	if(status >= 3 && buf[0] == 'I' && buf[1] == 'D' && buf[2] == '3') {
		while(1) {
			int i, lastff = 0;
			for(i = 0; i < status; ++i) {
				if(lastff) {
					if(buf[i] & 0xf0) {
						start += i-1;
						goto frame_found;
					}
					lastff = 0;
				}
				if(buf[i] == 0xff) lastff = 1;
			}
			start += status;
			status = sceIoRead(fd, buf, sizeof(buf));
			if(status <= 0) ERRORMSG("ERROR: couldnt find mp3 header\n");
		}
frame_found:;
#if 0
		if(status >= 10 && buf[3] == 3 && buf[4] == 0) /* id3 v2.3 */
			start = (buf[6] << 21) | (buf[7] << 14) |
				(buf[8] << 7)  | buf[9];
#endif
	}
	return start;
}

static int load_file(char *fn, int* fd, int *handle, SceMp3InitArg *arg)
{
	int status, start;
	unsigned char buf[4096];
	// Open the input file
	*fd = sceIoOpen(fn, PSP_O_RDONLY, 0777);
	if (*fd < 0) {
		ERRORMSG("ERROR: Could not open file '%s' - 0x%08X\n", fn, *fd);
	}

	start = find_mp3_frame(*fd);

	// Init mp3 resources
	status = sceMp3InitResource();
	if (status < 0) {
		ERRORMSG("ERROR: sceMp3InitResource returned 0x%08X\n", status);
	}

	memset(arg, 0, sizeof(*arg));
	arg->mp3StreamStart = start;
	arg->mp3StreamEnd = sceIoLseek32(*fd, 0, SEEK_END);
	arg->mp3Buf = mp3Buf;
	arg->mp3BufSize = sizeof(mp3Buf);
	arg->pcmBuf = pcmBuf;
	arg->pcmBufSize = sizeof(pcmBuf);

	*handle = sceMp3ReserveMp3Handle(arg);
	if (*handle < 0) {
		ERRORMSG("ERROR: sceMp3ReserveMp3Handle returned 0x%08X\n",
			 *handle);
	}

	// Fill the stream buffer with some data so that sceMp3Init has something to work with
	fillStreamBuffer(*fd, *handle);

	status = sceMp3Init(*handle);
	if (status < 0) {
		ERRORMSG("ERROR: sceMp3Init returned 0x%08X\n", status);
	}

	return status;
}

#define DECODE_MAGIC 0x80671402
//#define DECODE_MAGIC 0x80671103

int main(int argc, char *argv[])
{
	SceCtrlData pad;
	int status, handle, fd;
	SceMp3InitArg mp3Init;

	//init screen and callbacks
	pspDebugScreenInit();
	pspDebugScreenClear();
	SetupCallbacks();

	// Setup Pad
	sceCtrlSetSamplingCycle(0);
	sceCtrlSetSamplingMode(0);

	// Load modules
	status = sceUtilityLoadModule(PSP_MODULE_AV_AVCODEC);
	//status = sceUtilityLoadAvModule(PSP_AV_MODULE_AVCODEC);
	if (status < 0) {
		ERRORMSG
		    ("ERROR: sceUtilityLoadModule(PSP_MODULE_AV_AVCODEC) returned 0x%08X\n",
		     status);
	}

	status = sceUtilityLoadModule(PSP_MODULE_AV_MP3);
	//status = sceUtilityLoadAvModule(PSP_AV_MODULE_MP3);
	if (status < 0) {
		ERRORMSG
		    ("ERROR: sceUtilityLoadModule(PSP_MODULE_AV_MP3) returned 0x%08X\n",
		     status);
	}

#if 0
	status = sceAudioInit();
	if (status < 0) {
		ERRORMSG
		    ("ERROR: sceAudioInit() returned 0x%08X\n",
		     status);
	}
#endif

	// Reserve a mp3 handle for our playback

	load_file(MP3FILE, &fd, &handle, &mp3Init);

	int channel = -1;
	int samplingRate = sceMp3GetSamplingRate(handle);
	int numChannels = sceMp3GetMp3ChannelNum(handle);
	int volume = 0x7000; //PSP_AUDIO_VOLUME_MAX;
	int numPlayed = 0;
	int paused = 0;
	int lastButtons = 0;
	int loop = 0;

	while (isrunning) {
		sceDisplayWaitVblankStart();
		pspDebugScreenSetXY(0, 0);
		printf("PSP Mp3 Sample v1.0 by Raphael\n\n");
		printf("Playing '%s'...\n", MP3FILE);
		printf(" %i Hz\n", samplingRate);
		printf(" %i kbit/s\n", sceMp3GetBitRate(handle));
		printf(" %s\n", numChannels == 2 ? "Stereo" : "Mono");
		printf(" %s\n\n", loop == 0 ? "No loop" : "Loop");
		int playTime = samplingRate > 0 ? numPlayed / samplingRate : 0;
		printf(" Playtime: %02i:%02i\n", playTime / 60, playTime % 60);
		printf
		    ("\n\n\nPress CIRCLE to Pause/Resume playback\nPress TRIANGLE to reset playback\nPress CROSS to switch loop mode\nPress SQUARE to stop playback and quit\n");

		if (!paused) {
			// Check if we need to fill our stream buffer
			if (sceMp3CheckStreamDataNeeded(handle) > 0) {
				fillStreamBuffer(fd, handle);
			}
			// Decode some samples
			short *buf;
			int bytesDecoded;
			int retries = 0;
			// We retry in case it's just that we reached the end of the stream and need to loop
			for (; retries < 1; retries++) {
				bytesDecoded = sceMp3Decode(handle, &buf);
				if (bytesDecoded > 0)
					break;

				if (sceMp3CheckStreamDataNeeded(handle) <= 0)
					break;

				if (!fillStreamBuffer(fd, handle)) {
					numPlayed = 0;
				}
			}
			if (bytesDecoded < 0 && bytesDecoded != DECODE_MAGIC) {
				ERRORMSG
				    ("ERROR: sceMp3Decode returned 0x%08X\n",
				     bytesDecoded);
			}
			// Nothing more to decode? Must have reached end of input buffer
			if (bytesDecoded == 0 || bytesDecoded == DECODE_MAGIC) {
				paused = 1;
				sceMp3ResetPlayPosition(handle);
				numPlayed = 0;
			} else while(bytesDecoded > 0) {
				int samples = bytesDecoded / (2 * numChannels);
				/* PPSSPP limits the range of SRC channel reservation samples to 17 - 4111. */
				int actualSamples = samples > 4032 ? 4032 : samples;
				samples -= actualSamples;
				if (samples <= 17) actualSamples += samples;

				// Reserve the Audio channel for our output if not yet done
				if (channel >= 0) {
					while(sceAudioOutput2GetRestSample()) ;
					while(0x80268002 == sceAudioSRCChRelease()); /* loop until not busy */
					channel = -1;
				}

				if (channel < 0) {
					// samplingRate,
					channel = sceAudioSRCChReserve(
						  actualSamples,
						  samplingRate,
						  numChannels);
				}
				// Output the decoded samples and accumulate the number of played samples to get the playtime
				numPlayed +=
				    sceAudioSRCOutputBlocking(volume, buf);

				buf += numPlayed;
				bytesDecoded -= (numPlayed*2);
			}
		}

		sceCtrlPeekBufferPositive(&pad, 1);

		if (pad.Buttons != lastButtons) {
			if (pad.Buttons & PSP_CTRL_CIRCLE) {
				paused ^= 1;
			}

			if (pad.Buttons & PSP_CTRL_TRIANGLE) {
				// Reset the stream and playback status
				sceMp3ResetPlayPosition(handle);
				numPlayed = 0;
			}

			if (pad.Buttons & PSP_CTRL_CROSS) {
				loop = (loop == 0 ? -1 : 0);
				status = sceMp3SetLoopNum(handle, loop);
				if (status < 0) {
					ERRORMSG
					    ("ERROR: sceMp3SetLoopNum returned 0x%08X\n",
					     status);
				}
			}

			if (pad.Buttons & PSP_CTRL_SQUARE) {
				break;
			}

			lastButtons = pad.Buttons;
		}
	}

	// Cleanup time...
	if (channel >= 0)
		sceAudioChRelease(channel);

	status = sceMp3ReleaseMp3Handle(handle);
	if (status < 0) {
		ERRORMSG("ERROR: sceMp3ReleaseMp3Handle returned 0x%08X\n",
			 status);
	}

	status = sceMp3TermResource();
	if (status < 0) {
		ERRORMSG("ERROR: sceMp3TermResource returned 0x%08X\n", status);
	}

	status = sceIoClose(fd);
	if (status < 0) {
		ERRORMSG("ERROR: sceIoClose returned 0x%08X\n", status);
	}

	sceKernelExitGame();

	return 0;
}

makefile:

TARGET = All
OBJS = main.o

CFLAGS = -O2 -G0 -Wall
CXXFLAGS = $(CFLAGS) -fno-exceptions -fno-rtti
ASFLAGS = $(CFLAGS)

LIBS = -lpsppower -lz -lm -lpspdebug -lpspgu -lpspaudiolib -lpspaudio -lpspaudiocodec -lpsprtc -lpspmp3
# -lpspaudio_driver

EXTRA_TARGETS = EBOOT.PBP
PSP_EBOOT_TITLE = 
PSP_EBOOT_ICON = 
PSP_EBOOT_PIC1 = 

PSPSDK=$(shell psp-config --pspsdk-path)
include $(PSPSDK)/lib/build.mak

rofl0r avatar Feb 26 '24 16:02 rofl0r

thanks, this is a good start of an investigation! Already know that our mp3 stuff is wrong, it's not working well in some games that allow using mp3 as custom background music.

hrydgard avatar Feb 27 '24 04:02 hrydgard

Thanks for reporting this.

I looked into it way back in december (used to play on an old high-FPS build), before also giving up. Here were my notes:

SimpleAudio::Decode is ducked.

See the overview on API usage for avcodec_{send,receive}_{packet,frame}. Something's ducked up with how some codecs require draining the output before sending more stuff.

What's happening in particular is that after 1/2 frames, we receive a frame length that contains two frames, as reported by the logger. So audio breaks.

You can mess around with the order and it'll play choppily before hanging, so investigate.

FindNextMp3Sync() might be broken ? Think it decides the offset to the frame data ?

I may try to bang my head against this some more.

With the ffmpeg output draining taken care of, we can isolate this issue to PPSSPP's MP3 handler, correct ? Is FindNextMp3Sync() a good place to focus on ?

EDIT: I was about to look into it again and it looks like it's somehow been fixed in 1.17.1.

Nabile-Rahmani avatar Jul 09 '24 13:07 Nabile-Rahmani