Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

slow text output on Windows #740

Closed
kaddkaka opened this issue Apr 26, 2021 · 7 comments
Closed

slow text output on Windows #740

kaddkaka opened this issue Apr 26, 2021 · 7 comments
Labels
bug Something isn't working Windows Issue applies to Microsoft Windows

Comments

@kaddkaka
Copy link

kaddkaka commented Apr 26, 2021

Describe the bug

I am running a simple python script that prints the numbers from 0 to 99_999 and the rendering time and sometimes also the runtime of that is really long in wezterm (up to 45 seconds in Full screen which is about 90x490 characters in font size 9)

Starting WSL and running the python script on the local machine gives this output:

0
1
2
[...]
99997
99998
99999

real    0m10.106s
user    0m1.406s
sys     0m3.141s

Which corresponds to the render time which is about 10 seconds. (using my phone as a timer)

If I run the same script on a remote Linux machine that I ssh to the rendering time i 5 seconds (a little bit better!) and output is:

real    0m0,310s
user    0m0,188s
sys     0m0,120s

So the render time in this case is much longer compared to what time reports.

Environment (please complete the following information):

  • OS: Windows 10 Enterprise 1809
  • Version: wezterm 20210405-110924-a5bb5be8-125-g053cb11e
  • The active keyboard layout name ENG/SE
  • Clean westerm.lua or with default_prog = {"wsl"}

To Reproduce

Python script tmp.py:

for i in range(100_000):
    print(i)

Command to benchmark:

time python3 tmp.py

Trace log from WEZTERM_LOG=trace

Parts of the trace are available here: https://pastebin.com/uQJ1n9k6
Beginning of script output:

 2021-04-26T17:13:42.811Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:13:42.811Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:13:42.814Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 25.3µs
 2021-04-26T17:13:42.817Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.8441ms
 2021-04-26T17:13:42.817Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 13.1µs
 2021-04-26T17:13:42.817Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.5896ms
 2021-04-26T17:13:42.821Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.4579ms
 2021-04-26T17:13:43.920Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('\r'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(13), repeat_count: 1, key_is_down: true }
 2021-04-26T17:13:43.920Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:13:43.921Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 23µs
 2021-04-26T17:13:43.924Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.3957ms
 2021-04-26T17:13:43.924Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 13µs
 2021-04-26T17:13:43.924Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.0959ms
 2021-04-26T17:13:43.924Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:13:43.925Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:13:43.925Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:13:43.928Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.109ms
 2021-04-26T17:13:43.942Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:13:43.943Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:13:43.943Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:13:43.943Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:13:43.945Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 21.6µs
 2021-04-26T17:13:43.947Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.4036ms
 2021-04-26T17:13:43.947Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 7.5µs
 2021-04-26T17:13:43.948Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.0977ms
 2021-04-26T17:13:43.952Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:13:43.952Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:13:43.952Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:13:43.953Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=9.6425ms
 2021-04-26T17:13:43.985Z DEBUG wezterm_term::terminalstate        > perform Print('0')
 2021-04-26T17:13:43.985Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:13:43.985Z TRACE wezterm_term::terminalstate        > print x=0 y=24 cell=Cell { text: "0", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:13:43.985Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:13:43.985Z DEBUG wezterm_term::terminalstate        > perform Print('1')
 2021-04-26T17:13:43.985Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:13:43.985Z TRACE wezterm_term::terminalstate        > print x=0 y=25 cell=Cell { text: "1", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }

Middle

 2021-04-26T17:13:44.507Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:13:44.507Z DEBUG wezterm_term::screen               > scroll_up 0..41 num_rows=1 phys_scroll=2669..2710
 2021-04-26T17:13:44.507Z DEBUG wezterm_term::terminalstate        > perform Print('2')
 2021-04-26T17:13:44.507Z DEBUG wezterm_term::terminalstate        > perform Print('6')
 2021-04-26T17:13:44.507Z DEBUG wezterm_term::terminalstate        > perform Print('8')
 2021-04-26T17:13:44.507Z DEBUG wezterm_term::terminalstate        > perform Print('3')
 2021-04-26T17:13:44.507Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:13:44.507Z TRACE wezterm_term::terminalstate        > print x=0 y=40 cell=Cell { text: "2", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:13:44.507Z TRACE wezterm_term::terminalstate        > print x=1 y=40 cell=Cell { text: "6", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:13:44.507Z TRACE wezterm_term::terminalstate        > print x=2 y=40 cell=Cell { text: "8", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:13:44.507Z TRACE wezterm_term::terminalstate        > print x=3 y=40 cell=Cell { text: "3", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }

End of output:

 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::screen               > scroll_up 0..41 num_rows=1 phys_scroll=3500..3541
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Print('9')
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Print('9')
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Print('9')
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Print('9')
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Print('9')
 2021-04-26T17:14:09.166Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)


[...]


 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::screen               > scroll_up 0..41 num_rows=1 phys_scroll=3500..3541
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('s')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('y')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('s')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print(' ')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print(' ')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print(' ')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print(' ')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print(' ')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('0')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('m')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('0')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print(',')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('1')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('2')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('3')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Print('s')
 2021-04-26T17:14:09.168Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=0 y=40 cell=Cell { text: "s", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=1 y=40 cell=Cell { text: "y", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=2 y=40 cell=Cell { text: "s", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=3 y=40 cell=Cell { text: " ", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=4 y=40 cell=Cell { text: " ", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=5 y=40 cell=Cell { text: " ", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=6 y=40 cell=Cell { text: " ", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=7 y=40 cell=Cell { text: " ", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=8 y=40 cell=Cell { text: "0", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=9 y=40 cell=Cell { text: "m", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=10 y=40 cell=Cell { text: "0", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=11 y=40 cell=Cell { text: ",", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=12 y=40 cell=Cell { text: "1", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=13 y=40 cell=Cell { text: "2", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=14 y=40 cell=Cell { text: "3", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.168Z TRACE wezterm_term::terminalstate        > print x=15 y=40 cell=Cell { text: "s", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }

Expected behavior

Faster rendering

@kaddkaka kaddkaka added the bug Something isn't working label Apr 26, 2021
@wez
Copy link
Owner

wez commented Apr 26, 2021

grepping the log for elapsed should help focus on rendering information.

Something else you may wish to try is eliminating python buffering/performance concerns; redirect the output of your python script to a file, then time cat thatfile.txt and see if that is noticeably different.

@kaddkaka
Copy link
Author

kaddkaka commented Apr 26, 2021

python tmp.py > output.txt is instantaneous, cat output.txt is slow.

@kaddkaka
Copy link
Author

Grepping for elapsed and extracting interesting parts
Before printing of 0:

 2021-04-26T17:13:42.811Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:13:42.811Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:13:42.814Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 25.3µs
 2021-04-26T17:13:42.817Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.8441ms
 2021-04-26T17:13:42.817Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 13.1µs
 2021-04-26T17:13:42.817Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.5896ms
 2021-04-26T17:13:42.821Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.4579ms
 2021-04-26T17:13:43.920Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('\r'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(13), repeat_count: 1, key_is_down: true }
 2021-04-26T17:13:43.920Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:13:43.921Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 23µs
 2021-04-26T17:13:43.924Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.3957ms
 2021-04-26T17:13:43.924Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 13µs
 2021-04-26T17:13:43.924Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.0959ms
 2021-04-26T17:13:43.924Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:13:43.925Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:13:43.925Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:13:43.928Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.109ms
 2021-04-26T17:13:43.942Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:13:43.943Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:13:43.943Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:13:43.943Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:13:43.945Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 21.6µs
 2021-04-26T17:13:43.947Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.4036ms
 2021-04-26T17:13:43.947Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 7.5µs
 2021-04-26T17:13:43.948Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.0977ms
 2021-04-26T17:13:43.952Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:13:43.952Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:13:43.952Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:13:43.953Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=9.6425ms

After printing 17:

 2021-04-26T17:13:43.989Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 37.3µs
 2021-04-26T17:13:43.999Z TRACE wezterm_gui::termwindow::render    > lines elapsed 10.001ms
 2021-04-26T17:13:43.999Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 17.9µs
 2021-04-26T17:13:44.000Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=12.5267ms
 2021-04-26T17:13:44.005Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=17.4818ms

After this all elapsed sequences look very similar with these lines, repeated every 600~ line feeds or so (After printing ..., 96082, 96669, 97256, 97843, 99017)
After line 99604:

2021-04-26T17:14:09.065Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 22.4µs
 2021-04-26T17:14:09.076Z TRACE wezterm_gui::termwindow::render    > lines elapsed 10.8457ms
 2021-04-26T17:14:09.076Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 11.6µs
 2021-04-26T17:14:09.076Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=12.2104ms
 2021-04-26T17:14:09.080Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=16.3883ms

At exit:

 2021-04-26T17:14:09.169Z TRACE wezterm_term::terminalstate        > print x=35 y=40 cell=Cell { text: ">", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:09.170Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:14:09.170Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:09.173Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 22.7µs
 2021-04-26T17:14:09.184Z TRACE wezterm_gui::termwindow::render    > lines elapsed 11.2375ms
 2021-04-26T17:14:09.184Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 11.6µs
 2021-04-26T17:14:09.184Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=12.6964ms
 2021-04-26T17:14:09.188Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=16.4594ms
 2021-04-26T17:14:16.320Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('e'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(69), repeat_count: 1, key_is_down: true }
 2021-04-26T17:14:16.320Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.323Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 45.3µs
 2021-04-26T17:14:16.327Z TRACE wezterm_gui::termwindow::render    > lines elapsed 3.3574ms
 2021-04-26T17:14:16.327Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 12.6µs
 2021-04-26T17:14:16.327Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=6.0918ms
 2021-04-26T17:14:16.328Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:14:16.328Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:14:16.328Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:14:16.331Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=9.6637ms
 2021-04-26T17:14:16.346Z DEBUG wezterm_term::terminalstate        > perform Print('e')
 2021-04-26T17:14:16.346Z TRACE wezterm_term::terminalstate        > print x=37 y=40 cell=Cell { text: "e", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:16.346Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:14:16.346Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.348Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 22.5µs
 2021-04-26T17:14:16.351Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.8947ms
 2021-04-26T17:14:16.351Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 11µs
 2021-04-26T17:14:16.351Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.279ms
 2021-04-26T17:14:16.356Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=9.6479ms
 2021-04-26T17:14:16.532Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('x'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(88), repeat_count: 1, key_is_down: true }
 2021-04-26T17:14:16.533Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.534Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 24µs
 2021-04-26T17:14:16.537Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.1964ms
 2021-04-26T17:14:16.537Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 13.5µs
 2021-04-26T17:14:16.537Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=3.7785ms
 2021-04-26T17:14:16.538Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:14:16.538Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:14:16.538Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:14:16.541Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=7.5723ms
 2021-04-26T17:14:16.541Z DEBUG wezterm_term::terminalstate        > perform Print('x')
 2021-04-26T17:14:16.541Z TRACE wezterm_term::terminalstate        > print x=38 y=40 cell=Cell { text: "x", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:16.541Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:14:16.542Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.543Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 21.7µs
 2021-04-26T17:14:16.546Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.8133ms
 2021-04-26T17:14:16.546Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 9.7µs
 2021-04-26T17:14:16.547Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.1826ms
 2021-04-26T17:14:16.551Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.6342ms
 2021-04-26T17:14:16.661Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('i'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(73), repeat_count: 1, key_is_down: true }
 2021-04-26T17:14:16.661Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.664Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 47.8µs
 2021-04-26T17:14:16.668Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:14:16.668Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:14:16.668Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:14:16.669Z TRACE wezterm_gui::termwindow::render    > lines elapsed 4.5599ms
 2021-04-26T17:14:16.669Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 23.5µs
 2021-04-26T17:14:16.669Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=7.3554ms
 2021-04-26T17:14:16.677Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=15.2525ms
 2021-04-26T17:14:16.678Z DEBUG wezterm_term::terminalstate        > perform Print('i')
 2021-04-26T17:14:16.678Z TRACE wezterm_term::terminalstate        > print x=39 y=40 cell=Cell { text: "i", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:16.678Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:14:16.678Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.682Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 28.2µs
 2021-04-26T17:14:16.685Z TRACE wezterm_gui::termwindow::render    > lines elapsed 3.1839ms
 2021-04-26T17:14:16.685Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 10.5µs
 2021-04-26T17:14:16.685Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=5.1055ms
 2021-04-26T17:14:16.689Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=9.1628ms
 2021-04-26T17:14:16.758Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('t'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(84), repeat_count: 1, key_is_down: true }
 2021-04-26T17:14:16.759Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.760Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 21.9µs
 2021-04-26T17:14:16.762Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.1422ms
 2021-04-26T17:14:16.763Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 8.9µs
 2021-04-26T17:14:16.763Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=3.5598ms
 2021-04-26T17:14:16.766Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=7.2415ms
 2021-04-26T17:14:16.768Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:14:16.768Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:14:16.768Z DEBUG wezterm_term::terminalstate        > perform Print('t')
 2021-04-26T17:14:16.768Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:14:16.769Z TRACE wezterm_term::terminalstate        > print x=40 y=40 cell=Cell { text: "t", attrs: CellAttributes { attributes: 0, intensity: Normal, underline: None, blink: None, italic: false, reverse: false, strikethrough: false, invisible: false, wrapped: false, overline: false, semantic_type: Output, foreground: Default, background: Default, fat: None } }
 2021-04-26T17:14:16.769Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:14:16.769Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:16.770Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 21.8µs
 2021-04-26T17:14:16.773Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.919ms
 2021-04-26T17:14:16.773Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 13.2µs
 2021-04-26T17:14:16.773Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=4.2725ms
 2021-04-26T17:14:16.777Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.7038ms
 2021-04-26T17:14:17.287Z TRACE wezterm_gui::termwindow::keyevent  > key_event KeyEvent { key: Char('\r'), modifiers: NONE, raw_key: None, raw_modifiers: NONE, raw_code: Some(13), repeat_count: 1, key_is_down: true }
 2021-04-26T17:14:17.287Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:17.288Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 22.8µs
 2021-04-26T17:14:17.291Z TRACE wezterm_gui::termwindow::render    > lines elapsed 2.5273ms
 2021-04-26T17:14:17.291Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 9.4µs
 2021-04-26T17:14:17.291Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=3.9244ms
 2021-04-26T17:14:17.292Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:14:17.292Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:14:17.292Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:14:17.296Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=8.7488ms
 2021-04-26T17:14:17.297Z DEBUG wezterm_term::terminalstate        > perform Control(CarriageReturn)
 2021-04-26T17:14:17.297Z DEBUG wezterm_term::terminalstate        > perform Control(LineFeed)
 2021-04-26T17:14:17.297Z DEBUG wezterm_term::screen               > scroll_up 0..41 num_rows=1 phys_scroll=3500..3541
 2021-04-26T17:14:17.297Z TRACE async_io::driver                   > block_on: completed
 2021-04-26T17:14:17.297Z TRACE window::os::windows::window        > WindowOps::invalidate calling InvalidateRect
 2021-04-26T17:14:17.298Z TRACE async_std::task::builder           > block_on
 2021-04-26T17:14:17.298Z TRACE async_io::driver                   > block_on()
 2021-04-26T17:14:17.299Z TRACE async_io::driver                   > block_on: sleep until notification
 2021-04-26T17:14:17.300Z TRACE wezterm_gui::termwindow::render    > quad map elapsed 28.3µs
 2021-04-26T17:14:17.304Z TRACE wezterm_gui::termwindow::render    > lines elapsed 3.6484ms
 2021-04-26T17:14:17.304Z TRACE wezterm_gui::termwindow::render    > quad drop elapsed 14.9µs
 2021-04-26T17:14:17.304Z DEBUG wezterm_gui::termwindow::render    > paint_impl before call_draw elapsed=5.7651ms
 2021-04-26T17:14:17.309Z DEBUG wezterm_gui::termwindow::render    > paint_impl elapsed=10.7311ms
Connection to 10.99.65.98 closed.

Summing all the paint_impl elapsed time in the entire log results in 6906.4 ms

@wez
Copy link
Owner

wez commented Apr 27, 2021

ConPTY is the WIndows PTY layer. It is implemented as a separate helper process called openconsole.exe or conhost.exe that translates between terminal escapes and the native Windows console API model. Wezterm connects to conhost via pipes, and its child processes are connected to pipes on the other end of the conhost process. All terminal output from locally spawned processes is routed via a conhost process.

I ran a variation on your test; outputting the python script to a text file and time cat the file.

wezterm start wsl -> 4.555 total
wezterm start cmd and type the file: there's no time utility, but it feels similar in speed to wsl above
wezterm ssh linuxbox and cat the file: 0.057 total
wezterm connect wsl (see multiplexing) 0.604 total

The bottom two are faster because ConPTY isn't involved.

I also tried running "Windows Terminal":

powershell -> type: felt like it took closer to 20 seconds to me (about 4-5x slower than wezterm)
wsl -> time cat: reports 5.585 seconds, but felt like it took maybe 10 seconds to render (slower than wezterm)

My conclusion from this is that the bottleneck is the windows pty layer and not wezterm itself.

I'd recommend that you consider using https://wezfurlong.org/wezterm/multiplexing.html#connecting-into-windows-subsystem-for-linux if you plan on regularly outputting large quantities of text.

@wez wez added the Windows Issue applies to Microsoft Windows label Apr 27, 2021
@wez wez changed the title Wezterm unreasonable slow rendering on Windows slow text output on Windows Apr 27, 2021
@kaddkaka
Copy link
Author

kaddkaka commented Apr 27, 2021

Here is a more thorough investigation/exploration for only printing a log file that contains 100'000 lines:

Local computer type weztest.log

  • weztermgui (C:\windows\sysstem32\cmd.exe) - 2,8s
  • cmd - 3,0s
  • alacritty (powershell) - 31s
  • powershell - 36s

Local computer cat weztest.log

  • cygwin - 3,0s

Local computer, WSL cat weztest.log

  • WSL 10,1s

SSH to remote Linux machine (ping latency 4 ms) cat weztest.log

  • alacritty - 7s (tmux 0,3s)
  • Powershell - 3s (tmux 0,4s) / wemux: 0,4
  • cmd - 2,5 secondsx (tmux 0,3s)
  • cygwin - 3,1s (tmux instant, noticeably faster than wezterm "0,06")
  • WSL - 2,3s (tmux 0,3s)
  • Wezterm - 2,6 (0,07s)
  • Wezterm ssh - 1,3s (tmux 0,06s)
  • Wezterm ssh font8 - 2,8s (tmux 0,3 s)

With tmux all of the terminals above performed a lot faster! Cygwin is the clear winner

@kaddkaka
Copy link
Author

kaddkaka commented Apr 27, 2021

So connected over ssh and attached to the same tmux3.1b session cygwin is

  • slightly faster when cating the file, and
  • much faster when running a python script that prints 0-199999

Running python3 weztest2.py

  • cygwin/mintty: 0.6s
  • wezterm ssh: 4s

Could it be that the sluggish printing from python causes wezterm to have time to draw the screen more times resulting in slower rendering in total? How does cygwin speed this up?

wez added a commit that referenced this issue Apr 29, 2021
This has the effect of reducing the memory and scroll cost
for lines that are shorter than the physical width of the
terminal matrix.

refs: #740
wez added a commit that referenced this issue Apr 29, 2021
In the situation where we have a full screen terminal (eg: 500 cells
wide), but very little output (eg: only 10's of columns on the left are
NOT blank), we would previously spend a non-trivial amount of time
calculating fg/bg colors for the blanks that trailed the actual
clusters; the calculation for each row was:

  O(trailing-blanks * full cell color compute cost)

which was around 30us per row.  For large numbers of rows this could
add up to >10ms per frame.

This commit changes the logic to run in two phases:

 * O(selection-width) with simple fg/bg color updates for the selection
   range

 * O(1) full cell color compute cost for the cursor if the cursor
   is somehow in the trailing blank region and not already handled
   by the earlier clustering logic.

With the sequence of recent commits, the frame time for the large
terminal case has been reduced from ~22ms to ~7ms, which is approx 3x
improvement.

refs: #740
@wez wez closed this as completed in f084f4d May 2, 2021
@github-actions
Copy link

github-actions bot commented Feb 4, 2023

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues. If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Feb 4, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working Windows Issue applies to Microsoft Windows
Projects
None yet
Development

No branches or pull requests

2 participants