From a7700afbf6c58623959cb461f3f627233989f49f Mon Sep 17 00:00:00 2001 From: Laurent Morichetti Date: Thu, 18 Aug 2022 14:50:51 -0700 Subject: [PATCH] Use fatal() and warning() for logging errors Change-Id: I4d525ed2a7dba72beff6fbe43383015e55465fcd [ROCm/roctracer commit: 57867e480363b946813e3963e04c14e55d2c14b4] --- projects/roctracer/plugin/file/CMakeLists.txt | 2 +- projects/roctracer/plugin/file/file.cpp | 37 ++------ .../roctracer/src/roctracer/hsa_support.cpp | 50 +++++----- .../roctracer/src/roctracer/roctracer.cpp | 78 +++------------- .../roctracer/src/tracer_tool/tracer_tool.cpp | 91 +++++++------------ projects/roctracer/src/util/debug.cpp | 14 ++- projects/roctracer/src/util/debug.h | 10 ++ 7 files changed, 102 insertions(+), 180 deletions(-) diff --git a/projects/roctracer/plugin/file/CMakeLists.txt b/projects/roctracer/plugin/file/CMakeLists.txt index 78f75b5e99..f0888aeee2 100644 --- a/projects/roctracer/plugin/file/CMakeLists.txt +++ b/projects/roctracer/plugin/file/CMakeLists.txt @@ -35,7 +35,7 @@ target_include_directories(file_plugin PRIVATE ${PROJECT_SOURCE_DIR}/inc) target_link_options(file_plugin PRIVATE -Wl,--version-script=${CMAKE_CURRENT_SOURCE_DIR}/../exportmap -Wl,--no-undefined) -target_link_libraries(file_plugin PRIVATE roctracer hsa-runtime64::hsa-runtime64 stdc++fs) +target_link_libraries(file_plugin PRIVATE util roctracer hsa-runtime64::hsa-runtime64 stdc++fs) install(TARGETS file_plugin LIBRARY DESTINATION ${CMAKE_INSTALL_LIBDIR}/${PROJECT_NAME} diff --git a/projects/roctracer/plugin/file/file.cpp b/projects/roctracer/plugin/file/file.cpp index c7391c1d3b..a5f014f732 100644 --- a/projects/roctracer/plugin/file/file.cpp +++ b/projects/roctracer/plugin/file/file.cpp @@ -18,6 +18,8 @@ OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ +#include "debug.h" + #include #include #include @@ -45,40 +47,13 @@ // Macro to check ROCtracer calls status #define CHECK_ROCTRACER(call) \ do { \ - if ((call) != 0) fatal("%s\n", roctracer_error_string()); \ + if ((call) != 0) fatal("%s", roctracer_error_string()); \ } while (false) namespace fs = std::experimental::filesystem; namespace { -void warning(const char* format, ...) -#if defined(__GNUC__) - __attribute__((format(printf, 1, 2))) -#endif /* defined (__GNUC__) */ - ; - -void fatal [[noreturn]] (const char* format, ...) -#if defined(__GNUC__) -__attribute__((format(printf, 1, 2))) -#endif /* defined (__GNUC__) */ -; - -void warning(const char* format, ...) { - va_list va; - va_start(va, format); - vfprintf(stderr, format, va); - va_end(va); -} - -void fatal(const char* format, ...) { - va_list va; - va_start(va, format); - vfprintf(stderr, format, va); - va_end(va); - abort(); -} - uint32_t GetPid() { static uint32_t pid = syscall(__NR_getpid); return pid; @@ -171,7 +146,7 @@ class file_plugin_t { fs::path output_prefix(output_dir); if (!fs::is_directory(fs::status(output_prefix))) { - if (!stream_.fail()) warning("Cannot open output directory '%s'\n", output_dir); + if (!stream_.fail()) warning("Cannot open output directory '%s'", output_dir); stream_.setstate(std::ios_base::failbit); return; } @@ -232,7 +207,7 @@ class file_plugin_t { &hsa_handles); assert(status == HSA_STATUS_SUCCESS && "failed to iterate HSA agents"); if (hsa_handles.fail()) { - warning("Cannot write to '%s'\n", hsa_handles.name().c_str()); + warning("Cannot write to '%s'", hsa_handles.name().c_str()); return; } @@ -243,7 +218,7 @@ class file_plugin_t { CHECK_ROCTRACER(roctracer_get_timestamp(&app_begin_timestamp)); begin_ts << std::dec << app_begin_timestamp << std::endl; if (begin_ts.fail()) { - warning("Cannot write to '%s'\n", begin_ts.name().c_str()); + warning("Cannot write to '%s'", begin_ts.name().c_str()); return; } diff --git a/projects/roctracer/src/roctracer/hsa_support.cpp b/projects/roctracer/src/roctracer/hsa_support.cpp index c1e48aee22..b4c6d39c72 100644 --- a/projects/roctracer/src/roctracer/hsa_support.cpp +++ b/projects/roctracer/src/roctracer/hsa_support.cpp @@ -21,12 +21,12 @@ #include "hsa_support.h" #include "correlation_id.h" +#include "debug.h" #include "exception.h" #include "memory_pool.h" #include "roctracer.h" #include "roctracer_hsa.h" -#include "util/callback_table.h" -#include "util/logger.h" +#include "callback_table.h" #include #include @@ -107,10 +107,10 @@ class Tracker { // Creating a proxy signal status = saved_core_api.hsa_signal_create_fn(1, 0, NULL, &(entry->signal)); - if (status != HSA_STATUS_SUCCESS) FATAL_LOGGING("hsa_signal_create failed"); + if (status != HSA_STATUS_SUCCESS) fatal("hsa_signal_create failed"); status = saved_amd_ext_api.hsa_amd_signal_async_handler_fn( entry->signal, HSA_SIGNAL_CONDITION_LT, 1, Handler, entry); - if (status != HSA_STATUS_SUCCESS) FATAL_LOGGING("hsa_amd_signal_async_handler failed"); + if (status != HSA_STATUS_SUCCESS) fatal("hsa_amd_signal_async_handler failed"); } // Delete tracker entry @@ -126,7 +126,7 @@ class Tracker { uint64_t sysclock_hz = 0; hsa_status_t status = saved_core_api.hsa_system_get_info_fn(HSA_SYSTEM_INFO_TIMESTAMP_FREQUENCY, &sysclock_hz); - if (status != HSA_STATUS_SUCCESS) FATAL_LOGGING("hsa_system_get_info failed"); + if (status != HSA_STATUS_SUCCESS) fatal("hsa_system_get_info failed"); return (uint64_t)1000000000 / sysclock_hz; }(); @@ -134,8 +134,7 @@ class Tracker { hsa_amd_profiling_async_copy_time_t async_copy_time{}; hsa_status_t status = saved_amd_ext_api.hsa_amd_profiling_get_async_copy_time_fn( entry->signal, &async_copy_time); - if (status != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_amd_profiling_get_async_copy_time failed"); + if (status != HSA_STATUS_SUCCESS) fatal("hsa_amd_profiling_get_async_copy_time failed"); entry->begin = async_copy_time.start * sysclock_period; entry->end = async_copy_time.end * sysclock_period; } else { @@ -191,7 +190,7 @@ hsa_status_t HSA_API MemoryAllocateIntercept(hsa_region_t region, size_t size, v &data.allocate.segment) != HSA_STATUS_SUCCESS || saved_core_api.hsa_region_get_info_fn(region, HSA_REGION_INFO_GLOBAL_FLAGS, &data.allocate.global_flag) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_region_get_info failed"); + fatal("hsa_region_get_info failed"); callback_fun(ACTIVITY_DOMAIN_HSA_EVT, HSA_EVT_ID_ALLOCATE, &data, callback_arg); } @@ -209,7 +208,7 @@ hsa_status_t MemoryAssignAgentIntercept(void* ptr, hsa_agent_t agent, data.device.ptr = ptr; if (saved_core_api.hsa_agent_get_info_fn(agent, HSA_AGENT_INFO_DEVICE, &data.device.type) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_agent_get_info failed"); + fatal("hsa_agent_get_info failed"); callback_fun(ACTIVITY_DOMAIN_HSA_EVT, HSA_EVT_ID_DEVICE, &data, callback_arg); } @@ -248,7 +247,7 @@ hsa_status_t MemoryPoolAllocateIntercept(hsa_amd_memory_pool_t pool, size_t size saved_amd_ext_api.hsa_amd_memory_pool_get_info_fn( pool, HSA_AMD_MEMORY_POOL_INFO_GLOBAL_FLAGS, &data.allocate.global_flag) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_region_get_info failed"); + fatal("hsa_region_get_info failed"); callback_fun(ACTIVITY_DOMAIN_HSA_EVT, HSA_EVT_ID_ALLOCATE, &data, callback_arg); @@ -269,7 +268,7 @@ hsa_status_t MemoryPoolAllocateIntercept(hsa_amd_memory_pool_t pool, size_t size return HSA_STATUS_SUCCESS; auto it = agent_info_map.find(agent.handle); - if (it == agent_info_map.end()) FATAL_LOGGING("agent was not found in the agent_info map"); + if (it == agent_info_map.end()) fatal("agent was not found in the agent_info map"); hsa_evt_data_t data{}; data.device.type = it->second.type; @@ -308,7 +307,7 @@ hsa_status_t AgentsAllowAccessIntercept(uint32_t num_agents, const hsa_agent_t* while (num_agents--) { hsa_agent_t agent = *agents++; auto it = agent_info_map.find(agent.handle); - if (it == agent_info_map.end()) FATAL_LOGGING("agent was not found in the agent_info map"); + if (it == agent_info_map.end()) fatal("agent was not found in the agent_info map"); hsa_evt_data_t data{}; data.device.type = it->second.type; @@ -336,14 +335,14 @@ hsa_status_t CodeObjectCallback(hsa_executable_t executable, if (hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( loaded_code_object, HSA_VEN_AMD_LOADER_LOADED_CODE_OBJECT_INFO_CODE_OBJECT_STORAGE_TYPE, &data.codeobj.storage_type) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_ven_amd_loader_loaded_code_object_get_info failed"); + fatal("hsa_ven_amd_loader_loaded_code_object_get_info failed"); if (data.codeobj.storage_type == HSA_VEN_AMD_LOADER_CODE_OBJECT_STORAGE_TYPE_FILE) { if (hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( loaded_code_object, HSA_VEN_AMD_LOADER_LOADED_CODE_OBJECT_INFO_CODE_OBJECT_STORAGE_FILE, &data.codeobj.storage_file) != HSA_STATUS_SUCCESS || data.codeobj.storage_file == -1) - FATAL_LOGGING("hsa_ven_amd_loader_loaded_code_object_get_info failed"); + fatal("hsa_ven_amd_loader_loaded_code_object_get_info failed"); data.codeobj.memory_base = data.codeobj.memory_size = 0; } else if (data.codeobj.storage_type == HSA_VEN_AMD_LOADER_CODE_OBJECT_STORAGE_TYPE_MEMORY) { if (hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( @@ -354,12 +353,12 @@ hsa_status_t CodeObjectCallback(hsa_executable_t executable, loaded_code_object, HSA_VEN_AMD_LOADER_LOADED_CODE_OBJECT_INFO_CODE_OBJECT_STORAGE_MEMORY_SIZE, &data.codeobj.memory_size) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_ven_amd_loader_loaded_code_object_get_info failed"); + fatal("hsa_ven_amd_loader_loaded_code_object_get_info failed"); data.codeobj.storage_file = -1; } else if (data.codeobj.storage_type == HSA_VEN_AMD_LOADER_CODE_OBJECT_STORAGE_TYPE_NONE) { return HSA_STATUS_SUCCESS; // FIXME: do we really not care about these code objects? } else { - FATAL_LOGGING("Unknown code object storage type: " << data.codeobj.storage_type); + fatal("unknown code object storage type: %d", data.codeobj.storage_type); } if (hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( @@ -371,18 +370,18 @@ hsa_status_t CodeObjectCallback(hsa_executable_t executable, hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( loaded_code_object, HSA_VEN_AMD_LOADER_LOADED_CODE_OBJECT_INFO_LOAD_DELTA, &data.codeobj.load_delta) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_ven_amd_loader_loaded_code_object_get_info failed"); + fatal("hsa_ven_amd_loader_loaded_code_object_get_info failed"); if (hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( loaded_code_object, HSA_VEN_AMD_LOADER_LOADED_CODE_OBJECT_INFO_URI_LENGTH, &data.codeobj.uri_length) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_ven_amd_loader_loaded_code_object_get_info failed"); + fatal("hsa_ven_amd_loader_loaded_code_object_get_info failed"); std::string uri_str(data.codeobj.uri_length, '\0'); if (hsa_loader_api.hsa_ven_amd_loader_loaded_code_object_get_info( loaded_code_object, HSA_VEN_AMD_LOADER_LOADED_CODE_OBJECT_INFO_URI, uri_str.data()) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_ven_amd_loader_loaded_code_object_get_info failed"); + fatal("hsa_ven_amd_loader_loaded_code_object_get_info failed"); data.codeobj.uri = uri_str.c_str(); data.codeobj.unload = code_object_callback_arg->unload ? 1 : 0; @@ -480,22 +479,21 @@ hsa_status_t MemoryASyncCopyRectIntercept(const hsa_pitched_ptr_t* dst, roctracer_timestamp_t timestamp_ns() { uint64_t sysclock; - if (saved_core_api.hsa_system_get_info_fn == nullptr) - FATAL_LOGGING("HSA intercept is not active"); + assert(saved_core_api.hsa_system_get_info_fn != nullptr && "HSA intercept is not active"); if (hsa_status_t status = saved_core_api.hsa_system_get_info_fn(HSA_SYSTEM_INFO_TIMESTAMP, &sysclock); status == HSA_STATUS_ERROR_NOT_INITIALIZED) return 0; else if (status != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_system_get_info failed"); + fatal("hsa_system_get_info failed"); static uint64_t sysclock_period = []() { uint64_t sysclock_hz = 0; if (hsa_status_t status = saved_core_api.hsa_system_get_info_fn( HSA_SYSTEM_INFO_TIMESTAMP_FREQUENCY, &sysclock_hz); status != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_system_get_info failed"); + fatal("hsa_system_get_info failed"); return (uint64_t)1000000000 / sysclock_hz; }(); @@ -516,7 +514,7 @@ void Initialize(HsaApiTable* table) { hsa_support::AgentInfo agent_info; if (hsa_support::saved_core_api.hsa_agent_get_info_fn( agent, HSA_AGENT_INFO_DEVICE, &agent_info.type) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_agent_get_info failed"); + fatal("hsa_agent_get_info failed"); switch (agent_info.type) { case HSA_DEVICE_TYPE_CPU: static int cpu_agent_count = 0; @@ -535,12 +533,12 @@ void Initialize(HsaApiTable* table) { return HSA_STATUS_SUCCESS; }, nullptr) != HSA_STATUS_SUCCESS) - FATAL_LOGGING("hsa_iterate_agents failed"); + fatal("hsa_iterate_agents failed"); // Install the code object intercept. hsa_status_t status = table->core_->hsa_system_get_major_extension_table_fn( HSA_EXTENSION_AMD_LOADER, 1, sizeof(hsa_ven_amd_loader_1_01_pfn_t), &hsa_loader_api); - if (status != HSA_STATUS_SUCCESS) FATAL_LOGGING("hsa_system_get_major_extension_table failed"); + if (status != HSA_STATUS_SUCCESS) fatal("hsa_system_get_major_extension_table failed"); // Install the HSA_OPS intercept table->amd_ext_->hsa_amd_memory_async_copy_fn = MemoryASyncCopyIntercept; diff --git a/projects/roctracer/src/roctracer/roctracer.cpp b/projects/roctracer/src/roctracer/roctracer.cpp index 8d837e5479..2924fcac86 100644 --- a/projects/roctracer/src/roctracer/roctracer.cpp +++ b/projects/roctracer/src/roctracer/roctracer.cpp @@ -38,29 +38,13 @@ #include #include "correlation_id.h" +#include "debug.h" #include "journal.h" #include "loader.h" #include "hsa_support.h" #include "memory_pool.h" #include "exception.h" -#include "util/logger.h" - -#define CHECK_HSA_STATUS(msg, status) \ - do { \ - if ((status) != HSA_STATUS_SUCCESS) { \ - const char* status_string = nullptr; \ - hsa_status_string(status, &status_string); \ - FATAL_LOGGING(msg << ": " << (status_string ? status_string : "")); \ - } \ - } while (false) - -#define HIPAPI_CALL(call) \ - do { \ - hipError_t err = call; \ - if (err != hipSuccess) { \ - FATAL_LOGGING("HIP error: " #call " error(" << err << ")"); \ - } \ - } while (false) +#include "logger.h" #define API_METHOD_PREFIX \ roctracer_status_t err = ROCTRACER_STATUS_SUCCESS; \ @@ -81,15 +65,6 @@ (void)err; \ return X; -#define ONLOAD_TRACE(str) \ - if (getenv("ROCP_ONLOAD_TRACE")) do { \ - std::cout << "PID(" << GetPid() << "): TRACER_LIB::" << __FUNCTION__ << " " << str \ - << std::endl \ - << std::flush; \ - } while (false); -#define ONLOAD_TRACE_BEG() ONLOAD_TRACE("begin") -#define ONLOAD_TRACE_END() ONLOAD_TRACE("end") - static inline uint32_t GetPid() { static auto pid = syscall(__NR_getpid); return pid; @@ -178,12 +153,6 @@ void HIP_ApiCallback(uint32_t op_id, roctracer_record_t* record, void* callback_ } CorrelationIdPop(); } - - DEBUG_TRACE( - "HIP_ApiCallback(\"%s\") phase(%d): op(%u) record(%p) data(%p) pool(%p) " - "correlation_id(%lu) beg_ns(%lu) end_ns(%lu)\n", - roctracer_op_string(ACTIVITY_DOMAIN_HIP_API, op_id, 0), data->phase, op_id, record, data, - pool, data->correlation_id, timestamp_ns); } void HIP_AsyncActivityCallback(uint32_t op_id, void* record_ptr, void* arg) { @@ -201,13 +170,6 @@ void HIP_AsyncActivityCallback(uint32_t op_id, void* record_ptr, void* arg) { }); else pool->Write(record); - - DEBUG_TRACE( - "HIP_AsyncActivityCallback(\"%s\"): op(%u) kind(%u) record(%p) pool(%p) correlation_id(%d) " - "beg_ns(%lu) end_ns(%lu)\n", - roctracer_op_string(ACTIVITY_DOMAIN_HIP_OPS, record_ptr->op, record_ptr->kind), - record_ptr->op, record_ptr->kind, record, pool, record_ptr->correlation_id, - record_ptr->begin_ns, record_ptr->end_ns); } // Logger routines and primitives @@ -361,20 +323,20 @@ static void roctracer_enable_callback_fun(roctracer_domain_t domain, uint32_t op if (hipError_t err = HipLoader::Instance().RegisterApiCallback(op, (void*)callback, user_data); err != hipSuccess) - FATAL_LOGGING("HIP::RegisterApiCallback(" << op << ") error(" << err << ")"); + fatal("HIP::RegisterApiCallback(%d) failed (err=%d)", op, err); if ((hip_act_cb_tracker.enable_check(op, API_CB_MASK) & API_ACT_MASK) == 0) { if (hipError_t err = HipLoader::Instance().RegisterActivityCallback(op, (void*)HIP_ApiCallback, nullptr); err != hipSuccess) - FATAL_LOGGING("HIPAPI: HIP::RegisterActivityCallback(" << op << ") error(" << err << ")"); + fatal("HIP::RegisterActivityCallback(%d) failed (err=%d)", op, err); } break; } case ACTIVITY_DOMAIN_ROCTX: { if (RocTxLoader::Instance().Enabled() && !RocTxLoader::Instance().RegisterApiCallback(op, (void*)callback, user_data)) - FATAL_LOGGING("ROCTX::RegisterApiCallback(" << op << ") failed"); + fatal("ROCTX::RegisterApiCallback(%d) failed", op); break; } default: @@ -421,18 +383,17 @@ static void roctracer_disable_callback_fun(roctracer_domain_t domain, uint32_t o std::lock_guard lock(hip_activity_mutex); if (hipError_t err = HipLoader::Instance().RemoveApiCallback(op); err != hipSuccess) - FATAL_LOGGING("HIP::RemoveApiCallback(" << op << "), error(" << err << ")"); + fatal("HIP::RemoveApiCallback(%d) failed (err=%d)", op, err); if ((hip_act_cb_tracker.disable_check(op, API_CB_MASK) & API_ACT_MASK) == 0) { if (hipError_t err = HipLoader::Instance().RemoveActivityCallback(op); err != hipSuccess) - FATAL_LOGGING("HIPAPI: HIP::RemoveActivityCallback op(" << op << "), error(" << err - << ")"); + fatal("HIP::RemoveActivityCallback(%d) failed (err=%d)", op, err); } break; } case ACTIVITY_DOMAIN_ROCTX: { if (RocTxLoader::Instance().Enabled() && !RocTxLoader::Instance().RemoveApiCallback(op)) - FATAL_LOGGING("ROCTX::RemoveApiCallback(" << op << ") failed"); + fatal("ROCTX::RemoveApiCallback(%d) failed", op); break; } default: @@ -522,7 +483,7 @@ static void roctracer_enable_activity_fun(roctracer_domain_t domain, uint32_t op if (HipLoader::Instance().Enabled() && HipLoader::Instance().RegisterAsyncActivityCallback(op, (void*)HIP_AsyncActivityCallback, pool) != hipSuccess) - FATAL_LOGGING("HIP::EnableActivityCallback error"); + fatal("HIP::EnableActivityCallback error"); break; } case ACTIVITY_DOMAIN_HIP_API: { @@ -533,7 +494,7 @@ static void roctracer_enable_activity_fun(roctracer_domain_t domain, uint32_t op if (hipError_t err = HipLoader::Instance().RegisterActivityCallback(op, (void*)HIP_ApiCallback, pool); err != hipSuccess) - FATAL_LOGGING("HIP::RegisterActivityCallback(" << op << " error(" << err << ")"); + fatal("HIP::RegisterActivityCallback(%d) (err=%d)", op, err); break; } case ACTIVITY_DOMAIN_ROCTX: @@ -601,7 +562,7 @@ static void roctracer_disable_activity_fun(roctracer_domain_t domain, uint32_t o case ACTIVITY_DOMAIN_HIP_OPS: { if (HipLoader::Instance().Enabled() && HipLoader::Instance().RemoveAsyncActivityCallback(op) != hipSuccess) - FATAL_LOGGING("HIP::EnableActivityCallback(nullptr) error, op(" << op << ")"); + fatal("HIP::EnableActivityCallback(%d)", op); break; } case ACTIVITY_DOMAIN_HIP_API: { @@ -610,12 +571,12 @@ static void roctracer_disable_activity_fun(roctracer_domain_t domain, uint32_t o if ((hip_act_cb_tracker.disable_check(op, API_ACT_MASK) & API_CB_MASK) == 0) { if (hipError_t err = HipLoader::Instance().RemoveActivityCallback(op); err != hipSuccess) - FATAL_LOGGING("HIP::RemoveActivityCallback op(" << op << "), error(" << err << ")"); + fatal("HIP::RemoveActivityCallback(%d) failed (err=%d)", op, err); } else { if (hipError_t err = HipLoader::Instance().RegisterActivityCallback(op, (void*)HIP_ApiCallback, nullptr); err != hipSuccess) - FATAL_LOGGING("HIPACT: HIP::RegisterActivityCallback(" << op << ") error(" << err << ")"); + fatal("HIP::RegisterActivityCallback(%d) failed (err=%d)", op, err); } break; } @@ -794,17 +755,8 @@ ROCTRACER_API roctracer_status_t roctracer_set_properties(roctracer_domain_t dom API_METHOD_SUFFIX } -__attribute__((constructor)) void constructor() { - ONLOAD_TRACE_BEG(); - util::Logger::Create(); - ONLOAD_TRACE_END(); -} - -__attribute__((destructor)) void destructor() { - ONLOAD_TRACE_BEG(); - util::Logger::Destroy(); - ONLOAD_TRACE_END(); -} +__attribute__((constructor)) void constructor() { util::Logger::Create(); } +__attribute__((destructor)) void destructor() { util::Logger::Destroy(); } extern "C" { diff --git a/projects/roctracer/src/tracer_tool/tracer_tool.cpp b/projects/roctracer/src/tracer_tool/tracer_tool.cpp index af30e97a2b..0657bfcdec 100644 --- a/projects/roctracer/src/tracer_tool/tracer_tool.cpp +++ b/projects/roctracer/src/tracer_tool/tracer_tool.cpp @@ -48,9 +48,10 @@ #include #include /* usleep */ -#include "util/xml.h" +#include "debug.h" #include "loader.h" #include "trace_buffer.h" +#include "xml.h" namespace fs = std::experimental::filesystem; @@ -58,22 +59,15 @@ namespace fs = std::experimental::filesystem; #define CHECK_ROCTRACER(call) \ do { \ if ((call) != ROCTRACER_STATUS_SUCCESS) { \ - fatal(std::string(roctracer_error_string())); \ + fatal(#call " failed: %s", roctracer_error_string()); \ } \ - } while (0) + } while (false) LOADER_INSTANTIATE(); TRACE_BUFFER_INSTANTIATE(); namespace { -void warning(const std::string& msg) { std::cerr << msg << std::endl; } - -[[noreturn]] void fatal(const std::string& msg) { - std::cerr << msg << std::endl; - abort(); -} - thread_local std::stack> hsa_begin_timestamp, hip_begin_timestamp; @@ -143,7 +137,7 @@ class roctracer_plugin_t { roctracer_plugin_t(const std::string& plugin_path) { plugin_handle_ = dlopen(plugin_path.c_str(), RTLD_LAZY); if (plugin_handle_ == nullptr) { - warning(std::string("Warning: dlopen for ") + plugin_path + " failed: " + dlerror()); + warning("dlopen(\"%s\") failed: %s", plugin_path.c_str(), dlerror()); return; } @@ -449,7 +443,7 @@ std::string normalize_token(const std::string& token, bool not_empty, const std: } if (((first_pos != std::string::npos) && (norm_len == 0)) || ((first_pos == std::string::npos) && not_empty)) { - fatal("normalize_token error: " + error_str); + error("normalize_token error: %s", error_str.c_str()); } return (norm_len != 0) ? token.substr(first_pos, norm_len) : std::string(""); } @@ -460,19 +454,19 @@ int get_xml_array(const xml::Xml::level_t* node, const std::string& field, const const auto& opts = node->opts; auto it = opts.find(field); if (it != opts.end()) { - const std::string array_string = it->second; - if (label != nullptr) printf("%s%s = %s\n", label, field.c_str(), array_string.c_str()); + const std::string& array_string = it->second; + if (label != nullptr) std::cout << label << field << " = " << array_string << std::endl; size_t pos1 = 0; - const size_t string_len = array_string.length(); + size_t string_len = array_string.length(); while (pos1 < string_len) { // set pos2 such that it also handles case of multiple delimiter options. // For example- "hipLaunchKernel, hipExtModuleLaunchKernel, hipMemsetAsync" // in this example delimiters are ' ' and also ',' - const size_t pos2 = array_string.find_first_of(delim, pos1); - const bool found = (pos2 != std::string::npos); - const size_t token_len = (pos2 != std::string::npos) ? pos2 - pos1 : string_len - pos1; - const std::string token = array_string.substr(pos1, token_len); - const std::string norm_str = normalize_token(token, found, "get_xml_array"); + size_t pos2 = array_string.find_first_of(delim, pos1); + bool found = (pos2 != std::string::npos); + size_t token_len = (pos2 != std::string::npos) ? pos2 - pos1 : string_len - pos1; + std::string token = array_string.substr(pos1, token_len); + std::string norm_str = normalize_token(token, found, "get_xml_array"); if (norm_str.length() != 0) vec->push_back(norm_str); if (!found) break; // update pos2 such that it represents the first non-delimiter character @@ -590,28 +584,24 @@ void tool_load() { } } - printf("ROCTracer (pid=%d): ", (int)GetPid()); - fflush(stdout); + std::cout << "ROCtracer (" << std::dec << GetPid() << "):"; // XML input const char* xml_name = getenv("ROCP_INPUT"); if (xml_name != nullptr) { xml::Xml* xml = xml::Xml::Create(xml_name); - if (xml == nullptr) { - fprintf(stderr, "ROCTracer: Input file not found '%s'\n", xml_name); - abort(); - } + if (xml == nullptr) error("input file not found '%s'", xml_name); bool found = false; for (const auto* entry : xml->GetNodes("top.trace")) { auto it = entry->opts.find("name"); - if (it == entry->opts.end()) fatal("ROCTracer: trace name is missing"); + if (it == entry->opts.end()) error("trace name is missing"); const std::string& name = it->second; std::vector api_vec; for (const auto* node : entry->nodes) { if (node->tag != "parameters") - fatal("ROCTracer: trace node is not supported '" + name + ":%" + node->tag + "'"); + error("trace node is not supported '%s:%%%s'", name.c_str(), node->tag.c_str()); get_xml_array(node, "api", ", ", &api_vec); // delimiter options given as both spaces and commas (' ' and ',') break; @@ -638,9 +628,9 @@ void tool_load() { } } - if (found) printf("input from \"%s\"", xml_name); + if (found) std::cout << " input from \"" << xml_name << "\""; } - printf("\n"); + std::cout << std::endl; // Disable HIP activity if HSA activity was set if (trace_hsa_activity == true) trace_hip_activity = false; @@ -648,8 +638,7 @@ void tool_load() { // Enable rpcTX callbacks if (trace_roctx) { // initialize HSA tracing - fprintf(stdout, " rocTX-trace()\n"); - fflush(stdout); + std::cout << " rocTX-trace()" << std::endl; CHECK_ROCTRACER( roctracer_enable_domain_callback(ACTIVITY_DOMAIN_ROCTX, roctx_api_callback, nullptr)); } @@ -662,7 +651,7 @@ void tool_load() { if (sscanf(ctrl_str, "%d:%d:%d", &ctrl_delay, &ctrl_len, &ctrl_rate) != 3 || ctrl_len > ctrl_rate) - fatal("Invalid ROCP_CTRL_RATE variable (ctrl_delay:ctrl_len:ctrl_rate)"); + error("invalid ROCP_CTRL_RATE variable (ctrl_delay:ctrl_len:ctrl_rate)"); control_dist_us = ctrl_rate - ctrl_len; control_len_us = ctrl_len; @@ -671,26 +660,20 @@ void tool_load() { roctracer_stop(); if (ctrl_delay != UINT32_MAX) { - fprintf(stdout, "ROCTracer: trace control: delay(%uus), length(%uus), rate(%uus)\n", - ctrl_delay, ctrl_len, ctrl_rate); - fflush(stdout); + std::cout << "ROCtracer: trace control: delay(" << ctrl_delay << "us), length(" << ctrl_len + << "us), rate(" << ctrl_rate << "us)" << std::endl; trace_period_thread = new std::thread(trace_period_fun); } else { - fprintf(stdout, "ROCTracer: trace start disabled\n"); - fflush(stdout); + std::cout << "ROCtracer: trace start disabled" << std::endl; } } const char* flush_str = getenv("ROCP_FLUSH_RATE"); if (flush_str != nullptr) { sscanf(flush_str, "%d", &control_flush_us); - if (control_flush_us == 0) { - fprintf(stderr, "ROCTracer: control flush rate bad value\n"); - abort(); - } + if (control_flush_us == 0) error("invalid control flush rate value '%s'", flush_str); - fprintf(stdout, "ROCTracer: trace control flush rate(%uus)\n", control_flush_us); - fflush(stdout); + std::cout << "ROCtracer: trace control flush rate(" << control_flush_us << "us)" << std::endl; flush_thread = new std::thread(flush_thr_fun); } } @@ -707,7 +690,7 @@ ROCTRACER_EXPORT bool OnLoad(HsaApiTable* table, uint64_t runtime_version, uint64_t failed_tool_count, const char* const* failed_tool_names) { if (roctracer_version_major() != ROCTRACER_VERSION_MAJOR || roctracer_version_minor() < ROCTRACER_VERSION_MINOR) { - warning("The ROCtracer API version is not compatible with this tool"); + warning("the ROCtracer API version is not compatible with this tool"); return true; } @@ -719,8 +702,7 @@ ROCTRACER_EXPORT bool OnLoad(HsaApiTable* table, uint64_t runtime_version, // Enable HSA API callbacks/activity if (trace_hsa_api) { - fprintf(stdout, " HSA-trace("); - fflush(stdout); + std::cout << " HSA-trace("; if (hsa_api_vec.size() != 0) { for (unsigned i = 0; i < hsa_api_vec.size(); ++i) { uint32_t cid = HSA_API_ID_NUMBER; @@ -728,13 +710,13 @@ ROCTRACER_EXPORT bool OnLoad(HsaApiTable* table, uint64_t runtime_version, CHECK_ROCTRACER(roctracer_op_code(ACTIVITY_DOMAIN_HSA_API, api, &cid, nullptr)); CHECK_ROCTRACER( roctracer_enable_op_callback(ACTIVITY_DOMAIN_HSA_API, cid, hsa_api_callback, nullptr)); - printf(" %s", api); + std::cout << " " << api; } } else { CHECK_ROCTRACER( roctracer_enable_domain_callback(ACTIVITY_DOMAIN_HSA_API, hsa_api_callback, nullptr)); } - printf(")\n"); + std::cout << std::endl; } // Enable HSA GPU activity @@ -742,15 +724,13 @@ ROCTRACER_EXPORT bool OnLoad(HsaApiTable* table, uint64_t runtime_version, // Allocating tracing pool open_tracing_pool(); - fprintf(stdout, " HSA-activity-trace()\n"); - fflush(stdout); + std::cout << " HSA-activity-trace()" << std::endl; CHECK_ROCTRACER(roctracer_enable_op_activity(ACTIVITY_DOMAIN_HSA_OPS, HSA_OP_ID_COPY)); } // Enable HIP API callbacks/activity if (trace_hip_api || trace_hip_activity) { - fprintf(stdout, " HIP-trace()\n"); - fflush(stdout); + std::cout << " HIP-trace()" << std::endl; // Allocating tracing pool open_tracing_pool(); @@ -763,7 +743,7 @@ ROCTRACER_EXPORT bool OnLoad(HsaApiTable* table, uint64_t runtime_version, CHECK_ROCTRACER(roctracer_op_code(ACTIVITY_DOMAIN_HIP_API, api, &cid, nullptr)); CHECK_ROCTRACER(roctracer_enable_op_callback(ACTIVITY_DOMAIN_HIP_API, cid, hip_api_callback, nullptr)); - printf(" %s", api); + std::cout << " " << api; } } else { CHECK_ROCTRACER( @@ -778,8 +758,7 @@ ROCTRACER_EXPORT bool OnLoad(HsaApiTable* table, uint64_t runtime_version, // Enable PC sampling if (trace_pcs) { - fprintf(stdout, " PCS-trace()\n"); - fflush(stdout); + std::cout << " PCS-trace()" << std::endl; open_tracing_pool(); CHECK_ROCTRACER(roctracer_enable_op_activity(ACTIVITY_DOMAIN_HSA_OPS, HSA_OP_ID_RESERVED1)); } diff --git a/projects/roctracer/src/util/debug.cpp b/projects/roctracer/src/util/debug.cpp index 46c2ab8d00..760aea5c45 100644 --- a/projects/roctracer/src/util/debug.cpp +++ b/projects/roctracer/src/util/debug.cpp @@ -43,7 +43,7 @@ struct BackTraceInfo { void errorCallback(void* data, const char* message, int errnum) { BackTraceInfo* info = static_cast(data); - info->sstream << "Error: " << message << '(' << errnum << ')'; + info->sstream << "ROCtracer error: " << message << '(' << errnum << ')'; info->error = 1; } @@ -90,10 +90,18 @@ namespace roctracer { void warning(const char* format, ...) { va_list va; va_start(va, format); - std::cerr << "Warning: " << string_vprintf(format, va) << std::endl; + std::cerr << "ROCtracer warning: " << string_vprintf(format, va) << std::endl; va_end(va); } +void error(const char* format, ...) { + va_list va; + va_start(va, format); + std::cerr << "ROCtracer error: " << string_vprintf(format, va) << std::endl; + va_end(va); + exit(EXIT_FAILURE); +} + void fatal [[noreturn]] (const char* format, ...) { va_list va; va_start(va, format); @@ -110,7 +118,7 @@ void fatal [[noreturn]] (const char* format, ...) { message += info.sstream.str(); #endif /* defined (ENABLE_BACKTRACE) */ - std::cerr << "Error: " << message << std::endl; + std::cerr << "ROCtracer fatal error: " << message << std::endl; abort(); } diff --git a/projects/roctracer/src/util/debug.h b/projects/roctracer/src/util/debug.h index 9e295c1b27..d90afb48e9 100644 --- a/projects/roctracer/src/util/debug.h +++ b/projects/roctracer/src/util/debug.h @@ -28,6 +28,12 @@ extern void warning(const char* format, ...) #endif // defined (__GNUC__) ; +extern void error [[noreturn]] (const char* format, ...) +#if defined(__GNUC__) +__attribute__((format(printf, 1, 2))) +#endif // defined (__GNUC__) +; + extern void fatal [[noreturn]] (const char* format, ...) #if defined(__GNUC__) __attribute__((format(printf, 1, 2))) @@ -35,3 +41,7 @@ __attribute__((format(printf, 1, 2))) ; } // namespace roctracer + +using roctracer::error; +using roctracer::fatal; +using roctracer::warning;