Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logg #1091

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Logg #1091

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
6896a9d
add logger
meetesh06 Sep 12, 2021
50cb515
Merge branch 'master' into logg_new
meetesh06 Sep 12, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
28 changes: 26 additions & 2 deletions rir/src/api.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@
#include "interpreter/interp_incl.h"
#include "ir/BC.h"
#include "ir/Compiler.h"

#include "utils/measuring.h"
#include <cassert>
#include <cstdio>
#include <list>
Expand Down Expand Up @@ -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<double, std::milli> 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)
Expand Down Expand Up @@ -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<double, std::milli> 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<size_t>(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<double, std::milli> fail_time = cmp_end - cmp_start;
logg << "@,false," << fail_time.count() <<"\n";
#endif
if (debug.includes(pir::DebugFlag::ShowWarnings))
std::cerr << "Compilation failed\n";
},
{});
Expand Down
89 changes: 86 additions & 3 deletions rir/src/interpreter/interp.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@
#include "safe_force.h"
#include "utils/Pool.h"
#include "utils/measuring.h"

#include <chrono>
#include <assert.h>
#include <deque>
#include <libintl.h>
Expand Down Expand Up @@ -530,16 +530,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);
Expand All @@ -555,12 +568,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);
Expand All @@ -570,6 +592,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;
}
}
Expand Down Expand Up @@ -894,6 +920,53 @@ class SlowcaseCounter {
};
#endif

#if LOGG > 0
class Timer {
private:
std::chrono::time_point<std::chrono::_V2::steady_clock, std::chrono::_V2::steady_clock::duration> tick, tock;
std::chrono::duration<double, std::milli> 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<size_t>(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);

Expand Down Expand Up @@ -958,6 +1031,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);
Expand Down Expand Up @@ -1099,6 +1177,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:
Expand Down
26 changes: 24 additions & 2 deletions rir/src/runtime/DispatchTable.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -213,17 +213,39 @@ struct DispatchTable
return userDefinedContext_ | anotherContext;
}

int hast;

void blacklistContext(unsigned long con) {
if (blacklistIndex_ < BLACKLIST_SIZE) {
contextBlacklist_[blacklistIndex_++] = con;
}
}

bool isBlacklisted(const Context & c) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you could keep the list sorted, then you can abort the search once your entry is larger than the key?

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)
: RirRuntimeObject(
// 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
Expand Down
31 changes: 30 additions & 1 deletion rir/src/utils/measuring.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,11 +26,29 @@ struct MeasuringImpl {
std::unordered_map<std::string, size_t> events;
std::chrono::time_point<std::chrono::high_resolution_clock> start;
std::chrono::time_point<std::chrono::high_resolution_clock> end;
#if LOGG > 0
std::ofstream logg_stream;
std::chrono::time_point<std::chrono::steady_clock> 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();
Expand All @@ -47,6 +65,12 @@ struct MeasuringImpl {
} else {
dump(std::cerr);
}
#if LOGG > 0
c_end = std::chrono::steady_clock::now();
std::chrono::duration<double, std::milli> total = end - start;
logg_stream << "##," << total.count();
logg_stream.close();
#endif
}

void dump(std::ostream& out) {
Expand Down Expand Up @@ -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
6 changes: 5 additions & 1 deletion rir/src/utils/measuring.h
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
#ifndef MEASURING_H
#define MEASURING_H

#define LOGG 0
#include <string>

namespace rir {
Expand All @@ -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