Skip to content

Commit 6896a9d

Browse files
meetesh06meetesh06
committed
add logger
1 parent aee2f43 commit 6896a9d

File tree

5 files changed

+171
-9
lines changed

5 files changed

+171
-9
lines changed

‎rir/src/api.cpp‎

Lines changed: 26 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@
1515
#include "interpreter/interp_incl.h"
1616
#include "ir/BC.h"
1717
#include "ir/Compiler.h"
18-
18+
#include "utils/measuring.h"
1919
#include <cassert>
2020
#include <cstdio>
2121
#include <list>
@@ -303,8 +303,20 @@ SEXP pirCompile(SEXP what, const Context& assumptions, const std::string& name,
303303
logger.title("Compiling " + name);
304304
pir::Compiler cmp(m, logger);
305305
pir::Backend backend(m, logger, name);
306+
#if LOGG > 1
307+
std::ofstream & logg = Measuring::getLogStream();
308+
auto cmp_start = std::chrono::steady_clock::now();
309+
#endif
306310
auto compile = [&](pir::ClosureVersion* c) {
311+
#if LOGG > 1
312+
auto cmp_end = std::chrono::steady_clock::now();
313+
std::chrono::duration<double, std::milli> cmp_time = cmp_end - cmp_start;
314+
logg << "@,true," << cmp_time.count() <<",";
315+
#endif
307316
logger.flush();
317+
#if LOGG > 1
318+
auto opt_start = std::chrono::steady_clock::now();
319+
#endif
308320
cmp.optimizeModule();
309321

310322
if (dryRun)
@@ -341,11 +353,23 @@ SEXP pirCompile(SEXP what, const Context& assumptions, const std::string& name,
341353
apply(BODY(what), c);
342354
// Eagerly compile the main function
343355
done->body()->nativeCode();
356+
#if LOGG > 1
357+
auto opt_end = std::chrono::steady_clock::now();
358+
std::chrono::duration<double, std::milli> opt_time = opt_end - opt_start;
359+
int bb_count = 0;
360+
rir::pir::BreadthFirstVisitor::run(c->entry, [&](pir::BB* bb) {bb_count++;});
361+
logg << opt_time.count() <<"," << bb_count <<"," << c->promises().size() << "," << reinterpret_cast<size_t>(BODY(what)) <<"\n";
362+
#endif
344363
};
345364

346365
cmp.compileClosure(what, name, assumptions, true, compile,
347366
[&]() {
348-
if (debug.includes(pir::DebugFlag::ShowWarnings))
367+
#if LOGG > 1
368+
auto cmp_end = std::chrono::steady_clock::now();
369+
std::chrono::duration<double, std::milli> fail_time = cmp_end - cmp_start;
370+
logg << "@,false," << fail_time.count() <<"\n";
371+
#endif
372+
if (debug.includes(pir::DebugFlag::ShowWarnings))
349373
std::cerr << "Compilation failed\n";
350374
},
351375
{});

‎rir/src/interpreter/interp.cpp‎

Lines changed: 86 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@
1212
#include "safe_force.h"
1313
#include "utils/Pool.h"
1414
#include "utils/measuring.h"
15-
15+
#include <chrono>
1616
#include <assert.h>
1717
#include <deque>
1818
#include <libintl.h>
@@ -524,16 +524,29 @@ void recordDeoptReason(SEXP val, const DeoptReason& reason) {
524524
auto pos = reason.pc();
525525

526526
switch (reason.reason) {
527-
case DeoptReason::Unknown:
527+
case DeoptReason::Unknown: {
528+
#if LOGG > 2
529+
std::ofstream & logg = Measuring::getLogStream();
530+
logg << "Deopt: Unknown" << std::endl;
531+
#endif
528532
break;
533+
}
529534
case DeoptReason::DeadBranchReached: {
530535
assert(*pos == Opcode::record_test_);
536+
#if LOGG > 2
537+
std::ofstream & logg = Measuring::getLogStream();
538+
logg << "Deopt: DeadBranchReached" << std::endl;
539+
#endif
531540
ObservedTest* feedback = (ObservedTest*)(pos + 1);
532541
feedback->seen = ObservedTest::Both;
533542
break;
534543
}
535544
case DeoptReason::Typecheck: {
536545
assert(*pos == Opcode::record_type_);
546+
#if LOGG > 2
547+
std::ofstream & logg = Measuring::getLogStream();
548+
logg << "Deopt: Typecheck" << std::endl;
549+
#endif
537550
if (val == symbol::UnknownDeoptTrigger)
538551
break;
539552
ObservedValues* feedback = (ObservedValues*)(pos + 1);
@@ -549,12 +562,21 @@ void recordDeoptReason(SEXP val, const DeoptReason& reason) {
549562
}
550563
break;
551564
}
552-
case DeoptReason::DeadCall:
565+
case DeoptReason::DeadCall: {
566+
#if LOGG > 2
567+
std::ofstream & logg = Measuring::getLogStream();
568+
logg << "Deopt: DeadCall" << std::endl;
569+
#endif
553570
reason.srcCode()->deadCallReached++;
554571
// fall through
555572
[[clang::fallthrough]];
573+
}
556574
case DeoptReason::Calltarget: {
557575
assert(*pos == Opcode::record_call_);
576+
#if LOGG > 2
577+
std::ofstream & logg = Measuring::getLogStream();
578+
logg << "Deopt: CallTarget" << std::endl;
579+
#endif
558580
if (val == symbol::UnknownDeoptTrigger)
559581
break;
560582
ObservedCallees* feedback = (ObservedCallees*)(pos + 1);
@@ -564,6 +586,10 @@ void recordDeoptReason(SEXP val, const DeoptReason& reason) {
564586
}
565587
case DeoptReason::EnvStubMaterialized: {
566588
reason.srcCode()->flags.set(Code::NeedsFullEnv);
589+
#if LOGG > 2
590+
std::ofstream & logg = Measuring::getLogStream();
591+
logg << "Deopt: EnvStubMaterialized" << std::endl;
592+
#endif
567593
break;
568594
}
569595
}
@@ -888,6 +914,53 @@ class SlowcaseCounter {
888914
};
889915
#endif
890916

917+
#if LOGG > 0
918+
class Timer {
919+
private:
920+
std::chrono::time_point<std::chrono::_V2::steady_clock, std::chrono::_V2::steady_clock::duration> tick, tock;
921+
std::chrono::duration<double, std::milli> runtime;
922+
size_t fun_id;
923+
public:
924+
void start(const CallContext& call, int hast) {
925+
tick = std::chrono::steady_clock::now();
926+
std::ofstream & logg = Measuring::getLogStream();
927+
SEXP const lhs = CAR(call.ast);
928+
static const SEXP double_colons = Rf_install("::");
929+
static const SEXP triple_colons = Rf_install(":::");
930+
fun_id = reinterpret_cast<size_t>(BODY(call.callee));
931+
logg << "=,\"" << fun_id << "\"," << hast << ",";
932+
// Function Header
933+
if (TYPEOF(lhs) == SYMSXP) {
934+
// case 1: function call of the form f(x,y,z)
935+
logg << "\"" << CHAR(PRINTNAME(lhs)) << "\"";
936+
} else if (TYPEOF(lhs) == LANGSXP && ((CAR(lhs) == double_colons) || (CAR(lhs) == triple_colons))) {
937+
// case 2: function call of the form pkg::f(x,y,z) or pkg:::f(x,y,z)
938+
SEXP const fun1 = CAR(lhs);
939+
SEXP const pkg = CADR(lhs);
940+
SEXP const fun2 = CADDR(lhs);
941+
assert(TYPEOF(pkg) == SYMSXP && TYPEOF(fun2) == SYMSXP);
942+
logg << "\"" << CHAR(PRINTNAME(pkg)) << CHAR(PRINTNAME(fun1)) << CHAR(PRINTNAME(fun2)) << "\"";
943+
} else {
944+
logg << "\"AN_" << fun_id << "\"";
945+
}
946+
logg << "\n";
947+
}
948+
949+
void end(const Context & context) {
950+
std::ofstream & logg = Measuring::getLogStream();
951+
tock = std::chrono::steady_clock::now();
952+
runtime = tock - tick;
953+
logg << "!," << "\"" << context << "\"," << context.toI() << "," << runtime.count() << "," << fun_id << "\n";
954+
}
955+
private:
956+
void* operator new(size_t);
957+
void* operator new[](size_t);
958+
void operator delete(void*);
959+
void operator delete[](void*);
960+
};
961+
#endif
962+
963+
891964
SEXP doCall(CallContext& call, InterpreterInstance* ctx, bool popArgs) {
892965
assert(call.callee);
893966

@@ -952,6 +1025,11 @@ SEXP doCall(CallContext& call, InterpreterInstance* ctx, bool popArgs) {
9521025

9531026
auto table = DispatchTable::unpack(body);
9541027

1028+
#if LOGG > 0
1029+
Timer t;
1030+
t.start(call,table->hast);
1031+
#endif
1032+
9551033
inferCurrentContext(call, table->baseline()->signature().formalNargs(),
9561034
ctx);
9571035
Function* fun = dispatch(call, table);
@@ -1093,6 +1171,11 @@ SEXP doCall(CallContext& call, InterpreterInstance* ctx, bool popArgs) {
10931171
assert(!fun->flags.contains(Function::Deopt));
10941172
if (popArgs)
10951173
ostack_popn(ctx, call.passedArgs - call.suppliedArgs);
1174+
1175+
#if LOGG > 0
1176+
t.end(fun->context());
1177+
#endif
1178+
10961179
return result;
10971180
}
10981181
default:

‎rir/src/runtime/DispatchTable.h‎

Lines changed: 24 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55
#include "R/Serialize.h"
66
#include "RirRuntimeObject.h"
77
#include "utils/random.h"
8-
8+
#define BLACKLIST_SIZE 15
99
namespace rir {
1010

1111
#define DISPATCH_TABLE_MAGIC (unsigned)0xd7ab1e00
@@ -213,17 +213,39 @@ struct DispatchTable
213213
return userDefinedContext_ | anotherContext;
214214
}
215215

216+
int hast;
217+
218+
void blacklistContext(unsigned long con) {
219+
if (blacklistIndex_ < BLACKLIST_SIZE) {
220+
contextBlacklist_[blacklistIndex_++] = con;
221+
}
222+
}
223+
224+
bool isBlacklisted(const Context & c) {
225+
unsigned long con = c.toI();
226+
for(int i = 0; i < blacklistIndex_; i++){
227+
if(contextBlacklist_[i] == con) {
228+
return true;
229+
}
230+
}
231+
return false;
232+
}
233+
216234
private:
217235
DispatchTable() = delete;
218236
explicit DispatchTable(size_t cap)
219237
: RirRuntimeObject(
220238
// GC area starts at the end of the DispatchTable
221239
sizeof(DispatchTable),
222240
// GC area is just the pointers in the entry array
223-
cap) {}
241+
cap), hast(0) {
242+
for(int i = 0; i< BLACKLIST_SIZE; i++) { contextBlacklist_[i]=0; }
243+
}
224244

225245
size_t size_ = 0;
226246
Context userDefinedContext_;
247+
int blacklistIndex_ = 0;
248+
unsigned long contextBlacklist_[BLACKLIST_SIZE];
227249
};
228250
#pragma pack(pop)
229251
} // namespace rir

‎rir/src/utils/measuring.cpp‎

Lines changed: 30 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -26,11 +26,29 @@ struct MeasuringImpl {
2626
std::unordered_map<std::string, size_t> events;
2727
std::chrono::time_point<std::chrono::high_resolution_clock> start;
2828
std::chrono::time_point<std::chrono::high_resolution_clock> end;
29+
#if LOGG > 0
30+
std::ofstream logg_stream;
31+
std::chrono::time_point<std::chrono::steady_clock> c_start, c_end;
32+
#endif
2933
size_t threshold = 0;
3034
const unsigned width = 40;
3135
bool shouldOutput = false;
3236

33-
MeasuringImpl() : start(std::chrono::high_resolution_clock::now()) {}
37+
MeasuringImpl() : start(std::chrono::high_resolution_clock::now()) {
38+
#if LOGG > 0
39+
c_start = std::chrono::steady_clock::now();
40+
41+
if(getenv("LOGG") != NULL) {
42+
std::string binId = getenv("LOGG");
43+
logg_stream.open(binId + ".logg");
44+
} else {
45+
time_t timenow = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
46+
std::stringstream runId_ss;
47+
runId_ss << std::put_time( localtime( &timenow ), "%FT%T%z" ) << ".logg";
48+
logg_stream.open(runId_ss.str());
49+
}
50+
#endif
51+
}
3452

3553
~MeasuringImpl() {
3654
end = std::chrono::high_resolution_clock::now();
@@ -47,6 +65,12 @@ struct MeasuringImpl {
4765
} else {
4866
dump(std::cerr);
4967
}
68+
#if LOGG > 0
69+
c_end = std::chrono::steady_clock::now();
70+
std::chrono::duration<double, std::milli> total = end - start;
71+
logg_stream << "##," << total.count();
72+
logg_stream.close();
73+
#endif
5074
}
5175

5276
void dump(std::ostream& out) {
@@ -192,5 +216,10 @@ void Measuring::countEvent(const std::string& name, size_t n) {
192216
m->shouldOutput = true;
193217
m->events[name] += n;
194218
}
219+
#if LOGG > 0
220+
std::ofstream & Measuring::getLogStream() {
221+
return m->logg_stream;
222+
}
223+
#endif
195224

196225
} // namespace rir

‎rir/src/utils/measuring.h‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
#ifndef MEASURING_H
22
#define MEASURING_H
3-
3+
#define LOGG 0
44
#include <string>
55

66
namespace rir {
@@ -12,8 +12,12 @@ class Measuring {
1212
static void addTime(const std::string& name, double time);
1313
static void setEventThreshold(size_t n);
1414
static void countEvent(const std::string& name, size_t n = 1);
15+
#if LOGG > 0
16+
static std::ofstream & getLogStream();
17+
#endif
1518
};
1619

20+
1721
} // namespace rir
1822

1923
#endif

0 commit comments

Comments
 (0)