2014-05-03 8 views
5

Sto eseguendo un programma Haskell che esegue un lungo calcolo. Dopo un po 'di profilazione e tracciamento, ho notato quanto segue:Haskell profiling - clock_gettime

$ /usr/bin/time -v ./hl test.hl 
9000045000050000 
Command being timed: "./hl test.hl +RTS" 
User time (seconds): 1.43 
System time (seconds): 1.15 

E' stato utilizzato un sacco di tempo del sistema, anche se il mio codice non richiama esplicitamente le chiamate di sistema (si legge un file e interpreta po 'di codice in esso).

eseguendolo con strace -ttT mostra un sacco di chiamate a un timer:

17:04:52.454513 clock_gettime(CLOCK_THREAD_CPUTIME_ID, {1, 282721271}) = 0 <0.000529> 
17:04:52.456223 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000720> 
17:04:52.458749 rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0 <0.000239> 
17:04:52.460288 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {1, 285126436}) = 0 <0.000255> 
17:04:52.461650 --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_pid=0, si_uid=0, si_value=0} --- 
17:04:52.462242 rt_sigreturn()   = 0 <0.000458> 

ho pensato che potrebbe essere il RTS clock, quindi ho disabilitato e ri-run:

$ /usr/bin/time -v ./hl test.hl +RTS -V0 
9000045000050000 
Command being timed: "./hl test.hl +RTS -V0" 
User time (seconds): 1.73 
System time (seconds): 0.85 

L'output strace sembra quasi identico tranne che per l'attuale SIGVTALRM:

17:05:16.409729 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 155881514}) = 0 <0.000378> 
17:05:16.410746 clock_gettime(CLOCK_MONOTONIC, {2184631, 597586194}) = 0 <0.000432> 
17:05:16.412724 clock_gettime(CLOCK_THREAD_CPUTIME_ID, {0, 156994988}) = 0 <0.000290> 
17:05:16.413832 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000245> 
17:05:16.415017 rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0 <0.000305> 

I have a alcune domande:

  1. Perché Haskell chiama ripetutamente clock_gettime?
  2. C'è un modo per disabilitare questa funzionalità?
+0

sebbene non sia una soluzione al tuo problema, ma hai esaminato il criterio - per la creazione di profili? – epsilonhalbe

+0

Stai eseguendo il profiling? Il profiling fa un lavoro extra. – GarethR

+1

@GarethR: Mi sono assicurato che stia funzionando senza profilazione, persino creato una nuova sandbox cabal per essere sicuro di questo fatto. –

risposta

0

ho preso uno sguardo dove clock_gettime è chiamato nel GHC RTS e ha scoperto che è utilizzato in una chiamata a getMonotonicTime che a sua volta è alla base dei timeout nel TimerManager della biblioteca GHC.Event che viene utilizzato da l'IO Manager per il polling su handle, file, chiamate di sistema, ecc. La carta MIO è una buona risorsa relativamente recente nell'IO Manager. In ogni caso, non immagino che sarai in grado di eliminare quelle chiamate.

Si noti inoltre che mentre si vede un sacco di quelle chiamate di clock, questo non significa che sono le chiamate di sistema che stanno prendendo il momento più , che immagino si riferiscono più per GC, in realtà dello spettacolo IO, ecc