¿Por qué haskell enumerador basado en IO llama a sigprocmask con tanta frecuencia?

Question

resumen revisado

bien, parece que las llamadas al sistema son sin duda relacionados con la GC, y el problema subyacente es sólo eso GC está ocurriendo con demasiada frecuencia. Esto parece estar relacionado con el uso de splitWhen y pack, lo mejor que puedo decir mediante el perfil.

splitWhen's implementation convierte cada trozo de perezosa a texto estricto, y los concatena a todos, ya que crea un búfer de trozos. Eso seguramente asignará mucho.

paquete, ya que se está convirtiendo de un tipo a otro, tiene que asignar, y eso está en mi bucle interno, por lo que tiene sentido también.

emisión original

He tropezado con alguna actividad syscall sorprendente en empadronador Haskell basada IO. Esperando que alguien pueda arrojar algo de luz sobre él.

He estado jugando con una versión de Haskell de una secuencia de comandos rápida de perl que una vez escribí durante unos meses, dentro y fuera. El script lee en json de cada línea, y luego imprime un campo específico, si existe.

Aquí está la versión perl y cómo la estoy ejecutando.

cat ~/sample_input | perl -lpe '($_) = grep(/type/, split(/,/))' > /dev/null 

Aquí está la versión de Haskell (se invoca de manera similar a la versión perl).

{-# LANGUAGE OverloadedStrings #-} 
import qualified Data.Enumerator as E 
import qualified Data.Enumerator.Internal as EI 
import qualified Data.Enumerator.Text as ET 
import qualified Data.Enumerator.List as EL 
import qualified Data.Text as T 
import qualified Data.Text.IO as TI 
import Data.Functor 
import Control.Monad 
import qualified Data.Text.Lazy as TL 
import qualified Data.Text.Lazy.IO as TLI 
import System.Environment 
import System.IO (stdin, stdout) 
import GHC.IO.Handle (hSetBuffering, BufferMode(BlockBuffering)) 

fieldEnumerator field = enumStdin E.$= splitOn [',','\n'] E.$= grabField field 

enumStdin = ET.enumHandle stdin 

splitOn :: [Char] -> EI.Enumeratee T.Text T.Text IO b 
splitOn chars = (ET.splitWhen (`elem` chars)) 

grabField :: String -> EI.Enumeratee T.Text T.Text IO b 
grabField = EL.filter . T.isInfixOf . T.pack 

intercalateNewlines = EL.mapM_ (\field -> (TI.putStrLn field >> (putStr "\n\n"))) 

runE enum = E.run_ $ enum E.$$ intercalateNewlines 

main = do 
    (field:_) <- getArgs 
    runE $ fieldEnumerator field 

La sorpresa es que traza de la versión Haskell se ve algo como esto (el JSON real se suprime porque es los datos del trabajo), mientras que la versión de Perl hace lo que cabe esperar; un montón de lecturas seguidas de una escritura, repetida.

55333/0x8816f5: 366125  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 366136  3  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 367209  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 367218  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 368449  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 368458  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 369525  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 369534  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 370610  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 370620  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 371735  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 371744  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 371798  5  2 select(0x1, 0x7FFF5FBFBA70, 0x7FFF5FBFB9F0, 0x0, 0x7FFF5FBFBAF0)  = 1 0 
55333/0x8816f5: 371802  3  1 read(0x0, SOME_JSON, 0x1FA0)  = 8096 0 
55333/0x8816f5: 372907  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 372918  3  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 374063  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 374072  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 375147  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 375156  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 376283  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 376292  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 376809  6  2 select(0x1, 0x7FFF5FBFBA70, 0x7FFF5FBFB9F0, 0x0, 0x7FFF5FBFBAF0)  = 1 0 
55333/0x8816f5: 376814  5  3 read(0x0, SOME_JSON, 0x1FA0)  = 8096 0 
55333/0x8816f5: 377378  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 377387  3  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 378537  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 378546  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 379598  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 379604  3  0 sigreturn(0x7FFF5FBFF9A0, 0x1E, 0x1)  = 0 Err#-2 
55333/0x8816f5: 379613  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 380667  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 380678  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 381862  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 381871  3  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 382032  6  2 select(0x1, 0x7FFF5FBFBA70, 0x7FFF5FBFB9F0, 0x0, 0x7FFF5FBFBAF0)  = 1 0 
55333/0x8816f5: 382036  4  2 read(0x0, SOME_JSON, 0x1FA0)  = 8096 0 
55333/0x8816f5: 383064  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 383073  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 384118  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 384127  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 385206  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 385215  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 386348  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 386358  3  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 387468  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 387477  11  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 387614  6  2 select(0x1, 0x7FFF5FBFBA70, 0x7FFF5FBFB9F0, 0x0, 0x7FFF5FBFBAF0)  = 1 0 
55333/0x8816f5: 387620  5  3 read(0x0, SOME_JSON, 0x1FA0)  = 8096 0 
55333/0x8816f5: 388597  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 388606  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 389707  3  0 sigprocmask(0x1, 0x10069BFA8, 0x10069BFAC)  = 0x0 0 
55333/0x8816f5: 389716  2  0 sigprocmask(0x3, 0x10069BFAC, 0x0)  = 0x0 0 
55333/0x8816f5: 390261  7  3 select(0x2, 0x7FFF5FBFBA70, 0x7FFF5FBFB9F0, 0x0, 0x7FFF5FBFBAF0)  = 1 0 
55333/0x8816f5: 390273  6  3 write(0x1, SOME_OUTPUT, 0x1FA0)  = 8096 0 

Answer 1

¿Le preocupan las asignaciones o las llamadas (desde arriba?) A sigprocmask?

Si se trata de la antigua y desea utilizar el paquete enumerator este pequeño cambio ayuda a cabo una prueba de 4k establecido en un 50%: 8 MB de asignaciones reducido a 4 MB y GC de Gen0 pasó de 15 a 6.

splitOn :: EI.Enumeratee T.Text T.Text IO b 
splitOn = EL.concatMap (T.split fastSplit) 

fastSplit :: Char -> Bool 
fastSplit ',' = True 
fastSplit '\n' = True 
fastSplit _ = False 

Antes

(las estadísticas de +RTS -sstderr -RTS):

 
     8,212,680 bytes allocated in the heap 
     696,184 bytes copied during GC 
     148,656 bytes maximum residency (1 sample(s)) 
      30,664 bytes maximum slop 
       2 MB total memory in use (0 MB lost due to fragmentation) 

            Tot time (elapsed) Avg pause Max pause 
    Gen 0  15 colls,  0 par 0.00s 0.00s  0.0001s 0.0005s 
    Gen 1   1 colls,  0 par 0.00s 0.00s  0.0010s 0.0010s 

Después de:

 
     3,838,048 bytes allocated in the heap 
     689,592 bytes copied during GC 
     148,368 bytes maximum residency (1 sample(s)) 
      27,040 bytes maximum slop 
       2 MB total memory in use (0 MB lost due to fragmentation) 

            Tot time (elapsed) Avg pause Max pause 
    Gen 0   6 colls,  0 par 0.00s 0.00s  0.0001s 0.0003s 
    Gen 1   1 colls,  0 par 0.00s 0.00s  0.0006s 0.0006s 

, que es una mejora bastante razonable, pero definitivamente deja algo que desear. En lugar de patear al enumerador por mucho más, intenté reescribirlo en el conducto-0.4.1 solo para dar patadas. Debe ser equivalente ...

import Data.Conduit as C 
import qualified Data.Conduit.Binary as Cb 
import qualified Data.Conduit.List as Cl 
import qualified Data.Conduit.Text as Ct 
import qualified Data.Text as T 
import qualified Data.Text.IO as TI 
import Control.Monad.Trans (MonadIO, liftIO) 
import System.Environment 
import System.IO (stdin) 

grabField :: Monad m => String -> Conduit T.Text m T.Text 
grabField = Cl.filter . T.isInfixOf . T.pack 

printField :: MonadIO m => T.Text -> m() 
printField field = liftIO $ do 
    TI.putStrLn field 
    putStr "\n\n" 

fastSplit :: Char -> Bool 
fastSplit ',' = True 
fastSplit '\n' = True 
fastSplit _ = False 

main :: IO() 
main = do 
    field:_ <- getArgs 
    runResourceT $ Cb.sourceHandle stdin 
       $$ Ct.decode Ct.utf8 
       =$ Cl.concatMap (T.split fastSplit) 
       =$ grabField field 
       =$ Cl.mapM_ printField 

... pero por alguna razón asigna y retiene menos memoria:

 
     835,688 bytes allocated in the heap 
      8,576 bytes copied during GC 
      87,200 bytes maximum residency (1 sample(s)) 
      19,968 bytes maximum slop 
       1 MB total memory in use (0 MB lost due to fragmentation) 

            Tot time (elapsed) Avg pause Max pause 
    Gen 0   1 colls,  0 par 0.00s 0.00s  0.0000s 0.0000s 
    Gen 1   1 colls,  0 par 0.00s 0.00s  0.0008s 0.0008s 

Answer 2

Si la cantidad de datos leer entre esos sigsetmasks es grande, la primera suposición de la parte superior de la cabeza es que el tiempo de ejecución está haciendo el sigsetmask antes de ejecutar el GC, GC de manera que no se interrumpa la montón en un estado inconsistente.

Answer 3

más de un comentario y menos de una respuesta: si grep a través de fuente de GHC verá posix/TTY.c (código termios) y sm/GC.c (a través de {,un}blockUserSignals) tienen los candidatos más probables. Puede compilar GHC con símbolos de depuración o simplemente agregar algunas llamadas ficticias (únicas) al sistema para asegurarse de que puede diferenciar los dos perfiles de llamada del sistema para averiguarlo. Otra prueba barata sería eliminar cualquier interacción terminal y si el comportamiento de enmascaramiento desaparece, entonces sería una evidencia leve que respaldara el GC (ninguna respuesta).

EDIT: Debo reconocer que algunos códigos de biblioteca también pueden llamar al sigprocmask, ignoré eso como una fuente menos probable, ¡pero en realidad podría ser el problema!

Answer 4

La promoción de esta al nivel superior de:

Fwiw, voy a través del tiempo de ejecución (también estamos discutiendo esto en IRC) y sólo hay dos usos de sigprocmask: GC y la conductor tty. Como esto último es poco probable, he recomendado perfilar para verificar que esté haciendo una gran cantidad de GC y para intentar averiguar por qué.

Y resulta que (de IRC) está haciendo 90MB de asignación para 0.5MB de datos y el recolector de basura de hecho se está disparando bastante. Así que ahora depende de por qué el enumerador está haciendo tanta asignación adicional.