CrispyConductor / tmux-copy-toolkit

TMUX plugin with various copy-mode tools
MIT License
59 stars 6 forks source link

entering copy and open mode is slow. #4

Open alps2006 opened 3 years ago

alps2006 commented 3 years ago

showing the hits is slow when i trigger prefix-Q or prefix-P , Even the terminal has few contents.

CrispyConductor commented 3 years ago

Do you happen to be on a mac? I ran into a similar issue on a mac and traced it to the tmux respawn-pane command being inexplicably slow.

alps2006 commented 3 years ago

Yes, i do. My system is 10.14.6, but i don't use tmux respawn-pane command.

CrispyConductor commented 3 years ago

tmux-copy-toolkit uses tmux respawn-pane internally; it's part of how it swaps out the active pane for the pane displaying the selections. There's not really a way around using that command (or similar ones, which, iirc, had the same issue) with this architecture.

When I first looked into this, I initially suspected an issue in tmux, since it was a tmux command being slow. I ended up tracing it through tmux to try to find the source of the problem, and ended up tracing it to a Mac OS system call. Unfortunately I don't recall which system call it was, but it was something that had no business being as slow as it was; and I was unable to trace mac kernel problems any further, being closed-source and all. (Linux is my personal primary use-case anyway, so it wasn't a big issue for me.)

I just now tested it on a mac again, and interestingly, it seems to be working a lot faster than it previously did. Still not the immediate response that I'm used to on Linux machines, but it's now much more tolerable. I'm not sure exactly what change might have caused the difference. This is the same mac that I tested with before, but it has since been upgraded to Big Sur; so maybe they fixed the issue (at least partially). Currently it's on Mac OS version 11.6; so maybe upgrading might help you too?

alps2006 commented 3 years ago

Thanks for your reply. I found an interesting thing that the hints can be shown quickly when i keystroke arbitrarily before showing. I figured out a way that simulating a key event after redraw() method. So this is my solution temporarily.

M copytk.py
@@ -15,6 +15,7 @@ import shutil
 from datetime import datetime
 import time
 import platform
+import keyboard

 #logdir = '/tmp/copytklog'
 logdir = None
@@ -667,6 +668,7 @@ class PaneJumpAction:
                pass
        # refresh
        self.stdscr.refresh()
+       keyboard.press_and_release('left')

    def setstatus(self, msg):
        self.status_msg = msg
CrispyConductor commented 3 years ago

That's interesting, it sounds like it's entirely unrelated to the issue I encountered earlier. I wonder which process is capturing and acting on that keystroke. I'm not able to reproduce this myself, but a couple of questions might help figure out what's going on:

alps2006 commented 3 years ago

Approximately how long is the delay between hitting Ctrl-Q and the matches appearing?

It's about 4 seconds to appear the matches.

Pressing left arrow at any point during the delay causes the matches to immediately appear with effectively no further delay, right?

Yes, it is faster than before. it's less than 1 second to show the matches.

What happens if the key you press is a key that corresponds to one of the matches? Is that keypress ignored? Or does it cause the match to be selected with copytk?

The match will be selected when i press a key that corresponds to a match immediately.

...... It's disappointing. The matches appear delay as ever when i ssh to the host.

CrispyConductor commented 3 years ago

Wow, I didn't realize it was quite as slow as 4 seconds. That's not really usable.

Over SSH, does manually pressing a key yourself speed up the delay, or did you just try it with your temporary fix in the code? (I wouldn't expect the temp fix to work over SSH since the python 'keyboard' module simulates the attached physical keyboard device rather than sending keystrokes to whatever tty the python process is running in.)

The match will be selected when i press a key that corresponds to a match immediately.

This suggests a double-buffering issue in curses or tmux or something. The fact that copytk recognizes the keystroke even when the matches are not displayed indicates that copytk is running and accepting the keystroke, but its screen content is not being rendered. In the code, copytk never listens for a keystroke without first telling curses to render the screen, so this behavior shouldn't be possible within copytk alone.

I'm not sure which component involved could be responsible for not rendering the updated screen. I'd suspect curses or tmux, or possibly a race condition between the two; but those aren't the only possibilities.

There are a few diagnostic things you could potentially do to get more information:

  1. Run the copytk process independently outside of tmux, and see if the issue persists.

This is a little tricky to do since copytk still expects a tmux session to be running and properly set up. You can do this by:

a. Run a tmux session in a terminal. Set it up however you normally would, and select the (not zoomed) window/pane you want to use as a test case.

b. Get info about the selected pane (with the ) by running (outside of tmux): `tmux list-panes -F '#{?pane_active,, } Session ID: #{session_id} Window ID: #{window_id} Pane ID: #{pane_id} Pane size: #{pane_width}x#{pane_height}'`

c. Create a new dummy window and pane: tmux new-window -dPF '#{?pane_active,*, } Session ID: #{session_id} Window ID: #{window_id} Pane ID: #{pane_id} Pane size: #{pane_width}x#{pane_height}' and note down the returned info.

d. In a terminal outside of tmux, run copytk directly: python3 copytk.py --run-internal --orig-window '<First_Window_Id>' -t '<First_Pane_Id>' --hidden-window '<Second_Window_Id>' --hidden-t '<Second_Pane_Id>' --swap-mode pane-swap quickcopy example: python3 copytk.py --run-internal --orig-window '@1' -t '%8' --hidden-window '@10' --hidden-t '%17' --swap-mode pane-swap quickcopy

The contents of the initial tmux pane should then appear with the matches. If this occurs without delay when run outside of tmux, then the rendering refresh issue likely lies within tmux. If the delay still occurs, I'd suspect curses, but not sure.

  1. It's possible the issue might be caused by some sort of race condition if curses tries to refresh the screen at exactly the same time tmux swaps the pane in. You might be able to test this by adding an intentional delay (maybe 1s, something easily distinguishable from the usual 4s delay you're getting) in copytk before it renders the screen. A good place to add this test delay might be around line 1007 in copytk.py, just before the call to self.redraw(). If this fixes the issue (or rather, reduces the delay to whatever delay you intentionally add as a test), then that suggests a race condition between curses rendering the screen and tmux swapping in the pane.

  2. Use the copytk logger/profiler to see if there's any useful information in there. I kind-of doubt it, since this seems to be a screen refresh issue external to copytk, but I don't know for certain. Change the definition of logdir at the top of copytk.py to something other than None. The log will output granular timestamps for each internal copytk operation which would show exactly where the delay is. But my expectation, based on what you've said, is that it would just show that it had already rendered the screen and is waiting for the match keypress.

hupfdule commented 1 year ago

I have the same problem.

As there was no new response from OP, i tried your diagnostics:

  1. This immediately shows all the selections. There is absolutely no delay.
  2. No, this seems to add to the already existing delay.
  3. I don’t see any delay in that log. Nevertheless I inlude its contents here:
    2023-06-29 15:10:30.302843: running wrapper
    2023-06-29 15:10:30.302948: run tmux: display-message -p #{session_id} #{window_id} #{pane_id} #{pane_width} #{pane_height} #{window_zoomed_flag} #{cursor_x} #{cursor_y} #{copy_cursor_x} #{copy_cursor_y} #{pane_mode} #{scroll_position}
    2023-06-29 15:10:30.305995: tmux returned
    2023-06-29 15:10:30.306043: run tmux: new-window -dP -F #{session_id}:#{window_id} /bin/cat
    2023-06-29 15:10:30.309720: tmux returned
    2023-06-29 15:10:30.309763: run tmux: display-message -p -t $2:@41 #{session_id} #{window_id} #{pane_id} #{pane_width} #{pane_height} #{window_zoomed_flag} #{cursor_x} #{cursor_y} #{copy_cursor_x} #{copy_cursor_y} #{pane_mode} #{scroll_position}
    2023-06-29 15:10:30.312220: tmux returned
    2023-06-29 15:10:30.312323: wrapper triggering hidden pane respawn of inner process
    2023-06-29 15:10:30.312344: run tmux: respawn-pane -k -t $2:@41.%46 python3 "/home/mherrn/.tmux/plugins/tmux-copy-toolkit/copytk.py" '--run-internal' '-t' '%20' '--hidden-t' '%46' '--hidden-window' '@41' '--orig-window' '@16' '--swap-mode' 'pane-swap' "quickopen"
    2023-06-29 15:10:30.315389: tmux returned
    2023-06-29 15:10:30.375790: start run easymotion internal
    2023-06-29 15:10:30.375854: run tmux: display-message -p -t %20 #{session_id} #{window_id} #{pane_id} #{pane_width} #{pane_height} #{window_zoomed_flag} #{cursor_x} #{cursor_y} #{copy_cursor_x} #{copy_cursor_y} #{pane_mode} #{scroll_position}
    2023-06-29 15:10:30.378231: tmux returned
    2023-06-29 15:10:30.378278: run tmux: capture-pane -p -t $2:@16.%20
    2023-06-29 15:10:30.379946: tmux returned
    2023-06-29 15:10:30.379988: run tmux: capture-pane -p -J -t $2:@16.%20
    2023-06-29 15:10:30.381455: tmux returned
    2023-06-29 15:10:30.381512: run tmux: display-message -p -t %46 #{session_id} #{window_id} #{pane_id} #{pane_width} #{pane_height} #{window_zoomed_flag} #{cursor_x} #{cursor_y} #{copy_cursor_x} #{copy_cursor_y} #{pane_mode} #{scroll_position}
    2023-06-29 15:10:30.382982: tmux returned
    2023-06-29 15:10:30.383057: run tmux: show-options -g
    2023-06-29 15:10:30.384996: tmux returned
    quickcopy run
    Matching against expr (?:^|[][\s:=,#"{}()'])([a-zA-Z][a-zA-Z0-9]{1,5}://(?:[a-zA-Z0-9_]+(?::[a-zA-Z0-9_-]+)?@)?(?:(?:[a-zA-Z0-9][\w-]*\.)*[a-zA-Z][\w-]*|(?:[0-2]?[0-9]{1,2}\.){3}[0-2]?[0-9]{1,2})(?::[0-9]{1,5})?(?:/(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)?/?)?(?:\?(?:(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)+(?:=(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)?)?&)*(?:(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)+(?:=(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)?)?)?)?(?:#(?:(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)+(?:=(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)?)?&)*(?:(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)+(?:=(?:[\w.~%/&-]+|(?:[\w.~%/&-]*\([\w.~%/&-]*\)[\w.~%/&-]*)+)?)?)?)?)(?:$|[][\s:=,#"{}()'])
    Found match: (275, 308): https://github.com/hupfdule/apron
    Found match: (327, 369): https://github.com/hupfdule/apron/releases
    Found match: (386, 429): https://javadoc.io/doc/de.poiu.apron/apron/
    Found match: (447, 504): https://github.com/hupfdule/apron/blob/master/LICENSE.txt
    Found match: (523, 555): https://github.com/hupfdule/kilt
    Found match: (578, 635): https://logging.apache.org/log4j/2.x/log4j-jul/index.html
    Found match: (657, 703): https://www.slf4j.org/legacy.html#jul-to-slf4j
    Matching against expr (?:^|[][\s:=,#$"{}<>()`'])((?:/|~/|[A-Z]:[\\/])(?:(?:(?:[a-zA-Z0-9_-]{1,80}|\.|\.\.)|[a-zA-Z0-9_-]{1,60}\\? [a-zA-Z0-9_-]{1,60})[\\/])*(?:(?:(?:[a-zA-Z0-9_-]{1,80}|\.|\.\.)|[a-zA-Z0-9_-]{1,60}\\? [a-zA-Z0-9_-]{1,60})\.[a-zA-Z0-9]{1,6}|(?:[a-zA-Z0-9_-]{1,80}|\.|\.\.)[\\/]?))(?:$|[][\s:=,#$"{}<>()`'])
    got matches
    start arrange_matches
    arranged matches
    2023-06-29 15:10:30.392618: run tmux: swap-pane -s %46 -t %20
    2023-06-29 15:10:30.394513: tmux returned
    swapped in hidden pane

But I suspect one misconception. It doesn’t take that long until the panes “shadow buffer” is displayed, but until the possible selections are displayed (but maybe you already understood this correctly). However, I have taken a screencast to visualize the problem.

https://github.com/CrispyConductor/tmux-copy-toolkit/assets/36069345/ead67db8-71b1-4bc7-ae9c-35dd028b032b