Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

[-- Attachment #1: Type: text/plain, Size: 6042 bytes --]

Hi all,

I can't make sense of the following three observations: adding a useless (copy-sequence …) and discarding the result makes my code roughly 20-times faster, sending strings of length 2^16+1 to a subprocess is several times slower than sending strings of length 2^16, and sending 2^6 strings of length 2^10 is much faster than sending a single string of length 2^16.

Here's my function (read.py is a python script containing just "import sys; sys.stdin.read()"):

(defun bench (cargo-cult size)
  (let* ((message (make-string size ?a))
         (process-connection-type nil)
         (proc (start-process "reader" nil "python2" "read.py")))
    (dotimes (_ 100)
      (when cargo-cult
        (copy-sequence message))
      (process-send-string proc message))
    (kill-process proc)))

And here's the experimental data:

(benchmark-run 1 (bench t 65536))   ;; (0.048931082 0 0.0)
(benchmark-run 1 (bench nil 65536)) ;; (1.844878298 0 0.0)

(benchmark-run 1 (bench t 65537))   ;; (2.028768849 0 0.0)
(benchmark-run 1 (bench nil 65537)) ;; (1.175113209 0 0.0)

From this we learn that:

(1) Setting cargo-cult to *t* and running a useless `(copy-sequence message)' makes the code roughly 40 times *faster* on strings of length 65536.
(2) Adding one to the string length yields horrible performance (3.2MB/s), but at least the version without the useless copies is faster.

What's going on here?  strace suggests that the second benchmark is spending 98% of its time in pselect6 calls.

I confirmed that this isn't dependent on the version of Emacs in use (the same issue appears in Emacs 24.5).  It is not dependent on the program on the receiving end of the pipe, either (I tried with cat, read.py as above, and a minimal C program (attached)).  Replacing copy-sequence with concat preserves the surprising behavior, but using (ignore message) makes it disappear (everything is slow).  There are no transmission issues: the receiving side does read a string of "a"s of the right length.  Using a program other than Emacs to send the same strings doesn't show these performance issues.

Here is a bit more data, generated using the attached loop.sh and send-string-cli.el

;; (benchmark-send-string CARGO-CULT N-INNER-LOOP STRING-SIZE READ-PROGRAM) → BENCHMARK-RESULT
(benchmark-send-string t   200  1024  "python2" "read.py") → (0.067296848         1   0.004180474)
(benchmark-send-string nil 200  1024  "python2" "read.py") → (0.061934555         0   0.0)
(benchmark-send-string t   200  16384 "python2" "read.py") → (0.159620501         12  0.04479207899999999)
(benchmark-send-string nil 200  16384 "python2" "read.py") → (1.556031994         0   0.0)
(benchmark-send-string t   200  65536 "python2" "read.py") → (0.334425146         46  0.16486607800000005)
(benchmark-send-string nil 200  65536 "python2" "read.py") → (3.4018179170000002  0   0.0)
(benchmark-send-string t   200  65537 "python2" "read.py") → (12.418711961        46  0.239757055)
(benchmark-send-string nil 200  65537 "python2" "read.py") → (6.102755695         0   0.0)
(benchmark-send-string t   200  1024  "cat")               → (0.10330761          1   0.004161472999999999)
(benchmark-send-string nil 200  1024  "cat")               → (0.12250944600000001 1   0.0035327989999999997)
(benchmark-send-string t   200  16384 "cat")               → (1.3808745009999999  24  0.09748934199999998)
(benchmark-send-string nil 200  16384 "cat")               → (2.521698033         12  0.05619970500000001)
(benchmark-send-string t   200  65536 "cat")               → (4.120669224         99  0.4042515129999999)
(benchmark-send-string nil 200  65536 "cat")               → (9.412745340999999   50  0.218435563)
(benchmark-send-string t   200  65537 "cat")               → (12.176100455        99  0.502071993)
(benchmark-send-string nil 200  65537 "cat")               → (6.322310322000001   51  0.22764341199999993)
(benchmark-send-string t   200  1024  "read")              → (0.026363418         1   0.004118800999999998)
(benchmark-send-string nil 200  1024  "read")              → (0.061907866         0   0.0)
(benchmark-send-string t   200  16384 "read")              → (0.091360628         12  0.038132967000000004)
(benchmark-send-string nil 200  16384 "read")              → (0.12431489          0   0.0)
(benchmark-send-string t   200  65536 "read")              → (0.18765710700000002 46  0.14072835099999995)
(benchmark-send-string nil 200  65536 "read")              → (3.397287521         0   0.0)
(benchmark-send-string t   200  65537 "read")              → (12.389248452999999  46  0.257472908)
(benchmark-send-string nil 200  65537 "read")              → (3.258524461         0   0.0)
(benchmark-send-string t   1600 8192  "read")              → (0.258897164 49 0.17045154200000004)
(benchmark-send-string nil 1600 8192  "read")              → (0.07095391 0 0.0)

This shows one more thing:

(3) Sending 1600 strings of 8192 characters is much faster than sending 200 strings of length 65536.

I managed to reproduce these results on two different physical GNU/Linux machines.  Their configurations are:

    GNU Emacs 26.0.50 (build 9, x86_64-pc-linux-gnu, GTK+ Version 3.18.9) of 2017-03-11 built on clem-w50-mint
    Repository revision: fe68818be218537d341365c014f1a6234c9705d6
    Windowing system distributor 'The X.Org Foundation', version 11.0.11804000
    System Description:	Linux Mint 18.1 Serena

    In GNU Emacs 26.0.50.2 (x86_64-pc-linux-gnu, GTK+ Version 3.18.9) of 2017-02-08 built on goodsight
    Repository revision: eff901b8a39f42ddedf4c1db833b9071cae5962f
    System Description:	Ubuntu 16.04.2 LTS

Can anyone reproduce these issues, and help shed light on them? I'm trying to understand three things:

* Why does running additional, supposedly useless code speed things up so much? (1)
* Why does sending strings longer 2**16 characters slow things down so much? (2)
* What is the right way to get reliable performance from process-send-string? (3)

Thanks!
Clément.

[-- Attachment #2: loop.sh --]
[-- Type: application/x-shellscript, Size: 385 bytes --]

[-- Attachment #3: read.c --]
[-- Type: text/x-csrc, Size: 143 bytes --]

#include <unistd.h>

#define BUFSIZE (1 << 20)
char BUFFER[BUFSIZE];

int main () {
  while (read(STDIN_FILENO, BUFFER, BUFSIZE) > 0) {

  }
}

[-- Attachment #4: read.py --]
[-- Type: text/x-python-script, Size: 28 bytes --]

import sys
sys.stdin.read()

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #5: send-string-cli.el --]
[-- Type: text/x-emacs-lisp; name="send-string-cli.el", Size: 1059 bytes --]

(defun bench (cargo-cult size)
  (let* ((message (make-string size ?a))
         (process-connection-type nil)
         (proc (start-process "reader" nil "python2" "read.py")))
    (dotimes (_ 100)
      (when cargo-cult
        (copy-sequence message))
      (process-send-string proc message))
    (kill-process proc)))

(defun benchmark-send-string (cargo-cult n-inner-loops size prog &rest args)
  (let* ((message (make-string size ?a))
         (process-connection-type nil)
         (proc (apply #'start-process "reader" nil prog args)))
    (dotimes (_ n-inner-loops)
      (when cargo-cult
        (copy-sequence message))
      (process-send-string proc message))
    (kill-process proc)))

(pcase-let ((`(,cargo-cult ,n-inner-loops ,size . ,prog) argv))
  (setq cargo-cult (read cargo-cult))
  (setq size (string-to-number size))
  (setq n-inner-loops (string-to-number n-inner-loops))
  (let ((form `(benchmark-send-string ,cargo-cult ,n-inner-loops ,size ,@prog)))
    (message "%S → %S" form (eval `(benchmark-run 3 ,form)))))

(setq argv nil)

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

On 2017-03-25 00:06, Clément Pit-Claudel wrote:
> * Why does running additional, supposedly useless code speed things up so much? (1)

Interestingly, it turns out that (copy-sequence) isn't needed: instead, it's enough to use (sleep-for 0.000001) (or even (sleep-for cl-least-positive-normalized-float)) to get the 40x speedup.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Eli Zaretskii]

> From: Clément Pit-Claudel <cpitclaudel@gmail.com>
> Date: Sat, 25 Mar 2017 00:24:20 -0400
> 
> On 2017-03-25 00:06, Clément Pit-Claudel wrote:
> > * Why does running additional, supposedly useless code speed things up so much? (1)
> 
> Interestingly, it turns out that (copy-sequence) isn't needed: instead, it's enough to use (sleep-for 0.000001) (or even (sleep-for cl-least-positive-normalized-float)) to get the 40x speedup.

Because, if you don't sleep, the process is not yet running by the
time you get to process-send-string, and then Emacs waits for a much
longer time for it to become running?

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Andreas Politz]

The limiting factor may also be python itself...

;; python2
((0.114342188 0 0.0)
 (0.715895279 0 0.0)
 (2.120252213 0 0.0)
 (1.02429565 0 0.0))

;; bash = "while read;do : ;done"
((2.008305836 0 0.0)
 (1.999825023 0 0.0)
 (2.026715753 0 0.0)
 (2.060320318 0 0.0))

-ap

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

On 2017-03-25 06:38, Andreas Politz wrote:
> The limiting factor may also be python itself...
> 
> ;; python2
> ((0.114342188 0 0.0)
>  (0.715895279 0 0.0)
>  (2.120252213 0 0.0)
>  (1.02429565 0 0.0))
> 
> ;; bash = "while read;do : ;done"
> ((2.008305836 0 0.0)
>  (1.999825023 0 0.0)
>  (2.026715753 0 0.0)
>  (2.060320318 0 0.0))

Interesting! But doesn't this just show that bash is uniformly slow? Do you see the same surprising timings with the read.c program that I sent, or with cat, as with Python?

Clément.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Andreas Politz]

Clément Pit-Claudel <cpitclaudel@gmail.com> writes:

> On 2017-03-25 06:38, Andreas Politz wrote:
>> The limiting factor may also be python itself...
>>
>> ;; python2
>> ((0.114342188 0 0.0)
>>  (0.715895279 0 0.0)
>>  (2.120252213 0 0.0)
>>  (1.02429565 0 0.0))
>>
>> ;; bash = "while read;do : ;done"
>> ((2.008305836 0 0.0)
>>  (1.999825023 0 0.0)
>>  (2.026715753 0 0.0)
>>  (2.060320318 0 0.0))
>
> Interesting! But doesn't this just show that bash is uniformly slow?

This suggests to me, that the deciding factor in these numbers is python
and not Emacs.

Maybe it has a read buffer of a certain size, let's say 65536 ;O), and
if that buffer runs out of space, things get stalled.

-ap

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

On 2017-03-25 12:38, Andreas Politz wrote:
> Clément Pit-Claudel <cpitclaudel@gmail.com> writes:
> 
>> On 2017-03-25 06:38, Andreas Politz wrote:
>>> The limiting factor may also be python itself...
>>>
>>> ;; python2
>>> ((0.114342188 0 0.0)
>>>  (0.715895279 0 0.0)
>>>  (2.120252213 0 0.0)
>>>  (1.02429565 0 0.0))
>>>
>>> ;; bash = "while read;do : ;done"
>>> ((2.008305836 0 0.0)
>>>  (1.999825023 0 0.0)
>>>  (2.026715753 0 0.0)
>>>  (2.060320318 0 0.0))
>>
>> Interesting! But doesn't this just show that bash is uniformly slow?
> 
> This suggests to me, that the deciding factor in these numbers is python
> and not Emacs.
> 
> Maybe it has a read buffer of a certain size, let's say 65536 ;O), and
> if that buffer runs out of space, things get stalled.

The thing is, I reproduced these numbers with cat and a simple C program, so it's not python itself.  But indeed the default pipe buffer size on Linux is 65536 bytes, so there's certainly something going on with buffering at the 65536 (2^16)/65537 (2^16 + 1) threshold.

That doesn't explain observation 3 though (why is sending many small messages so much faster than 1 large one), nor observation 1 (why is the program without sleep or copy-sequence so slow?). Worse, Emacs' docs for process-send-string claims that messages larger than 500 bytes will be split.

Clément.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Eli Zaretskii]

> Cc: Eli Zaretskii <eliz@gnu.org>, emacs-devel@gnu.org
> From: Clément Pit-Claudel <cpitclaudel@gmail.com>
> Date: Sat, 25 Mar 2017 13:02:36 -0400
> 
> Emacs' docs for process-send-string claims that messages larger than 500 bytes will be split.

That's a lie, has been so for quite some time.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Andreas Politz]

Eli Zaretskii <eliz@gnu.org> writes:

>> Emacs' docs for process-send-string claims that messages larger than 500 bytes will be split.
>
> That's a lie, has been so for quite some time.

He is purposefully trying to deceive us ?

-ap

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Eli Zaretskii]

> From: Andreas Politz <politza@hochschule-trier.de>
> Cc: Clément Pit-Claudel <cpitclaudel@gmail.com>,
>   emacs-devel@gnu.org
> Date: Sat, 25 Mar 2017 18:40:37 +0100
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> >> Emacs' docs for process-send-string claims that messages larger than 500 bytes will be split.
> >
> > That's a lie, has been so for quite some time.
> 
> He is purposefully trying to deceive us ?

Not Clément, the docs.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Andreas Politz]

Clément Pit-Claudel <cpitclaudel@gmail.com> writes:

>> This suggests to me, that the deciding factor in these numbers is python
>> and not Emacs.
>
> The thing is, I reproduced these numbers with cat and a simple C
> program, so it's not python itself.

OK, then I'm probably wrong.

> [...] observation 1 (why is the program without sleep or copy-sequence
> so slow?)

I expressed a theory about this earlier.  I suggest taking a look at
send_process in process.c

-ap

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

On 2017-03-25 03:05, Eli Zaretskii wrote:
>> From: Clément Pit-Claudel <cpitclaudel@gmail.com> Date: Sat, 25 Mar
>> 2017 00:24:20 -0400
>> 
>> On 2017-03-25 00:06, Clément Pit-Claudel wrote:
>>> * Why does running additional, supposedly useless code speed
>>> things up so much? (1)
>> 
>> Interestingly, it turns out that (copy-sequence) isn't needed:
>> instead, it's enough to use (sleep-for 0.000001) (or even
>> (sleep-for cl-least-positive-normalized-float)) to get the 40x
>> speedup.
> 
> Because, if you don't sleep, the process is not yet running by the 
> time you get to process-send-string, and then Emacs waits for a much 
> longer time for it to become running?

Quick experiments suggest this isn't the case: hoisting the (sleep) calls out of the loop and sleeping n-inner-loops times instead yields much slower code than when the sleep calls are interleaved with the process-send-string calls.
That is, I don't observe the aforementioned speedup if I sleep a single, "long" time before the loop, instead of putting a small sleep in each iteration.

Similarly, taking the process creation out of the function being timed, then adding a long sleep and a call to accept-process-output before the benchmarked code doesn't change performance significantly:

(benchmark-send-string t 200 65536 proc) → (0.013895306 0 0.0)
(benchmark-send-string nil 200 65536 proc) → (2.3035461760000002 0 0.0)

I used this code to test this:

(require 'cl-lib)
(cl-float-limits)

(defun benchmark-send-string (cargo-cult n-inner-loops size proc)
  (let* ((message (make-string size ?a)))
    (dotimes (_ n-inner-loops)
      (when cargo-cult
        (sleep-for cl-least-positive-normalized-float))
      (process-send-string proc message))
    (kill-process proc)))

(pcase-let ((`(,cargo-cult ,n-inner-loops ,size . ,prog) argv))
  (setq cargo-cult (read cargo-cult))
  (setq size (string-to-number size))
  (setq n-inner-loops (string-to-number n-inner-loops))
  (let* ((process-connection-type nil)
         (proc (apply #'start-process "reader" nil prog))
         (form `(benchmark-send-string ,cargo-cult ,n-inner-loops ,size proc)))
    (sleep-for 1.0)
    (accept-process-output nil 1.0)
    (message "%S → %S" form (eval `(benchmark-run 1 ,form)))))

(setq argv nil)

Clément.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Andreas Politz]

Clément Pit-Claudel <cpitclaudel@gmail.com> writes:

> On 2017-03-25 00:06, Clément Pit-Claudel wrote:
>> * Why does running additional, supposedly useless code speed things up so much? (1)
>
> Interestingly, it turns out that (copy-sequence) isn't needed:
> instead, it's enough to use (sleep-for 0.000001) (or even (sleep-for
> cl-least-positive-normalized-float)) to get the 40x speedup.

What about this explanation: If you make Emacs wait inside the loop, it
can send some of the strings immediately.  Otherwise, it'll have to
store them all/some in memory first.

-ap

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

On 2017-03-25 06:47, Andreas Politz wrote:
> Clément Pit-Claudel <cpitclaudel@gmail.com> writes:
> 
>> On 2017-03-25 00:06, Clément Pit-Claudel wrote:
>>> * Why does running additional, supposedly useless code speed things up so much? (1)
>>
>> Interestingly, it turns out that (copy-sequence) isn't needed:
>> instead, it's enough to use (sleep-for 0.000001) (or even (sleep-for
>> cl-least-positive-normalized-float)) to get the 40x speedup.
> 
> What about this explanation: If you make Emacs wait inside the loop, it
> can send some of the strings immediately.  Otherwise, it'll have to
> store them all/some in memory first.

Possibly! But does this theory explain the following ((3) in my original email)?

(benchmark-send-string t   200  65536 "read")              → (0.18765710700000002 46  0.14072835099999995)
(benchmark-send-string nil 200  65536 "read")              → (3.397287521         0   0.0)

(benchmark-send-string t   1600 8192  "read")              → (0.258897164 49 0.17045154200000004)
(benchmark-send-string nil 1600 8192  "read")              → (0.07095391 0 0.0)

Sending 1600 strings of length 8192 with or without sleeps is much faster than sending 200 strings of length 65536.

Thanks for your ideas!
Clément.

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Stephen Leake]

Clément Pit-Claudel <cpitclaudel@gmail.com> writes:

> I can't make sense of the following three observations: adding a
> useless (copy-sequence …) and discarding the result makes my code
> roughly 20-times faster, sending strings of length 2^16+1 to a
> subprocess is several times slower than sending strings of length
> 2^16, and sending 2^6 strings of length 2^10 is much faster than
> sending a single string of length 2^16.

I have also seen weird timing behavior with subprocess communication.

One thing to check; are you using a pipe or a pty? To use a pipe, do:

(let ((process-connection-type nil))
    (start-process ...))

There's also make-process in emacs 25, which has an arg for this.

--
-- Stephe

Re: Why does adding a useless copy-sequence and discarding the result make my ELisp 40 times faster?

[Clément Pit-Claudel]

On 2017-03-26 09:14, Stephen Leake wrote:
> One thing to check; are you using a pipe or a pty? To use a pipe, do:
> 
> (let ((process-connection-type nil))
>     (start-process ...))

Thanks! That's already what the snippet that I posted does :)