Skip to content
This repository was archived by the owner on Jul 19, 2018. It is now read-only.

WIP: Logger Strawman #2475

Open
jzulauf-lunarg wants to merge 2 commits into
base: master
Choose a base branch
from
Open

WIP: Logger Strawman #2475

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
d92ce37
layers: Update CmdPushConstant Valid Usages
jzulauf-lunarg Mar 5, 2018
c513ac2
layers: Strawman/dartboard new message logger
jzulauf-lunarg Mar 9, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
71 changes: 39 additions & 32 deletions layers/core_validation.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -412,11 +412,10 @@ static bool ValidateMemoryIsValid(layer_data *dev_data, VkDeviceMemory mem, uint
DEVICE_MEM_INFO *mem_info = GetMemObjInfo(dev_data, mem);
if (mem_info) {
if (!mem_info->bound_ranges[bound_object_handle].valid) {
return log_msg(dev_data->report_data, VK_DEBUG_REPORT_WARNING_BIT_EXT, VK_DEBUG_REPORT_OBJECT_TYPE_DEVICE_MEMORY_EXT,
HandleToUint64(mem), __LINE__, MEMTRACK_INVALID_MEM_REGION, "MEM",
"%s: Cannot read invalid region of memory allocation 0x%" PRIx64 " for bound %s object 0x%" PRIx64
", please fill the memory before using.",
functionName, HandleToUint64(mem), object_string[type], bound_object_handle);
LOG_WARN_MSG(nullptr, msg, dev_data->report_data, mem, MEMTRACK_INVALID_MEM_REGION, "MEM");
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In looking for good examples I stumbled across VerifyBoundMemoryIsValid , which is using the wrong object types (hard coded image for things that can be buffers)... implementing the auto detection is going to take changing some interfaces (like that one) to not convert handles (which will probably fix some latent bugs) and templatizing things like VerifyBoundMemoryIsValid... that or adding LogMsg constructors that take uint64_t/object_type pairs.

msg.add(functionName).add(": Cannot read invalid region of memory allocation ").add_h(mem);
msg.add_fmt(" for bound %s object ", object_string[type]).add_h(bound_object_handle);
return msg.report();
}
}
return false;
Expand Down Expand Up @@ -1303,11 +1302,8 @@ static bool ValidatePipelineLocked(layer_data *dev_data, std::vector<std::unique
"Invalid Pipeline CreateInfo: exactly one of base pipeline index and handle must be specified");
} else if (pPipeline->graphicsPipelineCI.basePipelineIndex != -1) {
if (pPipeline->graphicsPipelineCI.basePipelineIndex >= pipelineIndex) {
skip |=
log_msg(dev_data->report_data, VK_DEBUG_REPORT_ERROR_BIT_EXT, VK_DEBUG_REPORT_OBJECT_TYPE_PIPELINE_EXT,
HandleToUint64(pPipeline->pipeline), __LINE__, VALIDATION_ERROR_208005a0, "DS",
"Invalid Pipeline CreateInfo: base pipeline must occur earlier in array than derivative pipeline. %s",
validation_error_map[VALIDATION_ERROR_208005a0]);
LOG_ERR_MSG(&skip, msg, dev_data->report_data, pPipeline->pipeline, VALIDATION_ERROR_208005a0, "DS");
msg.add("Invalid Pipeline CreateInfo: base pipeline must occur earlier in array than derivative pipeline.");
} else {
pBasePipeline = pPipelines[pPipeline->graphicsPipelineCI.basePipelineIndex].get();
}
Expand Down Expand Up @@ -2681,12 +2677,10 @@ static bool validateQueueFamilyIndices(layer_data *dev_data, GLOBAL_CB_NODE *pCB

if (pPool && queue_state) {
if (pPool->queueFamilyIndex != queue_state->queueFamilyIndex) {
skip |= log_msg(dev_data->report_data, VK_DEBUG_REPORT_ERROR_BIT_EXT, VK_DEBUG_REPORT_OBJECT_TYPE_COMMAND_BUFFER_EXT,
HandleToUint64(pCB->commandBuffer), __LINE__, VALIDATION_ERROR_31a00094, "DS",
"vkQueueSubmit: Primary command buffer 0x%" PRIx64
" created in queue family %d is being submitted on queue 0x%" PRIx64 " from queue family %d. %s",
HandleToUint64(pCB->commandBuffer), pPool->queueFamilyIndex, HandleToUint64(queue),
queue_state->queueFamilyIndex, validation_error_map[VALIDATION_ERROR_31a00094]);
LOG_ERR_MSG(&skip, msg, dev_data->report_data, pCB->commandBuffer, VALIDATION_ERROR_31a00094, "DS");
msg.add("vkQueueSubmit: Primary command buffer ").add_h(pCB->commandBuffer);
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

with more code gen, the add_h could be removed in favor of "overloads per handle type", s.t. all handles are known for what they are.

Copy link
Contributor

@krOoze krOoze Mar 10, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

skip, report_data, objType + object, layer name, and function name are usually constants for the whole function.
Would be nice not having to repeat them. Maybe class Logger? Then Logger log(all the above) and then per case log.err(veid, msg) or log.warn()?

Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 11, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perhaps a LoggerContext that could be used in a LogMsg constructor

msg << " created in queue family " << pPool->queueFamilyIndex << "is being submitted on queue ";
msg.add_h(queue) << " from queue family " << queue_state->queueFamilyIndex;
}

// Ensure that any bound images or buffers created with SHARING_MODE_CONCURRENT have access to the current queue family
Expand Down Expand Up @@ -8234,27 +8228,40 @@ VKAPI_ATTR void VKAPI_CALL CmdPushConstants(VkCommandBuffer commandBuffer, VkPip
"vkCmdPushConstants() call has no stageFlags set. %s", validation_error_map[VALIDATION_ERROR_1bc2dc03]);
}

// Check if specified push constant range falls within a pipeline-defined range which has matching stageFlags.
// The spec doesn't seem to disallow having multiple push constant ranges with the
// same offset and size, but different stageFlags. So we can't just check the
// stageFlags in the first range with matching offset and size.
// Check if pipeline_layout VkPushConstantRange(s) overlapping offset, size have stageFlags set for each stage in the command
// stageFlags argument, *and* that the command stageFlags argument has bits set for the stageFlags in each overlapping range.
if (!skip) {
const auto &ranges = *getPipelineLayout(dev_data, layout)->push_constant_ranges;
bool found_matching_range = false;
VkShaderStageFlags found_stages = 0;
for (const auto &range : ranges) {
if ((stageFlags == range.stageFlags) && (offset >= range.offset) && (offset + size <= range.offset + range.size)) {
found_matching_range = true;
break;
if ((offset >= range.offset) && (offset + size <= range.offset + range.size)) {
VkShaderStageFlags matching_stages = range.stageFlags & stageFlags;
if (matching_stages != range.stageFlags) {
// VALIDATION_ERROR_1bc00e08 VUID-vkCmdPushConstants-offset-01796
skip |= log_msg(dev_data->report_data, VK_DEBUG_REPORT_ERROR_BIT_EXT,
VK_DEBUG_REPORT_OBJECT_TYPE_COMMAND_BUFFER_EXT, HandleToUint64(commandBuffer), __LINE__,
VALIDATION_ERROR_1bc00e08, "DS",
"vkCmdPushConstants(): stageFlags (0x%" PRIx32 ", offset (%" PRIu32 "), and size (%" PRIu32
"), "
"must contain all stages in overlapping VkPushConstantRange stageFlags (0x%" PRIx32
"), offset (%" PRIu32 "), and size (%" PRIu32 ") in pipeline layout 0x%" PRIx64 ". %s",
(uint32_t)stageFlags, offset, size, (uint32_t)range.stageFlags, range.offset, range.size,
HandleToUint64(layout), validation_error_map[VALIDATION_ERROR_1bc00e08]);
}

// Accumulate all stages we've found
found_stages = matching_stages | found_stages;
}
}
if (!found_matching_range) {
skip |= log_msg(
dev_data->report_data, VK_DEBUG_REPORT_ERROR_BIT_EXT, VK_DEBUG_REPORT_OBJECT_TYPE_COMMAND_BUFFER_EXT,
HandleToUint64(commandBuffer), __LINE__, VALIDATION_ERROR_1bc002de, "DS",
"vkCmdPushConstants() stageFlags = 0x%" PRIx32
" do not match the stageFlags in any of the ranges with offset = %d and size = %d in pipeline layout 0x%" PRIx64
". %s",
(uint32_t)stageFlags, offset, size, HandleToUint64(layout), validation_error_map[VALIDATION_ERROR_1bc002de]);
if (found_stages != stageFlags) {
// VALIDATION_ERROR_1bc00e06 VUID-vkCmdPushConstants-offset-01795
uint32_t missing_stages = ~found_stages & stageFlags;
skip |= log_msg(dev_data->report_data, VK_DEBUG_REPORT_ERROR_BIT_EXT, VK_DEBUG_REPORT_OBJECT_TYPE_COMMAND_BUFFER_EXT,
HandleToUint64(commandBuffer), __LINE__, VALIDATION_ERROR_1bc00e06, "DS",
"vkCmdPushConstants(): stageFlags = 0x%" PRIx32 ", VkPushConstantRange in pipeline layout 0x%" PRIx64
" overlapping offset = %d and size = %d, do not contain stageFlags 0x%" PRIx32 ". %s",
(uint32_t)stageFlags, HandleToUint64(layout), offset, size, missing_stages,
validation_error_map[VALIDATION_ERROR_1bc00e06]);
}
}
lock.unlock();
Expand Down
157 changes: 150 additions & 7 deletions layers/vk_layer_logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,13 +26,16 @@
#include "vk_layer_config.h"
#include "vk_layer_data.h"
#include "vk_layer_table.h"
#include "vk_validation_error_messages.h"
#include "vk_loader_platform.h"
#include "vk_object_types.h"
#include "vulkan/vk_layer.h"
#include <signal.h>
#include <cinttypes>
#include <stdarg.h>
#include <stdbool.h>
#include <stdio.h>
#include <sstream>
#include <unordered_map>
#include <vector>

Expand Down Expand Up @@ -314,29 +317,42 @@ static inline void layer_disable_tmp_callbacks(debug_report_data *debug_data, ui
// Checks if the message will get logged.
// Allows layer to defer collecting & formating data if the
// message will be discarded.
static inline bool will_log_msg(debug_report_data *debug_data, VkFlags msgFlags) {
static inline bool will_log_msg(const debug_report_data *debug_data, VkFlags msgFlags) {
if (!debug_data || !(debug_data->active_flags & msgFlags)) {
// Message is not wanted
return false;
}

return true;
}

// sprintf to std::string, concatenating onto to_string if non-null, returns formatted string by value
#ifndef WIN32
static inline int string_sprintf(std::string *output, const char *fmt, ...) __attribute__((format(printf, 2, 3)));
static inline std::string string_sprintf(std::string *to_string, const char *fmt, ...) __attribute__((format(printf, 2, 3)));
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ignore this... I was planning to use it in the logger and discovered it wasn't actually working... these changes to show up in a separate PR.

#endif
static inline int string_sprintf(std::string *output, const char *fmt, ...) {
std::string &formatted = *output;
static inline std::string string_sprintf(std::string *to_string, const char *fmt, ...) {
std::string local;
to_string = (nullptr != to_string) ? to_string : &local;
std::string &formatted = *to_string;
size_t offset = formatted.size();

// Find out how many bytes we'll need.
va_list argptr;
va_start(argptr, fmt);
int reserve = vsnprintf(nullptr, 0, fmt, argptr);
va_end(argptr);
formatted.reserve(reserve + 1);
formatted.reserve(offset + reserve + 1);
formatted.resize(offset + reserve);

// sprintf those bytes to the output
va_start(argptr, fmt);
int result = vsnprintf((char *)formatted.data(), formatted.capacity(), fmt, argptr);
#ifndef NDEBUG
int result =
#endif
vsnprintf((char *)formatted.data() + offset, formatted.capacity(), fmt, argptr);
va_end(argptr);
assert(result == reserve);
return result;
return formatted;
}

#ifdef WIN32
Expand Down Expand Up @@ -439,4 +455,131 @@ uint64_t HandleToUint64(HANDLE_T h);

static inline uint64_t HandleToUint64(uint64_t h) { return h; }

class LogMsg {
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Clearly some comments are in order here... see the PR description for the "theory of operation" stuff.

public:
template <typename ObjectType>
LogMsg(bool *status, const debug_report_data *debug_data, VkFlags msg_flags, ObjectType src_object, size_t location,
int32_t msg_code, const char *layer_prefix)
: status_(status),
debug_data_(debug_data),
msg_flags_(msg_flags),
src_object_(HandleToUint64(src_object)),
src_object_type_(VkObjectTypeTraits<ObjectType>::kObjectType),
location_(location),
msg_code_(msg_code),
msg_code_is_vu_(false),
layer_prefix_(layer_prefix),
will_report_(will_log_msg(debug_data, msg_flags)),
reported_(false) {}
template <typename ObjectType>
LogMsg(bool *status, const debug_report_data *debug_data, VkFlags msg_flags, ObjectType src_object, size_t location,
UNIQUE_VALIDATION_ERROR_CODE msg_code, const char *layer_prefix)
: LogMsg(status, debug_data, msg_flags, src_object, location, static_cast<int32_t>(msg_code), layer_prefix) {
msg_code_is_vu_ = true;
}

template <typename IntType>
LogMsg &add_x(IntType out) {
if (will_report_) {
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

note the noop'ing controlled by will_report_

// We could use string_sprintf, but we'll try the awful native formatting support for this at least
report_ << "0x";
auto save_fill = report_.fill('0');
auto save_width = report_.width(2 * sizeof(IntType));
report_ << std::hex << out << std::dec;
report_.fill(save_fill);
report_.width(save_width);
}
return *this;
}

template <typename RefType>
LogMsg &add(RefType *out) {
return add_x<RefType *>(out);
}

template <typename HandleType>
LogMsg &add_h(const HandleType h) {
if (!will_report_) {
add_x(HandleToUint64(h));
}
return *this;
}

// Anything with an acceptable stringstream operation can just use add
template <typename OutType>
LogMsg &add(const OutType out) {
if (will_report_) {
report_ << out;
}
return *this;
}

// use sprintf to add formatted information
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thar be va_dragons here. See something, say something.

#ifndef WIN32
#define LOG_MSG_ADD_FMT_ATTR __attribute__((format(printf, 2, 3)))
#else
#define LOG_MSG_ADD_FMT_ATTR
#endif
LogMsg &add_fmt(const char *fmt, ...) LOG_MSG_ADD_FMT_ATTR {
if (will_report_) {
va_list argptr;
va_start(argptr, fmt);
char *str;
if (-1 != vasprintf(&str, fmt, argptr)) {
report_ << str;
free(str);
}
va_end(argptr);
}
return *this;
}

bool will_report() const { return will_report_; };
bool report() {
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This call is only needed if you supply a nullptr status... otherwise, just going out of scope takes care of sending the debug_report_log_msg

bool result = false;
if (will_report_ && !reported_) {
if (msg_code_is_vu_) {
add(" ");
add(validation_error_map[msg_code_]);
}
result = debug_report_log_msg(debug_data_, msg_flags_, get_debug_report_enum[src_object_type_], src_object_, location_,
msg_code_, layer_prefix_, report_.str().c_str());
reported_ = true;
if (status_) {
// Update this in the same chaining way as log_msg usage
*status_ |= result;
}
}
return result;
}

~LogMsg() { report(); }

private:
bool *status_;
const debug_report_data *debug_data_;
VkFlags msg_flags_;
uint64_t src_object_;
VulkanObjectType src_object_type_;
size_t location_;
int32_t msg_code_;
bool msg_code_is_vu_;
const char *layer_prefix_;
bool will_report_;
std::stringstream report_;
bool reported_;
};

// stream out to log msg using the public interface
template <typename OutType>
LogMsg &operator<<(LogMsg &logger, const OutType &out) {
return logger.add(out);
}

#define LOG_ERR_MSG(skip, msg, report_data, object, code, prefix) \
Copy link
Contributor Author

@jzulauf-lunarg jzulauf-lunarg Mar 9, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if the __LINE__ and prefix are going away, we can avoid the macro by subclassing LogMsg for the two common cases without loss of brevity.

LogMsg msg(skip, report_data, VK_DEBUG_REPORT_ERROR_BIT_EXT, object, __LINE__, code, prefix);

#define LOG_WARN_MSG(skip, msg, report_data, object, code, prefix) \
LogMsg msg(skip, report_data, VK_DEBUG_REPORT_WARNING_BIT_EXT, object, __LINE__, code, prefix);

#endif // LAYER_LOGGING_H
Loading