Using write-sequence on a broadcast stream is slow

Bug #1747648 reported by Guillaume LE VAILLANT on 2018-02-06
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
SBCL
Undecided
Unassigned

Bug Description

When writing data to a broadcast stream with write-sequence, the bytes are written one by one (using write-byte) to the streams in the broadcast stream. This leads to write-sequence on broadcast streams being very slow compared to using write-sequence on all the streams by hand.

Example of a session with SBCL 1.4.4 on GNU/Linux x86-64 using a "in.dat" file containing 100 MiB of random data:

(with-open-file (in "in.dat" :element-type '(unsigned-byte 8))
  (with-open-file (out1 "out1.dat" :direction :output :element-type '(unsigned-byte 8) :if-exists :supersede)
    (with-open-file (out2 "out2.dat" :direction :output :element-type '(unsigned-byte 8) :if-exists :supersede)
      (with-open-stream (out (make-broadcast-stream out1 out2))
        (sb-sprof:with-profiling (:reset t :sample-interval 0.01 :mode :cpu :report :flat :loop nil)
          (do* ((buffer (make-array 4096 :element-type '(unsigned-byte 8)))
                (n (read-sequence buffer in) (read-sequence buffer in)))
               ((zerop n))
            (write-sequence buffer out :end n)))))))

Number of samples: 364
Sample interval: 0.01 seconds
Total sampling time: 3.6399999 seconds
Number of cycles: 0
Sampled threads:
 #<SB-THREAD:THREAD "worker" RUNNING {1003727AE3}>

           Self Total Cumul
  Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------
   1 128 35.2 169 46.4 128 35.2 - SB-IMPL::OUTPUT-UNSIGNED-BYTE-FULL-BUFFERED
   2 74 20.3 236 64.8 202 55.5 - WRITE-BYTE
   3 48 13.2 291 79.9 250 68.7 - SB-IMPL::BROADCAST-BOUT
   4 36 9.9 36 9.9 286 78.6 - SB-IMPL::SYNCHRONIZE-STREAM-OUTPUT
   5 29 8.0 29 8.0 315 86.5 - (SB-IMPL::OPTIMIZED-DATA-VECTOR-REF (UNSIGNED-BYTE 8))
   6 20 5.5 357 98.1 335 92.0 - SB-IMPL::ANSI-STREAM-WRITE-SEQUENCE
   7 17 4.7 17 4.7 352 96.7 - SB-KERNEL:HAIRY-DATA-VECTOR-REF
   8 5 1.4 5 1.4 357 98.1 - (FLET "CLEANUP-FUN-7" :IN SB-IMPL::REFILL-INPUT-BUFFER)
   9 5 1.4 5 1.4 362 99.5 - "foreign function write"
  10 1 0.3 6 1.6 363 99.7 - SB-IMPL::FD-STREAM-READ-N-BYTES
...

(with-open-file (in "in.dat" :element-type '(unsigned-byte 8))
  (with-open-file (out1 "out1.dat" :direction :output :element-type '(unsigned-byte 8) :if-exists :supersede)
    (with-open-file (out2 "out2.dat" :direction :output :element-type '(unsigned-byte 8) :if-exists :supersede)
      (sb-sprof:with-profiling (:reset t :sample-interval 0.01 :mode :cpu :report :flat :loop nil)
        (do* ((buffer (make-array 4096 :element-type '(unsigned-byte 8)))
              (n (read-sequence buffer in) (read-sequence buffer in)))
             ((zerop n))
          (write-sequence buffer out1 :end n)
          (write-sequence buffer out2 :end n))))))

Number of samples: 18
Sample interval: 0.01 seconds
Total sampling time: 0.17999999 seconds
Number of cycles: 0
Sampled threads:
 #<SB-THREAD:THREAD "worker" RUNNING {100344FB53}>

           Self Total Cumul
  Nr Count % Count % Count % Calls Function
------------------------------------------------------------------------
   1 11 61.1 11 61.1 11 61.1 - "foreign function write"
   2 4 22.2 4 22.2 15 83.3 - (FLET "CLEANUP-FUN-7" :IN SB-IMPL::REFILL-INPUT-BUFFER)
   3 1 5.6 5 27.8 16 88.9 - READ-SEQUENCE
   4 1 5.6 1 5.6 17 94.4 - SB-IMPL::SYNCHRONIZE-STREAM-OUTPUT
   5 1 5.6 1 5.6 18 100.0 - SB-KERNEL:COPY-UB8-TO-SYSTEM-AREA
   6 0 0.0 18 100.0 18 100.0 - "Unknown component: #x10023DF400"
   7 0 0.0 18 100.0 18 100.0 - SB-INT:SIMPLE-EVAL-IN-LEXENV
   8 0 0.0 18 100.0 18 100.0 - EVAL
   9 0 0.0 18 100.0 18 100.0 - (LAMBDA NIL :IN SWANK:INTERACTIVE-EVAL)
  10 0 0.0 18 100.0 18 100.0 - SWANK::CALL-WITH-RETRY-RESTART
...

The attached patch changes write-sequence so that when it is called on a broadcast stream, write-sequence is called on all the streams of the broadcast stream.

With this patch, the running time of the previous test drops from 3.8 seconds to 0.18 seconds.

Stas Boukarev (stassats) wrote :

Adapted and applied in facdb7410775a2854413ed2019209d9c5508e761.

Changed in sbcl:
status: New → Fix Committed
Stas Boukarev (stassats) on 2018-03-31
Changed in sbcl:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers