diff --git a/dftracer/logger.py b/dftracer/logger.py index 8b7cdd3..ccdb518 100644 --- a/dftracer/logger.py +++ b/dftracer/logger.py @@ -100,6 +100,11 @@ def log_event(self, name, cat, start_time, duration, string_args=None): string_args = {} self.logger.log_event(name=name, cat=cat, start_time=start_time, duration=duration, string_args=string_args) + def log_metadata_event(self, key, value): + if DFTRACER_ENABLE and self.logger: + logging.debug(f"logger.log_metadata_event {key} {value}") + self.logger.log_metadata_event(key=key, value=value) + def finalize(self): if DFTRACER_ENABLE and self.logger: logging.debug(f"logger.finalize") @@ -221,6 +226,10 @@ def wrapper(*args, **kwargs): return wrapper + def log_metadata(self, key, value): + if DFTRACER_ENABLE and self._enable: + dftracer.get_instance().log_metadata_event(key=key, value=value) + def iter(self, func, iter_name="step"): if DFTRACER_ENABLE and self._enable: iter_val = 1 diff --git a/dftracer_dbg/logger.py b/dftracer_dbg/logger.py index 4fd113e..d39ac47 100644 --- a/dftracer_dbg/logger.py +++ b/dftracer_dbg/logger.py @@ -99,6 +99,13 @@ def log_event(self, name, cat, start_time, duration, string_args=None): if string_args is None: string_args = {} self.logger.log_event(name=name, cat=cat, start_time=start_time, duration=duration, string_args=string_args) + + def log_metadata_event(self, key, value): + if DFTRACER_ENABLE and self.logger: + logging.debug(f"logger.log_metadata_event {key} {value}") + if string_args is None: + string_args = {} + self.logger.log_metadata_event(key=key, value=value) def finalize(self): if DFTRACER_ENABLE and self.logger: @@ -171,7 +178,7 @@ def __exit__(self, exc_type, exc_val, exc_tb): if DFTRACER_ENABLE and self._enable: if not self._flush: self.flush() - + def log(self, func): if DFTRACER_ENABLE and self._enable: arg_names = inspect.getfullargspec(func)[0] @@ -221,6 +228,10 @@ def wrapper(*args, **kwargs): return wrapper + def log_metadata(self, key, value): + if DFTRACER_ENABLE and self._enable: + dftracer.get_instance().log_metadata_event(key=key, value=value) + def iter(self, func, iter_name="step"): if DFTRACER_ENABLE and self._enable: iter_val = 1 diff --git a/include/dftracer/dftracer.h b/include/dftracer/dftracer.h index aa1668f..beba9de 100644 --- a/include/dftracer/dftracer.h +++ b/include/dftracer/dftracer.h @@ -10,7 +10,8 @@ */ #include #include - +#define DF_DATA_EVENT 0 +#define DF_METADATA_EVENT 1 #ifdef __cplusplus extern "C" { #endif @@ -37,6 +38,7 @@ void finalize(); __attribute__((unused)) static ConstEventNameType CPP_LOG_CATEGORY = "CPP_APP"; class DFTracer { + int event_type; // 0->event 1->metadata bool initialized; ConstEventNameType name; ConstEventNameType cat; @@ -44,7 +46,8 @@ class DFTracer { std::unordered_map *metadata; public: - DFTracer(ConstEventNameType _name, ConstEventNameType _cat); + DFTracer(ConstEventNameType _name, ConstEventNameType _cat, + int event_type = DF_DATA_EVENT); void update(const char *key, int value); @@ -61,13 +64,18 @@ class DFTracer { initialize_no_bind(log_file, data_dirs, process_id); #define DFTRACER_CPP_FINI() finalize() #define DFTRACER_CPP_FUNCTION() \ - DFTracer profiler_dft_fn = DFTracer((char *)__FUNCTION__, CPP_LOG_CATEGORY); + DFTracer profiler_dft_fn = \ + DFTracer((char *)__FUNCTION__, CPP_LOG_CATEGORY, DF_DATA_EVENT); + +#define DFTRACER_CPP_METADATA(name, key, value) \ + { DFTracer profiler_##name = DFTracer(key, value, DF_METADATA_EVENT); } #define DFTRACER_CPP_REGION(name) \ - DFTracer profiler_##name = DFTracer(#name, CPP_LOG_CATEGORY); + DFTracer profiler_##name = DFTracer(#name, CPP_LOG_CATEGORY, DF_DATA_EVENT); #define DFTRACER_CPP_REGION_START(name) \ - DFTracer *profiler_##name = new DFTracer(#name, CPP_LOG_CATEGORY); + DFTracer *profiler_##name = \ + new DFTracer(#name, CPP_LOG_CATEGORY, DF_DATA_EVENT); #define DFTRACER_CPP_REGION_END(name) delete profiler_##name @@ -89,7 +97,7 @@ struct DFTracerData { __attribute__((unused)) static ConstEventNameType C_LOG_CATEGORY = "C_APP"; struct DFTracerData *initialize_region(ConstEventNameType name, - ConstEventNameType cat); + ConstEventNameType cat, int event_type); void finalize_region(struct DFTracerData *data); void update_metadata_int(struct DFTracerData *data, const char *key, int value); void update_metadata_string(struct DFTracerData *data, const char *key, @@ -102,15 +110,24 @@ void update_metadata_string(struct DFTracerData *data, const char *key, #define DFTRACER_C_FINI() finalize() #define DFTRACER_C_FUNCTION_START() \ - struct DFTracerData *data_fn = initialize_region(__func__, C_LOG_CATEGORY); + struct DFTracerData *data_fn = \ + initialize_region(__func__, C_LOG_CATEGORY, DF_DATA_EVENT); #define DFTRACER_C_FUNCTION_END() finalize_region(data_fn); #define DFTRACER_C_REGION_START(name) \ - struct DFTracerData *data_##name = initialize_region(#name, C_LOG_CATEGORY); + struct DFTracerData *data_##name = \ + initialize_region(#name, C_LOG_CATEGORY, DF_DATA_EVENT); #define DFTRACER_C_REGION_END(name) finalize_region(data_##name); +#define DFTRACER_C_METADATA(name, key, val) \ + { \ + struct DFTracerData *data_##name = \ + initialize_region(key, val, DF_METADATA_EVENT); \ + finalize_region(data_##name); \ + } + #define DFTRACER_C_FUNCTION_UPDATE_INT(key, val) \ update_metadata_int(data_fn, key, val); diff --git a/src/dftracer/core/dftracer_main.cpp b/src/dftracer/core/dftracer_main.cpp index 324891e..04f0ae5 100644 --- a/src/dftracer/core/dftracer_main.cpp +++ b/src/dftracer/core/dftracer_main.cpp @@ -89,6 +89,16 @@ void dftracer::DFTracerCore::log( } } +void dftracer::DFTracerCore::log_metadata(ConstEventNameType key, ConstEventNameType value) { + DFTRACER_LOG_DEBUG("DFTracerCore::log", ""); + if (this->is_initialized && conf->enable) { + if (logger != nullptr) { + logger->log_metadata(key, value); + } else { + DFTRACER_LOG_ERROR("DFTracerCore::log logger not initialized", ""); + } + } +} bool dftracer::DFTracerCore::finalize() { DFTRACER_LOG_DEBUG("DFTracerCore::finalize", ""); if (this->is_initialized && conf->enable) { diff --git a/src/dftracer/core/dftracer_main.h b/src/dftracer/core/dftracer_main.h index 4e54bcf..725e4cb 100644 --- a/src/dftracer/core/dftracer_main.h +++ b/src/dftracer/core/dftracer_main.h @@ -55,6 +55,8 @@ class DFTracerCore { void log(ConstEventNameType event_name, ConstEventNameType category, TimeResolution start_time, TimeResolution duration, std::unordered_map *metadata); + + void log_metadata(ConstEventNameType key, ConstEventNameType value); inline void enter_event() { logger->enter_event(); } diff --git a/src/dftracer/core/enumeration.h b/src/dftracer/core/enumeration.h index 5199ed3..ae6b30f 100644 --- a/src/dftracer/core/enumeration.h +++ b/src/dftracer/core/enumeration.h @@ -51,4 +51,5 @@ inline void convert(const std::string &s, cpplogger::LoggerType &type) { #define METADATA_NAME_FILE_HASH "FH" #define METADATA_NAME_HOSTNAME_HASH "HH" #define METADATA_NAME_STRING_HASH "SH" +#define CUSTOM_METADATA "CM" #endif // DFTRACER_ENUMERATION_H diff --git a/src/dftracer/df_logger.h b/src/dftracer/df_logger.h index 897a135..556f072 100644 --- a/src/dftracer/df_logger.h +++ b/src/dftracer/df_logger.h @@ -238,23 +238,7 @@ class DFTLogger { return t; } - inline void log(ConstEventNameType event_name, ConstEventNameType category, - TimeResolution start_time, TimeResolution duration, - std::unordered_map *metadata) { - DFTRACER_LOG_DEBUG("DFTLogger.log", ""); - ThreadID tid = 0; - if (dftracer_tid) { - tid = df_gettid(); - } - int local_index; - if (!include_metadata) { - local_index = index.load(); - } - if (metadata != nullptr) { - metadata->insert_or_assign("level", level); - int parent_index_value = get_parent(); - metadata->insert_or_assign("p_idx", parent_index_value); - } + inline void handle_mpi(ThreadID tid) { #ifdef DFTRACER_MPI_ENABLE if (!mpi_event) { int initialized; @@ -281,7 +265,26 @@ class DFTLogger { } } #endif + } + inline void log(ConstEventNameType event_name, ConstEventNameType category, + TimeResolution start_time, TimeResolution duration, + std::unordered_map *metadata) { + DFTRACER_LOG_DEBUG("DFTLogger.log", ""); + ThreadID tid = 0; + if (dftracer_tid) { + tid = df_gettid(); + } + int local_index; + if (!include_metadata) { + local_index = index.load(); + } + if (metadata != nullptr) { + metadata->insert_or_assign("level", level); + int parent_index_value = get_parent(); + metadata->insert_or_assign("p_idx", parent_index_value); + } + handle_mpi(tid); if (this->writer != nullptr) { if (include_metadata) { int current_index = get_current(); @@ -298,6 +301,26 @@ class DFTLogger { } } + inline void log_metadata(ConstEventNameType key, ConstEventNameType value) { + DFTRACER_LOG_DEBUG("DFTLogger.log_metadata", ""); + ThreadID tid = 0; + if (dftracer_tid) { + tid = df_gettid(); + } + int local_index; + if (!include_metadata) { + local_index = index.load(); + } + handle_mpi(tid); + if (this->writer != nullptr) { + this->writer->log_metadata(index_stack[level - 1], key, value, + CUSTOM_METADATA, this->process_id, tid); + has_entry = true; + } else { + DFTRACER_LOG_ERROR("DFTLogger.log_metadata writer not initialized", ""); + } + } + inline uint16_t hash_and_store(char *filename, ConstEventNameType name) { if (filename == NULL) return 0; char file[PATH_MAX]; diff --git a/src/dftracer/dftracer.cpp b/src/dftracer/dftracer.cpp index 11190d2..852e282 100644 --- a/src/dftracer/dftracer.cpp +++ b/src/dftracer/dftracer.cpp @@ -6,36 +6,47 @@ #include #include -DFTracer::DFTracer(ConstEventNameType _name, ConstEventNameType _cat) - : initialized(true), name(_name), cat(_cat), metadata(nullptr) { +DFTracer::DFTracer(ConstEventNameType _name, ConstEventNameType _cat, + int event_type) + : initialized(true), + name(_name), + cat(_cat), + metadata(nullptr), + event_type(event_type) { DFTRACER_LOG_DEBUG("DFTracer::DFTracer event %s cat %s ", _name, _cat); auto dftracer_core = DFTRACER_MAIN_SINGLETON(ProfilerStage::PROFILER_OTHER, ProfileType::PROFILER_CPP_APP); if (dftracer_core != nullptr) { - if (dftracer_core->include_metadata) - metadata = new std::unordered_map(); - start_time = dftracer_core->get_time(); + if (event_type == DF_DATA_EVENT) { + if (dftracer_core->include_metadata) + metadata = new std::unordered_map(); + start_time = dftracer_core->get_time(); + } } dftracer_core->enter_event(); } void DFTracer::update(const char *key, int value) { DFTRACER_LOG_DEBUG("DFTracer::update event %s cat %s key %s value %d ", name, cat, key, value); - auto dftracer_core = DFTRACER_MAIN_SINGLETON(ProfilerStage::PROFILER_OTHER, - ProfileType::PROFILER_CPP_APP); - if (dftracer_core != nullptr && dftracer_core->is_active() && - dftracer_core->include_metadata) { - metadata->insert_or_assign(key, value); + if (event_type == DF_DATA_EVENT) { + auto dftracer_core = DFTRACER_MAIN_SINGLETON(ProfilerStage::PROFILER_OTHER, + ProfileType::PROFILER_CPP_APP); + if (dftracer_core != nullptr && dftracer_core->is_active() && + dftracer_core->include_metadata) { + metadata->insert_or_assign(key, value); + } } } void DFTracer::update(const char *key, const char *value) { DFTRACER_LOG_DEBUG("DFTracer::update event %s cat %s key %s value %s ", name, cat, key, value); - auto dftracer_core = DFTRACER_MAIN_SINGLETON(ProfilerStage::PROFILER_OTHER, - ProfileType::PROFILER_CPP_APP); - if (dftracer_core != nullptr && dftracer_core->is_active() && - dftracer_core->include_metadata) { - metadata->insert_or_assign(key, value); + if (event_type == DF_DATA_EVENT) { + auto dftracer_core = DFTRACER_MAIN_SINGLETON(ProfilerStage::PROFILER_OTHER, + ProfileType::PROFILER_CPP_APP); + if (dftracer_core != nullptr && dftracer_core->is_active() && + dftracer_core->include_metadata) { + metadata->insert_or_assign(key, value); + } } } void DFTracer::finalize() { @@ -43,8 +54,13 @@ void DFTracer::finalize() { auto dftracer_core = DFTRACER_MAIN_SINGLETON(ProfilerStage::PROFILER_OTHER, ProfileType::PROFILER_CPP_APP); if (dftracer_core != nullptr && dftracer_core->is_active()) { - TimeResolution end_time = dftracer_core->get_time(); - dftracer_core->log(name, cat, start_time, end_time - start_time, metadata); + if (event_type == DF_DATA_EVENT) { + TimeResolution end_time = dftracer_core->get_time(); + dftracer_core->log(name, cat, start_time, end_time - start_time, + metadata); + } else if (event_type == DF_METADATA_EVENT) { + dftracer_core->log_metadata(name, cat); + } dftracer_core->exit_event(); if (dftracer_core->include_metadata) delete (metadata); @@ -73,10 +89,10 @@ void initialize_no_bind(const char *log_file, const char *data_dirs, } struct DFTracerData *initialize_region(ConstEventNameType name, - ConstEventNameType cat) { + ConstEventNameType cat, int event_type) { DFTRACER_LOG_DEBUG("dftracer.initialize_region event %s cat %s", name, cat); auto data = new DFTracerData(); - data->profiler = new DFTracer(name, C_LOG_CATEGORY); + data->profiler = new DFTracer(name, cat, event_type); return data; } void finalize_region(struct DFTracerData *data) { diff --git a/src/dftracer/pydftracer.cpp b/src/dftracer/pydftracer.cpp index 948bae9..5474072 100644 --- a/src/dftracer/pydftracer.cpp +++ b/src/dftracer/pydftracer.cpp @@ -31,5 +31,7 @@ PYBIND11_MODULE(pydftracer, m) { py::arg("int_args") = std::unordered_map(), py::arg("string_args") = std::unordered_map(), py::arg("float_args") = std::unordered_map()); + m.def("log_metadata_event", &dftracer::log_metadata_event, + "log metadata event", py::arg("key"), py::arg("value")); m.def("finalize", &dftracer::finalize, "finalize dftracer"); } diff --git a/src/dftracer/pydftracer.cpp.in b/src/dftracer/pydftracer.cpp.in index a84a77a..87dca74 100644 --- a/src/dftracer/pydftracer.cpp.in +++ b/src/dftracer/pydftracer.cpp.in @@ -41,6 +41,17 @@ void log_event(std::string name, std::string cat, TimeResolution start_time, DFTRACER_LOG_DEBUG("py.log_event dftracer not initialized", ""); } +void log_metadata_event(std::string key, std::string value) { + DFTRACER_LOG_DEBUG("py.log_metadata_event", ""); + auto dftracer_inst = + dftracer::Singleton::get_instance( + ProfilerStage::PROFILER_OTHER, ProfileType::PROFILER_PY_APP); + if (dftracer_inst != nullptr) + dftracer_inst->log_metadata(key.c_str(), value.c_str()); + else + DFTRACER_LOG_DEBUG("py.log_metadata_event dftracer not initialized", ""); +} + void enter_event() { DFTRACER_LOG_DEBUG("py.enter_event", ""); auto dftracer_inst = diff --git a/src/dftracer/pydftracer_dbg.cpp b/src/dftracer/pydftracer_dbg.cpp index d5eebb2..d7d44d3 100644 --- a/src/dftracer/pydftracer_dbg.cpp +++ b/src/dftracer/pydftracer_dbg.cpp @@ -31,5 +31,7 @@ PYBIND11_MODULE(pydftracer_dbg, m) { py::arg("int_args") = std::unordered_map(), py::arg("string_args") = std::unordered_map(), py::arg("float_args") = std::unordered_map()); + m.def("log_metadata_event", &dftracer::log_metadata_event, + "log metadata event", py::arg("key"), py::arg("value")); m.def("finalize", &dftracer::finalize, "finalize dftracer"); } diff --git a/test/c/test.c b/test/c/test.c index ffa2711..c295ce9 100644 --- a/test/c/test.c +++ b/test/c/test.c @@ -35,6 +35,7 @@ int main(int argc, char *argv[]) { init = 1; } } + DFTRACER_C_METADATA(meta, "key", "value"); char filename[1024]; sprintf(filename, "%s/demofile_c.txt", argv[1]); foo(); diff --git a/test/cpp/test.cpp b/test/cpp/test.cpp index 7ae752b..3ea4847 100644 --- a/test/cpp/test.cpp +++ b/test/cpp/test.cpp @@ -39,6 +39,7 @@ int main(int argc, char *argv[]) { init = 1; } } + DFTRACER_CPP_METADATA(meta, "key", "value"); char filename[1024]; sprintf(filename, "%s/demofile.txt", argv[1]); char filename_link[1024]; diff --git a/test/py/test.py b/test/py/test.py index 0ea9e1f..91f8c0d 100644 --- a/test/py/test.py +++ b/test/py/test.py @@ -148,6 +148,7 @@ def with_default_args(step=2): def main(): + dft_fn.log_metadata("key", "value") posix_calls((20, False)) t1 = threading.Thread(target=posix_calls, args=((10, False),)) custom_events()