Home | History | Annotate | Download | only in tsan
      1 /* Copyright (c) 2008-2010, Google Inc.
      2  * All rights reserved.
      3  *
      4  * Redistribution and use in source and binary forms, with or without
      5  * modification, are permitted provided that the following conditions are
      6  * met:
      7  *
      8  *     * Redistributions of source code must retain the above copyright
      9  * notice, this list of conditions and the following disclaimer.
     10  *     * Neither the name of Google Inc. nor the names of its
     11  * contributors may be used to endorse or promote products derived from
     12  * this software without specific prior written permission.
     13  *
     14  * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
     15  * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
     16  * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
     17  * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
     18  * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
     19  * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
     20  * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
     21  * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
     22  * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
     23  * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
     24  * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
     25  */
     26 
     27 // This file is part of ThreadSanitizer, a dynamic data race detector.
     28 // Author: Evgeniy Stepanov.
     29 
     30 #include <stdio.h>
     31 #include <stdlib.h>
     32 #include <string.h>
     33 #include <vector>
     34 #include <set>
     35 #include <iterator>
     36 #include <algorithm>
     37 
     38 #include "ts_lock.h"
     39 #include "ts_util.h"
     40 #include "ts_race_verifier.h"
     41 #include "thread_sanitizer.h"
     42 
     43 struct PossibleRace {
     44   PossibleRace() : pc(0), reported(false) {}
     45   // racy instruction
     46   uintptr_t pc;
     47   // concurrent traces
     48   vector<uintptr_t> traces;
     49   // report text
     50   string report;
     51   // whether this race has already been reported
     52   bool reported;
     53 };
     54 
     55 // pc -> race
     56 static map<uintptr_t, PossibleRace*>* races_map;
     57 
     58 // Data about a call site.
     59 struct CallSite {
     60   int thread_id;
     61   uintptr_t pc;
     62 };
     63 
     64 struct TypedCallSites {
     65   vector<CallSite> reads;
     66   vector<CallSite> writes;
     67 };
     68 
     69 // data address -> ([write callsites], [read callsites])
     70 typedef map<uintptr_t, TypedCallSites> AddressMap;
     71 
     72 static TSLock racecheck_lock;
     73 static AddressMap* racecheck_map;
     74 // data addresses that are ignored (they have already been reported)
     75 static set<uintptr_t>* ignore_addresses;
     76 
     77 // starting pc of the trace -> visit count
     78 // used to reduce the sleep time for hot traces
     79 typedef map<uintptr_t, int> VisitCountMap;
     80 static VisitCountMap* visit_count_map;
     81 
     82 static int n_reports;
     83 
     84 /**
     85  * Given max and min pc of a trace (both inclusive!), returns whether this trace
     86  * is interesting to us at all (via the return value), and whether it should be
     87  * instrumented fully (*instrument_pc=0), or 1 instruction only. In the latter
     88  * case, *instrument_pc contains the address of the said instruction.
     89  */
     90 bool RaceVerifierGetAddresses(uintptr_t min_pc, uintptr_t max_pc,
     91     uintptr_t* instrument_pc) {
     92   uintptr_t pc = 0;
     93   for (map<uintptr_t, PossibleRace*>::iterator it = races_map->begin();
     94        it != races_map->end(); ++it) {
     95     PossibleRace* race = it->second;
     96     if (race->reported)
     97       continue;
     98     if (race->pc >= min_pc && race->pc <= max_pc) {
     99       if (pc) {
    100         // Two race candidates in one trace. Just instrument it fully.
    101         *instrument_pc = 0;
    102         return true;
    103       }
    104       pc = race->pc;
    105     }
    106     for (vector<uintptr_t>::iterator it2 = race->traces.begin();
    107          it2 != race->traces.end(); ++it2) {
    108       if (*it2 >= min_pc && *it2 <= max_pc) {
    109         *instrument_pc = 0;
    110         return true;
    111       }
    112     }
    113   }
    114   *instrument_pc = pc;
    115   return !!pc;
    116 }
    117 
    118 static void UpdateSummary() {
    119   if (!G_flags->summary_file.empty()) {
    120     char buff[100];
    121     snprintf(buff, sizeof(buff),
    122 	     "RaceVerifier: %d report(s) verified\n", n_reports);
    123     // We overwrite the contents of this file with the new summary.
    124     // We don't do that at the end because even if we crash later
    125     // we will already have the summary.
    126     OpenFileWriteStringAndClose(G_flags->summary_file, buff);
    127   }
    128 }
    129 
    130 /* Build and print a race report for a data address. Does not print stack traces
    131    and symbols and all the fancy stuff - we don't have that info. Used when we
    132    don't have a ready report - for unexpected races and for
    133    --race-verifier-extra races.
    134 
    135    racecheck_lock must be held by the current thread.
    136 */
    137 static void PrintRaceReportEmpty(uintptr_t addr) {
    138   TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
    139   vector<CallSite>& writes = typedCallSites->writes;
    140   vector<CallSite>& reads = typedCallSites->reads;
    141   for (vector<CallSite>::const_iterator it = writes.begin();
    142        it != writes.end(); ++ it) {
    143     Printf("  write at %p\n", it->pc);
    144   }
    145   for (vector<CallSite>::const_iterator it = reads.begin();
    146        it != reads.end(); ++ it) {
    147     Printf("  read at %p\n", it->pc);
    148   }
    149 }
    150 
    151 /* Find a PossibleRace that matches current accesses (racecheck_map) to the
    152    given data address.
    153 
    154    racecheck_lock must be held by the current thread.
    155  */
    156 static PossibleRace* FindRaceForAddr(uintptr_t addr) {
    157   TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
    158   vector<CallSite>& writes = typedCallSites->writes;
    159   vector<CallSite>& reads = typedCallSites->reads;
    160   for (vector<CallSite>::const_iterator it = writes.begin();
    161        it != writes.end(); ++ it) {
    162     map<uintptr_t, PossibleRace*>::iterator it2 = races_map->find(it->pc);
    163     if (it2 != races_map->end())
    164       return it2->second;
    165   }
    166   for (vector<CallSite>::const_iterator it = reads.begin();
    167        it != reads.end(); ++ it) {
    168     map<uintptr_t, PossibleRace*>::iterator it2 = races_map->find(it->pc);
    169     if (it2 != races_map->end())
    170       return it2->second;
    171   }
    172   return NULL;
    173 }
    174 
    175 /* Prints a race report for the given data address, either finding one in a
    176    matching PossibleRace, or just printing pc's of the mops.
    177 
    178    racecheck_lock must be held by the current thread.
    179 */
    180 static void PrintRaceReport(uintptr_t addr) {
    181   PossibleRace* race = FindRaceForAddr(addr);
    182   if (race) {
    183     ExpectedRace* expected_race = ThreadSanitizerFindExpectedRace(addr);
    184     if (expected_race)
    185       expected_race->count++;
    186     bool is_expected = !!expected_race;
    187     bool is_unverifiable = is_expected && !expected_race->is_verifiable;
    188 
    189     if (is_expected && !is_unverifiable && !G_flags->show_expected_races)
    190       return;
    191 
    192     if (is_unverifiable)
    193       Printf("WARNING: Confirmed a race that was marked as UNVERIFIABLE:\n");
    194     else
    195       Printf("WARNING: Confirmed a race:\n");
    196     const string& report = race->report;
    197     if (report.empty()) {
    198       PrintRaceReportEmpty(addr);
    199     } else {
    200       Printf("%s", report.c_str());
    201     }
    202     // Suppress future reports for this race.
    203     race->reported = true;
    204     ignore_addresses->insert(addr);
    205 
    206     n_reports++;
    207   } else {
    208     Printf("Warning: unexpected race found!\n");
    209     PrintRaceReportEmpty(addr);
    210 
    211     n_reports ++;
    212   }
    213   UpdateSummary();
    214 }
    215 
    216 /**
    217  * This function is called before the mop delay.
    218  * @param thread_id Thread id.
    219  * @param addr Data address.
    220  * @param pc Instruction pc.
    221  * @param is_w Whether this is a write (true) or a read (false).
    222  * @return True if this access is interesting to us at all. If true, the caller
    223  *     should delay and then call RaceVerifierEndAccess. If false, it should do
    224  *     nothing more for this mop.
    225  */
    226 bool RaceVerifierStartAccess(int thread_id, uintptr_t addr, uintptr_t pc,
    227     bool is_w) {
    228   CallSite callSite;
    229   callSite.thread_id = thread_id;
    230   callSite.pc = pc;
    231   racecheck_lock.Lock();
    232 
    233   if (debug_race_verifier)
    234     Printf("[%d] pc %p %s addr %p start\n", thread_id, pc,
    235         is_w ? "write" : "read", addr);
    236 
    237   if (ignore_addresses->count(addr)) {
    238     racecheck_lock.Unlock();
    239     return false;
    240   }
    241 
    242   TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
    243   vector<CallSite>& writes = typedCallSites->writes;
    244   vector<CallSite>& reads = typedCallSites->reads;
    245   (is_w ? writes : reads).push_back(callSite);
    246   if (writes.size() > 0 && writes.size() + reads.size() > 1) {
    247     bool is_race = false;
    248     for (size_t i = 0; !is_race && i < writes.size(); ++i) {
    249       for (size_t j = 0; !is_race && j < writes.size(); ++j)
    250         if (writes[i].thread_id != writes[j].thread_id)
    251           is_race = true;
    252       for (size_t j = 0; !is_race && j < reads.size(); ++j)
    253         if (writes[i].thread_id != reads[j].thread_id)
    254           is_race = true;
    255     }
    256     if (is_race)
    257       PrintRaceReport(addr);
    258   }
    259   racecheck_lock.Unlock();
    260   return true;
    261 }
    262 
    263 /* This function is called after the mop delay, only if RaceVerifierStartAccess
    264    returned true. The arguments are exactly the same. */
    265 void RaceVerifierEndAccess(int thread_id, uintptr_t addr, uintptr_t pc,
    266     bool is_w) {
    267   racecheck_lock.Lock();
    268 
    269   if (debug_race_verifier)
    270     Printf("[%d] pc %p %s addr %p end\n", thread_id, pc,
    271         is_w ? "write" : "read", addr);
    272   if (ignore_addresses->count(addr)) {
    273     racecheck_lock.Unlock();
    274     return;
    275   }
    276 
    277   TypedCallSites* typedCallSites = &(*racecheck_map)[addr];
    278   vector<CallSite>& vec =
    279       is_w ? typedCallSites->writes : typedCallSites->reads;
    280   for (int i = vec.size() - 1; i >= 0; --i) {
    281     if (vec[i].thread_id == thread_id) {
    282       vec.erase(vec.begin() + i);
    283       break;
    284     }
    285   }
    286   racecheck_lock.Unlock();
    287 }
    288 
    289 /* Parse a race description that appears in TSan logs after the words
    290    "Race verifier data: ", not including the said words. It looks like
    291    "pc,trace[,trace]...", without spaces. */
    292 static PossibleRace* ParseRaceInfo(const string& raceInfo) {
    293   PossibleRace* race = new PossibleRace();
    294   const char* p = raceInfo.c_str();
    295   while (true) {
    296     char* end;
    297     uintptr_t addr = my_strtol(p, &end, 16);
    298     if (p == end) {
    299       Printf("Parse error: %s\n", p);
    300       exit(1);
    301     }
    302     if (!race->pc)
    303       race->pc = addr;
    304     else
    305       race->traces.push_back(addr);
    306     while (*end == '\n' || *end == '\r')
    307       ++end;
    308     if (*end == '\0') {
    309       // raceInfo already ends with \n
    310       Printf("Possible race: %s", raceInfo.c_str());
    311       return race;
    312     }
    313     if (*end != ',') {
    314       Printf("Parse error: comma expected: %s\n", end);
    315       delete race;
    316       return NULL;
    317     }
    318     p = end + 1;
    319   }
    320 }
    321 
    322 /* Parse a race description and add it to races_map. */
    323 static void RaceVerifierParseRaceInfo(const string& raceInfo) {
    324   PossibleRace* race = ParseRaceInfo(raceInfo);
    325   if (race)
    326     (*races_map)[race->pc] = race;
    327   else
    328     Printf("Bad raceInfo: %s\n", raceInfo.c_str());
    329 }
    330 
    331 
    332 class StringStream {
    333  public:
    334   StringStream(const string &s) : s_(s), data_(s.c_str()), p_(data_) {}
    335 
    336   bool Eof() {
    337     return !*p_;
    338   }
    339 
    340   string NextLine() {
    341     const char* first = p_;
    342     while (*p_ && *p_ != '\n') {
    343       ++p_;
    344     }
    345     if (*p_)
    346       ++p_;
    347     return string(first, p_ - first);
    348   }
    349 
    350  private:
    351   const string& s_;
    352   const char* data_;
    353   const char* p_;
    354 };
    355 
    356 /* Parse a TSan log and add all race verifier info's from it to our storage of
    357    possible races. */
    358 static void RaceVerifierParseFile(const string& fileName) {
    359   Printf("Reading race data from %s\n", fileName.c_str());
    360   const string RACEINFO_MARKER = "Race verifier data: ";
    361   string log = ReadFileToString(fileName, true /* die_if_failed */);
    362   StringStream ss(log);
    363   string* desc = NULL;
    364   int count = 0;
    365   while (!ss.Eof()) {
    366     string line = ss.NextLine();
    367     size_t pos;
    368     if ((line.find("WARNING: Possible data race during") !=
    369             string::npos) ||
    370         (line.find("WARNING: Expected data race during") !=
    371             string::npos)) {
    372       desc = new string();
    373       (*desc) += line;
    374     } else if ((pos = line.find(RACEINFO_MARKER)) != string::npos) {
    375       pos += RACEINFO_MARKER.size();
    376       string raceInfo = line.substr(pos);
    377       PossibleRace* race = ParseRaceInfo(raceInfo);
    378       (*desc) += "}}}\n";
    379       race->report = *desc;
    380       (*races_map)[race->pc] = race;
    381       count ++;
    382       delete desc;
    383       desc = NULL;
    384     } else if (desc) {
    385       (*desc) += line;
    386     }
    387   }
    388   Printf("Got %d possible races\n", count);
    389 }
    390 
    391 /**
    392  * Return the time to sleep for the given trace.
    393  * @param trace_pc The starting pc of the trace.
    394  * @return Time to sleep in ms, or 0 if this trace should be ignored.
    395  */
    396 int RaceVerifierGetSleepTime(uintptr_t trace_pc) {
    397   racecheck_lock.Lock();
    398   int visit_count = ++(*visit_count_map)[trace_pc];
    399   int tm;
    400   if (visit_count < 20) {
    401     tm = G_flags->race_verifier_sleep_ms;
    402   } else if (visit_count < 200) {
    403     tm = G_flags->race_verifier_sleep_ms / 10;
    404   } else {
    405     tm = 0;
    406   }
    407   if (debug_race_verifier) {
    408     if (visit_count == 20) {
    409       Printf("RaceVerifier: Trace %x: sleep time reduced.\n", trace_pc);
    410     } else if (visit_count == 200) {
    411       Printf("RaceVerifier: Trace %x: ignored.\n", trace_pc);
    412     }
    413   }
    414   racecheck_lock.Unlock();
    415   return tm;
    416 }
    417 
    418 /**
    419  * Init the race verifier. Should be called exactly once before any other
    420  * functions in this file.
    421  * @param fileNames Names of TSan log to parse.
    422  * @param raceInfos Additional race description strings.
    423  */
    424 void RaceVerifierInit(const vector<string>& fileNames,
    425     const vector<string>& raceInfos) {
    426   races_map = new map<uintptr_t, PossibleRace*>();
    427   racecheck_map = new AddressMap();
    428   visit_count_map = new VisitCountMap();
    429   ignore_addresses = new set<uintptr_t>();
    430 
    431   for (vector<string>::const_iterator it = fileNames.begin();
    432        it != fileNames.end(); ++it) {
    433     RaceVerifierParseFile(*it);
    434   }
    435   for (vector<string>::const_iterator it = raceInfos.begin();
    436        it != raceInfos.end(); ++it) {
    437     RaceVerifierParseRaceInfo(*it);
    438   }
    439 }
    440 
    441 void RaceVerifierFini() {
    442   Report("RaceVerifier summary: verified %d race(s)\n", n_reports);
    443   int n_errors = GetNumberOfFoundErrors();
    444   SetNumberOfFoundErrors(n_errors + n_reports);
    445 }
    446