[vim/vim] &columns mysteriously changes during initialization (Issue #10123)
errael
Steps to reproduce
The plugin I'm working with has had a long standing intermittent issue. &columns set on the command line did not always work. I've tried various suggestions, seemed to fix it, then it would show up again. The last time it was happening, I instrumented it. When the user command, Init, is executed the value of &columns is what I set on the command line. But occasionally some time later &columns has the default value.
NOTE: This is not an issue any more (or at least it doesn't seem to be). The plugin detects that &columns has changed, and sets it back to what it should be and the screen is drawn with the correct width. But I wanted to document it.
There's a vim script below that fails only a few percent of the time if anyone's curious. The failures are often clustered when I run it. The failures seem to happen if there's other system activity. I'm running on a big memory and SSD system; I'm beginning to think that might have something to do with the low failure rate.
Starting vim like:
gvim -f -c "set co=120" -c "Init"
Here's an excerpt to see the idea: the value of &columns occasionally changes between Boot() and Trampoline()
vim9script
command! -nargs=0 Init call Boot()
var startup_columns: number
def Trampoline(id: number)
if startup_columns != &co
Log(printf('FAIL: expected %d, got %d', startup_columns, &co))
endif
enddef
export def Boot()
startup_columns = &columns
timer_start(50, Trampoline)
enddef
If you run the script below, it creates /tmp/test_home with a .vim/pack/... and also a script. Do bash /tmp/test_home/run.sh [num-interations] to run the script. Note that when gvim is run, it uses the new directory as $HOME. It output its progress to the console and leave a log file. Notice that plugin has a DoStuff() function that does file IO, and which can be tweaked to adjust the amount of work.
Console output looks like:
...
Iteration 4: total bytes read 9876
Iteration 5: total bytes read 8649
FAIL: expected 120, got 100
Iteration 6: total bytes read 4639
Iteration 7: total bytes read 15394
FAIL: expected 120, got 100
Iteration 8: total bytes read 1275
...
Source this to create the test
vim9script
var test_home = '/tmp/test_home'
test_home->delete('rf')
var plug_dir = test_home .. '/.vim/pack/random-packages/start/columns_issue/plugin'
var lines =<< trim END
vim9script
command! -nargs=0 Init call Boot()
def Log(msg: string)
writefile([ msg ], '/dev/tty', 'a')
enddef
var iteration: any
var startup_columns: number
def Trampoline(id: number)
if startup_columns != &co
Log(printf('FAIL: expected %d, got %d', startup_columns, &co))
cq
endif
qa
enddef
var Busy: func
export def Boot()
startup_columns = &columns
iteration = g:->get('xxx', 'none')
Busy()
timer_start(50, Trampoline)
enddef
def DoStuff()
var basedir: string
var total = 0
def F(n: string)
try
var f = readfile(basedir .. '/' .. n, 'Bb')
total += len(f)
catch /.*/
Log(printf('Read of %s failed: %s', n, v:exception))
endtry
enddef
basedir = '/bin'
var dir = readdir(basedir)
for i in range(15)
F(dir[ rand() % len(dir) ])
endfor
Log(printf('Iteration %s: total bytes read %d', iteration, total))
enddef
Busy = DoStuff
END
plug_dir->mkdir('p')
lines->writefile(plug_dir .. '/script.vim')
lines =<< trim END
#!/bin/bash
i=0
bound=${1:-100}
while ((++i <= bound)); do
if HOME=TEST_HOME gvim -f -c "vim9 g:['xxx'] = $i" -c "set co=120" -c "Init"
then
echo OK $i >> TEST_HOME/log
else
echo FAIL $i >> TEST_HOME/log
fi
done
echo $(dc <<< "4k $(grep FAIL TEST_HOME/log | wc -l) \
$(wc -l < TEST_HOME/log) / 100 * p") "% failures"
END
lines->map((_, v) => substitute(v, 'TEST_HOME', test_home, ''))
lines->writefile(test_home .. '/run.sh')
Expected behaviour
Never fails.
As mentioned, I think this is no longer an issue for the plugin. It detects the problem and sets the column back to what it's supposed to be. Things work OK from that point on.
Version of Vim
8.2.4701
Environment
ubuntu (pop_os), gvim-gtk3
Logs and stack traces
No response
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
Christian Brabandt
don't know what this would cause. You may want to try to run this in the debugger and put a watchpoint on Columns
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
Bram Moolenaar
I don't think there is a point for having an issue open for this. You are most likely the only one who can debug this. And then the cause might very well not be a problem in Vim. Still, if someone sees the same issue or has a hint that is also possible with a closed issue.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
Bram Moolenaar
Closed #10123.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
@chrisbra
Thanks, I'll look around online, I'm guessing that gdb can be run from a script. In fact, if running under gdb changes timing it might happen more frequently. 10% would be a win.
You are most likely the only one who can debug this
Since the bug's hidden, it's unlikely that anyone will run the script and see how easily it reproduces for them (of course it may have been unlikely anyway). So yes, I guess it is up to me.
the cause might very well not be a problem in Vim
Like because of a window manager event?
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
7to...@gmail.com
Tom M
My message to vim_dev mailing list didn't reach GitHub. Copying:
I am experiencing something very similar. In my case it's 'lines' that is "mysteriously" changed during gVim startup.
Normally, after gVim is started, vim (:set lines? columns?) reports 24 lines and 80 columns. But sometimes starting gVim ends up with a smaller window having only 22 lines and 80 columns. In those cases the change of the window height is visible during startup: At first a 24x80 gVim window appears and even the usual intro screen is displayed for a fraction of a second. But then suddenly the window height gets cut down, the intro screen disappears (supposedly due to a redraw triggered by the window size change) and I then end up with a smaller gVim window (22x80). The clustering of the "bad" cases is similar too. When starting gVim sequentially 5 times in a row it's not uncommon that I get 1 good case and then 4 bad ones. What is also different from OP is that I have a classic spinning HDD. Not an SSD. And I do not notice any correlation between bad gVim startups and system activity.
I am on Debian 10.12 with Cinnamon Desktop Environment 3.8.8. My gVim is provided by vim-gtk 2:8.1.0875-5+deb10u2 Debian package. So it's basically Vim version 8.1.0875 with some later patches applied on top of it.
To rule out my .vimrc and plugins I just tried to start gVim a few times with "vim -g --clean" and I mostly got the same. The only notable difference was that the bad cases had 20x80 window (i.e. 2 more lines were cut compared to the bad cases without --clean).
I wonder if this can be caused by Cinnamon DE somehow. But I haven't had opportunity to test on a similar setup with different DE. What is your desktop environment, errael?
Tom
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
I've only recently moved to linux home system, running pop_os, ubuntu 21.10 based, looks like gnome 40.4.0 I recreate the problem in an fake home directory with only .vim.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
In directory where I built vim -g -O2 did
gdb --return-child-result --command=$DIR/test.gdb ./vim
where test.gdb is
### 1
break option.c:3343 if Columns == 120
commands
enable 2
disable 1
continue
end
### 2
watch Columns
commands
bt
continue
end
disable 2
set logging file /tmp/test_home/gdb.log
set logging redirect on
set environment HOME = /tmp/test_home
run -g -f -c "set co=120" -c "Init"
This produced the following log. You can note in the log where it gets a breakpoint processing set co=120; at which point it cancels that breakpoint and does a watch on Columns. Then later, pulled out of the main loop, it processes some signal that ends up setting the size back to 100; I think it's setting size to the terminal that started it up. Since it's running the gui, I believe it's already done that once.
Breakpoint 1 at 0x5197d6: file option.c, line 3343.
Hardware watchpoint 2: Columns
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff4e78640 (LWP 796527)]
[New Thread 0x7fffeffff640 (LWP 796528)]
[New Thread 0x7fffef7fe640 (LWP 796529)]
[New Thread 0x7fffeeffd640 (LWP 796530)]
[New Thread 0x7fffee7fc640 (LWP 796531)]
[Thread 0x7fffee7fc640 (LWP 796531) exited]
[New Thread 0x7fffee7fc640 (LWP 796532)]
[New Thread 0x7fffedffb640 (LWP 796533)]
[Thread 0x7fffee7fc640 (LWP 796532) exited]
[New Thread 0x7fffee7fc640 (LWP 796534)]
[Thread 0x7fffedffb640 (LWP 796533) exited]
[New Thread 0x7fffedffb640 (LWP 796535)]
[Thread 0x7fffee7fc640 (LWP 796534) exited]
[New Thread 0x7fffee7fc640 (LWP 796536)]
[New Thread 0x7fffed7fa640 (LWP 796537)]
[Thread 0x7fffedffb640 (LWP 796535) exited]
[Thread 0x7fffee7fc640 (LWP 796536) exited]
[Thread 0x7fffed7fa640 (LWP 796537) exited]
[New Thread 0x7fffed7fa640 (LWP 796538)]
[New Thread 0x7fffee7fc640 (LWP 796539)]
[Thread 0x7fffed7fa640 (LWP 796538) exited]
[Thread 0x7fffee7fc640 (LWP 796539) exited]
[New Thread 0x7fffee7fc640 (LWP 796540)]
Thread 1 "vim" hit Breakpoint 1, set_num_option (opt_idx=opt_idx@entry=50, varp=0x734c58 <Columns> "x", value=120, errbuf=errbuf@entry=0x7fffffffb480 "`\265\377\377\377\177", errbuflen=errbuflen@entry=80, opt_flags=opt_flags@entry=0) at option.c:3343
3343 if (curbuf->b_p_sw < 0)
Thread 1 "vim" hit Hardware watchpoint 2: Columns
Old value = 120
New value = 100
gui_get_shellsize () at gui.c:1639
1639 return OK;
#0 gui_get_shellsize () at gui.c:1639
#1 0x00000000005e6c5f in ui_get_shellsize () at ui.c:601
#2 0x00000000005c5ad5 in set_shellsize (width=width@entry=0, height=height@entry=0, mustset=mustset@entry=0) at term.c:3478
#3 0x00000000005c75fb in shell_resized () at term.c:3403
#4 0x0000000000630b95 in gui_resize_shell (pixel_width=820, pixel_height=pixel_height@entry=917) at gui.c:1589
#5 0x000000000063b971 in form_configure_event (widget=<optimized out>, event=0x7fffffffa7f8, data=<optimized out>) at gui_gtk_x11.c:4041
#6 0x00007ffff7b689b7 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#7 0x00007ffff72a7c0f in g_closure_invoke () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#8 0x00007ffff72c3ea6 in () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#9 0x00007ffff72c5296 in g_signal_emit_valist () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#10 0x00007ffff72c5ad3 in g_signal_emit () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#11 0x00007ffff7b31594 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#12 0x00007ffff79d4e61 in gtk_main_do_event () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#13 0x000000000064099e in form_send_configure (form=<optimized out>) at gui_gtk_f.c:860
#14 form_size_allocate (widget=0x7d0260, allocation=0x7fffffffa8d0) at gui_gtk_f.c:520
#15 0x00007ffff7b21c70 in gtk_widget_size_allocate_with_baseline () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#16 0x00007ffff78b46f2 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#17 0x00007ffff78b564c in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#18 0x00007ffff790bb57 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#19 0x00007ffff78b56c9 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#20 0x00007ffff7b21c70 in gtk_widget_size_allocate_with_baseline () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#21 0x00007ffff7b3e5fb in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#22 0x00007ffff72a7c0f in g_closure_invoke () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#23 0x00007ffff72c3b05 in () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#24 0x00007ffff72c5884 in g_signal_emit_valist () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#25 0x00007ffff72c5ad3 in g_signal_emit () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#26 0x00007ffff7b21ff2 in gtk_widget_size_allocate_with_baseline () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#27 0x00007ffff7b43024 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#28 0x00007ffff72c5970 in g_signal_emit_valist () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#29 0x00007ffff72c5ad3 in g_signal_emit () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#30 0x00007ffff78f8590 in () at /lib/x86_64-linux-gnu/libgtk-3.so.0
#31 0x00007ffff72c5970 in g_signal_emit_valist () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#32 0x00007ffff72c5ad3 in g_signal_emit () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#33 0x00007ffff76c4c06 in () at /lib/x86_64-linux-gnu/libgdk-3.so.0
#34 0x00007ffff76b12cd in () at /lib/x86_64-linux-gnu/libgdk-3.so.0
#35 0x00007ffff71b3e48 in () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#36 0x00007ffff71b37c4 in g_main_context_dispatch () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#37 0x00007ffff7206f08 in () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#38 0x00007ffff71b1003 in g_main_context_iteration () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#39 0x000000000063e44d in gui_mch_wait_for_chars (wtime=46) at gui_gtk_x11.c:6322
#40 0x00000000005e6b31 in ui_wait_for_chars_or_timer (wtime=<optimized out>, wait_func=0x634cb0 <gui_wait_for_chars_3>, interrupted=0x7fffffffba18, ignore_input=0) at ui.c:488
#41 0x00000000005e6662 in inchar_loop (buf=buf@entry=0x744379 <typebuf_init+57> "", maxlen=maxlen@entry=69, wtime=wtime@entry=-1, tb_change_cnt=tb_change_cnt@entry=5, wait_func=0x634ca0 <gui_wait_for_chars_or_timer>, resize_func=resize_func@entry=0x0) at ui.c:384
#42 0x00000000006324ac in gui_wait_for_chars_buf (buf=buf@entry=0x744379 <typebuf_init+57> "", maxlen=maxlen@entry=69, wtime=wtime@entry=-1, tb_change_cnt=tb_change_cnt@entry=5) at gui.c:3021
#43 0x00000000006324d5 in gui_inchar (buf=0x0, buf@entry=0x744379 <typebuf_init+57> "", maxlen=0, maxlen@entry=69, wtime=0, wtime@entry=-1, tb_change_cnt=100, tb_change_cnt@entry=5) at gui.c:3054
#44 0x00000000005e6476 in ui_inchar (buf=buf@entry=0x744379 <typebuf_init+57> "", maxlen=69, wtime=wtime@entry=-1, tb_change_cnt=tb_change_cnt@entry=5) at ui.c:226
#45 0x00000000004ad5ab in inchar (buf=0x744379 <typebuf_init+57> "", maxlen=207, wait_time=-1) at getchar.c:3651
#46 0x00000000004b1cea in vgetorpeek (advance=<optimized out>, advance@entry=1) at getchar.c:3430
#47 0x00000000004b067c in vgetc () at getchar.c:1731
#48 0x00000000004b2616 in safe_vgetc () at getchar.c:1960
#49 0x0000000000502f46 in normal_cmd (oap=oap@entry=0x7fffffffbd80, toplevel=toplevel@entry=1) at normal.c:733
#50 0x000000000066a1c6 in main_loop (cmdwin=cmdwin@entry=0, noexmode=noexmode@entry=0) at main.c:1498
#51 0x0000000000669c91 in vim_main2 () at main.c:877
#52 0x0000000000668941 in main (argc=<optimized out>, argv=<optimized out>) at main.c:424
[Thread 0x7fffee7fc640 (LWP 796540) exited]
[Thread 0x7fffef7fe640 (LWP 796529) exited]
[Thread 0x7fffeffff640 (LWP 796528) exited]
[Thread 0x7ffff4e78640 (LWP 796527) exited]
[Thread 0x7ffff5dcff00 (LWP 796523) exited]
[Inferior 1 (process 796523) exited with code 01]
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
Oops, left out an arg, --batch, when starting gdb in prev comment
gdb --batch --return-child-result --command=$DIR/test.gdb ./vim
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
Here's some results I collected. Seems to be a smoking gun.
There is some minor speculation, the sequence of events is formed by putting together different debug traces. Breakpoints in certain places prevent failure. Putting in some ch_log() could make it 100% certainty. A command line argument to do ch_logfile would be nice in general; considering that sometimes logging is needed before a user command gets control.
Here's the sequence of events that lead to mysterious column changes:
- During vim init
set col to 80 (default)
set col to 100 (cols of terminal where it started) - gui_mch_set_shell_size() message gtk for 100 col
- Process command line argument: "set co=120"
set_num_option(); Columns = 120 - gui_mch_set_shell_size message gtk for 120 col.
NOTE: at this point there are two messages to gtk about width in the pipe - Process command line argument: "Init"
def Boot() gets control, detect col == 120, does busy stuff, timer 50ms - form_configure_event()
Columns = 100 - def Trampoline() gets control, detect col == 100
- form_configure_event()
Columns = 120
NOTE: things are stable now. But the value of Columns has been bouncing around.
Typically the sequence is
- Columns = N
- gui_mch_set_shell_size N
- form_configure_event()
Confirms Column == N
But when the command line argument has "set co=XXX", Columns changes quickly and a second message gets in the pipe without the first message getting form_configure_event confirmation. The problems arise because the confirmation, form_configure_event, is used to set Columns and it's value bounces around. I'm guessing Lines has a similar issue.
I'm not familiar with gtk protocol/events, so some of my assumption on what is what may be wrong. But here are some possibilities.
- If the form_configure_event is in fact solely a reponse to gui_mch_set_shell_size (and resize doesn't come in this way) then the the form_configure events could simply be discarded.
- Could maintain a tiny queue of sent size messages, verify that received form_configure_events match what was sent and if it matches discard it and do not change Columns. If it doesn't match the size that was sent (I'm guessing this could happen if something was requested that couldn't be satisfied (like: set co=9999), then flush the queue and change Columns.
- Wait, do not processs commands while request outstanding. After sending gui_mch_set_shell_size() wait until form_configure_event is received for confirmation, before doing anything.
- Leave it as it is. Occasional mystery can spice things up, though typically you don't want it in your runtime system.
Here's one gdb output that is particularly telling. Notice how after setting columns to 120, the watch shows it going back to 100, then back to 120.
Thread 1 "vim" hit Breakpoint 1, set_num_option (opt_idx=opt_idx@entry=50,
\ varp=0x734c58 <Columns> "x", value=120, errbuf=errbuf@entry=0x7fffffffb480
\ "`\265\377\377\377\177", errbuflen=errbuflen@entry=80, opt_flags=opt_flags@entry=0)
\ at option.c:3343
3343 if (curbuf->b_p_sw < 0)
Thread 1 "vim" hit Breakpoint 3, form_configure_event (widget=0x7fffe800f650,
\ event=0x7fffffffa7f8, data=0x0) at gui_gtk_x11.c:4007
4007 {
$1 = {type = GDK_CONFIGURE, window = 0x11305b0, send_event = 0 '\000', x = 0, y = 67,
\ width = 820, height = 917}
Thread 1 "vim" hit Hardware watchpoint 2: Columns
Old value = 120
New value = 100
gui_get_shellsize () at gui.c:1639
1639 return OK;
#0 gui_get_shellsize () at gui.c:1639
#1 0x00000000005e6c5f in ui_get_shellsize () at ui.c:601
...
Thread 1 "vim" hit Breakpoint 3, form_configure_event (widget=0x7fffe800f650,
\ event=0x7fffffffa7f8, data=0x0) at gui_gtk_x11.c:4007
4007 {
$2 = {type = GDK_CONFIGURE, window = 0x11305b0, send_event = 0 '\000', x = 0, y = 67,
\ width = 980, height = 917}
Thread 1 "vim" hit Hardware watchpoint 2: Columns
Old value = 100
New value = 120
gui_get_shellsize () at gui.c:1639
1639 return OK;
#0 gui_get_shellsize () at gui.c:1639
#1 0x00000000005e6c5f in ui_get_shellsize () at ui.c:601
...
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
Bram Moolenaar
> Here's some results I collected. Seems to be a smoking gun.
> There is some minor speculation, the sequence of events is formed by
> putting together different debug traces. Breakpoints in certain places
> prevent failure. Putting in some ch_log() could make it 100%
> certainty. A command line argument to do ch_logfile would be nice in
> general; considering that sometimes logging is needed before a user
> command gets control.
>
> Here's the sequence of events that lead to mysterious column changes:
>
> set col to 80 (default)
> set col to 100 (cols of terminal where it started)
> 3. Process command line argument: "set co=120"
> set_num_option(); Columns = 120
> 4. gui_mch_set_shell_size message gtk for 120 col.
> def Boot() gets control, detect col == 120, does busy stuff, timer 50ms
> Columns = 100
> 7. def Trampoline() gets control, detect col == 100
> 8. form_configure_event()
> Columns = 120
>
>
> NOTE: things are stable now. But the value of Columns has been
> bouncing around.
changed the size after that event was put in the queue.
> Typically the sequence is
> 1. Columns = N
> 2. gui_mch_set_shell_size N
> 3. form_configure_event()
> Confirms Column == N
>
> But when the command line argument has "set co=XXX", Columns changes
> quickly and a second message gets in the pipe without the first
> message getting form_configure_event confirmation. The problems arise
> because the confirmation, form_configure_event, is used to set Columns
> and it's value bounces around. I'm guessing Lines has a similar issue.
>
> I'm not familiar with gtk protocol/events, so some of my assumption on
> what is what may be wrong. But here are some possibilities.
>
> gui_mch_set_shell_size (and resize doesn't come in this way) then the
> the form_configure events could simply be discarded.
> - Could maintain a tiny queue of sent size messages, verify that
> received form_configure_events match what was sent and if it matches
> discard it and do not change Columns. If it doesn't match the size
> that was sent (I'm guessing this could happen if something was
> requested that couldn't be satisfied (like: set co=9999), then flush
> the queue and change Columns.
> - Wait, do not processs commands while request outstanding. After
> sending gui_mch_set_shell_size() wait until form_configure_event is
> received for confirmation, before doing anything.
doesn't come we hang. We could perhaps flush the queue for certain
events before resizing?
> - Leave it as it is. Occasional mystery can spice things up, though
> typically you don't want it in your runtime system.
intentionally sets the size we can remember when that happened, and
ignore all events that are older.
--
BLACK KNIGHT: None shall pass.
ARTHUR: I have no quarrel with you, brave Sir knight, but I must cross
this bridge.
BLACK KNIGHT: Then you shall die.
"Monty Python and the Holy Grail" PYTHON (MONTY) PICTURES LTD
/// Bram Moolenaar -- ***@***.*** -- http://www.Moolenaar.net \\\
/// \\\
\\\ sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ ///
\\\ help me help AIDS victims -- http://ICCF-Holland.org ///
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
Someone familiar with the GTK protocol and events could probably easily answer your question. (If there is such a person (it's not me)).
If there is an "echo message" that simply sends back the same string, that could be used "when needed" to sync things up. That might be usable for concepts like "flush the queue"; no idea if there are sideband communications available. But the "when needed" is again something tricky and depends on knowing the GTK protocols.
Hope there's someone on the list who knows GTK.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
So the main problem is that we get a GTK event that is outdated, we changed the size after that event was put in the queue.
I don't think that's a useful way to look at it. Vim probably made a 2nd request to change the size before the first request was even seen by GTK.
Vim changes the size internally before vim even sends a message/request to GTK that it want's a different size. So any/all response from GTK will be outdated by definition. The message from vim requesting a size change is itself outdated; vim changed the size before it's own message was sent.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
I did a little looking around; found nothing about the relationship of gtk_window_resize and the configure-event callback.
For that matter, I wonder what the NULL argument on g_signal_connect is for? Or what are the UNUSED arguments in the configure-event callback? Oh, it's private data. If g_signal_connect isn't too expensive, and it's ok to call it again with the same signal name, "configure-event" in this case, but with different private data, then the private data could be used as a sequence number. Around when gtk_window_resize is sent new private-data/sequence-number could be set up. Would need to allocate a new sequence-number/gpointer so care must be taken to avoid leakage and can't deallocate an old gpointer until a message with a new/current gpointer is received. But messages with old sequence numbers could be discarded.
Since width/height are probably not changed all that often, a little extra overhead of doing g_signal_connect is probably OK.
Some special care might be needed to differentiate user intiated resize requests. But that might be as simple as if the event is not discarded because of an old sequence number, then use the event to set Columns.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.
errael
I couldn't let it go... The private data with g_signal_connect don't work as I expected; it seems to be handled through side band communications; the private data changes for all outstanding requests. The "match what was sent" approach wasn't so complicated, if there's ever an uncertainty, throw away the history and it acts like current. Here's some logging, the discard lines are marked. In a logging line, the first set of coordinates is pixels associated with the resize request and that's what's used for matching, the second is the (Columns,Rows) at the time of the logging. (And now I can take out the hardcoded ch_logfile in gui_gtk_x11.c). I'm going to muck around with it today; push something to discuss later.
=== 12
==== start log session ====
0.089445 : gui_gtk: New resize seq 1 (820, 984) (100, 57)
0.090557 : looking for messages on channels
0.142141 : columns: set_num_option: columns=120 (100, 57)
0.142352 : gui_gtk: New resize seq 2 (980, 984) (120, 57)
0.142802 : raw GUI output: "�|0;56R�|0;99V�|C�|C"
0.142821 : columns: set_num_option: columns=121 (120, 57)
0.143103 : gui_gtk: New resize seq 3 (988, 984) (121, 57)
0.143272 : columns: set_num_option: columns=122 (121, 57)
0.143460 : gui_gtk: New resize seq 4 (996, 984) (122, 57)
0.143800 : columns: set_num_option: columns=123 (122, 57)
0.146145 : gui_gtk: New resize seq 5 (1004, 984) (123, 57)
0.146286 : columns: set_num_option: columns=124 (123, 57)
0.146417 : gui_gtk: New resize seq 6 (1012, 984) (124, 57)
0.146538 : columns: set_num_option: columns=125 (124, 57)
0.146667 : gui_gtk: New resize seq 7 (1020, 984) (125, 57)
0.158724 : gui_gtk: form_configure_event: (996, 984) (125, 57)
0.158742 : gui_gtk: discard seq 4, cur seq 7 <<<<<<<<<<<<<<<<<<<<<
0.160234 : SafeState: Start triggering
0.164840 : gui_gtk: form_configure_event: (1020, 984) (125, 57)
0.164850 : gui_gtk: free 7 hists
0.164852 : gui_gtk: current, clear history
0.166900 : SafeState: Start triggering
0.166944 : looking for messages on channels
0.166951 : SafeState: back to waiting, triggering SafeStateAgain
0.207035 : Exiting...
OK 12
=== 13
==== start log session ====
0.087664 : gui_gtk: New resize seq 1 (820, 984) (100, 57)
0.088461 : looking for messages on channels
0.140154 : columns: set_num_option: columns=120 (100, 57)
0.140266 : gui_gtk: New resize seq 2 (980, 984) (120, 57)
0.140756 : raw GUI output: "�|0;56R�|0;99V�|C�|C"
0.140793 : columns: set_num_option: columns=121 (120, 57)
0.143109 : gui_gtk: New resize seq 3 (988, 984) (121, 57)
0.143279 : columns: set_num_option: columns=122 (121, 57)
0.143417 : gui_gtk: New resize seq 4 (996, 984) (122, 57)
0.143591 : columns: set_num_option: columns=123 (122, 57)
0.143725 : gui_gtk: New resize seq 5 (1004, 984) (123, 57)
0.143823 : columns: set_num_option: columns=124 (123, 57)
0.143904 : gui_gtk: New resize seq 6 (1012, 984) (124, 57)
0.143983 : columns: set_num_option: columns=125 (124, 57)
0.144066 : gui_gtk: New resize seq 7 (1020, 984) (125, 57)
0.149409 : gui_gtk: form_configure_event: (980, 984) (125, 57)
0.149423 : gui_gtk: discard seq 2, cur seq 7 <<<<<<<<<<<<<<<<<<<<<
0.150659 : SafeState: Start triggering
0.152670 : SafeState: Start triggering
0.152694 : looking for messages on channels
0.152699 : SafeState: back to waiting, triggering SafeStateAgain
0.156685 : gui_gtk: form_configure_event: (1020, 984) (125, 57)
0.156695 : gui_gtk: free 7 hists
0.156697 : gui_gtk: current, clear history
0.158420 : looking for messages on channels
0.158430 : SafeState: back to waiting, triggering SafeStateAgain
0.198676 : Exiting...
OK 13
—
Reply to this email directly, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.
errael
Here's a log with enable_resize_history = FALSE
Took a while for me to come to peace with this one. I think this takes the path on the main loop that goes through ui_get_shellsize to set Columns; while the plugin is running Columns doesn't match reality. I guess when the message came in around 3-, something had to be deferred (maybe because the plugin was running, or about to run). Finally, a couple tenths of a second later, in the callback, the correct value is detected. Makes sense that Columns can't change while the plugin has control (even it's in a system sleep).
==== start log session Tue Apr 12 13:14:49 2022 ====
1--- vim startup, resize gui msg to size of terminal that started vim
0.360341 : gui_gtk: New resize seq 1 (820, 984) [100, 57]
0.361109 : looking for messages on channels
0.434541 : raw GUI output: "�|0;56R�|0;99V�|C"
2--- process "-c set co=120"; resize msg
0.437240 : gui_gtk: New resize seq 2 (980, 984) [120, 57]
0.444449 : SafeState: Start triggering
0.512048 : gui_gtk: form_configure_event: (820, 984) [120, 57]
0.512067 : gui_gtk: SKIP discard seq 1, cur seq 2
0.512071 : gui_gtk: free 2 hists
0.512073 : gui_gtk: probable resize event, clearing
0.520358 : SafeState: Start triggering
3--- process "-c Init" somewhen around here executes plugin code
0.572572 : gui_gtk: form_configure_event: (980, 984) [100, 57]
0.572591 : gui_gtk: free 0 hists
0.572595 : gui_gtk: current, clear history
0.573599 : looking for messages on channels
0.573609 : SafeState: back to waiting, triggering SafeStateAgain
4--- plugin restarted by timer_start(50, Trampoline)
0.573654 : FAIL: expected 120, got 100
0.573794 : executing shell command: (sleep .1)>/tmp/voqzFom/0 2>&1
0.574817 : closing channel log in the child process
0.574852 : closing logfile /home/err/bugs/vim/columns-option-changes-unexpectedly/CH_LOG
5--- after system('sleep .1'), still wrong; do timer_start(100, yyy)
0.689161 : re-read co 100
0.711917 : looking for messages on channels
0.711930 : SafeState: back to waiting, triggering SafeStateAgain
6--- after timer, Columns is finally correct
0.789821 : From timer: co = 120
0.789907 : Exiting...
See at just after 2-, SKIP discard and go on to process the ack/event for an older resize msg and sets Columns back to 100. The event to go back to Columns=120 comes in around 3-; between 5- and 6- the event is finally process and Columns gets back to 120.
Here's the log with enable_resize_history = TRUE. The correspondence to the previous log is marked.
==== start log session Tue Apr 12 14:34:47 2022 ====
1--- vim startup, resize gui msg to size of terminal that started vim
0.351030 : gui_gtk: New resize seq 1 (820, 984) [100, 57]
0.351861 : looking for messages on channels
0.423494 : raw GUI output: "�|0;56R�|0;99V�|C"
2--- process "-c set co=120"; resize msg
0.426177 : gui_gtk: New resize seq 2 (980, 984) [120, 57]
0.443129 : SafeState: Start triggering
0.508360 : gui_gtk: form_configure_event: (820, 984) [120, 57]
0.508375 : gui_gtk: discard seq 1, cur seq 2
0.508660 : SafeState: Start triggering
3--- process "-c Init" somewhen around here executes plugin code
0.508694 : looking for messages on channels
0.508698 : SafeState: back to waiting, triggering SafeStateAgain
4--- plugin restarted by timer_start(50, Trampoline)
0.508717 : No failure
0.508734 : looking for messages on channels
0.508738 : SafeState: back to waiting, triggering SafeStateAgain
6--- Trampoline probably finishes here
0.561887 : gui_gtk: form_configure_event: (980, 984) [120, 57]
0.561903 : gui_gtk: free 2 hists
0.561906 : gui_gtk: current, clear history
0.562956 : looking for messages on channels
0.562965 : SafeState: back to waiting, triggering SafeStateAgain
0.608230 : From timer: co = 120
0.608311 : Exiting...
—
Reply to this email directly, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.
errael
Opened #10179.
—
Reply to this email directly, view it on GitHub.
You are receiving this because you are subscribed to this thread.