Merge pull request #16357 from hrydgard/pipeline-creation-error-handling

Vulkan: Better pipeline creation error handling

Common/GPU/Vulkan/VulkanLoader.cpp

@@ -727,6 +727,7 @@ void VulkanFree() {
 }
 
 const char *VulkanResultToString(VkResult res) {
+	static char temp[128]{};
 	switch (res) {
 	case VK_NOT_READY: return "VK_NOT_READY";
 	case VK_TIMEOUT: return "VK_TIMEOUT";
@@ -749,10 +750,25 @@ const char *VulkanResultToString(VkResult res) {
 	case VK_ERROR_OUT_OF_DATE_KHR: return "VK_ERROR_OUT_OF_DATE_KHR";
 	case VK_ERROR_INCOMPATIBLE_DISPLAY_KHR: return "VK_ERROR_INCOMPATIBLE_DISPLAY_KHR";
 	case VK_ERROR_NATIVE_WINDOW_IN_USE_KHR: return "VK_ERROR_NATIVE_WINDOW_IN_USE_KHR";
-	case VK_ERROR_OUT_OF_POOL_MEMORY_KHR: return "VK_ERROR_OUT_OF_POOL_MEMORY_KHR";
-	case VK_ERROR_INVALID_EXTERNAL_HANDLE_KHR: return "VK_ERROR_INVALID_EXTERNAL_HANDLE_KHR";
-
+	case VK_ERROR_OUT_OF_POOL_MEMORY: return "VK_ERROR_OUT_OF_POOL_MEMORY_KHR";
+	case VK_ERROR_INVALID_EXTERNAL_HANDLE: return "VK_ERROR_INVALID_EXTERNAL_HANDLE_KHR";
+	case VK_ERROR_FRAGMENTED_POOL: return "VK_ERROR_FRAGMENTED_POOL";
+	case VK_ERROR_UNKNOWN: return "VK_ERROR_UNKNOWN (-13)";
+	case VK_ERROR_FRAGMENTATION: return "VK_ERROR_FRAGMENTATION";
+	case VK_ERROR_INVALID_OPAQUE_CAPTURE_ADDRESS: return "VK_ERROR_INVALID_OPAQUE_CAPTURE_ADDRESS";
+	case VK_PIPELINE_COMPILE_REQUIRED: return "VK_PIPELINE_COMPILE_REQUIRED";
+	case VK_ERROR_VALIDATION_FAILED_EXT: return "VK_ERROR_VALIDATION_FAILED_EXT";
+	case VK_ERROR_INVALID_SHADER_NV: return "VK_ERROR_INVALID_SHADER_NV";
+	case VK_ERROR_INVALID_DRM_FORMAT_MODIFIER_PLANE_LAYOUT_EXT: return "VK_ERROR_INVALID_DRM_FORMAT_MODIFIER_PLANE_LAYOUT_EXT";
+	case VK_ERROR_NOT_PERMITTED_KHR: return "VK_ERROR_NOT_PERMITTED_KHR";
+	case VK_ERROR_FULL_SCREEN_EXCLUSIVE_MODE_LOST_EXT: return "VK_ERROR_FULL_SCREEN_EXCLUSIVE_MODE_LOST_EXT";
+	case VK_THREAD_IDLE_KHR: return "VK_THREAD_IDLE_KHR";
+	case VK_THREAD_DONE_KHR: return "VK_THREAD_DONE_KHR";
+	case VK_OPERATION_DEFERRED_KHR: return "VK_OPERATION_DEFERRED_KHR";
+	case VK_OPERATION_NOT_DEFERRED_KHR: return "VK_OPERATION_NOT_DEFERRED_KHR";
 	default:
-		return "VK_ERROR_...(unknown)";
+		// This isn't thread safe, but this should be rare, and at worst, we'll get a jumble of two messages.
+		snprintf(temp, sizeof(temp), "VK_ERROR_???: 0x%08x", (u32)res);
+		return temp;
 	}
 }

Common/GPU/Vulkan/VulkanQueueRunner.cpp

@@ -1443,6 +1443,8 @@ void VulkanQueueRunner::PerformRenderPass(const VKRStep &step, VkCommandBuffer c
 	VkPipeline lastPipeline = VK_NULL_HANDLE;
 	VkPipelineLayout pipelineLayout = VK_NULL_HANDLE;
 
+	bool pipelineOK = false;
+
 	int lastStencilWriteMask = -1;
 	int lastStencilCompareMask = -1;
 	int lastStencilReference = -1;
@@ -1474,11 +1476,15 @@ void VulkanQueueRunner::PerformRenderPass(const VKRStep &step, VkCommandBuffer c
 					vkCmdBindPipeline(cmd, VK_PIPELINE_BIND_POINT_GRAPHICS, pipeline);
 					pipelineLayout = c.pipeline.pipelineLayout;
 					lastGraphicsPipeline = graphicsPipeline;
-					// Reset dynamic state so it gets refreshed with the new pipeline.
-					lastStencilWriteMask = -1;
-					lastStencilCompareMask = -1;
-					lastStencilReference = -1;
+					pipelineOK = true;
+				} else {
+					pipelineOK = false;
 				}
+
+				// Reset dynamic state so it gets refreshed with the new pipeline.
+				lastStencilWriteMask = -1;
+				lastStencilCompareMask = -1;
+				lastStencilReference = -1;
 			}
 			break;
 		}
@@ -1550,7 +1556,9 @@ void VulkanQueueRunner::PerformRenderPass(const VKRStep &step, VkCommandBuffer c
 		}
 
 		case VKRRenderCommand::PUSH_CONSTANTS:
-			vkCmdPushConstants(cmd, pipelineLayout, c.push.stages, c.push.offset, c.push.size, c.push.data);
+			if (pipelineOK) {
+				vkCmdPushConstants(cmd, pipelineLayout, c.push.stages, c.push.offset, c.push.size, c.push.data);
+			}
 			break;
 
 		case VKRRenderCommand::STENCIL:
@@ -1569,21 +1577,23 @@ void VulkanQueueRunner::PerformRenderPass(const VKRStep &step, VkCommandBuffer c
 			break;
 
 		case VKRRenderCommand::DRAW_INDEXED:
-		{
-			vkCmdBindDescriptorSets(cmd, VK_PIPELINE_BIND_POINT_GRAPHICS, pipelineLayout, 1, 1, &c.drawIndexed.ds, c.drawIndexed.numUboOffsets, c.drawIndexed.uboOffsets);
-			vkCmdBindIndexBuffer(cmd, c.drawIndexed.ibuffer, c.drawIndexed.ioffset, (VkIndexType)c.drawIndexed.indexType);
-			VkDeviceSize voffset = c.drawIndexed.voffset;
-			vkCmdBindVertexBuffers(cmd, 0, 1, &c.drawIndexed.vbuffer, &voffset);
-			vkCmdDrawIndexed(cmd, c.drawIndexed.count, c.drawIndexed.instances, 0, 0, 0);
+			if (pipelineOK) {
+				vkCmdBindDescriptorSets(cmd, VK_PIPELINE_BIND_POINT_GRAPHICS, pipelineLayout, 1, 1, &c.drawIndexed.ds, c.drawIndexed.numUboOffsets, c.drawIndexed.uboOffsets);
+				vkCmdBindIndexBuffer(cmd, c.drawIndexed.ibuffer, c.drawIndexed.ioffset, (VkIndexType)c.drawIndexed.indexType);
+				VkDeviceSize voffset = c.drawIndexed.voffset;
+				vkCmdBindVertexBuffers(cmd, 0, 1, &c.drawIndexed.vbuffer, &voffset);
+				vkCmdDrawIndexed(cmd, c.drawIndexed.count, c.drawIndexed.instances, 0, 0, 0);
+			}
 			break;
-		}
 
 		case VKRRenderCommand::DRAW:
-			vkCmdBindDescriptorSets(cmd, VK_PIPELINE_BIND_POINT_GRAPHICS, pipelineLayout, 1, 1, &c.draw.ds, c.draw.numUboOffsets, c.draw.uboOffsets);
-			if (c.draw.vbuffer) {
-				vkCmdBindVertexBuffers(cmd, 0, 1, &c.draw.vbuffer, &c.draw.voffset);
+			if (pipelineOK) {
+				vkCmdBindDescriptorSets(cmd, VK_PIPELINE_BIND_POINT_GRAPHICS, pipelineLayout, 1, 1, &c.draw.ds, c.draw.numUboOffsets, c.draw.uboOffsets);
+				if (c.draw.vbuffer) {
+					vkCmdBindVertexBuffers(cmd, 0, 1, &c.draw.vbuffer, &c.draw.voffset);
+				}
+				vkCmdDraw(cmd, c.draw.count, 1, c.draw.offset, 0);
 			}
-			vkCmdDraw(cmd, c.draw.count, 1, c.draw.offset, 0);
 			break;
 
 		case VKRRenderCommand::CLEAR:

Common/GPU/Vulkan/VulkanRenderManager.cpp

@@ -94,10 +94,13 @@ bool VKRGraphicsPipeline::Create(VulkanContext *vulkan, VkRenderPass compatibleR
 		//
 		// At least create a null placeholder to avoid creating over and over if something is broken.
 		pipeline[(size_t)rpType]->Post(VK_NULL_HANDLE);
+		ERROR_LOG(G3D, "Failed creating graphics pipeline! VK_INCOMPLETE");
+		LogCreationFailure();
 		success = false;
 	} else if (result != VK_SUCCESS) {
 		pipeline[(size_t)rpType]->Post(VK_NULL_HANDLE);
 		ERROR_LOG(G3D, "Failed creating graphics pipeline! result='%s'", VulkanResultToString(result));
+		LogCreationFailure();
 		success = false;
 	} else {
 		// Success!
@@ -112,10 +115,13 @@ bool VKRGraphicsPipeline::Create(VulkanContext *vulkan, VkRenderPass compatibleR
 
 void VKRGraphicsPipeline::QueueForDeletion(VulkanContext *vulkan) {
 	for (size_t i = 0; i < (size_t)RenderPassType::TYPE_COUNT; i++) {
-		if (!pipeline[i])
+		if (!this->pipeline[i])
 			continue;
 		VkPipeline pipeline = this->pipeline[i]->BlockUntilReady();
-		vulkan->Delete().QueueDeletePipeline(pipeline);
+		// pipeline can be nullptr here, if it failed to compile before.
+		if (pipeline) {
+			vulkan->Delete().QueueDeletePipeline(pipeline);
+		}
 	}
 	vulkan->Delete().QueueCallback([](void *p) {
 		VKRGraphicsPipeline *pipeline = (VKRGraphicsPipeline *)p;
@@ -133,6 +139,16 @@ u32 VKRGraphicsPipeline::GetVariantsBitmask() const {
 	return bitmask;
 }
 
+void VKRGraphicsPipeline::LogCreationFailure() const {
+	ERROR_LOG(G3D, "vs: %s\n[END VS]", desc->vertexShaderSource.c_str());
+	ERROR_LOG(G3D, "fs: %s\n[END FS]", desc->fragmentShaderSource.c_str());
+	if (desc->geometryShader) {
+		ERROR_LOG(G3D, "gs: %s\n[END GS]", desc->geometryShaderSource.c_str());
+	}
+	// TODO: Maybe log various other state?
+	ERROR_LOG(G3D, "======== END OF PIPELINE ==========");
+}
+
 bool VKRComputePipeline::Create(VulkanContext *vulkan) {
 	if (!desc) {
 		// Already failed to create this one.

Common/GPU/Vulkan/VulkanRenderManager.h

@@ -145,6 +145,12 @@ struct VKRGraphicsPipelineDesc {
 	Promise<VkShaderModule> *fragmentShader = nullptr;
 	Promise<VkShaderModule> *geometryShader = nullptr;
 
+	// These are for pipeline creation failure logging.
+	// TODO: Store pointers to the string instead? Feels iffy but will probably work.
+	std::string vertexShaderSource;
+	std::string fragmentShaderSource;
+	std::string geometryShaderSource;
+
 	VkPipelineInputAssemblyStateCreateInfo inputAssembly{ VK_STRUCTURE_TYPE_PIPELINE_INPUT_ASSEMBLY_STATE_CREATE_INFO };
 	VkVertexInputAttributeDescription attrs[8]{};
 	VkVertexInputBindingDescription ibd{};
@@ -179,6 +185,8 @@ struct VKRGraphicsPipeline {
 
 	u32 GetVariantsBitmask() const;
 
+	void LogCreationFailure() const;
+
 	VKRGraphicsPipelineDesc *desc = nullptr;  // not owned!
 	Promise<VkPipeline> *pipeline[(size_t)RenderPassType::TYPE_COUNT]{};
 	std::string tag;

Common/LogManager.cpp

@@ -56,7 +56,7 @@ void GenericLog(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, const char
 	if (instance) {
 		instance->Log(level, type, file, line, fmt, args);
 	} else {
-		// Fall back to printf if we're before the log manager has been initialized.
+		// Fall back to printf or direct android logger with a small buffer if the log manager hasn't been initialized yet.
 #if PPSSPP_PLATFORM(ANDROID)
 		char temp[512];
 		vsnprintf(temp, sizeof(temp), fmt, args);

Common/Thread/Channel.h

@@ -20,18 +20,19 @@ struct Mailbox {
 	std::mutex mutex_;
 	std::condition_variable condvar_;
 	T data_{};
+	bool dataReceived_ = false;
 
 	T Wait() {
 		std::unique_lock<std::mutex> lock(mutex_);
-		while (!data_) {
+		while (!dataReceived_) {
 			condvar_.wait(lock);
 		}
 		return data_;
 	}
 
 	bool Poll(T *data) {
 		std::unique_lock<std::mutex> lock(mutex_);
-		if (data_) {
+		if (dataReceived_) {
 			*data = data_;
 			return true;
 		} else {
@@ -41,8 +42,9 @@ struct Mailbox {
 
 	bool Send(T data) {
 		std::unique_lock<std::mutex> lock(mutex_);
-		if (!data_) {
+		if (!dataReceived_) {
 			data_ = data;
+			dataReceived_ = true;
 			condvar_.notify_all();
 			return true;
 		} else {

Common/Thread/Promise.h

@@ -107,7 +107,7 @@ class Promise {
 		}
 	}
 
-	// For outside injection of data, when not using Spawn
+	// For outside injection of data, when not using Spawn.
 	void Post(T data) {
 		rx_->Send(data);
 	}

Common/VR/VRBase.h

@@ -18,7 +18,7 @@
 
 #if defined(_DEBUG) && (defined(XR_USE_GRAPHICS_API_OPENGL) || defined(XR_USE_GRAPHICS_API_OPENGL_ES))
 
-void GLCheckErrors(char* file, int line);
+void GLCheckErrors(const char* file, int line);
 
 #define GL(func) func; GLCheckErrors(__FILE__ , __LINE__);
 #else

Common/VR/VRFramebuffer.cpp

@@ -71,7 +71,7 @@ static const char* GlErrorString(GLenum error) {
 	}
 }
 
-void GLCheckErrors(char* file, int line) {
+void GLCheckErrors(const char* file, int line) {
 	for (int i = 0; i < 10; i++) {
 		const GLenum error = glGetError();
 		if (error == GL_NO_ERROR) {
@@ -86,7 +86,6 @@ void GLCheckErrors(char* file, int line) {
 #if XR_USE_GRAPHICS_API_OPENGL_ES
 
 static bool ovrFramebuffer_CreateGLES(XrSession session, ovrFramebuffer* frameBuffer, int width, int height, bool multiview) {
-
 	frameBuffer->Width = width;
 	frameBuffer->Height = height;
 

GPU/Common/FragmentShaderGenerator.cpp

@@ -94,6 +94,8 @@ bool GenerateFragmentShader(const FShaderID &id, char *buffer, const ShaderLangu
 	}
 
 	ShaderWriter p(buffer, compat, ShaderStage::Fragment, extensions, flags);
+	p.F("// %s\n", FragmentShaderDesc(id).c_str());
+
 	p.ApplySamplerMetadata(arrayTexture ? samplersStereo : samplersMono);
 
 	bool lmode = id.Bit(FS_BIT_LMODE);

GPU/Common/GeometryShaderGenerator.cpp

@@ -49,6 +49,9 @@ bool GenerateGeometryShader(const GShaderID &id, char *buffer, const ShaderLangu
 	bool clipClampedDepth = gstate_c.Use(GPU_USE_DEPTH_CLAMP);
 
 	ShaderWriter p(buffer, compat, ShaderStage::Geometry, extensions);
+
+	p.F("// %s\n", GeometryShaderDesc(id).c_str());
+
 	p.C("layout(triangles) in;\n");
 	if (clipClampedDepth && vertexRangeCulling && !gstate_c.Use(GPU_USE_CLIP_DISTANCE)) {
 		p.C("layout(triangle_strip, max_vertices = 12) out;\n");

GPU/Common/VertexShaderGenerator.cpp

@@ -168,6 +168,8 @@ bool GenerateVertexShader(const VShaderID &id, char *buffer, const ShaderLanguag
 
 	ShaderWriter p(buffer, compat, ShaderStage::Vertex, extensions);
 
+	p.F("// %s\n", VertexShaderDesc(id).c_str());
+
 	bool isModeThrough = id.Bit(VS_BIT_IS_THROUGH);
 	bool lmode = id.Bit(VS_BIT_LMODE);
 	bool doTexture = id.Bit(VS_BIT_DO_TEXTURE);

GPU/Vulkan/PipelineManagerVulkan.cpp

@@ -256,6 +256,11 @@ static VulkanPipeline *CreateVulkanPipeline(VulkanRenderManager *renderManager,
 	desc->fragmentShader = fs->GetModule();
 	desc->vertexShader = vs->GetModule();
 	desc->geometryShader = gs ? gs->GetModule() : nullptr;
+	desc->fragmentShaderSource = fs->GetShaderString(SHADER_STRING_SOURCE_CODE);
+	desc->vertexShaderSource = vs->GetShaderString(SHADER_STRING_SOURCE_CODE);
+	if (gs) {
+		desc->geometryShaderSource =  gs->GetShaderString(SHADER_STRING_SOURCE_CODE);
+	}
 
 	VkPipelineInputAssemblyStateCreateInfo &inputAssembly = desc->inputAssembly;
 	inputAssembly.flags = 0;

GPU/Vulkan/ShaderManagerVulkan.cpp

@@ -96,7 +96,7 @@ static Promise<VkShaderModule> *CompileShaderModuleAsync(VulkanContext *vulkan,
 		return shaderModule;
 	};
 
-#if defined(_DEBUG) || PPSSPP_PLATFORM(ANDROID)
+#if defined(_DEBUG)
 	// Don't parallelize in debug mode, pathological behavior due to mutex locks in allocator which is HEAVILY used by glslang.
 	return Promise<VkShaderModule>::AlreadyDone(compile());
 #else

android/jni/app-android.cpp

@@ -198,38 +198,44 @@ AndroidGraphicsContext *graphicsContext;
 #define LOG_APP_NAME "PPSSPP"
 #endif
 
-#ifdef _DEBUG
-#define DLOG(...)    __android_log_print(ANDROID_LOG_INFO, LOG_APP_NAME, __VA_ARGS__);
-#else
-#define DLOG(...)
-#endif
-
-#define ILOG(...)    __android_log_print(ANDROID_LOG_INFO, LOG_APP_NAME, __VA_ARGS__);
-#define WLOG(...)    __android_log_print(ANDROID_LOG_WARN, LOG_APP_NAME, __VA_ARGS__);
-#define ELOG(...)    __android_log_print(ANDROID_LOG_ERROR, LOG_APP_NAME, __VA_ARGS__);
-#define FLOG(...)    __android_log_print(ANDROID_LOG_FATAL, LOG_APP_NAME, __VA_ARGS__);
-
 #define MessageBox(a, b, c, d) __android_log_print(ANDROID_LOG_INFO, APP_NAME, "%s %s", (b), (c));
 
 void AndroidLogger::Log(const LogMessage &message) {
-	// Log with simplified headers as Android already provides timestamp etc.
+	int mode;
 	switch (message.level) {
-	case LogTypes::LVERBOSE:
-	case LogTypes::LDEBUG:
-	case LogTypes::LINFO:
-		ILOG("[%s] %s", message.log, message.msg.c_str());
+	case LogTypes::LWARNING:
+		mode = ANDROID_LOG_WARN;
 		break;
 	case LogTypes::LERROR:
-		ELOG("[%s] %s", message.log, message.msg.c_str());
-		break;
-	case LogTypes::LWARNING:
-		WLOG("[%s] %s", message.log, message.msg.c_str());
+		mode = ANDROID_LOG_ERROR;
 		break;
-	case LogTypes::LNOTICE:
 	default:
-		ILOG("[%s] !!! %s", message.log, message.msg.c_str());
+		mode = ANDROID_LOG_INFO;
 		break;
 	}
+
+	// Long log messages need splitting up.
+	// Not sure what the actual limit is (seems to vary), but let's be conservative.
+	const size_t maxLogLength = 512;
+	if (message.msg.length() < maxLogLength) {
+		// Log with simplified headers as Android already provides timestamp etc.
+		__android_log_print(mode, LOG_APP_NAME, "[%s] %s", message.log, message.msg.c_str());
+	} else {
+		std::string msg = message.msg;
+
+		// Ideally we should split at line breaks, but it's at least fairly usable anyway.
+		std::string first_part = msg.substr(0, maxLogLength);
+		__android_log_print(mode, LOG_APP_NAME, "[%s] %s", message.log, first_part.c_str());
+		msg = msg.substr(maxLogLength);
+
+		while (msg.length() > maxLogLength) {
+			std::string first_part = msg.substr(0, maxLogLength);
+			__android_log_print(mode, LOG_APP_NAME, "%s", first_part.c_str());
+			msg = msg.substr(maxLogLength);
+		}
+		// Print the final part.
+		__android_log_print(mode, LOG_APP_NAME, "%s", msg.c_str());
+	}
 }
 
 JNIEnv* getEnv() {