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
...

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers