rich icon indicating copy to clipboard operation
rich copied to clipboard

console.status 'blinking' artifact

Open dunkmann00 opened this issue 2 years ago • 13 comments

  • [X] I've checked docs and closed issues for possible solutions.
  • [X] I can't find my issue in the FAQ.

Describe the bug

I am using console.status and when run on Windows with command prompt I am seeing this blinking effect. My application uses all of the cpu, which I'm assuming has something to do with it. But it does not happen when ran on macOS.

https://user-images.githubusercontent.com/11963090/206074152-3803dda4-eb01-4598-a38e-2fc583f10264.mp4

Any ideas why this might be happening, or if there is anything I can do to get it to stop?

Thanks!

dunkmann00 avatar Dec 07 '22 02:12 dunkmann00

Thank you for your issue. Give us a little time to review it.

PS. You might want to check the FAQ if you haven't done so already.

This is an automated reply, generated by FAQtory

github-actions[bot] avatar Dec 07 '22 02:12 github-actions[bot]

Hello, i cannot reproduce the bug can you give more info on system specs. Function definition for console.status is below :

def status(
        self,
        status: RenderableType,
        *,
        spinner: str = "dots",
        spinner_style: str = "status.spinner",
        speed: float = 1.0,
        refresh_per_second: float = 12.5,
    ) -> "Status":
        """Display a status and spinner.

        Args:
            status (RenderableType): A status renderable (str or Text typically).
            spinner (str, optional): Name of spinner animation (see python -m rich.spinner). Defaults to "dots".
            spinner_style (StyleType, optional): Style of spinner. Defaults to "status.spinner".
            speed (float, optional): Speed factor for spinner animation. Defaults to 1.0.
            refresh_per_second (float, optional): Number of refreshes per second. Defaults to 12.5.

        Returns:
            Status: A Status object that may be used as a context manager.
        """
        from .status import Status

        status_renderable = Status(
            status,
            console=self,
            spinner=spinner,
            spinner_style=spinner_style,
            speed=speed,
            refresh_per_second=refresh_per_second,
        )
        return status_renderable

You can try to play with refresh_per_second and speed arguments. Default values are :
'speed: float = 1.0 , refresh_per_second: float = 12.5,' My guess is cpu cant handle render speed which is bizarre.

SertugF avatar Dec 12 '22 16:12 SertugF

@dunkmann00 nice project :) I'm not a contributor here, but I do like browsing various open source projects and trying to figure out unusual puzzles/behaviours.

It could take a while, so no problem if it's not at the top of your priorities, but could you try narrowing down the program (removing as much as possible unrelated to the flickering, until it stops happening) to see what a near-minimal program that exhibits this problem looks like?

(hopefully it'll eventually reduce down to a single Python module, and perhaps just a few lines of code. it's also possible that you might discover the reason for the problem along the way)

jayaddison avatar Dec 15 '22 12:12 jayaddison

Thanks @jayaddison! It's been fun working on it. And I actually was able to figure out what is going on and most of the why....

Background

The way my application works, it can run in a multi-core or single-core mode. Either way, it will use 100% of the core(s) to run. This problem is only happening in the following scenario:

  • Run in single-core mode
  • CPU utilization is at 100%
  • Run on Windows 10 with the standard command prompt

I can run this on macOS and everything works fine.

Why just Windows?

The first thing I discovered is that rich determined that in this environment it needed to run for legacy_windows: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/console.py#L588

This is correct, as when I initialized my console with legacy_windows to False, it didn't work and the ANSI codes were spit out across the terminal. So despite Legacy Mode not being checked in the command prompt's preferences, as far as rich is concerned this was legacy_windows.

Why is it blinking?

Well I actually figured this out later but its actually pretty straight forward so let's address this here. Status sets Spinner as the renderable object in the Live object it uses. When a Live object is asked for what it wants to render it updates the cursor: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/live.py#L258

In this function, it erases the line (or lines if there are multiple, but in this case there is only one): https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/live_render.py#L57

So every time the spinner updates it erases the whole line, in normal circumstances this isn't something that you can visually notice, but for some reason in my app, we can notice it.

Why is it written out in pieces?

This is partly giving away what is happening. At first I wasn't sure it was getting written out in pieces, or words, letters... But this is also actually pretty straightforward. When printing a string that has been styled with markup (i.e. "[bold]Hello![/]"), rich makes a Text object from this string and parses the different parts into Spans. So each piece that is styled differently is a different Span. When it comes time to write out the string (or technically the Text object at this point), each piece is written one at a time. I'll include the following citation for this, although everything I mentioned is happening throughout several places in the code so this doesn't really show all of it, but it does show where the Text object is created with the styling: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/markup.py#L103-L108

Now let's continue to follow how rich renders out to the command prompt. For starters, the Span objects we were referring to before have become Segment objects at this point. The details of how/why are not important and it essentially serves the same purpose from our perspective. Also, let's keep in mind I'm only going to discuss Windows legacy mode because thats what we are trying to get to the bottom of.

After we have finished handling console.print we get to the render call: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/console.py#L2023

This function is pretty interesting as it shows all the different controls in a neat and tidy spot. But of particular interest is where we write out our styled text: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/_windows_renderer.py#L17

Which leads us to here: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/_win32_console.py#L406

This is where the console style commands are issued to Windows, and where the text is finally written to stdout and flushed. Looking at how this is done we can see that for each segment (each piece of our styled string) the console style is updated, the string is written, and then the console style is set back to what it was originally: https://github.com/Textualize/rich/blob/8bcb7011cfb01462fcd08c7298e756c5e4486617/rich/_win32_console.py#L439-L443

Upon completion of writing out all the segments we are done...until the next refresh and we repeat all of that again.

So why is this blinking and writing so noticeable?

This is where I can't be 100% sure, but I have some thoughts. First, it would seem like having to issue the SetConsoleTextAttribute twice for each Segment could be decently expensive. I also tried to find some info about setting the console attributes and I found some stuff saying it is kind of slow (I don't remember where I found that, I think probably on StackOverflow, I don't think it was even a Python question, might have been C++, so C++ slow might not really be slow for Python, but I digress).

Whether or not that is slow, it would also seem like this has to do with threading. Since Status uses Live and Live runs with threads, it might just be how Windows (or Python?) is handling scheduling the threads. Instead of waiting for the entire line to be rendered, it may jump back and forth between the main thread and the status refresh thread. This might be adding enough latency to make it very easily noticeable, especially given that the line gets erased each time we refresh. 🤷


Well that was longer than I thought it would be.... If you do actually read through it, thanks! I think it was a pretty interesting investigation into the internals of rich. Which I only just started using, so this definitely helped me get more familiarized with it.

I also was not able to come up with a good way to 'fix' this. One thing I tried was to disable clearing the line. This looks better, but the spinner still skips around and doesn't run smoothly. Plus, there is no obvious way to add the ability to make clearing the line optional. I also don't feel that I know enough about rich to offer up a solution that works well in the general case.

My solution for this was to create my own status object. Before I was using rich I was doing this. At the time, I was trying to avoid dependencies so I took the code from the yaspin library and adapted it for my needs. I now modified my code again, incorporating rich into it to get the styling, but handling all of the updating, threading, and anything else on my own. I only use this for Windows legacy, otherwise it uses the Status class from rich (see here). As far as I can tell, this is the best solution, and for me it is perfectly adequate as it works really well.

Hope this was helpful/interesting to you @jayaddison or anyone else who happens to look at it 🍻

dunkmann00 avatar Dec 18 '22 17:12 dunkmann00

Nice findings, definitely interesting @dunkmann00. Two questions that spring to mind are:

  • You mention you were able to use an alternative library/component implementation: does that mean that it's possible to get the correct-and-intended rendering behaviour (spinner without flickering) by substituting some of the implementation? (if so: that means it's highly likely that this is a bug, and something that could be improved/fixed)

  • What intrinsically is it about rich in combination with your application that makes this occur? (seems like we're narrowing down on this -- and definitely have some strong clues, but the root cause remains elusive)

jayaddison avatar Dec 19 '22 00:12 jayaddison

You mention you were able to use an alternative library/component implementation: does that mean that it's possible to get the correct-and-intended rendering behaviour (spinner without flickering) by substituting some of the implementation? (if so: that means it's highly likely that this is a bug, and something that could be improved/fixed)

My implementation is different enough that I wouldn't make the assertion it's likely a bug in rich. I am able to do things for a very specific situation whereas rich needs to be more generalized to handle a wider range of scenarios (multi-line, changing status text, printing out text at the same time the status is running). Maybe its a bug, but it seems more like a limitation.

What intrinsically is it about rich in combination with your application that makes this occur? (seems like we're narrowing down on this -- and definitely have some strong clues, but the root cause remains elusive)

Good question. In your original post you asked if I had a 'near minimal program' that caused the problem. I never provided one, but here is an example that will cause it:

from rich.console import Console
import time

def main():
    console = Console()
    value = 1
    with console.status("What [cyan]will[/] [cyan bold]happen[/] [magenta]as we[/] [yellow bold]wait?[/]", spinner="bouncingBar"):
        while True:
            value *= 3
            # time.sleep(0.001)

if __name__ == '__main__':
    main()

If you uncomment the time.sleep(0.001) line, the problem goes away.

dunkmann00 avatar Dec 19 '22 02:12 dunkmann00

That's brilliant, thank you @dunkmann00.

I was on my way back here to add a delayed comment to agree that the double-call to SetConsoleTextAttribute seems odd (here, yep?) -- although my guess is that it's some kind of process to ensure that the console rendering state remains stable (maybe clearing/resetting some state?). Excellent to find some code to test with - I'll try experimenting with that here soon.

jayaddison avatar Dec 19 '22 10:12 jayaddison

The double call to SetConsoleTextAttribute is needed to make sure the state of the console is always put back to the default.

I found this SO post, thought it was relevant/interesting. The initial part of the accepted answer in particular:

You're going to run into performance problems. Console I/O, especially on Windows, is slow. Very, very slow (sometimes slower than writing to disk, even). In fact, you'll quickly become amazed how much other work you can do without it affecting the latency of your game loop, since the I/O will tend to dominate everything else. So the golden rule is simply to minimize the amount of I/O you do, above all else.

Not sure how accurate the specific claims of slowness are...but more or less this does seem to be what it feels like is happening with this issue in rich.

dunkmann00 avatar Dec 20 '22 05:12 dunkmann00

@dunkmann00 a note to let you know that I haven't forgotten about this thread and am planning to investigate further, in the still-nebuous 'soon' when I get around to it.

I was reminded of this while reading a textual blog post about performance of Python timers on the Windows platform. I realize that you're using the rich library directly and not using the textual library -- and I haven't confirmed that any of the findings there are relevant -- so take all this with a pinch of salt, but there could be some useful learnings in there.

jayaddison avatar Jan 09 '23 18:01 jayaddison

@dunkmann00 I've done a little more analysis - probably not as much as you, and I'm likely still catching up on the details (I did re-read your investigation, and it's thorough!).

It looks like you experienced this using v12.6.0 of rich, going by your poetry.lock file - could you see if the problem is reproducible when using v12.4.3 and v12.0.0? (in a VM/isolated environment, ideally - just in case any outdated transitive dependencies have had security issues since then)

(I'd like to check whether there was a behaviour or performance regression - those two versions seem like good candidates to use as initial probe points. roughly speaking this is a lazy, inefficient git bisection style search)

jayaddison avatar Jan 30 '23 11:01 jayaddison

I have Windows Terminal installed, and I explicitly set Default terminal application back to Windows Console Host and tried to replicate this issue in Command Prompt.exe. I have explicitly installed v12.6.0, and I have not been able to reproduce the error. The spinner might be "skipping" it's pattern a bit, but I'm not sure how it's meant to look in the first place.

Normal speed:

https://user-images.githubusercontent.com/17136956/221783487-6f619098-dad6-4b42-9194-8e884ae99230.mp4

Slowed down 300%:

https://user-images.githubusercontent.com/17136956/221784240-09dd73e5-6c05-447a-adbf-f4f388129a08.mp4

rlaphoenix avatar Feb 28 '23 07:02 rlaphoenix

@rlaphoenix does any flickering begin to occur after you increase the width and height (and both) of the console window to standard-ish and relatively-large-ish sizes?

jayaddison avatar Mar 07 '23 19:03 jayaddison

This is caused by cmd.exe being pretty much awful. I discovered a fix while investigating another issue, which I documented here: https://github.com/Textualize/rich/pull/3038#issuecomment-1786654627

tl;dr: Enabling Virtual Terminal support in cmd.exe is possible, and doing so fixes a large number of display issues. In your example, I can confirm this snippet fixed the flicker.

mon avatar Nov 14 '23 03:11 mon