src/build.cc

   1 // Copyright 2011 Google Inc. All Rights Reserved.
   2 //
   3 // Licensed under the Apache License, Version 2.0 (the "License");
   4 // you may not use this file except in compliance with the License.
   5 // You may obtain a copy of the License at
   6 //
   7 //     http://www.apache.org/licenses/LICENSE-2.0
   8 //
   9 // Unless required by applicable law or agreed to in writing, software
  10 // distributed under the License is distributed on an "AS IS" BASIS,
  11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12 // See the License for the specific language governing permissions and
  13 // limitations under the License.
  14
  15 #include "build.h"
  16
  17 #include <assert.h>
  18 #include <errno.h>
  19 #include <stdio.h>
  20 #include <stdlib.h>
  21 #include <functional>
  22
  23 #if defined(__SVR4) && defined(__sun)
  24 #include <sys/termios.h>
  25 #endif
  26
  27 #include "build_log.h"
  28 #include "debug_flags.h"
  29 #include "depfile_parser.h"
  30 #include "deps_log.h"
  31 #include "disk_interface.h"
  32 #include "graph.h"
  33 #include "msvc_helper.h"
  34 #include "state.h"
  35 #include "subprocess.h"
  36 #include "util.h"
  37
  38 namespace {
  39
  40 /// A CommandRunner that doesn't actually run the commands.
  41 struct DryRunCommandRunner : public CommandRunner {
  42   virtual ~DryRunCommandRunner() {}
  43
  44   // Overridden from CommandRunner:
  45   virtual bool CanRunMore();
  46   virtual bool StartCommand(Edge* edge);
  47   virtual bool WaitForCommand(Result* result);
  48
  49  private:
  50   queue<Edge*> finished_;
  51 };
  52
  53 bool DryRunCommandRunner::CanRunMore() {
  54   return true;
  55 }
  56
  57 bool DryRunCommandRunner::StartCommand(Edge* edge) {
  58   finished_.push(edge);
  59   return true;
  60 }
  61
  62 bool DryRunCommandRunner::WaitForCommand(Result* result) {
  63    if (finished_.empty())
  64      return false;
  65
  66    result->status = ExitSuccess;
  67    result->edge = finished_.front();
  68    finished_.pop();
  69    return true;
  70 }
  71
  72 }  // namespace
  73
  74 BuildStatus::BuildStatus(const BuildConfig& config)
  75     : config_(config),
  76       start_time_millis_(GetTimeMillis()),
  77       started_edges_(0), finished_edges_(0), total_edges_(0),
  78       progress_status_format_(NULL),
  79       overall_rate_(), current_rate_(config.parallelism) {
  80
  81   // Don't do anything fancy in verbose mode.
  82   if (config_.verbosity != BuildConfig::NORMAL)
  83     printer_.set_smart_terminal(false);
  84
  85   progress_status_format_ = getenv("NINJA_STATUS");
  86   if (!progress_status_format_)
  87     progress_status_format_ = "[%s/%t] ";
  88 }
  89
  90 void BuildStatus::PlanHasTotalEdges(int total) {
  91   total_edges_ = total;
  92 }
  93
  94 void BuildStatus::BuildEdgeStarted(Edge* edge) {
  95   int start_time = (int)(GetTimeMillis() - start_time_millis_);
  96   running_edges_.insert(make_pair(edge, start_time));
  97   ++started_edges_;
  98
  99   if (edge->use_console() || printer_.is_smart_terminal())
 100     PrintStatus(edge);
 101
 102   if (edge->use_console())
 103     printer_.SetConsoleLocked(true);
 104 }
 105
 106 void BuildStatus::BuildEdgeFinished(Edge* edge,
 107                                     bool success,
 108                                     const string& output,
 109                                     int* start_time,
 110                                     int* end_time) {
 111   int64_t now = GetTimeMillis();
 112   ++finished_edges_;
 113
 114   RunningEdgeMap::iterator i = running_edges_.find(edge);
 115   *start_time = i->second;
 116   *end_time = (int)(now - start_time_millis_);
 117   running_edges_.erase(i);
 118
 119   if (edge->use_console())
 120     printer_.SetConsoleLocked(false);
 121
 122   if (config_.verbosity == BuildConfig::QUIET)
 123     return;
 124
 125   if (!edge->use_console())
 126     PrintStatus(edge);
 127
 128   // Print the command that is spewing before printing its output.
 129   if (!success)
 130     printer_.PrintOnNewLine("FAILED: " + edge->EvaluateCommand() + "\n");
 131
 132   if (!output.empty()) {
 133     // ninja sets stdout and stderr of subprocesses to a pipe, to be able to
 134     // check if the output is empty. Some compilers, e.g. clang, check
 135     // isatty(stderr) to decide if they should print colored output.
 136     // To make it possible to use colored output with ninja, subprocesses should
 137     // be run with a flag that forces them to always print color escape codes.
 138     // To make sure these escape codes don't show up in a file if ninja's output
 139     // is piped to a file, ninja strips ansi escape codes again if it's not
 140     // writing to a |smart_terminal_|.
 141     // (Launching subprocesses in pseudo ttys doesn't work because there are
 142     // only a few hundred available on some systems, and ninja can launch
 143     // thousands of parallel compile commands.)
 144     // TODO: There should be a flag to disable escape code stripping.
 145     string final_output;
 146     if (!printer_.is_smart_terminal())
 147       final_output = StripAnsiEscapeCodes(output);
 148     else
 149       final_output = output;
 150     printer_.PrintOnNewLine(final_output);
 151   }
 152 }
 153
 154 void BuildStatus::BuildFinished() {
 155   printer_.SetConsoleLocked(false);
 156   printer_.PrintOnNewLine("");
 157 }
 158
 159 string BuildStatus::FormatProgressStatus(
 160     const char* progress_status_format) const {
 161   string out;
 162   char buf[32];
 163   int percent;
 164   for (const char* s = progress_status_format; *s != '\0'; ++s) {
 165     if (*s == '%') {
 166       ++s;
 167       switch (*s) {
 168       case '%':
 169         out.push_back('%');
 170         break;
 171
 172         // Started edges.
 173       case 's':
 174         snprintf(buf, sizeof(buf), "%d", started_edges_);
 175         out += buf;
 176         break;
 177
 178         // Total edges.
 179       case 't':
 180         snprintf(buf, sizeof(buf), "%d", total_edges_);
 181         out += buf;
 182         break;
 183
 184         // Running edges.
 185       case 'r':
 186         snprintf(buf, sizeof(buf), "%d", started_edges_ - finished_edges_);
 187         out += buf;
 188         break;
 189
 190         // Unstarted edges.
 191       case 'u':
 192         snprintf(buf, sizeof(buf), "%d", total_edges_ - started_edges_);
 193         out += buf;
 194         break;
 195
 196         // Finished edges.
 197       case 'f':
 198         snprintf(buf, sizeof(buf), "%d", finished_edges_);
 199         out += buf;
 200         break;
 201
 202         // Overall finished edges per second.
 203       case 'o':
 204         overall_rate_.UpdateRate(finished_edges_);
 205         snprinfRate(overall_rate_.rate(), buf, "%.1f");
 206         out += buf;
 207         break;
 208
 209         // Current rate, average over the last '-j' jobs.
 210       case 'c':
 211         current_rate_.UpdateRate(finished_edges_);
 212         snprinfRate(current_rate_.rate(), buf, "%.1f");
 213         out += buf;
 214         break;
 215
 216         // Percentage
 217       case 'p':
 218         percent = (100 * started_edges_) / total_edges_;
 219         snprintf(buf, sizeof(buf), "%3i%%", percent);
 220         out += buf;
 221         break;
 222
 223       case 'e': {
 224         double elapsed = overall_rate_.Elapsed();
 225         snprintf(buf, sizeof(buf), "%.3f", elapsed);
 226         out += buf;
 227         break;
 228       }
 229
 230       default:
 231         Fatal("unknown placeholder '%%%c' in $NINJA_STATUS", *s);
 232         return "";
 233       }
 234     } else {
 235       out.push_back(*s);
 236     }
 237   }
 238
 239   return out;
 240 }
 241
 242 void BuildStatus::PrintStatus(Edge* edge) {
 243   if (config_.verbosity == BuildConfig::QUIET)
 244     return;
 245
 246   bool force_full_command = config_.verbosity == BuildConfig::VERBOSE;
 247
 248   string to_print = edge->GetBinding("description");
 249   if (to_print.empty() || force_full_command)
 250     to_print = edge->GetBinding("command");
 251
 252   if (finished_edges_ == 0) {
 253     overall_rate_.Restart();
 254     current_rate_.Restart();
 255   }
 256   to_print = FormatProgressStatus(progress_status_format_) + to_print;
 257
 258   printer_.Print(to_print,
 259                  force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE);
 260 }
 261
 262 Plan::Plan() : command_edges_(0), wanted_edges_(0) {}
 263
 264 bool Plan::AddTarget(Node* node, string* err) {
 265   vector<Node*> stack;
 266   return AddSubTarget(node, &stack, err);
 267 }
 268
 269 bool Plan::AddSubTarget(Node* node, vector<Node*>* stack, string* err) {
 270   Edge* edge = node->in_edge();
 271   if (!edge) {  // Leaf node.
 272     if (node->dirty()) {
 273       string referenced;
 274       if (!stack->empty())
 275         referenced = ", needed by '" + stack->back()->path() + "',";
 276       *err = "'" + node->path() + "'" + referenced + " missing "
 277              "and no known rule to make it";
 278     }
 279     return false;
 280   }
 281
 282   if (CheckDependencyCycle(node, *stack, err))
 283     return false;
 284
 285   if (edge->outputs_ready())
 286     return false;  // Don't need to do anything.
 287
 288   // If an entry in want_ does not already exist for edge, create an entry which
 289   // maps to false, indicating that we do not want to build this entry itself.
 290   pair<map<Edge*, bool>::iterator, bool> want_ins =
 291     want_.insert(make_pair(edge, false));
 292   bool& want = want_ins.first->second;
 293
 294   // If we do need to build edge and we haven't already marked it as wanted,
 295   // mark it now.
 296   if (node->dirty() && !want) {
 297     want = true;
 298     ++wanted_edges_;
 299     if (edge->AllInputsReady())
 300       ScheduleWork(edge);
 301     if (!edge->is_phony())
 302       ++command_edges_;
 303   }
 304
 305   if (!want_ins.second)
 306     return true;  // We've already processed the inputs.
 307
 308   stack->push_back(node);
 309   for (vector<Node*>::iterator i = edge->inputs_.begin();
 310        i != edge->inputs_.end(); ++i) {
 311     if (!AddSubTarget(*i, stack, err) && !err->empty())
 312       return false;
 313   }
 314   assert(stack->back() == node);
 315   stack->pop_back();
 316
 317   return true;
 318 }
 319
 320 bool Plan::CheckDependencyCycle(Node* node, const vector<Node*>& stack,
 321                                 string* err) {
 322   vector<Node*>::const_iterator start = stack.begin();
 323   while (start != stack.end() && (*start)->in_edge() != node->in_edge())
 324     ++start;
 325   if (start == stack.end())
 326     return false;
 327
 328   // Build error string for the cycle.
 329   vector<Node*> cycle(start, stack.end());
 330   cycle.push_back(node);
 331
 332   if (cycle.front() != cycle.back()) {
 333     // Consider
 334     //   build a b: cat c
 335     //   build c: cat a
 336     // stack will contain [b, c], node will be a.  To not print b -> c -> a,
 337     // shift by one to get c -> a -> c which makes the cycle clear.
 338     cycle.erase(cycle.begin());
 339     cycle.push_back(cycle.front());
 340     assert(cycle.front() == cycle.back());
 341   }
 342
 343   *err = "dependency cycle: ";
 344   for (vector<Node*>::const_iterator i = cycle.begin(); i != cycle.end(); ++i) {
 345     if (i != cycle.begin())
 346       err->append(" -> ");
 347     err->append((*i)->path());
 348   }
 349   return true;
 350 }
 351
 352 Edge* Plan::FindWork() {
 353   if (ready_.empty())
 354     return NULL;
 355   set<Edge*>::iterator e = ready_.begin();
 356   Edge* edge = *e;
 357   ready_.erase(e);
 358   return edge;
 359 }
 360
 361 void Plan::ScheduleWork(Edge* edge) {
 362   Pool* pool = edge->pool();
 363   if (pool->ShouldDelayEdge()) {
 364     // The graph is not completely clean. Some Nodes have duplicate Out edges.
 365     // We need to explicitly ignore these here, otherwise their work will get
 366     // scheduled twice (see https://github.com/ninja-build/ninja/pull/519)
 367     if (ready_.count(edge)) {
 368       return;
 369     }
 370     pool->DelayEdge(edge);
 371     pool->RetrieveReadyEdges(&ready_);
 372   } else {
 373     pool->EdgeScheduled(*edge);
 374     ready_.insert(edge);
 375   }
 376 }
 377
 378 void Plan::EdgeFinished(Edge* edge) {
 379   map<Edge*, bool>::iterator e = want_.find(edge);
 380   assert(e != want_.end());
 381   bool directly_wanted = e->second;
 382   if (directly_wanted)
 383     --wanted_edges_;
 384   want_.erase(e);
 385   edge->outputs_ready_ = true;
 386
 387   // See if this job frees up any delayed jobs.
 388   if (directly_wanted)
 389     edge->pool()->EdgeFinished(*edge);
 390   edge->pool()->RetrieveReadyEdges(&ready_);
 391
 392   // Check off any nodes we were waiting for with this edge.
 393   for (vector<Node*>::iterator o = edge->outputs_.begin();
 394        o != edge->outputs_.end(); ++o) {
 395     NodeFinished(*o);
 396   }
 397 }
 398
 399 void Plan::NodeFinished(Node* node) {
 400   // See if we we want any edges from this node.
 401   for (vector<Edge*>::const_iterator oe = node->out_edges().begin();
 402        oe != node->out_edges().end(); ++oe) {
 403     map<Edge*, bool>::iterator want_e = want_.find(*oe);
 404     if (want_e == want_.end())
 405       continue;
 406
 407     // See if the edge is now ready.
 408     if ((*oe)->AllInputsReady()) {
 409       if (want_e->second) {
 410         ScheduleWork(*oe);
 411       } else {
 412         // We do not need to build this edge, but we might need to build one of
 413         // its dependents.
 414         EdgeFinished(*oe);
 415       }
 416     }
 417   }
 418 }
 419
 420 bool Plan::CleanNode(DependencyScan* scan, Node* node, string* err) {
 421   node->set_dirty(false);
 422
 423   for (vector<Edge*>::const_iterator oe = node->out_edges().begin();
 424        oe != node->out_edges().end(); ++oe) {
 425     // Don't process edges that we don't actually want.
 426     map<Edge*, bool>::iterator want_e = want_.find(*oe);
 427     if (want_e == want_.end() || !want_e->second)
 428       continue;
 429
 430     // Don't attempt to clean an edge if it failed to load deps.
 431     if ((*oe)->deps_missing_)
 432       continue;
 433
 434     // If all non-order-only inputs for this edge are now clean,
 435     // we might have changed the dirty state of the outputs.
 436     vector<Node*>::iterator
 437         begin = (*oe)->inputs_.begin(),
 438         end = (*oe)->inputs_.end() - (*oe)->order_only_deps_;
 439     if (find_if(begin, end, mem_fun(&Node::dirty)) == end) {
 440       // Recompute most_recent_input.
 441       Node* most_recent_input = NULL;
 442       for (vector<Node*>::iterator i = begin; i != end; ++i) {
 443         if (!most_recent_input || (*i)->mtime() > most_recent_input->mtime())
 444           most_recent_input = *i;
 445       }
 446
 447       // Now, this edge is dirty if any of the outputs are dirty.
 448       // If the edge isn't dirty, clean the outputs and mark the edge as not
 449       // wanted.
 450       bool outputs_dirty = false;
 451       if (!scan->RecomputeOutputsDirty(*oe, most_recent_input,
 452                                        &outputs_dirty, err)) {
 453         return false;
 454       }
 455       if (!outputs_dirty) {
 456         for (vector<Node*>::iterator o = (*oe)->outputs_.begin();
 457              o != (*oe)->outputs_.end(); ++o) {
 458           if (!CleanNode(scan, *o, err))
 459             return false;
 460         }
 461
 462         want_e->second = false;
 463         --wanted_edges_;
 464         if (!(*oe)->is_phony())
 465           --command_edges_;
 466       }
 467     }
 468   }
 469   return true;
 470 }
 471
 472 void Plan::Dump() {
 473   printf("pending: %d\n", (int)want_.size());
 474   for (map<Edge*, bool>::iterator e = want_.begin(); e != want_.end(); ++e) {
 475     if (e->second)
 476       printf("want ");
 477     e->first->Dump();
 478   }
 479   printf("ready: %d\n", (int)ready_.size());
 480 }
 481
 482 struct RealCommandRunner : public CommandRunner {
 483   explicit RealCommandRunner(const BuildConfig& config) : config_(config) {}
 484   virtual ~RealCommandRunner() {}
 485   virtual bool CanRunMore();
 486   virtual bool StartCommand(Edge* edge);
 487   virtual bool WaitForCommand(Result* result);
 488   virtual vector<Edge*> GetActiveEdges();
 489   virtual void Abort();
 490
 491   const BuildConfig& config_;
 492   SubprocessSet subprocs_;
 493   map<Subprocess*, Edge*> subproc_to_edge_;
 494 };
 495
 496 vector<Edge*> RealCommandRunner::GetActiveEdges() {
 497   vector<Edge*> edges;
 498   for (map<Subprocess*, Edge*>::iterator e = subproc_to_edge_.begin();
 499        e != subproc_to_edge_.end(); ++e)
 500     edges.push_back(e->second);
 501   return edges;
 502 }
 503
 504 void RealCommandRunner::Abort() {
 505   subprocs_.Clear();
 506 }
 507
 508 bool RealCommandRunner::CanRunMore() {
 509   size_t subproc_number =
 510       subprocs_.running_.size() + subprocs_.finished_.size();
 511   return (int)subproc_number < config_.parallelism
 512     && ((subprocs_.running_.empty() || config_.max_load_average <= 0.0f)
 513         || GetLoadAverage() < config_.max_load_average);
 514 }
 515
 516 bool RealCommandRunner::StartCommand(Edge* edge) {
 517   string command = edge->EvaluateCommand();
 518   Subprocess* subproc = subprocs_.Add(command, edge->use_console());
 519   if (!subproc)
 520     return false;
 521   subproc_to_edge_.insert(make_pair(subproc, edge));
 522
 523   return true;
 524 }
 525
 526 bool RealCommandRunner::WaitForCommand(Result* result) {
 527   Subprocess* subproc;
 528   while ((subproc = subprocs_.NextFinished()) == NULL) {
 529     bool interrupted = subprocs_.DoWork();
 530     if (interrupted)
 531       return false;
 532   }
 533
 534   result->status = subproc->Finish();
 535   result->output = subproc->GetOutput();
 536
 537   map<Subprocess*, Edge*>::iterator e = subproc_to_edge_.find(subproc);
 538   result->edge = e->second;
 539   subproc_to_edge_.erase(e);
 540
 541   delete subproc;
 542   return true;
 543 }
 544
 545 Builder::Builder(State* state, const BuildConfig& config,
 546                  BuildLog* build_log, DepsLog* deps_log,
 547                  DiskInterface* disk_interface)
 548     : state_(state), config_(config), disk_interface_(disk_interface),
 549       scan_(state, build_log, deps_log, disk_interface) {
 550   status_ = new BuildStatus(config);
 551 }
 552
 553 Builder::~Builder() {
 554   Cleanup();
 555 }
 556
 557 void Builder::Cleanup() {
 558   if (command_runner_.get()) {
 559     vector<Edge*> active_edges = command_runner_->GetActiveEdges();
 560     command_runner_->Abort();
 561
 562     for (vector<Edge*>::iterator e = active_edges.begin();
 563          e != active_edges.end(); ++e) {
 564       string depfile = (*e)->GetUnescapedDepfile();
 565       for (vector<Node*>::iterator o = (*e)->outputs_.begin();
 566            o != (*e)->outputs_.end(); ++o) {
 567         // Only delete this output if it was actually modified.  This is
 568         // important for things like the generator where we don't want to
 569         // delete the manifest file if we can avoid it.  But if the rule
 570         // uses a depfile, always delete.  (Consider the case where we
 571         // need to rebuild an output because of a modified header file
 572         // mentioned in a depfile, and the command touches its depfile
 573         // but is interrupted before it touches its output file.)
 574         string err;
 575         TimeStamp new_mtime = disk_interface_->Stat((*o)->path(), &err);
 576         if (new_mtime == -1)  // Log and ignore Stat() errors.
 577           Error("%s", err.c_str());
 578         if (!depfile.empty() || (*o)->mtime() != new_mtime)
 579           disk_interface_->RemoveFile((*o)->path());
 580       }
 581       if (!depfile.empty())
 582         disk_interface_->RemoveFile(depfile);
 583     }
 584   }
 585 }
 586
 587 Node* Builder::AddTarget(const string& name, string* err) {
 588   Node* node = state_->LookupNode(name);
 589   if (!node) {
 590     *err = "unknown target: '" + name + "'";
 591     return NULL;
 592   }
 593   if (!AddTarget(node, err))
 594     return NULL;
 595   return node;
 596 }
 597
 598 bool Builder::AddTarget(Node* node, string* err) {
 599   if (Edge* in_edge = node->in_edge()) {
 600     if (!scan_.RecomputeDirty(in_edge, err))
 601       return false;
 602     if (in_edge->outputs_ready())
 603       return true;  // Nothing to do.
 604   }
 605
 606   if (!plan_.AddTarget(node, err))
 607     return false;
 608
 609   return true;
 610 }
 611
 612 bool Builder::AlreadyUpToDate() const {
 613   return !plan_.more_to_do();
 614 }
 615
 616 bool Builder::Build(string* err) {
 617   assert(!AlreadyUpToDate());
 618
 619   status_->PlanHasTotalEdges(plan_.command_edge_count());
 620   int pending_commands = 0;
 621   int failures_allowed = config_.failures_allowed;
 622
 623   // Set up the command runner if we haven't done so already.
 624   if (!command_runner_.get()) {
 625     if (config_.dry_run)
 626       command_runner_.reset(new DryRunCommandRunner);
 627     else
 628       command_runner_.reset(new RealCommandRunner(config_));
 629   }
 630
 631   // This main loop runs the entire build process.
 632   // It is structured like this:
 633   // First, we attempt to start as many commands as allowed by the
 634   // command runner.
 635   // Second, we attempt to wait for / reap the next finished command.
 636   while (plan_.more_to_do()) {
 637     // See if we can start any more commands.
 638     if (failures_allowed && command_runner_->CanRunMore()) {
 639       if (Edge* edge = plan_.FindWork()) {
 640         if (!StartEdge(edge, err)) {
 641           Cleanup();
 642           status_->BuildFinished();
 643           return false;
 644         }
 645
 646         if (edge->is_phony()) {
 647           plan_.EdgeFinished(edge);
 648         } else {
 649           ++pending_commands;
 650         }
 651
 652         // We made some progress; go back to the main loop.
 653         continue;
 654       }
 655     }
 656
 657     // See if we can reap any finished commands.
 658     if (pending_commands) {
 659       CommandRunner::Result result;
 660       if (!command_runner_->WaitForCommand(&result) ||
 661           result.status == ExitInterrupted) {
 662         Cleanup();
 663         status_->BuildFinished();
 664         *err = "interrupted by user";
 665         return false;
 666       }
 667
 668       --pending_commands;
 669       if (!FinishCommand(&result, err)) {
 670         Cleanup();
 671         status_->BuildFinished();
 672         return false;
 673       }
 674
 675       if (!result.success()) {
 676         if (failures_allowed)
 677           failures_allowed--;
 678       }
 679
 680       // We made some progress; start the main loop over.
 681       continue;
 682     }
 683
 684     // If we get here, we cannot make any more progress.
 685     status_->BuildFinished();
 686     if (failures_allowed == 0) {
 687       if (config_.failures_allowed > 1)
 688         *err = "subcommands failed";
 689       else
 690         *err = "subcommand failed";
 691     } else if (failures_allowed < config_.failures_allowed)
 692       *err = "cannot make progress due to previous errors";
 693     else
 694       *err = "stuck [this is a bug]";
 695
 696     return false;
 697   }
 698
 699   status_->BuildFinished();
 700   return true;
 701 }
 702
 703 bool Builder::StartEdge(Edge* edge, string* err) {
 704   METRIC_RECORD("StartEdge");
 705   if (edge->is_phony())
 706     return true;
 707
 708   status_->BuildEdgeStarted(edge);
 709
 710   // Create directories necessary for outputs.
 711   // XXX: this will block; do we care?
 712   for (vector<Node*>::iterator o = edge->outputs_.begin();
 713        o != edge->outputs_.end(); ++o) {
 714     if (!disk_interface_->MakeDirs((*o)->path()))
 715       return false;
 716   }
 717
 718   // Create response file, if needed
 719   // XXX: this may also block; do we care?
 720   string rspfile = edge->GetUnescapedRspfile();
 721   if (!rspfile.empty()) {
 722     string content = edge->GetBinding("rspfile_content");
 723     if (!disk_interface_->WriteFile(rspfile, content))
 724       return false;
 725   }
 726
 727   // start command computing and run it
 728   if (!command_runner_->StartCommand(edge)) {
 729     err->assign("command '" + edge->EvaluateCommand() + "' failed.");
 730     return false;
 731   }
 732
 733   return true;
 734 }
 735
 736 bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
 737   METRIC_RECORD("FinishCommand");
 738
 739   Edge* edge = result->edge;
 740
 741   // First try to extract dependencies from the result, if any.
 742   // This must happen first as it filters the command output (we want
 743   // to filter /showIncludes output, even on compile failure) and
 744   // extraction itself can fail, which makes the command fail from a
 745   // build perspective.
 746   vector<Node*> deps_nodes;
 747   string deps_type = edge->GetBinding("deps");
 748   const string deps_prefix = edge->GetBinding("msvc_deps_prefix");
 749   if (!deps_type.empty()) {
 750     string extract_err;
 751     if (!ExtractDeps(result, deps_type, deps_prefix, &deps_nodes,
 752                      &extract_err) &&
 753         result->success()) {
 754       if (!result->output.empty())
 755         result->output.append("\n");
 756       result->output.append(extract_err);
 757       result->status = ExitFailure;
 758     }
 759   }
 760
 761   int start_time, end_time;
 762   status_->BuildEdgeFinished(edge, result->success(), result->output,
 763                              &start_time, &end_time);
 764
 765   // The rest of this function only applies to successful commands.
 766   if (!result->success())
 767     return true;
 768
 769   // Restat the edge outputs, if necessary.
 770   TimeStamp restat_mtime = 0;
 771   if (edge->GetBindingBool("restat") && !config_.dry_run) {
 772     bool node_cleaned = false;
 773
 774     for (vector<Node*>::iterator o = edge->outputs_.begin();
 775          o != edge->outputs_.end(); ++o) {
 776       TimeStamp new_mtime = disk_interface_->Stat((*o)->path(), err);
 777       if (new_mtime == -1)
 778         return false;
 779       if ((*o)->mtime() == new_mtime) {
 780         // The rule command did not change the output.  Propagate the clean
 781         // state through the build graph.
 782         // Note that this also applies to nonexistent outputs (mtime == 0).
 783         if (!plan_.CleanNode(&scan_, *o, err))
 784           return false;
 785         node_cleaned = true;
 786       }
 787     }
 788
 789     if (node_cleaned) {
 790       // If any output was cleaned, find the most recent mtime of any
 791       // (existing) non-order-only input or the depfile.
 792       for (vector<Node*>::iterator i = edge->inputs_.begin();
 793            i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
 794         TimeStamp input_mtime = disk_interface_->Stat((*i)->path(), err);
 795         if (input_mtime == -1)
 796           return false;
 797         if (input_mtime > restat_mtime)
 798           restat_mtime = input_mtime;
 799       }
 800
 801       string depfile = edge->GetUnescapedDepfile();
 802       if (restat_mtime != 0 && deps_type.empty() && !depfile.empty()) {
 803         TimeStamp depfile_mtime = disk_interface_->Stat(depfile, err);
 804         if (depfile_mtime == -1)
 805           return false;
 806         if (depfile_mtime > restat_mtime)
 807           restat_mtime = depfile_mtime;
 808       }
 809
 810       // The total number of edges in the plan may have changed as a result
 811       // of a restat.
 812       status_->PlanHasTotalEdges(plan_.command_edge_count());
 813     }
 814   }
 815
 816   plan_.EdgeFinished(edge);
 817
 818   // Delete any left over response file.
 819   string rspfile = edge->GetUnescapedRspfile();
 820   if (!rspfile.empty() && !g_keep_rsp)
 821     disk_interface_->RemoveFile(rspfile);
 822
 823   if (scan_.build_log()) {
 824     if (!scan_.build_log()->RecordCommand(edge, start_time, end_time,
 825                                           restat_mtime)) {
 826       *err = string("Error writing to build log: ") + strerror(errno);
 827       return false;
 828     }
 829   }
 830
 831   if (!deps_type.empty() && !config_.dry_run) {
 832     assert(edge->outputs_.size() == 1 && "should have been rejected by parser");
 833     Node* out = edge->outputs_[0];
 834     TimeStamp deps_mtime = disk_interface_->Stat(out->path(), err);
 835     if (deps_mtime == -1)
 836       return false;
 837     if (!scan_.deps_log()->RecordDeps(out, deps_mtime, deps_nodes)) {
 838       *err = string("Error writing to deps log: ") + strerror(errno);
 839       return false;
 840     }
 841   }
 842   return true;
 843 }
 844
 845 bool Builder::ExtractDeps(CommandRunner::Result* result,
 846                           const string& deps_type,
 847                           const string& deps_prefix,
 848                           vector<Node*>* deps_nodes,
 849                           string* err) {
 850 #ifdef _WIN32
 851   if (deps_type == "msvc") {
 852     CLParser parser;
 853     string output;
 854     if (!parser.Parse(result->output, deps_prefix, &output, err))
 855       return false;
 856     result->output = output;
 857     for (set<string>::iterator i = parser.includes_.begin();
 858          i != parser.includes_.end(); ++i) {
 859       // ~0 is assuming that with MSVC-parsed headers, it's ok to always make
 860       // all backslashes (as some of the slashes will certainly be backslashes
 861       // anyway). This could be fixed if necessary with some additional
 862       // complexity in IncludesNormalize::Relativize.
 863       deps_nodes->push_back(state_->GetNode(*i, ~0u));
 864     }
 865   } else
 866 #endif
 867   if (deps_type == "gcc") {
 868     string depfile = result->edge->GetUnescapedDepfile();
 869     if (depfile.empty()) {
 870       *err = string("edge with deps=gcc but no depfile makes no sense");
 871       return false;
 872     }
 873
 874     // Read depfile content.  Treat a missing depfile as empty.
 875     string content;
 876     switch (disk_interface_->ReadFile(depfile, &content, err)) {
 877     case DiskInterface::Okay:
 878       break;
 879     case DiskInterface::NotFound:
 880       err->clear();
 881       break;
 882     case DiskInterface::OtherError:
 883       return false;
 884     }
 885     if (content.empty())
 886       return true;
 887
 888     DepfileParser deps;
 889     if (!deps.Parse(&content, err))
 890       return false;
 891
 892     // XXX check depfile matches expected output.
 893     deps_nodes->reserve(deps.ins_.size());
 894     for (vector<StringPiece>::iterator i = deps.ins_.begin();
 895          i != deps.ins_.end(); ++i) {
 896       unsigned int slash_bits;
 897       if (!CanonicalizePath(const_cast<char*>(i->str_), &i->len_, &slash_bits,
 898                             err))
 899         return false;
 900       deps_nodes->push_back(state_->GetNode(*i, slash_bits));
 901     }
 902
 903     if (!g_keep_depfile) {
 904       if (disk_interface_->RemoveFile(depfile) < 0) {
 905         *err = string("deleting depfile: ") + strerror(errno) + string("\n");
 906         return false;
 907       }
 908     }
 909   } else {
 910     Fatal("unknown deps type '%s'", deps_type.c_str());
 911   }
 912
 913   return true;
 914 }