From 7b77d801145d63f957d6ca4c2da97d2af53f0132 Mon Sep 17 00:00:00 2001 From: Hariharan Devarajan Date: Sun, 8 Oct 2023 12:33:39 -0700 Subject: [PATCH] fixes to improve test cases. --- dlio_profiler/logger.py | 22 ++++++++------- src/dlio_profiler/core/dlio_profiler_main.h | 14 +++++----- src/dlio_profiler/dlio_profiler_preload.cpp | 8 +----- src/dlio_profiler/dlio_profiler_py.cpp | 12 ++++----- src/dlio_profiler/writer/chrome_writer.cpp | 4 +-- test/CMakeLists.txt | 20 ++++++++------ test/check_file.sh | 6 +++-- test/py/test.py | 30 ++++++++++++++------- 8 files changed, 66 insertions(+), 50 deletions(-) diff --git a/dlio_profiler/logger.py b/dlio_profiler/logger.py index 71bad527..a6f1f4ba 100644 --- a/dlio_profiler/logger.py +++ b/dlio_profiler/logger.py @@ -32,22 +32,26 @@ def __init__(self, logfile): def get_instance(cls, log_file=None): """ Static access method. """ if dlio_logger.__instance is None: - if log_file: - dlio_logger(log_file) - else: - raise Exception("log_file needs to be passed for first initialization.") + dlio_logger(log_file) return dlio_logger.__instance @staticmethod def initialize_log(logfile, data_dir, process_id): - log_file = Path(logfile) + log_file = None + if logfile : + log_file = Path(logfile) instance = dlio_logger.get_instance(log_file) if DLIO_PROFILER_ENABLE: - os.makedirs(log_file.parent, exist_ok=True) - if os.path.isfile(log_file): - os.remove(log_file) + if log_file: + os.makedirs(log_file.parent, exist_ok=True) + if os.path.isfile(log_file): + os.remove(log_file) instance.logger = profiler - instance.logger.initialize(f"{instance.logfile}", f"{data_dir}", process_id=process_id) + if log_file: + log_file = f"{instance.logfile}" + if data_dir: + data_dir = f"{data_dir}" + instance.logger.initialize(log_file = log_file, data_dirs = data_dir, process_id=process_id) return instance def get_time(self): diff --git a/src/dlio_profiler/core/dlio_profiler_main.h b/src/dlio_profiler/core/dlio_profiler_main.h index 6e277e50..4552ab2e 100644 --- a/src/dlio_profiler/core/dlio_profiler_main.h +++ b/src/dlio_profiler/core/dlio_profiler_main.h @@ -123,11 +123,6 @@ namespace dlio_profiler { stdio_instance->trace(path.c_str()); } } - size_t thread_hash = std::hash{}(std::this_thread::get_id()); - DLIO_PROFILER_LOGINFO("Running DLIO Profiler on thread %ld and pid %ld", thread_hash, this->process_id); - if (this->process_id == 0) - DLIO_PROFILER_LOGPRINT("Running DLIO Profiler with log_file %s data_dir %s and process %d", - this->log_file.c_str(), this->data_dirs.c_str(), this->process_id); } is_initialized = true; } @@ -142,6 +137,8 @@ namespace dlio_profiler { if (user_init_type != nullptr && strcmp(user_init_type, "PRELOAD") == 0) { initlialize(true, true, log_file, data_dirs, process_id); } + DLIO_PROFILER_LOGINFO("Preloading DLIO Profiler with log_file %s data_dir %s and process %d", + this->log_file.c_str(), this->data_dirs.c_str(), this->process_id); } break; } @@ -150,10 +147,12 @@ namespace dlio_profiler { case ProfileType::PROFILER_CPP_APP: { if (stage == ProfilerStage::PROFILER_INIT) { bool bind = false; - if (user_init_type != nullptr && strcmp(user_init_type, "FUNCTION") == 0) { + if (user_init_type == nullptr || strcmp(user_init_type, "FUNCTION") == 0) { bind = true; } initlialize(true, bind, log_file, data_dirs, process_id); + DLIO_PROFILER_LOGINFO("Initializing DLIO Profiler with log_file %s data_dir %s and process %d", + this->log_file.c_str(), this->data_dirs.c_str(), this->process_id); } break; } @@ -183,11 +182,12 @@ namespace dlio_profiler { bool finalize() { if (this->is_initialized && is_enabled) { - DLIO_PROFILER_LOGINFO("Calling finalize", ""); + DLIO_PROFILER_LOGINFO("Calling finalize on pid %d", this->process_id); dlio_profiler::Singleton::get_instance(false)->finalize(); if (bind) { free_bindings(); } + this->is_initialized = false; return true; } return false; diff --git a/src/dlio_profiler/dlio_profiler_preload.cpp b/src/dlio_profiler/dlio_profiler_preload.cpp index b9854b95..48db21ce 100644 --- a/src/dlio_profiler/dlio_profiler_preload.cpp +++ b/src/dlio_profiler/dlio_profiler_preload.cpp @@ -14,15 +14,9 @@ namespace dlio_profiler { bool is_init() {return dlio_profiler::init;} void set_init(bool _init) { dlio_profiler::init = _init;} void dlio_profiler_init(void) { - if (!is_init()) { dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_INIT, ProfileType::PROFILER_PRELOAD); - set_init(true); - } - } void dlio_profiler_fini(void) { - if (is_init()) { dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_FINI, ProfileType::PROFILER_PRELOAD)->finalize(); - set_init(false); - } + } \ No newline at end of file diff --git a/src/dlio_profiler/dlio_profiler_py.cpp b/src/dlio_profiler/dlio_profiler_py.cpp index 7214a549..024c932c 100644 --- a/src/dlio_profiler/dlio_profiler_py.cpp +++ b/src/dlio_profiler/dlio_profiler_py.cpp @@ -20,11 +20,11 @@ namespace dlio_profiler { - void initialize(std::string &log_file, std::string &data_dirs, int process_id) { - dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_INIT, ProfileType::PROFILER_PY_APP, log_file.c_str(), data_dirs.c_str(), &process_id); + void initialize(const char* log_file, const char* data_dirs, int process_id) { + dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_INIT, ProfileType::PROFILER_PY_APP, log_file, data_dirs, &process_id); } TimeResolution get_time() { - return dlio_profiler::Singleton::get_instance(false)->get_time(); + return dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_OTHER, ProfileType::PROFILER_PY_APP)->get_time(); } void log_event(std::string &name, std::string &cat, TimeResolution start_time, TimeResolution duration, std::unordered_map &int_args, @@ -34,7 +34,7 @@ namespace dlio_profiler { for (auto item:int_args) args.insert_or_assign(item.first, item.second); for (auto item:string_args) args.insert_or_assign(item.first, item.second); for (auto item:float_args) args.insert_or_assign(item.first, item.second); - dlio_profiler::Singleton::get_instance(false)->log(name, cat, start_time, duration, args); + dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_OTHER, ProfileType::PROFILER_PY_APP)->log(name.c_str(), cat.c_str(), start_time, duration, args); } void finalize() { dlio_profiler::Singleton::get_instance(ProfilerStage::PROFILER_FINI, ProfileType::PROFILER_PY_APP)->finalize(); @@ -43,8 +43,8 @@ namespace dlio_profiler { PYBIND11_MODULE(dlio_profiler_py, m) { m.doc() = "Python module for dlio_logger"; // optional module docstring m.def("initialize", &dlio_profiler::initialize, "initialize dlio profiler", - py::arg("log_file"), - py::arg("data_dirs"), + py::arg("log_file") = nullptr, + py::arg("data_dirs") = nullptr, py::arg("process_id") = -1); m.def("get_time", &dlio_profiler::get_time, "get time from profiler"); m.def("log_event", &dlio_profiler::log_event, "log event with args", diff --git a/src/dlio_profiler/writer/chrome_writer.cpp b/src/dlio_profiler/writer/chrome_writer.cpp index 2fb751c9..89f91dd0 100644 --- a/src/dlio_profiler/writer/chrome_writer.cpp +++ b/src/dlio_profiler/writer/chrome_writer.cpp @@ -82,7 +82,7 @@ dlio_profiler::ChromeWriter::convert_json(std::string &event_name, std::string & } auto start_sec = std::chrono::duration>(start_time); auto duration_sec = std::chrono::duration>(duration); - if (is_first_write) all_stream << " "; + if (is_first_write) all_stream << " "; all_stream << R"({"name":")" << event_name << "\"," << R"("cat":")" << category << "\"," << "\"pid\":" << pid << "," @@ -136,6 +136,6 @@ dlio_profiler::ChromeWriter::convert_json(std::string &event_name, std::string & } all_stream << "}"; all_stream << "}\n"; - DLIO_PROFILER_LOGINFO("event logged %s", all_stream.str().c_str()); + DLIO_PROFILER_LOGINFO("event logged %s into %s", all_stream.str().c_str(), this->filename.c_str()); return all_stream.str(); } diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 990650b1..d9ec605c 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -21,7 +21,7 @@ set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INIT=PR set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_DATA_DIR=${CMAKE_CURRENT_BINARY_DIR}/data) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}) -add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}*) +add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}* 7) set_tests_properties(check_file_exists_${test_name} PROPERTIES DEPENDS ${test_name}) find_program (BASH_PROGRAM bash) @@ -35,7 +35,7 @@ set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INIT=PR set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_DATA_DIR=${CMAKE_CURRENT_BINARY_DIR}/data) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}) -add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}*) +add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}* 7) set_tests_properties(check_file_exists_${test_name} PROPERTIES DEPENDS ${test_name}) set(test_name test_cpp_basic_meta) @@ -49,7 +49,7 @@ set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_FIL set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_LEVEL=INFO) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INC_METADATA=1) -add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}*) +add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}* 7) set_tests_properties(check_file_exists_${test_name} PROPERTIES DEPENDS ${test_name}) set(test_name test_cpp_basic_affinity) @@ -64,7 +64,7 @@ set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_LEV set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INC_METADATA=1) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_SET_CORE_AFFINITY=1) -add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}*) +add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}* 7) set_tests_properties(check_file_exists_${test_name} PROPERTIES DEPENDS ${test_name}) @@ -73,12 +73,14 @@ message("-- Found python at location " ${PYTHON_EXE}) set(test_name test_py_only) add_test(${test_name} ${PYTHON_EXE} ${CMAKE_CURRENT_SOURCE_DIR}/py/test.py) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT PYTHONPATH=$ENV{PYTHONPATH}:${CMAKE_SOURCE_DIR}/venv/lib) -set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}_app) +set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}_app) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT LD_LIBRARY_PATH=${CMAKE_BINARY_DIR}/lib:${CMAKE_SOURCE_DIR}/dependency/.spack-env/view/lib64) +set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_DATA_DIR=${CMAKE_CURRENT_BINARY_DIR}/data) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_ENABLE=1) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_LEVEL=INFO) +set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INC_METADATA=1) -add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}*) +add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}* 84) set_tests_properties(check_file_exists_${test_name} PROPERTIES DEPENDS ${test_name}) find_program(PYTHON_EXE python) @@ -87,12 +89,14 @@ set(test_name test_py_both) add_test(${test_name} ${PYTHON_EXE} ${CMAKE_CURRENT_SOURCE_DIR}/py/test.py) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT PYTHONPATH=$ENV{PYTHONPATH}:${CMAKE_SOURCE_DIR}/venv/lib) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT LD_LIBRARY_PATH=${CMAKE_BINARY_DIR}/lib:${CMAKE_SOURCE_DIR}/dependency/.spack-env/view/lib64) -set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}_app) +set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}_app) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT LD_PRELOAD=${CMAKE_BINARY_DIR}/lib/libdlio_profiler_preload.so) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_DATA_DIR=${CMAKE_CURRENT_BINARY_DIR}/data) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_FILE=${CMAKE_CURRENT_BINARY_DIR}/${test_name}) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INIT=PRELOAD) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_ENABLE=1) set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_LOG_LEVEL=INFO) -add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}*) +set_property(TEST ${test_name} APPEND PROPERTY ENVIRONMENT DLIO_PROFILER_INC_METADATA=1) + +add_test(check_file_exists_${test_name} ${BASH_PROGRAM} ${CMAKE_CURRENT_SOURCE_DIR}/check_file.sh ${CMAKE_CURRENT_BINARY_DIR}/${test_name}* 85) set_tests_properties(check_file_exists_${test_name} PROPERTIES DEPENDS ${test_name}) diff --git a/test/check_file.sh b/test/check_file.sh index ad0c585f..45d023ed 100644 --- a/test/check_file.sh +++ b/test/check_file.sh @@ -1,7 +1,9 @@ #!/bin/bash +expected_lines=$2 echo "cat $1 | grep POSIX | wc -l" num_posix_lines=$(cat $1 | wc -l) echo $num_posix_lines -if [[ "$num_posix_lines" == '0' ]]; then +if [[ "$num_posix_lines" -ne "$expected_lines" ]]; then exit 1 -fi \ No newline at end of file +fi +rm $1 \ No newline at end of file diff --git a/test/py/test.py b/test/py/test.py index bc7bcf0c..3f42a97b 100644 --- a/test/py/test.py +++ b/test/py/test.py @@ -10,11 +10,11 @@ cwd = os.getcwd() log_file=os.getenv("LOG_FILE", f"{cwd}/test_py-app.pwf") -log_inst = dlio_logger.initialize_log(log_file, f"{cwd}/data", -1) +log_inst = dlio_logger.initialize_log(logfile=None, data_dir=None, process_id=-1) dlio_log = fn_interceptor("COMPUTE") @dlio_log.log -def log_events(): +def log_events(index): sleep(1) def custom_events(): @@ -28,11 +28,17 @@ def custom_events(): log_inst.log_event("test", "cat2", start, end - start, int_args=args) -def posix_calls(index): +def posix_calls(val): + index, is_spawn = val path=f"{cwd}/data/demofile{index}.txt" f = open(path, "w+") f.write("Now the file has more content!") f.close() + if is_spawn: + print(f"Calling spawn on {index} with pid {os.getpid()}") + log_inst.finalize() + else: + print(f"Not calling spawn on {index} with pid {os.getpid()}") def npz_calls(index): #print(f"{cwd}/data/demofile2.npz") @@ -57,23 +63,29 @@ def init(): print(f'Initializing process {os.getpid()}') def main(): - t1 = threading.Thread(target=posix_calls, args=(10,)) + t1 = threading.Thread(target=posix_calls, args=(10,False)) custom_events() t2 = threading.Thread(target=npz_calls, args=(1,)) t3 = threading.Thread(target=jpeg_calls, args=(2,)) + t4 = threading.Thread(target=log_events, args=(3,)) # starting thread 1 t1.start() t2.start() t3.start() + t4.start() t1.join() t2.join() t3.join() - index = 3 - for context in ('fork', 'spawn'): - with get_context(context).Pool(2, initializer=init) as pool: - pool.map(posix_calls, (index, index + 1, index + 2)) - index = index + 3 + t4.join() + index = 4 + with get_context('fork').Pool(1, initializer=init) as pool: + pool.map(posix_calls, ((index,False),)) + index = index + 1 + + with get_context('spawn').Pool(1, initializer=init) as pool: + pool.map(posix_calls, ((index, True),)) + index = index + 1 log_inst.finalize()