stepus53/psil
1
0
Fork 0
mirror of https://github.com/usatiuk/psil.git synced 2025-10-28 18:57:48 +01:00
Code Issues Actions Packages Projects Releases Wiki Activity

better logger

Browse Source
This commit is contained in:
Stepan Usatiuk
2024-01-03 15:33:40 +01:00
parent 8d68d7d795
commit 35a0a74a00
10 changed files with 170 additions and 121 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
.clang-format
View File

@@ -33,7 +33,7 @@ BreakBeforeBinaryOperators: None
BreakBeforeTernaryOperators: true BreakBeforeTernaryOperators: true
BreakConstructorInitializers: BeforeColon BreakConstructorInitializers: BeforeColon
BreakInheritanceList: BeforeColon BreakInheritanceList: BeforeColon
ColumnLimit: 0 ColumnLimit: 140
CompactNamespaces: false CompactNamespaces: false
ContinuationIndentWidth: 8 ContinuationIndentWidth: 8
IndentCaseLabels: true IndentCaseLabels: true

1
.idea/cmake.xml generated
View File

@@ -4,6 +4,7 @@
<configurations> <configurations>
<configuration PROFILE_NAME="Debug" ENABLED="true" CONFIG_NAME="Debug" GENERATION_OPTIONS="-DSANITIZE=YES" /> <configuration PROFILE_NAME="Debug" ENABLED="true" CONFIG_NAME="Debug" GENERATION_OPTIONS="-DSANITIZE=YES" />
<configuration PROFILE_NAME="RelWithDebInfo" ENABLED="true" CONFIG_NAME="RelWithDebInfo" /> <configuration PROFILE_NAME="RelWithDebInfo" ENABLED="true" CONFIG_NAME="RelWithDebInfo" />
<configuration PROFILE_NAME="Release" ENABLED="true" CONFIG_NAME="Release" />
</configurations> </configurations>
</component> </component>
</project> </project>

1
src/CMakeLists.txt
View File

@@ -2,6 +2,7 @@ set(CMAKE_CXX_STANDARD 17)
set(CMAKE_CXX_STANDARD_REQUIRED ON) set(CMAKE_CXX_STANDARD_REQUIRED ON)
add_subdirectory(vm) add_subdirectory(vm)
add_subdirectory(logger)
add_executable(psil main.cpp) add_executable(psil main.cpp)

6
src/logger/CMakeLists.txt Normal file
View File

@@ -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)

49
src/logger/include/Logger.h Normal file
View File

@@ -0,0 +1,49 @@
//
// Created by stepus53 on 3.1.24.
//
#ifndef PSIL_LOGGER_H
#define PSIL_LOGGER_H
#include <chrono>
#include <functional>
#include <iostream>
#include <ostream>
#include <string>
#include <unordered_map>
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<void(std::ostream &)> &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<std::string, int> _levels;
static inline std::unordered_map<int, std::string> _level_names{
{ERROR, "ERROR"},
{INFO, "INFO"},
{DEBUG, "DEBUG"},
{TRACE, "TRACE"},
};
int _default_level = 1;
std::chrono::time_point<std::chrono::high_resolution_clock> _start_time = std::chrono::high_resolution_clock::now();
std::reference_wrapper<std::ostream> _out = std::cout;
std::reference_wrapper<std::ostream> _out_err = std::cerr;
};
#endif//PSIL_LOGGER_H

46
src/logger/src/Logger.cpp Normal file
View File

@@ -0,0 +1,46 @@
//
// Created by stepus53 on 3.1.24.
//
#include "Logger.h"
#include <iomanip>
#include <sstream>
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<double>(std::chrono::duration_cast<std::chrono::milliseconds>(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<void(std::ostream &)> &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; }

2
src/vm/CMakeLists.txt
View File

@@ -4,4 +4,6 @@ set(CMAKE_CXX_STANDARD_REQUIRED ON)
add_library(vm src/VM.cpp src/Cell.cpp add_library(vm src/VM.cpp src/Cell.cpp
src/Parser.cpp src/MemoryContext.cpp src/Handle.cpp src/Compiler.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) target_include_directories(vm PUBLIC include)

31
src/vm/include/MemoryContext.h
View File

@@ -18,6 +18,7 @@
#include "Cell.h" #include "Cell.h"
#include "Handle.h" #include "Handle.h"
#include "Logger.h"
class Handle; class Handle;
@@ -39,11 +40,8 @@ public:
void request_gc_and_wait() { void request_gc_and_wait() {
std::unique_lock l(_gc_done_m); std::unique_lock l(_gc_done_m);
_gc_done = false; _gc_done = false;
{ { request_gc(); }
request_gc(); if (!_gc_done) _gc_done_cv.wait(l, [&] { return _gc_done.load(); });
}
if (!_gc_done)
_gc_done_cv.wait(l, [&] { return _gc_done.load(); });
} }
void request_gc() { void request_gc() {
@@ -52,21 +50,16 @@ public:
_gc_request_cv.notify_all(); _gc_request_cv.notify_all();
} }
size_t cell_count() { size_t cell_count() { return _cells_num; }
return _cells_num;
}
template<typename R> template<typename R>
R run_dirty(const std::function<R(std::function<void(Cell *)>)> &f) { R run_dirty(const std::function<R(std::function<void(Cell *)>)> &f) {
std::lock_guard l(_gc_dirty_notif_queue_lock); std::lock_guard l(_gc_dirty_notif_queue_lock);
return f([&](Cell *c) { return f([&](Cell *c) {
// { if (c == nullptr) return;
// std::stringstream out; Logger::log("MemoryContext", [&](std::ostream &out) { out << "marked dirty: " << c; }, Logger::DEBUG);
// out << "marked dirty: " << c << " \n"; _gc_dirty_notif_queue.emplace(c);
// std::cerr << out.str(); });
// }
_gc_dirty_notif_queue.emplace(c); });
} }
private: private:
@@ -81,7 +74,7 @@ private:
if ((_cells_num + tcellnum) >= (_cell_limit)) { if ((_cells_num + tcellnum) >= (_cell_limit)) {
// We might need to run GC twice as it has to process the messages; // 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++) { for (int i = 0; i < 3 && (_cells_num + tcellnum) >= (_cell_limit); i++) {
request_gc_and_wait(); request_gc_and_wait();
{ {
@@ -90,6 +83,8 @@ private:
} }
} }
if ((_cells_num + tcellnum) >= (_cell_limit)) { if ((_cells_num + tcellnum) >= (_cell_limit)) {
Logger::log("MemoryContext", "Out of cells", Logger::ERROR);
throw std::runtime_error("Out of cells"); throw std::runtime_error("Out of cells");
} }
} }
@@ -100,9 +95,7 @@ private:
std::lock_guard tmplg(_new_roots_lock); std::lock_guard tmplg(_new_roots_lock);
Handle ret(cell); Handle ret(cell);
_temp_cells.emplace_back(cell); _temp_cells.emplace_back(cell);
if ((_cells_num + _temp_cells.size() + 1) >= (size_t) (_cell_limit / 2)) { if ((_cells_num + _temp_cells.size() + 1) >= (size_t) (_cell_limit / 2)) { request_gc(); }
request_gc();
}
return ret; return ret;
} }
} }

133
src/vm/src/MemoryContext.cpp
View File

@@ -10,10 +10,7 @@
#include <sstream> #include <sstream>
#include <unordered_set> #include <unordered_set>
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() { MemoryContext::~MemoryContext() {
// Three times because the first one might not start it as it's been running already // 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); std::lock_guard l(_new_roots_lock);
_new_roots[c]++; _new_roots[c]++;
// { Logger::log(
// std::stringstream out; "MemoryContext",
// out << "new root: " << c << " T: " << static_cast<int>(c->_type) << " NUM: " << _new_roots[c] << "\n"; [&](std::ostream &out) { out << "new root: " << c << " T: " << static_cast<int>(c->_type) << " NUM: " << _new_roots[c]; },
// std::cerr << out.str(); Logger::TRACE);
// }
} }
} }
void MemoryContext::remove_root(Cell *c) { void MemoryContext::remove_root(Cell *c) {
{ {
std::lock_guard l(_new_roots_lock); std::lock_guard l(_new_roots_lock);
_new_roots[c]--; _new_roots[c]--;
// { Logger::log(
// std::stringstream out; "MemoryContext",
// out << "del root: " << c << " T: " << static_cast<int>(c->_type) << " NUM: " << _new_roots[c] << "\n"; [&](std::ostream &out) { out << "del root: " << c << " T: " << static_cast<int>(c->_type) << " NUM: " << _new_roots[c]; },
// std::cerr << out.str(); Logger::TRACE);
// }
if (_new_roots[c] == 0) _new_roots.erase(c); if (_new_roots[c] == 0) _new_roots.erase(c);
} }
} }
@@ -63,11 +58,7 @@ void MemoryContext::gc_thread_entry() {
} }
if (_gc_thread_stop) return; if (_gc_thread_stop) return;
// { Logger::log("MemoryContext", [&](std::ostream &out) { out << "gc start "; }, Logger::DEBUG);
// std::stringstream out;
// out << "gc start " << '\n';
// std::cerr << out.str();
// }
auto gcstart = std::chrono::high_resolution_clock::now(); auto gcstart = std::chrono::high_resolution_clock::now();
std::queue<Cell *> toVisit; std::queue<Cell *> toVisit;
@@ -80,21 +71,14 @@ void MemoryContext::gc_thread_entry() {
if (c == nullptr) continue; if (c == nullptr) continue;
if (c->_live) continue; if (c->_live) continue;
c->_live = true; c->_live = true;
// Logger::log(
// { "MemoryContext", [&](std::ostream &out) { out << "visiting c " << c << " " << static_cast<int>(c->_type); },
// std::stringstream out; Logger::TRACE);
// out << "processing c " << c << " " << static_cast<int>(c->_type) << "\n";
// std::cerr << out.str();
// }
if (c->_type == CellType::CONS) { if (c->_type == CellType::CONS) {
ConsCell &cc = dynamic_cast<ConsCell &>(*c); ConsCell &cc = dynamic_cast<ConsCell &>(*c);
// {std::stringstream out; out << "processing car " << cc._car << "\n"; std::cerr<<out.str();}
toVisit.emplace(cc._car); toVisit.emplace(cc._car);
// {std::stringstream out; out << "real car " << toVisit.back() << "\n"; std::cerr<<out.str();}
// {std::stringstream out; out << "processing cdr " << cc._cdr << "\n"; std::cerr<<out.str();}
toVisit.emplace(cc._cdr); toVisit.emplace(cc._cdr);
// {std::stringstream out; out << "real cdr " << toVisit.back() << "\n"; std::cerr<<out.str();}
} }
} }
}; };
@@ -114,51 +98,38 @@ void MemoryContext::gc_thread_entry() {
for (auto const &r: new_roots) { for (auto const &r: new_roots) {
// { Logger::log(
// std::stringstream out; "MemoryContext", [&](std::ostream &out) { out << "processing new " << r.first << " diff " << r.second; },
// out << "processing new " << r.first << " diff " << r.second << "\n"; Logger::TRACE);
// std::cerr << out.str();
// }
if (r.second == 0) continue; if (r.second == 0) continue;
_roots[r.first] += r.second; _roots[r.first] += r.second;
if (_roots[r.first] <= 0) if (_roots[r.first] <= 0) _roots.erase(r.first);
_roots.erase(r.first);
} }
auto stop = std::chrono::high_resolution_clock::now(); auto stop = std::chrono::high_resolution_clock::now();
{
std::stringstream out; Logger::log("MemoryContext",
out << "New roots time: " << std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count() << "\n"; "New roots processing time: " +
std::cout << out.str(); std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
} Logger::INFO);
} }
{ {
auto start = std::chrono::high_resolution_clock::now(); auto start = std::chrono::high_resolution_clock::now();
std::for_each(_cells.begin(), _cells.end(), [&](Cell *c) { std::for_each(_cells.begin(), _cells.end(), [&](Cell *c) { c->_live = false; });
c->_live = false;
});
for (const auto &r: _roots) { for (const auto &r: _roots) {
// { Logger::log(
// std::stringstream out; "MemoryContext", [&](std::ostream &out) { out << "processing r " << r.first << " diff " << r.second; },
// out << "processing r " << r.first << " diff " << r.second << "\n"; Logger::DEBUG);
// std::cerr << out.str();
// }
toVisit.emplace(r.first); toVisit.emplace(r.first);
} }
visitAll(); visitAll();
auto stop = std::chrono::high_resolution_clock::now(); auto stop = std::chrono::high_resolution_clock::now();
// { Logger::log("MemoryContext", [&](std::ostream &out) { out << "Scanned " << _roots.size() << " roots"; }, Logger::DEBUG);
// std::stringstream out; Logger::log("MemoryContext",
// out << "Scanned " << _roots.size() << " roots" << std::endl; "Roots scan time: " + std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
// std::cerr << out.str(); Logger::INFO);
// }
{
std::stringstream out;
out << "Roots scan time: " << std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count() << "\n";
std::cout << out.str();
}
} }
{ {
@@ -170,11 +141,7 @@ void MemoryContext::gc_thread_entry() {
} }
while (!dirtied.empty()) { while (!dirtied.empty()) {
for (const auto &r: dirtied) { for (const auto &r: dirtied) {
// { Logger::log("MemoryContext", [&](std::ostream &out) { out << "processing dirty " << r; }, Logger::DEBUG);
// std::stringstream out;
// out << "processing dirty " << r << "\n";
// std::cerr << out.str();
// }
toVisit.emplace(r); toVisit.emplace(r);
} }
visitAll(); visitAll();
@@ -187,11 +154,9 @@ void MemoryContext::gc_thread_entry() {
} }
auto stop = std::chrono::high_resolution_clock::now(); auto stop = std::chrono::high_resolution_clock::now();
{ Logger::log("MemoryContext",
std::stringstream out; "Dirty scan time: " + std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
out << "Dirty mark time: " << std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count() << "\n"; Logger::INFO);
std::cout << out.str();
}
} }
{ {
auto start = std::chrono::high_resolution_clock::now(); auto start = std::chrono::high_resolution_clock::now();
@@ -201,13 +166,7 @@ void MemoryContext::gc_thread_entry() {
_cells.remove_if([&](Cell *l) { _cells.remove_if([&](Cell *l) {
if (!l->_live) { if (!l->_live) {
freed += 1; freed += 1;
Logger::log("MemoryContext", [&](std::ostream &out) { out << "deleting: " << l; }, Logger::DEBUG);
// {
// std::stringstream out;
// out << "deleting: " << l << "\n";
// std::cerr << out.str();
// }
delete l; delete l;
return true; return true;
} }
@@ -215,25 +174,17 @@ void MemoryContext::gc_thread_entry() {
}); });
auto stop = std::chrono::high_resolution_clock::now(); auto stop = std::chrono::high_resolution_clock::now();
{ Logger::log("MemoryContext",
std::stringstream out; "Sweep time: " + std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
out << "Sweep time: " << std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count() << "\n"; Logger::INFO);
std::cout << out.str();
}
_cells_num = _cells.size(); _cells_num = _cells.size();
{ Logger::log("MemoryContext", "GC Freed: " + std::to_string(freed) + " cells left: " + std::to_string(_cells_num), Logger::INFO);
std::stringstream out;
out << "GC Freed " << freed << " cells left: " << _cells_num << " \n";
std::cout << out.str();
}
} }
auto gcstop = std::chrono::high_resolution_clock::now(); auto gcstop = std::chrono::high_resolution_clock::now();
{ Logger::log("MemoryContext",
std::stringstream out; "GC total time: " + std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(gcstop - gcstart).count()),
out << "GC total time: " << std::chrono::duration_cast<std::chrono::microseconds>(gcstop - gcstart).count() << "\n"; Logger::INFO);
std::cout << out.str();
}
{ {

20
src/vm/src/VM.cpp
View File

@@ -36,15 +36,11 @@ void VM::step() {
Handle curFrame = _e; Handle curFrame = _e;
for (int i = 1; i < frame; i++) { for (int i = 1; i < frame; i++) { curFrame = curFrame.cdr(); }
curFrame = curFrame.cdr();
}
Handle curArg = curFrame.car(); Handle curArg = curFrame.car();
for (int i = 1; i < arg; i++) { for (int i = 1; i < arg; i++) { curArg = curArg.cdr(); }
curArg = curArg.cdr();
}
_s.push(curArg.car()); _s.push(curArg.car());
} else if (poppedH == SEL) { } else if (poppedH == SEL) {
@@ -130,10 +126,14 @@ void VM::step() {
} else if (poppedH == EVAL) { } else if (poppedH == EVAL) {
Handle code = _s.pop(); Handle code = _s.pop();
Handle newc = Compiler::compile(code, nullptr); Handle newc = Compiler::compile(code, nullptr);
std::cerr << "compiled:\n"; Logger::log(
std::cerr << "(" << code << ")\n"; "Compiler",
std::cerr << "to:\n"; [&](std::ostream &out) {
std::cerr << "(" << newc << ")\n"; out << "Compiled (" << code << ")\n";
out << "to\n";
out << "(" << newc << ")";
},
Logger::DEBUG);
newc.splice(_c); newc.splice(_c);
_c = newc; _c = newc;
} else if (poppedH == PRINT) { } else if (poppedH == PRINT) {