tsan/ts_race_verifier.cc

/* Copyright (c) 2008-2010, Google Inc.
 * All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions are
 * met:
 *
 *     * Redistributions of source code must retain the above copyright
 * notice, this list of conditions and the following disclaimer.
 *     * Neither the name of Google Inc. nor the names of its
 * contributors may be used to endorse or promote products derived from
 * this software without specific prior written permission.
 *
 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
 * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
 * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
 * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
 * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
 * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
 * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
 * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
 * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
 * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 */

// This file is part of ThreadSanitizer, a dynamic data race detector.
// Author: Evgeniy Stepanov.

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <vector>
#include <set>
#include <iterator>
#include <algorithm>

#include "ts_lock.h"
#include "ts_util.h"
#include "ts_race_verifier.h"
#include "thread_sanitizer.h"

struct PossibleRace {
  PossibleRace() : pc(0), reported(false) {}
  // racy instruction
  uintptr_t pc;
  // concurrent traces
  vector<uintptr_t> traces;
  // report text
  string report;
  // whether this race has already been reported
  bool reported;
};

// pc -> race
static map<uintptr_t, PossibleRace*>* races_map;

// Data about a call site.
struct CallSite {
  int thread_id;
  uintptr_t pc;
};

struct TypedCallSites {
  vector<CallSite> reads;
  vector<CallSite> writes;
};

// data address -> ([write callsites], [read callsites])
typedef map<uintptr_t, TypedCallSites> AddressMap;

static TSLock racecheck_lock;
static AddressMap* racecheck_map;
// data addresses that are ignored (they have already been reported)
static set<uintptr_t>* ignore_addresses;

// starting pc of the trace -> visit count
// used to reduce the sleep time for hot traces
typedef map<uintptr_t, int> VisitCountMap;
static VisitCountMap* visit_count_map;

static int n_reports;

/**
 * Given max and min pc of a trace (both inclusive!), returns whether this trace
 * is interesting to us at all (via the return value), and whether it should be
 * instrumented fully (*instrument_pc=0), or 1 instruction only. In the latter
 * case, *instrument_pc contains the address of the said instruction.
 */
bool RaceVerifierGetAddresses(uintptr_t min_pc, uintptr_t max_pc,
    uintptr_t* instrument_pc) {
  uintptr_t pc = 0;
  for (map<uintptr_t, PossibleRace*>::iterator it = races_map->begin();
       it != races_map->end(); ++it) {
    PossibleRace* race = it->second;
    if (race->reported)
      continue;
    if (race->pc >= min_pc && race->pc <= max_pc) {
      if (pc) {
        // Two race candidates in one trace. Just instrument it fully.
        *instrument_pc = 0;
        return true;
      }
      pc = race->pc;
    }
    for (vector<uintptr_t>::iterator it2 = race->traces.begin();
         it2 != race->traces.end(); ++it2) {
      if (*it2 >= min_pc && *it2 <= max_pc) {
        *instrument_pc = 0;
        return true;
      }
    }
  }
  *instrument_pc = pc;
  return !!pc;
}

static void UpdateSummary() {
  if (!G_flags->summary_file.empty()) {
    char buff[100];
    snprintf(buff, sizeof(buff),
	     "RaceVerifier: %d report(s) verified\n", n_reports);
    // We overwrite the contents of this file with the new summary.
    // We don't do that at the end because even if we crash later
    // we will already have the summary.
    OpenFileWriteStringAndClose(G_flags->summary_file, buff);
  }
}

/* Build and print a race report for a data address. Does not print stack traces
   and symbols and all the fancy stuff - we don't have that info. Used when we
   don't have a ready report - for unexpected races and for
   --race-verifier-extra races.

   racecheck_lock must be held by the current thread.
*/
static void PrintRaceReportEmpty(uintptr_t addr) {
  TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
  vector<CallSite>& writes = typedCallSites->writes;
  vector<CallSite>& reads = typedCallSites->reads;
  for (vector<CallSite>::const_iterator it = writes.begin();
       it != writes.end(); ++ it) {
    Printf("  write at %p\n", it->pc);
  }
  for (vector<CallSite>::const_iterator it = reads.begin();
       it != reads.end(); ++ it) {
    Printf("  read at %p\n", it->pc);
  }
}

/* Find a PossibleRace that matches current accesses (racecheck_map) to the
   given data address.

   racecheck_lock must be held by the current thread.
 */
static PossibleRace* FindRaceForAddr(uintptr_t addr) {
  TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
  vector<CallSite>& writes = typedCallSites->writes;
  vector<CallSite>& reads = typedCallSites->reads;
  for (vector<CallSite>::const_iterator it = writes.begin();
       it != writes.end(); ++ it) {
    map<uintptr_t, PossibleRace*>::iterator it2 = races_map->find(it->pc);
    if (it2 != races_map->end())
      return it2->second;
  }
  for (vector<CallSite>::const_iterator it = reads.begin();
       it != reads.end(); ++ it) {
    map<uintptr_t, PossibleRace*>::iterator it2 = races_map->find(it->pc);
    if (it2 != races_map->end())
      return it2->second;
  }
  return NULL;
}

/* Prints a race report for the given data address, either finding one in a
   matching PossibleRace, or just printing pc's of the mops.

   racecheck_lock must be held by the current thread.
*/
static void PrintRaceReport(uintptr_t addr) {
  PossibleRace* race = FindRaceForAddr(addr);
  if (race) {
    ExpectedRace* expected_race = ThreadSanitizerFindExpectedRace(addr);
    if (expected_race)
      expected_race->count++;
    bool is_expected = !!expected_race;
    bool is_unverifiable = is_expected && !expected_race->is_verifiable;

    if (is_expected && !is_unverifiable && !G_flags->show_expected_races)
      return;

    if (is_unverifiable)
      Printf("WARNING: Confirmed a race that was marked as UNVERIFIABLE:\n");
    else
      Printf("WARNING: Confirmed a race:\n");
    const string& report = race->report;
    if (report.empty()) {
      PrintRaceReportEmpty(addr);
    } else {
      Printf("%s", report.c_str());
    }
    // Suppress future reports for this race.
    race->reported = true;
    ignore_addresses->insert(addr);

    n_reports++;
  } else {
    Printf("Warning: unexpected race found!\n");
    PrintRaceReportEmpty(addr);

    n_reports ++;
  }
  UpdateSummary();
}

/**
 * This function is called before the mop delay.
 * @param thread_id Thread id.
 * @param addr Data address.
 * @param pc Instruction pc.
 * @param is_w Whether this is a write (true) or a read (false).
 * @return True if this access is interesting to us at all. If true, the caller
 *     should delay and then call RaceVerifierEndAccess. If false, it should do
 *     nothing more for this mop.
 */
bool RaceVerifierStartAccess(int thread_id, uintptr_t addr, uintptr_t pc,
    bool is_w) {
  CallSite callSite;
  callSite.thread_id = thread_id;
  callSite.pc = pc;
  racecheck_lock.Lock();

  if (debug_race_verifier)
    Printf("[%d] pc %p %s addr %p start\n", thread_id, pc,
        is_w ? "write" : "read", addr);

  if (ignore_addresses->count(addr)) {
    racecheck_lock.Unlock();
    return false;
  }

  TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
  vector<CallSite>& writes = typedCallSites->writes;
  vector<CallSite>& reads = typedCallSites->reads;
  (is_w ? writes : reads).push_back(callSite);
  if (writes.size() > 0 && writes.size() + reads.size() > 1) {
    bool is_race = false;
    for (size_t i = 0; !is_race && i < writes.size(); ++i) {
      for (size_t j = 0; !is_race && j < writes.size(); ++j)
        if (writes[i].thread_id != writes[j].thread_id)
          is_race = true;
      for (size_t j = 0; !is_race && j < reads.size(); ++j)
        if (writes[i].thread_id != reads[j].thread_id)
          is_race = true;
    }
    if (is_race)
      PrintRaceReport(addr);
  }
  racecheck_lock.Unlock();
  return true;
}

/* This function is called after the mop delay, only if RaceVerifierStartAccess
   returned true. The arguments are exactly the same. */
void RaceVerifierEndAccess(int thread_id, uintptr_t addr, uintptr_t pc,
    bool is_w) {
  racecheck_lock.Lock();

  if (debug_race_verifier)
    Printf("[%d] pc %p %s addr %p end\n", thread_id, pc,
        is_w ? "write" : "read", addr);
  if (ignore_addresses->count(addr)) {
    racecheck_lock.Unlock();
    return;
  }

  TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
  vector<CallSite>& vec =
      is_w ? typedCallSites->writes : typedCallSites->reads;
  for (int i = vec.size() - 1; i >= 0; --i) {
    if (vec[i].thread_id == thread_id) {
      vec.erase(vec.begin() + i);
      break;
    }
  }
  racecheck_lock.Unlock();
}

/* Parse a race description that appears in TSan logs after the words
   "Race verifier data: ", not including the said words. It looks like
   "pc,trace[,trace]...", without spaces. */
static PossibleRace* ParseRaceInfo(const string& raceInfo) {
  PossibleRace* race = new PossibleRace();
  const char* p = raceInfo.c_str();
  while (true) {
    char* end;
    uintptr_t addr = my_strtol(p, &end, 16);
    if (p == end) {
      Printf("Parse error: %s\n", p);
      exit(1);
    }
    if (!race->pc)
      race->pc = addr;
    else
      race->traces.push_back(addr);
    while (*end == '\n' || *end == '\r')
      ++end;
    if (*end == '\0') {
      // raceInfo already ends with \n
      Printf("Possible race: %s", raceInfo.c_str());
      return race;
    }
    if (*end != ',') {
      Printf("Parse error: comma expected: %s\n", end);
      delete race;
      return NULL;
    }
    p = end + 1;
  }
}

/* Parse a race description and add it to races_map. */
static void RaceVerifierParseRaceInfo(const string& raceInfo) {
  PossibleRace* race = ParseRaceInfo(raceInfo);
  if (race)
    (*races_map)[race->pc] = race;
  else
    Printf("Bad raceInfo: %s\n", raceInfo.c_str());
}


class StringStream {
 public:
  StringStream(const string &s) : s_(s), data_(s.c_str()), p_(data_) {}

  bool Eof() {
    return !*p_;
  }

  string NextLine() {
    const char* first = p_;
    while (*p_ && *p_ != '\n') {
      ++p_;
    }
    if (*p_)
      ++p_;
    return string(first, p_ - first);
  }

 private:
  const string& s_;
  const char* data_;
  const char* p_;
};

/* Parse a TSan log and add all race verifier info's from it to our storage of
   possible races. */
static void RaceVerifierParseFile(const string& fileName) {
  Printf("Reading race data from %s\n", fileName.c_str());
  const string RACEINFO_MARKER = "Race verifier data: ";
  string log = ReadFileToString(fileName, true /* die_if_failed */);
  StringStream ss(log);
  string* desc = NULL;
  int count = 0;
  while (!ss.Eof()) {
    string line = ss.NextLine();
    size_t pos;
    if ((line.find("WARNING: Possible data race during") !=
            string::npos) ||
        (line.find("WARNING: Expected data race during") !=
            string::npos)) {
      desc = new string();
      (*desc) += line;
    } else if ((pos = line.find(RACEINFO_MARKER)) != string::npos) {
      pos += RACEINFO_MARKER.size();
      string raceInfo = line.substr(pos);
      PossibleRace* race = ParseRaceInfo(raceInfo);
      (*desc) += "}}}\n";
      race->report = *desc;
      (*races_map)[race->pc] = race;
      count ++;
      delete desc;
      desc = NULL;
    } else if (desc) {
      (*desc) += line;
    }
  }
  Printf("Got %d possible races\n", count);
}

/**
 * Return the time to sleep for the given trace.
 * @param trace_pc The starting pc of the trace.
 * @return Time to sleep in ms, or 0 if this trace should be ignored.
 */
int RaceVerifierGetSleepTime(uintptr_t trace_pc) {
  racecheck_lock.Lock();
  int visit_count = ++(*visit_count_map)[trace_pc];
  int tm;
  if (visit_count < 20) {
    tm = G_flags->race_verifier_sleep_ms;
  } else if (visit_count < 200) {
    tm = G_flags->race_verifier_sleep_ms / 10;
  } else {
    tm = 0;
  }
  if (debug_race_verifier) {
    if (visit_count == 20) {
      Printf("RaceVerifier: Trace %x: sleep time reduced.\n", trace_pc);
    } else if (visit_count == 200) {
      Printf("RaceVerifier: Trace %x: ignored.\n", trace_pc);
    }
  }
  racecheck_lock.Unlock();
  return tm;
}

/**
 * Init the race verifier. Should be called exactly once before any other
 * functions in this file.
 * @param fileNames Names of TSan log to parse.
 * @param raceInfos Additional race description strings.
 */
void RaceVerifierInit(const vector<string>& fileNames,
    const vector<string>& raceInfos) {
  races_map = new map<uintptr_t, PossibleRace*>();
  racecheck_map = new AddressMap();
  visit_count_map = new VisitCountMap();
  ignore_addresses = new set<uintptr_t>();

  for (vector<string>::const_iterator it = fileNames.begin();
       it != fileNames.end(); ++it) {
    RaceVerifierParseFile(*it);
  }
  for (vector<string>::const_iterator it = raceInfos.begin();
       it != raceInfos.end(); ++it) {
    RaceVerifierParseRaceInfo(*it);
  }
}

void RaceVerifierFini() {
  Report("RaceVerifier summary: verified %d race(s)\n", n_reports);
  int n_errors = GetNumberOfFoundErrors();
  SetNumberOfFoundErrors(n_errors + n_reports);
}