From 6896a9d76dcb40a780dfb82c471fde3e1f769f2d Mon Sep 17 00:00:00 2001 From: Meetesh Mehta Date: Sun, 12 Sep 2021 13:18:47 +0530 Subject: [PATCH] add logger --- rir/src/api.cpp | 28 ++++++++++- rir/src/interpreter/interp.cpp | 89 +++++++++++++++++++++++++++++++-- rir/src/runtime/DispatchTable.h | 26 +++++++++- rir/src/utils/measuring.cpp | 31 +++++++++++- rir/src/utils/measuring.h | 6 ++- 5 files changed, 171 insertions(+), 9 deletions(-) diff --git a/rir/src/api.cpp b/rir/src/api.cpp index aeca359ff..ce56ebfbd 100644 --- a/rir/src/api.cpp +++ b/rir/src/api.cpp @@ -15,7 +15,7 @@ #include "interpreter/interp_incl.h" #include "ir/BC.h" #include "ir/Compiler.h" - +#include "utils/measuring.h" #include #include #include @@ -303,8 +303,20 @@ SEXP pirCompile(SEXP what, const Context& assumptions, const std::string& name, logger.title("Compiling " + name); pir::Compiler cmp(m, logger); pir::Backend backend(m, logger, name); + #if LOGG > 1 + std::ofstream & logg = Measuring::getLogStream(); + auto cmp_start = std::chrono::steady_clock::now(); + #endif auto compile = [&](pir::ClosureVersion* c) { + #if LOGG > 1 + auto cmp_end = std::chrono::steady_clock::now(); + std::chrono::duration cmp_time = cmp_end - cmp_start; + logg << "@,true," << cmp_time.count() <<","; + #endif logger.flush(); + #if LOGG > 1 + auto opt_start = std::chrono::steady_clock::now(); + #endif cmp.optimizeModule(); if (dryRun) @@ -341,11 +353,23 @@ SEXP pirCompile(SEXP what, const Context& assumptions, const std::string& name, apply(BODY(what), c); // Eagerly compile the main function done->body()->nativeCode(); + #if LOGG > 1 + auto opt_end = std::chrono::steady_clock::now(); + std::chrono::duration opt_time = opt_end - opt_start; + int bb_count = 0; + rir::pir::BreadthFirstVisitor::run(c->entry, [&](pir::BB* bb) {bb_count++;}); + logg << opt_time.count() <<"," << bb_count <<"," << c->promises().size() << "," << reinterpret_cast(BODY(what)) <<"\n"; + #endif }; cmp.compileClosure(what, name, assumptions, true, compile, [&]() { - if (debug.includes(pir::DebugFlag::ShowWarnings)) + #if LOGG > 1 + auto cmp_end = std::chrono::steady_clock::now(); + std::chrono::duration fail_time = cmp_end - cmp_start; + logg << "@,false," << fail_time.count() <<"\n"; + #endif + if (debug.includes(pir::DebugFlag::ShowWarnings)) std::cerr << "Compilation failed\n"; }, {}); diff --git a/rir/src/interpreter/interp.cpp b/rir/src/interpreter/interp.cpp index 59d37fe33..5a3465a0f 100644 --- a/rir/src/interpreter/interp.cpp +++ b/rir/src/interpreter/interp.cpp @@ -12,7 +12,7 @@ #include "safe_force.h" #include "utils/Pool.h" #include "utils/measuring.h" - +#include #include #include #include @@ -524,16 +524,29 @@ void recordDeoptReason(SEXP val, const DeoptReason& reason) { auto pos = reason.pc(); switch (reason.reason) { - case DeoptReason::Unknown: + case DeoptReason::Unknown: { + #if LOGG > 2 + std::ofstream & logg = Measuring::getLogStream(); + logg << "Deopt: Unknown" << std::endl; + #endif break; + } case DeoptReason::DeadBranchReached: { assert(*pos == Opcode::record_test_); + #if LOGG > 2 + std::ofstream & logg = Measuring::getLogStream(); + logg << "Deopt: DeadBranchReached" << std::endl; + #endif ObservedTest* feedback = (ObservedTest*)(pos + 1); feedback->seen = ObservedTest::Both; break; } case DeoptReason::Typecheck: { assert(*pos == Opcode::record_type_); + #if LOGG > 2 + std::ofstream & logg = Measuring::getLogStream(); + logg << "Deopt: Typecheck" << std::endl; + #endif if (val == symbol::UnknownDeoptTrigger) break; ObservedValues* feedback = (ObservedValues*)(pos + 1); @@ -549,12 +562,21 @@ void recordDeoptReason(SEXP val, const DeoptReason& reason) { } break; } - case DeoptReason::DeadCall: + case DeoptReason::DeadCall: { + #if LOGG > 2 + std::ofstream & logg = Measuring::getLogStream(); + logg << "Deopt: DeadCall" << std::endl; + #endif reason.srcCode()->deadCallReached++; // fall through [[clang::fallthrough]]; + } case DeoptReason::Calltarget: { assert(*pos == Opcode::record_call_); + #if LOGG > 2 + std::ofstream & logg = Measuring::getLogStream(); + logg << "Deopt: CallTarget" << std::endl; + #endif if (val == symbol::UnknownDeoptTrigger) break; ObservedCallees* feedback = (ObservedCallees*)(pos + 1); @@ -564,6 +586,10 @@ void recordDeoptReason(SEXP val, const DeoptReason& reason) { } case DeoptReason::EnvStubMaterialized: { reason.srcCode()->flags.set(Code::NeedsFullEnv); + #if LOGG > 2 + std::ofstream & logg = Measuring::getLogStream(); + logg << "Deopt: EnvStubMaterialized" << std::endl; + #endif break; } } @@ -888,6 +914,53 @@ class SlowcaseCounter { }; #endif +#if LOGG > 0 +class Timer { +private: + std::chrono::time_point tick, tock; + std::chrono::duration runtime; + size_t fun_id; +public: + void start(const CallContext& call, int hast) { + tick = std::chrono::steady_clock::now(); + std::ofstream & logg = Measuring::getLogStream(); + SEXP const lhs = CAR(call.ast); + static const SEXP double_colons = Rf_install("::"); + static const SEXP triple_colons = Rf_install(":::"); + fun_id = reinterpret_cast(BODY(call.callee)); + logg << "=,\"" << fun_id << "\"," << hast << ","; + // Function Header + if (TYPEOF(lhs) == SYMSXP) { + // case 1: function call of the form f(x,y,z) + logg << "\"" << CHAR(PRINTNAME(lhs)) << "\""; + } else if (TYPEOF(lhs) == LANGSXP && ((CAR(lhs) == double_colons) || (CAR(lhs) == triple_colons))) { + // case 2: function call of the form pkg::f(x,y,z) or pkg:::f(x,y,z) + SEXP const fun1 = CAR(lhs); + SEXP const pkg = CADR(lhs); + SEXP const fun2 = CADDR(lhs); + assert(TYPEOF(pkg) == SYMSXP && TYPEOF(fun2) == SYMSXP); + logg << "\"" << CHAR(PRINTNAME(pkg)) << CHAR(PRINTNAME(fun1)) << CHAR(PRINTNAME(fun2)) << "\""; + } else { + logg << "\"AN_" << fun_id << "\""; + } + logg << "\n"; + } + + void end(const Context & context) { + std::ofstream & logg = Measuring::getLogStream(); + tock = std::chrono::steady_clock::now(); + runtime = tock - tick; + logg << "!," << "\"" << context << "\"," << context.toI() << "," << runtime.count() << "," << fun_id << "\n"; + } +private: + void* operator new(size_t); + void* operator new[](size_t); + void operator delete(void*); + void operator delete[](void*); +}; +#endif + + SEXP doCall(CallContext& call, InterpreterInstance* ctx, bool popArgs) { assert(call.callee); @@ -952,6 +1025,11 @@ SEXP doCall(CallContext& call, InterpreterInstance* ctx, bool popArgs) { auto table = DispatchTable::unpack(body); + #if LOGG > 0 + Timer t; + t.start(call,table->hast); + #endif + inferCurrentContext(call, table->baseline()->signature().formalNargs(), ctx); Function* fun = dispatch(call, table); @@ -1093,6 +1171,11 @@ SEXP doCall(CallContext& call, InterpreterInstance* ctx, bool popArgs) { assert(!fun->flags.contains(Function::Deopt)); if (popArgs) ostack_popn(ctx, call.passedArgs - call.suppliedArgs); + + #if LOGG > 0 + t.end(fun->context()); + #endif + return result; } default: diff --git a/rir/src/runtime/DispatchTable.h b/rir/src/runtime/DispatchTable.h index ee2f2b6c3..77262b1b9 100644 --- a/rir/src/runtime/DispatchTable.h +++ b/rir/src/runtime/DispatchTable.h @@ -5,7 +5,7 @@ #include "R/Serialize.h" #include "RirRuntimeObject.h" #include "utils/random.h" - +#define BLACKLIST_SIZE 15 namespace rir { #define DISPATCH_TABLE_MAGIC (unsigned)0xd7ab1e00 @@ -213,6 +213,24 @@ struct DispatchTable return userDefinedContext_ | anotherContext; } + int hast; + + void blacklistContext(unsigned long con) { + if (blacklistIndex_ < BLACKLIST_SIZE) { + contextBlacklist_[blacklistIndex_++] = con; + } + } + + bool isBlacklisted(const Context & c) { + unsigned long con = c.toI(); + for(int i = 0; i < blacklistIndex_; i++){ + if(contextBlacklist_[i] == con) { + return true; + } + } + return false; + } + private: DispatchTable() = delete; explicit DispatchTable(size_t cap) @@ -220,10 +238,14 @@ struct DispatchTable // GC area starts at the end of the DispatchTable sizeof(DispatchTable), // GC area is just the pointers in the entry array - cap) {} + cap), hast(0) { + for(int i = 0; i< BLACKLIST_SIZE; i++) { contextBlacklist_[i]=0; } + } size_t size_ = 0; Context userDefinedContext_; + int blacklistIndex_ = 0; + unsigned long contextBlacklist_[BLACKLIST_SIZE]; }; #pragma pack(pop) } // namespace rir diff --git a/rir/src/utils/measuring.cpp b/rir/src/utils/measuring.cpp index 4965ccdca..2841ae893 100644 --- a/rir/src/utils/measuring.cpp +++ b/rir/src/utils/measuring.cpp @@ -26,11 +26,29 @@ struct MeasuringImpl { std::unordered_map events; std::chrono::time_point start; std::chrono::time_point end; + #if LOGG > 0 + std::ofstream logg_stream; + std::chrono::time_point c_start, c_end; + #endif size_t threshold = 0; const unsigned width = 40; bool shouldOutput = false; - MeasuringImpl() : start(std::chrono::high_resolution_clock::now()) {} + MeasuringImpl() : start(std::chrono::high_resolution_clock::now()) { + #if LOGG > 0 + c_start = std::chrono::steady_clock::now(); + + if(getenv("LOGG") != NULL) { + std::string binId = getenv("LOGG"); + logg_stream.open(binId + ".logg"); + } else { + time_t timenow = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + std::stringstream runId_ss; + runId_ss << std::put_time( localtime( &timenow ), "%FT%T%z" ) << ".logg"; + logg_stream.open(runId_ss.str()); + } + #endif + } ~MeasuringImpl() { end = std::chrono::high_resolution_clock::now(); @@ -47,6 +65,12 @@ struct MeasuringImpl { } else { dump(std::cerr); } + #if LOGG > 0 + c_end = std::chrono::steady_clock::now(); + std::chrono::duration total = end - start; + logg_stream << "##," << total.count(); + logg_stream.close(); + #endif } void dump(std::ostream& out) { @@ -192,5 +216,10 @@ void Measuring::countEvent(const std::string& name, size_t n) { m->shouldOutput = true; m->events[name] += n; } +#if LOGG > 0 +std::ofstream & Measuring::getLogStream() { + return m->logg_stream; +} +#endif } // namespace rir diff --git a/rir/src/utils/measuring.h b/rir/src/utils/measuring.h index 134f89c0d..af3e33630 100644 --- a/rir/src/utils/measuring.h +++ b/rir/src/utils/measuring.h @@ -1,6 +1,6 @@ #ifndef MEASURING_H #define MEASURING_H - +#define LOGG 0 #include namespace rir { @@ -12,8 +12,12 @@ class Measuring { static void addTime(const std::string& name, double time); static void setEventThreshold(size_t n); static void countEvent(const std::string& name, size_t n = 1); + #if LOGG > 0 + static std::ofstream & getLogStream(); + #endif }; + } // namespace rir #endif