search

Textualize / rich

Rich is a Python library for rich text and beautiful formatting in the terminal.
https://rich.readthedocs.io/en/latest/
MIT License
48.26k stars 1.7k forks source link

console.status 'blinking' artifact #2691

Open dunkmann00 opened 1 year ago

dunkmann00 commented 1 year ago

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!

github-actions[bot] commented 1 year ago

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

SertugF commented 1 year ago

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_persecond and speed arguments. Default values are :
'speed: float = 1.0 , refresh_persecond: float = 12.5,' My guess is cpu cant handle render speed which is bizarre.

jayaddison commented 1 year ago

@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)

dunkmann00 commented 1 year ago

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:

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 🍻

jayaddison commented 1 year ago

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

dunkmann00 commented 1 year ago

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.

jayaddison commented 1 year ago

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.

dunkmann00 commented 1 year ago

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.

jayaddison commented 1 year ago

@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 commented 1 year ago

@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)

rlaphoenix commented 1 year ago

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

jayaddison commented 1 year ago

@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?

mon commented 8 months ago

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.