1 //===-- StatsTracker.cpp --------------------------------------------------===//
2 //
3 // The KLEE Symbolic Virtual Machine
4 //
5 // This file is distributed under the University of Illinois Open Source
6 // License. See LICENSE.TXT for details.
7 //
8 //===----------------------------------------------------------------------===//
9
10 #include "StatsTracker.h"
11
12 #include "ExecutionState.h"
13
14 #include "klee/Config/Version.h"
15 #include "klee/Module/InstructionInfoTable.h"
16 #include "klee/Module/KInstruction.h"
17 #include "klee/Module/KModule.h"
18 #include "klee/Solver/SolverStats.h"
19 #include "klee/Statistics/Statistics.h"
20 #include "klee/Support/ErrorHandling.h"
21 #include "klee/Support/ModuleUtil.h"
22 #include "klee/System/MemoryUsage.h"
23
24 #include "CallPathManager.h"
25 #include "CoreStats.h"
26 #include "Executor.h"
27 #include "MemoryManager.h"
28 #include "UserSearcher.h"
29
30 #include "llvm/ADT/SmallBitVector.h"
31 #include "llvm/IR/BasicBlock.h"
32 #if LLVM_VERSION_CODE < LLVM_VERSION(8, 0)
33 #include "llvm/IR/CallSite.h"
34 #endif
35 #include "llvm/IR/CFG.h"
36 #include "llvm/IR/Function.h"
37 #include "llvm/IR/InlineAsm.h"
38 #include "llvm/IR/Instructions.h"
39 #include "llvm/IR/IntrinsicInst.h"
40 #include "llvm/IR/Module.h"
41 #include "llvm/IR/Type.h"
42 #include "llvm/Support/CommandLine.h"
43 #include "llvm/Support/FileSystem.h"
44 #include "llvm/Support/Path.h"
45 #include "llvm/Support/Process.h"
46
47 #include <fstream>
48 #include <unistd.h>
49
50 using namespace klee;
51 using namespace llvm;
52
53 ///
54
55 namespace {
56 cl::OptionCategory
57 StatsCat("Statistics options",
58 "These options control the statistics generated by KLEE.");
59
60 cl::opt<bool> TrackInstructionTime(
61 "track-instruction-time", cl::init(false),
62 cl::desc(
63 "Enable tracking of time for individual instructions (default=false)"),
64 cl::cat(StatsCat));
65
66 cl::opt<bool>
67 OutputStats("output-stats", cl::init(true),
68 cl::desc("Write running stats trace file (default=true)"),
69 cl::cat(StatsCat));
70
71 cl::opt<bool> OutputIStats("output-istats", cl::init(true),
72 cl::desc("Write instruction level statistics in "
73 "callgrind format (default=true)"),
74 cl::cat(StatsCat));
75
76 cl::opt<std::string> StatsWriteInterval(
77 "stats-write-interval", cl::init("1s"),
78 cl::desc("Approximate time between stats writes (default=1s)"),
79 cl::cat(StatsCat));
80
81 cl::opt<unsigned> StatsWriteAfterInstructions(
82 "stats-write-after-instructions", cl::init(0),
83 cl::desc(
84 "Write statistics after each n instructions, 0 to disable (default=0)"),
85 cl::cat(StatsCat));
86
87 cl::opt<unsigned> CommitEvery(
88 "stats-commit-after", cl::init(0),
89 cl::desc("Commit the statistics every N writes. By default commit every "
90 "write with -stats-write-interval or every 1000 writes with "
91 "-stats-write-after-instructions. (default=0)"),
92 cl::cat(StatsCat));
93
94 cl::opt<std::string> IStatsWriteInterval(
95 "istats-write-interval", cl::init("10s"),
96 cl::desc(
97 "Approximate number of seconds between istats writes (default=10s)"),
98 cl::cat(StatsCat));
99
100 cl::opt<unsigned> IStatsWriteAfterInstructions(
101 "istats-write-after-instructions", cl::init(0),
102 cl::desc(
103 "Write istats after each n instructions, 0 to disable (default=0)"),
104 cl::cat(StatsCat));
105
106 // XXX I really would like to have dynamic rate control for something like this.
107 cl::opt<std::string> UncoveredUpdateInterval(
108 "uncovered-update-interval", cl::init("30s"),
109 cl::desc("Update interval for uncovered instructions (default=30s)"),
110 cl::cat(StatsCat));
111
112 cl::opt<bool> UseCallPaths("use-call-paths", cl::init(true),
113 cl::desc("Enable calltree tracking for instruction "
114 "level statistics (default=true)"),
115 cl::cat(StatsCat));
116
117 } // namespace
118
119 ///
120
useStatistics()121 bool StatsTracker::useStatistics() {
122 return OutputStats || OutputIStats;
123 }
124
useIStats()125 bool StatsTracker::useIStats() {
126 return OutputIStats;
127 }
128
129 /// Check for special cases where we statically know an instruction is
130 /// uncoverable. Currently the case is an unreachable instruction
131 /// following a noreturn call; the instruction is really only there to
132 /// satisfy LLVM's termination requirement.
instructionIsCoverable(Instruction * i)133 static bool instructionIsCoverable(Instruction *i) {
134 if (i->getOpcode() == Instruction::Unreachable) {
135 BasicBlock *bb = i->getParent();
136 BasicBlock::iterator it(i);
137 if (it==bb->begin()) {
138 return true;
139 } else {
140 Instruction *prev = &*(--it);
141 if (isa<CallInst>(prev) || isa<InvokeInst>(prev)) {
142 Function *target = getDirectCallTarget(
143 #if LLVM_VERSION_CODE >= LLVM_VERSION(8, 0)
144 cast<CallBase>(*prev),
145 #else
146 CallSite(prev),
147 #endif
148 /*moduleIsFullyLinked=*/true);
149 if (target && target->doesNotReturn())
150 return false;
151 }
152 }
153 }
154
155 return true;
156 }
157
sqlite3ErrToStringAndFree(const std::string & prefix,char * sqlite3ErrMsg)158 std::string sqlite3ErrToStringAndFree(const std::string& prefix , char* sqlite3ErrMsg) {
159 std::ostringstream sstream;
160 sstream << prefix << sqlite3ErrMsg;
161 sqlite3_free(sqlite3ErrMsg);
162 return sstream.str();
163 }
164
StatsTracker(Executor & _executor,std::string _objectFilename,bool _updateMinDistToUncovered)165 StatsTracker::StatsTracker(Executor &_executor, std::string _objectFilename,
166 bool _updateMinDistToUncovered)
167 : executor(_executor),
168 objectFilename(_objectFilename),
169 startWallTime(time::getWallTime()),
170 numBranches(0),
171 fullBranches(0),
172 partialBranches(0),
173 updateMinDistToUncovered(_updateMinDistToUncovered) {
174
175 const time::Span statsWriteInterval(StatsWriteInterval);
176 if (StatsWriteAfterInstructions > 0 && statsWriteInterval)
177 klee_error("Both options --stats-write-interval and "
178 "--stats-write-after-instructions cannot be enabled at the same "
179 "time.");
180
181 const time::Span iStatsWriteInterval(IStatsWriteInterval);
182 if (IStatsWriteAfterInstructions > 0 && iStatsWriteInterval)
183 klee_error(
184 "Both options --istats-write-interval and "
185 "--istats-write-after-instructions cannot be enabled at the same "
186 "time.");
187
188 KModule *km = executor.kmodule.get();
189 if(CommitEvery > 0) {
190 statsCommitEvery = CommitEvery;
191 } else {
192 statsCommitEvery = statsWriteInterval ? 1 : 1000;
193 }
194
195 if (!sys::path::is_absolute(objectFilename)) {
196 SmallString<128> current(objectFilename);
197 if(sys::fs::make_absolute(current)) {
198 Twine current_twine(current.str()); // requires a twine for this
199 if (!sys::fs::exists(current_twine)) {
200 objectFilename = current.c_str();
201 }
202 }
203 }
204
205 if (useStatistics() || userSearcherRequiresMD2U())
206 theStatisticManager->useIndexedStats(km->infos->getMaxID());
207
208 for (auto &kfp : km->functions) {
209 KFunction *kf = kfp.get();
210 kf->trackCoverage = 1;
211
212 for (unsigned i=0; i<kf->numInstructions; ++i) {
213 KInstruction *ki = kf->instructions[i];
214
215 if (OutputIStats) {
216 unsigned id = ki->info->id;
217 theStatisticManager->setIndex(id);
218 if (kf->trackCoverage && instructionIsCoverable(ki->inst))
219 ++stats::uncoveredInstructions;
220 }
221
222 if (kf->trackCoverage) {
223 if (BranchInst *bi = dyn_cast<BranchInst>(ki->inst))
224 if (!bi->isUnconditional())
225 numBranches++;
226 }
227 }
228 }
229
230 if (OutputStats) {
231 sqlite3_config(SQLITE_CONFIG_SINGLETHREAD);
232 sqlite3_enable_shared_cache(0);
233
234 // open database
235 auto db_filename = executor.interpreterHandler->getOutputFilename("run.stats");
236 if (sqlite3_open(db_filename.c_str(), &statsFile) != SQLITE_OK) {
237 std::ostringstream errorstream;
238 errorstream << "Can't open database: " << sqlite3_errmsg(statsFile);
239 sqlite3_close(statsFile);
240 klee_error("%s", errorstream.str().c_str());
241 }
242
243 // prepare statements
244 if (sqlite3_prepare_v2(statsFile, "BEGIN TRANSACTION", -1, &transactionBeginStmt, nullptr) != SQLITE_OK) {
245 klee_error("Cannot create prepared statement: %s", sqlite3_errmsg(statsFile));
246 }
247
248 if (sqlite3_prepare_v2(statsFile, "END TRANSACTION", -1, &transactionEndStmt, nullptr) != SQLITE_OK) {
249 klee_error("Cannot create prepared statement: %s", sqlite3_errmsg(statsFile));
250 }
251
252 // set options
253 char *zErrMsg;
254 if (sqlite3_exec(statsFile, "PRAGMA synchronous = OFF", nullptr, nullptr, &zErrMsg) != SQLITE_OK) {
255 klee_error("%s", sqlite3ErrToStringAndFree("Can't set options for database: ", zErrMsg).c_str());
256 }
257
258 // note: we use WAL here a) for speed and b) to prevent creation of new file descriptors (as with TRUNCATE)
259 if (sqlite3_exec(statsFile, "PRAGMA journal_mode = WAL", nullptr, nullptr, &zErrMsg) != SQLITE_OK) {
260 klee_error("%s", sqlite3ErrToStringAndFree("Can't set options for database: ", zErrMsg).c_str());
261 }
262
263 // create table
264 writeStatsHeader();
265
266 // begin transaction
267 auto rc = sqlite3_step(transactionBeginStmt);
268 if (rc != SQLITE_DONE) {
269 klee_warning("Can't begin transaction: %s", sqlite3_errmsg(statsFile));
270 }
271 sqlite3_reset(transactionBeginStmt);
272
273 writeStatsLine();
274
275 if (statsWriteInterval)
276 executor.timers.add(std::make_unique<Timer>(statsWriteInterval, [&]{
277 writeStatsLine();
278 }));
279 }
280
281 // Add timer to calculate uncovered instructions if needed by the solver
282 if (updateMinDistToUncovered) {
283 computeReachableUncovered();
284 executor.timers.add(std::make_unique<Timer>(time::Span{UncoveredUpdateInterval}, [&]{
285 computeReachableUncovered();
286 }));
287 }
288
289 if (OutputIStats) {
290 istatsFile = executor.interpreterHandler->openOutputFile("run.istats");
291 if (istatsFile) {
292 if (iStatsWriteInterval)
293 executor.timers.add(std::make_unique<Timer>(iStatsWriteInterval, [&]{
294 writeIStats();
295 }));
296 } else {
297 klee_error("Unable to open instruction level stats file (run.istats).");
298 }
299 }
300 }
301
~StatsTracker()302 StatsTracker::~StatsTracker() {
303 if (statsFile) {
304 auto rc = sqlite3_step(transactionEndStmt);
305 if (rc != SQLITE_DONE) {
306 klee_warning("Can't commit transaction: %s", sqlite3_errmsg(statsFile));
307 }
308 sqlite3_reset(transactionEndStmt);
309 sqlite3_finalize(transactionBeginStmt);
310 sqlite3_finalize(transactionEndStmt);
311 sqlite3_finalize(insertStmt);
312 sqlite3_close(statsFile);
313 }
314 }
315
done()316 void StatsTracker::done() {
317 if (statsFile)
318 writeStatsLine();
319
320 if (OutputIStats) {
321 if (updateMinDistToUncovered)
322 computeReachableUncovered();
323 if (istatsFile)
324 writeIStats();
325 }
326 }
327
stepInstruction(ExecutionState & es)328 void StatsTracker::stepInstruction(ExecutionState &es) {
329 if (OutputIStats) {
330 if (TrackInstructionTime) {
331 static time::Point lastNowTime(time::getWallTime());
332 static time::Span lastUserTime;
333
334 if (!lastUserTime) {
335 lastUserTime = time::getUserTime();
336 } else {
337 const auto now = time::getWallTime();
338 const auto user = time::getUserTime();
339 const auto delta = user - lastUserTime;
340 const auto deltaNow = now - lastNowTime;
341 stats::instructionTime += delta.toMicroseconds();
342 stats::instructionRealTime += deltaNow.toMicroseconds();
343 lastUserTime = user;
344 lastNowTime = now;
345 }
346 }
347
348 Instruction *inst = es.pc->inst;
349 const InstructionInfo &ii = *es.pc->info;
350 StackFrame &sf = es.stack.back();
351 theStatisticManager->setIndex(ii.id);
352 if (UseCallPaths)
353 theStatisticManager->setContext(&sf.callPathNode->statistics);
354
355 if (es.instsSinceCovNew)
356 ++es.instsSinceCovNew;
357
358 if (sf.kf->trackCoverage && instructionIsCoverable(inst)) {
359 if (!theStatisticManager->getIndexedValue(stats::coveredInstructions, ii.id)) {
360 // Checking for actual stoppoints avoids inconsistencies due
361 // to line number propogation.
362 //
363 // FIXME: This trick no longer works, we should fix this in the line
364 // number propogation.
365 es.coveredLines[&ii.file].insert(ii.line);
366 es.coveredNew = true;
367 es.instsSinceCovNew = 1;
368 ++stats::coveredInstructions;
369 stats::uncoveredInstructions += (uint64_t)-1;
370 }
371 }
372 }
373
374 if (statsFile && StatsWriteAfterInstructions &&
375 stats::instructions % StatsWriteAfterInstructions.getValue() == 0)
376 writeStatsLine();
377
378 if (istatsFile && IStatsWriteAfterInstructions &&
379 stats::instructions % IStatsWriteAfterInstructions.getValue() == 0)
380 writeIStats();
381 }
382
383 ///
384
385 /* Should be called _after_ the es->pushFrame() */
framePushed(ExecutionState & es,StackFrame * parentFrame)386 void StatsTracker::framePushed(ExecutionState &es, StackFrame *parentFrame) {
387 if (OutputIStats) {
388 StackFrame &sf = es.stack.back();
389
390 if (UseCallPaths) {
391 CallPathNode *parent = parentFrame ? parentFrame->callPathNode : 0;
392 CallPathNode *cp = callPathManager.getCallPath(parent,
393 sf.caller ? sf.caller->inst : 0,
394 sf.kf->function);
395 sf.callPathNode = cp;
396 cp->count++;
397 }
398 }
399
400 if (updateMinDistToUncovered) {
401 StackFrame &sf = es.stack.back();
402
403 uint64_t minDistAtRA = 0;
404 if (parentFrame)
405 minDistAtRA = parentFrame->minDistToUncoveredOnReturn;
406
407 sf.minDistToUncoveredOnReturn =
408 sf.caller ? computeMinDistToUncovered(sf.caller, minDistAtRA) : 0;
409 }
410 }
411
412 /* Should be called _after_ the es->popFrame() */
framePopped(ExecutionState & es)413 void StatsTracker::framePopped(ExecutionState &es) {
414 // XXX remove me?
415 }
416
markBranchVisited(ExecutionState * visitedTrue,ExecutionState * visitedFalse)417 void StatsTracker::markBranchVisited(ExecutionState *visitedTrue,
418 ExecutionState *visitedFalse) {
419 if (OutputIStats) {
420 unsigned id = theStatisticManager->getIndex();
421 uint64_t hasTrue = theStatisticManager->getIndexedValue(stats::trueBranches, id);
422 uint64_t hasFalse = theStatisticManager->getIndexedValue(stats::falseBranches, id);
423 if (visitedTrue && !hasTrue) {
424 visitedTrue->coveredNew = true;
425 visitedTrue->instsSinceCovNew = 1;
426 ++stats::trueBranches;
427 if (hasFalse) { ++fullBranches; --partialBranches; }
428 else ++partialBranches;
429 hasTrue = 1;
430 }
431 if (visitedFalse && !hasFalse) {
432 visitedFalse->coveredNew = true;
433 visitedFalse->instsSinceCovNew = 1;
434 ++stats::falseBranches;
435 if (hasTrue) { ++fullBranches; --partialBranches; }
436 else ++partialBranches;
437 }
438 }
439 }
440
writeStatsHeader()441 void StatsTracker::writeStatsHeader() {
442 std::ostringstream create, insert;
443 create << "CREATE TABLE stats ("
444 << "Instructions INTEGER,"
445 << "FullBranches INTEGER,"
446 << "PartialBranches INTEGER,"
447 << "NumBranches INTEGER,"
448 << "UserTime REAL,"
449 << "NumStates INTEGER,"
450 << "MallocUsage INTEGER,"
451 << "NumQueries INTEGER,"
452 << "NumQueryConstructs INTEGER,"
453 << "WallTime REAL,"
454 << "CoveredInstructions INTEGER,"
455 << "UncoveredInstructions INTEGER,"
456 << "QueryTime INTEGER,"
457 << "SolverTime INTEGER,"
458 << "CexCacheTime INTEGER,"
459 << "ForkTime INTEGER,"
460 << "ResolveTime INTEGER,"
461 << "QueryCexCacheMisses INTEGER,"
462 << "QueryCexCacheHits INTEGER,"
463 << "ArrayHashTime INTEGER"
464 << ')';
465 char *zErrMsg = nullptr;
466 if(sqlite3_exec(statsFile, create.str().c_str(), nullptr, nullptr, &zErrMsg)) {
467 klee_error("%s", sqlite3ErrToStringAndFree("ERROR creating table: ", zErrMsg).c_str());
468 }
469 /* Sometimes KLEE runs out of file descriptors and hence we try to a) keep important fds open and b) prevent the
470 * creation of temporary files. SQLite3 uses temporary files for statement journals, which help rollbacks when
471 * constraints are violated. We have no constraints in our table so there shouldn't be a constraint violation.
472 * `OR FAIL` will not write to temp files and therefore not rollback but simply fail. As said before this should not
473 * happen, but if it does this statement will fail with SQLITE_CONSTRAINT error. If this happens you should either
474 * remove the constraints or consider using `IGNORE` mode.
475 */
476 insert << "INSERT OR FAIL INTO stats ("
477 << "Instructions,"
478 << "FullBranches,"
479 << "PartialBranches,"
480 << "NumBranches,"
481 << "UserTime,"
482 << "NumStates,"
483 << "MallocUsage,"
484 << "NumQueries,"
485 << "NumQueryConstructs,"
486 << "WallTime,"
487 << "CoveredInstructions,"
488 << "UncoveredInstructions,"
489 << "QueryTime,"
490 << "SolverTime,"
491 << "CexCacheTime,"
492 << "ForkTime,"
493 << "ResolveTime,"
494 << "QueryCexCacheMisses,"
495 << "QueryCexCacheHits,"
496 << "ArrayHashTime"
497 << ") VALUES ("
498 << "?,"
499 << "?,"
500 << "?,"
501 << "?,"
502 << "?,"
503 << "?,"
504 << "?,"
505 << "?,"
506 << "?,"
507 << "?,"
508 << "?,"
509 << "?,"
510 << "?,"
511 << "?,"
512 << "?,"
513 << "?,"
514 << "?,"
515 << "?,"
516 << "?,"
517 << "? "
518 << ')';
519
520 if(sqlite3_prepare_v2(statsFile, insert.str().c_str(), -1, &insertStmt, nullptr) != SQLITE_OK) {
521 klee_error("Cannot create prepared statement: %s", sqlite3_errmsg(statsFile));
522 }
523 }
524
elapsed()525 time::Span StatsTracker::elapsed() {
526 return time::getWallTime() - startWallTime;
527 }
528
writeStatsLine()529 void StatsTracker::writeStatsLine() {
530 sqlite3_bind_int64(insertStmt, 1, stats::instructions);
531 sqlite3_bind_int64(insertStmt, 2, fullBranches);
532 sqlite3_bind_int64(insertStmt, 3, partialBranches);
533 sqlite3_bind_int64(insertStmt, 4, numBranches);
534 sqlite3_bind_int64(insertStmt, 5, time::getUserTime().toMicroseconds());
535 sqlite3_bind_int64(insertStmt, 6, executor.states.size());
536 sqlite3_bind_int64(insertStmt, 7, util::GetTotalMallocUsage() + executor.memory->getUsedDeterministicSize());
537 sqlite3_bind_int64(insertStmt, 8, stats::queries);
538 sqlite3_bind_int64(insertStmt, 9, stats::queryConstructs);
539 sqlite3_bind_int64(insertStmt, 10, elapsed().toMicroseconds());
540 sqlite3_bind_int64(insertStmt, 11, stats::coveredInstructions);
541 sqlite3_bind_int64(insertStmt, 12, stats::uncoveredInstructions);
542 sqlite3_bind_int64(insertStmt, 13, stats::queryTime);
543 sqlite3_bind_int64(insertStmt, 14, stats::solverTime);
544 sqlite3_bind_int64(insertStmt, 15, stats::cexCacheTime);
545 sqlite3_bind_int64(insertStmt, 16, stats::forkTime);
546 sqlite3_bind_int64(insertStmt, 17, stats::resolveTime);
547 sqlite3_bind_int64(insertStmt, 18, stats::queryCexCacheMisses);
548 sqlite3_bind_int64(insertStmt, 19, stats::queryCexCacheHits);
549 #ifdef KLEE_ARRAY_DEBUG
550 sqlite3_bind_int64(insertStmt, 20, stats::arrayHashTime);
551 #else
552 sqlite3_bind_int64(insertStmt, 20, -1LL);
553 #endif
554 int errCode = sqlite3_step(insertStmt);
555 if(errCode != SQLITE_DONE) klee_error("Error writing stats data: %s", sqlite3_errmsg(statsFile));
556 sqlite3_reset(insertStmt);
557
558 statsWriteCount++;
559 if(statsWriteCount == statsCommitEvery) {
560 errCode = sqlite3_step(transactionEndStmt);
561 if (errCode != SQLITE_DONE) klee_warning("Transaction commit error: %s", sqlite3_errmsg(statsFile));
562 sqlite3_reset(transactionEndStmt);
563 errCode = sqlite3_step(transactionBeginStmt);
564 if (errCode != SQLITE_DONE) klee_warning("Transaction begin error: %s", sqlite3_errmsg(statsFile));
565 sqlite3_reset(transactionBeginStmt);
566
567 statsWriteCount = 0;
568 }
569 }
570
updateStateStatistics(uint64_t addend)571 void StatsTracker::updateStateStatistics(uint64_t addend) {
572 for (std::set<ExecutionState*>::iterator it = executor.states.begin(),
573 ie = executor.states.end(); it != ie; ++it) {
574 ExecutionState &state = **it;
575 const InstructionInfo &ii = *state.pc->info;
576 theStatisticManager->incrementIndexedValue(stats::states, ii.id, addend);
577 if (UseCallPaths)
578 state.stack.back().callPathNode->statistics.incrementValue(stats::states, addend);
579 }
580 }
581
writeIStats()582 void StatsTracker::writeIStats() {
583 const auto m = executor.kmodule->module.get();
584 llvm::raw_fd_ostream &of = *istatsFile;
585
586 // We assume that we didn't move the file pointer
587 unsigned istatsSize = of.tell();
588
589 of.seek(0);
590
591 of << "version: 1\n";
592 of << "creator: klee\n";
593 of << "pid: " << getpid() << "\n";
594 of << "cmd: " << m->getModuleIdentifier() << "\n\n";
595 of << "\n";
596
597 StatisticManager &sm = *theStatisticManager;
598 unsigned nStats = sm.getNumStatistics();
599 llvm::SmallBitVector istatsMask(nStats);
600
601 istatsMask.set(sm.getStatisticID("Queries"));
602 istatsMask.set(sm.getStatisticID("QueriesValid"));
603 istatsMask.set(sm.getStatisticID("QueriesInvalid"));
604 istatsMask.set(sm.getStatisticID("QueryTime"));
605 istatsMask.set(sm.getStatisticID("ResolveTime"));
606 istatsMask.set(sm.getStatisticID("Instructions"));
607 istatsMask.set(sm.getStatisticID("InstructionTimes"));
608 istatsMask.set(sm.getStatisticID("InstructionRealTimes"));
609 istatsMask.set(sm.getStatisticID("Forks"));
610 istatsMask.set(sm.getStatisticID("CoveredInstructions"));
611 istatsMask.set(sm.getStatisticID("UncoveredInstructions"));
612 istatsMask.set(sm.getStatisticID("States"));
613 istatsMask.set(sm.getStatisticID("MinDistToUncovered"));
614
615 of << "positions: instr line\n";
616
617 for (unsigned i=0; i<nStats; i++) {
618 if (istatsMask.test(i)) {
619 Statistic &s = sm.getStatistic(i);
620 of << "event: " << s.getShortName() << " : "
621 << s.getName() << "\n";
622 }
623 }
624
625 of << "events: ";
626 for (unsigned i=0; i<nStats; i++) {
627 if (istatsMask.test(i))
628 of << sm.getStatistic(i).getShortName() << " ";
629 }
630 of << "\n";
631
632 // set state counts, decremented after we process so that we don't
633 // have to zero all records each time.
634 if (istatsMask.test(stats::states.getID()))
635 updateStateStatistics(1);
636
637 std::string sourceFile = "";
638
639 CallSiteSummaryTable callSiteStats;
640 if (UseCallPaths)
641 callPathManager.getSummaryStatistics(callSiteStats);
642
643 of << "ob=" << llvm::sys::path::filename(objectFilename).str() << "\n";
644
645 for (Module::iterator fnIt = m->begin(), fn_ie = m->end();
646 fnIt != fn_ie; ++fnIt) {
647 if (!fnIt->isDeclaration()) {
648 // Always try to write the filename before the function name, as otherwise
649 // KCachegrind can create two entries for the function, one with an
650 // unnamed file and one without.
651 Function *fn = &*fnIt;
652 const FunctionInfo &ii = executor.kmodule->infos->getFunctionInfo(*fn);
653 if (ii.file != sourceFile) {
654 of << "fl=" << ii.file << "\n";
655 sourceFile = ii.file;
656 }
657
658 of << "fn=" << fnIt->getName().str() << "\n";
659 for (Function::iterator bbIt = fnIt->begin(), bb_ie = fnIt->end();
660 bbIt != bb_ie; ++bbIt) {
661 for (BasicBlock::iterator it = bbIt->begin(), ie = bbIt->end();
662 it != ie; ++it) {
663 Instruction *instr = &*it;
664 const InstructionInfo &ii = executor.kmodule->infos->getInfo(*instr);
665 unsigned index = ii.id;
666 if (ii.file!=sourceFile) {
667 of << "fl=" << ii.file << "\n";
668 sourceFile = ii.file;
669 }
670 of << ii.assemblyLine << " ";
671 of << ii.line << " ";
672 for (unsigned i=0; i<nStats; i++)
673 if (istatsMask.test(i))
674 of << sm.getIndexedValue(sm.getStatistic(i), index) << " ";
675 of << "\n";
676
677 if (UseCallPaths &&
678 (isa<CallInst>(instr) || isa<InvokeInst>(instr))) {
679 CallSiteSummaryTable::iterator it = callSiteStats.find(instr);
680 if (it!=callSiteStats.end()) {
681 for (auto fit = it->second.begin(), fie = it->second.end();
682 fit != fie; ++fit) {
683 const Function *f = fit->first;
684 CallSiteInfo &csi = fit->second;
685 const FunctionInfo &fii =
686 executor.kmodule->infos->getFunctionInfo(*f);
687
688 if (fii.file!="" && fii.file!=sourceFile)
689 of << "cfl=" << fii.file << "\n";
690 of << "cfn=" << f->getName().str() << "\n";
691 of << "calls=" << csi.count << " ";
692 of << fii.assemblyLine << " ";
693 of << fii.line << "\n";
694
695 of << ii.assemblyLine << " ";
696 of << ii.line << " ";
697 for (unsigned i=0; i<nStats; i++) {
698 if (istatsMask.test(i)) {
699 Statistic &s = sm.getStatistic(i);
700 uint64_t value;
701
702 // Hack, ignore things that don't make sense on
703 // call paths.
704 if (&s == &stats::uncoveredInstructions) {
705 value = 0;
706 } else {
707 value = csi.statistics.getValue(s);
708 }
709
710 of << value << " ";
711 }
712 }
713 of << "\n";
714 }
715 }
716 }
717 }
718 }
719 }
720 }
721
722 if (istatsMask.test(stats::states.getID()))
723 updateStateStatistics((uint64_t)-1);
724
725 // Clear then end of the file if necessary (no truncate op?).
726 unsigned pos = of.tell();
727 for (unsigned i=pos; i<istatsSize; ++i)
728 of << '\n';
729
730 of.flush();
731 }
732
733 ///
734
735 typedef std::map<Instruction*, std::vector<Function*> > calltargets_ty;
736
737 static calltargets_ty callTargets;
738 static std::map<Function*, std::vector<Instruction*> > functionCallers;
739 static std::map<Function*, unsigned> functionShortestPath;
740
getSuccs(Instruction * i)741 static std::vector<Instruction*> getSuccs(Instruction *i) {
742 BasicBlock *bb = i->getParent();
743 std::vector<Instruction*> res;
744
745 if (i==bb->getTerminator()) {
746 for (succ_iterator it = succ_begin(bb), ie = succ_end(bb); it != ie; ++it)
747 res.push_back(&*(it->begin()));
748 } else {
749 res.push_back(&*(++(i->getIterator())));
750 }
751
752 return res;
753 }
754
computeMinDistToUncovered(const KInstruction * ki,uint64_t minDistAtRA)755 uint64_t klee::computeMinDistToUncovered(const KInstruction *ki,
756 uint64_t minDistAtRA) {
757 StatisticManager &sm = *theStatisticManager;
758 if (minDistAtRA==0) { // unreachable on return, best is local
759 return sm.getIndexedValue(stats::minDistToUncovered,
760 ki->info->id);
761 } else {
762 uint64_t minDistLocal = sm.getIndexedValue(stats::minDistToUncovered,
763 ki->info->id);
764 uint64_t distToReturn = sm.getIndexedValue(stats::minDistToReturn,
765 ki->info->id);
766
767 if (distToReturn==0) { // return unreachable, best is local
768 return minDistLocal;
769 } else if (!minDistLocal) { // no local reachable
770 return distToReturn + minDistAtRA;
771 } else {
772 return std::min(minDistLocal, distToReturn + minDistAtRA);
773 }
774 }
775 }
776
computeReachableUncovered()777 void StatsTracker::computeReachableUncovered() {
778 KModule *km = executor.kmodule.get();
779 const auto m = km->module.get();
780 static bool init = true;
781 const InstructionInfoTable &infos = *km->infos;
782 StatisticManager &sm = *theStatisticManager;
783
784 if (init) {
785 init = false;
786
787 // Compute call targets. It would be nice to use alias information
788 // instead of assuming all indirect calls hit all escaping
789 // functions, eh?
790 for (Module::iterator fnIt = m->begin(), fn_ie = m->end();
791 fnIt != fn_ie; ++fnIt) {
792 for (Function::iterator bbIt = fnIt->begin(), bb_ie = fnIt->end();
793 bbIt != bb_ie; ++bbIt) {
794 for (BasicBlock::iterator it = bbIt->begin(), ie = bbIt->end();
795 it != ie; ++it) {
796 Instruction *inst = &*it;
797 if (isa<CallInst>(inst) || isa<InvokeInst>(inst)) {
798 #if LLVM_VERSION_CODE >= LLVM_VERSION(8, 0)
799 const CallBase &cs = cast<CallBase>(*inst);
800 if (isa<InlineAsm>(cs.getCalledOperand())) {
801 #else
802 const CallSite cs(inst);
803 if (isa<InlineAsm>(cs.getCalledValue())) {
804 #endif
805 // We can never call through here so assume no targets
806 // (which should be correct anyhow).
807 callTargets.insert(std::make_pair(inst,
808 std::vector<Function*>()));
809 } else if (Function *target = getDirectCallTarget(
810 cs, /*moduleIsFullyLinked=*/true)) {
811 callTargets[inst].push_back(target);
812 } else {
813 callTargets[inst] =
814 std::vector<Function*>(km->escapingFunctions.begin(),
815 km->escapingFunctions.end());
816 }
817 }
818 }
819 }
820 }
821
822 // Compute function callers as reflexion of callTargets.
823 for (calltargets_ty::iterator it = callTargets.begin(),
824 ie = callTargets.end(); it != ie; ++it)
825 for (std::vector<Function*>::iterator fit = it->second.begin(),
826 fie = it->second.end(); fit != fie; ++fit)
827 functionCallers[*fit].push_back(it->first);
828
829 // Initialize minDistToReturn to shortest paths through
830 // functions. 0 is unreachable.
831 std::vector<Instruction *> instructions;
832 for (Module::iterator fnIt = m->begin(), fn_ie = m->end();
833 fnIt != fn_ie; ++fnIt) {
834 Function *fn = &*fnIt;
835 if (fnIt->isDeclaration()) {
836 if (fnIt->doesNotReturn()) {
837 functionShortestPath[fn] = 0;
838 } else {
839 functionShortestPath[fn] = 1; // whatever
840 }
841 } else {
842 functionShortestPath[fn] = 0;
843 }
844
845 // Not sure if I should bother to preorder here. XXX I should.
846 for (Function::iterator bbIt = fnIt->begin(), bb_ie = fnIt->end();
847 bbIt != bb_ie; ++bbIt) {
848 for (BasicBlock::iterator it = bbIt->begin(), ie = bbIt->end();
849 it != ie; ++it) {
850 Instruction *inst = &*it;
851 instructions.push_back(inst);
852 unsigned id = infos.getInfo(*inst).id;
853 sm.setIndexedValue(stats::minDistToReturn,
854 id,
855 isa<ReturnInst>(inst)
856 );
857 }
858 }
859 }
860
861 std::reverse(instructions.begin(), instructions.end());
862
863 // I'm so lazy it's not even worklisted.
864 bool changed;
865 do {
866 changed = false;
867 for (auto it = instructions.begin(), ie = instructions.end(); it != ie;
868 ++it) {
869 Instruction *inst = *it;
870 unsigned bestThrough = 0;
871
872 if (isa<CallInst>(inst) || isa<InvokeInst>(inst)) {
873 std::vector<Function*> &targets = callTargets[inst];
874 for (std::vector<Function*>::iterator fnIt = targets.begin(),
875 ie = targets.end(); fnIt != ie; ++fnIt) {
876 uint64_t dist = functionShortestPath[*fnIt];
877 if (dist) {
878 dist = 1+dist; // count instruction itself
879 if (bestThrough==0 || dist<bestThrough)
880 bestThrough = dist;
881 }
882 }
883 } else {
884 bestThrough = 1;
885 }
886
887 if (bestThrough) {
888 unsigned id = infos.getInfo(*(*it)).id;
889 uint64_t best, cur = best = sm.getIndexedValue(stats::minDistToReturn, id);
890 std::vector<Instruction*> succs = getSuccs(*it);
891 for (std::vector<Instruction*>::iterator it2 = succs.begin(),
892 ie = succs.end(); it2 != ie; ++it2) {
893 uint64_t dist = sm.getIndexedValue(stats::minDistToReturn,
894 infos.getInfo(*(*it2)).id);
895 if (dist) {
896 uint64_t val = bestThrough + dist;
897 if (best==0 || val<best)
898 best = val;
899 }
900 }
901 // there's a corner case here when a function only includes a single
902 // instruction (a ret). in that case, we MUST update
903 // functionShortestPath, or it will remain 0 (erroneously indicating
904 // that no return instructions are reachable)
905 Function *f = inst->getParent()->getParent();
906 if (best != cur || (inst == &*(f->begin()->begin())
907 && functionShortestPath[f] != best)) {
908 sm.setIndexedValue(stats::minDistToReturn, id, best);
909 changed = true;
910
911 // Update shortest path if this is the entry point.
912 if (inst == &*(f->begin()->begin()))
913 functionShortestPath[f] = best;
914 }
915 }
916 }
917 } while (changed);
918 }
919
920 // compute minDistToUncovered, 0 is unreachable
921 std::vector<Instruction *> instructions;
922 for (Module::iterator fnIt = m->begin(), fn_ie = m->end();
923 fnIt != fn_ie; ++fnIt) {
924 // Not sure if I should bother to preorder here.
925 for (Function::iterator bbIt = fnIt->begin(), bb_ie = fnIt->end();
926 bbIt != bb_ie; ++bbIt) {
927 for (BasicBlock::iterator it = bbIt->begin(), ie = bbIt->end();
928 it != ie; ++it) {
929 Instruction *inst = &*it;
930 unsigned id = infos.getInfo(*inst).id;
931 instructions.push_back(inst);
932 sm.setIndexedValue(stats::minDistToUncovered,
933 id,
934 sm.getIndexedValue(stats::uncoveredInstructions, id));
935 }
936 }
937 }
938
939 std::reverse(instructions.begin(), instructions.end());
940
941 // I'm so lazy it's not even worklisted.
942 bool changed;
943 do {
944 changed = false;
945 for (std::vector<Instruction*>::iterator it = instructions.begin(),
946 ie = instructions.end(); it != ie; ++it) {
947 Instruction *inst = *it;
948 uint64_t best, cur = best = sm.getIndexedValue(stats::minDistToUncovered,
949 infos.getInfo(*inst).id);
950 unsigned bestThrough = 0;
951
952 if (isa<CallInst>(inst) || isa<InvokeInst>(inst)) {
953 std::vector<Function*> &targets = callTargets[inst];
954 for (std::vector<Function*>::iterator fnIt = targets.begin(),
955 ie = targets.end(); fnIt != ie; ++fnIt) {
956 uint64_t dist = functionShortestPath[*fnIt];
957 if (dist) {
958 dist = 1+dist; // count instruction itself
959 if (bestThrough==0 || dist<bestThrough)
960 bestThrough = dist;
961 }
962
963 if (!(*fnIt)->isDeclaration()) {
964 uint64_t calleeDist = sm.getIndexedValue(
965 stats::minDistToUncovered, infos.getFunctionInfo(*(*fnIt)).id);
966 if (calleeDist) {
967 calleeDist = 1+calleeDist; // count instruction itself
968 if (best==0 || calleeDist<best)
969 best = calleeDist;
970 }
971 }
972 }
973 } else {
974 bestThrough = 1;
975 }
976
977 if (bestThrough) {
978 std::vector<Instruction*> succs = getSuccs(inst);
979 for (std::vector<Instruction*>::iterator it2 = succs.begin(),
980 ie = succs.end(); it2 != ie; ++it2) {
981 uint64_t dist = sm.getIndexedValue(stats::minDistToUncovered,
982 infos.getInfo(*(*it2)).id);
983 if (dist) {
984 uint64_t val = bestThrough + dist;
985 if (best==0 || val<best)
986 best = val;
987 }
988 }
989 }
990
991 if (best != cur) {
992 sm.setIndexedValue(stats::minDistToUncovered, infos.getInfo(*inst).id,
993 best);
994 changed = true;
995 }
996 }
997 } while (changed);
998
999 for (std::set<ExecutionState*>::iterator it = executor.states.begin(),
1000 ie = executor.states.end(); it != ie; ++it) {
1001 ExecutionState *es = *it;
1002 uint64_t currentFrameMinDist = 0;
1003 for (ExecutionState::stack_ty::iterator sfIt = es->stack.begin(),
1004 sf_ie = es->stack.end(); sfIt != sf_ie; ++sfIt) {
1005 ExecutionState::stack_ty::iterator next = sfIt + 1;
1006 KInstIterator kii;
1007
1008 if (next==es->stack.end()) {
1009 kii = es->pc;
1010 } else {
1011 kii = next->caller;
1012 ++kii;
1013 }
1014
1015 sfIt->minDistToUncoveredOnReturn = currentFrameMinDist;
1016
1017 currentFrameMinDist = computeMinDistToUncovered(kii, currentFrameMinDist);
1018 }
1019 }
1020 }
1021