sb-ext::run-program slow response time using threaded sbcl with poll support under slime

[Gerome Fournier]

When using emacs/slime and sbcl with thread + poll support, I noticed slow response times while executing external commands (more than 1 second to execute hostname):

CL-USER> (time (sb-ext:run-program "/bin/hostname" '()))
Evaluation took:
  1.062 seconds of real time
  0.004222 seconds of total run time (0.002214 user, 0.002008 system)
  0.38% CPU
  3,822,252,932 processor cycles
  16 bytes consed

Without thread support, or if I force slime communication style to :FD-HANDLER, I get a normal response time:

$ cat ~/.swank.lisp
(setq SWANK:*COMMUNICATION-STYLE* :FD-HANDLER)

CL-USER> (time (sb-ext:run-program "/bin/hostname" '()))
Evaluation took:
  0.051 seconds of real time
  0.001575 seconds of total run time (0.001575 user, 0.000000 system)
  3.92% CPU
  184,040,468 processor cycles
  0 bytes consed

Tests have been done under freebsd 11 / emacs 25.2.1 / slime 2.19 / sbcl 1.3.19. Same king of behavior has been reported under darwin by another user.

$ uname -a
FreeBSD foo.localdomain 11.0-RELEASE-p9 FreeBSD 11.0-RELEASE-p9 #0: Tue Apr 11 08:48:40 UTC 2017 <email address hidden>:/usr/obj/usr/src/sys/GENERIC amd64

$ sbcl --version
SBCL 1.3.19

*features*

(:QUICKLISP :SB-BSD-SOCKETS-ADDRINFO :ASDF-PACKAGE-SYSTEM :ASDF3.1 :ASDF3
 :ASDF2 :ASDF :OS-UNIX :NON-BASE-CHARS-EXIST-P :ASDF-UNICODE :64-BIT
 :64-BIT-REGISTERS :ALIEN-CALLBACKS :ANSI-CL :ASH-RIGHT-VOPS :BSD
 :C-STACK-IS-CONTROL-STACK :COMMON-LISP :COMPACT-INSTANCE-HEADER
 :COMPARE-AND-SWAP-VOPS :COMPLEX-FLOAT-VOPS :CYCLE-COUNTER :ELF :FLOAT-EQL-VOPS
 :FP-AND-PC-STANDARD-SAVE :FREEBSD :GCC-TLS :GENCGC :IEEE-FLOATING-POINT
 :IMMOBILE-CODE :IMMOBILE-SPACE :INLINE-CONSTANTS :INTEGER-EQL-VOP
 :LINKAGE-TABLE :LITTLE-ENDIAN :MEMORY-BARRIER-VOPS :MULTIPLY-HIGH-VOPS
 :OS-PROVIDES-BLKSIZE-T :OS-PROVIDES-DLADDR :OS-PROVIDES-DLOPEN
 :OS-PROVIDES-GETPROTOBY-R :OS-PROVIDES-POLL :OS-PROVIDES-PUTWC
 :OS-PROVIDES-SUSECONDS-T :PACKAGE-LOCAL-NICKNAMES :PRECISE-ARG-COUNT-ERROR
 :RAW-INSTANCE-INIT-VOPS :RAW-SIGNED-WORD :SB-DOC :SB-EVAL :SB-LDB
 :SB-PACKAGE-LOCKS :SB-SIMD-PACK :SB-SOURCE-LOCATIONS :SB-THREAD :SB-TRACEROOT
 :SB-UNICODE :SBCL :STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-FIXED-OBJECTS
 :STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-VECTORS
 :STACK-GROWS-DOWNWARD-NOT-UPWARD :SYMBOL-INFO-VOPS :UNBIND-N-VOP
 :UNDEFINED-FUN-RESTARTS :UNIX :UNWIND-TO-FRAME-AND-CALL-VOP :X86-64)

After investigation, the delay of one second is generated by the (process-wait) function defined in src/code/run-program.lisp, which rely on a call to (serve-all-events 1) in order to wait for the external process.

(serve-all-events), rely on (sub-sub-serve-event). This function, defined in src/code/serve-event.lisp, has the following block invoked when :os-provides-poll but no descriptor handlers are available:

              ;; If invoked with no descriptors only for the effect of waiting
              ;; until the timeout, make a valid pointer to a (struct pollfd).
              (with-alien ((a (struct sb!unix:pollfd)))
                (sb!unix:unix-poll a 0 to-millisec)))

I my case (threaded sbcl running under slime), no descriptors are invoked, so the command waits for one second before returning. Therefore, the call to (process-wait) takes ~ 1s. When switching slime communication style to :FH-HANDLER, call to (process-wait) is faster, as (sub-sub-serve-event) is invoked with some descriptors, it returns as soon as the polling is effective.

I wondered if the call to (serve-all-events 1) under (process-wait) might be improved (at least reducing the timing?).

[Stas Boukarev (stassats)]

92aa401293bb94d3585b5947f000e026714dc10e

[Yan (metayan)]

Works on Darwin (10.13.6) built as sbcl-1.4.14-170-gfd5bf5300
The one-second "delay" is no more. Great. Thanks.