Dlaczego tak często wywołuje sigprocask wywołania IZ wywołania funkcji Iskell?

Question

REVISED STRESZCZENIE

Dobra, wygląda na to, że syscalli są z pewnością związane z GC, a podstawowy problem jest tak, że GC dzieje się zbyt często. Wydaje się, że jest to związane z użyciem splitWhen i pack, o czym najlepiej mogę powiedzieć poprzez profilowanie.

splitWhen's implementation Konwertuje każdy fragment z leniwego na tekst ścisły i łączy je wszystkie, ponieważ buduje bufor kawałków. To dużo znaczy.

opakowanie, ponieważ konwertuje z jednego typu na inny, musi je przydzielić, i to jest w mojej wewnętrznej pętli, więc ma to sens.

ORYGINALNE WYDANIE

ja natknąłem się na jakąś zaskakującą aktywnością syscall w Haskell wyliczający oparciu IO. Mając nadzieję, że ktoś może rzucić trochę światła na to.

Używam wersji haskell do szybkiego skryptu perl, który napisałem od kilku miesięcy, włączam i wyłączam. Skrypt czyta w niektórych jsonach z każdej linii, a następnie wypisuje określone pole, jeśli istnieje.

Oto wersja perla i jak ja to działa.

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

Oto wersja haskell (jest wywoływana podobnie do wersji perla).

{-# 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 

Niespodzianką jest to, że ślad wersji Haskell wygląda mniej więcej tak (rzeczywista JSON jest stłumiony, bo to dane z pracy), natomiast wersja perl robi to, czego się spodziewać; kilka powtórzeń, po których następuje zapis, powtórzono.

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

Czy niepokoi Cię alokacja lub wywołanie (narzut z?) Na sigprocmask?

Jeśli to były i chcesz skorzystać z pakietu enumerator ta mała zmiana pomaga zewnątrz 4k badanie opisane przez około 50%: 8MB alokacji zredukowany do 4MB i gen0 GC poszła od 15 do 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 

przed (statystyk z +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 

Po:

 
     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 

Co jest całkiem rozsądną poprawą, ale z pewnością pozostawia wiele do życzenia. Zamiast wykopywania modułu wyliczającego za dużo więcej, zdecydowałem się na przepisanie go w kanale-0.4.1 tylko dla kopnięć. Powinien on być odpowiednikiem ...

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 

... ale dla niektórych przydziela rozumu i zachowuje mniej pamięci:

 
     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

Jeśli ilość danych czytać między tymi sigsetmasks jest duża, pierwsza przypuszczenie poza czubek głowy jest to, że środowisko wykonawcze robi sigsetmask przed przebiegów GC, GC tak że nie zostaje przerwana z sterty w niespójnym stanie.

Answer 3

Ponad komentarz i mniej niż odpowiedź: jeśli grep przez źródła GHC zobaczysz posix/TTY.c (kod termios) i sm/GC.c (poprzez {,un}blockUserSignals) mają najbardziej prawdopodobnych kandydatów. Możesz skompilować GHC z symbolami debugowania lub po prostu rzucić jakieś fałszywe (unikalne) wywołania systemowe, aby upewnić się, że możesz rozróżnić dwa profile połączeń systemowych, aby się dowiedzieć. Kolejnym tanim testem byłoby usunięcie wszelkich interakcji terminalu i zniknięcie maskowania byłoby łagodnym dowodem wspierającym GC (brak odpowiedzi).

EDYCJA: Powinienem przyznać, że niektóre biblioteki mogą również wywoływać kod sigprocmask, zignorowałem to jako mniej prawdopodobne źródło, ale może to być problem!

Answer 4

Promowanie to do najwyższego poziomu od komentarze:

FWIW, idę po starcie (my też omawiając ten w IRC) i istnieją tylko dwa zastosowania sigprocmask: GC a sterownik tty. To ostatnie jest mało prawdopodobne, zaleciłem profilowanie, aby sprawdzić, czy robi dużo GC i próbować dowiedzieć się dlaczego.

Okazuje się (z IRC), że wykonuje 90 MB alokacji na 0,5 MB danych, a odśmiecacz jest rzeczywiście uruchamiany całkiem sporo. Więc teraz to właśnie dlatego enumerator robi tak wiele dodatkowych przydziałów.