Piccola perdita CPU Haskell

Sto riscontrando piccole perdite di CPU utilizzando GHC 7.8.3 e Yesod 1.4.9.Piccola perdita CPU Haskell

Quando eseguo il mio sito con time e lo interrompo (Ctrl + C) dopo 1 minuto senza fare nulla (basta eseguire, nessuna richiesta), consuma 1 secondo. Rappresenta circa l'1,7% della CPU.

$ time mysite 
^C 

real 1m0.226s 
user 0m1.024s 
sys  0m0.060s

se disattivo il minimo garbage collector, scende a 0,35 secondo (0,6% di CPU). Sebbene sia meglio, consuma ancora CPU senza fare nulla.

$ time mysite +RTS -I0 # Disable idle GC 
^C 

real 1m0.519s 
user 0m0.352s 
sys  0m0.064s 

$ time mysite +RTS -I0 
^C 

real 4m0.676s 
user 0m0.888s 
sys  0m0.468s 

$ time mysite +RTS -I0 
^C 

real 7m28.282s 
user 0m1.452s 
sys  0m0.976s

Rispetto ad un comando cat in attesa a tempo indeterminato di qualcosa su standard input:

$ time cat 
^C 

real 1m1.349s 
user 0m0.000s 
sys  0m0.000s

C'è qualcos'altro in Haskell che fa consumare CPU in background?

È una perdita da Yesod?

O è qualcosa che ho fatto nel mio programma? (Ho solo aggiunto funzioni di gestione, non faccio il calcolo parallelo)

Modifica 2015-05-31 19:25

Ecco l'esecuzione con la bandiera -s:

$ time mysite +RTS -I0 -s 
^C  23,138,184 bytes allocated in the heap 
     4,422,096 bytes copied during GC 
     2,319,960 bytes maximum residency (4 sample(s)) 
     210,584 bytes maximum slop 
       6 MB total memory in use (0 MB lost due to fragmentation) 

            Tot time (elapsed) Avg pause Max pause 
    Gen 0  30 colls,  0 par 0.00s 0.00s  0.0001s 0.0003s 
    Gen 1   4 colls,  0 par 0.03s 0.04s  0.0103s 0.0211s 

    TASKS: 5 (1 bound, 4 peak workers (4 total), using -N1) 

    SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled) 

    INIT time 0.00s ( 0.00s elapsed) 
    MUT  time 0.86s (224.38s elapsed) 
    GC  time 0.03s ( 0.05s elapsed) 
    RP  time 0.00s ( 0.00s elapsed) 
    PROF time 0.00s ( 0.00s elapsed) 
    EXIT time 0.00s ( 0.00s elapsed) 
    Total time 0.90s (224.43s elapsed) 

    Alloc rate 26,778,662 bytes per MUT second 

    Productivity 96.9% of total user, 0.4% of total elapsed 

gc_alloc_block_sync: 0 
whitehole_spin: 0 
gen[0].sync: 0 
gen[1].sync: 0 


real 3m44.447s 
user 0m0.896s 
sys  0m0.320s

e con profiling:

$ time mysite +RTS -I0 
^C  23,024,424 bytes allocated in the heap 
     19,367,640 bytes copied during GC 
     2,319,960 bytes maximum residency (94 sample(s)) 
     211,312 bytes maximum slop 
       6 MB total memory in use (0 MB lost due to fragmentation) 

            Tot time (elapsed) Avg pause Max pause 
    Gen 0  27 colls,  0 par 0.00s 0.00s  0.0002s 0.0005s 
    Gen 1  94 colls,  0 par 1.09s 1.04s  0.0111s 0.0218s 

    TASKS: 5 (1 bound, 4 peak workers (4 total), using -N1) 

    SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled) 

    INIT time 0.00s ( 0.00s elapsed) 
    MUT  time 1.00s (201.66s elapsed) 
    GC  time 1.07s ( 1.03s elapsed) 
    RP  time 0.00s ( 0.00s elapsed) 
    PROF time 0.02s ( 0.02s elapsed) 
    EXIT time 0.00s ( 0.00s elapsed) 
    Total time 2.09s (202.68s elapsed) 

    Alloc rate 23,115,591 bytes per MUT second 

    Productivity 47.7% of total user, 0.5% of total elapsed 

gc_alloc_block_sync: 0 
whitehole_spin: 0 
gen[0].sync: 0 
gen[1].sync: 0 


real 3m22.697s 
user 0m2.088s 
sys  0m0.060s

mysite.prof:

Sun May 31 19:16 2015 Time and Allocation Profiling Report (Final) 

     mysite +RTS -N -p -s -h -i0.1 -I0 -RTS 

    total time =  0.05 secs (49 ticks @ 1000 us, 1 processor) 
    total alloc = 17,590,528 bytes (excludes profiling overheads) 

COST CENTRE   MODULE     %time %alloc 

MAIN     MAIN     98.0 93.7 
acquireSeedSystem.\.\ System.Random.MWC  2.0 0.0 
toByteString   Data.Serialize.Builder 0.0 3.9 


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

MAIN      MAIN          5684   0 98.0 93.7 100.0 100.0 
createSystemRandom   System.Random.MWC       11396   0 0.0 0.0  2.0 0.3 
    withSystemRandom   System.Random.MWC       11397   0 0.0 0.1  2.0 0.3 
    acquireSeedSystem  System.Random.MWC       11399   0 0.0 0.0  2.0 0.2 
    acquireSeedSystem.\  System.Random.MWC       11401   1 0.0 0.2  2.0 0.2 
    acquireSeedSystem.\.\ System.Random.MWC       11403   1 2.0 0.0  2.0 0.0 
sndS      Data.Serialize.Put       11386   21 0.0 0.0  0.0 0.0 
put      Data.Serialize        11384   21 0.0 0.0  0.0 0.0 
unPut      Data.Serialize.Put       11383   21 0.0 0.0  0.0 0.0 
toByteString    Data.Serialize.Builder      11378   21 0.0 3.9  0.0 4.0 
    flush.\     Data.Serialize.Builder      11393   21 0.0 0.0  0.0 0.0 
    withSize     Data.Serialize.Builder      11388   0 0.0 0.0  0.0 0.0 
    withSize.\    Data.Serialize.Builder      11389   21 0.0 0.0  0.0 0.0 
    runBuilder    Data.Serialize.Builder      11390   21 0.0 0.0  0.0 0.0 
    runBuilder    Data.Serialize.Builder      11382   21 0.0 0.0  0.0 0.0 
unstream/resize   Data.Text.Internal.Fusion     11372   174 0.0 0.1  0.0 0.1 
CAF      GHC.IO.Encoding       11322   0 0.0 0.0  0.0 0.0 
CAF      GHC.IO.FD         11319   0 0.0 0.0  0.0 0.0 
CAF      GHC.IO.Handle.FD       11318   0 0.0 0.2  0.0 0.2 
CAF      GHC.Event.Thread       11304   0 0.0 0.0  0.0 0.0 
CAF      GHC.Conc.Signal       11292   0 0.0 0.0  0.0 0.0 
CAF      GHC.IO.Encoding.Iconv      11288   0 0.0 0.0  0.0 0.0 
CAF      GHC.TopHandler        11284   0 0.0 0.0  0.0 0.0 
CAF      GHC.Event.Control       11271   0 0.0 0.0  0.0 0.0 
CAF      Main          11263   0 0.0 0.0  0.0 0.0 
    main      Main          11368   1 0.0 0.0  0.0 0.0 
CAF      Application        11262   0 0.0 0.0  0.0 0.0 
CAF      Foundation         11261   0 0.0 0.0  0.0 0.0 
CAF      Model          11260   0 0.0 0.1  0.0 0.3 
    unstream/resize   Data.Text.Internal.Fusion     11375   35 0.0 0.1  0.0 0.1 
CAF      Settings         11259   0 0.0 0.1  0.0 0.2 
    unstream/resize   Data.Text.Internal.Fusion     11370   20 0.0 0.1  0.0 0.1 
CAF      Database.Persist.Postgresql     6229   0 0.0 0.3  0.0 0.9 
    unstream/resize   Data.Text.Internal.Fusion     11373   93 0.0 0.6  0.0 0.6 
CAF      Database.PostgreSQL.Simple.Transaction  6224   0 0.0 0.0  0.0 0.0 
CAF      Database.PostgreSQL.Simple.TypeInfo.Static 6222   0 0.0 0.0  0.0 0.0 
CAF      Database.PostgreSQL.Simple.Internal   6219   0 0.0 0.0  0.0 0.0 
CAF      Yesod.Static        6210   0 0.0 0.0  0.0 0.0 
CAF      Crypto.Hash.Conduit       6193   0 0.0 0.0  0.0 0.0 
CAF      Yesod.Default.Config2      6192   0 0.0 0.0  0.0 0.0 
    unstream/resize   Data.Text.Internal.Fusion     11371   1 0.0 0.0  0.0 0.0 
CAF      Yesod.Core.Internal.Util     6154   0 0.0 0.0  0.0 0.0 
CAF      Text.Libyaml        6121   0 0.0 0.0  0.0 0.0 
CAF      Data.Yaml         6120   0 0.0 0.0  0.0 0.0 
CAF      Data.Yaml.Internal       6119   0 0.0 0.0  0.0 0.0 
    unstream/resize   Data.Text.Internal.Fusion     11369   1 0.0 0.0  0.0 0.0 
CAF      Database.Persist.Quasi      6055   0 0.0 0.0  0.0 0.0 
    unstream/resize   Data.Text.Internal.Fusion     11376   1 0.0 0.0  0.0 0.0 
CAF      Database.Persist.Sql.Internal    6046   0 0.0 0.0  0.0 0.0 
    unstream/resize   Data.Text.Internal.Fusion     11377   6 0.0 0.0  0.0 0.0 
CAF      Data.Pool         6036   0 0.0 0.0  0.0 0.0 
CAF      Network.HTTP.Client.TLS      6014   0 0.0 0.0  0.0 0.0 
CAF      System.X509.Unix       6010   0 0.0 0.0  0.0 0.0 
CAF      Crypto.Hash.MD5        5927   0 0.0 0.0  0.0 0.0 
CAF      Data.Serialize        5873   0 0.0 0.0  0.0 0.0 
    put      Data.Serialize        11385   1 0.0 0.0  0.0 0.0 
CAF      Data.Serialize.Put       5872   0 0.0 0.0  0.0 0.0 
    withSize     Data.Serialize.Builder      11387   1 0.0 0.0  0.0 0.0 
CAF      Data.Serialize.Builder      5870   0 0.0 0.0  0.0 0.0 
    flush      Data.Serialize.Builder      11392   1 0.0 0.0  0.0 0.0 
    toByteString    Data.Serialize.Builder      11391   0 0.0 0.0  0.0 0.0 
    defaultSize    Data.Serialize.Builder      11379   1 0.0 0.0  0.0 0.0 
    defaultSize.overhead  Data.Serialize.Builder      11381   1 0.0 0.0  0.0 0.0 
    defaultSize.k   Data.Serialize.Builder      11380   1 0.0 0.0  0.0 0.0 
CAF      Crypto.Random.Entropy.Unix     5866   0 0.0 0.0  0.0 0.0 
CAF      Network.HTTP.Client.Manager     5861   0 0.0 0.0  0.0 0.0 
    unstream/resize   Data.Text.Internal.Fusion     11374   3 0.0 0.0  0.0 0.0 
CAF      System.Random.MWC       5842   0 0.0 0.0  0.0 0.0 
    coff      System.Random.MWC       11405   1 0.0 0.0  0.0 0.0 
    ioff      System.Random.MWC       11404   1 0.0 0.0  0.0 0.0 
    acquireSeedSystem   System.Random.MWC       11398   1 0.0 0.0  0.0 0.0 
    acquireSeedSystem.random System.Random.MWC       11402   1 0.0 0.0  0.0 0.0 
    acquireSeedSystem.nbytes System.Random.MWC       11400   1 0.0 0.0  0.0 0.0 
    createSystemRandom  System.Random.MWC       11394   1 0.0 0.0  0.0 0.0 
    withSystemRandom   System.Random.MWC       11395   1 0.0 0.0  0.0 0.0 
CAF      Data.Streaming.Network.Internal    5833   0 0.0 0.0  0.0 0.0 
CAF      Data.Scientific        5728   0 0.0 0.1  0.0 0.1 
CAF      Data.Text.Array        5722   0 0.0 0.0  0.0 0.0 
CAF      Data.Text.Internal       5718   0 0.0 0.0  0.0 0.0

Modifica 2015-06-01 08:40

È possibile sfogliare il codice sorgente al seguente repository → https://github.com/Zigazou/Ouep

fonte

2015-05-30 zigazou

Qualsiasi caricamento e inizializzazione contano ('cat' non mostra nulla perché carica in <1ms). Aumenta ulteriormente col passare del tempo? Da quanto? –

Sì, aumenta col passare del tempo. Ho scoperto questo comportamento quando guardavo 'top', vedendo il mio sito nei primi dieci processi. Così ho deciso di provare con 'time' per avere numeri migliori di' top'. – zigazou

Il tempo di '0.352s' potrebbe essere la configurazione del runtime + Yesod. Per un confronto migliore, prova ad aspettare 1m e ad aspettare 2m e sottrarre i tempi: questo dovrebbe darti una stima migliore della CPU/s. – chi

Trovato un related bug nel bug tracker Yesod. Ran il mio programma come questo:

mioserver + RTS -i0 -RTS Sviluppo

E ora l'utilizzo della CPU inattiva è scesa a quasi nulla, rispetto al 14% o giù di lì prima (del computer ARM). L'opzione I0 (vale a dire I e zero) disattiva la garbage collection periodica, che per impostazione predefinita è di 0.3 secondi. Non sono sicuro delle implicazioni sulla reattività delle app o sull'uso della memoria, ma per me almeno questo è sicuramente il colpevole.

fonte

2015-06-27 18:29:14 Bzzt

Piccola perdita CPU Haskell

risposta

Problemi correlati