Merge pull request #13238 from hrydgard/minor-logging-cleanup

Logging and error handling improvements around save states
This commit is contained in:
Henrik Rydgård 2020-08-02 19:05:58 +02:00 committed by GitHub
commit 60683cf4a4
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 84 additions and 84 deletions

View file

@ -30,23 +30,26 @@ PointerWrapSection PointerWrap::Section(const char *title, int minVer, int ver)
char marker[16] = {0};
int foundVersion = ver;
// This is strncpy because we rely on its weird non-null-terminating truncation behaviour.
// This is strncpy because we rely on its weird non-null-terminating zero-filling truncation behaviour.
// Can't replace it with the more sensible truncate_cpy because that would break savestates.
strncpy(marker, title, sizeof(marker));
if (!ExpectVoid(marker, sizeof(marker)))
{
if (!ExpectVoid(marker, sizeof(marker))) {
// Might be before we added name markers for safety.
if (foundVersion == 1 && ExpectVoid(&foundVersion, sizeof(foundVersion)))
if (foundVersion == 1 && ExpectVoid(&foundVersion, sizeof(foundVersion))) {
DoMarker(title);
// Wasn't found, but maybe we can still load the state.
else
} else {
// Wasn't found, but maybe we can still load the state.
foundVersion = 0;
}
else
}
} else {
Do(foundVersion);
}
if (error == ERROR_FAILURE || foundVersion < minVer || foundVersion > ver) {
WARN_LOG(SAVESTATE, "Savestate failure: wrong version %d found for %s", foundVersion, title);
if (!firstBadSectionTitle_) {
firstBadSectionTitle_ = title;
}
WARN_LOG(SAVESTATE, "Savestate failure: wrong version %d found for section '%s'", foundVersion, title);
SetError(ERROR_FAILURE);
return PointerWrapSection(*this, -1, title);
}
@ -58,6 +61,7 @@ void PointerWrap::SetError(Error error_) {
error = error_;
}
if (error > ERROR_WARNING) {
// For the rest of this run, just measure.
mode = PointerWrap::MODE_MEASURE;
}
}

View file

@ -76,6 +76,7 @@ private:
// Wrapper class
class PointerWrap
{
private:
// This makes it a compile error if you forget to define DoState() on non-POD.
// Which also can be a problem, for example struct tm is non-POD on linux, for whatever reason...
#ifdef _MSC_VER
@ -111,6 +112,8 @@ class PointerWrap
}
};
const char *firstBadSectionTitle_ = nullptr;
public:
enum Mode {
MODE_READ = 1, // load
@ -127,11 +130,11 @@ public:
u8 **ptr;
Mode mode;
Error error;
Error error = ERROR_NONE;
public:
PointerWrap(u8 **ptr_, Mode mode_) : ptr(ptr_), mode(mode_), error(ERROR_NONE) {}
PointerWrap(unsigned char **ptr_, int mode_) : ptr((u8**)ptr_), mode((Mode)mode_), error(ERROR_NONE) {}
PointerWrap(u8 **ptr_, Mode mode_) : ptr(ptr_), mode(mode_) {}
PointerWrap(unsigned char **ptr_, int mode_) : ptr((u8**)ptr_), mode((Mode)mode_) {}
PointerWrapSection Section(const char *title, int ver);
@ -145,6 +148,10 @@ public:
u8 **GetPPtr() {return ptr;}
void SetError(Error error_);
const char *GetBadSectionTitle() const {
return firstBadSectionTitle_;
}
// Same as DoVoid, except doesn't advance pointer if it doesn't match on read.
bool ExpectVoid(void *data, int size);
void DoVoid(void *data, int size);
@ -586,7 +593,7 @@ public:
// May fail badly if ptr doesn't point to valid data.
template<class T>
static Error LoadPtr(u8 *ptr, T &_class)
static Error LoadPtr(u8 *ptr, T &_class, std::string *errorString)
{
PointerWrap p(&ptr, PointerWrap::MODE_READ);
_class.DoState(p);
@ -594,6 +601,7 @@ public:
if (p.error != p.ERROR_FAILURE) {
return ERROR_NONE;
} else {
*errorString = std::string("Failure at ") + p.GetBadSectionTitle();
return ERROR_BROKEN_STATE;
}
}
@ -630,14 +638,13 @@ public:
u8 *ptr = nullptr;
size_t sz;
Error error = LoadFile(filename, gitVersion, ptr, sz, failureReason);
if (error == ERROR_NONE) {
error = LoadPtr(ptr, _class);
delete [] ptr;
}
INFO_LOG(SAVESTATE, "ChunkReader: Done loading %s", filename.c_str());
if (error == ERROR_NONE) {
failureReason->clear();
error = LoadPtr(ptr, _class, failureReason);
delete [] ptr;
INFO_LOG(SAVESTATE, "ChunkReader: Done loading '%s'", filename.c_str());
} else {
WARN_LOG(SAVESTATE, "ChunkReader: Error found during load of '%s'", filename.c_str());
}
return error;
}

View file

@ -33,13 +33,12 @@ VKAPI_ATTR VkBool32 VKAPI_CALL VulkanDebugUtilsCallback(
const char *pMessage = pCallbackData->pMessage;
// Apparent bugs around timestamp validation in the validation layers
if (strstr(pMessage, "vkCmdBeginQuery(): VkQueryPool"))
return false;
if (strstr(pMessage, "vkGetQueryPoolResults() on VkQueryPool"))
return false;
int messageCode = pCallbackData->messageIdNumber;
if (messageCode == 101294395) {
// UNASSIGNED-CoreValidation-Shader-OutputNotConsumed - benign perf warning
return false;
}
const char *pLayerPrefix = "";
if (messageSeverity & VK_DEBUG_UTILS_MESSAGE_SEVERITY_ERROR_BIT_EXT) {
message << "ERROR(";
@ -58,7 +57,7 @@ VKAPI_ATTR VkBool32 VKAPI_CALL VulkanDebugUtilsCallback(
} else if (messageType & VK_DEBUG_UTILS_MESSAGE_TYPE_VALIDATION_BIT_EXT) {
message << "validation";
}
message << ":" << pCallbackData->messageIdNumber << ") " << pMessage << "\n";
message << ":" << messageCode << ") " << pMessage << "\n";
std::string msg = message.str();

View file

@ -143,7 +143,9 @@ void VulkanPushBuffer::Map() {
}
void VulkanPushBuffer::Unmap() {
_dbg_assert_(writePtr_ != 0);
_dbg_assert_msg_(writePtr_ != nullptr, "VulkanPushBuffer::Unmap: writePtr_ null here means we have a bug (map/unmap mismatch)");
if (!writePtr_)
return;
if ((memoryPropertyMask_ & VK_MEMORY_PROPERTY_HOST_COHERENT_BIT) == 0) {
VkMappedMemoryRange range{ VK_STRUCTURE_TYPE_MAPPED_MEMORY_RANGE };

View file

@ -91,9 +91,9 @@ namespace SaveState
return CChunkFileReader::SavePtr(&data[0], state);
}
CChunkFileReader::Error LoadFromRam(std::vector<u8> &data) {
CChunkFileReader::Error LoadFromRam(std::vector<u8> &data, std::string *errorString) {
SaveStart state;
return CChunkFileReader::LoadPtr(&data[0], state);
return CChunkFileReader::LoadPtr(&data[0], state, errorString);
}
struct StateRingbuffer
@ -135,7 +135,7 @@ namespace SaveState
return err;
}
CChunkFileReader::Error Restore()
CChunkFileReader::Error Restore(std::string *errorString)
{
std::lock_guard<std::mutex> guard(lock_);
@ -149,7 +149,7 @@ namespace SaveState
static std::vector<u8> buffer;
LockedDecompress(buffer, states_[n], bases_[baseMapping_[n]]);
return LoadFromRam(buffer);
return LoadFromRam(buffer, errorString);
}
void ScheduleCompress(std::vector<u8> *result, const std::vector<u8> *state, const std::vector<u8> *base)
@ -632,13 +632,14 @@ namespace SaveState
return copy;
}
bool HandleFailure()
bool HandleLoadFailure()
{
// Okay, first, let's give the rewind state a shot - maybe we can at least not reset entirely.
// Even if this was a rewind, maybe we can still load a previous one.
CChunkFileReader::Error result;
do {
result = rewindStates.Restore();
std::string errorString;
result = rewindStates.Restore(&errorString);
} while (result == CChunkFileReader::ERROR_BROKEN_STATE);
if (result == CChunkFileReader::ERROR_NONE) {
@ -728,7 +729,6 @@ namespace SaveState
Status callbackResult;
bool tempResult;
std::string callbackMessage;
std::string reason;
std::string title;
auto sc = GetI18NCategory("Screen");
@ -740,13 +740,14 @@ namespace SaveState
i18nSaveFailure = sc->T("Failed to save state");
std::string slot_prefix = op.slot >= 0 ? StringFromFormat("(%d) ", op.slot + 1) : "";
std::string errorString;
switch (op.type)
{
case SAVESTATE_LOAD:
INFO_LOG(SAVESTATE, "Loading state from %s", op.filename.c_str());
INFO_LOG(SAVESTATE, "Loading state from '%s'", op.filename.c_str());
// Use the state's latest version as a guess for saveStateInitialGitVersion.
result = CChunkFileReader::Load(op.filename, &saveStateInitialGitVersion, state, &reason);
result = CChunkFileReader::Load(op.filename, &saveStateInitialGitVersion, state, &errorString);
if (result == CChunkFileReader::ERROR_NONE) {
callbackMessage = slot_prefix + sc->T("Loaded State");
callbackResult = Status::SUCCESS;
@ -777,12 +778,12 @@ namespace SaveState
}
#endif
} else if (result == CChunkFileReader::ERROR_BROKEN_STATE) {
HandleFailure();
callbackMessage = i18nLoadFailure;
ERROR_LOG(SAVESTATE, "Load state failure: %s", reason.c_str());
HandleLoadFailure();
callbackMessage = std::string(i18nLoadFailure) + ": " + errorString;
ERROR_LOG(SAVESTATE, "Load state failure: %s", errorString.c_str());
callbackResult = Status::FAILURE;
} else {
callbackMessage = sc->T(reason.c_str(), i18nLoadFailure);
callbackMessage = sc->T(errorString.c_str(), i18nLoadFailure);
callbackResult = Status::FAILURE;
}
break;
@ -812,9 +813,9 @@ namespace SaveState
}
#endif
} else if (result == CChunkFileReader::ERROR_BROKEN_STATE) {
HandleFailure();
// TODO: What else might we want to do here? This should be very unusual.
callbackMessage = i18nSaveFailure;
ERROR_LOG(SAVESTATE, "Save state failure: %s", reason.c_str());
ERROR_LOG(SAVESTATE, "Save state failure");
callbackResult = Status::FAILURE;
} else {
callbackMessage = i18nSaveFailure;
@ -834,24 +835,24 @@ namespace SaveState
case SAVESTATE_REWIND:
INFO_LOG(SAVESTATE, "Rewinding to recent savestate snapshot");
result = rewindStates.Restore();
result = rewindStates.Restore(&errorString);
if (result == CChunkFileReader::ERROR_NONE) {
callbackMessage = sc->T("Loaded State");
callbackResult = Status::SUCCESS;
hasLoadedState = true;
} else if (result == CChunkFileReader::ERROR_BROKEN_STATE) {
// Cripes. Good news is, we might have more. Let's try those too, better than a reset.
if (HandleFailure()) {
if (HandleLoadFailure()) {
// Well, we did rewind, even if too much...
callbackMessage = sc->T("Loaded State");
callbackResult = Status::SUCCESS;
hasLoadedState = true;
} else {
callbackMessage = i18nLoadFailure;
callbackMessage = std::string(i18nLoadFailure) + ": " + errorString;
callbackResult = Status::FAILURE;
}
} else {
callbackMessage = i18nLoadFailure;
callbackMessage = std::string(i18nLoadFailure) + ": " + errorString;
callbackResult = Status::FAILURE;
}
break;

View file

@ -69,7 +69,7 @@ namespace SaveState
void Save(const std::string &filename, int slot, Callback callback = Callback(), void *cbUserData = 0);
CChunkFileReader::Error SaveToRam(std::vector<u8> &state);
CChunkFileReader::Error LoadFromRam(std::vector<u8> &state);
CChunkFileReader::Error LoadFromRam(std::vector<u8> &state, std::string *errorString);
// For testing / automated tests. Runs a save state verification pass (async.)
// Warning: callback will be called on a different thread.

View file

@ -403,7 +403,7 @@ VirtualFramebuffer *FramebufferManagerCommon::DoSetRenderFrameBuffer(const Frame
// This happens a lot, but virtually always it's cleared.
// It's possible the other might not clear, but when every game is reported it's not useful.
if (params.isWritingDepth) {
WARN_LOG(SCEGE, "FBO reusing depthbuffer, %08x/%08x and %08x/%08x", params.fb_address, params.z_address, vfbs_[i]->fb_address, vfbs_[i]->z_address);
WARN_LOG(SCEGE, "FBO reusing depthbuffer, c=%08x/d=%08x and c=%08x/d=%08x", params.fb_address, params.z_address, vfbs_[i]->fb_address, vfbs_[i]->z_address);
sharingReported = true;
}
}
@ -412,7 +412,7 @@ VirtualFramebuffer *FramebufferManagerCommon::DoSetRenderFrameBuffer(const Frame
// We already have it!
} else if (vfb != currentRenderVfb_) {
// Use it as a render target.
DEBUG_LOG(FRAMEBUF, "Switching render target to FBO for %08x: %i x %i x %i ", vfb->fb_address, vfb->width, vfb->height, vfb->format);
DEBUG_LOG(FRAMEBUF, "Switching render target to FBO for %08x: %d x %d x %d ", vfb->fb_address, vfb->width, vfb->height, vfb->format);
vfb->usageFlags |= FB_USAGE_RENDERTARGET;
vfb->last_frame_render = gpuStats.numFlips;
frameLastFramebufUsed_ = gpuStats.numFlips;

View file

@ -1439,13 +1439,15 @@ void EmuScreen::render() {
return;
}
// Freeze-frame functionality (loads a savestate on every frame).
if (PSP_CoreParameter().freezeNext) {
PSP_CoreParameter().frozen = true;
PSP_CoreParameter().freezeNext = false;
SaveState::SaveToRam(freezeState_);
} else if (PSP_CoreParameter().frozen) {
if (CChunkFileReader::ERROR_NONE != SaveState::LoadFromRam(freezeState_)) {
ERROR_LOG(SAVESTATE, "Failed to load freeze state. Unfreezing.");
std::string errorString;
if (CChunkFileReader::ERROR_NONE != SaveState::LoadFromRam(freezeState_, &errorString)) {
ERROR_LOG(SAVESTATE, "Failed to load freeze state (%s). Unfreezing.", errorString.c_str());
PSP_CoreParameter().frozen = false;
}
}
@ -1503,23 +1505,6 @@ void EmuScreen::render() {
screenManager()->getUIContext()->BeginFrame();
renderUI();
}
// We have no use for backbuffer depth or stencil, so let tiled renderers discard them after tiling.
/*
if (gl_extensions.GLES3 && glInvalidateFramebuffer != nullptr) {
GLenum attachments[2] = { GL_DEPTH, GL_STENCIL };
glInvalidateFramebuffer(GL_FRAMEBUFFER, 2, attachments);
} else if (!gl_extensions.GLES3) {
#ifdef USING_GLES2
// Tiled renderers like PowerVR should benefit greatly from this. However - seems I can't call it?
bool hasDiscard = gl_extensions.EXT_discard_framebuffer; // TODO
if (hasDiscard) {
//const GLenum targets[3] = { GL_COLOR_EXT, GL_DEPTH_EXT, GL_STENCIL_EXT };
//glDiscardFramebufferEXT(GL_FRAMEBUFFER, 3, targets);
}
#endif
}
*/
}
bool EmuScreen::hasVisibleUI() {

View file

@ -58,10 +58,10 @@ void CreateImage(VulkanContext *vulkan, VkCommandBuffer cmd, VKRImage &img, int
vulkan->MemoryTypeFromProperties(memreq.memoryTypeBits, VK_MEMORY_PROPERTY_DEVICE_LOCAL_BIT, &alloc.memoryTypeIndex);
VkResult res = vkAllocateMemory(vulkan->GetDevice(), &alloc, nullptr, &img.memory);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
res = vkBindImageMemory(vulkan->GetDevice(), img.image, img.memory, 0);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
VkImageAspectFlags aspects = color ? VK_IMAGE_ASPECT_COLOR_BIT : (VK_IMAGE_ASPECT_DEPTH_BIT | VK_IMAGE_ASPECT_STENCIL_BIT);
@ -435,7 +435,7 @@ void VulkanRenderManager::BeginFrame(bool enableProfiling) {
renderStepOffset_ = 0;
frameData.profile.timestampDescriptions.clear();
if (frameData_->profilingEnabled_) {
if (frameData.profilingEnabled_) {
// For various reasons, we need to always use an init cmd buffer in this case to perform the vkCmdResetQueryPool,
// unless we want to limit ourselves to only measure the main cmd buffer.
// Reserve the first two queries for initCmd.
@ -466,7 +466,7 @@ VkCommandBuffer VulkanRenderManager::GetInitCmd() {
}
void VulkanRenderManager::BindFramebufferAsRenderTarget(VKRFramebuffer *fb, VKRRenderPassAction color, VKRRenderPassAction depth, VKRRenderPassAction stencil, uint32_t clearColor, float clearDepth, uint8_t clearStencil, const char *tag) {
assert(insideFrame_);
_dbg_assert_(insideFrame_);
// Eliminate dupes, instantly convert to a clear if possible.
if (!steps_.empty() && steps_.back()->stepType == VKRStepType::RENDER && steps_.back()->render.framebuffer == fb) {
u32 clearMask = 0;
@ -581,7 +581,7 @@ void VulkanRenderManager::BindFramebufferAsRenderTarget(VKRFramebuffer *fb, VKRR
}
bool VulkanRenderManager::CopyFramebufferToMemorySync(VKRFramebuffer *src, int aspectBits, int x, int y, int w, int h, Draw::DataFormat destFormat, uint8_t *pixels, int pixelStride, const char *tag) {
assert(insideFrame_);
_dbg_assert_(insideFrame_);
for (int i = (int)steps_.size() - 1; i >= 0; i--) {
if (steps_[i]->stepType == VKRStepType::RENDER && steps_[i]->render.framebuffer == src) {
steps_[i]->render.numReads++;
@ -643,7 +643,7 @@ bool VulkanRenderManager::CopyFramebufferToMemorySync(VKRFramebuffer *src, int a
}
void VulkanRenderManager::CopyImageToMemorySync(VkImage image, int mipLevel, int x, int y, int w, int h, Draw::DataFormat destFormat, uint8_t *pixels, int pixelStride, const char *tag) {
assert(insideFrame_);
_dbg_assert_(insideFrame_);
VKRStep *step = new VKRStep{ VKRStepType::READBACK_IMAGE };
step->readback_image.image = image;
step->readback_image.srcRect.offset = { x, y };
@ -679,7 +679,7 @@ bool VulkanRenderManager::InitBackbufferFramebuffers(int width, int height) {
for (uint32_t i = 0; i < swapchainImageCount_; i++) {
attachments[0] = swapchainImages_[i].view;
res = vkCreateFramebuffer(vulkan_->GetDevice(), &fb_info, nullptr, &framebuffers_[i]);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
if (res != VK_SUCCESS) {
framebuffers_.clear();
return false;
@ -714,7 +714,7 @@ bool VulkanRenderManager::InitDepthStencilBuffer(VkCommandBuffer cmd) {
VkDevice device = vulkan_->GetDevice();
res = vkCreateImage(device, &image_info, nullptr, &depth_.image);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
if (res != VK_SUCCESS)
return false;
@ -736,17 +736,17 @@ bool VulkanRenderManager::InitDepthStencilBuffer(VkCommandBuffer cmd) {
pass = vulkan_->MemoryTypeFromProperties(mem_reqs.memoryTypeBits,
0, /* No requirements */
&mem_alloc.memoryTypeIndex);
assert(pass);
_dbg_assert_(pass);
if (!pass)
return false;
res = vkAllocateMemory(device, &mem_alloc, NULL, &depth_.mem);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
if (res != VK_SUCCESS)
return false;
res = vkBindImageMemory(device, depth_.image, depth_.mem, 0);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
if (res != VK_SUCCESS)
return false;
@ -772,7 +772,7 @@ bool VulkanRenderManager::InitDepthStencilBuffer(VkCommandBuffer cmd) {
depth_view_info.flags = 0;
res = vkCreateImageView(device, &depth_view_info, NULL, &depth_.view);
assert(res == VK_SUCCESS);
_dbg_assert_(res == VK_SUCCESS);
if (res != VK_SUCCESS)
return false;
@ -1076,7 +1076,6 @@ void VulkanRenderManager::Submit(int frame, bool triggerFrameFence) {
int numCmdBufs = 0;
if (frameData.hasInitCommands) {
cmdBufs[numCmdBufs++] = frameData.initCmd;
frameData.hasInitCommands = false;
if (splitSubmit_) {
// Send the init commands off separately. Used this once to confirm that the cause of a device loss was in the init cmdbuf.
VkSubmitInfo submit_info{ VK_STRUCTURE_TYPE_SUBMIT_INFO };
@ -1120,6 +1119,8 @@ void VulkanRenderManager::Submit(int frame, bool triggerFrameFence) {
frameData.readyForFence = true;
frameData.push_condVar.notify_all();
}
frameData.hasInitCommands = false;
}
void VulkanRenderManager::EndSubmitFrame(int frame) {
@ -1177,7 +1178,7 @@ void VulkanRenderManager::Run(int frame) {
break;
default:
assert(false);
_dbg_assert_(false);
}
VLOG("PULL: Finished running frame %d", frame);
@ -1229,7 +1230,7 @@ void VulkanRenderManager::FlushSync() {
frameData.steps = std::move(steps_);
steps_.clear();
frameData.readyForRun = true;
assert(frameData.readyForFence == false);
_dbg_assert_(!frameData.readyForFence);
frameData.type = VKRRunType::SYNC;
frameData.pull_condVar.notify_all();
}

View file

@ -820,7 +820,8 @@ bool retro_unserialize(const void *data, size_t size)
if (useEmuThread)
EmuThreadPause(); // Does nothing if already paused
retVal = CChunkFileReader::LoadPtr((u8 *)data, state)
std::string errorString;
retVal = CChunkFileReader::LoadPtr((u8 *)data, state, &errorString)
== CChunkFileReader::ERROR_NONE;
if (useEmuThread)