diff --git a/.clang-format b/.clang-format index f170fa6..833a44c 100644 --- a/.clang-format +++ b/.clang-format @@ -33,7 +33,7 @@ BreakBeforeBinaryOperators: None BreakBeforeTernaryOperators: true BreakConstructorInitializers: BeforeColon BreakInheritanceList: BeforeColon -ColumnLimit: 0 +ColumnLimit: 140 CompactNamespaces: false ContinuationIndentWidth: 8 IndentCaseLabels: true diff --git a/.idea/cmake.xml b/.idea/cmake.xml index b7ec5ba..52f8459 100644 --- a/.idea/cmake.xml +++ b/.idea/cmake.xml @@ -4,6 +4,7 @@ + \ No newline at end of file diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 856483f..2635a17 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -2,6 +2,7 @@ set(CMAKE_CXX_STANDARD 17) set(CMAKE_CXX_STANDARD_REQUIRED ON) add_subdirectory(vm) +add_subdirectory(logger) add_executable(psil main.cpp) diff --git a/src/logger/CMakeLists.txt b/src/logger/CMakeLists.txt new file mode 100644 index 0000000..e62d350 --- /dev/null +++ b/src/logger/CMakeLists.txt @@ -0,0 +1,6 @@ +set(CMAKE_CXX_STANDARD 17) +set(CMAKE_CXX_STANDARD_REQUIRED ON) + +add_library(logger src/Logger.cpp) + +target_include_directories(logger PUBLIC include) diff --git a/src/logger/include/Logger.h b/src/logger/include/Logger.h new file mode 100644 index 0000000..758fba9 --- /dev/null +++ b/src/logger/include/Logger.h @@ -0,0 +1,49 @@ +// +// Created by stepus53 on 3.1.24. +// + +#ifndef PSIL_LOGGER_H +#define PSIL_LOGGER_H + +#include +#include +#include +#include +#include +#include + +class Logger { +public: + enum LogLevel { DISABLED = 0, ERROR = 1, INFO = 2, DEBUG = 3, TRACE = 4 }; + static void log(const std::string &tag, const std::string &what, int level); + static void log(const std::string &tag, const std::function &fn, int level); + + // 0 - disabled + // 1 - error + // 2 - info + // 3 - debug + // 4 - trace + static void set_level(const std::string &tag, int level); + static void set_default_level(int level); + + static void set_out(std::ostream &out); + static void set_out_err(std::ostream &out_err); + +private: + static Logger &get(); + + std::unordered_map _levels; + static inline std::unordered_map _level_names{ + {ERROR, "ERROR"}, + {INFO, "INFO"}, + {DEBUG, "DEBUG"}, + {TRACE, "TRACE"}, + }; + int _default_level = 1; + std::chrono::time_point _start_time = std::chrono::high_resolution_clock::now(); + std::reference_wrapper _out = std::cout; + std::reference_wrapper _out_err = std::cerr; +}; + + +#endif//PSIL_LOGGER_H diff --git a/src/logger/src/Logger.cpp b/src/logger/src/Logger.cpp new file mode 100644 index 0000000..912155c --- /dev/null +++ b/src/logger/src/Logger.cpp @@ -0,0 +1,46 @@ +// +// Created by stepus53 on 3.1.24. +// + +#include "Logger.h" + +#include +#include + +Logger &Logger::get() { + static Logger logger; + return logger; +} + +void Logger::log(const std::string &tag, const std::string &what, int level) { + int en_level = get()._default_level; + if (get()._levels.find(tag) != get()._levels.end()) en_level = get()._levels.at(tag); + + if (en_level < level) return; + + auto now = std::chrono::high_resolution_clock::now(); + std::stringstream out; + out << std::setprecision(4) << std::fixed << "[" + << static_cast(std::chrono::duration_cast(now - get()._start_time).count()) / 1000.0 << "s]" + << "[" << tag << "][" << get()._level_names.at(level) << "] " << what << '\n'; + + if (level == 1) get()._out_err.get() << out.str(); + else + get()._out.get() << out.str(); +} + +void Logger::log(const std::string &tag, const std::function &fn, int level) { + int en_level = get()._default_level; + if (get()._levels.find(tag) != get()._levels.end()) en_level = get()._levels.at(tag); + + if (en_level < level) return; + + std::stringstream out; + fn(out); + log(tag, out.str(), level); +} + +void Logger::set_level(const std::string &tag, int level) { get()._levels[tag] = level; } +void Logger::set_out(std::ostream &out) { get()._out = out; } +void Logger::set_out_err(std::ostream &out_err) { get()._out_err = out_err; } +void Logger::set_default_level(int level) { get()._default_level = level; } diff --git a/src/vm/CMakeLists.txt b/src/vm/CMakeLists.txt index f0c3fbb..0628937 100644 --- a/src/vm/CMakeLists.txt +++ b/src/vm/CMakeLists.txt @@ -4,4 +4,6 @@ set(CMAKE_CXX_STANDARD_REQUIRED ON) add_library(vm src/VM.cpp src/Cell.cpp src/Parser.cpp src/MemoryContext.cpp src/Handle.cpp src/Compiler.cpp) +target_link_libraries(vm PUBLIC logger) + target_include_directories(vm PUBLIC include) diff --git a/src/vm/include/MemoryContext.h b/src/vm/include/MemoryContext.h index 97afdbf..744cd1b 100644 --- a/src/vm/include/MemoryContext.h +++ b/src/vm/include/MemoryContext.h @@ -18,6 +18,7 @@ #include "Cell.h" #include "Handle.h" +#include "Logger.h" class Handle; @@ -39,11 +40,8 @@ public: void request_gc_and_wait() { std::unique_lock l(_gc_done_m); _gc_done = false; - { - request_gc(); - } - if (!_gc_done) - _gc_done_cv.wait(l, [&] { return _gc_done.load(); }); + { request_gc(); } + if (!_gc_done) _gc_done_cv.wait(l, [&] { return _gc_done.load(); }); } void request_gc() { @@ -52,21 +50,16 @@ public: _gc_request_cv.notify_all(); } - size_t cell_count() { - return _cells_num; - } + size_t cell_count() { return _cells_num; } template R run_dirty(const std::function)> &f) { std::lock_guard l(_gc_dirty_notif_queue_lock); return f([&](Cell *c) { -// { -// std::stringstream out; -// out << "marked dirty: " << c << " \n"; -// std::cerr << out.str(); -// } - - _gc_dirty_notif_queue.emplace(c); }); + if (c == nullptr) return; + Logger::log("MemoryContext", [&](std::ostream &out) { out << "marked dirty: " << c; }, Logger::DEBUG); + _gc_dirty_notif_queue.emplace(c); + }); } private: @@ -81,7 +74,7 @@ private: if ((_cells_num + tcellnum) >= (_cell_limit)) { // We might need to run GC twice as it has to process the messages; - std::cerr << "Running forced GC" << std::endl; + Logger::log("MemoryContext", "Running forced gc", Logger::ERROR); for (int i = 0; i < 3 && (_cells_num + tcellnum) >= (_cell_limit); i++) { request_gc_and_wait(); { @@ -90,6 +83,8 @@ private: } } if ((_cells_num + tcellnum) >= (_cell_limit)) { + Logger::log("MemoryContext", "Out of cells", Logger::ERROR); + throw std::runtime_error("Out of cells"); } } @@ -100,9 +95,7 @@ private: std::lock_guard tmplg(_new_roots_lock); Handle ret(cell); _temp_cells.emplace_back(cell); - if ((_cells_num + _temp_cells.size() + 1) >= (size_t) (_cell_limit / 2)) { - request_gc(); - } + if ((_cells_num + _temp_cells.size() + 1) >= (size_t) (_cell_limit / 2)) { request_gc(); } return ret; } } diff --git a/src/vm/src/MemoryContext.cpp b/src/vm/src/MemoryContext.cpp index 0171f5e..376ec8a 100644 --- a/src/vm/src/MemoryContext.cpp +++ b/src/vm/src/MemoryContext.cpp @@ -10,10 +10,7 @@ #include #include - -MemoryContext::MemoryContext() { - _gc_thread = std::thread(std::bind(&MemoryContext::gc_thread_entry, this)); -} +MemoryContext::MemoryContext() { _gc_thread = std::thread(std::bind(&MemoryContext::gc_thread_entry, this)); } MemoryContext::~MemoryContext() { // Three times because the first one might not start it as it's been running already @@ -35,22 +32,20 @@ void MemoryContext::add_root(Cell *c) { { std::lock_guard l(_new_roots_lock); _new_roots[c]++; - // { - // std::stringstream out; - // out << "new root: " << c << " T: " << static_cast(c->_type) << " NUM: " << _new_roots[c] << "\n"; - // std::cerr << out.str(); - // } + Logger::log( + "MemoryContext", + [&](std::ostream &out) { out << "new root: " << c << " T: " << static_cast(c->_type) << " NUM: " << _new_roots[c]; }, + Logger::TRACE); } } void MemoryContext::remove_root(Cell *c) { { std::lock_guard l(_new_roots_lock); _new_roots[c]--; - // { - // std::stringstream out; - // out << "del root: " << c << " T: " << static_cast(c->_type) << " NUM: " << _new_roots[c] << "\n"; - // std::cerr << out.str(); - // } + Logger::log( + "MemoryContext", + [&](std::ostream &out) { out << "del root: " << c << " T: " << static_cast(c->_type) << " NUM: " << _new_roots[c]; }, + Logger::TRACE); if (_new_roots[c] == 0) _new_roots.erase(c); } } @@ -63,11 +58,7 @@ void MemoryContext::gc_thread_entry() { } if (_gc_thread_stop) return; - // { - // std::stringstream out; - // out << "gc start " << '\n'; - // std::cerr << out.str(); - // } + Logger::log("MemoryContext", [&](std::ostream &out) { out << "gc start "; }, Logger::DEBUG); auto gcstart = std::chrono::high_resolution_clock::now(); std::queue toVisit; @@ -80,21 +71,14 @@ void MemoryContext::gc_thread_entry() { if (c == nullptr) continue; if (c->_live) continue; c->_live = true; - // - // { - // std::stringstream out; - // out << "processing c " << c << " " << static_cast(c->_type) << "\n"; - // std::cerr << out.str(); - // } + Logger::log( + "MemoryContext", [&](std::ostream &out) { out << "visiting c " << c << " " << static_cast(c->_type); }, + Logger::TRACE); if (c->_type == CellType::CONS) { ConsCell &cc = dynamic_cast(*c); - // {std::stringstream out; out << "processing car " << cc._car << "\n"; std::cerr<(stop - start).count() << "\n"; - std::cout << out.str(); - } + + Logger::log("MemoryContext", + "New roots processing time: " + + std::to_string(std::chrono::duration_cast(stop - start).count()), + Logger::INFO); } { auto start = std::chrono::high_resolution_clock::now(); - std::for_each(_cells.begin(), _cells.end(), [&](Cell *c) { - c->_live = false; - }); + std::for_each(_cells.begin(), _cells.end(), [&](Cell *c) { c->_live = false; }); for (const auto &r: _roots) { - // { - // std::stringstream out; - // out << "processing r " << r.first << " diff " << r.second << "\n"; - // std::cerr << out.str(); - // } + Logger::log( + "MemoryContext", [&](std::ostream &out) { out << "processing r " << r.first << " diff " << r.second; }, + Logger::DEBUG); toVisit.emplace(r.first); } visitAll(); auto stop = std::chrono::high_resolution_clock::now(); - // { - // std::stringstream out; - // out << "Scanned " << _roots.size() << " roots" << std::endl; - // std::cerr << out.str(); - // } - { - std::stringstream out; - out << "Roots scan time: " << std::chrono::duration_cast(stop - start).count() << "\n"; - std::cout << out.str(); - } + Logger::log("MemoryContext", [&](std::ostream &out) { out << "Scanned " << _roots.size() << " roots"; }, Logger::DEBUG); + Logger::log("MemoryContext", + "Roots scan time: " + std::to_string(std::chrono::duration_cast(stop - start).count()), + Logger::INFO); } { @@ -170,11 +141,7 @@ void MemoryContext::gc_thread_entry() { } while (!dirtied.empty()) { for (const auto &r: dirtied) { - // { - // std::stringstream out; - // out << "processing dirty " << r << "\n"; - // std::cerr << out.str(); - // } + Logger::log("MemoryContext", [&](std::ostream &out) { out << "processing dirty " << r; }, Logger::DEBUG); toVisit.emplace(r); } visitAll(); @@ -187,11 +154,9 @@ void MemoryContext::gc_thread_entry() { } auto stop = std::chrono::high_resolution_clock::now(); - { - std::stringstream out; - out << "Dirty mark time: " << std::chrono::duration_cast(stop - start).count() << "\n"; - std::cout << out.str(); - } + Logger::log("MemoryContext", + "Dirty scan time: " + std::to_string(std::chrono::duration_cast(stop - start).count()), + Logger::INFO); } { auto start = std::chrono::high_resolution_clock::now(); @@ -201,13 +166,7 @@ void MemoryContext::gc_thread_entry() { _cells.remove_if([&](Cell *l) { if (!l->_live) { freed += 1; - - // { - // std::stringstream out; - // out << "deleting: " << l << "\n"; - // std::cerr << out.str(); - // } - + Logger::log("MemoryContext", [&](std::ostream &out) { out << "deleting: " << l; }, Logger::DEBUG); delete l; return true; } @@ -215,25 +174,17 @@ void MemoryContext::gc_thread_entry() { }); auto stop = std::chrono::high_resolution_clock::now(); - { - std::stringstream out; - out << "Sweep time: " << std::chrono::duration_cast(stop - start).count() << "\n"; - std::cout << out.str(); - } + Logger::log("MemoryContext", + "Sweep time: " + std::to_string(std::chrono::duration_cast(stop - start).count()), + Logger::INFO); _cells_num = _cells.size(); - { - std::stringstream out; - out << "GC Freed " << freed << " cells left: " << _cells_num << " \n"; - std::cout << out.str(); - } + Logger::log("MemoryContext", "GC Freed: " + std::to_string(freed) + " cells left: " + std::to_string(_cells_num), Logger::INFO); } auto gcstop = std::chrono::high_resolution_clock::now(); - { - std::stringstream out; - out << "GC total time: " << std::chrono::duration_cast(gcstop - gcstart).count() << "\n"; - std::cout << out.str(); - } + Logger::log("MemoryContext", + "GC total time: " + std::to_string(std::chrono::duration_cast(gcstop - gcstart).count()), + Logger::INFO); { diff --git a/src/vm/src/VM.cpp b/src/vm/src/VM.cpp index 16cf8f1..eca5dc4 100644 --- a/src/vm/src/VM.cpp +++ b/src/vm/src/VM.cpp @@ -36,15 +36,11 @@ void VM::step() { Handle curFrame = _e; - for (int i = 1; i < frame; i++) { - curFrame = curFrame.cdr(); - } + for (int i = 1; i < frame; i++) { curFrame = curFrame.cdr(); } Handle curArg = curFrame.car(); - for (int i = 1; i < arg; i++) { - curArg = curArg.cdr(); - } + for (int i = 1; i < arg; i++) { curArg = curArg.cdr(); } _s.push(curArg.car()); } else if (poppedH == SEL) { @@ -130,10 +126,14 @@ void VM::step() { } else if (poppedH == EVAL) { Handle code = _s.pop(); Handle newc = Compiler::compile(code, nullptr); - std::cerr << "compiled:\n"; - std::cerr << "(" << code << ")\n"; - std::cerr << "to:\n"; - std::cerr << "(" << newc << ")\n"; + Logger::log( + "Compiler", + [&](std::ostream &out) { + out << "Compiled (" << code << ")\n"; + out << "to\n"; + out << "(" << newc << ")"; + }, + Logger::DEBUG); newc.splice(_c); _c = newc; } else if (poppedH == PRINT) {