Skip to content

Time logging and extractor duration logging #77

New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

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

Time logging and extractor duration logging #77

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
de9ee40
Added time to logging
vwvw May 14, 2024
c90f169
Added duration logging for extractor
vwvw May 14, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion condition_extractor/src/GlobalStruct.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -102,7 +102,7 @@ void GlobalStruct::analyze() {
// SVFUtil::outs() << "----\n";
}

// SVFUtil::outs() << "[DEBUG] early stop\n";
// SVFUtil::outs() << libfuzz::logTime() << "[DEBUG] early stop\n";
// exit(1);

this->new_edges = newEdges;
Expand Down
10 changes: 10 additions & 0 deletions condition_extractor/src/LibfuzzUtil.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,8 @@
#include <iostream>
#include <fstream>
#include <ios>
#include <iomanip>
#include <ctime>

#define MAXLEN 1000

Expand Down Expand Up @@ -109,5 +111,13 @@ namespace libfuzz {

return typ_pointed->isSized() ? DL->getTypeSizeInBits(typ_pointed) : 0;
}

std::string logTime() {
auto t = std::time(nullptr);
auto tm = *std::localtime(&t);
std::ostringstream oss;
oss << std::put_time(&tm, "%d-%m-%Y %H-%M-%S ");
return oss.str();
};

}
2 changes: 2 additions & 0 deletions condition_extractor/src/LibfuzzUtil.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -144,6 +144,8 @@ namespace libfuzz {
void dumpApiInfo(function_record a_fun);

uint64_t estimate_size(llvm::Type* a_type, bool has_byval, llvm::DataLayout *DL);

std::string logTime();

} // llvm namespace
#endif // LLVM_TRANSFORMS_UTILS_HEXTYPE_H
69 changes: 39 additions & 30 deletions condition_extractor/src/extractor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -282,15 +282,15 @@ void testDom2(FunctionConditions *fun_conds, IBBGraph* ibbg) {
for (auto i: meta.getAccessTypeSet()->getAllICFGNodes())
cond_nodes.insert(i);

SVFUtil::outs() << "[DEBUG] All nodes from ATS: " << cond_nodes.size() << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[DEBUG] All nodes from ATS: " << cond_nodes.size() << "\n";

std::set<const ICFGNode*> not_found;
for (auto i: cond_nodes) {
if (ibbg->getIBBNode(i->getId()) == nullptr)
not_found.insert(i);
}

SVFUtil::outs() << "[DEBUG] Not found " << not_found.size() << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[DEBUG] Not found " << not_found.size() << "\n";
// std::set<const SVFFunction*> funs;
// for (auto i: not_found) {
// // SVFUtil::outs() << i->toString() << "\n";
Expand All @@ -311,7 +311,7 @@ void testDom2(FunctionConditions *fun_conds, IBBGraph* ibbg) {

// // find common subset (if any) and check if the 2 doms are coherent

// SVFUtil::outs() << "[DOING DOM TESTING]\n";
// SVFUtil::outs() << libfuzz::logTime() << "[DOING DOM TESTING]\n";

// // std::set<ICFGNode*> all_nodes = dom->getRelevantNodes();
// IBBGraph::NodeIDSet all_nodes_id = ibbg->getNodeIdAllocated();
Expand Down Expand Up @@ -339,7 +339,7 @@ void testDom2(FunctionConditions *fun_conds, IBBGraph* ibbg) {
// SVFUtil::isa<FunEntryICFGNode>(node2))
// continue;

// SVFUtil::outs() << "[INFO] TEST " << i << "/" << MAX_TEST << ")\r";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] TEST " << i << "/" << MAX_TEST << ")\r";

// bool n1_d_n2_a = dom->dominates(node1, node2);
// bool n2_d_n1_a = dom->dominates(node2, node1);
Expand Down Expand Up @@ -377,6 +377,7 @@ void setDataLayout(const Function* F) {

int main(int argc, char ** argv)
{
auto start_timer = std::chrono::system_clock::now();

int arg_num = 0;
char **arg_value = new char*[argc];
Expand All @@ -403,12 +404,12 @@ int main(int argc, char ** argv)
LLVMModuleSet::getLLVMModuleSet()->preProcessBCs(moduleNameVec);
}

SVFUtil::outs() << "[INFO] Loading library...\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Loading library...\n";

LLVMModuleSet* llvmModuleSet = LLVMModuleSet::getLLVMModuleSet();
SVFModule* svfModule = LLVMModuleSet::getLLVMModuleSet()->buildSVFModule(moduleNameVec);

SVFUtil::outs() << "[INFO] Done\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Done\n";

ValueMetadata::consider_indirect_calls = doIndJump;

Expand All @@ -425,7 +426,7 @@ int main(int argc, char ** argv)
std::set<std::string> functions;
// read all the functions from apis_clang.json
if (all_functions) {
SVFUtil::outs() << "[INFO] I analyze all the functions\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] I analyze all the functions\n";

ifstream f(LibInterface);

Expand Down Expand Up @@ -453,13 +454,13 @@ int main(int argc, char ** argv)
f.close();
}
else {
SVFUtil::outs() << "[INFO] analyzing function: " << function << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] analyzing function: " << function << "\n";
// functions.push_back(function);
functions.insert(function);
}

if (OutputType == OutType::stdo)
SVFUtil::outs() << "[WARNING] outputting in stdout, ignoring OutputFile\n";
SVFUtil::outs() << libfuzz::logTime() << "[WARNING] outputting in stdout, ignoring OutputFile\n";

// Dump LLVM apis function per function
for(const SVFFunction* svfFun : svfModule->getFunctionSet() ){
Expand Down Expand Up @@ -503,7 +504,7 @@ int main(int argc, char ** argv)

point_to_analysys->analyze();

SVFUtil::outs() << "[INFO] Analysis done!\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Analysis done!\n";

GlobalStruct::CallEdgeMap newEdges = point_to_analysys->get_new_edges();
// NOTE: copy callsite->target relation in a neutral structure
Expand Down Expand Up @@ -568,20 +569,23 @@ int main(int argc, char ** argv)
}
}

// SVFUtil::outs() << "[INFO] The minimize set of function\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] The minimize set of function\n";
std::ofstream minimizeApiFile(minimizeApi);
for (auto f: minimize_functions) {
minimizeApiFile << f << "\n";
}
minimizeApiFile.close();
// SVFUtil::outs() << "[INFO] All function\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] All function\n";
// for (auto f: functions)
// SVFUtil::outs() << f << "\n";

// SVFUtil::outs() << "[INFO] Total: " << minimize_functions.size() << "\n";
// SVFUtil::outs() << "[INFO] Original: " << functions.size() << "\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] Total: " << minimize_functions.size() << "\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] Original: " << functions.size() << "\n";

}
auto end_timer = std::chrono::system_clock::now();
std::chrono::duration<double> elapsed_seconds = end_timer-start_timer;
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Elapsed analysis time [s]: " << elapsed_seconds.count() << "\n";

// SVFUtil::outs() << " === EXIT FOR DEBUG ===\n";
// exit(1);
Expand All @@ -591,8 +595,9 @@ int main(int argc, char ** argv)
unsigned int tot_function = functions.size();
unsigned int num_function = 0;

SVFUtil::outs() << "[INFO] running analysis...\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] running analysis...\n";
for (auto f: functions) {
start_timer = std::chrono::system_clock::now();

num_function++;
FunctionConditions fun_conds;
Expand All @@ -605,12 +610,12 @@ int main(int argc, char ** argv)
if ( fun->getName() != f)
continue;

SVFUtil::outs() << "[INFO " << prog << "] processing params for: "
SVFUtil::outs() << libfuzz::logTime() << "[INFO " << prog << "] processing params for: "
<< fun->getName() << "\n";

for (auto const& p : x.second) {
if (verbose >= Verbosity::v1)
SVFUtil::outs() << "[INFO] param: " << p->toString() << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] param: " << p->toString() << "\n";

auto val = p->getValue();
auto llvm_val = llvmModuleSet->getLLVMValue(val);
Expand Down Expand Up @@ -648,12 +653,12 @@ int main(int argc, char ** argv)
if ( fun->getName() != f)
continue;

SVFUtil::outs() << "[INFO " << prog << "] processing return for: "
SVFUtil::outs() << libfuzz::logTime() << "[INFO " << prog << "] processing return for: "
<< fun->getName() << "\n";

auto p = x.second;
if (verbose >= Verbosity::v1)
SVFUtil::outs() << "[INFO] return: " << p->toString() << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] return: " << p->toString() << "\n";
auto llvm_value = llvmModuleSet->getLLVMValue(p->getValue());
ValueMetadata returnMetadata =
ValueMetadata::extractReturnMetadata(svfg, llvm_value);
Expand Down Expand Up @@ -683,23 +688,23 @@ int main(int argc, char ** argv)
std::string postdom_cache_file = getCachePostDomFile(fun_name);

dom = new Dominator(point_to_analysys, fun_entry, doIndJump);
// SVFUtil::outs() << "[INFO] Running pruneUnreachableFunctions()\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] Running pruneUnreachableFunctions()\n";
// dom->pruneUnreachableFunctions();
// SVFUtil::outs() << "[INFO] Running buildPhiFun()\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] Running buildPhiFun()\n";
// dom->buildPhiFun();
// SVFUtil::outs() << "[INFO] Running inferSubGraph()\n";
// SVFUtil::outs() << libfuzz::logTime() << "[INFO] Running inferSubGraph()\n";
// dom->inferSubGraph();
if (cacheFolder != "" && doesFileExists(dom_cache_file)) {
SVFUtil::outs() << "[INFO] There is DOM cache, loading it\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] There is DOM cache, loading it\n";
dom->loadDom(dom_cache_file);
} else {
SVFUtil::outs() << "[INFO] No DOM cache, computing from scratch and save\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] No DOM cache, computing from scratch and save\n";
auto begin = chrono::high_resolution_clock::now();
dom->createDom();
auto end = chrono::high_resolution_clock::now();
auto dur = end - begin;
auto min = std::chrono::duration_cast<std::chrono::minutes>(dur).count();
SVFUtil::outs() << "[TIME] Dom: " << min << "min\n";
SVFUtil::outs() << libfuzz::logTime() << "[TIME] Dom: " << min << "min\n";
// dom->saveIBBGraph("ibbgraph_2");

if (cacheFolder != "")
Expand All @@ -709,24 +714,24 @@ int main(int argc, char ** argv)
pDom = new PostDominator(point_to_analysys, fun_entry,
fun_exit, doIndJump);
if (cacheFolder != "" && doesFileExists(postdom_cache_file)) {
SVFUtil::outs() << "[INFO] There is POSTDOM cache, loading it\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] There is POSTDOM cache, loading it\n";
pDom->loadDom(postdom_cache_file);
} else {
SVFUtil::outs() << "[INFO] No POSTDOM cache, computing from scratch and save\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] No POSTDOM cache, computing from scratch and save\n";
auto begin = chrono::high_resolution_clock::now();
pDom->createDom();
auto end = chrono::high_resolution_clock::now();
auto dur = end - begin;
auto min = std::chrono::duration_cast<std::chrono::minutes>(dur).count();
SVFUtil::outs() << "[TIME] Postdom: " << min << "min\n";
SVFUtil::outs() << libfuzz::logTime() << "[TIME] Postdom: " << min << "min\n";
// pDom->saveIBBGraph("ibbgraph_3");

if (cacheFolder != "")
pDom->dumpDom(postdom_cache_file);
}

if (printDominator) {
SVFUtil::outs() << "[INFO] dumping dominators...\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] dumping dominators...\n";
std::string str1, str2;
if (dom) {
dom->dumpTransRed("./" + dom_cache_file);
Expand Down Expand Up @@ -762,6 +767,10 @@ int main(int argc, char ** argv)

fun_cond_set.addFunctionConditions(fun_conds);

end_timer = std::chrono::system_clock::now();
elapsed_seconds = end_timer-start_timer;
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Analysis time [s] for " << f << elapsed_seconds.count() << "\n";

}

if (OutputType == OutType::txt) {
Expand Down Expand Up @@ -800,7 +809,7 @@ int main(int argc, char ** argv)
fw.close();
}

SVFUtil::outs() << "[INFO] struct data layout done!\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] struct data layout done!\n";
}

// clean up memory
Expand Down
3 changes: 2 additions & 1 deletion library_statistics_extractor/src/GlobalStruct.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@

#include "GlobalStruct.h"
#include "TypeMatcher.h"
#include "LibfuzzUtil.h"

using namespace SVF;
using namespace SVFUtil;
Expand Down Expand Up @@ -102,7 +103,7 @@ void GlobalStruct::analyze() {
// SVFUtil::outs() << "----\n";
}

// SVFUtil::outs() << "[DEBUG] early stop\n";
// SVFUtil::outs() << libfuzz::logTime() << "[DEBUG] early stop\n";
// exit(1);

connectCallerAndCallee(newEdges, svfgEdges);
Expand Down
19 changes: 10 additions & 9 deletions library_statistics_extractor/src/extractor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@
#include "PhiFunction.h"
#include "TypeMatcher.h"
#include "GlobalStruct.h"
#include "LibfuzzUtil.h"

// for random sampling
#include <random>
Expand Down Expand Up @@ -267,12 +268,12 @@ int main(int argc, char ** argv)
LLVMModuleSet::getLLVMModuleSet()->preProcessBCs(moduleNameVec);
}

SVFUtil::outs() << "[INFO] Loading library...\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Loading library...\n";

LLVMModuleSet* llvmModuleSet = LLVMModuleSet::getLLVMModuleSet();
SVFModule* svfModule = LLVMModuleSet::getLLVMModuleSet()->buildSVFModule(moduleNameVec);

SVFUtil::outs() << "[INFO] Done\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Done\n";

// I extract all the function names from the LLVM module
std::set<std::string> functions_llvm;
Expand All @@ -287,7 +288,7 @@ int main(int argc, char ** argv)
std::set<std::string> functions;
// read all the functions from apis_clang.json
if (all_functions) {
SVFUtil::outs() << "[INFO] I analyze all the functions\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] I analyze all the functions\n";

ifstream f(LibInterface);

Expand Down Expand Up @@ -315,13 +316,13 @@ int main(int argc, char ** argv)
f.close();
}
else {
SVFUtil::outs() << "[INFO] analyzing function: " << function << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] analyzing function: " << function << "\n";
// functions.push_back(function);
functions.insert(function);
}

if (OutputType == OutType::stdo)
SVFUtil::outs() << "[WARNING] outputting in stdout, ignoring OutputFile\n";
SVFUtil::outs() << libfuzz::logTime() << "[WARNING] outputting in stdout, ignoring OutputFile\n";

/// Build Program Assignment Graph (SVFIR)
SVFIRBuilder builder(svfModule);
Expand All @@ -336,7 +337,7 @@ int main(int argc, char ** argv)

point_to_analysys->analyze();

SVFUtil::outs() << "[INFO] Analysis done!\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] Analysis done!\n";

PAG::FunToArgsListMap funmap_par = pag->getFunArgsMap();

Expand Down Expand Up @@ -371,7 +372,7 @@ int main(int argc, char ** argv)

std::map<std::string, unsigned int> weights;

SVFUtil::outs() << "[INFO] running analysis...\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] running analysis...\n";
for(const SVFFunction* svfFun : svfModule->getFunctionSet() ){
auto llvm_val = llvmModuleSet->getLLVMValue(svfFun);
const llvm::Function* F = SVFUtil::dyn_cast<Function>(llvm_val);
Expand All @@ -386,11 +387,11 @@ int main(int argc, char ** argv)
std::to_string(tot_function);

// SVFUtil::outs() << "Processing " << f << "\n";
SVFUtil::outs() << "[INFO " << prog << "] processing: "
SVFUtil::outs() << libfuzz::logTime() << "[INFO " << prog << "] processing: "
<< function_name << "\n";

unsigned int n_instruction = countReachableInst(pag, icfg, svfFun);
SVFUtil::outs() << "[INFO] N. Inst.: " << n_instruction << "\n";
SVFUtil::outs() << libfuzz::logTime() << "[INFO] N. Inst.: " << n_instruction << "\n";
weights[function_name] = n_instruction;
}

Expand Down