From 4a582240aa81ef5ede8853c4e23956f1b2adb15b Mon Sep 17 00:00:00 2001 From: Fabian Schiebel <52407375+fabianbs96@users.noreply.github.com> Date: Tue, 15 Aug 2023 19:36:57 +0200 Subject: [PATCH] Fix and update PAMM (#655) --- CMakeLists.txt | 14 +- .../IfdsIde/Solver/FlowEdgeFunctionCache.h | 82 ++-- .../DataFlow/IfdsIde/Solver/IDESolver.h | 141 +++--- .../phasar/DataFlow/IfdsIde/SolverResults.h | 4 +- include/phasar/Utils/PAMM.h | 89 ++-- include/phasar/Utils/PAMMMacros.h | 41 +- include/phasar/Utils/TypeTraits.h | 22 + include/phasar/Utils/Utilities.h | 13 + lib/PhasarLLVM/ControlFlow/LLVMBasedICFG.cpp | 9 +- .../IfdsIde/Problems/IFDSConstAnalysis.cpp | 17 +- .../Passes/GeneralStatisticsAnalysis.cpp | 26 +- lib/PhasarLLVM/Pointer/LLVMAliasGraph.cpp | 11 +- lib/Utils/PAMM.cpp | 444 ++++++++++-------- unittests/Utils/PAMMTest.cpp | 127 ++--- 14 files changed, 532 insertions(+), 508 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index cec3c6243..b9eb75366 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -117,15 +117,15 @@ if (NOT PHASAR_ENABLE_PAMM) set_property(CACHE PHASAR_ENABLE_PAMM PROPERTY STRINGS "Off" "Core" "Full") endif() if(PHASAR_ENABLE_PAMM STREQUAL "Core" AND NOT PHASAR_BUILD_UNITTESTS) - set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -DPAMM_CORE") - message("PAMM metric severity level: Core") + add_compile_definitions(PAMM_CORE) + message(STATUS "PAMM metric severity level: Core") elseif(PHASAR_ENABLE_PAMM STREQUAL "Full" AND NOT PHASAR_BUILD_UNITTESTS) - set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -DPAMM_FULL") - message("PAMM metric severity level: Full") -elseif(PHASAR_BUILD_UNITTESTS) - message("PAMM metric severity level: Off (due to unittests)") + add_compile_definitions(PAMM_FULL) + message(STATUS "PAMM metric severity level: Full") +elseif(PHASAR_BUILD_UNITTESTS AND (PHASAR_ENABLE_PAMM STREQUAL "Core" OR PHASAR_ENABLE_PAMM STREQUAL "Full")) + message(WARNING "PAMM metric severity level: Off (due to unittests)") else() - message("PAMM metric severity level: Off") + message(STATUS "PAMM metric severity level: Off") endif() option(PHASAR_ENABLE_DYNAMIC_LOG "Makes it possible to switch the logger on and off at runtime (default is ON)" ON) diff --git a/include/phasar/DataFlow/IfdsIde/Solver/FlowEdgeFunctionCache.h b/include/phasar/DataFlow/IfdsIde/Solver/FlowEdgeFunctionCache.h index 23d4b918c..a670a403f 100644 --- a/include/phasar/DataFlow/IfdsIde/Solver/FlowEdgeFunctionCache.h +++ b/include/phasar/DataFlow/IfdsIde/Solver/FlowEdgeFunctionCache.h @@ -144,35 +144,35 @@ class FlowEdgeFunctionCache { AutoAddZero(Problem.getIFDSIDESolverConfig().autoAddZero()), ZV(Problem.getZeroValue()) { PAMM_GET_INSTANCE; - REG_COUNTER("Normal-FF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Normal-FF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Normal-FF Construction", 0, Full); + REG_COUNTER("Normal-FF Cache Hit", 0, Full); // Counters for the call flow functions - REG_COUNTER("Call-FF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Call-FF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Call-FF Construction", 0, Full); + REG_COUNTER("Call-FF Cache Hit", 0, Full); // Counters for return flow functions - REG_COUNTER("Return-FF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Return-FF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Return-FF Construction", 0, Full); + REG_COUNTER("Return-FF Cache Hit", 0, Full); // Counters for the call to return flow functions - REG_COUNTER("CallToRet-FF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("CallToRet-FF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("CallToRet-FF Construction", 0, Full); + REG_COUNTER("CallToRet-FF Cache Hit", 0, Full); // Counters for the summary flow functions - REG_COUNTER("Summary-FF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Summary-FF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Summary-FF Construction", 0, Full); + REG_COUNTER("Summary-FF Cache Hit", 0, Full); // Counters for the normal edge functions - REG_COUNTER("Normal-EF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Normal-EF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Normal-EF Construction", 0, Full); + REG_COUNTER("Normal-EF Cache Hit", 0, Full); // Counters for the call edge functions - REG_COUNTER("Call-EF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Call-EF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Call-EF Construction", 0, Full); + REG_COUNTER("Call-EF Cache Hit", 0, Full); // Counters for the return edge functions - REG_COUNTER("Return-EF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Return-EF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Return-EF Construction", 0, Full); + REG_COUNTER("Return-EF Cache Hit", 0, Full); // Counters for the call to return edge functions - REG_COUNTER("CallToRet-EF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("CallToRet-EF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("CallToRet-EF Construction", 0, Full); + REG_COUNTER("CallToRet-EF Cache Hit", 0, Full); // Counters for the summary edge functions - REG_COUNTER("Summary-EF Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Summary-EF Cache Hit", 0, PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Summary-EF Construction", 0, Full); + REG_COUNTER("Summary-EF Cache Hit", 0, Full); } ~FlowEdgeFunctionCache() = default; @@ -194,7 +194,7 @@ class FlowEdgeFunctionCache { auto SearchNormalFlowFunction = NormalFunctionCache.find(Key); if (SearchNormalFlowFunction != NormalFunctionCache.end()) { PHASAR_LOG_LEVEL(DEBUG, "Flow function fetched from cache"); - INC_COUNTER("Normal-FF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Normal-FF Cache Hit", 1, Full); if (SearchNormalFlowFunction->second.FlowFuncPtr != nullptr) { return SearchNormalFlowFunction->second.FlowFuncPtr; } @@ -205,7 +205,7 @@ class FlowEdgeFunctionCache { SearchNormalFlowFunction->second.FlowFuncPtr = FF; return FF; } - INC_COUNTER("Normal-FF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Normal-FF Construction", 1, Full); auto FF = (AutoAddZero) ? std::make_shared>( Problem.getNormalFlowFunction(Curr, Succ), ZV) @@ -227,10 +227,10 @@ class FlowEdgeFunctionCache { auto SearchCallFlowFunction = CallFlowFunctionCache.find(Key); if (SearchCallFlowFunction != CallFlowFunctionCache.end()) { PHASAR_LOG_LEVEL(DEBUG, "Flow function fetched from cache"); - INC_COUNTER("Call-FF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Call-FF Cache Hit", 1, Full); return SearchCallFlowFunction->second; } - INC_COUNTER("Call-FF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Call-FF Construction", 1, Full); auto FF = (AutoAddZero) ? std::make_shared>( Problem.getCallFlowFunction(CallSite, DestFun), ZV) @@ -257,10 +257,10 @@ class FlowEdgeFunctionCache { auto SearchReturnFlowFunction = ReturnFlowFunctionCache.find(Key); if (SearchReturnFlowFunction != ReturnFlowFunctionCache.end()) { PHASAR_LOG_LEVEL(DEBUG, "Flow function fetched from cache"); - INC_COUNTER("Return-FF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Return-FF Cache Hit", 1, Full); return SearchReturnFlowFunction->second; } - INC_COUNTER("Return-FF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Return-FF Construction", 1, Full); auto FF = (AutoAddZero) ? std::make_shared>( Problem.getRetFlowFunction(CallSite, CalleeFun, @@ -291,10 +291,10 @@ class FlowEdgeFunctionCache { auto SearchCallToRetFlowFunction = CallToRetFlowFunctionCache.find(Key); if (SearchCallToRetFlowFunction != CallToRetFlowFunctionCache.end()) { PHASAR_LOG_LEVEL(DEBUG, "Flow function fetched from cache"); - INC_COUNTER("CallToRet-FF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("CallToRet-FF Cache Hit", 1, Full); return SearchCallToRetFlowFunction->second; } - INC_COUNTER("CallToRet-FF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("CallToRet-FF Construction", 1, Full); auto FF = (AutoAddZero) ? std::make_shared>( @@ -308,7 +308,7 @@ class FlowEdgeFunctionCache { FlowFunctionPtrType getSummaryFlowFunction(n_t CallSite, f_t DestFun) { // PAMM_GET_INSTANCE; - // INC_COUNTER("Summary-FF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + // INC_COUNTER("Summary-FF Construction", 1, Full); IF_LOG_ENABLED( PHASAR_LOG_LEVEL(DEBUG, "Summary flow function factory call"); PHASAR_LOG_LEVEL(DEBUG, @@ -338,13 +338,13 @@ class FlowEdgeFunctionCache { auto SearchEdgeFunc = SearchInnerMap->second.EdgeFunctionMap.find( createEdgeFunctionNodeKey(CurrNode, SuccNode)); if (SearchEdgeFunc != SearchInnerMap->second.EdgeFunctionMap.end()) { - INC_COUNTER("Normal-EF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Normal-EF Cache Hit", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Edge function fetched from cache"); PHASAR_LOG_LEVEL(DEBUG, "Provide Edge Function: " << SearchEdgeFunc->second); return SearchEdgeFunc->second; } - INC_COUNTER("Normal-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Normal-EF Construction", 1, Full); auto EF = Problem.getNormalEdgeFunction(Curr, CurrNode, Succ, SuccNode); SearchInnerMap->second.EdgeFunctionMap.insert( @@ -354,7 +354,7 @@ class FlowEdgeFunctionCache { PHASAR_LOG_LEVEL(DEBUG, "Provide Edge Function: " << EF); return EF; } - INC_COUNTER("Normal-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Normal-EF Construction", 1, Full); auto EF = Problem.getNormalEdgeFunction(Curr, CurrNode, Succ, SuccNode); NormalFunctionCache.try_emplace( @@ -383,13 +383,13 @@ class FlowEdgeFunctionCache { auto Key = std::tie(CallSite, SrcNode, DestinationFunction, DestNode); auto SearchCallEdgeFunction = CallEdgeFunctionCache.find(Key); if (SearchCallEdgeFunction != CallEdgeFunctionCache.end()) { - INC_COUNTER("Call-EF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Call-EF Cache Hit", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Edge function fetched from cache"); PHASAR_LOG_LEVEL( DEBUG, "Provide Edge Function: " << SearchCallEdgeFunction->second); return SearchCallEdgeFunction->second; } - INC_COUNTER("Call-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Call-EF Construction", 1, Full); auto EF = Problem.getCallEdgeFunction(CallSite, SrcNode, DestinationFunction, DestNode); CallEdgeFunctionCache.insert(std::make_pair(Key, EF)); @@ -420,13 +420,13 @@ class FlowEdgeFunctionCache { RetNode); auto SearchReturnEdgeFunction = ReturnEdgeFunctionCache.find(Key); if (SearchReturnEdgeFunction != ReturnEdgeFunctionCache.end()) { - INC_COUNTER("Return-EF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Return-EF Cache Hit", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Edge function fetched from cache"); PHASAR_LOG_LEVEL( DEBUG, "Provide Edge Function: " << SearchReturnEdgeFunction->second); return SearchReturnEdgeFunction->second; } - INC_COUNTER("Return-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Return-EF Construction", 1, Full); auto EF = Problem.getReturnEdgeFunction(CallSite, CalleeFunction, ExitInst, ExitNode, RetSite, RetNode); ReturnEdgeFunctionCache.insert(std::make_pair(Key, EF)); @@ -462,13 +462,13 @@ class FlowEdgeFunctionCache { auto SearchEdgeFunc = SearchInnerMap->second.find( createEdgeFunctionNodeKey(CallNode, RetSiteNode)); if (SearchEdgeFunc != SearchInnerMap->second.end()) { - INC_COUNTER("CallToRet-EF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("CallToRet-EF Cache Hit", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Edge function fetched from cache"); PHASAR_LOG_LEVEL(DEBUG, "Provide Edge Function: " << SearchEdgeFunc->second); return SearchEdgeFunc->second; } - INC_COUNTER("CallToRet-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("CallToRet-EF Construction", 1, Full); auto EF = Problem.getCallToRetEdgeFunction(CallSite, CallNode, RetSite, RetSiteNode, Callees); @@ -480,7 +480,7 @@ class FlowEdgeFunctionCache { return EF; } - INC_COUNTER("CallToRet-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("CallToRet-EF Construction", 1, Full); auto EF = Problem.getCallToRetEdgeFunction(CallSite, CallNode, RetSite, RetSiteNode, Callees); @@ -510,13 +510,13 @@ class FlowEdgeFunctionCache { auto Key = std::tie(CallSite, CallNode, RetSite, RetSiteNode); auto SearchSummaryEdgeFunction = SummaryEdgeFunctionCache.find(Key); if (SearchSummaryEdgeFunction != SummaryEdgeFunctionCache.end()) { - INC_COUNTER("Summary-EF Cache Hit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Summary-EF Cache Hit", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Edge function fetched from cache"); PHASAR_LOG_LEVEL(DEBUG, "Provide Edge Function: " << SearchSummaryEdgeFunction->second); return SearchSummaryEdgeFunction->second; } - INC_COUNTER("Summary-EF Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Summary-EF Construction", 1, Full); auto EF = Problem.getSummaryEdgeFunction(CallSite, CallNode, RetSite, RetSiteNode); SummaryEdgeFunctionCache.insert(std::make_pair(Key, EF)); diff --git a/include/phasar/DataFlow/IfdsIde/Solver/IDESolver.h b/include/phasar/DataFlow/IfdsIde/Solver/IDESolver.h index 0eb324dc0..41207a44d 100644 --- a/include/phasar/DataFlow/IfdsIde/Solver/IDESolver.h +++ b/include/phasar/DataFlow/IfdsIde/Solver/IDESolver.h @@ -281,7 +281,7 @@ class IDESolver /// virtual void processCall(const PathEdge Edge) { PAMM_GET_INSTANCE; - INC_COUNTER("Process Call", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Process Call", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Process call at target: " << IDEProblem.NtoString(Edge.getTarget())); d_t d1 = Edge.factAtSource(); @@ -313,17 +313,14 @@ class IDESolver PHASAR_LOG_LEVEL(DEBUG, "Found and process special summary"); for (n_t ReturnSiteN : ReturnSiteNs) { container_type Res = computeSummaryFlowFunction(SpecialSum, d1, d2); - INC_COUNTER("SpecialSummary-FF Application", 1, - PAMM_SEVERITY_LEVEL::Full); - ADD_TO_HISTOGRAM("Data-flow facts", res.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("SpecialSummary-FF Application", 1, Full); + ADD_TO_HISTOGRAM("Data-flow facts", Res.size(), 1, Full); saveEdges(n, ReturnSiteN, d2, Res, false); for (d_t d3 : Res) { EdgeFunction SumEdgFnE = CachedFlowEdgeFunctions.getSummaryEdgeFunction(n, d2, ReturnSiteN, d3); - INC_COUNTER("SpecialSummary-EF Queries", 1, - PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("SpecialSummary-EF Queries", 1, Full); IF_LOG_ENABLED( PHASAR_LOG_LEVEL( DEBUG, "Queried Summary Edge Function: " << SumEdgFnE); @@ -337,10 +334,9 @@ class IDESolver // compute the call-flow function FlowFunctionPtrType Function = CachedFlowEdgeFunctions.getCallFlowFunction(n, SCalledProcN); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); container_type Res = computeCallFlowFunction(Function, d1, d2); - ADD_TO_HISTOGRAM("Data-flow facts", res.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + ADD_TO_HISTOGRAM("Data-flow facts", Res.size(), 1, Full); // for each callee's start point(s) auto StartPointsOf = ICF->getStartPointsOf(SCalledProcN); if (StartPointsOf.empty()) { @@ -386,11 +382,11 @@ class IDESolver FlowFunctionPtrType RetFunction = CachedFlowEdgeFunctions.getRetFlowFunction(n, SCalledProcN, eP, RetSiteN); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); const container_type ReturnedFacts = computeReturnFlowFunction( RetFunction, d3, d4, n, Container{d2}); - ADD_TO_HISTOGRAM("Data-flow facts", returnedFacts.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + ADD_TO_HISTOGRAM("Data-flow facts", ReturnedFacts.size(), 1, + Full); saveEdges(eP, RetSiteN, d4, ReturnedFacts, true); // for each target value of the function for (d_t d5 : ReturnedFacts) { @@ -415,7 +411,7 @@ class IDESolver d5)] .push_back(f5); } - INC_COUNTER("EF Queries", 2, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("EF Queries", 2, Full); // compose call * calleeSummary * return edge functions PHASAR_LOG_LEVEL(DEBUG, "Compose: " << f5 << " * " << fCalleeSummary << " * " @@ -444,11 +440,10 @@ class IDESolver FlowFunctionPtrType CallToReturnFF = CachedFlowEdgeFunctions.getCallToRetFlowFunction(n, ReturnSiteN, Callees); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); container_type ReturnFacts = computeCallToReturnFlowFunction(CallToReturnFF, d1, d2); - ADD_TO_HISTOGRAM("Data-flow facts", returnFacts.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + ADD_TO_HISTOGRAM("Data-flow facts", ReturnFacts.size(), 1, Full); saveEdges(n, ReturnSiteN, d2, ReturnFacts, false); for (d_t d3 : ReturnFacts) { EdgeFunction EdgeFnE = @@ -460,7 +455,7 @@ class IDESolver IntermediateEdgeFunctions[std::make_tuple(n, d2, ReturnSiteN, d3)] .push_back(EdgeFnE); } - INC_COUNTER("EF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("EF Queries", 1, Full); auto fPrime = f.composeWith(EdgeFnE); PHASAR_LOG_LEVEL(DEBUG, "Compose: " << EdgeFnE << " * " << f << " = " << fPrime); @@ -476,7 +471,7 @@ class IDESolver /// virtual void processNormalFlow(PathEdge Edge) { PAMM_GET_INSTANCE; - INC_COUNTER("Process Normal", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Process Normal", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Process normal at target: " << IDEProblem.NtoString(Edge.getTarget())); EdgeFunction f = jumpFunction(Edge); @@ -485,10 +480,9 @@ class IDESolver for (const auto nPrime : ICF->getSuccsOf(n)) { FlowFunctionPtrType FlowFunc = CachedFlowEdgeFunctions.getNormalFlowFunction(n, nPrime); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); const container_type Res = computeNormalFlowFunction(FlowFunc, d1, d2); - ADD_TO_HISTOGRAM("Data-flow facts", res.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + ADD_TO_HISTOGRAM("Data-flow facts", Res.size(), 1, Full); saveEdges(n, nPrime, d2, Res, false); for (d_t d3 : Res) { EdgeFunction g = @@ -501,7 +495,7 @@ class IDESolver } PHASAR_LOG_LEVEL(DEBUG, "Compose: " << g << " * " << f << " = " << fPrime); - INC_COUNTER("EF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("EF Queries", 1, Full); WorkList.emplace_back(PathEdge(d1, nPrime, std::move(d3)), std::move(fPrime)); } @@ -523,7 +517,7 @@ class IDESolver auto fPrime = Entry.second; n_t SP = Stmt; l_t Val = val(SP, Fact); - INC_COUNTER("Value Propagation", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Value Propagation", 1, Full); propagateValue(CallSite, dPrime, fPrime.computeTarget(Val)); } } @@ -535,7 +529,7 @@ class IDESolver for (const f_t Callee : ICF->getCalleesOfCallAt(Stmt)) { FlowFunctionPtrType CallFlowFunction = CachedFlowEdgeFunctions.getCallFlowFunction(Stmt, Callee); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); for (const d_t dPrime : CallFlowFunction->computeTargets(Fact)) { EdgeFunction EdgeFn = CachedFlowEdgeFunctions.getCallEdgeFunction( Stmt, Fact, Callee, dPrime); @@ -546,9 +540,9 @@ class IDESolver .push_back(EdgeFn); } } - INC_COUNTER("EF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("EF Queries", 1, Full); for (const n_t StartPoint : ICF->getStartPointsOf(Callee)) { - INC_COUNTER("Value Propagation", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Value Propagation", 1, Full); propagateValue(StartPoint, dPrime, EdgeFn.computeTarget(val(Stmt, Fact))); } @@ -629,7 +623,7 @@ class IDESolver // should be made a callable at some point void pathEdgeProcessingTask(PathEdge Edge) { PAMM_GET_INSTANCE; - INC_COUNTER("JumpFn Construction", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("JumpFn Construction", 1, Full); IF_LOG_ENABLED( PHASAR_LOG_LEVEL( DEBUG, @@ -696,7 +690,7 @@ class IDESolver setVal(n, d, IDEProblem.join(val(n, d), fPrime.computeTarget(std::move(TargetVal)))); - INC_COUNTER("Value Computation", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Value Computation", 1, Full); } } } @@ -793,7 +787,7 @@ class IDESolver PHASAR_LOG_LEVEL(DEBUG, "\tFact: " << IDEProblem.DtoString(Fact)); PHASAR_LOG_LEVEL(DEBUG, "\tValue: " << IDEProblem.LtoString(Value)); if (!IDEProblem.isZeroValue(Fact)) { - INC_COUNTER("Gen facts", 1, PAMM_SEVERITY_LEVEL::Core); + INC_COUNTER("Gen facts", 1, Core); } WorkList.emplace_back(PathEdge(Fact, StartPoint, Fact), EdgeIdentity{}); @@ -811,7 +805,7 @@ class IDESolver /// virtual void processExit(const PathEdge Edge) { PAMM_GET_INSTANCE; - INC_COUNTER("Process Exit", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("Process Exit", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Process exit at target: " << IDEProblem.NtoString(Edge.getTarget())); n_t n = Edge.getTarget(); // an exit node; line 21... @@ -843,13 +837,12 @@ class IDESolver FlowFunctionPtrType RetFunction = CachedFlowEdgeFunctions.getRetFlowFunction( c, FunctionThatNeedsSummary, n, RetSiteC); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); // for each incoming-call value for (d_t d4 : Entry.second) { const container_type Targets = computeReturnFlowFunction(RetFunction, d1, d2, c, Entry.second); - ADD_TO_HISTOGRAM("Data-flow facts", targets.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + ADD_TO_HISTOGRAM("Data-flow facts", Targets.size(), 1, Full); saveEdges(n, RetSiteC, d2, Targets, true); // for each target value at the return site // line 23 @@ -872,7 +865,7 @@ class IDESolver IntermediateEdgeFunctions[std::make_tuple(n, d2, RetSiteC, d5)] .push_back(f5); } - INC_COUNTER("EF Queries", 2, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("EF Queries", 2, Full); // compose call function * function * return function PHASAR_LOG_LEVEL(DEBUG, "Compose: " << f5 << " * " << f << " * " << f4); @@ -914,11 +907,10 @@ class IDESolver FlowFunctionPtrType RetFunction = CachedFlowEdgeFunctions.getRetFlowFunction( Caller, FunctionThatNeedsSummary, n, RetSiteC); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); const container_type Targets = computeReturnFlowFunction( RetFunction, d1, d2, Caller, Container{ZeroValue}); - ADD_TO_HISTOGRAM("Data-flow facts", targets.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + ADD_TO_HISTOGRAM("Data-flow facts", Targets.size(), 1, Full); saveEdges(n, RetSiteC, d2, Targets, true); for (d_t d5 : Targets) { EdgeFunction f5 = @@ -929,7 +921,7 @@ class IDESolver IntermediateEdgeFunctions[std::make_tuple(n, d2, RetSiteC, d5)] .push_back(f5); } - INC_COUNTER("EF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("EF Queries", 1, Full); PHASAR_LOG_LEVEL(DEBUG, "Compose: " << f5 << " * " << f); propagteUnbalancedReturnFlow(RetSiteC, d5, f.composeWith(f5), Caller); @@ -946,7 +938,7 @@ class IDESolver FlowFunctionPtrType RetFunction = CachedFlowEdgeFunctions.getRetFlowFunction( nullptr, FunctionThatNeedsSummary, n, nullptr); - INC_COUNTER("FF Queries", 1, PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("FF Queries", 1, Full); RetFunction->computeTargets(d2); } } @@ -1331,11 +1323,14 @@ class IDESolver // Special case if (ProcessSummaryFacts.find(std::make_pair(Edge.second, D2)) != ProcessSummaryFacts.end()) { - std::multiset SummaryDMultiSet = - EndsummaryTab.get(Edge.second, D2).columnKeySet(); - // remove duplicates from multiset - std::set SummaryDSet(SummaryDMultiSet.begin(), - SummaryDMultiSet.end()); + + std::set SummaryDSet; + EndsummaryTab.get(Edge.second, D2) + .foreachCell([&SummaryDSet](const auto &Row, const auto &Col, + const auto &Val) { + SummaryDSet.insert(Col); + }); + // Process summary just as an intra-procedural edge if (SummaryDSet.find(D2) != SummaryDSet.end()) { NumGenFacts += SummaryDSet.size() - 1; @@ -1384,13 +1379,10 @@ class IDESolver PHASAR_LOG_LEVEL(DEBUG, "#Reuse: " << Entry.second); TotalSummaryReuse += Entry.second; } - INC_COUNTER("Gen facts", NumGenFacts, PAMM_SEVERITY_LEVEL::Core); - INC_COUNTER("Kill facts", NumKillFacts, PAMM_SEVERITY_LEVEL::Core); - INC_COUNTER("Summary-reuse", TotalSummaryReuse, PAMM_SEVERITY_LEVEL::Core); - INC_COUNTER("Intra Path Edges", NumIntraPathEdges, - PAMM_SEVERITY_LEVEL::Core); - INC_COUNTER("Inter Path Edges", NumInterPathEdges, - PAMM_SEVERITY_LEVEL::Core); + INC_COUNTER("Gen facts", NumGenFacts, Core); + INC_COUNTER("Summary-reuse", TotalSummaryReuse, Core); + INC_COUNTER("Intra Path Edges", NumIntraPathEdges, Core); + INC_COUNTER("Inter Path Edges", NumInterPathEdges, Core); PHASAR_LOG_LEVEL(INFO, "----------------------------------------------"); PHASAR_LOG_LEVEL(INFO, "=== Solver Statistics ==="); @@ -1658,30 +1650,30 @@ class IDESolver bool doInitialize() { PAMM_GET_INSTANCE; - REG_COUNTER("Gen facts", 0, PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("Kill facts", 0, PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("Summary-reuse", 0, PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("Intra Path Edges", 0, PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("Inter Path Edges", 0, PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("FF Queries", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("EF Queries", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Value Propagation", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Value Computation", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("SpecialSummary-FF Application", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("SpecialSummary-EF Queries", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("JumpFn Construction", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Process Call", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Process Normal", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("Process Exit", 0, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("[Calls] getAliasSet", 0, PAMM_SEVERITY_LEVEL::Full); - REG_HISTOGRAM("Data-flow facts", PAMM_SEVERITY_LEVEL::Full); - REG_HISTOGRAM("Points-to", PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("Gen facts", 0, Core); + REG_COUNTER("Kill facts", 0, Core); + REG_COUNTER("Summary-reuse", 0, Core); + REG_COUNTER("Intra Path Edges", 0, Core); + REG_COUNTER("Inter Path Edges", 0, Core); + REG_COUNTER("FF Queries", 0, Full); + REG_COUNTER("EF Queries", 0, Full); + REG_COUNTER("Value Propagation", 0, Full); + REG_COUNTER("Value Computation", 0, Full); + REG_COUNTER("SpecialSummary-FF Application", 0, Full); + REG_COUNTER("SpecialSummary-EF Queries", 0, Full); + REG_COUNTER("JumpFn Construction", 0, Full); + REG_COUNTER("Process Call", 0, Full); + REG_COUNTER("Process Normal", 0, Full); + REG_COUNTER("Process Exit", 0, Full); + REG_COUNTER("[Calls] getAliasSet", 0, Full); + REG_HISTOGRAM("Data-flow facts", Full); + REG_HISTOGRAM("Points-to", Full); PHASAR_LOG_LEVEL(INFO, "IDE solver is solving the specified problem"); PHASAR_LOG_LEVEL(INFO, "Submit initial seeds, construct exploded super graph"); // computations starting here - START_TIMER("DFA Phase I", PAMM_SEVERITY_LEVEL::Full); + START_TIMER("DFA Phase I", Full); // We start our analysis and construct exploded supergraph submitInitialSeeds(); @@ -1701,14 +1693,15 @@ class IDESolver } void finalizeInternal() { - STOP_TIMER("DFA Phase I", PAMM_SEVERITY_LEVEL::Full); + PAMM_GET_INSTANCE; + STOP_TIMER("DFA Phase I", Full); if (SolverConfig.computeValues()) { - START_TIMER("DFA Phase II", PAMM_SEVERITY_LEVEL::Full); + START_TIMER("DFA Phase II", Full); // Computing the final values for the edge functions PHASAR_LOG_LEVEL( INFO, "Compute the final values according to the edge functions"); computeValues(); - STOP_TIMER("DFA Phase II", PAMM_SEVERITY_LEVEL::Full); + STOP_TIMER("DFA Phase II", Full); } PHASAR_LOG_LEVEL(INFO, "Problem solved"); if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::Core) { diff --git a/include/phasar/DataFlow/IfdsIde/SolverResults.h b/include/phasar/DataFlow/IfdsIde/SolverResults.h index fb532a134..780f1ea6f 100644 --- a/include/phasar/DataFlow/IfdsIde/SolverResults.h +++ b/include/phasar/DataFlow/IfdsIde/SolverResults.h @@ -138,7 +138,7 @@ class SolverResultsBase { using f_t = typename ICFGTy::f_t; PAMM_GET_INSTANCE; - START_TIMER("DFA IDE Result Dumping", PAMM_SEVERITY_LEVEL::Full); + START_TIMER("DFA IDE Result Dumping", Full); OS << "\n***************************************************************\n" << "* Raw IDESolver results *\n" << "***************************************************************\n"; @@ -179,7 +179,7 @@ class SolverResultsBase { } } OS << '\n'; - STOP_TIMER("DFA IDE Result Dumping", PAMM_SEVERITY_LEVEL::Full); + STOP_TIMER("DFA IDE Result Dumping", Full); } template diff --git a/include/phasar/Utils/PAMM.h b/include/phasar/Utils/PAMM.h index 2f9265516..50f8f215c 100644 --- a/include/phasar/Utils/PAMM.h +++ b/include/phasar/Utils/PAMM.h @@ -17,12 +17,18 @@ #ifndef PHASAR_UTILS_PAMM_H_ #define PHASAR_UTILS_PAMM_H_ +#include "phasar/Utils/TypeTraits.h" + +#include "llvm/ADT/ArrayRef.h" +#include "llvm/ADT/StringMap.h" +#include "llvm/ADT/StringRef.h" + #include // high_resolution_clock::time_point, milliseconds +#include #include -#include // set -#include // string -#include // unordered_map -#include // vector +#include // set +#include // string +#include // vector namespace llvm { class raw_ostream; @@ -50,24 +56,13 @@ namespace psr { /// @note This class implements the Singleton Pattern - use the /// PAMM_GET_INSTANCE macro to retrieve an instance of PAMM before you use any /// other macro from this class. -class PAMM { -private: - PAMM() = default; - ~PAMM() = default; +class PAMM final { +public: using TimePoint_t = std::chrono::high_resolution_clock::time_point; using Duration_t = std::chrono::milliseconds; - std::unordered_map RunningTimer; - std::unordered_map> - StoppedTimer; - std::unordered_map>> - RepeatingTimer; - std::unordered_map Counter; - std::unordered_map> - Histogram; -public: + PAMM() noexcept = default; + ~PAMM() = default; // PAMM is used as singleton. PAMM(const PAMM &PM) = delete; PAMM(PAMM &&PM) = delete; @@ -76,7 +71,7 @@ class PAMM { /// \brief Returns a reference to the PAMM object (singleton) - associated /// macro: PAMM_GET_INSTANCE. - static PAMM &getInstance(); + [[nodiscard]] static PAMM &getInstance(); /// \brief Resets PAMM, i.e. discards all gathered information (timer, counter /// etc.) - associated macro: RESET_PAMM. @@ -86,12 +81,12 @@ class PAMM { /// \brief Starts a timer under the given timer id - associated macro: /// START_TIMER(TIMER_ID, SEV_LVL). /// \param TimerId Unique timer id. - void startTimer(const std::string &TimerId); + void startTimer(llvm::StringRef TimerId); /// \brief Resets timer under the given timer id - associated macro: /// RESET_TIMER(TIMER_ID, SEV_LVL). /// \param TimerId Unique timer id. - void resetTimer(const std::string &TimerId); + void resetTimer(llvm::StringRef TimerId); /// If pauseTimer is true, a running timer gets paused, its start time point /// will paired with a current time point, and stored as an accumulated timer. @@ -107,18 +102,18 @@ class PAMM { /// \brief Stops or pauses a timer under the given timer id. /// \param TimerId Unique timer id. /// \param PauseTimer If true, timer will be paused instead of stopped. - void stopTimer(const std::string &TimerId, bool PauseTimer = false); + void stopTimer(llvm::StringRef TimerId, bool PauseTimer = false); /// \brief Computes the elapsed time of the given timer up until now or up to /// the moment the timer was stopped - associated macro: GET_TIMER(TIMERID) /// \param TimerId Unique timer id. /// \return Timer duration. - unsigned long elapsedTime(const std::string &TimerId); + uint64_t elapsedTime(llvm::StringRef TimerId); /// For each accumulated timer a vector holds all recorded durations. /// \brief Computes the elapsed time for all accumulated timer being used. /// \return Map containing measured durations of all accumulated timer. - std::unordered_map> + [[nodiscard]] llvm::StringMap> elapsedTimeOfRepeatingTimer(); /// A running timer will not be stopped. The precision for time computation @@ -129,42 +124,46 @@ class PAMM { /// explicitly. /// \brief Returns the elapsed time for a given timer id. /// \param timerId Unique timer id. - static std::string getPrintableDuration(unsigned long Duration); + [[nodiscard]] static std::string getPrintableDuration(uint64_t Duration); /// \brief Registers a new counter under the given counter id - associated /// macro: REG_COUNTER(COUNTER_ID, INIT_VALUE, SEV_LVL). /// \param CounterId Unique counter id. - void regCounter(const std::string &CounterId, unsigned IntialValue = 0); + void regCounter(llvm::StringRef CounterId, unsigned IntialValue = 0); /// \brief Increases the count for the given counter - associated macro: /// INC_COUNTER(COUNTER_ID, VALUE, SEV_LVL). /// \param CounterId Unique counter id. /// \param CValue to be added to the current counter. - void incCounter(const std::string &CounterId, unsigned CValue = 1); + void incCounter(llvm::StringRef CounterId, unsigned CValue = 1); /// \brief Decreases the count for the given counter - associated macro: /// DEC_COUNTER(COUNTER_ID, VALUE, SEV_LVL). /// \param CounterId Unique counter id. /// \param CValue to be subtracted from the current counter. - void decCounter(const std::string &CounterId, unsigned CValue = 1); + void decCounter(llvm::StringRef CounterId, unsigned CValue = 1); /// The associated macro does not check PAMM's severity level explicitly. /// \brief Returns the current count for the given counter - associated macro: /// GET_COUNTER(COUNTER_ID). /// \param CounterId Unique counter id. - int getCounter(const std::string &CounterId); + std::optional getCounter(llvm::StringRef CounterId); /// The associated macro does not check PAMM's severity level explicitly. /// \brief Sums the counts for the given counter ids - associated macro: /// GET_SUM_COUNT(...). /// \param CounterIds Unique counter ids. /// \note Macro uses variadic parameters, e.g. GET_SUM_COUNT({"foo", "bar"}). - int getSumCount(const std::set &CounterIds); + std::optional getSumCount(const std::set &CounterIds); + std::optional + getSumCount(llvm::ArrayRef CounterIds); + std::optional + getSumCount(std::initializer_list CounterIds); /// \brief Registers a new histogram - associated macro: /// REG_HISTOGRAM(HISTOGRAM_ID, SEV_LVL). /// \param HistogramId Unique hitogram id. - void regHistogram(const std::string &HistogramId); + void regHistogram(llvm::StringRef HistogramId); /// \brief Adds a new observed data point to the corresponding histogram - /// associated macro: ADD_TO_HISTOGRAM(HISTOGRAM_ID, DATAPOINT_ID, @@ -172,9 +171,10 @@ class PAMM { /// \param HistogramId ID of the histogram that tracks given data points. /// \param DataPointId ID of the given data point. /// \param DataPointValue Value of the given data point. - void addToHistogram(const std::string &HistogramId, - const std::string &DataPointId, - unsigned long DataPointValue = 1); + void addToHistogram(llvm::StringRef HistogramId, llvm::StringRef DataPointId, + uint64_t DataPointValue = 1); + + void stopAllTimers(); void printTimers(llvm::raw_ostream &OS); @@ -190,11 +190,20 @@ class PAMM { /// EXPORT_MEASURED_DATA(PATH). /// \param OutputPath to exported JSON file. void exportMeasuredData( - const std::string &OutputPath, - const std::string &ProjectId = "default-phasar-project", - const std::optional> &Modules = std::nullopt, - const std::optional> &DataFlowAnalyses = - std::nullopt); + const llvm::Twine &OutputPath, + llvm::StringRef ProjectId = "default-phasar-project", + const std::vector *Modules = nullptr, + const std::vector *DataFlowAnalyses = nullptr); + + [[nodiscard]] const auto &getHistogram() const noexcept { return Histogram; } + +private: + llvm::StringMap RunningTimer; + llvm::StringMap> StoppedTimer; + llvm::StringMap>> + RepeatingTimer; + llvm::StringMap Counter; + llvm::StringMap> Histogram; }; } // namespace psr diff --git a/include/phasar/Utils/PAMMMacros.h b/include/phasar/Utils/PAMMMacros.h index adf4356c1..f41ef4a0e 100644 --- a/include/phasar/Utils/PAMMMacros.h +++ b/include/phasar/Utils/PAMMMacros.h @@ -19,14 +19,20 @@ namespace psr { /// Defines the different level of severity of PAMM's performance evaluation -enum PAMM_SEVERITY_LEVEL { Off = 0, Core, Full }; // NOLINT +enum class PAMM_SEVERITY_LEVEL { Off = 0, Core, Full }; // NOLINT #if defined(PAMM_FULL) -static constexpr unsigned PAMM_CURR_SEV_LEVEL = 2; // NOLINT +// NOLINTNEXTLINE +static constexpr PAMM_SEVERITY_LEVEL PAMM_CURR_SEV_LEVEL = + PAMM_SEVERITY_LEVEL::Full; #elif defined(PAMM_CORE) -static constexpr unsigned PAMM_CURR_SEV_LEVEL = 1; // NOLINT +// NOLINTNEXTLINE +static constexpr PAMM_SEVERITY_LEVEL PAMM_CURR_SEV_LEVEL = + PAMM_SEVERITY_LEVEL::Core; #else -static constexpr unsigned PAMM_CURR_SEV_LEVEL = 0; // NOLINT +// NOLINTNEXTLINE +static constexpr PAMM_SEVERITY_LEVEL PAMM_CURR_SEV_LEVEL = + PAMM_SEVERITY_LEVEL::Off; #endif } // namespace psr @@ -39,46 +45,46 @@ static constexpr unsigned PAMM_CURR_SEV_LEVEL = 0; // NOLINT #define PAMM_RESET pamm.reset() #define START_TIMER(TIMER_ID, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.startTimer(TIMER_ID); \ } #define RESET_TIMER(TIMER_ID, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.resetTimer(TIMER_ID); \ } #define PAUSE_TIMER(TIMER_ID, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.stopTimer(TIMER_ID, true); \ } #define STOP_TIMER(TIMER_ID, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.stopTimer(TIMER_ID); \ } #define PRINT_TIMER(TIMER_ID) \ pamm.getPrintableDuration(pamm.elapsedTime(TIMER_ID)) #define REG_COUNTER(COUNTER_ID, INIT_VALUE, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.regCounter(COUNTER_ID, INIT_VALUE); \ } #define INC_COUNTER(COUNTER_ID, VALUE, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.incCounter(COUNTER_ID, VALUE); \ } #define DEC_COUNTER(COUNTER_ID, VALUE, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.decCounter(COUNTER_ID, VALUE); \ } #define GET_COUNTER(COUNTER_ID) pamm.getCounter(COUNTER_ID) #define GET_SUM_COUNT(...) pamm.getSumCount(__VA_ARGS__) #define REG_HISTOGRAM(HISTOGRAM_ID, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ pamm.regHistogram(HISTOGRAM_ID); \ } #define ADD_TO_HISTOGRAM(HISTOGRAM_ID, DATAPOINT_ID, DATAPOINT_VALUE, SEV_LVL) \ - if constexpr (PAMM_CURR_SEV_LEVEL >= SEV_LVL) { \ - pamm.addToHistogram(HISTOGRAM_ID, std::to_string(DATAPOINT_ID), \ + if constexpr (PAMM_CURR_SEV_LEVEL >= PAMM_SEVERITY_LEVEL::SEV_LVL) { \ + pamm.addToHistogram(HISTOGRAM_ID, adl_to_string(DATAPOINT_ID), \ DATAPOINT_VALUE); \ } @@ -101,9 +107,10 @@ static constexpr unsigned PAMM_CURR_SEV_LEVEL = 0; // NOLINT #define EXPORT_MEASURED_DATA(PATH) // The following macros could be used in log messages, thus they have to // provide some default value to avoid compiler errors -#define PRINT_TIMER(TIMER_ID) "-1" -#define GET_COUNTER(COUNTER_ID) "-1" -#define GET_SUM_COUNT(...) "-1" +#define PRINT_TIMER(TIMER_ID) "" +#define GET_COUNTER(COUNTER_ID) "" +#define GET_SUM_COUNT(...) "" + #endif #endif diff --git a/include/phasar/Utils/TypeTraits.h b/include/phasar/Utils/TypeTraits.h index 0957292bb..3f1d8d302 100644 --- a/include/phasar/Utils/TypeTraits.h +++ b/include/phasar/Utils/TypeTraits.h @@ -66,6 +66,19 @@ template struct has_str().str())> : std::true_type { }; // NOLINT +template struct has_adl_to_string { + template ())))> + static std::true_type test(int); + template ()))> + static std::true_type test(long); + template static std::false_type test(...); + + static constexpr bool value = + std::is_same_v; +}; + template struct has_erase_iterator : std::false_type {}; // NOLINT template @@ -155,6 +168,9 @@ constexpr bool is_printable_v = detail::is_printable::value; // NOLINT template constexpr bool has_str_v = detail::has_str::value; // NOLINT +template +constexpr bool has_adl_to_string_v = detail::has_adl_to_string::value; + template constexpr bool has_erase_iterator_v = // NOLINT detail::has_erase_iterator::value; @@ -233,6 +249,12 @@ template struct DefaultConstruct { } }; +template >> +[[nodiscard]] decltype(auto) adl_to_string(const T &Val) { + using std::to_string; + return to_string(Val); +} + // NOLINTEND(readability-identifier-naming) } // namespace psr diff --git a/include/phasar/Utils/Utilities.h b/include/phasar/Utils/Utilities.h index 512345a2e..12154af21 100644 --- a/include/phasar/Utils/Utilities.h +++ b/include/phasar/Utils/Utilities.h @@ -15,6 +15,7 @@ #include "llvm/ADT/Hashing.h" #include "llvm/ADT/SmallVector.h" +#include "llvm/Support/raw_ostream.h" #include #include @@ -253,6 +254,18 @@ auto remove_by_index(Container &Cont, const Indices &Idx) { return remove_by_index(begin(Cont), end(Cont), begin(Idx), end(Idx)); } +template >> +llvm::raw_ostream &operator<<(llvm::raw_ostream &OS, + const std::optional &Opt) { + if (Opt) { + OS << *Opt; + } else { + OS << ""; + } + + return OS; +} + } // namespace psr #endif diff --git a/lib/PhasarLLVM/ControlFlow/LLVMBasedICFG.cpp b/lib/PhasarLLVM/ControlFlow/LLVMBasedICFG.cpp index 591e4e746..42d715c27 100644 --- a/lib/PhasarLLVM/ControlFlow/LLVMBasedICFG.cpp +++ b/lib/PhasarLLVM/ControlFlow/LLVMBasedICFG.cpp @@ -144,9 +144,12 @@ auto LLVMBasedICFG::Builder::buildCallGraph(Soundness /*S*/) << llvmIRToString(IndirectCall)); } } - REG_COUNTER("CG Vertices", boost::num_vertices(ret), - PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("CG Edges", boost::num_edges(ret), PAMM_SEVERITY_LEVEL::Full); + + PAMM_GET_INSTANCE; + REG_COUNTER("CG Functions", CGBuilder.viewCallGraph().getNumVertexFunctions(), + Full); + REG_COUNTER("CG CallSites", CGBuilder.viewCallGraph().getNumVertexCallSites(), + Full); PHASAR_LOG_LEVEL_CAT(INFO, "LLVMBasedICFG", "Call graph has been constructed"); return CGBuilder.consumeCallGraph(); diff --git a/lib/PhasarLLVM/DataFlow/IfdsIde/Problems/IFDSConstAnalysis.cpp b/lib/PhasarLLVM/DataFlow/IfdsIde/Problems/IFDSConstAnalysis.cpp index 0213a77ad..7a9d83212 100644 --- a/lib/PhasarLLVM/DataFlow/IfdsIde/Problems/IFDSConstAnalysis.cpp +++ b/lib/PhasarLLVM/DataFlow/IfdsIde/Problems/IFDSConstAnalysis.cpp @@ -40,9 +40,8 @@ IFDSConstAnalysis::IFDSConstAnalysis(const LLVMProjectIRDB *IRDB, PT(PT) { assert(PT); PAMM_GET_INSTANCE; - REG_HISTOGRAM("Context-relevant Pointer", PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("[Calls] getContextRelevantAliasSet", 0, - PAMM_SEVERITY_LEVEL::Full); + REG_HISTOGRAM("Context-relevant Pointer", Full); + REG_COUNTER("[Calls] getContextRelevantAliasSet", 0, Full); } IFDSConstAnalysis::FlowFunctionPtrType @@ -207,10 +206,8 @@ std::set IFDSConstAnalysis::getContextRelevantAliasSet( std::set &AliasSet, IFDSConstAnalysis::f_t CurrentContext) { PAMM_GET_INSTANCE; - INC_COUNTER("[Calls] getContextRelevantAliasSet", 1, - PAMM_SEVERITY_LEVEL::Full); - START_TIMER("Context-Relevant-Alias-Set Computation", - PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("[Calls] getContextRelevantAliasSet", 1, Full); + START_TIMER("Context-Relevant-Alias-Set Computation", Full); std::set ToGenerate; for (const auto *Alias : AliasSet) { PHASAR_LOG_LEVEL(DEBUG, "Alias: " << llvmIRToString(Alias)); @@ -238,10 +235,8 @@ std::set IFDSConstAnalysis::getContextRelevantAliasSet( } } // ignore everything else } - PAUSE_TIMER("Context-Relevant-Alias-Set Computation", - PAMM_SEVERITY_LEVEL::Full); - ADD_TO_HISTOGRAM("Context-relevant Pointer", ToGenerate.size(), 1, - PAMM_SEVERITY_LEVEL::Full); + PAUSE_TIMER("Context-Relevant-Alias-Set Computation", Full); + ADD_TO_HISTOGRAM("Context-relevant Pointer", ToGenerate.size(), 1, Full); return ToGenerate; } diff --git a/lib/PhasarLLVM/Passes/GeneralStatisticsAnalysis.cpp b/lib/PhasarLLVM/Passes/GeneralStatisticsAnalysis.cpp index 974ab2ba4..0b46a0c6f 100644 --- a/lib/PhasarLLVM/Passes/GeneralStatisticsAnalysis.cpp +++ b/lib/PhasarLLVM/Passes/GeneralStatisticsAnalysis.cpp @@ -139,23 +139,15 @@ GeneralStatistics GeneralStatisticsAnalysis::runOnModule(llvm::Module &M) { // the counter with the values of the counter varibles, i.e. PAMM simply // holds the results. PAMM_GET_INSTANCE; - REG_COUNTER("GS Instructions", Stats.instructions, PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("GS Allocated Types", Stats.allocatedTypes.size(), - PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Allocation-Sites", Stats.allocationsites, - PAMM_SEVERITY_LEVEL::Core); - REG_COUNTER("GS Basic Blocks", Stats.basicblocks, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Call-Sites", Stats.callsites, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Functions", Stats.functions, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Globals", Stats.globals, PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Global Pointer", Stats.globalPointers, - PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Memory Intrinsics", Stats.memIntrinsic, - PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Store Instructions", Stats.storeInstructions, - PAMM_SEVERITY_LEVEL::Full); - REG_COUNTER("GS Load Instructions", Stats.loadInstructions, - PAMM_SEVERITY_LEVEL::Full); + REG_COUNTER("GS Instructions", Stats.Instructions, Core); + REG_COUNTER("GS Allocated Types", Stats.AllocatedTypes.size(), Full); + REG_COUNTER("GS Basic Blocks", Stats.BasicBlocks, Full); + REG_COUNTER("GS Call-Sites", Stats.CallSites, Full); + REG_COUNTER("GS Functions", Stats.Functions, Full); + REG_COUNTER("GS Globals", Stats.Globals, Full); + REG_COUNTER("GS Memory Intrinsics", Stats.MemIntrinsics, Full); + REG_COUNTER("GS Store Instructions", Stats.StoreInstructions, Full); + REG_COUNTER("GS Load Instructions", Stats.LoadInstructions, Full); // Using the logging guard explicitly since we are printing allocated types // manually IF_LOG_ENABLED( diff --git a/lib/PhasarLLVM/Pointer/LLVMAliasGraph.cpp b/lib/PhasarLLVM/Pointer/LLVMAliasGraph.cpp index 7eb255bce..5d217fb44 100644 --- a/lib/PhasarLLVM/Pointer/LLVMAliasGraph.cpp +++ b/lib/PhasarLLVM/Pointer/LLVMAliasGraph.cpp @@ -205,7 +205,7 @@ void LLVMAliasGraph::computeAliasGraph(llvm::Function *F) { } } - INC_COUNTER("GS Pointer", Pointers.size(), PAMM_SEVERITY_LEVEL::Core); + INC_COUNTER("GS Pointer", Pointers.size(), Core); // make vertices for all pointers for (auto *P : Pointers) { @@ -363,8 +363,8 @@ auto LLVMAliasGraph::getAliasSet(const llvm::Value *V, const llvm::Instruction * /*I*/) -> AliasSetPtrTy { PAMM_GET_INSTANCE; - INC_COUNTER("[Calls] getAliasSet", 1, PAMM_SEVERITY_LEVEL::Full); - START_TIMER("Alias-Set Computation", PAMM_SEVERITY_LEVEL::Full); + INC_COUNTER("[Calls] getAliasSet", 1, Full); + START_TIMER("Alias-Set Computation", Full); const auto *VF = retrieveFunction(V); computeAliasGraph(VF); // check if the graph contains a corresponding vertex @@ -388,9 +388,8 @@ auto LLVMAliasGraph::getAliasSet(const llvm::Value *V, for (auto Vertex : ReachableVertices) { ResultSet->insert(PAG[Vertex].V); } - PAUSE_TIMER("Alias-Set Computation", PAMM_SEVERITY_LEVEL::Full); - ADD_TO_HISTOGRAM("Points-to", ResultSet->size(), 1, - PAMM_SEVERITY_LEVEL::Full); + PAUSE_TIMER("Alias-Set Computation", Full); + ADD_TO_HISTOGRAM("Points-to", ResultSet->size(), 1, Full); return ResultSet; } diff --git a/lib/Utils/PAMM.cpp b/lib/Utils/PAMM.cpp index 7da9b7f5f..b1ea931ac 100644 --- a/lib/Utils/PAMM.cpp +++ b/lib/Utils/PAMM.cpp @@ -16,15 +16,26 @@ #include "phasar/Utils/PAMM.h" +#include "phasar/Utils/ChronoUtils.h" +#include "phasar/Utils/NlohmannLogging.h" + +#include "llvm/ADT/SmallString.h" +#include "llvm/ADT/StringRef.h" +#include "llvm/ADT/Twine.h" +#include "llvm/Support/Compiler.h" +#include "llvm/Support/ErrorHandling.h" #include "llvm/Support/raw_ostream.h" #include "nlohmann/json.hpp" #include +#include #include #include #include +#include #include +#include using namespace psr; using json = nlohmann::json; @@ -36,38 +47,43 @@ PAMM &PAMM::getInstance() { return Instance; } -void PAMM::startTimer(const std::string &TimerId) { - bool ValidTimerId = - !RunningTimer.count(TimerId) && !StoppedTimer.count(TimerId); - assert(ValidTimerId && "startTimer failed due to an invalid timer id"); - if (ValidTimerId) { - PAMM::TimePoint_t Start = std::chrono::high_resolution_clock::now(); - RunningTimer[TimerId] = Start; +void PAMM::startTimer(llvm::StringRef TimerId) { + if (LLVM_UNLIKELY(StoppedTimer.count(TimerId))) { + llvm::report_fatal_error("Do not start an already stopped timer"); } + + auto [It, Inserted] = RunningTimer.try_emplace(TimerId); + if (LLVM_UNLIKELY(!Inserted)) { + llvm::report_fatal_error("Do not start an already running timer"); + } + + PAMM::TimePoint_t Start = std::chrono::high_resolution_clock::now(); + It->second = Start; } -void PAMM::resetTimer(const std::string &TimerId) { - assert((RunningTimer.count(TimerId) && !StoppedTimer.count(TimerId)) || - (!RunningTimer.count(TimerId) && StoppedTimer.count(TimerId)) && +void PAMM::resetTimer(llvm::StringRef TimerId) { + bool InRunningTimers = RunningTimer.erase(TimerId); + bool InStoppedTimers = StoppedTimer.erase(TimerId); + + assert((InRunningTimers && !InStoppedTimers) || + (!InRunningTimers && InStoppedTimers) && "resetTimer failed due to an invalid timer id"); - if (RunningTimer.count(TimerId)) { - RunningTimer.erase(RunningTimer.find(TimerId)); - } else if (StoppedTimer.count(TimerId)) { - StoppedTimer.erase(StoppedTimer.find(TimerId)); - } } -void PAMM::stopTimer(const std::string &TimerId, bool PauseTimer) { - bool TimerRunning = RunningTimer.count(TimerId); - bool ValidTimerId = TimerRunning || StoppedTimer.count(TimerId); +void PAMM::stopTimer(llvm::StringRef TimerId, bool PauseTimer) { + auto RunningIt = RunningTimer.find(TimerId); + auto StoppedIt = StoppedTimer.find(TimerId); + bool TimerRunning = RunningIt != RunningTimer.end(); + bool TimerStopped = StoppedIt != StoppedTimer.end(); + bool ValidTimerId = TimerRunning || TimerStopped; assert(ValidTimerId && "stopTimer failed due to an invalid timer id or timer " "was already stopped"); assert(TimerRunning && "stopTimer failed because timer was already stopped"); - if (ValidTimerId) { - auto Timer = RunningTimer.find(TimerId); + + if (LLVM_LIKELY(ValidTimerId)) { PAMM::TimePoint_t End = std::chrono::high_resolution_clock::now(); - PAMM::TimePoint_t Start = Timer->second; - RunningTimer.erase(Timer); + PAMM::TimePoint_t Start = RunningIt->second; + RunningTimer.erase(RunningIt); auto P = make_pair(Start, End); if (PauseTimer) { RepeatingTimer[TimerId].push_back(P); @@ -77,191 +93,220 @@ void PAMM::stopTimer(const std::string &TimerId, bool PauseTimer) { } } -unsigned long PAMM::elapsedTime(const std::string &TimerId) { - assert((RunningTimer.count(TimerId) || StoppedTimer.count(TimerId)) && - "elapsedTime failed due to an invalid timer id"); - if (RunningTimer.count(TimerId)) { +uint64_t PAMM::elapsedTime(llvm::StringRef TimerId) { + auto RunningIt = RunningTimer.find(TimerId); + + if (RunningIt != RunningTimer.end()) { PAMM::TimePoint_t End = std::chrono::high_resolution_clock::now(); - PAMM::TimePoint_t Start = RunningTimer[TimerId]; + PAMM::TimePoint_t Start = RunningIt->second; auto Duration = std::chrono::duration_cast(End - Start); return Duration.count(); } - if (StoppedTimer.count(TimerId)) { - auto Duration = std::chrono::duration_cast( - StoppedTimer[TimerId].second - StoppedTimer[TimerId].first); + if (auto StoppedIt = StoppedTimer.find(TimerId); + StoppedIt != StoppedTimer.end()) { + auto [Start, End] = StoppedIt->second; + auto Duration = std::chrono::duration_cast(End - Start); return Duration.count(); } + + assert(false && "elapsedTime failed due to an invalid timer id"); return 0; } -std::unordered_map> -PAMM::elapsedTimeOfRepeatingTimer() { - std::unordered_map> AccTimes; +template +static void foreachElapsedTimeOfRepeatingTimer( + llvm::StringMap< + std::vector>> + &RepeatingTimer, + HandlerFn Handler) { for (const auto &Timer : RepeatingTimer) { - std::vector AccTimeVec; - for (auto Timepair : Timer.second) { - auto Duration = std::chrono::duration_cast( - Timepair.second - Timepair.first); - AccTimeVec.push_back(Duration.count()); - } - AccTimes[Timer.first] = AccTimeVec; + std::invoke( + Handler, Timer.first(), [&Timer](std::vector &AccTimeVec) { + AccTimeVec.reserve(Timer.second.size()); + + for (auto [Start, End] : Timer.second) { + auto Duration = + std::chrono::duration_cast(End - Start); + AccTimeVec.push_back(Duration.count()); + } + }); } +} + +llvm::StringMap> PAMM::elapsedTimeOfRepeatingTimer() { + llvm::StringMap> AccTimes; + + foreachElapsedTimeOfRepeatingTimer( + RepeatingTimer, [&AccTimes](llvm::StringRef Id, auto Handler) { + std::invoke(std::move(Handler), AccTimes[Id]); + }); + return AccTimes; } -std::string PAMM::getPrintableDuration(unsigned long Duration) { - unsigned long Milliseconds = Duration % 1000; - unsigned long Seconds = ((Duration - Milliseconds) / 1000) % 60; - unsigned long Minutes = - ((((Duration - Milliseconds) / 1000) - Seconds) / 60) % 60; - unsigned long Hours = - (((((Duration - Milliseconds) / 1000) - Seconds) / 60) - Minutes) / 60; - std::ostringstream Oss; - if (Hours) { - Oss << Hours << "h "; - } - if (Minutes) { - Oss << Minutes << "m "; - } - if (Seconds) { - Oss << Seconds << "sec "; - } - if (Milliseconds) { - Oss << Milliseconds << "ms"; - } else { - Oss << "0 ms"; - } - return Oss.str(); +std::string PAMM::getPrintableDuration(uint64_t Duration) { + return hms(std::chrono::milliseconds{Duration}).str(); } -void PAMM::regCounter(const std::string &CounterId, unsigned IntialValue) { - bool ValidCounterId = !Counter.count(CounterId); - assert(ValidCounterId && "regCounter failed due to an invalid counter id"); - if (ValidCounterId) { - Counter[CounterId] = IntialValue; - } +void PAMM::regCounter(llvm::StringRef CounterId, unsigned IntialValue) { + auto [It, Inserted] = Counter.try_emplace(CounterId, IntialValue); + assert(Inserted && "regCounter failed due to an invalid counter id"); } -void PAMM::incCounter(const std::string &CounterId, unsigned CValue) { - bool ValidCounterId = Counter.count(CounterId); +void PAMM::incCounter(llvm::StringRef CounterId, unsigned CValue) { + auto It = Counter.find(CounterId); + bool ValidCounterId = It != Counter.end(); assert(ValidCounterId && "incCounter failed due to an invalid counter id"); if (ValidCounterId) { - Counter[CounterId] += CValue; + It->second += CValue; } } -void PAMM::decCounter(const std::string &CounterId, unsigned CValue) { - bool ValidCounterId = Counter.count(CounterId); +void PAMM::decCounter(llvm::StringRef CounterId, unsigned CValue) { + auto It = Counter.find(CounterId); + bool ValidCounterId = It != Counter.end(); assert(ValidCounterId && "decCounter failed due to an invalid counter id"); if (ValidCounterId) { - Counter[CounterId] -= CValue; + It->second -= CValue; } } -int PAMM::getCounter(const std::string &CounterId) { - bool ValidCounterId = Counter.count(CounterId); +std::optional PAMM::getCounter(llvm::StringRef CounterId) { + auto It = Counter.find(CounterId); + bool ValidCounterId = It != Counter.end(); assert(ValidCounterId && "getCounter failed due to an invalid counter id"); if (ValidCounterId) { - return Counter[CounterId]; + return It->second; } - return -1; + return std::nullopt; } -int PAMM::getSumCount(const std::set &CounterIds) { - int Sum = 0; - for (const std::string &Id : CounterIds) { - int Count = getCounter(Id); - assert(Count != -1 && "getSumCount failed due to an invalid counter id"); - if (Count != -1) { - Sum += Count; - } else { - return -1; +template +static std::optional +getSumCountInternal(PAMM &P, ForwardIterator It, + ForwardIteratorSentinel End) noexcept { + uint64_t Ctr = 0; + for (; It != End; ++It) { + auto Count = P.getCounter(*It); + if (!Count) { + return std::nullopt; } + + Ctr += *Count; } - return Sum; + + return Ctr; } -void PAMM::regHistogram(const std::string &HistogramId) { - bool ValidHid = !Histogram.count(HistogramId); - assert(ValidHid && "failed to register new histogram due to an invalid id"); - if (ValidHid) { - std::unordered_map H; - Histogram[HistogramId] = H; - } +std::optional +PAMM::getSumCount(const std::set &CounterIds) { + return getSumCountInternal(*this, CounterIds.begin(), CounterIds.end()); } -void PAMM::addToHistogram(const std::string &HistogramId, - const std::string &DataPointId, - unsigned long DataPointValue) { - assert(Histogram.count(HistogramId) && - "adding data point to histogram failed due to invalid id"); - if (Histogram[HistogramId].count(DataPointId)) { - Histogram[HistogramId][DataPointId] += DataPointValue; - } else { - Histogram[HistogramId][DataPointId] = DataPointValue; +std::optional +PAMM::getSumCount(llvm::ArrayRef CounterIds) { + return getSumCountInternal(*this, CounterIds.begin(), CounterIds.end()); +} + +std::optional +PAMM::getSumCount(std::initializer_list CounterIds) { + return getSumCountInternal(*this, CounterIds.begin(), CounterIds.end()); +} + +void PAMM::regHistogram(llvm::StringRef HistogramId) { + auto [It, Inserted] = Histogram.try_emplace(HistogramId); + assert(Inserted && "failed to register new histogram due to an invalid id"); +} + +void PAMM::addToHistogram(llvm::StringRef HistogramId, + llvm::StringRef DataPointId, + uint64_t DataPointValue) { + auto HistIt = Histogram.find(HistogramId); + if (HistIt == Histogram.end()) { + assert(false && "adding data point to histogram failed due to invalid id"); + return; + } + + auto [DataIt, Inserted] = + HistIt->second.try_emplace(DataPointId, DataPointValue); + if (!Inserted) { + DataIt->second += DataPointValue; } } -void PAMM::printTimers(llvm::raw_ostream &Os) { - // stop all running timer +void PAMM::stopAllTimers() { while (!RunningTimer.empty()) { - stopTimer(RunningTimer.begin()->first); + // safe copy + auto Id = RunningTimer.begin()->first().str(); + stopTimer(Id); } - Os << "Single Timer\n"; - Os << "------------\n"; +} + +void PAMM::printTimers(llvm::raw_ostream &OS) { + // stop all running timer + stopAllTimers(); + + OS << "Single Timer\n"; + OS << "------------\n"; for (const auto &Timer : StoppedTimer) { - unsigned long Time = elapsedTime(Timer.first); - Os << Timer.first << " : " << getPrintableDuration(Time) << '\n'; + uint64_t Time = elapsedTime(Timer.first()); + OS << Timer.first() << " : " << getPrintableDuration(Time) << '\n'; } if (StoppedTimer.empty()) { - Os << "No single Timer started!\n\n"; + OS << "No single Timer started!\n\n"; } else { - Os << "\n"; - } - Os << "Repeating Timer\n"; - Os << "---------------\n"; - for (const auto &Timer : elapsedTimeOfRepeatingTimer()) { - unsigned long Sum = 0; - Os << Timer.first << " Timer:\n"; - for (auto Duration : Timer.second) { - Sum += Duration; - Os << Duration << '\n'; - } - Os << "===\n" << Sum << "\n\n"; + OS << "\n"; } + OS << "Repeating Timer\n"; + OS << "---------------\n"; + + foreachElapsedTimeOfRepeatingTimer(RepeatingTimer, + [&OS](llvm::StringRef Id, auto Handler) { + OS << Id << " Timer:\n"; + std::vector Times; + std::invoke(std::move(Handler), Times); + + uint64_t Sum = 0; + for (auto Duration : Times) { + Sum += Duration; + OS << Duration << '\n'; + } + OS << "===\n" << Sum << "\n\n"; + }); + if (RepeatingTimer.empty()) { - Os << "No repeating Timer found!\n"; + OS << "No repeating Timer found!\n"; } else { - Os << '\n'; + OS << '\n'; } } -void PAMM::printCounters(llvm::raw_ostream &Os) { - Os << "\nCounter\n"; - Os << "-------\n"; +void PAMM::printCounters(llvm::raw_ostream &OS) { + OS << "\nCounter\n"; + OS << "-------\n"; for (const auto &Counter : Counter) { - Os << Counter.first << " : " << Counter.second << '\n'; + OS << Counter.first() << " : " << Counter.second << '\n'; } if (Counter.empty()) { - Os << "No Counter registered!\n"; + OS << "No Counter registered!\n"; } else { - Os << "\n"; + OS << "\n"; } } -void PAMM::printHistograms(llvm::raw_ostream &Os) { - Os << "\nHistograms\n"; - Os << "--------------\n"; +void PAMM::printHistograms(llvm::raw_ostream &OS) { + OS << "\nHistograms\n"; + OS << "--------------\n"; for (const auto &H : Histogram) { - Os << H.first << " Histogram\n"; - Os << "Value : #Occurrences\n"; + OS << H.first() << " Histogram\n"; + OS << "Value : #Occurrences\n"; for (const auto &Entry : H.second) { - Os << Entry.first << " : " << Entry.second << '\n'; + OS << Entry.first() << " : " << Entry.second << '\n'; } - Os << '\n'; + OS << '\n'; } if (Histogram.empty()) { - Os << "No histograms tracked!\n"; + OS << "No histograms tracked!\n"; } } @@ -274,72 +319,83 @@ void PAMM::printMeasuredData(llvm::raw_ostream &Os) { } void PAMM::exportMeasuredData( - const std::string &OutputPath, const std::string &ProjectId, - const std::optional> &Modules, - const std::optional> &DataFlowAnalyses) { + const llvm::Twine &OutputPath, llvm::StringRef ProjectId, + const std::vector *Modules, + const std::vector *DataFlowAnalyses) { // json file for holding all data json JsonData; - // add timer data - while (!RunningTimer.empty()) { - stopTimer(std::string(RunningTimer.begin()->first)); - } - json JTimer; - for (const auto &Timer : StoppedTimer) { - unsigned long Time = elapsedTime(Timer.first); - JTimer[Timer.first] = Time; - } - for (const auto &Timer : elapsedTimeOfRepeatingTimer()) { - JTimer[Timer.first] = Timer.second; - } - JsonData["Timer"] = JTimer; + stopAllTimers(); + { + // add timer data + json JTimer; + for (const auto &Timer : StoppedTimer) { + uint64_t Time = elapsedTime(Timer.first()); + JTimer[Timer.first().str()] = Time; + } - // add histogram data if available - json JHistogram; - for (const auto &H : Histogram) { - json JSetH; - for (const auto &Entry : H.second) { - JSetH[Entry.first] = Entry.second; + foreachElapsedTimeOfRepeatingTimer( + RepeatingTimer, [&JTimer](llvm::StringRef Id, auto Handler) { + std::vector Times; + std::invoke(std::move(Handler), Times); + JTimer[Id.str()] = std::move(Times); + }); + + JsonData["Timer"] = std::move(JTimer); + } + + { + // add histogram data if available + json JHistogram; + for (const auto &H : Histogram) { + json JSetH; + for (const auto &Entry : H.second) { + JSetH[Entry.first()] = Entry.second; + } + JHistogram[H.first()] = std::move(JSetH); + } + if (!JHistogram.is_null()) { + JsonData["Histogram"] = std::move(JHistogram); } - JHistogram[H.first] = JSetH; } - if (!JHistogram.is_null()) { - JsonData["Histogram"] = JHistogram; + { + // add counter data + json JCounter; + for (const auto &Counter : Counter) { + JCounter[Counter.first()] = Counter.second; + } + JsonData["Counter"] = std::move(JCounter); } - // add counter data - json JCounter; - for (const auto &Counter : Counter) { - JCounter[Counter.first] = Counter.second; + { + // add analysis/project/source file information if available + json JInfo; + JInfo["Project-ID"] = ProjectId; + + if (Modules) { + JInfo["Module(s)"] = *Modules; + } + if (DataFlowAnalyses) { + JInfo["Data-flow analysis"] = *DataFlowAnalyses; + } + if (!JInfo.is_null()) { + JsonData["Info"] = std::move(JInfo); + } } - JsonData["Counter"] = JCounter; - // add analysis/project/source file information if available - json JInfo; + llvm::SmallString<128> Buf; + OutputPath.toStringRef(Buf); + if (!Buf.endswith(".json")) { + Buf.append(".json"); + } - JInfo["Project-ID"] = ProjectId; + std::error_code EC; + llvm::raw_fd_ostream OS(Buf, EC); - if (Modules) { - JInfo["Module(s)"] = *Modules; - } - if (DataFlowAnalyses) { - JInfo["Data-flow analysis"] = *DataFlowAnalyses; - } - if (!JInfo.is_null()) { - JsonData["Info"] = JInfo; + if (EC) { + throw std::system_error(EC); } - std::string Cfp(OutputPath); - if (Cfp.find(".json") == std::string::npos) { - Cfp += ".json"; - } - std::ofstream File(Cfp); - if (File.is_open()) { - File << std::setw(2) // sets the indentation - << JsonData << std::endl; - File.close(); - } else { - throw std::ios_base::failure("could not write file: " + Cfp); - } + OS << JsonData << '\n'; } void PAMM::reset() { diff --git a/unittests/Utils/PAMMTest.cpp b/unittests/Utils/PAMMTest.cpp index bec561d75..71aa2982e 100644 --- a/unittests/Utils/PAMMTest.cpp +++ b/unittests/Utils/PAMMTest.cpp @@ -2,6 +2,7 @@ #include "phasar/Config/Configuration.h" +#include "llvm/ADT/StringMap.h" #include "llvm/Support/raw_ostream.h" #include "gtest/gtest.h" @@ -29,9 +30,11 @@ class PAMMTest : public ::testing::Test { TEST_F(PAMMTest, HandleTimer) { // PAMM &pamm = PAMM::getInstance(); PAMM::getInstance().startTimer("timer1"); - std::this_thread::sleep_for(std::chrono::milliseconds(1200)); + std::this_thread::sleep_for(std::chrono::milliseconds(120)); PAMM::getInstance().stopTimer("timer1"); - EXPECT_GE(PAMM::getInstance().elapsedTime("timer1"), 1200U); + auto Elapsed = PAMM::getInstance().elapsedTime("timer1"); + EXPECT_GE(Elapsed, 120U) << "Bad time measurement"; + EXPECT_LT(Elapsed, 240U) << "Too much tolerance"; } TEST_F(PAMMTest, HandleCounter) { @@ -72,7 +75,7 @@ TEST_F(PAMMTest, HandleJSONOutput) { Pamm.addToHistogram("Test-Set", "42"); Pamm.incCounter("setOpCount", 11); - std::this_thread::sleep_for(std::chrono::milliseconds(1800)); + std::this_thread::sleep_for(std::chrono::milliseconds(180)); Pamm.stopTimer("timer2"); Pamm.addToHistogram("Test-Set", "42"); @@ -90,7 +93,7 @@ TEST_F(PAMMTest, HandleJSONOutput) { Pamm.startTimer("timer3"); Pamm.incCounter("timerCount"); - std::this_thread::sleep_for(std::chrono::milliseconds(2300)); + std::this_thread::sleep_for(std::chrono::milliseconds(230)); Pamm.addToHistogram("Test-Set", "1"); Pamm.addToHistogram("Test-Set", "1"); @@ -105,99 +108,31 @@ TEST_F(PAMMTest, HandleJSONOutput) { Pamm.incCounter("setOpCount", 9); Pamm.stopTimer("timer3"); Pamm.exportMeasuredData("HandleJSONOutputTest"); -} -TEST_F(PAMMTest, DISABLED_PerformanceTimerBasic) { - time_point Start1 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(10)); - time_point End1 = std::chrono::high_resolution_clock::now(); - time_point Start2 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(20)); - time_point End2 = std::chrono::high_resolution_clock::now(); - time_point Start3 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(30)); - time_point End3 = std::chrono::high_resolution_clock::now(); - time_point Start4 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(40)); - time_point End4 = std::chrono::high_resolution_clock::now(); - time_point Start5 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(50)); - time_point End5 = std::chrono::high_resolution_clock::now(); - time_point Start6 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(100)); - time_point End6 = std::chrono::high_resolution_clock::now(); - time_point Start7 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(150)); - time_point End7 = std::chrono::high_resolution_clock::now(); - time_point Start8 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(200)); - time_point End8 = std::chrono::high_resolution_clock::now(); - time_point Start9 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(300)); - time_point End9 = std::chrono::high_resolution_clock::now(); - time_point Start10 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(500)); - time_point End10 = std::chrono::high_resolution_clock::now(); - time_point Start11 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(1000)); - time_point End11 = std::chrono::high_resolution_clock::now(); - time_point Start12 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(2000)); - time_point End12 = std::chrono::high_resolution_clock::now(); - time_point Start13 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(5000)); - time_point End13 = std::chrono::high_resolution_clock::now(); - time_point Start14 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(10000)); - time_point End14 = std::chrono::high_resolution_clock::now(); - time_point Start15 = std::chrono::high_resolution_clock::now(); - std::this_thread::sleep_for(std::chrono::milliseconds(20000)); - time_point End15 = std::chrono::high_resolution_clock::now(); - auto Duration = - std::chrono::duration_cast(End1 - Start1); - llvm::outs() << "timer_1 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End2 - Start2); - llvm::outs() << "timer_2 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End3 - Start3); - llvm::outs() << "timer_3 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End4 - Start4); - llvm::outs() << "timer_4 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End5 - Start5); - llvm::outs() << "timer_5 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End6 - Start6); - llvm::outs() << "timer_6 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End7 - Start7); - llvm::outs() << "timer_7 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End8 - Start8); - llvm::outs() << "timer_8 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End9 - Start9); - llvm::outs() << "timer_9 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End10 - Start10); - llvm::outs() << "timer_10 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End11 - Start11); - llvm::outs() << "timer_11 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End12 - Start12); - llvm::outs() << "timer_12 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End13 - Start13); - llvm::outs() << "timer_13 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End14 - Start14); - llvm::outs() << "timer_14 : " << Duration.count() << '\n'; - Duration = - std::chrono::duration_cast(End15 - Start15); - llvm::outs() << "timer_15 : " << Duration.count() << '\n'; + EXPECT_EQ(30, Pamm.getCounter("setOpCount")); + EXPECT_EQ(3, Pamm.getCounter("timerCount")); + + auto Timer1Elapsed = Pamm.elapsedTime("timer1"); + auto Timer2Elapsed = Pamm.elapsedTime("timer2"); + auto Timer3Elapsed = Pamm.elapsedTime("timer3"); + + EXPECT_GE(Timer1Elapsed, 410); // 180+230 + EXPECT_LT(Timer1Elapsed, 820); // 180+230 + + EXPECT_GE(Timer2Elapsed, 180); + EXPECT_LT(Timer2Elapsed, 360); + + EXPECT_GE(Timer3Elapsed, 230); + EXPECT_LT(Timer3Elapsed, 460); + + EXPECT_EQ(1, Pamm.getHistogram().size()); + EXPECT_EQ("Test-Set", Pamm.getHistogram().begin()->first()); + + llvm::StringMap Gt = { + {"1", 10}, {"2", 4}, {"13", 3}, {"42", 13}, {"54", 3}, + }; + const auto &Hist = Pamm.getHistogram().begin()->second; + EXPECT_EQ(Hist, Gt); } // main function for the test case