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 <stdio.h>
  19
  20 #ifdef _WIN32
  21 #include <windows.h>
  22 #else
  23 #include <sys/ioctl.h>
  24 #include <sys/time.h>
  25 #include <sys/termios.h>
  26 #endif
  27
  28 #include "build_log.h"
  29 #include "disk_interface.h"
  30 #include "graph.h"
  31 #include "state.h"
  32 #include "subprocess.h"
  33 #include "util.h"
  34
  35 /// Tracks the status of a build: completion fraction, printing updates.
  36 struct BuildStatus {
  37   BuildStatus(const BuildConfig& config);
  38   void PlanHasTotalEdges(int total);
  39   void BuildEdgeStarted(Edge* edge);
  40   void BuildEdgeFinished(Edge* edge, bool success, const string& output,
  41                          int* start_time, int* end_time);
  42
  43  private:
  44   void PrintStatus(Edge* edge);
  45
  46   const BuildConfig& config_;
  47
  48   /// Time the build started.
  49   int64_t start_time_millis_;
  50   /// Time we last printed an update.
  51   int64_t last_update_millis_;
  52
  53   int started_edges_, finished_edges_, total_edges_;
  54
  55   /// Map of running edge to time the edge started running.
  56   typedef map<Edge*, int> RunningEdgeMap;
  57   RunningEdgeMap running_edges_;
  58
  59   /// Whether we can do fancy terminal control codes.
  60   bool smart_terminal_;
  61 };
  62
  63 BuildStatus::BuildStatus(const BuildConfig& config)
  64     : config_(config),
  65       start_time_millis_(GetTimeMillis()),
  66       last_update_millis_(start_time_millis_),
  67       started_edges_(0), finished_edges_(0), total_edges_(0) {
  68 #ifndef WIN32
  69   const char* term = getenv("TERM");
  70   smart_terminal_ = isatty(1) && term && string(term) != "dumb";
  71 #else
  72   smart_terminal_ = false;
  73   // Disable output buffer.  It'd be nice to use line buffering but
  74   // MSDN says: "For some systems, [_IOLBF] provides line
  75   // buffering. However, for Win32, the behavior is the same as _IOFBF
  76   // - Full Buffering."
  77   setvbuf(stdout, NULL, _IONBF, 0);
  78 #endif
  79
  80   // Don't do anything fancy in verbose mode.
  81   if (config_.verbosity != BuildConfig::NORMAL)
  82     smart_terminal_ = false;
  83 }
  84
  85 void BuildStatus::PlanHasTotalEdges(int total) {
  86   total_edges_ = total;
  87 }
  88
  89 void BuildStatus::BuildEdgeStarted(Edge* edge) {
  90   int start_time = (int)(GetTimeMillis() - start_time_millis_);
  91   running_edges_.insert(make_pair(edge, start_time));
  92   ++started_edges_;
  93
  94   PrintStatus(edge);
  95 }
  96
  97 void BuildStatus::BuildEdgeFinished(Edge* edge,
  98                                     bool success,
  99                                     const string& output,
 100                                     int* start_time,
 101                                     int* end_time) {
 102   int64_t now = GetTimeMillis();
 103   ++finished_edges_;
 104
 105   RunningEdgeMap::iterator i = running_edges_.find(edge);
 106   *start_time = i->second;
 107   *end_time = (int)(now - start_time_millis_);
 108   int total_time = end_time - start_time;
 109   running_edges_.erase(i);
 110
 111   if (config_.verbosity == BuildConfig::QUIET)
 112     return;
 113
 114   if (smart_terminal_)
 115     PrintStatus(edge);
 116
 117   if (success && output.empty()) {
 118     if (smart_terminal_) {
 119       if (finished_edges_ == total_edges_)
 120         printf("\n");
 121     } else {
 122       if (total_time > 5*1000) {
 123         printf("%.1f%% %d/%d\n", finished_edges_ * 100 / (float)total_edges_,
 124                finished_edges_, total_edges_);
 125         last_update_millis_ = now;
 126       }
 127     }
 128   } else {
 129     if (smart_terminal_)
 130       printf("\n");
 131
 132     // Print the command that is spewing before printing its output.
 133     if (!success)
 134       printf("FAILED: %s\n", edge->EvaluateCommand().c_str());
 135
 136     // ninja sets stdout and stderr of subprocesses to a pipe, to be able to
 137     // check if the output is empty. Some compilers, e.g. clang, check
 138     // isatty(stderr) to decide if they should print colored output.
 139     // To make it possible to use colored output with ninja, subprocesses should
 140     // be run with a flag that forces them to always print color escape codes.
 141     // To make sure these escape codes don't show up in a file if ninja's output
 142     // is piped to a file, ninja strips ansi escape codes again if it's not
 143     // writing to a |smart_terminal_|.
 144     // (Launching subprocesses in pseudo ttys doesn't work because there are
 145     // only a few hundred available on some systems, and ninja can launch
 146     // thousands of parallel compile commands.)
 147     // TODO: There should be a flag to disable escape code stripping.
 148     string final_output;
 149     if (!smart_terminal_)
 150       final_output = StripAnsiEscapeCodes(output);
 151     else
 152       final_output = output;
 153
 154     if (!final_output.empty())
 155       printf("%s", final_output.c_str());
 156   }
 157 }
 158
 159 void BuildStatus::PrintStatus(Edge* edge) {
 160   if (config_.verbosity == BuildConfig::QUIET)
 161     return;
 162
 163   bool force_full_command = config_.verbosity == BuildConfig::VERBOSE;
 164
 165   string to_print = edge->GetDescription();
 166   if (to_print.empty() || force_full_command)
 167     to_print = edge->EvaluateCommand();
 168
 169   if (smart_terminal_)
 170     printf("\r");  // Print over previous line, if any.
 171
 172   int progress_chars = printf("[%d/%d] ", started_edges_, total_edges_);
 173
 174 #ifndef WIN32
 175   if (smart_terminal_ && !force_full_command) {
 176     // Limit output to width of the terminal if provided so we don't cause
 177     // line-wrapping.
 178     winsize size;
 179     if ((ioctl(0, TIOCGWINSZ, &size) == 0) && size.ws_col) {
 180       const int kMargin = progress_chars + 3;  // Space for [xx/yy] and "...".
 181       if (to_print.size() + kMargin > size.ws_col) {
 182         int elide_size = (size.ws_col - kMargin) / 2;
 183         to_print = to_print.substr(0, elide_size)
 184           + "..."
 185           + to_print.substr(to_print.size() - elide_size, elide_size);
 186       }
 187     }
 188   }
 189 #else
 190   NINJA_UNUSED_ARG(progress_chars);
 191 #endif
 192
 193   printf("%s", to_print.c_str());
 194
 195   if (smart_terminal_ && !force_full_command) {
 196     printf("\x1B[K");  // Clear to end of line.
 197     fflush(stdout);
 198   } else {
 199     printf("\n");
 200   }
 201 }
 202
 203 Plan::Plan() : command_edges_(0), wanted_edges_(0) {}
 204
 205 bool Plan::AddTarget(Node* node, string* err) {
 206   vector<Node*> stack;
 207   return AddSubTarget(node, &stack, err);
 208 }
 209
 210 bool Plan::AddSubTarget(Node* node, vector<Node*>* stack, string* err) {
 211   Edge* edge = node->in_edge();
 212   if (!edge) {  // Leaf node.
 213     if (node->dirty()) {
 214       string referenced;
 215       if (!stack->empty())
 216         referenced = ", needed by '" + stack->back()->path() + "',";
 217       *err = "'" + node->path() + "'" + referenced + " missing "
 218              "and no known rule to make it";
 219     }
 220     return false;
 221   }
 222
 223   if (CheckDependencyCycle(node, stack, err))
 224     return false;
 225
 226   if (edge->outputs_ready())
 227     return false;  // Don't need to do anything.
 228
 229   // If an entry in want_ does not already exist for edge, create an entry which
 230   // maps to false, indicating that we do not want to build this entry itself.
 231   pair<map<Edge*, bool>::iterator, bool> want_ins =
 232     want_.insert(make_pair(edge, false));
 233   bool& want = want_ins.first->second;
 234
 235   // If we do need to build edge and we haven't already marked it as wanted,
 236   // mark it now.
 237   if (node->dirty() && !want) {
 238     want = true;
 239     ++wanted_edges_;
 240     if (edge->AllInputsReady())
 241       ready_.insert(edge);
 242     if (!edge->is_phony())
 243       ++command_edges_;
 244   }
 245
 246   if (!want_ins.second)
 247     return true;  // We've already processed the inputs.
 248
 249   stack->push_back(node);
 250   for (vector<Node*>::iterator i = edge->inputs_.begin();
 251        i != edge->inputs_.end(); ++i) {
 252     if (!AddSubTarget(*i, stack, err) && !err->empty())
 253       return false;
 254   }
 255   assert(stack->back() == node);
 256   stack->pop_back();
 257
 258   return true;
 259 }
 260
 261 bool Plan::CheckDependencyCycle(Node* node, vector<Node*>* stack, string* err) {
 262   vector<Node*>::reverse_iterator ri =
 263       find(stack->rbegin(), stack->rend(), node);
 264   if (ri == stack->rend())
 265     return false;
 266
 267   // Add this node onto the stack to make it clearer where the loop
 268   // is.
 269   stack->push_back(node);
 270
 271   vector<Node*>::iterator start = find(stack->begin(), stack->end(), node);
 272   *err = "dependency cycle: ";
 273   for (vector<Node*>::iterator i = start; i != stack->end(); ++i) {
 274     if (i != start)
 275       err->append(" -> ");
 276     err->append((*i)->path());
 277   }
 278   return true;
 279 }
 280
 281 Edge* Plan::FindWork() {
 282   if (ready_.empty())
 283     return NULL;
 284   set<Edge*>::iterator i = ready_.begin();
 285   Edge* edge = *i;
 286   ready_.erase(i);
 287   return edge;
 288 }
 289
 290 void Plan::EdgeFinished(Edge* edge) {
 291   map<Edge*, bool>::iterator i = want_.find(edge);
 292   assert(i != want_.end());
 293   if (i->second)
 294     --wanted_edges_;
 295   want_.erase(i);
 296   edge->outputs_ready_ = true;
 297
 298   // Check off any nodes we were waiting for with this edge.
 299   for (vector<Node*>::iterator i = edge->outputs_.begin();
 300        i != edge->outputs_.end(); ++i) {
 301     NodeFinished(*i);
 302   }
 303 }
 304
 305 void Plan::NodeFinished(Node* node) {
 306   // See if we we want any edges from this node.
 307   for (vector<Edge*>::const_iterator i = node->out_edges().begin();
 308        i != node->out_edges().end(); ++i) {
 309     map<Edge*, bool>::iterator want_i = want_.find(*i);
 310     if (want_i == want_.end())
 311       continue;
 312
 313     // See if the edge is now ready.
 314     if ((*i)->AllInputsReady()) {
 315       if (want_i->second) {
 316         ready_.insert(*i);
 317       } else {
 318         // We do not need to build this edge, but we might need to build one of
 319         // its dependents.
 320         EdgeFinished(*i);
 321       }
 322     }
 323   }
 324 }
 325
 326 void Plan::CleanNode(BuildLog* build_log, Node* node) {
 327   node->set_dirty(false);
 328
 329   for (vector<Edge*>::const_iterator ei = node->out_edges().begin();
 330        ei != node->out_edges().end(); ++ei) {
 331     // Don't process edges that we don't actually want.
 332     map<Edge*, bool>::iterator want_i = want_.find(*ei);
 333     if (want_i == want_.end() || !want_i->second)
 334       continue;
 335
 336     // If all non-order-only inputs for this edge are now clean,
 337     // we might have changed the dirty state of the outputs.
 338     vector<Node*>::iterator begin = (*ei)->inputs_.begin(),
 339                             end = (*ei)->inputs_.end() - (*ei)->order_only_deps_;
 340     if (find_if(begin, end, mem_fun(&Node::dirty)) == end) {
 341       // Recompute most_recent_input and command.
 342       TimeStamp most_recent_input = 1;
 343       for (vector<Node*>::iterator ni = begin; ni != end; ++ni)
 344         if ((*ni)->mtime() > most_recent_input)
 345           most_recent_input = (*ni)->mtime();
 346       string command = (*ei)->EvaluateCommand();
 347
 348       // Now, recompute the dirty state of each output.
 349       bool all_outputs_clean = true;
 350       for (vector<Node*>::iterator ni = (*ei)->outputs_.begin();
 351            ni != (*ei)->outputs_.end(); ++ni) {
 352         if (!(*ni)->dirty())
 353           continue;
 354
 355         if ((*ei)->RecomputeOutputDirty(build_log, most_recent_input, command,
 356                                         *ni)) {
 357           (*ni)->MarkDirty();
 358           all_outputs_clean = false;
 359         } else {
 360           CleanNode(build_log, *ni);
 361         }
 362       }
 363
 364       // If we cleaned all outputs, mark the node as not wanted.
 365       if (all_outputs_clean) {
 366         want_i->second = false;
 367         --wanted_edges_;
 368         if (!(*ei)->is_phony())
 369           --command_edges_;
 370       }
 371     }
 372   }
 373 }
 374
 375 void Plan::Dump() {
 376   printf("pending: %d\n", (int)want_.size());
 377   for (map<Edge*, bool>::iterator i = want_.begin(); i != want_.end(); ++i) {
 378     if (i->second)
 379       printf("want ");
 380     i->first->Dump();
 381   }
 382   printf("ready: %d\n", (int)ready_.size());
 383 }
 384
 385 struct RealCommandRunner : public CommandRunner {
 386   RealCommandRunner(const BuildConfig& config) : config_(config) {}
 387   virtual ~RealCommandRunner() {}
 388   virtual bool CanRunMore();
 389   virtual bool StartCommand(Edge* edge);
 390   virtual Edge* WaitForCommand(bool* success, string* output);
 391
 392   const BuildConfig& config_;
 393   SubprocessSet subprocs_;
 394   map<Subprocess*, Edge*> subproc_to_edge_;
 395 };
 396
 397 bool RealCommandRunner::CanRunMore() {
 398   return ((int)subprocs_.running_.size()) < config_.parallelism;
 399 }
 400
 401 bool RealCommandRunner::StartCommand(Edge* edge) {
 402   string command = edge->EvaluateCommand();
 403   Subprocess* subproc = new Subprocess;
 404   subproc_to_edge_.insert(make_pair(subproc, edge));
 405   if (!subproc->Start(&subprocs_, command))
 406     return false;
 407
 408   subprocs_.Add(subproc);
 409   return true;
 410 }
 411
 412 Edge* RealCommandRunner::WaitForCommand(bool* success, string* output) {
 413   Subprocess* subproc;
 414   while ((subproc = subprocs_.NextFinished()) == NULL) {
 415     subprocs_.DoWork();
 416   }
 417
 418   *success = subproc->Finish();
 419   *output = subproc->GetOutput();
 420
 421   map<Subprocess*, Edge*>::iterator i = subproc_to_edge_.find(subproc);
 422   Edge* edge = i->second;
 423   subproc_to_edge_.erase(i);
 424
 425   delete subproc;
 426   return edge;
 427 }
 428
 429 /// A CommandRunner that doesn't actually run the commands.
 430 struct DryRunCommandRunner : public CommandRunner {
 431   virtual ~DryRunCommandRunner() {}
 432   virtual bool CanRunMore() {
 433     return true;
 434   }
 435   virtual bool StartCommand(Edge* edge) {
 436     finished_.push(edge);
 437     return true;
 438   }
 439   virtual Edge* WaitForCommand(bool* success, string* output) {
 440     if (finished_.empty())
 441       return NULL;
 442     *success = true;
 443     Edge* edge = finished_.front();
 444     finished_.pop();
 445     return edge;
 446   }
 447
 448   queue<Edge*> finished_;
 449 };
 450
 451 Builder::Builder(State* state, const BuildConfig& config)
 452     : state_(state), config_(config) {
 453   disk_interface_ = new RealDiskInterface;
 454   if (config.dry_run)
 455     command_runner_ = new DryRunCommandRunner;
 456   else
 457     command_runner_ = new RealCommandRunner(config);
 458   status_ = new BuildStatus(config);
 459   log_ = state->build_log_;
 460 }
 461
 462 Node* Builder::AddTarget(const string& name, string* err) {
 463   Node* node = state_->LookupNode(name);
 464   if (!node) {
 465     *err = "unknown target: '" + name + "'";
 466     return NULL;
 467   }
 468   if (!AddTarget(node, err))
 469     return NULL;
 470   return node;
 471 }
 472
 473 bool Builder::AddTarget(Node* node, string* err) {
 474   node->StatIfNecessary(disk_interface_);
 475   if (Edge* in_edge = node->in_edge()) {
 476     if (!in_edge->RecomputeDirty(state_, disk_interface_, err))
 477       return false;
 478     if (in_edge->outputs_ready())
 479       return true;  // Nothing to do.
 480   }
 481
 482   if (!plan_.AddTarget(node, err))
 483     return false;
 484
 485   return true;
 486 }
 487
 488 bool Builder::AlreadyUpToDate() const {
 489   return !plan_.more_to_do();
 490 }
 491
 492 bool Builder::Build(string* err) {
 493   assert(!AlreadyUpToDate());
 494
 495   status_->PlanHasTotalEdges(plan_.command_edge_count());
 496   int pending_commands = 0;
 497   int failures_allowed = config_.swallow_failures;
 498
 499   // This main loop runs the entire build process.
 500   // It is structured like this:
 501   // First, we attempt to start as many commands as allowed by the
 502   // command runner.
 503   // Second, we attempt to wait for / reap the next finished command.
 504   // If we can do neither of those, the build is stuck, and we report
 505   // an error.
 506   while (plan_.more_to_do()) {
 507     // See if we can start any more commands.
 508     if (command_runner_->CanRunMore()) {
 509       if (Edge* edge = plan_.FindWork()) {
 510         if (!StartEdge(edge, err))
 511           return false;
 512
 513         if (edge->is_phony())
 514           FinishEdge(edge, true, "");
 515         else
 516           ++pending_commands;
 517
 518         // We made some progress; go back to the main loop.
 519         continue;
 520       }
 521     }
 522
 523     // See if we can reap any finished commands.
 524     if (pending_commands) {
 525       bool success;
 526       string output;
 527       Edge* edge;
 528       if ((edge = command_runner_->WaitForCommand(&success, &output))) {
 529         --pending_commands;
 530         FinishEdge(edge, success, output);
 531         if (!success) {
 532           if (failures_allowed-- == 0) {
 533             if (config_.swallow_failures != 0)
 534               *err = "subcommands failed";
 535             else
 536               *err = "subcommand failed";
 537             return false;
 538           }
 539         }
 540
 541         // We made some progress; start the main loop over.
 542         continue;
 543       }
 544     }
 545
 546     // If we get here, we can neither enqueue new commands nor are any running.
 547     if (pending_commands) {
 548       *err = "stuck: pending commands but none to wait for? [this is a bug]";
 549       return false;
 550     }
 551
 552     // If we get here, we cannot make any more progress.
 553     if (failures_allowed < config_.swallow_failures) {
 554       *err = "cannot make progress due to previous errors";
 555       return false;
 556     } else {
 557       *err = "stuck [this is a bug]";
 558       return false;
 559     }
 560   }
 561
 562   return true;
 563 }
 564
 565 bool Builder::StartEdge(Edge* edge, string* err) {
 566   if (edge->is_phony())
 567     return true;
 568
 569   status_->BuildEdgeStarted(edge);
 570
 571   // Create directories necessary for outputs.
 572   // XXX: this will block; do we care?
 573   for (vector<Node*>::iterator i = edge->outputs_.begin();
 574        i != edge->outputs_.end(); ++i) {
 575     if (!disk_interface_->MakeDirs((*i)->path()))
 576       return false;
 577   }
 578
 579   // Compute command and start it.
 580   string command = edge->EvaluateCommand();
 581   if (!command_runner_->StartCommand(edge)) {
 582     err->assign("command '" + command + "' failed.");
 583     return false;
 584   }
 585
 586   return true;
 587 }
 588
 589 void Builder::FinishEdge(Edge* edge, bool success, const string& output) {
 590   TimeStamp restat_mtime = 0;
 591
 592   if (success) {
 593     if (edge->rule().restat() && !config_.dry_run) {
 594       bool node_cleaned = false;
 595
 596       for (vector<Node*>::iterator i = edge->outputs_.begin();
 597            i != edge->outputs_.end(); ++i) {
 598         TimeStamp new_mtime = disk_interface_->Stat((*i)->path());
 599         if ((*i)->mtime() == new_mtime) {
 600           // The rule command did not change the output.  Propagate the clean
 601           // state through the build graph.
 602           // Note that this also applies to nonexistent outputs (mtime == 0).
 603           plan_.CleanNode(log_, *i);
 604           node_cleaned = true;
 605         }
 606       }
 607
 608       if (node_cleaned) {
 609         // If any output was cleaned, find the most recent mtime of any
 610         // (existing) non-order-only input or the depfile.
 611         for (vector<Node*>::iterator i = edge->inputs_.begin();
 612              i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
 613           TimeStamp input_mtime = disk_interface_->Stat((*i)->path());
 614           if (input_mtime == 0) {
 615             restat_mtime = 0;
 616             break;
 617           }
 618           if (input_mtime > restat_mtime)
 619             restat_mtime = input_mtime;
 620         }
 621
 622         if (restat_mtime != 0 && !edge->rule().depfile().empty()) {
 623           TimeStamp depfile_mtime = disk_interface_->Stat(edge->EvaluateDepFile());
 624           if (depfile_mtime == 0)
 625             restat_mtime = 0;
 626           else if (depfile_mtime > restat_mtime)
 627             restat_mtime = depfile_mtime;
 628         }
 629
 630         // The total number of edges in the plan may have changed as a result
 631         // of a restat.
 632         status_->PlanHasTotalEdges(plan_.command_edge_count());
 633       }
 634     }
 635
 636     plan_.EdgeFinished(edge);
 637   }
 638
 639   if (edge->is_phony())
 640     return;
 641
 642   int start_time, end_time;
 643   status_->BuildEdgeFinished(edge, success, output, &start_time, &end_time);
 644   if (success && log_)
 645     log_->RecordCommand(edge, start_time, end_time, restat_mtime);
 646 }