Skip to content

Commit

Permalink
Improve Logger Performance (#683)
Browse files Browse the repository at this point in the history 
* Make use of LoggerFilterLevel to conditionally disable message formatting

* Move more from the Logger header to the implementation file

* Refactor StdStream + some cleanup

* Re-enable PIC by default to support ASLR
  • Loading branch information
@fabianbs96
fabianbs96 authored Nov 25, 2023
1 parent 4c04ed3 commit 3aca432
Show file tree
Hide file tree
Showing 4 changed files with 288 additions and 258 deletions.
175 changes: 93 additions & 82 deletions include/phasar/DataFlow/IfdsIde/Solver/IDESolver.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -286,15 +286,16 @@ class IDESolver
const auto &ReturnSiteNs = ICF->getReturnSitesOfCallAt(n);
const auto &Callees = ICF->getCalleesOfCallAt(n);

IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(DEBUG, "Possible callees:"); for (auto Callee
: Callees) {
PHASAR_LOG_LEVEL(DEBUG, " " << Callee->getName());
} PHASAR_LOG_LEVEL(DEBUG, "Possible return sites:");
for (auto ret
: ReturnSiteNs) {
PHASAR_LOG_LEVEL(DEBUG, " " << NToString(ret));
});
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(DEBUG, "Possible callees:");
for (auto Callee : Callees) {
PHASAR_LOG_LEVEL(DEBUG, " " << Callee->getName());
}
PHASAR_LOG_LEVEL(DEBUG, "Possible return sites:");
for (auto ret : ReturnSiteNs) {
PHASAR_LOG_LEVEL(DEBUG, " " << NToString(ret));
}
});

// for each possible callee
for (f_t SCalledProcN : Callees) { // still line 14
Expand All @@ -315,11 +316,11 @@ class IDESolver
CachedFlowEdgeFunctions.getSummaryEdgeFunction(n, d2,
ReturnSiteN, d3);
INC_COUNTER("SpecialSummary-EF Queries", 1, Full);
IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(
DEBUG, "Queried Summary Edge Function: " << SumEdgFnE);
PHASAR_LOG_LEVEL(DEBUG, "Compose: " << SumEdgFnE << " * " << f
<< '\n'));

PHASAR_LOG_LEVEL(DEBUG,
"Queried Summary Edge Function: " << SumEdgFnE);
PHASAR_LOG_LEVEL(DEBUG,
"Compose: " << SumEdgFnE << " * " << f << '\n');
WorkList.emplace_back(PathEdge(d1, ReturnSiteN, std::move(d3)),
f.composeWith(SumEdgFnE));
}
Expand Down Expand Up @@ -562,7 +563,7 @@ class IDESolver
}

void setVal(n_t NHashN, d_t NHashD, l_t L) {
IF_LOG_ENABLED({
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(DEBUG,
"Function : " << ICF->getFunctionOf(NHashN)->getName());
PHASAR_LOG_LEVEL(DEBUG, "Inst. : " << NToString(NHashN));
Expand All @@ -580,13 +581,14 @@ class IDESolver
}

EdgeFunction<l_t> jumpFunction(const PathEdge<n_t, d_t> Edge) {
IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(DEBUG, "JumpFunctions Forward-Lookup:");
PHASAR_LOG_LEVEL(DEBUG,
" Source D: " << DToString(Edge.factAtSource()));
PHASAR_LOG_LEVEL(DEBUG, " Target N: " << NToString(Edge.getTarget()));
PHASAR_LOG_LEVEL(DEBUG,
" Target D: " << DToString(Edge.factAtTarget())));
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(DEBUG, "JumpFunctions Forward-Lookup:");
PHASAR_LOG_LEVEL(DEBUG,
" Source D: " << DToString(Edge.factAtSource()));
PHASAR_LOG_LEVEL(DEBUG, " Target N: " << NToString(Edge.getTarget()));
PHASAR_LOG_LEVEL(DEBUG,
" Target D: " << DToString(Edge.factAtTarget()));
});

auto FwdLookupRes =
JumpFn->forwardLookup(Edge.factAtSource(), Edge.getTarget());
Expand Down Expand Up @@ -617,21 +619,22 @@ class IDESolver
void pathEdgeProcessingTask(PathEdge<n_t, d_t> Edge) {
PAMM_GET_INSTANCE;
INC_COUNTER("JumpFn Construction", 1, Full);
IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(
DEBUG,
"-------------------------------------------- "
<< PathEdgeCount
<< ". Path Edge --------------------------------------------");
PHASAR_LOG_LEVEL(DEBUG, ' ');
PHASAR_LOG_LEVEL(DEBUG, "Process " << PathEdgeCount << ". path edge:");
PHASAR_LOG_LEVEL(DEBUG, "< D source: " << DToString(Edge.factAtSource())
<< " ;");
PHASAR_LOG_LEVEL(DEBUG,
" N target: " << NToString(Edge.getTarget()) << " ;");
PHASAR_LOG_LEVEL(DEBUG, " D target: " << DToString(Edge.factAtTarget())
<< " >");
PHASAR_LOG_LEVEL(DEBUG, ' '));
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(
DEBUG,
"-------------------------------------------- "
<< PathEdgeCount
<< ". Path Edge --------------------------------------------");
PHASAR_LOG_LEVEL(DEBUG, ' ');
PHASAR_LOG_LEVEL(DEBUG, "Process " << PathEdgeCount << ". path edge:");
PHASAR_LOG_LEVEL(DEBUG, "< D source: " << DToString(Edge.factAtSource())
<< " ;");
PHASAR_LOG_LEVEL(DEBUG,
" N target: " << NToString(Edge.getTarget()) << " ;");
PHASAR_LOG_LEVEL(DEBUG, " D target: " << DToString(Edge.factAtTarget())
<< " >");
PHASAR_LOG_LEVEL(DEBUG, ' ');
});

if (!ICF->isCallSite(Edge.getTarget())) {
if (ICF->isExitInst(Edge.getTarget())) {
Expand Down Expand Up @@ -1063,28 +1066,31 @@ class IDESolver
EdgeFunction<l_t> fPrime = JumpFnE.joinWith(f);
bool NewFunction = fPrime != JumpFnE;

IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(
DEBUG, "Join: " << JumpFnE << " & " << f
<< (JumpFnE == f ? " (EF's are equal)" : " "));
PHASAR_LOG_LEVEL(DEBUG,
" = " << fPrime
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(DEBUG,
"Join: " << JumpFnE << " & " << f
<< (JumpFnE == f ? " (EF's are equal)" : " "));
PHASAR_LOG_LEVEL(DEBUG, " = "
<< fPrime
<< (NewFunction ? " (new jump func)" : " "));
PHASAR_LOG_LEVEL(DEBUG, ' '));
PHASAR_LOG_LEVEL(DEBUG, ' ');
});
if (NewFunction) {
JumpFn->addFunction(SourceVal, Target, TargetVal, fPrime);
PathEdge Edge(SourceVal, Target, TargetVal);
PathEdgeCount++;
pathEdgeProcessingTask(std::move(Edge));

IF_LOG_ENABLED(if (!IDEProblem.isZeroValue(TargetVal)) {
PHASAR_LOG_LEVEL(DEBUG, "EDGE: <F: " << Target->getFunction()->getName()
<< ", D: " << DToString(SourceVal)
<< '>');
PHASAR_LOG_LEVEL(DEBUG, " ---> <N: " << NToString(Target) << ',');
PHASAR_LOG_LEVEL(DEBUG, " D: " << DToString(TargetVal) << ',');
PHASAR_LOG_LEVEL(DEBUG, " EF: " << fPrime << '>');
PHASAR_LOG_LEVEL(DEBUG, ' ');
IF_LOG_LEVEL_ENABLED(DEBUG, {
if (!IDEProblem.isZeroValue(TargetVal)) {
PHASAR_LOG_LEVEL(
DEBUG, "EDGE: <F: " << Target->getFunction()->getName()
<< ", D: " << DToString(SourceVal) << '>');
PHASAR_LOG_LEVEL(DEBUG, " ---> <N: " << NToString(Target) << ',');
PHASAR_LOG_LEVEL(DEBUG, " D: " << DToString(TargetVal) << ',');
PHASAR_LOG_LEVEL(DEBUG, " EF: " << fPrime << '>');
PHASAR_LOG_LEVEL(DEBUG, ' ');
}
});
} else {
PHASAR_LOG_LEVEL(DEBUG, "PROPAGATE: No new function!");
Expand Down Expand Up @@ -1118,41 +1124,43 @@ class IDESolver
}

void printIncomingTab() const {
IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(DEBUG, "Start of incomingtab entry");
for (const auto &Cell
: IncomingTab.cellSet()) {
PHASAR_LOG_LEVEL(DEBUG, "sP: " << NToString(Cell.getRowKey()));
PHASAR_LOG_LEVEL(DEBUG, "d3: " << DToString(Cell.getColumnKey()));
for (const auto &Entry : Cell.getValue()) {
PHASAR_LOG_LEVEL(DEBUG, " n: " << NToString(Entry.first));
for (const auto &Fact : Entry.second) {
PHASAR_LOG_LEVEL(DEBUG, " d2: " << DToString(Fact));
}
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(DEBUG, "Start of incomingtab entry");
for (const auto &Cell : IncomingTab.cellSet()) {
PHASAR_LOG_LEVEL(DEBUG, "sP: " << NToString(Cell.getRowKey()));
PHASAR_LOG_LEVEL(DEBUG, "d3: " << DToString(Cell.getColumnKey()));
for (const auto &Entry : Cell.getValue()) {
PHASAR_LOG_LEVEL(DEBUG, " n: " << NToString(Entry.first));
for (const auto &Fact : Entry.second) {
PHASAR_LOG_LEVEL(DEBUG, " d2: " << DToString(Fact));
}
PHASAR_LOG_LEVEL(DEBUG, "---------------");
} PHASAR_LOG_LEVEL(DEBUG, "End of incomingtab entry");)
}
PHASAR_LOG_LEVEL(DEBUG, "---------------");
}
PHASAR_LOG_LEVEL(DEBUG, "End of incomingtab entry");
})
}

void printEndSummaryTab() const {
IF_LOG_ENABLED(
PHASAR_LOG_LEVEL(DEBUG, "Start of endsummarytab entry");

EndsummaryTab.foreachCell(
[](const auto &Row, const auto &Col, const auto &Val) {
PHASAR_LOG_LEVEL(DEBUG, "sP: " << NToString(Row));
PHASAR_LOG_LEVEL(DEBUG, "d1: " << DToString(Col));

Val.foreachCell([](const auto &InnerRow, const auto &InnerCol,
const auto &InnerVal) {
PHASAR_LOG_LEVEL(DEBUG, " eP: " << NToString(InnerRow));
PHASAR_LOG_LEVEL(DEBUG, " d2: " << DToString(InnerCol));
PHASAR_LOG_LEVEL(DEBUG, " EF: " << InnerVal);
});
PHASAR_LOG_LEVEL(DEBUG, "---------------");
IF_LOG_LEVEL_ENABLED(DEBUG, {
PHASAR_LOG_LEVEL(DEBUG, "Start of endsummarytab entry");

EndsummaryTab.foreachCell(
[](const auto &Row, const auto &Col, const auto &Val) {
PHASAR_LOG_LEVEL(DEBUG, "sP: " << NToString(Row));
PHASAR_LOG_LEVEL(DEBUG, "d1: " << DToString(Col));

Val.foreachCell([](const auto &InnerRow, const auto &InnerCol,
const auto &InnerVal) {
PHASAR_LOG_LEVEL(DEBUG, " eP: " << NToString(InnerRow));
PHASAR_LOG_LEVEL(DEBUG, " d2: " << DToString(InnerCol));
PHASAR_LOG_LEVEL(DEBUG, " EF: " << InnerVal);
});
PHASAR_LOG_LEVEL(DEBUG, "---------------");
});

PHASAR_LOG_LEVEL(DEBUG, "End of endsummarytab entry");)
PHASAR_LOG_LEVEL(DEBUG, "End of endsummarytab entry");
})
}

void printComputedPathEdges() {
Expand Down Expand Up @@ -1259,7 +1267,7 @@ class IDESolver
if (ICF->isCallSite(Edge.first)) {
ValidInCallerContext[Edge.second].insert(D2s.begin(), D2s.end());
}
IF_LOG_ENABLED([this](const auto &D2s) {
IF_LOG_LEVEL_ENABLED(DEBUG, [this](const auto &D2s) {
for (auto D2 : D2s) {
PHASAR_LOG_LEVEL(DEBUG, "d2: " << DToString(D2));
}
Expand Down Expand Up @@ -1671,6 +1679,8 @@ class IDESolver
void finalizeInternal() {
PAMM_GET_INSTANCE;
STOP_TIMER("DFA Phase I", Full);
PHASAR_LOG_LEVEL(INFO, "[info]: IDE Phase I completed");

if (SolverConfig.computeValues()) {
START_TIMER("DFA Phase II", Full);
// Computing the final values for the edge functions
Expand All @@ -1679,6 +1689,7 @@ class IDESolver
computeValues();
STOP_TIMER("DFA Phase II", Full);
}

PHASAR_LOG_LEVEL(INFO, "Problem solved");
if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::Core) {
computeAndPrintStatistics();
Expand Down
Loading

0 comments on commit 3aca432

Please sign in to comment.