diff --git a/layers/error_message/logging.cpp b/layers/error_message/logging.cpp index 10c0b0c14f5..7bf6a31433c 100644 --- a/layers/error_message/logging.cpp +++ b/layers/error_message/logging.cpp @@ -111,19 +111,26 @@ bool DebugReport::UpdateLogMsgCounts(int32_t vuid_hash) const { } } -bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, const char *msg, const char *text_vuid) const { - bool bail = false; - std::vector queue_labels; - std::vector cmd_buf_labels; +bool DebugReport::LogMessage(VkFlags msg_flags, const LogObjectList &objects, const Location &loc, std::string_view vuid_text, + const std::string &main_message) { + assert(*(vuid_text.data() + vuid_text.size()) == '\0'); - // Convert the info to the VK_EXT_debug_utils format - VkDebugUtilsMessageTypeFlagsEXT msg_type; VkDebugUtilsMessageSeverityFlagsEXT msg_severity; + VkDebugUtilsMessageTypeFlagsEXT msg_type; + + // Convert the info to the VK_EXT_debug_utils format DebugReportFlagsToAnnotFlags(msg_flags, &msg_severity, &msg_type); - if (!(active_msg_severities & msg_severity) || !(active_msg_types & msg_type)) { - return false; // quick check again to make sure user wants these printed + std::unique_lock lock(debug_output_mutex); + // Avoid logging cost if msg is to be ignored + const uint32_t vuid_hash = (vuid_text.empty()) ? 0 : hash_util::VuidHash(vuid_text); + if (!LogMsgEnabled(vuid_hash, msg_severity, msg_type)) { + return false; } + bool bail = false; + std::vector queue_labels; + std::vector cmd_buf_labels; + std::vector object_labels; // Ensures that push_back will not reallocate, thereby providing pointer // stability for pushed strings. @@ -173,12 +180,10 @@ bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, c object_name_infos.push_back(object_name_info); } - const uint32_t message_id_number = text_vuid ? hash_util::VuidHash(text_vuid) : 0U; - VkDebugUtilsMessengerCallbackDataEXT callback_data = vku::InitStructHelper(); callback_data.flags = 0; - callback_data.pMessageIdName = text_vuid; - callback_data.messageIdNumber = vvl_bit_cast(message_id_number); + callback_data.pMessageIdName = vuid_text.data(); + callback_data.messageIdNumber = vvl_bit_cast(vuid_hash); callback_data.pMessage = nullptr; callback_data.queueLabelCount = static_cast(queue_labels.size()); callback_data.pQueueLabels = queue_labels.empty() ? nullptr : queue_labels.data(); @@ -187,10 +192,61 @@ bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, c callback_data.objectCount = static_cast(object_name_infos.size()); callback_data.pObjects = object_name_infos.data(); + std::string full_message = CreateMessageText(msg_flags, loc, object_name_infos, vuid_hash, vuid_text, main_message); + + const auto callback_list = &debug_callback_list; + // We only output to default callbacks if there are no non-default callbacks + bool use_default_callbacks = true; + for (const auto ¤t_callback : *callback_list) { + use_default_callbacks &= current_callback.IsDefault(); + } + +#ifdef VK_USE_PLATFORM_ANDROID_KHR + if (force_default_log_callback) { + use_default_callbacks = true; + } +#endif + + const char *layer_prefix = "Validation"; + for (const auto ¤t_callback : *callback_list) { + // Skip callback if it's a default callback and there are non-default callbacks present + if (current_callback.IsDefault() && !use_default_callbacks) continue; + + // VK_EXT_debug_utils callback + if (current_callback.IsUtils() && (current_callback.debug_utils_msg_flags & msg_severity) && + (current_callback.debug_utils_msg_type & msg_type)) { + callback_data.pMessage = full_message.c_str(); + if (current_callback.debug_utils_callback_function_ptr( + static_cast(msg_severity), msg_type, &callback_data, + current_callback.pUserData)) { + bail = true; + } + } else if (!current_callback.IsUtils() && (current_callback.debug_report_msg_flags & msg_flags)) { + // VK_EXT_debug_report callback (deprecated) + if (object_name_infos.empty()) { + VkDebugUtilsObjectNameInfoEXT null_object_name = {VK_STRUCTURE_TYPE_DEBUG_UTILS_OBJECT_NAME_INFO_EXT, nullptr, + VK_OBJECT_TYPE_UNKNOWN, 0, nullptr}; + // need to have at least one object + object_name_infos.emplace_back(null_object_name); + } + if (current_callback.debug_report_callback_function_ptr( + msg_flags, ConvertCoreObjectToDebugReportObject(object_name_infos[0].objectType), + object_name_infos[0].objectHandle, vuid_hash, 0, layer_prefix, full_message.c_str(), + current_callback.pUserData)) { + bail = true; + } + } + } + return bail; +} + +std::string DebugReport::CreateMessageText(VkFlags msg_flags, const Location &loc, + const std::vector &object_name_infos, + const uint32_t vuid_hash, std::string_view vuid_text, const std::string &main_message) { std::ostringstream oss; #if defined(BUILD_SELF_VVL) - oss << "Self "; + oss << "Self "; // How we know if the error is from Self Validation when debugging GPU-AV #endif if (message_format_settings.display_application_name && !message_format_settings.application_name.empty()) { @@ -212,8 +268,8 @@ bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, c } } - if (text_vuid != nullptr) { - oss << "[ " << text_vuid << " ]"; + if (!vuid_text.empty()) { + oss << "[ " << vuid_text << " ]"; } // User can get these from VkDebugUtilsMessengerCallbackDataEXT::pObjects if desired @@ -240,7 +296,7 @@ bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, c } } - oss << " | MessageID = 0x" << std::hex << message_id_number; + oss << " | MessageID = 0x" << std::hex << vuid_hash; } // Add a new line to seperate everything from the start of the "real" error message @@ -250,53 +306,55 @@ bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, c oss << " "; } - oss << msg; - std::string composite = oss.str(); + oss << loc.Message() << " " << main_message; - const auto callback_list = &debug_callback_list; - // We only output to default callbacks if there are no non-default callbacks - bool use_default_callbacks = true; - for (const auto ¤t_callback : *callback_list) { - use_default_callbacks &= current_callback.IsDefault(); - } + // Append the spec error text to the error message, unless it contains a word treated as special + if ((vuid_text.find("VUID-") != std::string::npos)) { + // Linear search makes no assumptions about the layout of the string table. This is not fast, but it does not need to be at + // this point in the error reporting path + uint32_t num_vuids = sizeof(vuid_spec_text) / sizeof(vuid_spec_text_pair); + const char *spec_text = nullptr; + // Only the Antora site will make use of the sections + std::string spec_url_section; + for (uint32_t i = 0; i < num_vuids; i++) { + if (0 == strncmp(vuid_text.data(), vuid_spec_text[i].vuid, vuid_text.size())) { + spec_text = vuid_spec_text[i].spec_text; + spec_url_section = vuid_spec_text[i].url_id; + break; + } + } -#ifdef VK_USE_PLATFORM_ANDROID_KHR - if (force_default_log_callback) { - use_default_callbacks = true; - } + // Construct and append the specification text and link to the appropriate version of the spec + if (nullptr != spec_text) { +#ifdef ANNOTATED_SPEC_LINK + std::string spec_url_base = ANNOTATED_SPEC_LINK; +#else + std::string spec_url_base = "https://docs.vulkan.org/spec/latest/"; #endif - const char *layer_prefix = "Validation"; - for (const auto ¤t_callback : *callback_list) { - // Skip callback if it's a default callback and there are non-default callbacks present - if (current_callback.IsDefault() && !use_default_callbacks) continue; - - // VK_EXT_debug_utils callback - if (current_callback.IsUtils() && (current_callback.debug_utils_msg_flags & msg_severity) && - (current_callback.debug_utils_msg_type & msg_type)) { - callback_data.pMessage = composite.c_str(); - if (current_callback.debug_utils_callback_function_ptr( - static_cast(msg_severity), msg_type, &callback_data, - current_callback.pUserData)) { - bail = true; + // Add period at end if forgotten + // This provides better seperation between error message and spec text + if (main_message.back() != '.' && main_message.back() != '\n') { + oss << '.'; } - } else if (!current_callback.IsUtils() && (current_callback.debug_report_msg_flags & msg_flags)) { - // VK_EXT_debug_report callback (deprecated) - if (object_name_infos.empty()) { - VkDebugUtilsObjectNameInfoEXT null_object_name = {VK_STRUCTURE_TYPE_DEBUG_UTILS_OBJECT_NAME_INFO_EXT, nullptr, - VK_OBJECT_TYPE_UNKNOWN, 0, nullptr}; - // need to have at least one object - object_name_infos.emplace_back(null_object_name); + + // Start Vulkan spec text with a new line to make it easier visually + if (main_message.back() != '\n') { + oss << '\n'; } - if (current_callback.debug_report_callback_function_ptr( - msg_flags, ConvertCoreObjectToDebugReportObject(object_name_infos[0].objectType), - object_name_infos[0].objectHandle, message_id_number, 0, layer_prefix, composite.c_str(), - current_callback.pUserData)) { - bail = true; + + oss << "The Vulkan spec states: " << spec_text; + + // Spec link can always be found searching the VUID. + // But regardless of "verbose" setting, print the spec text as sometimes the error message in the layer is designed to + // complement it. + if (message_format_settings.verbose) { + oss << " (" << spec_url_base << spec_url_section << "#" << vuid_text << ")"; } } } - return bail; + + return oss.str(); } void DebugReport::SetUtilsObjectName(const VkDebugUtilsObjectNameInfoEXT *pNameInfo) { @@ -572,93 +630,26 @@ VKAPI_ATTR void DeactivateInstanceDebugCallbacks(DebugReport *debug_report) { // helper for VUID based filtering. This needs to be separate so it can be called before incurring // the cost of sprintf()-ing the err_msg needed by LogMsgLocked(). -bool DebugReport::LogMsgEnabled(std::string_view vuid_text, VkDebugUtilsMessageSeverityFlagsEXT msg_severity, +bool DebugReport::LogMsgEnabled(uint32_t vuid_hash, VkDebugUtilsMessageSeverityFlagsEXT msg_severity, VkDebugUtilsMessageTypeFlagsEXT msg_type) { if (!(active_msg_severities & msg_severity) || !(active_msg_types & msg_type)) { return false; } // If message is in filter list, bail out very early - const uint32_t message_id = hash_util::VuidHash(vuid_text); - if (filter_message_ids.find(message_id) != filter_message_ids.end()) { + if (filter_message_ids.find(vuid_hash) != filter_message_ids.end()) { return false; } - if ((duplicate_message_limit > 0) && UpdateLogMsgCounts(static_cast(message_id))) { + if ((duplicate_message_limit > 0) && UpdateLogMsgCounts(static_cast(vuid_hash))) { // Count for this particular message is over the limit, ignore it return false; } return true; } -bool DebugReport::LogMsg(VkFlags msg_flags, const LogObjectList &objects, const Location &loc, std::string_view vuid_text, - const char *format, va_list argptr) { - assert(*(vuid_text.data() + vuid_text.size()) == '\0'); - - VkDebugUtilsMessageSeverityFlagsEXT msg_severity; - VkDebugUtilsMessageTypeFlagsEXT msg_type; - - DebugReportFlagsToAnnotFlags(msg_flags, &msg_severity, &msg_type); - std::unique_lock lock(debug_output_mutex); - // Avoid logging cost if msg is to be ignored - if (!LogMsgEnabled(vuid_text, msg_severity, msg_type)) { - return false; - } - - std::string full_message = text::VFormat(format, argptr); - full_message = loc.Message() + " " + full_message; - - // Append the spec error text to the error message, unless it contains a word treated as special - if ((vuid_text.find("VUID-") != std::string::npos)) { - // Linear search makes no assumptions about the layout of the string table. This is not fast, but it does not need to be at - // this point in the error reporting path - uint32_t num_vuids = sizeof(vuid_spec_text) / sizeof(vuid_spec_text_pair); - const char *spec_text = nullptr; - // Only the Antora site will make use of the sections - std::string spec_url_section; - for (uint32_t i = 0; i < num_vuids; i++) { - if (0 == strncmp(vuid_text.data(), vuid_spec_text[i].vuid, vuid_text.size())) { - spec_text = vuid_spec_text[i].spec_text; - spec_url_section = vuid_spec_text[i].url_id; - break; - } - } - - // Construct and append the specification text and link to the appropriate version of the spec - if (nullptr != spec_text) { -#ifdef ANNOTATED_SPEC_LINK - std::string spec_url_base = ANNOTATED_SPEC_LINK; -#else - std::string spec_url_base = "https://docs.vulkan.org/spec/latest/"; -#endif - - // Add period at end if forgotten - // This provides better seperation between error message and spec text - if (full_message.back() != '.' && full_message.back() != '\n') { - full_message.append("."); - } - - // Start Vulkan spec text with a new line to make it easier visually - if (full_message.back() != '\n') { - full_message.append("\n"); - } - - full_message.append("The Vulkan spec states: "); - full_message.append(spec_text); - - // Spec link can always be found searching the VUID. - // But regardless of "verbose" setting, print the spec text as sometime it the error message in the layer is designed to - // compliment it. - if (message_format_settings.verbose) { - full_message.append(" ("); - full_message.append(spec_url_base); - full_message.append(spec_url_section); - full_message.append("#"); // CMake hates hashes - full_message.append(vuid_text); - full_message.append(")"); - } - } - } - - return DebugLogMsg(msg_flags, objects, full_message.c_str(), vuid_text.data()); +bool DebugReport::LogMessageVaList(VkFlags msg_flags, const LogObjectList &objects, const Location &loc, std::string_view vuid_text, + const char *format, va_list argptr) { + const std::string main_message = text::VFormat(format, argptr); + return LogMessage(msg_flags, objects, loc, vuid_text, main_message); } VKAPI_ATTR VkBool32 VKAPI_CALL MessengerBreakCallback([[maybe_unused]] VkDebugUtilsMessageSeverityFlagBitsEXT message_severity, diff --git a/layers/error_message/logging.h b/layers/error_message/logging.h index d6f5253c4ec..fe571770aeb 100644 --- a/layers/error_message/logging.h +++ b/layers/error_message/logging.h @@ -223,11 +223,12 @@ class DebugReport { return FormatHandle(VkHandleInfo::Typename(), HandleToUint64(handle)); } - // Formats messages to be in the proper format, handles VUID logic, and any legacy issues - bool LogMsg(VkFlags msg_flags, const LogObjectList &objects, const Location &loc, std::string_view vuid_text, - const char *format, va_list argptr); - // Core logging that interacts with the DebugCallbacks - bool DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, const char *msg, const char *text_vuid) const; + // Legacy way to log messages with C-style va_list + bool LogMessageVaList(VkFlags msg_flags, const LogObjectList &objects, const Location &loc, std::string_view vuid_text, + const char *format, va_list argptr); + // Formats messages to be in the proper format, handles VUID logic, any legacy issues, and finally calls the callback + bool LogMessage(VkFlags msg_flags, const LogObjectList &objects, const Location &loc, std::string_view vuid_text, + const std::string &main_message); void BeginQueueDebugUtilsLabel(VkQueue queue, const VkDebugUtilsLabelEXT *label_info); void EndQueueDebugUtilsLabel(VkQueue queue); @@ -241,8 +242,11 @@ class DebugReport { private: bool UpdateLogMsgCounts(int32_t vuid_hash) const; - bool LogMsgEnabled(std::string_view vuid_text, VkDebugUtilsMessageSeverityFlagsEXT msg_severity, + bool LogMsgEnabled(uint32_t vuid_hash, VkDebugUtilsMessageSeverityFlagsEXT msg_severity, VkDebugUtilsMessageTypeFlagsEXT msg_type); + std::string CreateMessageText(VkFlags msg_flags, const Location &loc, + const std::vector &object_name_infos, const uint32_t vuid_hash, + std::string_view vuid_text, const std::string &main_message); VkDebugUtilsMessageSeverityFlagsEXT active_msg_severities{0}; VkDebugUtilsMessageTypeFlagsEXT active_msg_types{0}; @@ -267,7 +271,7 @@ class Logger { LogError(std::string_view vuid_text, const LogObjectList &objlist, const Location &loc, const char *format, ...) const { va_list argptr; va_start(argptr, format); - const bool result = debug_report->LogMsg(kErrorBit, objlist, loc, vuid_text, format, argptr); + const bool result = debug_report->LogMessageVaList(kErrorBit, objlist, loc, vuid_text, format, argptr); va_end(argptr); return result; } @@ -277,7 +281,7 @@ class Logger { const char *format, ...) const { va_list argptr; va_start(argptr, format); - const bool result = debug_report->LogMsg(kWarningBit, objlist, loc, vuid_text, format, argptr); + const bool result = debug_report->LogMessageVaList(kWarningBit, objlist, loc, vuid_text, format, argptr); va_end(argptr); return result; } @@ -286,7 +290,7 @@ class Logger { LogWarning(std::string_view vuid_text, const LogObjectList &objlist, const Location &loc, const char *format, ...) const { va_list argptr; va_start(argptr, format); - const bool result = debug_report->LogMsg(kWarningBit, objlist, loc, vuid_text, format, argptr); + const bool result = debug_report->LogMessageVaList(kWarningBit, objlist, loc, vuid_text, format, argptr); va_end(argptr); return result; } @@ -295,7 +299,7 @@ class Logger { const char *format, ...) const { va_list argptr; va_start(argptr, format); - const bool result = debug_report->LogMsg(kPerformanceWarningBit, objlist, loc, vuid_text, format, argptr); + const bool result = debug_report->LogMessageVaList(kPerformanceWarningBit, objlist, loc, vuid_text, format, argptr); va_end(argptr); return result; } @@ -304,7 +308,7 @@ class Logger { LogInfo(std::string_view vuid_text, const LogObjectList &objlist, const Location &loc, const char *format, ...) const { va_list argptr; va_start(argptr, format); - const bool result = debug_report->LogMsg(kInformationBit, objlist, loc, vuid_text, format, argptr); + const bool result = debug_report->LogMessageVaList(kInformationBit, objlist, loc, vuid_text, format, argptr); va_end(argptr); return result; } @@ -313,7 +317,7 @@ class Logger { LogVerbose(std::string_view vuid_text, const LogObjectList &objlist, const Location &loc, const char *format, ...) const { va_list argptr; va_start(argptr, format); - const bool result = debug_report->LogMsg(kVerboseBit, objlist, loc, vuid_text, format, argptr); + const bool result = debug_report->LogMessageVaList(kVerboseBit, objlist, loc, vuid_text, format, argptr); va_end(argptr); return result; } diff --git a/layers/gpuav/debug_printf/debug_printf.cpp b/layers/gpuav/debug_printf/debug_printf.cpp index 15acd51e9bc..807bd5bf72d 100644 --- a/layers/gpuav/debug_printf/debug_printf.cpp +++ b/layers/gpuav/debug_printf/debug_printf.cpp @@ -350,7 +350,7 @@ void AnalyzeAndGenerateMessage(Validator &gpuav, VkCommandBuffer command_buffer, } else { // LogInfo will print out a lot of extra information (Object handles, VUID, hash, etc) // If the user doesn't set "verbose", but wants to use the debug callback, we should limit it to the bare minimum - gpuav.debug_report->DebugLogMsg(kInformationBit, {}, shader_message.str().c_str(), "VVL-DEBUG-PRINTF"); + gpuav.debug_report->LogMessage(kInformationBit, {}, loc, "VVL-DEBUG-PRINTF", shader_message.str().c_str()); } } output_record_i += debug_record->size; diff --git a/layers/gpuav/spirv/module.cpp b/layers/gpuav/spirv/module.cpp index 0006fbabb4b..df33b40be55 100644 --- a/layers/gpuav/spirv/module.cpp +++ b/layers/gpuav/spirv/module.cpp @@ -17,6 +17,7 @@ #include #include "gpuav/shaders/gpuav_shaders_constants.h" #include "error_message/logging.h" +#include "error_message/error_location.h" #include "error_message/log_message_type.h" #include @@ -680,7 +681,8 @@ void Module::PostProcess() { void Module::InternalWarning(const char* tag, const char* message) { if (debug_report_) { - debug_report_->DebugLogMsg(kWarningBit, {}, message, tag); + Location loc(vvl::Func::Empty); + debug_report_->LogMessage(kWarningBit, {}, loc, tag, message); } else { std::cout << "[" << tag << "] " << message << '\n'; } @@ -688,7 +690,8 @@ void Module::InternalWarning(const char* tag, const char* message) { void Module::InternalError(const char* tag, const char* message) { if (debug_report_) { - debug_report_->DebugLogMsg(kErrorBit, {}, message, tag); + Location loc(vvl::Func::Empty); + debug_report_->LogMessage(kErrorBit, {}, loc, tag, message); } else { std::cerr << "[" << tag << "] " << message << '\n'; } diff --git a/layers/layer_options.cpp b/layers/layer_options.cpp index 18a46493e1c..7fa3e3613c7 100644 --- a/layers/layer_options.cpp +++ b/layers/layer_options.cpp @@ -1367,7 +1367,8 @@ void ProcessConfigAndEnvSettings(ConfigAndEnvSettings *settings_data) { } for (const auto &warning : setting_warnings) { - settings_data->debug_report->DebugLogMsg(kWarningBit, {}, warning.c_str(), "VALIDATION-SETTINGS"); + Location loc(vvl::Func::vkCreateInstance); + settings_data->debug_report->LogMessage(kWarningBit, {}, loc, "VALIDATION-SETTINGS", warning.c_str()); } vkuDestroyLayerSettingSet(layer_setting_set, nullptr);