Haskell 分析 - clock_gettime答案

【问题标题】：Haskell profiling - clock_gettimeHaskell 分析 - clock_gettime
【发布时间】：2014-06-19 18:24:02
【问题描述】：

我正在运行一个进行长时间计算的 Haskell 程序。经过一些分析和跟踪，我注意到以下几点：

$ /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

即使我的代码没有显式调用任何系统调用（它读取文件并解释其中的一些代码），它也使用了大量系统时间。

使用 strace -ttT 运行它会显示对计时器的大量调用：

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>

我认为它可能是RTS clock，所以我禁用它并重新运行：

$ /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

除了实际的 SIGVTALRM 之外，strace 的输出看起来几乎相同：

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>

我有几个问题：

为什么 Haskell 反复调用 clock_gettime？
有没有办法禁用此功能？

【问题讨论】：

虽然它不能解决您的问题，但您是否查看了标准 - 进行分析？
您正在运行分析吗？分析会做额外的工作。
@GarethR：我确保我在没有分析的情况下运行，甚至创建了一个新的阴谋集团沙箱来确定这一事实。

标签： haskell profiling clock

【解决方案1】：

我查看了在 GHC RTS 中调用 clock_gettime 的位置，发现它用于对 getMonotonicTime 的调用，而这又是 GHC.Event 的 TimerManager 中超时的基础IO 管理器用于轮询句柄、文件、系统调用等的库。MIO 论文是 IO 管理器上一个很好的相对较新的资源。无论如何，我不认为您将能够消除这些电话。

还请注意，虽然您看到很多个时钟调用，但这并不意味着它们是花费最多时间的系统调用，我想这更相关到GC，实际执行IO等

【讨论】：