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