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