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

tmux uses 100% CPU stuck inside window_copy_cursor_previous_word_pos #2253

Closed
timotheecour opened this issue Jun 1, 2020 · 52 comments
Closed

Comments

@timotheecour
Copy link

timotheecour commented Jun 1, 2020

tmux froze on me for no apparent reason; here's the backtrace:
(obviously hard to reproduce but could indicate a rarely occuring bug)

Issue description

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00000001010146fe tmux`grid_line_length + 12
  frame #1: 0x000000010103f287 tmux`window_copy_cursor_previous_word_pos + 192
  frame #2: 0x0000000101040bc4 tmux`window_copy_synchronize_cursor_end + 123
  frame #3: 0x00000001010409be tmux`window_copy_set_selection + 85
  frame #4: 0x000000010103fdbc tmux`window_copy_cursor_end_of_line + 281
  frame #5: 0x000000010103ecf8 tmux`window_copy_pageup1 + 247
  frame #6: 0x00000001010423a6 tmux`window_copy_cmd_page_up + 28
  frame #7: 0x000000010103e682 tmux`window_copy_command + 300
  frame #8: 0x0000000101002919 tmux`cmd_send_keys_exec + 350
  frame #9: 0x0000000100ffffd7 tmux`cmdq_next + 453
  frame #10: 0x000000010102dc99 tmux`server_loop + 52
  frame #11: 0x000000010102349a tmux`proc_loop + 54
  frame #12: 0x000000010102d6ad tmux`server_start + 538
  frame #13: 0x0000000100ff3d2d tmux`client_main + 989
  frame #14: 0x000000010103518b tmux`main + 1788
  frame #15: 0x00007fff71963cc9 libdyld.dylib`start + 1

Required information

  • tmux version (tmux -V).
    tmux 3.1a

  • Platform (uname -sp).
    Darwin i386

  • $TERM inside and outside of tmux (echo $TERM).
    xterm-256color

  • Logs from tmux (tmux kill-server; tmux -vv new).

@nicm
Copy link
Member

nicm commented Jun 1, 2020

I don't see anything obvious. I assume it was in an infinite loop (100% CPU) rather than frozen?

If you can reproduce, then it would be interesting to try and work out what it is looping around (one way is to attach lldb and continue/^C a few times and see what the common frame is - is it always in grid_line_length?).

Also you can attach lldb and make a coredump (process save-core /tmp/corefile) and it would be good to see what is in *gd and px in frame 0 and maybe some stuff from other frames.

@timotheecour
Copy link
Author

I assume it was in an infinite loop (100% CPU) rather than frozen?

correct (appears frozen ie unresponsive but eating 100% CPU)

If you can reproduce

i wish :) already killed server though

one way is to attach lldb and continue/^C a few times and see what the common frame is - is it always in grid_line_length?

that i had done; it was always either in grid_line_length or its parent frame window_copy_cursor_previous_word_pos

Also you can attach lldb and make a coredump (process save-core /tmp/corefile) and it would be good to see what is in *gd and px in frame 0 and maybe some stuff from other frames.

iirc that's linux? I'm on OSX; also, i don't know how to reproduce... i was just hoping there could be some easy to spot bug in one of those functions but it may be a long shot

@nicm
Copy link
Member

nicm commented Jun 1, 2020

OK well let me know if you can reproduce.

lldb is OS X, the backtrace you showed was from lldb, I'm not certain you can make it save a core though.

@timotheecour
Copy link
Author

feel free to close in the meantime, up to you... I'll write a note back here if it happens a again

@nicm nicm closed this as completed Jun 1, 2020
@zozowell
Copy link

+1. I ran into same situation time to time, I've upgraded to latest 3.1b, but it still happens. have to kill tmux process every time. It's on MacOS, apple terminal, mouse support on is on.

@krader1961
Copy link

@zozowell, Did you attach to the tmux server process with lldb and capture a backtrace? Does it match the backtrace in the opening comment of this issue?

@zozowell
Copy link

zozowell commented Jun 18, 2020

@krader1961 , no, I have killed my server, if it happens again I'll try to capture a trace.

@zozowell
Copy link

zozowell commented Jul 10, 2020

It happens again, I got very similar backtrace as that @timotheecour pasted in initial post:

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00000001089f2e80 tmux`grid_get_cell1
    frame #1: 0x00000001089f5617 tmux`grid_line_length + 119
    frame #2: 0x0000000108a2ae50 tmux`window_copy_cursor_previous_word_pos + 336
    frame #3: 0x0000000108a2ccf7 tmux`window_copy_synchronize_cursor_end + 135
    frame #4: 0x0000000108a2c9ad tmux`window_copy_set_selection + 93
    frame #5: 0x0000000108a2b988 tmux`window_copy_scroll_down + 168
    frame #6: 0x0000000108a2b3e4 tmux`window_copy_cursor_up + 132
    frame #7: 0x0000000108a2f30d tmux`window_copy_cmd_scroll_up + 45
    frame #8: 0x0000000108a29ea7 tmux`window_copy_command + 327
    frame #9: 0x00000001089dfc6e tmux`cmd_send_keys_exec + 350
    frame #10: 0x00000001089dd168 tmux`cmdq_next + 920
    frame #11: 0x0000000108a146cd tmux`server_loop + 61
    frame #12: 0x0000000108a07048 tmux`proc_loop + 56
    frame #13: 0x0000000108a13fb9 tmux`server_start + 553
    frame #14: 0x00000001089cd5f2 tmux`client_main + 1058
    frame #15: 0x0000000108a1d2d1 tmux`main + 1665
    frame #16: 0x00007fff73636cc9 libdyld.dylib`start + 1
    frame #17: 0x00007fff73636cc9 libdyld.dylib`start + 1

cc @krader1961

@timotheecour
Copy link
Author

@nicm nicm can we reopen? this keeps happening; tmux consumes 100% CPU and makes laptop impossibly hot.
this wasn't the case with older versions (iirc < 3.1a)

the busy loop is here:

void
proc_loop(struct tmuxproc *tp, int (*loopcb)(void))
{
  log_debug("%s loop enter", tp->name);
  do
    event_loop(EVLOOP_ONCE);
  while (!tp->exit && (loopcb == NULL || !loopcb ()));
  log_debug("%s loop exit", tp->name);
}

here are a few lldb output:

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x0000000100554c5a libevent-2.1.7.dylib`evutil_vsnprintf + 12
  frame #1: 0x0000000100556534 libevent-2.1.7.dylib`event_logv_ + 63
  frame #2: 0x00000001005566bd libevent-2.1.7.dylib`event_warn + 163
  frame #3: 0x0000000100556e7a libevent-2.1.7.dylib`select_dispatch + 492
  frame #4: 0x000000010054e50a libevent-2.1.7.dylib`event_base_loop + 633
  frame #5: 0x000000010043448c tmux`proc_loop + 40
  frame #6: 0x000000010040515b tmux`client_main + 2059
  frame #7: 0x000000010044618b tmux`main + 1788
  frame #8: 0x00007fff6e985cc9 libdyld.dylib`start + 1

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00007fff6eacf0fe libsystem_kernel.dylib`__select + 10
  frame #1: 0x0000000100556d55 libevent-2.1.7.dylib`select_dispatch + 199
  frame #2: 0x000000010054e50a libevent-2.1.7.dylib`event_base_loop + 633
  frame #3: 0x000000010043448c tmux`proc_loop + 40
  frame #4: 0x000000010040515b tmux`client_main + 2059
  frame #5: 0x000000010044618b tmux`main + 1788
  frame #6: 0x00007fff6e985cc9 libdyld.dylib`start + 1

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00007fff6eacf0fe libsystem_kernel.dylib`__select + 10
  frame #1: 0x0000000100556d55 libevent-2.1.7.dylib`select_dispatch + 199
  frame #2: 0x000000010054e50a libevent-2.1.7.dylib`event_base_loop + 633
  frame #3: 0x000000010043448c tmux`proc_loop + 40
  frame #4: 0x000000010040515b tmux`client_main + 2059
  frame #5: 0x000000010044618b tmux`main + 1788
  frame #6: 0x00007fff6e985cc9 libdyld.dylib`start + 1


(lldb) up
frame #3: 0x000000010043448c tmux`proc_loop + 40
tmux`proc_loop:
->  0x10043448c <+40>: cmpl   $0x0, 0x8(%r14)
    0x100434491 <+45>: jne    0x10043449e               ; <+58>
    0x100434493 <+47>: testq  %rbx, %rbx
    0x100434496 <+50>: je     0x100434482               ; <+30>


(lldb) up
frame #4: 0x000000010040515b tmux`client_main + 2059
tmux`client_main:
->  0x10040515b <+2059>: cmpl   $0xd9, 0x76e33(%rip)      ; client_peer + 4
    0x100405165 <+2069>: jne    0x100405199               ; <+2121>
    0x100405167 <+2071>: testb  $0x40, 0x76e13(%rip)      ; client_flags
    0x10040516e <+2078>: je     0x100405186               ; <+2102>

(lldb) up
frame #5: 0x000000010044618b tmux`main + 1788
tmux`main:
->  0x10044618b <+1788>: movl   %eax, %edi
    0x10044618d <+1790>: callq  0x10045e59a               ; symbol stub for: exit
    0x100446192 <+1795>: cmpl   $0x56, %eax
    0x100446195 <+1798>: jne    0x1004461bb               ; <+1836>


(lldb) up
frame #6: 0x00007fff6e985cc9 libdyld.dylib`start + 1
libdyld.dylib`start:
->  0x7fff6e985cc9 <+1>: movl   %eax, %edi
    0x7fff6e985ccb <+3>: callq  0x7fff6e99982e            ; symbol stub for: exit
    0x7fff6e985cd0 <+8>: hlt
    0x7fff6e985cd1 <+9>: nop

@nicm
Copy link
Member

nicm commented Jan 14, 2021

Does this still happen with master?

@timotheecour
Copy link
Author

I haven't tried; i'm on tmux 3.1a

i don't know how to reproduce

@timotheecour
Copy link
Author

timotheecour commented Jan 14, 2021

before i kill tmux, any thing simple you want me to try? (im on osx)

@nicm
Copy link
Member

nicm commented Jan 14, 2021

No just see if it goes away in master please.

@timotheecour
Copy link
Author

one more thing:

pstree 10756
--- 10756 timothee tmux display -p TMUX_PWD_#D

@veeg
Copy link

veeg commented Feb 12, 2021

I hit this issue weekly with tmux-3.1c, on fedora 33.

@veeg
Copy link

veeg commented Feb 12, 2021

Here are my observations.

It consistently spins in the two top frames, grid_line_length and window_copy_cursor_previous_word_pos. Below are randomly stopped points with the frame variables printed for both functions.

* thread #1, name = 'tmux: server', stop reason = signal SIGSTOP
    frame #0: 0x000055be698a4590 tmux`window_copy_cursor_previous_word_pos.constprop.0(wme=0x000055be69d5a690, separators=" ", ppx=0x00007ffe8bd2463c, ppy=0x00007ffe8bd24638, already=0) at window-copy.c:4130:8
   4127					px = window_copy_find_length(wme, py);
   4128	
   4129					/* Stop if separator at EOL. */
-> 4130					if (px > 0 && window_copy_in_set(wme, px - 1,
   4131					    py, separators))
   4132						break;
   4133				}
(lldb) frame variable
(window_mode_entry *) wme = 0x000055be69d5a690
(const char *) separators = 0x000055be69acf240 " "
(u_int *) ppx = 0x00007ffe8bd2463c
(u_int *) ppy = 0x00007ffe8bd24638
(window_copy_mode_data *) data = 0x000055be69d80100
(u_int) px = 0
(u_int) py = 98
(int) already = 0
(lldb) ^C
(lldb) c
Process 328221 resuming
(lldb) c
error: Process is running.  Use 'process interrupt' to pause execution.
Process 328221 stopped
* thread #1, name = 'tmux: server', stop reason = signal SIGSTOP
    frame #0: 0x000055be69864ad0 tmux`grid_line_length(gd=0x000055be69ded510, py=98) at grid.c:1380:1
   1377			px--;
   1378		}
   1379		return (px);
-> 1380	}
(lldb) frame variable
(grid *) gd = 0x000055be69ded510
(u_int) py = 98
(grid_cell) gc = {
  data = (data = "\U00000015", have = '\0', size = '\0', width = '\0')
  attr = 0
  flags = '\0'
  fg = 1
  bg = 0
  us = 1
}
(u_int) px = 0

A memory read of *gd, if at all helpful:

(lldb)  memory read 0x000055be69ded510
0x55be69ded510: 01 00 00 00 6a 00 00 00 21 00 00 00 89 00 00 00  ....j...!.......
0x55be69ded520: 8a 00 00 00 d0 07 00 00 e0 8c d9 69 be 55 00 00  ...........i.U..

Attached is also a GDB produced corefile of this point in time.
tmux-core-2253.tar.gz

@nicm
Copy link
Member

nicm commented Feb 12, 2021

Please see my last two comments.

@veeg
Copy link

veeg commented Feb 12, 2021

I built tmux from source, 679b228, and using this version to test with for the next few weeks.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

@nicm I'm using tmux next-3.3 (after your comment in #2253 (comment) recommending using master form that time) but I'm still experiencing very high constant CPU usage

1780   tmux         99.4  123 hrs  1/1    0    13    591M   0B     344M   1780  1     running  *0[1]             0.00000 0.00000    501  2957118681+ 1175437002+ 4853540+    2422530+   271747391+ 2424433+

this causes the fan to be loud, and the laptop to be hot.

can we please re-open this issue until this is resolved?

here's an example backtrace:

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00007fff6c1d1e94 libsystem_c.dylib`tzload + 1093
  frame #1: 0x00007fff6c1d1330 libsystem_c.dylib`tzsetwall_basic + 176
  frame #2: 0x00007fff6c1d3131 libsystem_c.dylib`localtime + 153
  frame #3: 0x0000000105740661 tmux`format_expand1 + 210
  frame #4: 0x00000001057451b8 tmux`format_choose + 100
  frame #5: 0x00000001057442db tmux`format_replace + 5050
  frame #6: 0x0000000105740859 tmux`format_expand1 + 714
  frame #7: 0x00000001057440da tmux`format_replace + 4537
  frame #8: 0x0000000105740859 tmux`format_expand1 + 714
  frame #9: 0x0000000105743e22 tmux`format_replace + 3841
  frame #10: 0x0000000105740859 tmux`format_expand1 + 714
  frame #11: 0x0000000105740589 tmux`format_expand_time + 38
  frame #12: 0x000000010576d480 tmux`status_redraw + 524
  frame #13: 0x000000010575ddcb tmux`screen_redraw_screen + 127
  frame #14: 0x00000001057674eb tmux`server_client_loop + 1607
  frame #15: 0x0000000105769a57 tmux`server_loop + 74
  frame #16: 0x000000010575cd2f tmux`proc_loop + 54
  frame #17: 0x0000000105769443 tmux`server_start + 633
  frame #18: 0x0000000105723d2a tmux`client_main + 1054
  frame #19: 0x0000000105771da6 tmux`main + 1948
  frame #20: 0x00007fff6c131cc9 libdyld.dylib`start + 1
  frame #21: 0x00007fff6c131cc9 libdyld.dylib`start + 1

@nicm
Copy link
Member

nicm commented Feb 16, 2021

This is different from the window copy problem. When this happens, please send the tmux server SIGUSR2 (pkill -USR2 tmux) and it should start to write a server log file in the directory where you started tmux. Let it run for 10 seconds or so and then show me the server log file.

@nicm nicm reopened this Feb 16, 2021
@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

thanks for reopening.

and it should start to write a server log file in the directory where you started tmux

@nicm
Copy link
Member

nicm commented Feb 16, 2021

Yes same to tell it to stop.

If you are on Linux you can maybe look at where /proc/1780/cwd points and it should be in that directory.

@nicm
Copy link
Member

nicm commented Feb 16, 2021

Oh wait you are on Mac. I will look and see how to find the cwd later on.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

how do I make sure I don't start exhausing my disk with the server logs? is there a reliable way to stop collecting logs if I don't know whether I ran an odd or even number of calls to pkill -USR2 tmux ?

ls ~/ | grep 2021 returns nothing.

(and I'd really rather not kill tmux server since I have sessions in use).

Appreciated.

@nicm
Copy link
Member

nicm commented Feb 16, 2021

If you do lsof -d cwd|grep tmux it will show the server's cwd which should be where it will open the log file. But if you can't find it then it probably didn't open it, there is no way to tell whether it tried or not.

It looks like it doesn't work on macOS for some reason with pkill or kill, so you can try sending it from lldb instead. If you print log_level it will show whether you are logging or not already. Note that you need to send the signal while tmux is running, then continue it to let it process it, then interrupt it to print the log level:

$ tmux display -p '#{pid}'
5920
$ lldb `which tmux` -p 5920
(lldb) process attach --pid 5920
Process 5920 stopped
....
(lldb) p log_level
(void *) $0 = 0x0000000000000000
(lldb) c
(lldb) process signal USR2
Process 5920 stopped
...
(lldb) c
(lldb) process interrupt
Process 5920 stopped
...
(lldb) p log_level
(void *) $1 = 0x0000000000000001
(lldb) q
$ lsof -d cwd|grep tmux
tmux      5918 nicholas  cwd    DIR    1,7      384 1004943002 /private/tmp
tmux      5920 nicholas  cwd    DIR    1,7      384 1004943002 /private/tmp
$ ls -l /private/tmp/tmux-server-5920.log
-rw-r--r--  1 nicholas  wheel   239K 16 Feb 08:46 /private/tmp/tmux-server-5920.log
$

So basically do this:

tmux display -p '#{pid}' # get tmux server pid
lldb `which tmux` -p $PWD # attach lldb
c # continue tmux
process signal SIGUSR2 # send signal
c # continue tmux again

And the log file should be there. Do the same thing again to turn it off.

@nicm
Copy link
Member

nicm commented Feb 16, 2021

Hmm, this just worked for me but I swear it didn't work earlier:

$ tmux display -p '#{pid}'
5969
$ kill -USR2 5969
$ ls -l tmux-server-5969.log
-rw-r--r--  1 nicholas  wheel   108K 16 Feb 08:49 tmux-server-5969.log

So you might be able to get it to work...

pgrep (and pkill but it is the same program) seems to be very unreliable on macOS, it looks like sometimes it shows tmux and sometimes not. So it seems like Apple has contrived to break it somehow.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

@nicm here are a sample of logs I obtained through your suggestion: https://gist.github.com/timotheecour/c2e19e41380d07247418deefd0e6a2cf

(It quickly reaches 500MB in a few minutes, so this is a small sample)

most of the time is spent in format_replace or format_expand1.

(I've truncated it right before it shows my env variables for privacy)

note that I wasn't doing any interaction in tmux while those logs were generated

@nicm
Copy link
Member

nicm commented Feb 16, 2021

This log is less than a second, can you show me at least 5 seconds or so? If it is big please gzip or bzip2 it, it should compress well.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

@nicm here's some important additional info:

my .tmux.conf contained:

set -g status-interval 1
set -g status-right '#[fg=black,bg=white,bold] #(bash -c "/Users/timothee/.config/tmux_status2.sh tmux_statusRight")'
set -g status-left '#[fg=colour235,bg=colour252,bold] #{pane_id} '

after I change to set -g status-interval 30, the problem seems to mostly disappear.

here's the content of tmux_status2.sh:

#!/usr/bin/env zsh
# D20190425T142950:here
# set -ue
set -u
tmux_pane_current_path() {
  tmux display-message -p "#{pane_current_path}"
}
tmux_pwd(){
  # D20181109T124247:here
  tmux showenv "$(tmux display -p "TMUX_PWD_#D")" | cut -d= -f2-
  # not as reliable (if pwd changes during a command) and has a number of issues, eg [pane_current_path returns empty when `less` (or `more`) is called · Issue #1532 · tmux/tmux](https://github.com/tmux/tmux/issues/1532)
  # tmux_pane_current_path
}

tmux_cd_pwd(){
  cd "$(tmux_pwd)"
}

tmux_statusRight(){
  (
    dir=$(tmux_pwd)
    cd "$dir"
    echo $dir" "$(git rev-parse --abbrev-ref HEAD)
  )
}

REGEX_CMD='^(tmux_statusRight|tmux_pwd|tmux_cd_pwd)$'
if (echo "$1" | grep -E -q $REGEX_CMD); then
  eval "$@"
fi

What I don't understand is why running this status line every 1 second results in sustained ~70% CPU usage. It seems to me it's a regression (IIRC (I could be wrong though) I had this running without issues in prior tmux versions, without this issue. Note that most of the cost is in the tmux specific code to update the status (format_expand1 etc).

Also note, I have ~20 tmux windows (roughly 1 pane per window), if that's relevant.

This log is less than a second, can you show me at least 5 seconds or so? If it is big please gzip or bzip2 it, it should compress well.

in light of above information, let me know if that's still needed (I'd need to redact it for privacy eg for env vars etc)

@nicm
Copy link
Member

nicm commented Feb 16, 2021

It probably takes a lot longer to expand the status line than it did before it was a format. You may be asking it to do too much work for status-interval 1. It could probably be made faster.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

EDIT: indeed, I can reproduce this issue with this simple script that simply calls date:

set -g status-interval 1
set -g status-right '#[fg=black,bg=white,bold] #(date)'

instead of using tmux_status2.sh

Even with status-interval set to 4, it uses 7 to 20% CPU. This seems to point it a regression/bug in how tmux updates status line, it shouldn't use that much CPU for something udpated every 4 seconds.

Please let me know if you can reproduce on your end.

@nicm
Copy link
Member

nicm commented Feb 16, 2021

I wonder if it is to do with #(). What if you don't use #()?

@timotheecour
Copy link
Author

same problem:
here's my minimized .tmux.conf that I've refreshed (I don't want to kill my existing panes):

set -g base-index 1
set -g pane-base-index 1

bind C-c run "tmux show-buffer | reattach-to-user-namespace pbcopy"
bind C-v run "reattach-to-user-namespace pbpaste | tmux load-buffer - && tmux paste-buffer"

setw -g mode-keys vi

if-shell "uname | grep -q Darwin" "set -g default-command \"reattach-to-user-namespace -l $SHELL \"" " "

set-option -g history-limit 50000

set -g status-interval 1
set -g status-right date5
bind r source-file /Users/timothee/.tmux.conf \; display-message "Config reloaded."

=> same problem: sustained ~20% CPU usage for tmux

@nicm
Copy link
Member

nicm commented Feb 16, 2021

So if you put just the two status line options in a new file and do:

tmux -Ltest -f new.conf new

Do you still see the problem?

@nicm
Copy link
Member

nicm commented Feb 16, 2021

See the problem with the new test server obviously, not with your existing one.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

Do you still see the problem?

good news: yes, i still see the problem, which means it should be easy to reproduce.

set -g status-interval 1
set -g status-right date6

the CPU usage seems roughly proportional to the number of windows I open in the new server, so that the CPU load may appear small with just 1 window, but grows to sustained 10% CPU with 20 windows (note: 20 empty windows; in my original case maybe the fact that the 20 windows I had were not empty caused CPU usage to be closer to 70%, or some other factor).

wild guess:

This seems to point to at least 1 bug/regression, which is that tmux updates status line of windows even if they're not in foreground. IMO a status line should (at least by default) only be updated if it's in foregreound, so that:

  • when another application is in foregreound, tmux would consume 0% CPU
  • when tmux is in foreground, the fact that we have lots of windows would be irrelevant (since only 1 window would call status refresh)

@nicm
Copy link
Member

nicm commented Feb 16, 2021

I'll try it tomorrow although I routinely have dozens of windows so I am not sure it will be quite so easy to reproduce.

Can you please do the same but add -vv, then open 20 or so windows and let it run for 20 seconds or so, then exit tmux and show me the tmux server log file.

Windows do not have status lines, only clients do and tmux will not update a client's status line if it is detached, because it doesn't exist. I don't know what you mean by foreground.

@nicm
Copy link
Member

nicm commented Feb 16, 2021

Do you mean windows as in tmux windows, or do you mean clients attached to a session in the server?

@timotheecour
Copy link
Author

windows as in tmux windows

I mean that: 20 tmux windows, each with 1 pane

@nicm
Copy link
Member

nicm commented Feb 16, 2021

OK good, the code that is O(n) with number of windows is much less than that with number of clients. There would be little we can do about the latter.

@timotheecour
Copy link
Author

timotheecour commented Feb 16, 2021

@nicm I generated the log file with -vv for your suggestion in #2253 (comment); if you still can't reproduce on your end and need to look at the log file, do have an email I can send it to? (2.4MB after compression)

i generated it as follows to avoid things like private environment variables appearing in it:

env -i HOME=/tmp/d26 TERM=xterm-256color bash
/usr/local/bin/tmux -vv -Ltest -f /Users/timothee/.tmux.temp.conf new
# open windows, etc, then get server pid via: tmux display -p '#{pid}'
zip ~/tmux-server-77098.log.zip ~/tmux-server-77098.log

in future, would be nice if there's a way to add a "privacy" option when generating such log files, eg to mask environment variables etc.

@nicm
Copy link
Member

nicm commented Feb 17, 2021

@nicm
Copy link
Member

nicm commented Feb 17, 2021

I see this, but not as dramatically as you do. It looks like strftime/localtime_r is particularly expensive on macOS and we do call it a lot, please try this: x.diff.txt

@nicm
Copy link
Member

nicm commented Feb 17, 2021

This might be better also: y.diff.txt

@nicm
Copy link
Member

nicm commented Feb 17, 2021

I think y.diff.txt can't work as it is now, please try the first one (x.diff.txt) only.

@nicm
Copy link
Member

nicm commented Feb 17, 2021

Here is latest with another fix as well:
z.diff.txt

@timotheecour
Copy link
Author

timotheecour commented Feb 17, 2021

thanks, will try tmrw (btw would git branches be easier?)

@nicm
Copy link
Member

nicm commented Feb 17, 2021

Try this one instead please actually which is a larger change and converts all the "default" format variables (those that are always added) into a table of callbacks so they are only allocated when they are actually used which should be much faster:
tmux-format-table.diff.txt

I don't like having a table and then a tree for additional format variables so I may try to get rid of the tree entirely but this will do for the moment.

@nicm
Copy link
Member

nicm commented Feb 22, 2021

I have applied this now, please let me know if you continue to see problems. Thanks!

@nicm nicm closed this as completed Feb 22, 2021
@timotheecour
Copy link
Author

timotheecour commented Mar 6, 2021

@nicm thanks for the fix! I've finally gotten around to update tmux (tmux next-3.3, via brew --HEAD) and here are my observations:

show date every 1 second, 10 tmux windows: 2.5 percent CPU
show date every 1 second, 20 tmux windows: 3.5 percent CPU
show date every 1 second, 40 tmux windows: 10 percent CPU

if i change interval, CPU decreases roughly proportionally, down to roughly 0 (even with 40 tmux windows) if i use large enough interval (eg 60 secnods)

this mostly fixes the usability problem; what I don't understand though is why CPU usage increases with number of windows, since i'd expect that:

  • only the foreground window should trigger a redraw event based on status-interval, the windows not selected as foreground should mute the timer based notifications for status interval redraw
  • when tmux isn't in foreground (not sure if this is the right term, please ask for clarification if unclear; ie in my case, when my iterm tab isn't selecting a window containing tmux), then tmux should consume 0% CPU
  • this would improve battery life when not plugged to an adapter for tmux users

note: if this isn't a good default, then at least i think it'd make sense to support as an option ability to disable status interval refresh when a tmux window isn't in foregreound; this could be implemented by having a trigger that'd disable the timer event trigger when a tmux window is being switched out to background, and renabled when switched in foreground.

@nicm
Copy link
Member

nicm commented Mar 6, 2021

tmux has to redraw the status line regardless of active window, it is part of the client not to the window. But it will need to do more work with 40 windows than with 10.

If there are 40 windows with programs generating output then tmux has to process all data whether or not they are the active window.

tmux has no way to know if you are looking at the terminal it is running in or not. It has to do the same work whether you are looking at it or doing something else.

If tmux is using too much CPU with 40 windows you could use instruments to see where it is spending most of its time.

@github-actions
Copy link

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jun 10, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Development

No branches or pull requests

5 participants