From 5a7c4c4f6e205e0eb702f18af77907e7239639da Mon Sep 17 00:00:00 2001 From: Tom Pollard Date: Wed, 4 Dec 2019 12:51:32 +0000 Subject: _frontend/app.py: Make message printing tick driven --- src/buildstream/_frontend/app.py | 43 +++++++++++++++++++++++++++++----------- 1 file changed, 31 insertions(+), 12 deletions(-) diff --git a/src/buildstream/_frontend/app.py b/src/buildstream/_frontend/app.py index b3687911b..b7aeb040b 100644 --- a/src/buildstream/_frontend/app.py +++ b/src/buildstream/_frontend/app.py @@ -89,6 +89,9 @@ class App: self._error_profile = Profile(fg="red", dim=True) self._detail_profile = Profile(dim=True) + # Cached messages + self._message_text = "" + # # Early initialization # @@ -237,7 +240,7 @@ class App: self.context.messenger.set_message_handler(self._message_handler) # Allow the Messenger to write status messages - self.context.messenger.set_render_status_cb(self._maybe_render_status) + self.context.messenger.set_render_status_cb(self._render) # Preflight the artifact cache after initializing logging, # this can cause messages to be emitted. @@ -315,15 +318,19 @@ class App: if self._started: self._print_summary() + else: + # Check that any cached messages are printed + self._render(message_text=self._message_text) # Exit with the error self._error_exit(e) except RecursionError: + # Check that any cached messages are printed + self._render(message_text=self._message_text) click.echo( "RecursionError: Dependency depth is too large. Maximum recursion depth exceeded.", err=True ) sys.exit(-1) - else: # No exceptions occurred, print session time and summary if session_name: @@ -333,6 +340,9 @@ class App: # Notify session success self._notify("{} succeeded".format(session_name), "") + else: + # Check that any cached messages are printed + self._render(message_text=self._message_text) # init_project() # @@ -524,9 +534,17 @@ class App: sys.exit(-1) # - # Render the status area, conditional on some internal state + # Render message & status area, conditional on some internal state. This + # is driven by the tick rate by default if applicable. Internal tasks + # using the simple_task context manager, i.e resolving pipeline elements, that + # use this as callback should not drive the message printing by default. # - def _maybe_render_status(self): + def _render(self, message_text=None): + + if self._status and message_text: + self._status.clear() + click.echo(message_text, nl=False, err=True) + self._message_text = "" # If we're suspended or terminating, then dont render the status area if self._status and self.stream and not (self.stream.suspended or self.stream.terminated): @@ -585,7 +603,7 @@ class App: click.echo("\nContinuing\n", err=True) def _tick(self): - self._maybe_render_status() + self._render(message_text=self._message_text) # Callback that a job has failed # @@ -723,6 +741,8 @@ class App: # Print a summary of the queues # def _print_summary(self): + # Ensure all status & messages have been processed + self._render(message_text=self._message_text) click.echo("", err=True) self.logger.print_summary(self.stream, self._main_options["log_file"]) @@ -779,14 +799,13 @@ class App: if is_silenced and (message.message_type not in unconditional_messages): return - if self._status: - self._status.clear() - + # Format the message & cache it text = self.logger.render(message) - click.echo(text, nl=False, err=True) + self._message_text += text - # Maybe render the status area - self._maybe_render_status() + # If scheduler tick isn't active then render + if not self.stream.running: + self._render(message_text=self._message_text) # Additionally log to a file if self._main_options["log_file"]: @@ -799,7 +818,7 @@ class App: with self.stream.suspend(): yield finally: - self._maybe_render_status() + self._render(message_text=self._message_text) # Some validation routines for project initialization # -- cgit v1.2.1 From 16cbb7cb91a5b59e9c9907b64b2e02d7027ea5c0 Mon Sep 17 00:00:00 2001 From: Tom Pollard Date: Wed, 4 Dec 2019 13:49:47 +0000 Subject: userconfig.yaml: Add bool for disabling console output throttling Also highlight the change & configuration in NEWS --- NEWS | 10 ++++++++++ src/buildstream/_context.py | 15 ++++++++++++++- src/buildstream/_frontend/app.py | 8 ++++++-- src/buildstream/data/userconfig.yaml | 3 +++ 4 files changed, 33 insertions(+), 3 deletions(-) diff --git a/NEWS b/NEWS index 602b14b51..293085cfe 100644 --- a/NEWS +++ b/NEWS @@ -20,6 +20,16 @@ API Plugins authors that do this and believe BuildStream should be testing that part of their plugins should open an issue on BuildStream. +Miscellaneous +------------- + + o By default the update rate of builstream console output + (e.g. messages & status updates) when executing a scheduler driven task is + restricted to once per second, known as the tick, with messages being batched + in the intervening periods if necessary. This restriction can be lifted with + `throttle-ui-updates: False` in user configuration. Logging behaviour remains + unaffected by this configuration. + ================== buildstream 1.91.3 diff --git a/src/buildstream/_context.py b/src/buildstream/_context.py index 9642edd49..513754a4c 100644 --- a/src/buildstream/_context.py +++ b/src/buildstream/_context.py @@ -114,6 +114,9 @@ class Context: # Format string for printing message lines in the master log self.log_message_format = None + # Wether to rate limit the updating of the bst output where applicable + self.log_throttle_updates = None + # Maximum number of fetch or refresh tasks self.sched_fetchers = None @@ -337,7 +340,16 @@ class Context: # Load logging config logging = defaults.get_mapping("logging") logging.validate_keys( - ["key-length", "verbose", "error-lines", "message-lines", "debug", "element-format", "message-format"] + [ + "key-length", + "verbose", + "error-lines", + "message-lines", + "debug", + "element-format", + "message-format", + "throttle-ui-updates", + ] ) self.log_key_length = logging.get_int("key-length") self.log_debug = logging.get_bool("debug") @@ -346,6 +358,7 @@ class Context: self.log_message_lines = logging.get_int("message-lines") self.log_element_format = logging.get_str("element-format") self.log_message_format = logging.get_str("message-format") + self.log_throttle_updates = logging.get_bool("throttle-ui-updates") # Load scheduler config scheduler = defaults.get_mapping("scheduler") diff --git a/src/buildstream/_frontend/app.py b/src/buildstream/_frontend/app.py index b7aeb040b..cd05b7f8d 100644 --- a/src/buildstream/_frontend/app.py +++ b/src/buildstream/_frontend/app.py @@ -91,6 +91,7 @@ class App: # Cached messages self._message_text = "" + self._cache_messages = None # # Early initialization @@ -239,6 +240,9 @@ class App: # Propagate pipeline feedback to the user self.context.messenger.set_message_handler(self._message_handler) + # Check if throttling frontend updates to tick rate + self._cache_messages = self.context.log_throttle_updates + # Allow the Messenger to write status messages self.context.messenger.set_render_status_cb(self._render) @@ -803,8 +807,8 @@ class App: text = self.logger.render(message) self._message_text += text - # If scheduler tick isn't active then render - if not self.stream.running: + # If we're not rate limiting messaging, or the scheduler tick isn't active then render + if not self._cache_messages or not self.stream.running: self._render(message_text=self._message_text) # Additionally log to a file diff --git a/src/buildstream/data/userconfig.yaml b/src/buildstream/data/userconfig.yaml index dc31c10ce..5b568167b 100644 --- a/src/buildstream/data/userconfig.yaml +++ b/src/buildstream/data/userconfig.yaml @@ -133,3 +133,6 @@ logging: message-format: | [%{elapsed}][%{key}][%{element}] %{action} %{message} + + # Limit bst console output update rate to 1Hz where applicable + throttle-ui-updates: True -- cgit v1.2.1