[vim/vim] 100% cpu usage with "syntax on" and "set mouse=a" after clicking (#4828)

[James P. Harvey]

Describe the bug

When I run vim in a tty (no x server) and click using my mouse (using a text mouse cursor from gpm) CPU usage reliably goes to 100% until vim is closed.

To Reproduce
Detailed steps to reproduce the behavior:

1. Enter a tty with gpm running which gives you a mouse cursor in console. No x server. (For me, I'm running in a qemu virtual machine.)
2. Have no /etc/vimrc and in ~/.vimrc only have syntax on and set mouse=a.
3. Run vim, see CPU usage is normal
4. Click somewhere, see CPU usage go to 100% until you quit vim.

Expected behavior
CPU usage shouldn't noticeably change when a mouse click is made.

Environment (please complete the following information):

• Vim version 8.1.1776
• OS: Arch Linux, up to date
• Terminal: console (no x server)

Additional context

• I don't see 100% CPU usage when running an x server, and a terminal with vim inside it, using the x cursor!
• I'm seeing this when filetype is vim or nothing.
• I finally figured out why this was happening from an issue on the numbers plugin which I'm NOT using. Just mentioning it because @njia figured out his issue was an interaction between the mouse and syntax on.
• Turning off syntax on or mouse=a prevents the CPU usage spike.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub

[Bram Moolenaar]

Can you run Vim in a debugger to find out where it is looping?
Might also be a problem in the gpm library.

[James P. Harvey]

Sure, here is a backtrace. Feel free to let me know if there's anything else I can get from gdb that will help.

I've been able to reproduce this both with using QEMU's -usbdevice tablet for absolute mouse positioning, and without this argument using its default PS/2 mouse emulation.

I've tried reproducing this outside of a VM, but haven't gotten vim and gpm to work together on my host machine. The text mouse cursor shows up, but if I click, it's highlighting text on the tty with gpm and not passing the mouse clicks to vim. Not sure if it's because I have x running on another tty, or if it's because it's a different mouse (real one vs emulated.)

[James P. Harvey]

I've also noticed clicking isn't working as intended. Something seems off with the polling. Sounds like this could be related to the same malfunctioning code.

In normal mode, if I click on a character, the blinking cursor doesn't move. x makes the blinking cursor move, and properly removes the character at the spot that was clicked, just not the spot the blinking cursor is indicating.

Same thing with i, where the blinking cursor doesn't move, but it inserts at the intended and clicked spot.

But, something really bizarre happens with a. It's like it only checks for/handles a mouse click once per new character typed. Before pressing a, if I click in several different locations then press a and type 12345, each number shows up at one of the locations I had clicked before I started typing numbers.

I was originally using gpm's imps2 emulation, which doesn't work great because QEMU's PS/2 mouse has issues with positioning, and clicks registering in different locations than the mouse cursor shows. I found a pull-request from someone adding the vbox mouse type to gpm, and VirtualBox uses the same USB tablet emulation for absolute positioning that QEMU does. Applying and using it makes the positioning act correctly, just as the USB tablet emulation does for QEMU in x. But, the 100% CPU usage and something being off with the polling remain the same.

[John Little]

I have reproduced this. vim 8.1.1888, Ubuntu 19.04, gpm 1.20.7-5, kernel 5.0.0-25.

The mouse handling gets very lost, with mouse events queued up and vim trying to act on them after each key press. Mouse handling in nano has no problem.

I built vim v8.0.0000, from 2016, and it still has the problem. I can't say I've used vim in the linux console with the mouse in the last three years, though. I wonder if anyone has.

[Bram Moolenaar]

> Sure, here is a
> [backtrace](https://github.com/vim/vim/files/3513745/gdb.noansi.txt).

> Feel free to let me know if there's anything else I can get from gdb
> that will help.

That's the normal place to wait for input. I guess the problem is that
select() indicates there is something to read, Vim reads it (of fails to
read it) and calls select() again, looping over that.

> I've been able to reproduce this both with using QEMU's `-usbdevice
> tablet` for absolute mouse positioning, and without this argument
> using its default PS/2 mouse emulation.
>
> I've tried reproducing this outside of a VM, but haven't gotten vim
> and gpm to work together on my host machine. The text mouse cursor
> shows up, but if I click, it's highlighting text on the tty with gpm
> and not passing the mouse clicks to vim. Not sure if it's because I
> have x running on another tty, or if it's because it's a different
> mouse (real one vs emulated.)

Since this is timing sensitive, what works best is to enable logging:

call ch_logfile('log', 'w')

And build Vim with ch_log() calls in a few places, like this:

ch_log(NULL, "now the value is %d", value);

I would do this near the start of RealWaitForChar() and below select(),
so you can check if it's looping inside RealWaitForChar() or at a higher
level. Then see what gets into the "log" file.

--
From "know your smileys":
|-P Reaction to unusually ugly C code

/// Bram Moolenaar -- Br...@Moolenaar.net -- http://www.Moolenaar.net \\\
/// sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ \\\
\\\ an exciting new programming language -- http://www.Zimbu.org ///
\\\ help me help AIDS victims -- http://ICCF-Holland.org ///

[James P. Harvey]

Noticed another oddity. In the VM, vim only receives clicks from gpm and goes into 100% CPU usage when being ran as root. When being ran as a regular user, vim doesn't receive clicks from gpm (clicks just highlight text on the screen from the tty) and CPU usage doesn't spike. I'd be curious to know if @jlittlenz reproduced this problem as root or non-root.

---

The loop is in inchar_loop(). It's called repeatedly, but mch_inchar() is called a handful of times.

The number of times RealWaitForChar() is called is identical to the times select() is called within it, so no looping in there.

I changed inchar_loop() to be function_with_logging.c.txt. Additionally, I log ret from RealWaitForChar::select() and the result immediately calculated after select().

In this attachment, I put a comment on each logging line showing the number of times it's logged. There are also 143172 looking for messages on channels, 143174 WaitForChar(), 143174 WaitForCharOrMouse(), and 143203 RealWaitForChar().

I don't know if the actual log will be needed with my summary of it below and the annotations in the attachment code, but here is the 50MB log

When vim starts, I did nothing. There's a reasonable 88 log lines.

At 4 seconds, I moved the mouse. There's a reasonable 35 log lines.

At 9.8 seconds, I left clicked. This is when 100% CPU usage starts. At this point, the blinking cursor hasn't moved. The main repetition is:

(Looking at function_with_logging.c.txt will give this output context in what parts of inchar_loop() is being ran.)

1
2
looking for messages on channels
3
4
10
11
13
WaitForChar()
WaitForCharOrMouse()
RealWaitForChar()
ret: 1
result: 0
20

At 14.9 seconds, I pressed the up arrow. That's when the cursor moves. It repeatedly shows:

1
2
looking for messages on channels
3
5
7
7a
7a: elapsed_time [starts at 0, grows to 4000, re-running on same number many times]
7a+: wait_time [starts at 4000, shrinks to 0, re-running on same number many times]
10
11
13
WaitForChar()
WaitForCharOrMouse()
RealWaitForChar()
ret: 1
result: 0
20

After elapsed_time becomes 4000 and wait_time becomes 0, it goes back into the previous 1-2-looking-3-4-10-11-13-WaitForChar-WaitForCharOrMouse-RealWaitForChar-20 loop.

Somewhere around the end (maybe around 19.8) is where I typed :q<cr>.

[John Little]

I'd be curious to know if @jlittlenz reproduced this problem as root or non-root.

It was with my normal login.

[Bram Moolenaar]

James Harvey wrote:

> Noticed another oddity. In the VM, vim only receives clicks from gpm and goes into 100% CPU usage when being ran as root. When being ran as a regular user, vim doesn't receive clicks from gpm (clicks just highlight text on the screen from the tty) and CPU usage doesn't spike. I'd be curious to know if @jlittlenz reproduced this problem as root or non-root.
>
> ---
>
> The loop is in `inchar_loop()`. It's called repeatedly, but `mch_inchar()` is called a handful of times.

>
> The number of times `RealWaitForChar()` is called is identical to the times `select()` is called within it, so no looping in there.
>

> I changed `inchar_loop()` to be [function_with_logging.c.txt](https://github.com/vim/vim/files/3518431/function_with_logging.c.txt). Additionally, I log `ret` from `RealWaitForChar::select()` and the `result` immediately calculated after `select()`.
>
> In this attachment, I put a comment on each logging line showing the number of times it's logged. There are also 143172 `looking for messages on channels`, 143174 `WaitForChar()`, 143174 `WaitForCharOrMouse()`, and 143203 `RealWaitForChar()`.
>
> I don't know if the actual log will be needed with my summary of it below and the annotations in the attachment code, but here is [the 50MB log](https://paste.c-net.org/RowingShunned)

>
> When vim starts, I did nothing. There's a reasonable 88 log lines.
>
> At 4 seconds, I moved the mouse. There's a reasonable 35 log lines.
>
> At 9.8 seconds, I left clicked. This is when 100% CPU usage starts. At this point, the blinking cursor hasn't moved. The main repetition is:
>

> (Looking at [function_with_logging.c.txt](https://github.com/vim/vim/files/3518431/function_with_logging.c.txt) will give this output context in what parts of `inchar_loop()` is being ran.)

Thanks for digging into this. To me it sounds like we detect that the
mouse click is done, but reading it from GPM somehow fails, and it keeps
indicating that there is something to read.

So does "gpm_process_wanted" gets set as expected? And is
mch_gpm_process() then called?
Then what does Gpm_GetEvent() do? Perhaps it returns some error?

--
Warning label on a superhero Halloween costume:
"Caution: Cape does not enable user to fly."

/// Bram Moolenaar -- Br...@Moolenaar.net -- http://www.Moolenaar.net \\\
/// sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ \\\
\\\ an exciting new programming language -- http://www.Zimbu.org ///
\\\ help me help AIDS victims -- http://ICCF-Holland.org ///

—

[John Little]

It occurred to me to check out some older versions. I booted into a few isos I had lying around:

OS                gpm      kernel    vim      result
Ubuntu 16.04.5    1.20.4   4.15.0    7.4.1689  fail
Ubuntu 18.04      1.20.7   4.15.0    8.0.1453  fail
Gentoo            1.20.7   4.14.70   8.0.1298  pass

(The Gentoo was from systemrescuecd 5.3.1.)

This suggests gpm support in vim has been broken for years on Ubuntu. Booting from an iso means I didn't pick up any settings or customization that I've set. The only common thing in these tests is the hardware.

[Christian Brabandt]

could also be a kernel thing :( Can this be reported to Ubuntu please?

[Christian Brabandt]

Oh and can you also test and build an uptodate vim on Gentoo and check if it works then?

[James P. Harvey]

brammool wrote:

Thanks for digging into this. To me it sounds like we detect that the mouse click is done, but reading it from GPM somehow fails, and it keeps indicating that there is something to read. So does "gpm_process_wanted" gets set as expected? And is mch_gpm_process() then called? Then what does Gpm_GetEvent() do? Perhaps it returns some error?

You're welcome. Sorry I've been tied up for a few days to get answers to your questions.

I dug into os_unix.c::WaitForCharOrMouse(). During the 100% CPU usage:

• if (!ignore_input && input_available()) is false
• FEAT_MOUSE_DEC is defined, but WantQueryMouse is false, so it doesn't enter the if block for potentially running mch_write
• FEAT_MOUSE_GPM is defined, so it enters the if defined block
  • FEAT_XCLIPBOARD is undefined, so it doesn't run do_xterm_trace() or set rest
  • It enters the do/while
  • • FEAT_XCLIPBOARD is undefined, so we don't look at rest
  • • FEAT_SOUND_CANBERRA is defined, but has_sound_callback_in_queue() is false
  • • FEAT_MOUSE_GPM is defined
  • • • It sets gpm_process_wanted = 0
  • • • RealWaitForChar() sets avail to 0, and sets gpm_process_wanted to 1
  • • • !avail
  • • • • !ignore_input && input_available() is false, so it doesn't return
  • • • • FEAT_XCLIPBOARD is undefined, so it doesn't look at rest or do_xterm_trace()
  • • • • it breaks
  • Because FEAT_MOUSE_GPM was defined, at the bottom, it doesn't call RealWaitForChar()
• It returns 0

So, it never calls mch_gpm_process because of the break in the do/while caused by !avail

---

I used the idea by @jlittlenz, but used the official Arch ISO's:

• 2016.01.01 no CPU usage after click, and moves cursor right away
  • linux 4.3.3-2
  • vim 7.4.944
  • gpm 1.20.7-6
• 2016.02.01 100% CPU after click, and doesn't move right away
  • linux 4.4.1-2
  • vim 7.4.1386-1
  • gpm 1.20.7-6

On an up to date system (linux 5.2.9 and gpm 1.20.7.r27) verified vim 7.4.944 doesn't have the bug and 7.4.1386 does, so I bisected between the two.

vim 7.4.1350 ec70bdd introduces the bug, which modifies WaitForChar().

With a relatively quick glance, I don't see why this introduces the bug, so I've quadruple checked this is really what introduces it. (Unless that's a different bug with the same symptoms that the monthly ISO then code bisect happened to point to.)

---

Digging a bit at RealWaitForChar():

• Called with fd=0, msec=2800 to start and down to 538, check_for_gpm=0 (tens of thousands of times, vs NULL only 31 times), interrupted=1 (tens of thousands of times, vs NULL only 32 times)
• HAVE_SELECT is defined
• to_wait >= 0 usually
• FEAT_MOUSE_GPM is defined, and check_for_gpm != NULL && gpm_flag && gpm_fd >= 0 is true
  • Call FD_SET
  • ret is set to select() return of 1
  • result is set to 0. ret == 1, and I've confirmed FD_ISSET(fd, &rfds) is false
  • • This is what 7.4.1350 introduced
  • result is false, and interrupted != NULL && ret > 0 is true, so set *interrupted to true
  • FEAT_MOUSE_GPM is defined, and ret > 0 && gpm_flag && check_for_gpm != NULL && gpm_fd >= 0 is true, and FD_ISSET(gpm_fd, &rfds) is true, so set *check_for_gpm to 1
• Returns 0

[John Little]

@chrisbra:

Oh and can you also test and build an uptodate vim on Gentoo and check if it works then?

I'm sorry, I can't replicate my earlier finding of a functional vim with gpm on gentoo. I think I was booting a very old systemrescuecd USB stick which I can't now persuade the UEFI on my computer to boot from at all (it can be quite capricious, it won't do any BIOS boot at all, and a few days ago it would only do a BIOS boot from a USB). I decided to install gentoo to check it out, not realizing how long that learning curve would be, and it became a matter of pointless obstinacy. I got there eventually, built an up to date vim with gpm, and it is just as broken as on Ubuntu. A minimal gentoo would, I imagine, be a reasonable use case for vim + gpm.

[Bram Moolenaar]

Closed #4828 via b5432d8.

[Bram Moolenaar]

James P. Harvey wrote:

> brammool wrote:
> > Thanks for digging into this. To me it sounds like we detect that
> > the mouse click is done, but reading it from GPM somehow fails, and
> > it keeps indicating that there is something to read. So does
> > "gpm_process_wanted" gets set as expected? And is mch_gpm_process()
> > then called? Then what does Gpm_GetEvent() do? Perhaps it returns
> > some error?
>
> You're welcome. Sorry I've been tied up for a few days to get answers to your questions.
>

> I dug into `os_unix.c::WaitForCharOrMouse()`. During the 100% CPU usage:
> * `if (!ignore_input && input_available())` is false
> * `FEAT_MOUSE_DEC` is defined, but `WantQueryMouse` is false, so it doesn't enter the if block for potentially running `mch_write`
> * `FEAT_MOUSE_GPM` is defined, so it enters the `if defined` block
> * `FEAT_XCLIPBOARD` is undefined, so it doesn't run `do_xterm_trace()` or set `rest`
> * It enters the `do`/`while`
> * * `FEAT_XCLIPBOARD` is undefined, so we don't look at `rest`
> * * `FEAT_SOUND_CANBERRA` is defined, but `has_sound_callback_in_queue()` is false
> * * `FEAT_MOUSE_GPM` is defined
> * * * It sets `gpm_process_wanted = 0`
> * * * `RealWaitForChar()` sets `avail` to `0`, and sets `gpm_process_wanted` to `1`
> * * * `!avail`
> * * * * `!ignore_input && input_available()` is false, so it doesn't return
> * * * * `FEAT_XCLIPBOARD` is undefined, so it doesn't look at rest or `do_xterm_trace()`
> * * * * it breaks
> * Because `FEAT_MOUSE_GPM` was defined, at the bottom, it doesn't call `RealWaitForChar()`
> * It returns `0`
>
> So, it never calls `mch_gpm_process` because of the `break` in the `do`/`while` caused by `!avail`

Thanks for the detailed description. So the "if (!avail)" is wrong.
I'll make a patch, I checked it makes the GPM mouse work again.
Please check it also fixes the 100% CPU problem.

--
Drink wet cement and get really stoned.

/// Bram Moolenaar -- Br...@Moolenaar.net -- http://www.Moolenaar.net \\\
/// sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ \\\
\\\ an exciting new programming language -- http://www.Zimbu.org ///
\\\ help me help AIDS victims -- http://ICCF-Holland.org ///

—

[James P. Harvey]

brammool wrote:
Thanks for the detailed description. So the "if (!avail)" is wrong. I'll make a patch, I checked it makes the GPM mouse work again. Please check it also fixes the 100% CPU problem.

Thanks for the patch! It makes the GPM mouse work as expected, and fixes the 100% CPU problem.