Skip to content

Commit

Permalink
layer: Cleanup logging code
Browse files Browse the repository at this point in the history
  • Loading branch information
@spencer-lunarg
spencer-lunarg committed Feb 24, 2025
1 parent 32d36e8 commit aab9e95
Show file tree
Hide file tree
Showing 5 changed files with 143 additions and 144 deletions.
247 changes: 119 additions & 128 deletions layers/error_message/logging.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<VkDebugUtilsLabelEXT> queue_labels;
std::vector<VkDebugUtilsLabelEXT> 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<std::mutex> 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<VkDebugUtilsLabelEXT> queue_labels;
std::vector<VkDebugUtilsLabelEXT> cmd_buf_labels;

std::vector<std::string> object_labels;
// Ensures that push_back will not reallocate, thereby providing pointer
// stability for pushed strings.
Expand Down Expand Up @@ -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<int32_t>(message_id_number);
callback_data.pMessageIdName = vuid_text.data();
callback_data.messageIdNumber = vvl_bit_cast<int32_t>(vuid_hash);
callback_data.pMessage = nullptr;
callback_data.queueLabelCount = static_cast<uint32_t>(queue_labels.size());
callback_data.pQueueLabels = queue_labels.empty() ? nullptr : queue_labels.data();
Expand All @@ -187,10 +192,61 @@ bool DebugReport::DebugLogMsg(VkFlags msg_flags, const LogObjectList &objects, c
callback_data.objectCount = static_cast<uint32_t>(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 &current_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 &current_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<VkDebugUtilsMessageSeverityFlagBitsEXT>(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<VkDebugUtilsObjectNameInfoEXT> &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()) {
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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 &current_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 &current_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<VkDebugUtilsMessageSeverityFlagBitsEXT>(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) {
Expand Down Expand Up @@ -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<int32_t>(message_id))) {
if ((duplicate_message_limit > 0) && UpdateLogMsgCounts(static_cast<int32_t>(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<std::mutex> 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,
Expand Down
Loading

0 comments on commit aab9e95

Please sign in to comment.