printf -> model_print
[model-checker.git] / model.cc
index e5c8a55033289bf7393094c514d9e85658489342..8dcb6f3ad8e69a0e82ad3991c4425a35f1a24640 100644 (file)
--- a/model.cc
+++ b/model.cc
 
 ModelChecker *model;
 
+struct bug_message {
+       bug_message(const char *str) {
+               const char *fmt = "  [BUG] %s\n";
+               msg = (char *)snapshot_malloc(strlen(fmt) + strlen(str));
+               sprintf(msg, fmt, str);
+       }
+       ~bug_message() { if (msg) snapshot_free(msg); }
+
+       char *msg;
+       void print() { model_print("%s", msg); }
+
+       SNAPSHOTALLOC
+};
+
 /**
  * Structure for holding small ModelChecker members that should be snapshotted
  */
@@ -27,6 +41,8 @@ struct model_snapshot_members {
        modelclock_t used_sequence_numbers;
        Thread *nextThread;
        ModelAction *next_backtrack;
+       std::vector< bug_message *, SnapshotAlloc<bug_message *> > bugs;
+       struct execution_stats stats;
 };
 
 /** @brief Constructor */
@@ -34,8 +50,6 @@ ModelChecker::ModelChecker(struct model_params params) :
        /* Initialize default scheduler */
        params(params),
        scheduler(new Scheduler()),
-       num_executions(0),
-       num_feasible_executions(0),
        diverge(NULL),
        earliest_diverge(NULL),
        action_trace(new action_list_t()),
@@ -56,7 +70,7 @@ ModelChecker::ModelChecker(struct model_params params) :
        bad_synchronization(false)
 {
        /* Allocate this "size" on the snapshotting heap */
-       priv = (struct model_snapshot_members *)calloc(1, sizeof(*priv));
+       priv = (struct model_snapshot_members *)snapshot_calloc(1, sizeof(*priv));
        /* First thread created will have id INITIAL_THREAD_ID */
        priv->next_thread_id = INITIAL_THREAD_ID;
 
@@ -88,6 +102,11 @@ ModelChecker::~ModelChecker()
        delete node_stack;
        delete scheduler;
        delete mo_graph;
+
+       for (unsigned int i = 0; i < priv->bugs.size(); i++)
+               delete priv->bugs[i];
+       priv->bugs.clear();
+       snapshot_free(priv);
 }
 
 static action_list_t * get_safe_ptr_action(HashTable<const void *, action_list_t *, uintptr_t, 4> * hash, void * ptr) {
@@ -294,6 +313,101 @@ bool ModelChecker::is_deadlocked() const
        return blocking_threads;
 }
 
+/**
+ * Check if this is a complete execution. That is, have all thread completed
+ * execution (rather than exiting because sleep sets have forced a redundant
+ * execution).
+ *
+ * @return True if the execution is complete.
+ */
+bool ModelChecker::is_complete_execution() const
+{
+       for (unsigned int i = 0; i < get_num_threads(); i++)
+               if (is_enabled(int_to_id(i)))
+                       return false;
+       return true;
+}
+
+/**
+ * @brief Assert a bug in the executing program.
+ *
+ * Use this function to assert any sort of bug in the user program. If the
+ * current trace is feasible (actually, a prefix of some feasible execution),
+ * then this execution will be aborted, printing the appropriate message. If
+ * the current trace is not yet feasible, the error message will be stashed and
+ * printed if the execution ever becomes feasible.
+ *
+ * @param msg Descriptive message for the bug (do not include newline char)
+ * @return True if bug is immediately-feasible
+ */
+bool ModelChecker::assert_bug(const char *msg)
+{
+       priv->bugs.push_back(new bug_message(msg));
+
+       if (isfeasibleprefix()) {
+               set_assert();
+               return true;
+       }
+       return false;
+}
+
+/**
+ * @brief Assert a bug in the executing program, asserted by a user thread
+ * @see ModelChecker::assert_bug
+ * @param msg Descriptive message for the bug (do not include newline char)
+ */
+void ModelChecker::assert_user_bug(const char *msg)
+{
+       /* If feasible bug, bail out now */
+       if (assert_bug(msg))
+               switch_to_master(NULL);
+}
+
+/** @return True, if any bugs have been reported for this execution */
+bool ModelChecker::have_bug_reports() const
+{
+       return priv->bugs.size() != 0;
+}
+
+/** @brief Print bug report listing for this execution (if any bugs exist) */
+void ModelChecker::print_bugs() const
+{
+       if (have_bug_reports()) {
+               model_print("Bug report: %zu bug%s detected\n",
+                               priv->bugs.size(),
+                               priv->bugs.size() > 1 ? "s" : "");
+               for (unsigned int i = 0; i < priv->bugs.size(); i++)
+                       priv->bugs[i]->print();
+       }
+}
+
+/**
+ * @brief Record end-of-execution stats
+ *
+ * Must be run when exiting an execution. Records various stats.
+ * @see struct execution_stats
+ */
+void ModelChecker::record_stats()
+{
+       stats.num_total++;
+       if (!isfinalfeasible())
+               stats.num_infeasible++;
+       else if (have_bug_reports())
+               stats.num_buggy_executions++;
+       else if (is_complete_execution())
+               stats.num_complete++;
+}
+
+/** @brief Print execution stats */
+void ModelChecker::print_stats() const
+{
+       model_print("Number of complete, bug-free executions: %d\n", stats.num_complete);
+       model_print("Number of buggy executions: %d\n", stats.num_buggy_executions);
+       model_print("Number of infeasible executions: %d\n", stats.num_infeasible);
+       model_print("Total executions: %d\n", stats.num_total);
+       model_print("Total nodes created: %d\n", node_stack->get_total_nodes());
+}
+
 /**
  * Queries the model-checker for more executions to explore and, if one
  * exists, resets the model-checker state to execute a new execution.
@@ -305,27 +419,27 @@ bool ModelChecker::next_execution()
 {
        DBG();
 
-       num_executions++;
+       record_stats();
 
-       if (is_deadlocked())
-               printf("ERROR: DEADLOCK\n");
-       if (isfinalfeasible()) {
-               printf("Earliest divergence point since last feasible execution:\n");
+       if (isfinalfeasible() && (is_complete_execution() || have_bug_reports())) {
+               model_print("Earliest divergence point since last feasible execution:\n");
                if (earliest_diverge)
                        earliest_diverge->print();
                else
-                       printf("(Not set)\n");
+                       model_print("(Not set)\n");
 
                earliest_diverge = NULL;
-               num_feasible_executions++;
-       }
-
-       DEBUG("Number of acquires waiting on pending release sequences: %zu\n",
-                       pending_rel_seqs->size());
 
+               if (is_deadlocked())
+                       assert_bug("Deadlock detected");
 
-       if (isfinalfeasible() || DBG_ENABLED()) {
                checkDataRaces();
+               print_bugs();
+               model_print("\n");
+               print_stats();
+               print_summary();
+       } else if (DBG_ENABLED()) {
+               model_print("\n");
                print_summary();
        }
 
@@ -333,7 +447,7 @@ bool ModelChecker::next_execution()
                return false;
 
        if (DBG_ENABLED()) {
-               printf("Next execution will diverge at:\n");
+               model_print("Next execution will diverge at:\n");
                diverge->print();
        }
 
@@ -580,10 +694,8 @@ bool ModelChecker::process_mutex(ModelAction *curr) {
        }
                //otherwise fall into the lock case
        case ATOMIC_LOCK: {
-               if (curr->get_cv()->getClock(state->alloc_tid) <= state->alloc_clock) {
-                       printf("Lock access before initialization\n");
-                       set_assert();
-               }
+               if (curr->get_cv()->getClock(state->alloc_tid) <= state->alloc_clock)
+                       assert_bug("Lock access before initialization");
                state->islocked = true;
                ModelAction *unlock = get_last_unlock(curr);
                //synchronize with the previous unlock statement
@@ -792,8 +904,7 @@ void ModelChecker::process_relseq_fixup(ModelAction *curr, work_queue_t *work_qu
        }
 
        /* See if we have realized a data race */
-       if (checkDataRaces())
-               set_assert();
+       checkDataRaces();
 }
 
 /**
@@ -942,7 +1053,7 @@ Thread * ModelChecker::check_current_action(ModelAction *curr)
 
        /* Initialize work_queue with the "current action" work */
        work_queue_t work_queue(1, CheckCurrWorkEntry(curr));
-       while (!work_queue.empty()) {
+       while (!work_queue.empty() && !has_asserted()) {
                WorkQueueEntry work = work_queue.front();
                work_queue.pop_front();
 
@@ -1023,7 +1134,8 @@ void ModelChecker::check_curr_backtracking(ModelAction * curr) {
        }
 }
 
-bool ModelChecker::promises_expired() {
+bool ModelChecker::promises_expired() const
+{
        for (unsigned int promise_index = 0; promise_index < promises->size(); promise_index++) {
                Promise *promise = (*promises)[promise_index];
                if (promise->get_expiration()<priv->used_sequence_numbers) {
@@ -1035,12 +1147,14 @@ bool ModelChecker::promises_expired() {
 
 /** @return whether the current partial trace must be a prefix of a
  * feasible trace. */
-bool ModelChecker::isfeasibleprefix() {
+bool ModelChecker::isfeasibleprefix() const
+{
        return promises->size() == 0 && pending_rel_seqs->size() == 0 && isfeasible();
 }
 
 /** @return whether the current partial trace is feasible. */
-bool ModelChecker::isfeasible() {
+bool ModelChecker::isfeasible() const
+{
        if (DBG_ENABLED() && mo_graph->checkForRMWViolation())
                DEBUG("Infeasible: RMW violation\n");
 
@@ -1049,7 +1163,8 @@ bool ModelChecker::isfeasible() {
 
 /** @return whether the current partial trace is feasible other than
  * multiple RMW reading from the same store. */
-bool ModelChecker::isfeasibleotherthanRMW() {
+bool ModelChecker::isfeasibleotherthanRMW() const
+{
        if (DBG_ENABLED()) {
                if (mo_graph->checkForCycles())
                        DEBUG("Infeasible: modification order cycles\n");
@@ -1066,7 +1181,8 @@ bool ModelChecker::isfeasibleotherthanRMW() {
 }
 
 /** Returns whether the current completed trace is feasible. */
-bool ModelChecker::isfinalfeasible() {
+bool ModelChecker::isfinalfeasible() const
+{
        if (DBG_ENABLED() && promises->size() != 0)
                DEBUG("Infeasible: unrevolved promises\n");
 
@@ -1719,9 +1835,7 @@ bool ModelChecker::resolve_release_sequences(void *location, work_queue_t *work_
        }
 
        // If we resolved promises or data races, see if we have realized a data race.
-       if (checkDataRaces()) {
-               set_assert();
-       }
+       checkDataRaces();
 
        return updated;
 }
@@ -2080,18 +2194,15 @@ void ModelChecker::build_reads_from_past(ModelAction *curr)
                }
        }
 
-       if (!initialized) {
-               /** @todo Need a more informative way of reporting errors. */
-               printf("ERROR: may read from uninitialized atomic\n");
-               set_assert();
-       }
+       if (!initialized)
+               assert_bug("May read from uninitialized atomic");
 
        if (DBG_ENABLED() || !initialized) {
-               printf("Reached read action:\n");
+               model_print("Reached read action:\n");
                curr->print();
-               printf("Printing may_read_from\n");
+               model_print("Printing may_read_from\n");
                curr->get_node()->print_may_read_from();
-               printf("End printing may_read_from\n");
+               model_print("End printing may_read_from\n");
        }
 }
 
@@ -2115,16 +2226,16 @@ static void print_list(action_list_t *list)
 {
        action_list_t::iterator it;
 
-       printf("---------------------------------------------------------------------\n");
-       printf("Trace:\n");
+       model_print("---------------------------------------------------------------------\n");
+       model_print("Trace:\n");
        unsigned int hash=0;
 
        for (it = list->begin(); it != list->end(); it++) {
                (*it)->print();
                hash=hash^(hash<<3)^((*it)->hash());
        }
-       printf("HASH %u\n", hash);
-       printf("---------------------------------------------------------------------\n");
+       model_print("HASH %u\n", hash);
+       model_print("---------------------------------------------------------------------\n");
 }
 
 #if SUPPORT_MOD_ORDER_DUMP
@@ -2157,24 +2268,19 @@ void ModelChecker::dumpGraph(char *filename) {
 
 void ModelChecker::print_summary()
 {
-       printf("\n");
-       printf("Number of executions: %d\n", num_executions);
-       printf("Number of feasible executions: %d\n", num_feasible_executions);
-       printf("Total nodes created: %d\n", node_stack->get_total_nodes());
-
 #if SUPPORT_MOD_ORDER_DUMP
        scheduler->print();
        char buffername[100];
-       sprintf(buffername, "exec%04u", num_executions);
+       sprintf(buffername, "exec%04u", stats.num_total);
        mo_graph->dumpGraphToFile(buffername);
-       sprintf(buffername, "graph%04u", num_executions);
+       sprintf(buffername, "graph%04u", stats.num_total);
        dumpGraph(buffername);
 #endif
 
        if (!isfinalfeasible())
-               printf("INFEASIBLE EXECUTION!\n");
+               model_print("INFEASIBLE EXECUTION!\n");
        print_list(action_trace);
-       printf("\n");
+       model_print("\n");
 }
 
 /**
@@ -2284,6 +2390,10 @@ bool ModelChecker::take_step() {
        /* Infeasible -> don't take any more steps */
        if (!isfeasible())
                return false;
+       else if (isfeasibleprefix() && have_bug_reports()) {
+               set_assert();
+               return false;
+       }
 
        if (params.bound != 0) {
                if (priv->used_sequence_numbers > params.bound) {
@@ -2305,7 +2415,7 @@ bool ModelChecker::take_step() {
         */
        if (!pending_rel_seqs->empty() && (!next || next->is_model_thread()) &&
                        isfinalfeasible() && !unrealizedraces.empty()) {
-               printf("*** WARNING: release sequence fixup action (%zu pending release seuqences) ***\n",
+               model_print("*** WARNING: release sequence fixup action (%zu pending release seuqences) ***\n",
                                pending_rel_seqs->size());
                ModelAction *fixup = new ModelAction(MODEL_FIXUP_RELSEQ,
                                std::memory_order_seq_cst, NULL, VALUE_NONE,