performance - Rendimiento de Haskell implementando el programa "cat" de Unix con Data.ByteString

pipeline

Question

Tengo el siguiente código Haskell, implementando una versión simple de la utilidad de línea de comandos unix "cat". Probando el rendimiento con "tiempo" en un archivo de 400MB, es aproximadamente 3x más lento. (el script exacto que estoy usando para probarlo está debajo del código).

Mis preguntas son:

1. ¿Es esta una prueba válida de rendimiento?
2. ¿Cómo puedo hacer que este programa se ejecute más rápido?
3. ¿Cómo puedo identificar cuellos de botella de rendimiento en los programas de Haskell en general?

Con respecto a las preguntas 2 y 3: He usado GHC -prof, luego ejecutando con + RTS -p, pero encuentro la salida un poco poco informativa aquí.

Fuente (Main.hs)

module Main where

import System.IO
import System.Environment
import Data.ByteString as BS

import Control.Monad

-- Copied from cat source code
bufsize = 1024*128

go handle buf = do
  hPut stdout buf
  eof <- hIsEOF handle
  unless eof $ do
    buf <- hGetSome handle bufsize
    go handle buf

main = do
  file    <- fmap Prelude.head getArgs
  handle  <- openFile file ReadMode
  buf     <- hGetSome handle bufsize
  hSetBuffering stdin $ BlockBuffering (Just bufsize)
  hSetBuffering stdout $ BlockBuffering (Just bufsize)
  go handle buf

Script de tiempo (run.sh):

#!/usr/bin/env bash

# Generate 10M lines of silly test data
yes aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa | head -n 10000000 > huge

# Compile with optimisation
ghc -O2 Main.hs

# Run haskell
echo "timing Haskell"
time ./Main huge > /dev/null

echo ""
echo ""

# Run cat
echo "timing ''cat''"
time cat huge > /dev/null

Mis resultados:

timing Haskell

real    0m0.980s
user    0m0.296s
sys     0m0.684s


timing ''cat''

real    0m0.304s
user    0m0.001s
sys     0m0.302s

El informe de perfiles al compilar con -prof y ejecutarse con + RTS -p se encuentra a continuación:

  Sat Dec 13 21:26 2014 Time and Allocation Profiling Report  (Final)

     Main +RTS -p -RTS huge

  total time  =        0.92 secs   (922 ticks @ 1000 us, 1 processor)
  total alloc = 7,258,596,176 bytes  (excludes profiling overheads)

COST CENTRE MODULE  %time %alloc

MAIN        MAIN    100.0  100.0


                                                       individual     inherited
COST CENTRE MODULE                   no.     entries  %time %alloc   %time %alloc

MAIN        MAIN                      46           0  100.0  100.0   100.0  100.0
 CAF        GHC.Conc.Signal           84           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.FD                 82           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Handle.FD          81           0    0.0    0.0     0.0    0.0
 CAF        System.Posix.Internals    76           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding           70           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding.Iconv     69           0    0.0    0.0     0.0    0.0

Answer 1

Esta es solo una respuesta parcial que trata de abordar la segunda pregunta:

GHC.IO.Buffer algo como esto utilizando la API GHC.IO.Buffer :

module Main where

import System.IO
import System.Environment
import GHC.IO.Buffer
import Data.ByteString as BS

import Control.Monad

-- Copied from cat source code
bufsize = 1024*128

go handle bufPtr = do
  read <- hGetBuf handle bufPtr bufsize
  when (read > 0) $ do
    hPutBuf stdout bufPtr read
    go handle bufPtr

main = do
  file    <- fmap Prelude.head getArgs
  handle  <- openFile file ReadMode
  buf     <- newByteBuffer bufsize WriteBuffer

  withBuffer buf $ go handle

y parece acercarse más al rendimiento de ''cat'', pero aún así definitivamente más lento ...

time ./Cat huge > /dev/null 
./Cat huge > /dev/null  0.00s user 0.06s system 76% cpu 0.081 total

time cat huge > /dev/null  
cat huge > /dev/null  0.00s user 0.05s system 75% cpu 0.063 total

Creo que al usar la API de búfer, podemos evitar explícitamente la asignación de todas las secuencias de bytes del búfer cuando se usa hGetSome como en el código original, pero estoy adivinando aquí y tampoco sé qué sucede exactamente en ambos códigos compilados ...

ACTUALIZACIÓN: Agregar el rendimiento del código original en mi computadora portátil:

time ./Cat2 huge > /dev/null
./Cat2 huge > /dev/null  0.12s user 0.10s system 99% cpu 0.219 total

ACTUALIZACIÓN 2: Agregando algunos resultados de perfiles básicos:

Código original:

Cat2 +RTS -p -RTS huge

    total time  =        0.21 secs   (211 ticks @ 1000 us, 1 processor)
    total alloc = 6,954,068,112 bytes  (excludes profiling overheads)

COST CENTRE MODULE  %time %alloc

MAIN        MAIN    100.0  100.0


                                                       individual     inherited
COST CENTRE MODULE                   no.     entries  %time %alloc   %time %alloc

MAIN        MAIN                      46           0  100.0  100.0   100.0  100.0
 CAF        GHC.IO.Handle.FD          86           0    0.0    0.0     0.0    0.0
 CAF        GHC.Conc.Signal           82           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding           80           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.FD                 79           0    0.0    0.0     0.0    0.0
 CAF        System.Posix.Internals    75           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding.Iconv     72           0    0.0    0.0     0.0    0.0

Código de la API de búfer:

Cat +RTS -p -RTS huge

    total time  =        0.06 secs   (61 ticks @ 1000 us, 1 processor)
    total alloc =   3,487,712 bytes  (excludes profiling overheads)

COST CENTRE MODULE  %time %alloc

MAIN        MAIN    100.0   98.9


                                                      individual     inherited
COST CENTRE MODULE                  no.     entries  %time %alloc   %time %alloc

MAIN        MAIN                     44           0  100.0   98.9   100.0  100.0
 CAF        GHC.IO.Handle.FD         85           0    0.0    1.0     0.0    1.0
 CAF        GHC.Conc.Signal          82           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding          80           0    0.0    0.1     0.0    0.1
 CAF        GHC.IO.FD                79           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding.Iconv    71           0    0.0    0.0     0.0    0.0

Note especialmente la gran diferencia en los costos de asignación ...

Answer 2

La pregunta original me hizo pensar que se trataba de encontrar un problema de rendimiento en el código exacto proporcionado. Dado que el comentario "Espero ir por una solución de Haskell más idiomática / de" alto nivel "contradice esa suposición, daré la solución de Haskell idiomática de rendimiento razonable.

La forma en que esperaría que cualquier programador al azar familiarizado con Haskell para resolver este problema es con los perezosos perezosos. Esto permite que el programador simplemente especifique la tarea de leer la entrada y poner la salida, mientras que deja que el compilador se preocupe por el desorden con las construcciones de búfer y bucle.

módulo principal donde

import System.IO
import System.Environment
import Data.ByteString.Lazy as BS

import Control.Monad

main :: IO ()
main = do
  file    <- fmap Prelude.head getArgs
  handle  <- openFile file ReadMode
  buf     <- BS.hGetContents handle
  hPut stdout buf

El resultado es más legible y tiene un mejor rendimiento que el código en la pregunta original:

timing ''cat''

real    0m0.075s
user    0m0.000s
sys     0m0.074s
timing strict bytestring with GHC -O2

real    0m0.254s
user    0m0.126s
sys     0m0.127s
timing strict bytestring with GHC -O2 -fllvm

real    0m0.267s
user    0m0.132s
sys     0m0.134s
timing lazy bytestring with GHC -O2

real    0m0.091s
user    0m0.023s
sys     0m0.067s
timing lazy bytestring with GHC -O2 -fllvm

real    0m0.091s
user    0m0.021s
sys     0m0.069s

Es decir, la solución de bytestring perezosa es un 21% más lenta que cat . Poner a cat por último para un comportamiento de almacenamiento en caché preferencial resulta en un tiempo de ejecución de 59 ms, lo que hace que la solución de Haskell sea un 51% más lenta.

EDITAR: Dons sugirió que el uso de IO mapeado en memoria modelaría con mayor precisión el comportamiento del gato. No estoy seguro de cuán precisa es esa afirmación, pero mmap casi siempre resulta en un mejor rendimiento y esta situación no es una excepción:

timing memory mapped lazy bytestring with GHC -O2

real    0m0.008s
user    0m0.004s
sys     0m0.003s

El cual fue producido por:

module Main where

import System.IO (stdout)
import System.Environment
import System.IO.Posix.MMap.Lazy
import Data.ByteString.Lazy (hPut)

import Control.Monad

main :: IO ()
main = do
  file    <- fmap Prelude.head getArgs
  buf     <- unsafeMMapFile file
  hPut stdout buf

Answer 3

Observación post festum :

No estoy seguro de cuál es la pregunta ahora que la gente lo ha pateado un poco. Quería ver qué pasaba con bytestring-mmap , así que hice una versión de tuberías para "corregir" su módulo de bytestring perezoso. https://github.com/michaelt/pipes-bytestring-mmap En consecuencia, armé todos estos programas, usando el método de prueba de sibi . Los únicos dos de los módulos en https://github.com/michaelt/pipes-bytestring-mmap/tree/master/bench que parecen cualquier cosa menos haskell de bread-and-butter tonto son los que utilizan la gestión de búfer explícita de lujo.

De todos modos, aquí hay algunos resultados: El tamaño del archivo aumenta en 10 * a medida que avanzamos hacia la derecha. Es interesante ver en qué medida los programas difieren en diferentes tamaños de archivo. Los programas que no usan mmap solo comienzan a mostrar su carácter como ''lineal en la longitud del archivo'' a 420M. En ese momento, y después, todos son casi exactamente iguales, lo que sugiere que el comportamiento bastante divergente en tamaños más pequeños no puede tomarse demasiado en serio. Todos los archivos mmap comportan de manera similar (entre ellos) con algunas curiosidades (que he replicado). Todo esto está en os x.

4200000           42000000          420000000         4200000000

timing ''cat''

real  0m0.006s    real  0m0.013s    real  0m0.919s    real  0m8.154s
user  0m0.002s    user  0m0.002s    user  0m0.005s    user  0m0.028s
sys   0m0.003s    sys   0m0.009s    sys   0m0.223s    sys   0m2.179s


timing lazy bytestring - idiomatic Haskell (following Thomas M. DuBuisson) 

real  0m0.009s    real  0m0.025s    real  0m0.894s    real  0m9.146s
user  0m0.002s    user  0m0.006s    user  0m0.078s    user  0m0.787s
sys   0m0.005s    sys   0m0.016s    sys   0m0.288s    sys   0m3.001s


timing fancy buffering following statusfailed

real  0m0.014s    real  0m0.066s    real  0m0.876s    real  0m8.686s
user  0m0.005s    user  0m0.028s    user  0m0.278s    user  0m2.724s
sys   0m0.007s    sys   0m0.035s    sys   0m0.424s    sys   0m4.232s


timing fancier use of GHC.Buf following bmk

real  0m0.011s    real  0m0.018s    real  0m0.831s    real  0m8.218s
user  0m0.002s    user  0m0.003s    user  0m0.034s    user  0m0.289s
sys   0m0.006s    sys   0m0.013s    sys   0m0.236s    sys   0m2.447s


timing Pipes.ByteString following sibi

real  0m0.012s    real  0m0.020s    real  0m0.845s    real  0m8.241s
user  0m0.003s    user  0m0.004s    user  0m0.020s    user  0m0.175s
sys   0m0.007s    sys   0m0.014s    sys   0m0.239s    sys   0m2.509s

Luego con mmap

timing Lazy.MMap following dons and Thomas M. DuBuisson 

real  0m0.006s    real  0m0.006s    real  0m0.037s    real  0m0.133s
user  0m0.002s    user  0m0.002s    user  0m0.006s    user  0m0.051s
sys   0m0.003s    sys   0m0.003s    sys   0m0.013s    sys   0m0.061

timing Pipes.ByteString.MMap with SafeT machinery

real  0m0.006s    real  0m0.010s    real  0m0.051s    real  0m0.196s
user  0m0.002s    user  0m0.004s    user  0m0.012s    user  0m0.099s
sys   0m0.003s    sys   0m0.005s    sys   0m0.016s    sys   0m0.072s


timing Pipes.ByteString.MMap ''withFile'' style

real  0m0.008s    real  0m0.008s    real  0m0.142s    real  0m0.134s
user  0m0.002s    user  0m0.002s    user  0m0.007s    user  0m0.046s
sys   0m0.004s    sys   0m0.004s    sys   0m0.016s    sys   0m0.066s