Ninja
build.cc
Go to the documentation of this file.
00001 // Copyright 2011 Google Inc. All Rights Reserved.
00002 //
00003 // Licensed under the Apache License, Version 2.0 (the "License");
00004 // you may not use this file except in compliance with the License.
00005 // You may obtain a copy of the License at
00006 //
00007 //     http://www.apache.org/licenses/LICENSE-2.0
00008 //
00009 // Unless required by applicable law or agreed to in writing, software
00010 // distributed under the License is distributed on an "AS IS" BASIS,
00011 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
00012 // See the License for the specific language governing permissions and
00013 // limitations under the License.
00014 
00015 #include "build.h"
00016 
00017 #include <assert.h>
00018 #include <errno.h>
00019 #include <stdio.h>
00020 #include <stdlib.h>
00021 #include <functional>
00022 
00023 #if defined(__SVR4) && defined(__sun)
00024 #include <sys/termios.h>
00025 #endif
00026 
00027 #include "build_log.h"
00028 #include "debug_flags.h"
00029 #include "depfile_parser.h"
00030 #include "deps_log.h"
00031 #include "disk_interface.h"
00032 #include "graph.h"
00033 #include "msvc_helper.h"
00034 #include "state.h"
00035 #include "subprocess.h"
00036 #include "util.h"
00037 
00038 namespace {
00039 
00040 /// A CommandRunner that doesn't actually run the commands.
00041 struct DryRunCommandRunner : public CommandRunner {
00042   virtual ~DryRunCommandRunner() {}
00043 
00044   // Overridden from CommandRunner:
00045   virtual bool CanRunMore();
00046   virtual bool StartCommand(Edge* edge);
00047   virtual bool WaitForCommand(Result* result);
00048 
00049  private:
00050   queue<Edge*> finished_;
00051 };
00052 
00053 bool DryRunCommandRunner::CanRunMore() {
00054   return true;
00055 }
00056 
00057 bool DryRunCommandRunner::StartCommand(Edge* edge) {
00058   finished_.push(edge);
00059   return true;
00060 }
00061 
00062 bool DryRunCommandRunner::WaitForCommand(Result* result) {
00063    if (finished_.empty())
00064      return false;
00065 
00066    result->status = ExitSuccess;
00067    result->edge = finished_.front();
00068    finished_.pop();
00069    return true;
00070 }
00071 
00072 }  // namespace
00073 
00074 BuildStatus::BuildStatus(const BuildConfig& config)
00075     : config_(config),
00076       start_time_millis_(GetTimeMillis()),
00077       started_edges_(0), finished_edges_(0), total_edges_(0),
00078       progress_status_format_(NULL),
00079       overall_rate_(), current_rate_(config.parallelism) {
00080 
00081   // Don't do anything fancy in verbose mode.
00082   if (config_.verbosity != BuildConfig::NORMAL)
00083     printer_.set_smart_terminal(false);
00084 
00085   progress_status_format_ = getenv("NINJA_STATUS");
00086   if (!progress_status_format_)
00087     progress_status_format_ = "[%s/%t] ";
00088 }
00089 
00090 void BuildStatus::PlanHasTotalEdges(int total) {
00091   total_edges_ = total;
00092 }
00093 
00094 void BuildStatus::BuildEdgeStarted(Edge* edge) {
00095   int start_time = (int)(GetTimeMillis() - start_time_millis_);
00096   running_edges_.insert(make_pair(edge, start_time));
00097   ++started_edges_;
00098 
00099   PrintStatus(edge);
00100 
00101   if (edge->use_console())
00102     printer_.SetConsoleLocked(true);
00103 }
00104 
00105 void BuildStatus::BuildEdgeFinished(Edge* edge,
00106                                     bool success,
00107                                     const string& output,
00108                                     int* start_time,
00109                                     int* end_time) {
00110   int64_t now = GetTimeMillis();
00111   ++finished_edges_;
00112 
00113   RunningEdgeMap::iterator i = running_edges_.find(edge);
00114   *start_time = i->second;
00115   *end_time = (int)(now - start_time_millis_);
00116   running_edges_.erase(i);
00117 
00118   if (edge->use_console())
00119     printer_.SetConsoleLocked(false);
00120 
00121   if (config_.verbosity == BuildConfig::QUIET)
00122     return;
00123 
00124   if (!edge->use_console() && printer_.is_smart_terminal())
00125     PrintStatus(edge);
00126 
00127   // Print the command that is spewing before printing its output.
00128   if (!success)
00129     printer_.PrintOnNewLine("FAILED: " + edge->EvaluateCommand() + "\n");
00130 
00131   if (!output.empty()) {
00132     // ninja sets stdout and stderr of subprocesses to a pipe, to be able to
00133     // check if the output is empty. Some compilers, e.g. clang, check
00134     // isatty(stderr) to decide if they should print colored output.
00135     // To make it possible to use colored output with ninja, subprocesses should
00136     // be run with a flag that forces them to always print color escape codes.
00137     // To make sure these escape codes don't show up in a file if ninja's output
00138     // is piped to a file, ninja strips ansi escape codes again if it's not
00139     // writing to a |smart_terminal_|.
00140     // (Launching subprocesses in pseudo ttys doesn't work because there are
00141     // only a few hundred available on some systems, and ninja can launch
00142     // thousands of parallel compile commands.)
00143     // TODO: There should be a flag to disable escape code stripping.
00144     string final_output;
00145     if (!printer_.is_smart_terminal())
00146       final_output = StripAnsiEscapeCodes(output);
00147     else
00148       final_output = output;
00149     printer_.PrintOnNewLine(final_output);
00150   }
00151 }
00152 
00153 void BuildStatus::BuildFinished() {
00154   printer_.SetConsoleLocked(false);
00155   printer_.PrintOnNewLine("");
00156 }
00157 
00158 string BuildStatus::FormatProgressStatus(
00159     const char* progress_status_format) const {
00160   string out;
00161   char buf[32];
00162   int percent;
00163   for (const char* s = progress_status_format; *s != '\0'; ++s) {
00164     if (*s == '%') {
00165       ++s;
00166       switch (*s) {
00167       case '%':
00168         out.push_back('%');
00169         break;
00170 
00171         // Started edges.
00172       case 's':
00173         snprintf(buf, sizeof(buf), "%d", started_edges_);
00174         out += buf;
00175         break;
00176 
00177         // Total edges.
00178       case 't':
00179         snprintf(buf, sizeof(buf), "%d", total_edges_);
00180         out += buf;
00181         break;
00182 
00183         // Running edges.
00184       case 'r':
00185         snprintf(buf, sizeof(buf), "%d", started_edges_ - finished_edges_);
00186         out += buf;
00187         break;
00188 
00189         // Unstarted edges.
00190       case 'u':
00191         snprintf(buf, sizeof(buf), "%d", total_edges_ - started_edges_);
00192         out += buf;
00193         break;
00194 
00195         // Finished edges.
00196       case 'f':
00197         snprintf(buf, sizeof(buf), "%d", finished_edges_);
00198         out += buf;
00199         break;
00200 
00201         // Overall finished edges per second.
00202       case 'o':
00203         overall_rate_.UpdateRate(finished_edges_);
00204         snprinfRate(overall_rate_.rate(), buf, "%.1f");
00205         out += buf;
00206         break;
00207 
00208         // Current rate, average over the last '-j' jobs.
00209       case 'c':
00210         current_rate_.UpdateRate(finished_edges_);
00211         snprinfRate(current_rate_.rate(), buf, "%.1f");
00212         out += buf;
00213         break;
00214 
00215         // Percentage
00216       case 'p':
00217         percent = (100 * started_edges_) / total_edges_;
00218         snprintf(buf, sizeof(buf), "%3i%%", percent);
00219         out += buf;
00220         break;
00221 
00222       case 'e': {
00223         double elapsed = overall_rate_.Elapsed();
00224         snprintf(buf, sizeof(buf), "%.3f", elapsed);
00225         out += buf;
00226         break;
00227       }
00228 
00229       default:
00230         Fatal("unknown placeholder '%%%c' in $NINJA_STATUS", *s);
00231         return "";
00232       }
00233     } else {
00234       out.push_back(*s);
00235     }
00236   }
00237 
00238   return out;
00239 }
00240 
00241 void BuildStatus::PrintStatus(Edge* edge) {
00242   if (config_.verbosity == BuildConfig::QUIET)
00243     return;
00244 
00245   bool force_full_command = config_.verbosity == BuildConfig::VERBOSE;
00246 
00247   string to_print = edge->GetBinding("description");
00248   if (to_print.empty() || force_full_command)
00249     to_print = edge->GetBinding("command");
00250 
00251   if (finished_edges_ == 0) {
00252     overall_rate_.Restart();
00253     current_rate_.Restart();
00254   }
00255   to_print = FormatProgressStatus(progress_status_format_) + to_print;
00256 
00257   printer_.Print(to_print,
00258                  force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE);
00259 }
00260 
00261 Plan::Plan() : command_edges_(0), wanted_edges_(0) {}
00262 
00263 bool Plan::AddTarget(Node* node, string* err) {
00264   vector<Node*> stack;
00265   return AddSubTarget(node, &stack, err);
00266 }
00267 
00268 bool Plan::AddSubTarget(Node* node, vector<Node*>* stack, string* err) {
00269   Edge* edge = node->in_edge();
00270   if (!edge) {  // Leaf node.
00271     if (node->dirty()) {
00272       string referenced;
00273       if (!stack->empty())
00274         referenced = ", needed by '" + stack->back()->path() + "',";
00275       *err = "'" + node->path() + "'" + referenced + " missing "
00276              "and no known rule to make it";
00277     }
00278     return false;
00279   }
00280 
00281   if (CheckDependencyCycle(node, stack, err))
00282     return false;
00283 
00284   if (edge->outputs_ready())
00285     return false;  // Don't need to do anything.
00286 
00287   // If an entry in want_ does not already exist for edge, create an entry which
00288   // maps to false, indicating that we do not want to build this entry itself.
00289   pair<map<Edge*, bool>::iterator, bool> want_ins =
00290     want_.insert(make_pair(edge, false));
00291   bool& want = want_ins.first->second;
00292 
00293   // If we do need to build edge and we haven't already marked it as wanted,
00294   // mark it now.
00295   if (node->dirty() && !want) {
00296     want = true;
00297     ++wanted_edges_;
00298     if (edge->AllInputsReady())
00299       ScheduleWork(edge);
00300     if (!edge->is_phony())
00301       ++command_edges_;
00302   }
00303 
00304   if (!want_ins.second)
00305     return true;  // We've already processed the inputs.
00306 
00307   stack->push_back(node);
00308   for (vector<Node*>::iterator i = edge->inputs_.begin();
00309        i != edge->inputs_.end(); ++i) {
00310     if (!AddSubTarget(*i, stack, err) && !err->empty())
00311       return false;
00312   }
00313   assert(stack->back() == node);
00314   stack->pop_back();
00315 
00316   return true;
00317 }
00318 
00319 bool Plan::CheckDependencyCycle(Node* node, vector<Node*>* stack, string* err) {
00320   vector<Node*>::reverse_iterator ri =
00321       find(stack->rbegin(), stack->rend(), node);
00322   if (ri == stack->rend())
00323     return false;
00324 
00325   // Add this node onto the stack to make it clearer where the loop
00326   // is.
00327   stack->push_back(node);
00328 
00329   vector<Node*>::iterator start = find(stack->begin(), stack->end(), node);
00330   *err = "dependency cycle: ";
00331   for (vector<Node*>::iterator i = start; i != stack->end(); ++i) {
00332     if (i != start)
00333       err->append(" -> ");
00334     err->append((*i)->path());
00335   }
00336   return true;
00337 }
00338 
00339 Edge* Plan::FindWork() {
00340   if (ready_.empty())
00341     return NULL;
00342   set<Edge*>::iterator i = ready_.begin();
00343   Edge* edge = *i;
00344   ready_.erase(i);
00345   return edge;
00346 }
00347 
00348 void Plan::ScheduleWork(Edge* edge) {
00349   Pool* pool = edge->pool();
00350   if (pool->ShouldDelayEdge()) {
00351     // The graph is not completely clean. Some Nodes have duplicate Out edges.
00352     // We need to explicitly ignore these here, otherwise their work will get
00353     // scheduled twice (see https://github.com/martine/ninja/pull/519)
00354     if (ready_.count(edge)) {
00355       return;
00356     }
00357     pool->DelayEdge(edge);
00358     pool->RetrieveReadyEdges(&ready_);
00359   } else {
00360     pool->EdgeScheduled(*edge);
00361     ready_.insert(edge);
00362   }
00363 }
00364 
00365 void Plan::ResumeDelayedJobs(Edge* edge) {
00366   edge->pool()->EdgeFinished(*edge);
00367   edge->pool()->RetrieveReadyEdges(&ready_);
00368 }
00369 
00370 void Plan::EdgeFinished(Edge* edge) {
00371   map<Edge*, bool>::iterator i = want_.find(edge);
00372   assert(i != want_.end());
00373   if (i->second)
00374     --wanted_edges_;
00375   want_.erase(i);
00376   edge->outputs_ready_ = true;
00377 
00378   // See if this job frees up any delayed jobs
00379   ResumeDelayedJobs(edge);
00380 
00381   // Check off any nodes we were waiting for with this edge.
00382   for (vector<Node*>::iterator i = edge->outputs_.begin();
00383        i != edge->outputs_.end(); ++i) {
00384     NodeFinished(*i);
00385   }
00386 }
00387 
00388 void Plan::NodeFinished(Node* node) {
00389   // See if we we want any edges from this node.
00390   for (vector<Edge*>::const_iterator i = node->out_edges().begin();
00391        i != node->out_edges().end(); ++i) {
00392     map<Edge*, bool>::iterator want_i = want_.find(*i);
00393     if (want_i == want_.end())
00394       continue;
00395 
00396     // See if the edge is now ready.
00397     if ((*i)->AllInputsReady()) {
00398       if (want_i->second) {
00399         ScheduleWork(*i);
00400       } else {
00401         // We do not need to build this edge, but we might need to build one of
00402         // its dependents.
00403         EdgeFinished(*i);
00404       }
00405     }
00406   }
00407 }
00408 
00409 void Plan::CleanNode(DependencyScan* scan, Node* node) {
00410   node->set_dirty(false);
00411 
00412   for (vector<Edge*>::const_iterator ei = node->out_edges().begin();
00413        ei != node->out_edges().end(); ++ei) {
00414     // Don't process edges that we don't actually want.
00415     map<Edge*, bool>::iterator want_i = want_.find(*ei);
00416     if (want_i == want_.end() || !want_i->second)
00417       continue;
00418 
00419     // Don't attempt to clean an edge if it failed to load deps.
00420     if ((*ei)->deps_missing_)
00421       continue;
00422 
00423     // If all non-order-only inputs for this edge are now clean,
00424     // we might have changed the dirty state of the outputs.
00425     vector<Node*>::iterator
00426         begin = (*ei)->inputs_.begin(),
00427         end = (*ei)->inputs_.end() - (*ei)->order_only_deps_;
00428     if (find_if(begin, end, mem_fun(&Node::dirty)) == end) {
00429       // Recompute most_recent_input.
00430       Node* most_recent_input = NULL;
00431       for (vector<Node*>::iterator ni = begin; ni != end; ++ni) {
00432         if (!most_recent_input || (*ni)->mtime() > most_recent_input->mtime())
00433           most_recent_input = *ni;
00434       }
00435 
00436       // Now, this edge is dirty if any of the outputs are dirty.
00437       // If the edge isn't dirty, clean the outputs and mark the edge as not
00438       // wanted.
00439       if (!scan->RecomputeOutputsDirty(*ei, most_recent_input)) {
00440         for (vector<Node*>::iterator ni = (*ei)->outputs_.begin();
00441              ni != (*ei)->outputs_.end(); ++ni) {
00442           CleanNode(scan, *ni);
00443         }
00444 
00445         want_i->second = false;
00446         --wanted_edges_;
00447         if (!(*ei)->is_phony())
00448           --command_edges_;
00449       }
00450     }
00451   }
00452 }
00453 
00454 void Plan::Dump() {
00455   printf("pending: %d\n", (int)want_.size());
00456   for (map<Edge*, bool>::iterator i = want_.begin(); i != want_.end(); ++i) {
00457     if (i->second)
00458       printf("want ");
00459     i->first->Dump();
00460   }
00461   printf("ready: %d\n", (int)ready_.size());
00462 }
00463 
00464 struct RealCommandRunner : public CommandRunner {
00465   explicit RealCommandRunner(const BuildConfig& config) : config_(config) {}
00466   virtual ~RealCommandRunner() {}
00467   virtual bool CanRunMore();
00468   virtual bool StartCommand(Edge* edge);
00469   virtual bool WaitForCommand(Result* result);
00470   virtual vector<Edge*> GetActiveEdges();
00471   virtual void Abort();
00472 
00473   const BuildConfig& config_;
00474   SubprocessSet subprocs_;
00475   map<Subprocess*, Edge*> subproc_to_edge_;
00476 };
00477 
00478 vector<Edge*> RealCommandRunner::GetActiveEdges() {
00479   vector<Edge*> edges;
00480   for (map<Subprocess*, Edge*>::iterator i = subproc_to_edge_.begin();
00481        i != subproc_to_edge_.end(); ++i)
00482     edges.push_back(i->second);
00483   return edges;
00484 }
00485 
00486 void RealCommandRunner::Abort() {
00487   subprocs_.Clear();
00488 }
00489 
00490 bool RealCommandRunner::CanRunMore() {
00491   return ((int)subprocs_.running_.size()) < config_.parallelism
00492     && ((subprocs_.running_.empty() || config_.max_load_average <= 0.0f)
00493         || GetLoadAverage() < config_.max_load_average);
00494 }
00495 
00496 bool RealCommandRunner::StartCommand(Edge* edge) {
00497   string command = edge->EvaluateCommand();
00498   Subprocess* subproc = subprocs_.Add(command, edge->use_console());
00499   if (!subproc)
00500     return false;
00501   subproc_to_edge_.insert(make_pair(subproc, edge));
00502 
00503   return true;
00504 }
00505 
00506 bool RealCommandRunner::WaitForCommand(Result* result) {
00507   Subprocess* subproc;
00508   while ((subproc = subprocs_.NextFinished()) == NULL) {
00509     bool interrupted = subprocs_.DoWork();
00510     if (interrupted)
00511       return false;
00512   }
00513 
00514   result->status = subproc->Finish();
00515   result->output = subproc->GetOutput();
00516 
00517   map<Subprocess*, Edge*>::iterator i = subproc_to_edge_.find(subproc);
00518   result->edge = i->second;
00519   subproc_to_edge_.erase(i);
00520 
00521   delete subproc;
00522   return true;
00523 }
00524 
00525 Builder::Builder(State* state, const BuildConfig& config,
00526                  BuildLog* build_log, DepsLog* deps_log,
00527                  DiskInterface* disk_interface)
00528     : state_(state), config_(config), disk_interface_(disk_interface),
00529       scan_(state, build_log, deps_log, disk_interface) {
00530   status_ = new BuildStatus(config);
00531 }
00532 
00533 Builder::~Builder() {
00534   Cleanup();
00535 }
00536 
00537 void Builder::Cleanup() {
00538   if (command_runner_.get()) {
00539     vector<Edge*> active_edges = command_runner_->GetActiveEdges();
00540     command_runner_->Abort();
00541 
00542     for (vector<Edge*>::iterator i = active_edges.begin();
00543          i != active_edges.end(); ++i) {
00544       string depfile = (*i)->GetUnescapedDepfile();
00545       for (vector<Node*>::iterator ni = (*i)->outputs_.begin();
00546            ni != (*i)->outputs_.end(); ++ni) {
00547         // Only delete this output if it was actually modified.  This is
00548         // important for things like the generator where we don't want to
00549         // delete the manifest file if we can avoid it.  But if the rule
00550         // uses a depfile, always delete.  (Consider the case where we
00551         // need to rebuild an output because of a modified header file
00552         // mentioned in a depfile, and the command touches its depfile
00553         // but is interrupted before it touches its output file.)
00554         if (!depfile.empty() ||
00555             (*ni)->mtime() != disk_interface_->Stat((*ni)->path())) {
00556           disk_interface_->RemoveFile((*ni)->path());
00557         }
00558       }
00559       if (!depfile.empty())
00560         disk_interface_->RemoveFile(depfile);
00561     }
00562   }
00563 }
00564 
00565 Node* Builder::AddTarget(const string& name, string* err) {
00566   Node* node = state_->LookupNode(name);
00567   if (!node) {
00568     *err = "unknown target: '" + name + "'";
00569     return NULL;
00570   }
00571   if (!AddTarget(node, err))
00572     return NULL;
00573   return node;
00574 }
00575 
00576 bool Builder::AddTarget(Node* node, string* err) {
00577   node->StatIfNecessary(disk_interface_);
00578   if (Edge* in_edge = node->in_edge()) {
00579     if (!scan_.RecomputeDirty(in_edge, err))
00580       return false;
00581     if (in_edge->outputs_ready())
00582       return true;  // Nothing to do.
00583   }
00584 
00585   if (!plan_.AddTarget(node, err))
00586     return false;
00587 
00588   return true;
00589 }
00590 
00591 bool Builder::AlreadyUpToDate() const {
00592   return !plan_.more_to_do();
00593 }
00594 
00595 bool Builder::Build(string* err) {
00596   assert(!AlreadyUpToDate());
00597 
00598   status_->PlanHasTotalEdges(plan_.command_edge_count());
00599   int pending_commands = 0;
00600   int failures_allowed = config_.failures_allowed;
00601 
00602   // Set up the command runner if we haven't done so already.
00603   if (!command_runner_.get()) {
00604     if (config_.dry_run)
00605       command_runner_.reset(new DryRunCommandRunner);
00606     else
00607       command_runner_.reset(new RealCommandRunner(config_));
00608   }
00609 
00610   // This main loop runs the entire build process.
00611   // It is structured like this:
00612   // First, we attempt to start as many commands as allowed by the
00613   // command runner.
00614   // Second, we attempt to wait for / reap the next finished command.
00615   while (plan_.more_to_do()) {
00616     // See if we can start any more commands.
00617     if (failures_allowed && command_runner_->CanRunMore()) {
00618       if (Edge* edge = plan_.FindWork()) {
00619         if (!StartEdge(edge, err)) {
00620           Cleanup();
00621           status_->BuildFinished();
00622           return false;
00623         }
00624 
00625         if (edge->is_phony()) {
00626           plan_.EdgeFinished(edge);
00627         } else {
00628           ++pending_commands;
00629         }
00630 
00631         // We made some progress; go back to the main loop.
00632         continue;
00633       }
00634     }
00635 
00636     // See if we can reap any finished commands.
00637     if (pending_commands) {
00638       CommandRunner::Result result;
00639       if (!command_runner_->WaitForCommand(&result) ||
00640           result.status == ExitInterrupted) {
00641         Cleanup();
00642         status_->BuildFinished();
00643         *err = "interrupted by user";
00644         return false;
00645       }
00646 
00647       --pending_commands;
00648       if (!FinishCommand(&result, err)) {
00649         Cleanup();
00650         status_->BuildFinished();
00651         return false;
00652       }
00653 
00654       if (!result.success()) {
00655         if (failures_allowed)
00656           failures_allowed--;
00657       }
00658 
00659       // We made some progress; start the main loop over.
00660       continue;
00661     }
00662 
00663     // If we get here, we cannot make any more progress.
00664     status_->BuildFinished();
00665     if (failures_allowed == 0) {
00666       if (config_.failures_allowed > 1)
00667         *err = "subcommands failed";
00668       else
00669         *err = "subcommand failed";
00670     } else if (failures_allowed < config_.failures_allowed)
00671       *err = "cannot make progress due to previous errors";
00672     else
00673       *err = "stuck [this is a bug]";
00674 
00675     return false;
00676   }
00677 
00678   status_->BuildFinished();
00679   return true;
00680 }
00681 
00682 bool Builder::StartEdge(Edge* edge, string* err) {
00683   METRIC_RECORD("StartEdge");
00684   if (edge->is_phony())
00685     return true;
00686 
00687   status_->BuildEdgeStarted(edge);
00688 
00689   // Create directories necessary for outputs.
00690   // XXX: this will block; do we care?
00691   for (vector<Node*>::iterator i = edge->outputs_.begin();
00692        i != edge->outputs_.end(); ++i) {
00693     if (!disk_interface_->MakeDirs((*i)->path()))
00694       return false;
00695   }
00696 
00697   // Create response file, if needed
00698   // XXX: this may also block; do we care?
00699   string rspfile = edge->GetUnescapedRspfile();
00700   if (!rspfile.empty()) {
00701     string content = edge->GetBinding("rspfile_content");
00702     if (!disk_interface_->WriteFile(rspfile, content))
00703       return false;
00704   }
00705 
00706   // start command computing and run it
00707   if (!command_runner_->StartCommand(edge)) {
00708     err->assign("command '" + edge->EvaluateCommand() + "' failed.");
00709     return false;
00710   }
00711 
00712   return true;
00713 }
00714 
00715 bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
00716   METRIC_RECORD("FinishCommand");
00717 
00718   Edge* edge = result->edge;
00719 
00720   // First try to extract dependencies from the result, if any.
00721   // This must happen first as it filters the command output (we want
00722   // to filter /showIncludes output, even on compile failure) and
00723   // extraction itself can fail, which makes the command fail from a
00724   // build perspective.
00725   vector<Node*> deps_nodes;
00726   string deps_type = edge->GetBinding("deps");
00727   const string deps_prefix = edge->GetBinding("msvc_deps_prefix");
00728   if (!deps_type.empty()) {
00729     string extract_err;
00730     if (!ExtractDeps(result, deps_type, deps_prefix, &deps_nodes,
00731                      &extract_err) &&
00732         result->success()) {
00733       if (!result->output.empty())
00734         result->output.append("\n");
00735       result->output.append(extract_err);
00736       result->status = ExitFailure;
00737     }
00738   }
00739 
00740   int start_time, end_time;
00741   status_->BuildEdgeFinished(edge, result->success(), result->output,
00742                              &start_time, &end_time);
00743 
00744   // The rest of this function only applies to successful commands.
00745   if (!result->success())
00746     return true;
00747 
00748   // Restat the edge outputs, if necessary.
00749   TimeStamp restat_mtime = 0;
00750   if (edge->GetBindingBool("restat") && !config_.dry_run) {
00751     bool node_cleaned = false;
00752 
00753     for (vector<Node*>::iterator i = edge->outputs_.begin();
00754          i != edge->outputs_.end(); ++i) {
00755       TimeStamp new_mtime = disk_interface_->Stat((*i)->path());
00756       if ((*i)->mtime() == new_mtime) {
00757         // The rule command did not change the output.  Propagate the clean
00758         // state through the build graph.
00759         // Note that this also applies to nonexistent outputs (mtime == 0).
00760         plan_.CleanNode(&scan_, *i);
00761         node_cleaned = true;
00762       }
00763     }
00764 
00765     if (node_cleaned) {
00766       // If any output was cleaned, find the most recent mtime of any
00767       // (existing) non-order-only input or the depfile.
00768       for (vector<Node*>::iterator i = edge->inputs_.begin();
00769            i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
00770         TimeStamp input_mtime = disk_interface_->Stat((*i)->path());
00771         if (input_mtime > restat_mtime)
00772           restat_mtime = input_mtime;
00773       }
00774 
00775       string depfile = edge->GetUnescapedDepfile();
00776       if (restat_mtime != 0 && deps_type.empty() && !depfile.empty()) {
00777         TimeStamp depfile_mtime = disk_interface_->Stat(depfile);
00778         if (depfile_mtime > restat_mtime)
00779           restat_mtime = depfile_mtime;
00780       }
00781 
00782       // The total number of edges in the plan may have changed as a result
00783       // of a restat.
00784       status_->PlanHasTotalEdges(plan_.command_edge_count());
00785     }
00786   }
00787 
00788   plan_.EdgeFinished(edge);
00789 
00790   // Delete any left over response file.
00791   string rspfile = edge->GetUnescapedRspfile();
00792   if (!rspfile.empty() && !g_keep_rsp)
00793     disk_interface_->RemoveFile(rspfile);
00794 
00795   if (scan_.build_log()) {
00796     if (!scan_.build_log()->RecordCommand(edge, start_time, end_time,
00797                                           restat_mtime)) {
00798       *err = string("Error writing to build log: ") + strerror(errno);
00799       return false;
00800     }
00801   }
00802 
00803   if (!deps_type.empty() && !config_.dry_run) {
00804     assert(edge->outputs_.size() == 1 && "should have been rejected by parser");
00805     Node* out = edge->outputs_[0];
00806     TimeStamp deps_mtime = disk_interface_->Stat(out->path());
00807     if (!scan_.deps_log()->RecordDeps(out, deps_mtime, deps_nodes)) {
00808       *err = string("Error writing to deps log: ") + strerror(errno);
00809       return false;
00810     }
00811   }
00812   return true;
00813 }
00814 
00815 bool Builder::ExtractDeps(CommandRunner::Result* result,
00816                           const string& deps_type,
00817                           const string& deps_prefix,
00818                           vector<Node*>* deps_nodes,
00819                           string* err) {
00820 #ifdef _WIN32
00821   if (deps_type == "msvc") {
00822     CLParser parser;
00823     result->output = parser.Parse(result->output, deps_prefix);
00824     for (set<string>::iterator i = parser.includes_.begin();
00825          i != parser.includes_.end(); ++i) {
00826       deps_nodes->push_back(state_->GetNode(*i));
00827     }
00828   } else
00829 #endif
00830   if (deps_type == "gcc") {
00831     string depfile = result->edge->GetUnescapedDepfile();
00832     if (depfile.empty()) {
00833       *err = string("edge with deps=gcc but no depfile makes no sense");
00834       return false;
00835     }
00836 
00837     string content = disk_interface_->ReadFile(depfile, err);
00838     if (!err->empty())
00839       return false;
00840     if (content.empty())
00841       return true;
00842 
00843     DepfileParser deps;
00844     if (!deps.Parse(&content, err))
00845       return false;
00846 
00847     // XXX check depfile matches expected output.
00848     deps_nodes->reserve(deps.ins_.size());
00849     for (vector<StringPiece>::iterator i = deps.ins_.begin();
00850          i != deps.ins_.end(); ++i) {
00851       if (!CanonicalizePath(const_cast<char*>(i->str_), &i->len_, err))
00852         return false;
00853       deps_nodes->push_back(state_->GetNode(*i));
00854     }
00855 
00856     if (disk_interface_->RemoveFile(depfile) < 0) {
00857       *err = string("deleting depfile: ") + strerror(errno) + string("\n");
00858       return false;
00859     }
00860   } else {
00861     Fatal("unknown deps type '%s'", deps_type.c_str());
00862   }
00863 
00864   return true;
00865 }