Xvnc consumes 100% CPU usage after client disconnects

[Tristan Schmelcher]

I have been experiencing this bug for several years but I finally decided to investigate it. I run Xvnc through xinetd and I often find that there are left-over Xvnc processes each consuming 100% CPU. They tend to crop up when a client disconnects. In particular, scanning ports with nmap produces the problem every time.

I used gdb to capture a few stack traces of the offending code:

(gdb) bt
#0 0x00007f468f811c1f in _IO_vfprintf_internal (s=<value optimized out>,
    format=<value optimized out>, ap=<value optimized out>) at vfprintf.c:1542
#1 0x00007f468f81bb24 in __fprintf (stream=<value optimized out>,
    format=<value optimized out>) at fprintf.c:33
#2 0x000000000055ddbe in rfb::Logger_File::write (this=0xaa9cc0, level=0,
    logname=0x7b4b14 "XserverDesktop",
    message=0x7ffff1070a60 "XserverDesktop::wakeupHandler: unable to accept new connection: Invalid argument (22)") at Logger_file.cxx:88
#3 0x000000000054b989 in rfb::Logger::write(int, const char *, const char *, typedef __va_list_tag __va_list_tag *) (this=0xaa9cc0, level=0,
    logname=0x7b4b14 "XserverDesktop",
    format=0x7b4c08 "XserverDesktop::wakeupHandler: %s", ap=0x7ffff1071a90)
    at Logger.cxx:76
#4 0x000000000053db47 in rfb::LogWriter::error(char const*, ...) ()
#5 0x00000000005438ed in XserverDesktop::wakeupHandler(fd_set*, int) ()
#6 0x000000000053c054 in vncWakeupHandler ()
#7 0x000000000042809b in WakeupHandler ()
#8 0x000000000043ab17 in WaitForSomething ()
#9 0x0000000000427866 in Dispatch ()
#10 0x000000000040c2e6 in main ()

(gdb) bt
#0 0x00007f468f8a23a0 in __write_nocancel () at ../sysdeps/unix/syscall-template.S:82
#1 0x00007f468f83d773 in _IO_new_file_write (f=0x7f468fb589c0, data=<value optimized out>, n=69) at fileops.c:1276
#2 0x00007f468f83d3ba in new_do_write (fp=0x7f468fb589c0, data=0x7f4690735000 " XserverDesktop: XserverDesktop::wakeupHandler: unable to accept new\nfrom list!\nt!\nVNC.\n", to_do=69) at fileops.c:530
#3 0x00007f468f83e925 in _IO_new_do_write (fp=<value optimized out>, data=<value optimized out>, to_do=69) at fileops.c:503
#4 0x00007f468f83d51d in _IO_new_file_xsputn (f=0x7f468fb589c0, data=0x7b79ea, n=1) at fileops.c:1358
#5 0x00007f468f8109b6 in _IO_vfprintf_internal (s=0x7f468fb589c0, format=0x7b79ea "\n%*s", ap=0x7ffff10708f0) at vfprintf.c:1333
#6 0x00007f468f81bb24 in __fprintf (stream=<value optimized out>, format=<value optimized out>) at fprintf.c:33
#7 0x000000000055dd91 in rfb::Logger_File::write (this=0xaa9cc0, level=0, logname=0x7b4b14 "XserverDesktop", message=0x7ffff1070a94 "connection: Invalid argument (22)") at Logger_file.cxx:85
#8 0x000000000054b989 in rfb::Logger::write(int, const char *, const char *, typedef __va_list_tag __va_list_tag *) (this=0xaa9cc0, level=0, logname=0x7b4b14 "XserverDesktop", format=0x7b4c08 "XserverDesktop::wakeupHandler: %s", ap=0x7ffff1071a90) at Logger.cxx:76
#9 0x000000000053db47 in rfb::LogWriter::error(char const*, ...) ()
#10 0x00000000005438ed in XserverDesktop::wakeupHandler(fd_set*, int) ()
#11 0x000000000053c054 in vncWakeupHandler ()
#12 0x000000000042809b in WakeupHandler ()
#13 0x000000000043ab17 in WaitForSomething ()
#14 0x0000000000427866 in Dispatch ()
#15 0x000000000040c2e6 in main ()

(gdb) bt
#0 0x00007f3b454913e3 in __gxx_personality_v0 ()
   from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#1 0x00007f3b44f4c646 in _Unwind_RaiseException ()
   from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2 0x00007f3b45491a51 in __cxa_throw ()
   from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3 0x000000000057780c in network::TcpListener::accept (this=0x1d0cb40)
    at TcpSocket.cxx:417
#4 0x0000000000543863 in XserverDesktop::wakeupHandler(fd_set*, int) ()
#5 0x000000000053c054 in vncWakeupHandler ()
#6 0x000000000042809b in WakeupHandler ()
#7 0x000000000043ab17 in WaitForSomething ()
#8 0x0000000000427866 in Dispatch ()
#9 0x000000000040c2e6 in main ()

So it seems to be spending all its time on C++ exception handling and logging error messages. :/

I also got a couple profiles with oprofile, which are attached.

Note that other ppl have this problem too, e.g. http://ubuntuforums.org/showthread.php?t=172839

ProblemType: Bug
DistroRelease: Ubuntu 11.04
Package: vnc4server 4.1.1+xorg4.3.0-37ubuntu2
ProcVersionSignature: Ubuntu 2.6.38-10.46-generic 2.6.38.7
Uname: Linux 2.6.38-10-generic x86_64
NonfreeKernelModules: nvidia
Architecture: amd64
Date: Mon Aug 1 11:26:14 2011
ProcEnviron:
 LANGUAGE=en_US:en
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: vnc4
UpgradeStatus: Upgraded to natty on 2011-05-08 (85 days ago)

[Tristan Schmelcher (tschmelcher)]

Also attaching my xinetd file for Xvnc.

[Tristan Schmelcher (tschmelcher)]

I've tracked down the problem and implemented a fix. The issue is that Xvnc in inetd mode detects whether it is run as "wait" or "nowait" by checking if the inetd socket has a valid peer name with getpeername(). If it has a valid peer name then it assumes nowait mode, otherwise it assumes wait mode. But this is unreliable, because if it is run in nowait mode and a client connects and disconnects very quickly then the socket will no longer have a valid peer name when Xvnc checks and it will mistakenly use wait mode. The 100% CPU results from repeatedly trying to call accept() on the socket in the select loop.

My solution is to instead detect wait vs. nowait via getsockopt(..., SOL_SOCKET, SO_ACCEPTCONN, ...), which works reliably in both modes.

[Tristan Schmelcher (tschmelcher)]

Patch also sent to Debian at http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=640158

[Launchpad Janitor (janitor)]

This bug was fixed in the package vnc4 - 4.1.1+xorg4.3.0-37ubuntu3

---------------
vnc4 (4.1.1+xorg4.3.0-37ubuntu3) oneiric; urgency=low

  * Fix 100% CPU hang when run from inetd in nowait mode if a client
    connects and disconnects quickly (e.g., nmap). LP: #819473
    - Added patch to debian/patches/*100-percent-cpu-hang-in-inetd-mode.patch
      for reference.
 -- Tristan Schmelcher <email address hidden> Fri, 02 Sep 2011 13:42:34 -0700