Merge pull request #13296 from hrydgard/log-improvements

Log improvements

Common/Vulkan/VulkanLoader.cpp

@@ -476,7 +476,7 @@ bool VulkanLoad() {
 	LOAD_GLOBAL_FUNC(vkEnumerateInstanceLayerProperties);
 
 	if (vkCreateInstance && vkGetInstanceProcAddr && vkGetDeviceProcAddr && vkEnumerateInstanceExtensionProperties && vkEnumerateInstanceLayerProperties) {
-		WARN_LOG(G3D, "VulkanLoad: Base functions loaded.");
+		INFO_LOG(G3D, "VulkanLoad: Base functions loaded.");
 		return true;
 	} else {
 		ERROR_LOG(G3D, "VulkanLoad: Failed to load Vulkan base functions.");
@@ -549,14 +549,14 @@ void VulkanLoadInstanceFunctions(VkInstance instance, const VulkanExtensions &en
 		LOAD_INSTANCE_FUNC(instance, vkSetDebugUtilsObjectTagEXT);
 	}
 
-	WARN_LOG(G3D, "Vulkan instance functions loaded.");
+	INFO_LOG(G3D, "Vulkan instance functions loaded.");
 }
 
 // On some implementations, loading functions (that have Device as their first parameter) via vkGetDeviceProcAddr may
 // increase performance - but then these function pointers will only work on that specific device. Thus, this loader is not very
 // good for multi-device - not likely we'll ever try that anyway though.
 void VulkanLoadDeviceFunctions(VkDevice device, const VulkanExtensions &enabledExtensions) {
-	WARN_LOG(G3D, "Vulkan device functions loaded.");
+	INFO_LOG(G3D, "Vulkan device functions loaded.");
 
 	LOAD_DEVICE_FUNC(device, vkQueueSubmit);
 	LOAD_DEVICE_FUNC(device, vkQueueWaitIdle);

Core/HLE/HLE.cpp

@@ -875,7 +875,7 @@ void hleDoLogInternal(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u64 res,
 
 	if (reportTag != nullptr) {
 		// A blank string means always log, not just once.
-		if (reportTag[0] == '\0' || Reporting::ShouldLogOnce(reportTag)) {
+		if (reportTag[0] == '\0' || Reporting::ShouldLogNTimes(reportTag, 1)) {
 			// Here we want the original key, so that different args, etc. group together.
 			std::string key = std::string(kernelFlag) + std::string("%08x=") + funcName + "(%s)";
 			if (reason != nullptr)

Core/Reporting.cpp

@@ -63,7 +63,7 @@ namespace Reporting
 	// Temporarily stores a reference to the hostname.
 	static std::string lastHostname;
 	// Keeps track of report-only-once identifiers.  Since they're always constants, a pointer is okay.
-	static std::set<const char *> logOnceUsed;
+	static std::map<const char *, int> logOnceUsed;
 	// Keeps track of whether a harmful setting was ever used.
 	static bool everUnsupported = false;
 	// Support is cached here to avoid checking it on every single request.
@@ -347,10 +347,21 @@ namespace Reporting
 			everUnsupported = true;
 	}
 
-	bool ShouldLogOnce(const char *identifier)
+	bool ShouldLogNTimes(const char *identifier, int count)
 	{
 		// True if it wasn't there already -> so yes, log.
-		return logOnceUsed.insert(identifier).second;
+		auto iter = logOnceUsed.find(identifier);
+		if (iter == logOnceUsed.end()) {
+			logOnceUsed.insert(std::pair<const char*, int>(identifier, 1));
+			return true;
+		} else {
+			if (iter->second >= count) {
+				return false;
+			} else {
+				iter->second++;
+				return true;
+			}
+		}
 	}
 
 	std::string CurrentGameID()

Core/Reporting.h

@@ -17,27 +17,33 @@
 
 #pragma once
 
-#include "Common/CommonTypes.h"
-#include "Common/Log.h"
 #include <string>
 #include <vector>
 
+#include "Common/CommonTypes.h"
+#include "Common/Log.h"
+
 #define DEBUG_LOG_REPORT(t,...)   do { DEBUG_LOG(t, __VA_ARGS__);  Reporting::ReportMessage(__VA_ARGS__); } while (false)
 #define ERROR_LOG_REPORT(t,...)   do { ERROR_LOG(t, __VA_ARGS__);  Reporting::ReportMessage(__VA_ARGS__); } while (false)
 #define WARN_LOG_REPORT(t,...)    do { WARN_LOG(t, __VA_ARGS__);   Reporting::ReportMessage(__VA_ARGS__); } while (false)
 #define NOTICE_LOG_REPORT(t,...)  do { NOTICE_LOG(t, __VA_ARGS__); Reporting::ReportMessage(__VA_ARGS__); } while (false)
 #define INFO_LOG_REPORT(t,...)    do { INFO_LOG(t, __VA_ARGS__);   Reporting::ReportMessage(__VA_ARGS__); } while (false)
 
-#define DEBUG_LOG_REPORT_ONCE(n,t,...)   do { if (Reporting::ShouldLogOnce(#n)) { DEBUG_LOG_REPORT(t, __VA_ARGS__); } } while (false)
-#define ERROR_LOG_REPORT_ONCE(n,t,...)   do { if (Reporting::ShouldLogOnce(#n)) { ERROR_LOG_REPORT(t, __VA_ARGS__); } } while (false)
-#define WARN_LOG_REPORT_ONCE(n,t,...)    do { if (Reporting::ShouldLogOnce(#n)) { WARN_LOG_REPORT(t, __VA_ARGS__); } } while (false)
-#define NOTICE_LOG_REPORT_ONCE(n,t,...)  do { if (Reporting::ShouldLogOnce(#n)) { NOTICE_LOG_REPORT(t, __VA_ARGS__); } } while (false)
-#define INFO_LOG_REPORT_ONCE(n,t,...)    do { if (Reporting::ShouldLogOnce(#n)) { INFO_LOG_REPORT(t, __VA_ARGS__); } } while (false)
+#define DEBUG_LOG_REPORT_ONCE(n,t,...)   do { if (Reporting::ShouldLogNTimes(#n, 1)) { DEBUG_LOG_REPORT(t, __VA_ARGS__); } } while (false)
+#define ERROR_LOG_REPORT_ONCE(n,t,...)   do { if (Reporting::ShouldLogNTimes(#n, 1)) { ERROR_LOG_REPORT(t, __VA_ARGS__); } } while (false)
+#define WARN_LOG_REPORT_ONCE(n,t,...)    do { if (Reporting::ShouldLogNTimes(#n, 1)) { WARN_LOG_REPORT(t, __VA_ARGS__); } } while (false)
+#define NOTICE_LOG_REPORT_ONCE(n,t,...)  do { if (Reporting::ShouldLogNTimes(#n, 1)) { NOTICE_LOG_REPORT(t, __VA_ARGS__); } } while (false)
+#define INFO_LOG_REPORT_ONCE(n,t,...)    do { if (Reporting::ShouldLogNTimes(#n, 1)) { INFO_LOG_REPORT(t, __VA_ARGS__); } } while (false)
+
+#define ERROR_LOG_ONCE(n,t,...)   do { if (Reporting::ShouldLogNTimes(#n, 1)) { ERROR_LOG(t, __VA_ARGS__); } } while (false)
+#define WARN_LOG_ONCE(n,t,...)    do { if (Reporting::ShouldLogNTimes(#n, 1)) { WARN_LOG(t, __VA_ARGS__); } } while (false)
+#define NOTICE_LOG_ONCE(n,t,...)  do { if (Reporting::ShouldLogNTimes(#n, 1)) { NOTICE_LOG(t, __VA_ARGS__); } } while (false)
+#define INFO_LOG_ONCE(n,t,...)    do { if (Reporting::ShouldLogNTimes(#n, 1)) { INFO_LOG(t, __VA_ARGS__); } } while (false)
 
-#define ERROR_LOG_ONCE(n,t,...)   do { if (Reporting::ShouldLogOnce(#n)) { ERROR_LOG(t, __VA_ARGS__); } } while (false)
-#define WARN_LOG_ONCE(n,t,...)    do { if (Reporting::ShouldLogOnce(#n)) { WARN_LOG(t, __VA_ARGS__); } } while (false)
-#define NOTICE_LOG_ONCE(n,t,...)  do { if (Reporting::ShouldLogOnce(#n)) { NOTICE_LOG(t, __VA_ARGS__); } } while (false)
-#define INFO_LOG_ONCE(n,t,...)    do { if (Reporting::ShouldLogOnce(#n)) { INFO_LOG(t, __VA_ARGS__); } } while (false)
+#define ERROR_LOG_N_TIMES(s,n,t,...)   do { if (Reporting::ShouldLogNTimes(#s, n)) { ERROR_LOG(t, __VA_ARGS__); } } while (false)
+#define WARN_LOG_N_TIMES(s,n,t,...)    do { if (Reporting::ShouldLogNTimes(#s, n)) { WARN_LOG(t, __VA_ARGS__); } } while (false)
+#define NOTICE_LOG_N_TIMES(s,n,t,...)  do { if (Reporting::ShouldLogNTimes(#s, n)) { NOTICE_LOG(t, __VA_ARGS__); } } while (false)
+#define INFO_LOG_N_TIMES(s,n,t,...)    do { if (Reporting::ShouldLogNTimes(#s, n)) { INFO_LOG(t, __VA_ARGS__); } } while (false)
 
 class PointerWrap;
 
@@ -79,7 +85,7 @@ namespace Reporting
 	std::vector<std::string> CompatibilitySuggestions();
 
 	// Returns true if that identifier has not been logged yet.
-	bool ShouldLogOnce(const char *identifier);
+	bool ShouldLogNTimes(const char *identifier, int n);
 
 	enum class ReportStatus {
 		WORKING,

GPU/Common/FramebufferManagerCommon.cpp

@@ -1086,7 +1086,7 @@ void FramebufferManagerCommon::ResizeFramebufFBO(VirtualFramebuffer *vfb, int w,
 	}
 
 	if (!vfb->fbo) {
-		ERROR_LOG(FRAMEBUF, "Error creating FBO! %i x %i", vfb->renderWidth, vfb->renderHeight);
+		ERROR_LOG(FRAMEBUF, "Error creating FBO during resize! %d x %d", vfb->renderWidth, vfb->renderHeight);
 		vfb->last_frame_failed = gpuStats.numFlips;
 	}
 }
@@ -1431,7 +1431,7 @@ bool FramebufferManagerCommon::CreateDownloadTempBuffer(VirtualFramebuffer *nvfb
 	snprintf(name, sizeof(name), "download_temp");
 	nvfb->fbo = draw_->CreateFramebuffer({ nvfb->bufferWidth, nvfb->bufferHeight, 1, 1, false, (Draw::FBColorDepth)nvfb->colorDepth, name });
 	if (!nvfb->fbo) {
-		ERROR_LOG(FRAMEBUF, "Error creating GL FBO! %i x %i", nvfb->renderWidth, nvfb->renderHeight);
+		ERROR_LOG(FRAMEBUF, "Error creating FBO! %d x %d", nvfb->renderWidth, nvfb->renderHeight);
 		return false;
 	}
 	return true;
@@ -1566,7 +1566,10 @@ bool FramebufferManagerCommon::NotifyBlockTransferBefore(u32 dstBasePtr, int dst
 	if (dstBuffer && srcBuffer) {
 		if (srcBuffer == dstBuffer) {
 			if (srcX != dstX || srcY != dstY) {
-				WARN_LOG_ONCE(dstsrc, G3D, "Intra-buffer block transfer %08x -> %08x (%dx%d %dbpp)", srcBasePtr, dstBasePtr, width, height, bpp);
+				WARN_LOG_N_TIMES(dstsrc, 100, G3D, "Intra-buffer block transfer %08x (x:%d y:%d stride:%d) -> %08x (x:%d y:%d stride:%d) (%dx%d %dbpp)",
+					srcBasePtr, srcX, srcY, srcStride,
+					dstBasePtr, dstX, dstY, dstStride,
+					width, height, bpp);
 				FlushBeforeCopy();
 				BlitFramebuffer(dstBuffer, dstX, dstY, srcBuffer, srcX, srcY, dstWidth, dstHeight, bpp);
 				RebindFramebuffer("rebind after intra block transfer");
@@ -1577,7 +1580,10 @@ bool FramebufferManagerCommon::NotifyBlockTransferBefore(u32 dstBasePtr, int dst
 				return true;
 			}
 		} else {
-			WARN_LOG_ONCE(dstnotsrc, G3D, "Inter-buffer block transfer %08x -> %08x (%dx%d %dbpp)", srcBasePtr, dstBasePtr, width, height, bpp);
+			WARN_LOG_N_TIMES(dstnotsrc, 100, G3D, "Inter-buffer block transfer  %08x (x:%d y:%d stride:%d) -> %08x (x:%d y:%d stride:%d) (%dx%d %dbpp)",
+				srcBasePtr, srcX, srcY, srcStride,
+				dstBasePtr, dstX, dstY, dstStride,
+				width, height, bpp);
 			// Just do the blit!
 			FlushBeforeCopy();
 			BlitFramebuffer(dstBuffer, dstX, dstY, srcBuffer, srcX, srcY, dstWidth, dstHeight, bpp);
@@ -1590,7 +1596,10 @@ bool FramebufferManagerCommon::NotifyBlockTransferBefore(u32 dstBasePtr, int dst
 		// Here we should just draw the pixels into the buffer.  Copy first.
 		return false;
 	} else if (srcBuffer) {
-		WARN_LOG_ONCE(btd, G3D, "Block transfer download %08x -> %08x (%dx%d %dbpp)", srcBasePtr, dstBasePtr, width, height, bpp);
+		WARN_LOG_N_TIMES(btd, 100, G3D, "Block transfer readback %08x (x:%d y:%d stride:%d) -> %08x (x:%d y:%d stride:%d) (%dx%d %dbpp)",
+			srcBasePtr, srcX, srcY, srcStride,
+			dstBasePtr, dstX, dstY, dstStride,
+			width, height, bpp);
 		FlushBeforeCopy();
 		if (g_Config.bBlockTransferGPU && !srcBuffer->memoryUpdated) {
 			const int srcBpp = srcBuffer->format == GE_FORMAT_8888 ? 4 : 2;
@@ -1599,8 +1608,9 @@ bool FramebufferManagerCommon::NotifyBlockTransferBefore(u32 dstBasePtr, int dst
 			if (srcHeight <= 0 || (tooTall && srcY != 0)) {
 				WARN_LOG_ONCE(btdheight, G3D, "Block transfer download %08x -> %08x skipped, %d+%d is taller than %d", srcBasePtr, dstBasePtr, srcY, srcHeight, srcBuffer->bufferHeight);
 			} else {
-				if (tooTall)
+				if (tooTall) {
 					WARN_LOG_ONCE(btdheight, G3D, "Block transfer download %08x -> %08x dangerous, %d+%d is taller than %d", srcBasePtr, dstBasePtr, srcY, srcHeight, srcBuffer->bufferHeight);
+				}
 				ReadFramebufferToMemory(srcBuffer, static_cast<int>(srcX * srcXFactor), srcY, static_cast<int>(srcWidth * srcXFactor), srcHeight);
 				srcBuffer->usageFlags = (srcBuffer->usageFlags | FB_USAGE_DOWNLOAD) & ~FB_USAGE_DOWNLOAD_CLEAR;
 			}

UI/NativeApp.cpp

@@ -373,7 +373,7 @@ void CreateDirectoriesAndroid() {
 static void CheckFailedGPUBackends() {
 #ifdef _DEBUG
 	// If you're in debug mode, you probably don't want a fallback. If you're in release mode, use IGNORE below.
-	WARN_LOG(LOADER, "Not checking for failed graphics backends in debug mode");
+	NOTICE_LOG(LOADER, "Not checking for failed graphics backends in debug mode");
 	return;
 #endif