make this faster than a tortoise

This commit is contained in:
2024-02-13 22:24:50 +01:00
parent 8f94830ae2
commit 34d31dea77
10 changed files with 63 additions and 67 deletions

View File

@@ -38,7 +38,7 @@ void parse_options(int argc, char *argv[]) {
if (split.at(0) == "log") {
if (split.size() != 3) throw std::invalid_argument("Log options must be in format --log:TAG:LEVEL");
try {
Logger::set_level(split.at(1), std::stoi(split.at(2)));
Logger::set_level(Logger::str_to_tag(split.at(1)), std::stoi(split.at(2)));
} catch (...) { throw std::invalid_argument("Log options must be in format --log:TAG:LEVEL"); }
} else if (split.size() == 1) {
std::string str = split.at(0);

View File

@@ -16,18 +16,21 @@
class Logger {
public:
Logger();
enum LogLevel { ALWAYS = 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);
enum LogTag { MemoryContext, VM, Compiler, LogTagMax };
static void log(LogTag tag, const std::string &what, int level);
static void log(LogTag 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 int get_level(const std::string &tag);
static bool en_level(const std::string &tag, int level);
static void set_level(LogTag tag, int level);
static int get_level(LogTag tag);
static bool en_level(LogTag tag, int level);
static void set_out(std::ostream &out);
static void set_out_err(std::ostream &out_err);
@@ -36,15 +39,21 @@ public:
static Logger &get();
static LogTag str_to_tag(const std::string &str) { return _str_to_tag.at(str); }
private:
std::unordered_map<std::string, int> _levels;
std::array<LogLevel, LogTag::LogTagMax> _levels{};
static inline std::unordered_map<int, std::string> _level_names{
{ALWAYS, "ALWAYS"}, {ERROR, "ERROR"}, {INFO, "INFO"}, {DEBUG, "DEBUG"}, {TRACE, "TRACE"},
};
static inline std::unordered_map<std::string, LogTag> _str_to_tag{
{"VM", VM},
{"MemoryContext", MemoryContext},
{"Compiler", Compiler},
};
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;
std::shared_mutex _mutex;
};

View File

@@ -13,10 +13,9 @@ Logger &Logger::get() {
return logger;
}
void Logger::log(const std::string &tag, const std::string &what, int level) {
void Logger::log(LogTag tag, const std::string &what, int level) {
if (!en_level(tag, level)) return;
{
std::shared_lock l(get()._mutex);
auto now = std::chrono::high_resolution_clock::now();
std::stringstream out;
out << std::setprecision(3) << std::fixed << "["
@@ -32,7 +31,7 @@ void Logger::log(const std::string &tag, const std::string &what, int level) {
}
}
void Logger::log(const std::string &tag, const std::function<void(std::ostream &)> &fn, int level) {
void Logger::log(LogTag tag, const std::function<void(std::ostream &)> &fn, int level) {
if (!en_level(tag, level)) return;
std::stringstream out;
@@ -40,30 +39,17 @@ void Logger::log(const std::string &tag, const std::function<void(std::ostream &
log(tag, out.str(), level);
}
void Logger::set_level(const std::string &tag, int level) {
std::lock_guard l(get()._mutex);
get()._levels[tag] = level;
}
void Logger::set_out(std::ostream &out) {
std::lock_guard l(get()._mutex);
get()._out = out;
}
void Logger::set_out_err(std::ostream &out_err) {
std::lock_guard l(get()._mutex);
get()._out_err = out_err;
}
void Logger::reset() {
std::lock_guard l(get()._mutex);
get()._levels = {};
}
int Logger::get_level(const std::string &tag) {
std::shared_lock l(get()._mutex);
int en_level = Options::get<size_t>("default_log_level");
if (get()._levels.find(tag) != get()._levels.end()) en_level = get()._levels.at(tag);
return en_level;
}
bool Logger::en_level(const std::string &tag, int level) {
void Logger::set_level(LogTag tag, int level) { get()._levels[tag] = static_cast<LogLevel>(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::reset() { get()._levels.fill(static_cast<LogLevel>(Options::get<size_t>("default_log_level"))); }
int Logger::get_level(LogTag tag) { return get()._levels.at(tag); }
bool Logger::en_level(LogTag tag, int level) {
int en_level = get_level(tag);
if (en_level < level) return false;
return true;
}
Logger::Logger() { _levels.fill(static_cast<LogLevel>(Options::get<size_t>("default_log_level"))); }

View File

@@ -57,7 +57,7 @@ public:
std::lock_guard l(_gc_dirty_notif_queue_lock);
return f([&](Cell *c) {
if (c == nullptr) return;
Logger::log("MemoryContext", [&](std::ostream &out) { out << "marked dirty: " << c; }, Logger::DEBUG);
Logger::log(Logger::MemoryContext, [&](std::ostream &out) { out << "marked dirty: " << c; }, Logger::DEBUG);
_gc_dirty_notif_queue.emplace(c);
});
}
@@ -74,7 +74,7 @@ private:
if ((_cells_num + tcellnum) >= (Options::get<size_t>("cell_limit"))) {
// We might need to run GC twice as it has to process the messages;
Logger::log("MemoryContext", "Running forced gc", Logger::ERROR);
Logger::log(Logger::MemoryContext, "Running forced gc", Logger::ERROR);
for (int i = 0; i < 3 && (_cells_num + tcellnum) >= (Options::get<size_t>("cell_limit")); i++) {
request_gc_and_wait();
{
@@ -83,7 +83,7 @@ private:
}
}
if ((_cells_num + tcellnum) >= (Options::get<size_t>("cell_limit"))) {
Logger::log("MemoryContext", "Out of cells", Logger::ERROR);
Logger::log(Logger::MemoryContext, "Out of cells", Logger::ERROR);
throw std::runtime_error("Out of cells");
}

View File

@@ -36,7 +36,7 @@ void MemoryContext::add_root(Cell *c) {
std::lock_guard l(_new_roots_lock);
_new_roots[c]++;
Logger::log(
"MemoryContext",
Logger::MemoryContext,
[&](std::ostream &out) {
out << "new root: " << c << " T: " << static_cast<int>(c->_type) << " NUM: " << _new_roots[c];
},
@@ -48,7 +48,7 @@ void MemoryContext::remove_root(Cell *c) {
std::lock_guard l(_new_roots_lock);
_new_roots[c]--;
Logger::log(
"MemoryContext",
Logger::MemoryContext,
[&](std::ostream &out) {
out << "del root: " << c << " T: " << static_cast<int>(c->_type) << " NUM: " << _new_roots[c];
},
@@ -65,7 +65,7 @@ void MemoryContext::gc_thread_entry() {
}
if (_gc_thread_stop) return;
Logger::log("MemoryContext", [&](std::ostream &out) { out << "gc start "; }, Logger::DEBUG);
Logger::log(Logger::MemoryContext, [&](std::ostream &out) { out << "gc start "; }, Logger::DEBUG);
auto gcstart = std::chrono::high_resolution_clock::now();
std::queue<Cell *> toVisit;
@@ -79,7 +79,7 @@ void MemoryContext::gc_thread_entry() {
if (c->_live) continue;
c->_live = true;
Logger::log(
"MemoryContext",
Logger::MemoryContext,
[&](std::ostream &out) { out << "visiting c " << c << " " << static_cast<int>(c->_type); },
Logger::TRACE);
@@ -107,7 +107,7 @@ void MemoryContext::gc_thread_entry() {
for (auto const &r: new_roots) {
Logger::log(
"MemoryContext",
Logger::MemoryContext,
[&](std::ostream &out) { out << "processing new " << r.first << " diff " << r.second; },
Logger::TRACE);
if (r.second == 0) continue;
@@ -118,7 +118,7 @@ void MemoryContext::gc_thread_entry() {
auto stop = std::chrono::high_resolution_clock::now();
Logger::log(
"MemoryContext",
Logger::MemoryContext,
"New roots processing time: " +
std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
Logger::INFO);
@@ -130,7 +130,7 @@ void MemoryContext::gc_thread_entry() {
for (const auto &r: _roots) {
Logger::log(
"MemoryContext",
Logger::MemoryContext,
[&](std::ostream &out) { out << "processing r " << r.first << " diff " << r.second; },
Logger::TRACE);
toVisit.emplace(r.first);
@@ -138,10 +138,10 @@ void MemoryContext::gc_thread_entry() {
visitAll();
auto stop = std::chrono::high_resolution_clock::now();
Logger::log(
"MemoryContext", [&](std::ostream &out) { out << "Scanned " << _roots.size() << " roots"; },
Logger::MemoryContext, [&](std::ostream &out) { out << "Scanned " << _roots.size() << " roots"; },
Logger::DEBUG);
Logger::log(
"MemoryContext",
Logger::MemoryContext,
"Roots scan time: " +
std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
Logger::INFO);
@@ -157,7 +157,7 @@ void MemoryContext::gc_thread_entry() {
while (!dirtied.empty()) {
for (const auto &r: dirtied) {
Logger::log(
"MemoryContext", [&](std::ostream &out) { out << "processing dirty " << r; },
Logger::MemoryContext, [&](std::ostream &out) { out << "processing dirty " << r; },
Logger::DEBUG);
toVisit.emplace(r);
}
@@ -172,7 +172,7 @@ void MemoryContext::gc_thread_entry() {
auto stop = std::chrono::high_resolution_clock::now();
Logger::log(
"MemoryContext",
Logger::MemoryContext,
"Dirty scan time: " +
std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
Logger::INFO);
@@ -185,7 +185,8 @@ void MemoryContext::gc_thread_entry() {
_cells.remove_if([&](Cell *l) {
if (!l->_live) {
freed += 1;
Logger::log("MemoryContext", [&](std::ostream &out) { out << "deleting: " << l; }, Logger::TRACE);
Logger::log(
Logger::MemoryContext, [&](std::ostream &out) { out << "deleting: " << l; }, Logger::TRACE);
delete l;
return true;
}
@@ -194,19 +195,19 @@ void MemoryContext::gc_thread_entry() {
auto stop = std::chrono::high_resolution_clock::now();
Logger::log(
"MemoryContext",
Logger::MemoryContext,
"Sweep time: " +
std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(stop - start).count()),
Logger::INFO);
_cells_num = _cells.size();
Logger::log("MemoryContext",
Logger::log(Logger::MemoryContext,
"GC Freed: " + std::to_string(freed) + " cells left: " + std::to_string(_cells_num),
Logger::INFO);
}
auto gcstop = std::chrono::high_resolution_clock::now();
Logger::log(
"MemoryContext",
Logger::MemoryContext,
"GC total time: " +
std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(gcstop - gcstart).count()),
Logger::INFO);

View File

@@ -26,7 +26,7 @@ void VM::step() {
CellValType poppedCmd = poppedH.type() == CellType::STRATOM ? str_to_cmd.at(poppedH.strval()) : poppedH.val();
Logger::log(
"VM",
Logger::VM,
[&](std::ostream &out) {
out << "Executing " << cmd_to_str.at(poppedCmd) << "\n";
if (!_s.null()) out << "s:" << _s << "\n";
@@ -104,7 +104,7 @@ void VM::step() {
_d.push(_c);
std::optional<std::string> name;
if (Logger::en_level("VM", Logger::DEBUG)) {
if (Logger::en_level(Logger::VM, Logger::DEBUG)) {
name = "unknown";
if (_globals_names_map.find(closureH) != _globals_names_map.end())
name = _globals_names_map.at(closureH);
@@ -116,7 +116,7 @@ void VM::step() {
_e = closureH.cdr();
Logger::log(
"VM",
Logger::VM,
[&](std::ostream &out) {
out << _cur_call_level;
for (int i = 0; i < _cur_call_level; i++) out << " ";
@@ -133,7 +133,7 @@ void VM::step() {
_cur_call_level--;
Handle n;
if (Logger::en_level("VM", Logger::DEBUG)) n = _d.pop();
if (Logger::en_level(Logger::VM, Logger::DEBUG)) n = _d.pop();
Handle c = _d.pop();
Handle e = _d.pop();
@@ -146,7 +146,7 @@ void VM::step() {
_s = s;
Logger::log(
"VM",
Logger::VM,
[&](std::ostream &out) {
out << _cur_call_level;
for (int i = 0; i < _cur_call_level; i++) out << " ";
@@ -175,7 +175,7 @@ void VM::step() {
_d.push(origE);
_d.push(_c);
if (Logger::en_level("VM", Logger::DEBUG)) _d.push(Handle("rap"));
if (Logger::en_level(Logger::VM, Logger::DEBUG)) _d.push(Handle("rap"));
_s = Handle::cons(nullptr, nullptr);
_c = closureH.car();
@@ -268,7 +268,7 @@ void VM::step() {
Handle code = _s.pop();
Handle newc = Compiler::compile(code, _globals_names);
Logger::log(
"Compiler",
Logger::Compiler,
[&](std::ostream &out) {
out << "Compiled (" << code << ")";
out << " to ";
@@ -312,7 +312,7 @@ void VM::step() {
}
Logger::log(
"VM",
Logger::VM,
[&](std::ostream &out) {
out << "Executed " << cmd_to_str.at(poppedCmd) << "\n";
if (!_s.null()) out << "s:" << _s << "\n";

View File

@@ -15,8 +15,8 @@ public:
void SetUp() override {
Options::set<size_t>("cell_limit", 50000);
Options::set<bool>("command_strs", true);
Logger::set_level("VM", Logger::DEBUG);
Logger::set_level("Compiler", Logger::DEBUG);
Logger::set_level(Logger::VM, Logger::DEBUG);
Logger::set_level(Logger::Compiler, Logger::DEBUG);
}
void TearDown() override {
@@ -281,7 +281,7 @@ TEST(CompilerTest, GlobalDefineFnRec) {
std::stringstream ssin;
std::stringstream ssout;
Options::set<bool>("command_strs", false);
Logger::set_level("VM", Options::get<size_t>("default_log_level"));
Logger::set_level(Logger::VM, Options::get<size_t>("default_log_level"));
{
VM vm(ssin, ssout);
Parser parser;
@@ -291,7 +291,7 @@ TEST(CompilerTest, GlobalDefineFnRec) {
vm.run();
}
Options::set<bool>("command_strs", true);
Logger::set_level("VM", Logger::DEBUG);
Logger::set_level(Logger::VM, Logger::DEBUG);
ssout.flush();
EXPECT_EQ(ssout.str(), "6765\n");
}

View File

@@ -11,7 +11,7 @@ public:
void SetUp() override {
Options::set<size_t>("cell_limit", 60000);
Logger::set_level("Compiler", Logger::DEBUG);
Logger::set_level(Logger::Compiler, Logger::DEBUG);
}
void TearDown() override {

View File

@@ -8,7 +8,7 @@ public:
void SetUp() override {
Options::set<size_t>("cell_limit", 5000);
Logger::set_level("Compiler", Logger::DEBUG);
Logger::set_level(Logger::Compiler, Logger::DEBUG);
}
void TearDown() override {

View File

@@ -9,7 +9,7 @@ public:
void SetUp() override {
Options::set<size_t>("cell_limit", 5000);
Logger::set_level("Compiler", Logger::DEBUG);
Logger::set_level(Logger::Compiler, Logger::DEBUG);
}
void TearDown() override {