Sens z profilera GHC

Question

Próbuję uzyskać sens z profilera GHC. Jest dość prosta aplikacja, która korzysta z bibliotek werq i lens-aeson, a podczas poznawania profilowania GHC postanowiłem trochę się z tym pogodzić.

Korzystanie z różnych opcji (narzędzie time, +RTS -p -RTS i +RTS -p -h) Uzyskałem całkowicie różne liczby wykorzystania pamięci. Mając te wszystkie liczby, jestem całkowicie zagubiony, próbując zrozumieć, co się dzieje i ile pamięci faktycznie wykorzystuje aplikacja.

Ta sytuacja przypomina mi zdanie Arthura Blocha: "Człowiek z zegarkiem wie, która jest godzina, człowiek z dwoma zegarami nigdy nie jest pewny".

Czy możesz, proszę, zasugerować mi, jak mogę odczytać wszystkie te liczby i jakie jest znaczenie każdego z nich.

Oto numery:

time -l raporty wokół 19m

#/usr/bin/time -l ./simple-wreq 
... 
     3.02 real   0.39 user   0.17 sys 
    19070976 maximum resident set size 
     0 average shared memory size 
     0 average unshared data size 
     0 average unshared stack size 
    21040 page reclaims 
     0 page faults 
     0 swaps 
     0 block input operations 
     0 block output operations 
     71 messages sent 
     71 messages received 
     2991 signals received 
     43 voluntary context switches 
     6490 involuntary context switches 

Korzystanie +RTS -p -RTS raporty flag wokół 92m. Mimo, że mówi „całkowita Alloc” wydaje mi się dziwne, że to prosta aplikacja taka jak ta może przydzielić i zwolnić 91M

# ./simple-wreq +RTS -p -RTS  
# cat simple-wreq.prof 
     Fri Oct 14 15:08 2016 Time and Allocation Profiling Report (Final) 

      simple-wreq +RTS -N -p -RTS 

     total time =  0.07 secs (69 ticks @ 1000 us, 1 processor) 
     total alloc = 91,905,888 bytes (excludes profiling overheads) 

COST CENTRE        MODULE       %time %alloc 

main.g         Main        60.9 88.8 
MAIN         MAIN        24.6 2.5 
decodeLenient/look      Data.ByteString.Base64.Internal 5.8 2.6 
decodeLenientWithTable/fill    Data.ByteString.Base64.Internal 2.9 0.1 
decodeLenientWithTable.\.\.fill   Data.ByteString.Base64.Internal 1.4 0.0 
decodeLenientWithTable.\.\.fill.\  Data.ByteString.Base64.Internal 1.4 0.1 
decodeLenientWithTable.\.\.fill.\.\.\.\ Data.ByteString.Base64.Internal 1.4 3.3 
decodeLenient       Data.ByteString.Base64.Lazy  1.4 1.4 


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

MAIN              MAIN        443   0 24.6 2.5 100.0 100.0 
main             Main        887   0 0.0 0.0 75.4 97.4 
    main.g             Main        889   0 60.9 88.8 75.4 97.4 
    object_            Data.Aeson.Parser.Internal  925   0 0.0 0.0  0.0 0.2 
    jstring_            Data.Aeson.Parser.Internal  927   50 0.0 0.2  0.0 0.2 
    unstream/resize          Data.Text.Internal.Fusion   923   600 0.0 0.3  0.0 0.3 
    decodeLenient           Data.ByteString.Base64.Lazy  891   0 1.4 1.4 14.5 8.1 
    decodeLenient          Data.ByteString.Base64   897   500 0.0 0.0 13.0 6.7 
.... 

+RTS -p -h i hp2ps pokazać mi następujący obraz i dwa numery: 114k w nagłówku i coś około 1,8Mb na wykresie.

I, tak na wszelki wypadek, tutaj jest to aplikacja:

module Main where 

import Network.Wreq 
import Control.Lens 
import Data.Aeson.Lens 
import Control.Monad 

main :: IO() 
main = replicateM_ 10 g 
    where 
    g = do 
     r <- get "http://httpbin.org/get" 
     print $ r ^. responseBody 
        . key "headers" 
        . key "User-Agent" 
        . _String 

UPDATE 1: podziękować wszystkim za niesamowite dobrych odpowiedzi. Zgodnie z sugestią dodałem dane wyjściowe +RTS -s, więc cały obraz buduje się dla wszystkich, którzy go czytają.

#./simple-wreq +RTS -s 
... 
    128,875,432 bytes allocated in the heap 
     32,414,616 bytes copied during GC 
     2,394,888 bytes maximum residency (16 sample(s)) 
     355,192 bytes maximum slop 
       7 MB total memory in use (0 MB lost due to fragmentation) 

            Tot time (elapsed) Avg pause Max pause 
    Gen 0  194 colls,  0 par 0.018s 0.022s  0.0001s 0.0022s 
    Gen 1  16 colls,  0 par 0.027s 0.031s  0.0019s 0.0042s 

UPDATE 2: Rozmiar pliku wykonywalnego:

#du -h simple-wreq 
63M  simple-wreq 

Answer 1

Człowiek z zegarkiem wie, która jest godzina. Człowiek z dwoma zegarkami nigdy nie jest pewien.

Ah, ale co pokazują dwa zegarki? Czy oba mają pokazywać aktualny czas w UTC? A może jeden z nich ma pokazywać czas w UTC, a drugi czas w pewnym punkcie na Marsie? Dopóki są zsynchronizowane, drugi scenariusz nie będzie problemem, prawda?

I dokładnie tak się dzieje. Porównując różne pomiary pamięci:

• maksymalny pobyt
• całkowita ilość przydzielonej pamięci

Maksymalny pobyt jest najwyższą ilość pamięci program zawsze korzysta na dany czas. To 19 MB. Jednak całkowita ilość przydzielonej pamięci jest o wiele większa, ponieważ tak działa GHC: "przydziela" pamięć dla obiektów, które są śmieciami, czyli prawie wszystko, co nie zostało rozpakowane.

Pozwól nam sprawdzić na przykład za to C:

int main() { 
    int i; 
    char * mem; 

    for(i = 0; i < 5; ++i) { 
     mem = malloc(19 * 1000 * 1000); 
     free(mem); 
    } 
    return 0; 
} 

Gdy używamy malloc będziemy przeznaczyć 19 megabajtów pamięci. Jednak natychmiast zwalniamy pamięć. Największa ilość pamięci jaką mamy w jednym punkcie to 19 megabajtów (i trochę więcej na stos i sam program).

Łącznie przeznaczamy 5 * 19M, 95M łącznie. Mimo to mogliśmy uruchomić nasz mały program z zaledwie 20 MB pamięci RAM. To jest różnica między całkowitą przydzieloną pamięcią a i maksymalną rezydenturą. Należy pamiętać, że czas pobytu zgłoszony przez czas wynosi zawsze co najmniej du <executable>, ponieważ musi on również znajdować się w pamięci.

Najprostszym sposobem generowania statystyk jest, zgodnie z informacją, -s, który pokaże, jaka była maksymalna rezydentura z punktu widzenia programu Haskella. W twoim przypadku będzie to 1.9M, numer w twoim profilu sterty (lub podwójna kwota wynikająca z profilowania). I tak, pliki wykonywalne Haskella wydają się być bardzo duże, ponieważ biblioteki są statycznie połączone.

Answer 2

time -l jest wyświetlanie (rezydent, nie znaczy wyswapowany) wielkość procesu widziany przez system operacyjny (oczywiście) . Obejmuje to dwukrotność maksymalnego rozmiaru sterty Haskell (ze względu na sposób, w jaki działa GC GC), plus wszystko inne przydzielone przez RTS lub inne biblioteki C, plus kod samego pliku wykonywalnego oraz bibliotek, od których to zależy itd. Zgaduję, że w tym przypadku głównym czynnikiem wpływającym na 19M jest wielkość twojej możliwej do wyegzekwowania.

total alloc to całkowita kwota przydzielona do sterty Haskell. Nie jest to wcale miara maksymalnego rozmiaru sterty (co zwykle ludzie rozumieją przez "ile pamięci używa mój program"). Alokacja jest bardzo tania, a wskaźniki alokacji około 1GB/s są typowe dla programu Haskell.

Liczba w nagłówku wyjścia hp2ps "114 242 bajtów x sekund" jest znowu zupełnie inna: jest to całka wykresu i jest mierzona w bajtach * sekundach, a nie w bajtach. Na przykład, jeśli twój program ma strukturę 4 MB na 4 sekundy, spowoduje to zwiększenie tej liczby o 40 MB * s.

liczbie około 1,8 MB pokazane na wykresie jest rzeczywisty rozmiar maksymalny sterty Haskell, który jest prawdopodobnie największym jesteś najbardziej zainteresowany.

pan pomija najbardziej użyteczne źródło o numerach wykonanie twojego programu, który uruchamia go z +RTS -s (nie wymaga to nawet, aby został zbudowany z profilowaniem).