diff --git a/doc/manual.asciidoc b/doc/manual.asciidoc index 1e9ede9891..074ba0fc48 100644 --- a/doc/manual.asciidoc +++ b/doc/manual.asciidoc @@ -190,7 +190,8 @@ you don't need to pass `-j`.) Environment variables ~~~~~~~~~~~~~~~~~~~~~ -Ninja supports one environment variable to control its behavior: +Ninja supports a few environment variables to control its behavior: + `NINJA_STATUS`, the progress status printed before the rule being run. Several placeholders are available: @@ -215,6 +216,12 @@ The default progress status is `"[%f/%t] "` (note the trailing space to separate from the build rule). Another example of possible progress status could be `"[%u/%r/%f] "`. +`NINJA_STATUS_REFRESH_MILLIS`, the refresh timeout in milliseconds +for status updates in interactive terminals. The default value is 1000, +to allow time-sensitive formatters like `%w` to be updated during +long build runs (e.g. when one or more build commands run for a long +time). + Extra tools ~~~~~~~~~~~ diff --git a/misc/output_test.py b/misc/output_test.py index 9691e68245..064672b289 100755 --- a/misc/output_test.py +++ b/misc/output_test.py @@ -16,6 +16,7 @@ default_env = dict(os.environ) default_env.pop('NINJA_STATUS', None) +default_env.pop('NINJA_STATUS_REFRESH_MILLIS', None) default_env.pop('CLICOLOR_FORCE', None) default_env['TERM'] = '' NINJA_PATH = os.path.abspath('./ninja') @@ -310,6 +311,41 @@ def test_ninja_status_quiet(self) -> None: output = run(Output.BUILD_SIMPLE_ECHO, flags='--quiet') self.assertEqual(output, 'do thing\n') + @unittest.skip("Time-based test fails on Github CI") + def test_ninja_status_periodic_update(self) -> None: + b = BuildDir('''\ + rule sleep_then_print + command = sleep 2 && echo done + description = sleep2s + + build all: sleep_then_print + ''') + with b: + env = default_env.copy() + env["NINJA_STATUS"] = "[%w] " + self.assertListEqual( + b.run('all', raw_output=True, env=env).replace("\r\n", "").split("\r"), + [ + "", + "[00:00] sleep2s\x1b[K", + "[00:01] sleep2s\x1b[K", + "[00:02] sleep2s\x1b[K", + "[00:02] sleep2s\x1b[Kdone", + ]) + + env["NINJA_STATUS_REFRESH_MILLIS"] = "500" + self.assertListEqual( + b.run('all', raw_output=True, env=env).replace("\r\n", "").split("\r"), + [ + "", + "[00:00] sleep2s\x1b[K", + "[00:00] sleep2s\x1b[K", + "[00:01] sleep2s\x1b[K", + "[00:01] sleep2s\x1b[K", + "[00:02] sleep2s\x1b[K", + "[00:02] sleep2s\x1b[Kdone", + ]) + def test_entering_directory_on_stdout(self) -> None: output = run(Output.BUILD_SIMPLE_ECHO, flags='-C$PWD', pipe=True) self.assertEqual(output.splitlines()[0][:25], "ninja: Entering directory") diff --git a/src/build.cc b/src/build.cc index d256d940b0..6147efd7fc 100644 --- a/src/build.cc +++ b/src/build.cc @@ -696,10 +696,13 @@ bool Builder::Build(string* err) { // Set up the command runner if we haven't done so already. if (!command_runner_.get()) { - if (config_.dry_run) + if (config_.dry_run) { command_runner_.reset(new DryRunCommandRunner); - else - command_runner_.reset(CommandRunner::factory(config_)); + } else { + command_runner_.reset(CommandRunner::factory(config_, [this]() { + status_->Refresh(GetTimeMillis() - start_time_millis_); + })); + } } // We are about to start the build process. diff --git a/src/build.h b/src/build.h index ba39e7728a..569712ee09 100644 --- a/src/build.h +++ b/src/build.h @@ -16,6 +16,7 @@ #define NINJA_BUILD_H_ #include +#include #include #include #include @@ -151,6 +152,9 @@ struct CommandRunner { virtual size_t CanRunMore() const = 0; virtual bool StartCommand(Edge* edge) = 0; + // A callable value used to refresh the current Ninja status. + using StatusRefresher = std::function; + /// The result of waiting for a command. struct Result { Result() : edge(NULL) {} @@ -166,13 +170,13 @@ struct CommandRunner { virtual void Abort() {} /// Creates the RealCommandRunner - static CommandRunner* factory(const BuildConfig& config); + static CommandRunner* factory(const BuildConfig& config, + StatusRefresher&& refresh_status); }; /// Options (e.g. verbosity, parallelism) passed to a build. struct BuildConfig { - BuildConfig() : verbosity(NORMAL), dry_run(false), parallelism(1), - failures_allowed(1), max_load_average(-0.0f) {} + BuildConfig() = default; enum Verbosity { QUIET, // No output -- used when testing. @@ -180,13 +184,16 @@ struct BuildConfig { NORMAL, // regular output and status update VERBOSE }; - Verbosity verbosity; - bool dry_run; - int parallelism; - int failures_allowed; + Verbosity verbosity = NORMAL; + bool dry_run = false; + int parallelism = 1; + int failures_allowed = 1; /// The maximum load average we must not exceed. A negative value /// means that we do not have any limit. - double max_load_average; + double max_load_average = -0.0f; + /// Number of milliseconds between status refreshes in interactive + /// terminals. + int status_refresh_millis = 1000; DepfileParserOptions depfile_parser_options; }; diff --git a/src/ninja.cc b/src/ninja.cc index f681bfec11..de0936b66a 100644 --- a/src/ninja.cc +++ b/src/ninja.cc @@ -1729,6 +1729,11 @@ NORETURN void real_main(int argc, char** argv) { Options options = {}; options.input_file = "build.ninja"; + const char* status_refresh_env = getenv("NINJA_STATUS_REFRESH_MILLIS"); + if (status_refresh_env) { + config.status_refresh_millis = atoi(status_refresh_env); + } + setvbuf(stdout, NULL, _IOLBF, BUFSIZ); const char* ninja_command = argv[0]; diff --git a/src/real_command_runner.cc b/src/real_command_runner.cc index 453652f5e5..77906cb2cb 100644 --- a/src/real_command_runner.cc +++ b/src/real_command_runner.cc @@ -16,7 +16,9 @@ #include "subprocess.h" struct RealCommandRunner : public CommandRunner { - explicit RealCommandRunner(const BuildConfig& config) : config_(config) {} + explicit RealCommandRunner(const BuildConfig& config, + StatusRefresher&& refresh_status) + : config_(config), refresh_status_(std::move(refresh_status)) {} size_t CanRunMore() const override; bool StartCommand(Edge* edge) override; bool WaitForCommand(Result* result) override; @@ -24,6 +26,7 @@ struct RealCommandRunner : public CommandRunner { void Abort() override; const BuildConfig& config_; + StatusRefresher refresh_status_; SubprocessSet subprocs_; std::map subproc_to_edge_; }; @@ -75,9 +78,14 @@ bool RealCommandRunner::StartCommand(Edge* edge) { bool RealCommandRunner::WaitForCommand(Result* result) { Subprocess* subproc; - while ((subproc = subprocs_.NextFinished()) == NULL) { - bool interrupted = subprocs_.DoWork(); - if (interrupted) + while ((subproc = subprocs_.NextFinished()) == nullptr) { + SubprocessSet::WorkResult ret = + subprocs_.DoWork(config_.status_refresh_millis); + if (ret == SubprocessSet::WorkResult::TIMEOUT) { + refresh_status_(); + continue; + } + if (ret == SubprocessSet::WorkResult::INTERRUPTION) return false; } @@ -93,6 +101,7 @@ bool RealCommandRunner::WaitForCommand(Result* result) { return true; } -CommandRunner* CommandRunner::factory(const BuildConfig& config) { - return new RealCommandRunner(config); +CommandRunner* CommandRunner::factory(const BuildConfig& config, + StatusRefresher&& refresh_status) { + return new RealCommandRunner(config, std::move(refresh_status)); } diff --git a/src/status.h b/src/status.h index 29db7c203a..40e4754841 100644 --- a/src/status.h +++ b/src/status.h @@ -34,6 +34,13 @@ struct Status { virtual void BuildStarted() = 0; virtual void BuildFinished() = 0; + /// Refresh status display after some time has passed. Useful + /// when printing the status on an interactive terminal. Does + /// nothing by default. \arg cur_time_millis is the current time + /// expressed in milliseconds, using the same epoch than the + /// one used in BuildEdgeStart() and BuildEdgeFinished(). + virtual void Refresh(int64_t cur_time_millis) {} + /// Set the Explanations instance to use to report explanations, /// argument can be nullptr if no explanations need to be printed /// (which is the default). diff --git a/src/status_printer.cc b/src/status_printer.cc index 8db6809561..80149da657 100644 --- a/src/status_printer.cc +++ b/src/status_printer.cc @@ -304,13 +304,13 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format, // Overall finished edges per second. case 'o': - SnprintfRate(finished_edges_ / (time_millis_ / 1e3), buf, "%.1f"); + SnprintfRate(finished_edges_ / (time_millis / 1e3), buf, "%.1f"); out += buf; break; // Current rate, average over the last '-j' jobs. case 'c': - current_rate_.UpdateRate(finished_edges_, time_millis_); + current_rate_.UpdateRate(finished_edges_, time_millis); SnprintfRate(current_rate_.rate(), buf, "%.1f"); out += buf; break; @@ -336,15 +336,15 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format, case 'E': // ETA, seconds case 'W': // ETA, human-readable { - double elapsed_sec = time_millis_ / 1e3; + double elapsed_sec = time_millis / 1e3; double eta_sec = -1; // To be printed as "?". if (time_predicted_percentage_ != 0.0) { - // So, we know that we've spent time_millis_ wall clock, + // So, we know that we've spent time_millis wall clock, // and that is time_predicted_percentage_ percent. // How much time will we need to complete 100%? - double total_wall_time = time_millis_ / time_predicted_percentage_; + double total_wall_time = time_millis / time_predicted_percentage_; // Naturally, that gives us the time remaining. - eta_sec = (total_wall_time - time_millis_) / 1e3; + eta_sec = (total_wall_time - time_millis) / 1e3; } const bool print_with_hours = @@ -428,17 +428,28 @@ void StatusPrinter::PrintStatus(const Edge* edge, int64_t time_millis) { bool force_full_command = config_.verbosity == BuildConfig::VERBOSE; - string to_print = edge->GetBinding("description"); - if (to_print.empty() || force_full_command) - to_print = edge->GetBinding("command"); + last_description_ = edge->GetBinding("description"); + if (last_description_.empty() || force_full_command) + last_description_ = edge->GetBinding("command"); - to_print = FormatProgressStatus(progress_status_format_, time_millis) - + to_print; + RefreshStatus(time_millis, force_full_command); +} +void StatusPrinter::RefreshStatus(int64_t cur_time_millis, + bool force_full_command) { + std::string to_print = + FormatProgressStatus(progress_status_format_, cur_time_millis) + + last_description_; printer_.Print(to_print, force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE); } +void StatusPrinter::Refresh(int64_t cur_time_millis) { + if (printer_.is_smart_terminal()) { + RefreshStatus(cur_time_millis, false); + } +} + void StatusPrinter::Warning(const char* msg, ...) { va_list ap; va_start(ap, msg); diff --git a/src/status_printer.h b/src/status_printer.h index 08a8d1a93d..b9e601b09f 100644 --- a/src/status_printer.h +++ b/src/status_printer.h @@ -36,6 +36,8 @@ struct StatusPrinter : Status { void BuildStarted() override; void BuildFinished() override; + void Refresh(int64_t cur_time_millis) override; + void Info(const char* msg, ...) override; void Warning(const char* msg, ...) override; void Error(const char* msg, ...) override; @@ -82,6 +84,8 @@ struct StatusPrinter : Status { /// For how many edges we don't know the previous run time? int eta_unpredictable_edges_remaining_ = 0; + void RefreshStatus(int64_t cur_time_millis, bool force_full_command); + void RecalculateProgressPrediction(); /// Prints progress output. @@ -93,6 +97,9 @@ struct StatusPrinter : Status { /// The custom progress status format to use. const char* progress_status_format_; + /// Last command's description or command-line. + std::string last_description_; + template void SnprintfRate(double rate, char (&buf)[S], const char* format) const { if (rate == -1) diff --git a/src/subprocess-posix.cc b/src/subprocess-posix.cc index 8e785406c9..e62252c336 100644 --- a/src/subprocess-posix.cc +++ b/src/subprocess-posix.cc @@ -248,14 +248,38 @@ Subprocess *SubprocessSet::Add(const string& command, bool use_console) { return subprocess; } -#ifdef USE_PPOLL bool SubprocessSet::DoWork() { - vector fds; + WorkResult ret = DoWork(-1); + return ret == WorkResult::INTERRUPTION; +} + +// An optional timespec struct value for pselect() or ppoll(). Usage: +// - Create instance, pass timeout in milliseconds. +// - Call ptr() tp get the pointer to pass to pselect() or ppoll(). +struct TimeoutHelper { + // Constructor. A negative timeout_ms value means no timeout. + TimeoutHelper(int64_t timeout_ms) { + if (timeout_ms >= 0) { + ts_.tv_sec = static_cast(timeout_ms / 1000); + ts_.tv_nsec = static_cast((timeout_ms % 1000) * 1000000L); + ptr_ = &ts_; + } + } + + const struct timespec* ptr() const { return ptr_; } + + private: + struct timespec ts_ {}; + const struct timespec* ptr_ = nullptr; +}; + +#ifdef USE_PPOLL +SubprocessSet::WorkResult SubprocessSet::DoWork(int64_t timeout_millis) { + std::vector fds; nfds_t nfds = 0; - for (vector::iterator i = running_.begin(); - i != running_.end(); ++i) { - int fd = (*i)->fd_; + for (const auto& proc : running_) { + int fd = proc->fd_; if (fd < 0) continue; pollfd pfd = { fd, POLLIN | POLLPRI, 0 }; @@ -264,49 +288,50 @@ bool SubprocessSet::DoWork() { } interrupted_ = 0; - int ret = ppoll(&fds.front(), nfds, NULL, &old_mask_); + TimeoutHelper timeout(timeout_millis); + int ret = ppoll(&fds.front(), nfds, timeout.ptr(), &old_mask_); + if (ret == 0) { + return WorkResult::TIMEOUT; + } if (ret == -1) { if (errno != EINTR) { - perror("ninja: ppoll"); - return false; + Fatal("ppoll", strerror(errno)); } - return IsInterrupted(); + return IsInterrupted() ? WorkResult::INTERRUPTION : WorkResult::COMPLETION; } HandlePendingInterruption(); if (IsInterrupted()) - return true; + return WorkResult::INTERRUPTION; nfds_t cur_nfd = 0; - for (vector::iterator i = running_.begin(); - i != running_.end(); ) { - int fd = (*i)->fd_; + for (auto it = running_.begin(); it != running_.end();) { + int fd = (*it)->fd_; if (fd < 0) continue; assert(fd == fds[cur_nfd].fd); if (fds[cur_nfd++].revents) { - (*i)->OnPipeReady(); - if ((*i)->Done()) { - finished_.push(*i); - i = running_.erase(i); + (*it)->OnPipeReady(); + if ((*it)->Done()) { + finished_.push(*it); + it = running_.erase(it); continue; } } - ++i; + ++it; } - return IsInterrupted(); + return IsInterrupted() ? WorkResult::INTERRUPTION : WorkResult::COMPLETION; } #else // !defined(USE_PPOLL) -bool SubprocessSet::DoWork() { +SubprocessSet::WorkResult SubprocessSet::DoWork(int64_t timeout_millis) { fd_set set; int nfds = 0; FD_ZERO(&set); - for (vector::iterator i = running_.begin(); - i != running_.end(); ++i) { - int fd = (*i)->fd_; + for (const auto& proc : running_) { + int fd = proc->fd_; if (fd >= 0) { FD_SET(fd, &set); if (nfds < fd+1) @@ -315,34 +340,37 @@ bool SubprocessSet::DoWork() { } interrupted_ = 0; - int ret = pselect(nfds, &set, 0, 0, 0, &old_mask_); + TimeoutHelper timeout(timeout_millis); + int ret = pselect(nfds, &set, 0, 0, timeout.ptr(), &old_mask_); + if (ret == 0) + return WorkResult::TIMEOUT; + if (ret == -1) { if (errno != EINTR) { - perror("ninja: pselect"); - return false; + Fatal("pselect", strerror(errno)); } - return IsInterrupted(); + return IsInterrupted() ? WorkResult::INTERRUPTION : WorkResult::COMPLETION; } HandlePendingInterruption(); if (IsInterrupted()) - return true; + return WorkResult::INTERRUPTION; - for (vector::iterator i = running_.begin(); - i != running_.end(); ) { - int fd = (*i)->fd_; + for (std::vector::iterator it = running_.begin(); + it != running_.end();) { + int fd = (*it)->fd_; if (fd >= 0 && FD_ISSET(fd, &set)) { - (*i)->OnPipeReady(); - if ((*i)->Done()) { - finished_.push(*i); - i = running_.erase(i); + (*it)->OnPipeReady(); + if ((*it)->Done()) { + finished_.push(*it); + it = running_.erase(it); continue; } } - ++i; + ++it; } - return IsInterrupted(); + return IsInterrupted() ? WorkResult::INTERRUPTION : WorkResult::COMPLETION; } #endif // !defined(USE_PPOLL) diff --git a/src/subprocess-win32.cc b/src/subprocess-win32.cc index ff3baaca7f..863288e7af 100644 --- a/src/subprocess-win32.cc +++ b/src/subprocess-win32.cc @@ -252,19 +252,29 @@ Subprocess *SubprocessSet::Add(const string& command, bool use_console) { } bool SubprocessSet::DoWork() { + WorkResult ret = DoWork(-1); + return ret == WorkResult::INTERRUPTION; +} + +SubprocessSet::WorkResult SubprocessSet::DoWork(int64_t timeout_millis) { DWORD bytes_read; Subprocess* subproc; OVERLAPPED* overlapped; + DWORD timeout = + (timeout_millis < 0) ? INFINITE : static_cast(timeout_millis); if (!GetQueuedCompletionStatus(ioport_, &bytes_read, (PULONG_PTR)&subproc, - &overlapped, INFINITE)) { + &overlapped, timeout)) { + if (!overlapped) { + return WorkResult::TIMEOUT; + } if (GetLastError() != ERROR_BROKEN_PIPE) Win32Fatal("GetQueuedCompletionStatus"); } if (!subproc) // A NULL subproc indicates that we were interrupted and is // delivered by NotifyInterrupted above. - return true; + return WorkResult::INTERRUPTION; subproc->OnPipeReady(); @@ -277,7 +287,7 @@ bool SubprocessSet::DoWork() { } } - return false; + return WorkResult::COMPLETION; } Subprocess* SubprocessSet::NextFinished() { diff --git a/src/subprocess.h b/src/subprocess.h index 9e3d2ee98f..6fcfa0c340 100644 --- a/src/subprocess.h +++ b/src/subprocess.h @@ -15,9 +15,11 @@ #ifndef NINJA_SUBPROCESS_H_ #define NINJA_SUBPROCESS_H_ +#include + +#include #include #include -#include #ifdef _WIN32 #include @@ -83,9 +85,43 @@ struct SubprocessSet { SubprocessSet(); ~SubprocessSet(); + // Value returned by DoWork() method, + // - COMPLETION means that a process has completed. + // - INTERRUPTION means that user interruption happened. On Posix this means + // a SIGINT, SIGHUP or SIGTERM signal. On Win32, this means Ctrl-C was + // pressed. + // - TIMEOUT means that the called timed out. + enum class WorkResult { + COMPLETION = 0, + INTERRUPTION = 1, + TIMEOUT = 3, + }; + + // Start a new subprocess running |command|. Set |use_console| to true + // if the process will inherit the current console handles (terminal + // input and outputs on Posix). If false, the subprocess' output + // will be buffered instead, and available after completion. Subprocess* Add(const std::string& command, bool use_console = false); + + // Equivalent to DoWork(-1), which returns true in case of interruption + // and false otherwise. bool DoWork(); + + // Wait for at most |timeout_millis| milli-seconds for either a process + // completion or a user-initiated interruption. If |timeout_millis| is + // negative, waits indefinitely, and never return WorkStatus::TIMEOUT. + // + // IMPORTANT: On Posix, spurious wakeups are possible, and will return + // WorkResult::COMPLETION even though no process has really + // completed. The caller should call NextFinished() and compare the + // its result to nullptr to check for this rare condition. + WorkResult DoWork(int64_t timeout_millis); + + // Return the next Subprocess after a WorkResult::COMPLETION result. + // The result can be nullptr on Posix in case of spurious wakeups. + // NOTE: This transfers ownership of the Subprocess instance to the caller. Subprocess* NextFinished(); + void Clear(); std::vector running_; diff --git a/src/subprocess_test.cc b/src/subprocess_test.cc index 073fe86931..d74abf670e 100644 --- a/src/subprocess_test.cc +++ b/src/subprocess_test.cc @@ -146,6 +146,21 @@ TEST_F(SubprocessTest, InterruptParentWithSigHup) { ASSERT_FALSE("We should have been interrupted"); } +TEST_F(SubprocessTest, Timeout) { + Subprocess* subproc = subprocs_.Add("sleep 1"); + ASSERT_NE((Subprocess*)0, subproc); + size_t timeout_count = 0; + while (true) { + ASSERT_FALSE(subproc->Done()); + SubprocessSet::WorkResult ret = subprocs_.DoWork(100); + if (ret == SubprocessSet::WorkResult::TIMEOUT) + ++timeout_count; + else + break; + } + ASSERT_GT(timeout_count, 0); +} + TEST_F(SubprocessTest, Console) { // Skip test if we don't have the console ourselves. if (isatty(0) && isatty(1) && isatty(2)) {