从 GHC 分析器中理解

Question

我试图从 GHC 分析器中理解。有一个相当简单的应用程序，它使用 werq 和 lens-aeson 库，在学习 GHC 分析的同时，我决定尝试一下。

使用不同的选项（time 工具、+RTS -p -RTS 和 +RTS -p -h）我获得了完全不同的内存使用量。有了所有这些数字，我现在完全无法理解发生了什么，以及应用程序实际使用了多少内存。

这种情况让我想起了 Arthur Bloch 的一句话："A man with a watch knows what time it is. A man with two watches is never sure."

能否请你给我一些建议，我如何读取所有这些数字，每个数字的含义是什么。

这是数字：

time -l 报告大约 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

使用 +RTS -p -RTS 标志报告大约 92M。虽然它说"total alloc"我觉得很奇怪，像这样一个简单的应用程序可以分配和释放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 和 hp2ps 给我看下面的图片和两个数字： 114K 在 header 和 [=48= 周围的东西]1.8Mb 在图表上。

并且，以防万一，这是应用程序：

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

更新 1： 感谢大家的精彩回复。正如建议的那样，我添加了 +RTS -s 输出，这样整个图片就可以为阅读它的每个人构建起来。

#./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

更新 2：可执行文件的大小：

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

Answer 1

time -l 显示操作系统看到的（常驻，即未换出）进程大小（很明显）。这包括 Haskell 堆最大大小的两倍（由于 GHC 的 GC 工作方式），加上 RTS 或其他 C 库分配的任何其他内容，加上可执行文件本身的代码加上它所依赖的库等。我猜在这种情况下，19M 的主要贡献者是您的可执行文件的大小。

total alloc 是分配到 Haskell 堆上的总量。它根本不是最大堆大小的度量（这是人们通常所说的 "how much memory is my program using" 的意思）。分配非常便宜，Haskell 程序的典型分配速率约为 1GB/s。

hp2ps 输出“114,272 字节 x 秒”的 header 中的数字再次完全不同：它是图形的积分，以字节 * 秒为单位，而不是以字节为单位。例如，如果您的程序在 10 MB 结构上保持 4 秒，那么这将导致该数字增加 40 MB*s。

图中显示的大约 1.8 MB 的数字是 Haskell 堆的实际最大大小，这可能是您最感兴趣的数字。

您省略了有关程序执行的最有用的数字来源，即运行和 +RTS -s（这甚至不需要它是通过分析构建的）。

Answer 2

A man with a watch knows what time it is. A man with two watches is never sure.

啊，但是两只手表代表什么？两者都是为了显示 UTC 中的当前时间吗？或者其中一个应该显示 UTC 时间，另一个显示火星上某个点的时间？只要同步，第二种情况应该没问题吧？

这正是这里发生的事情。您比较不同的内存测量值：

最长居住时间
已分配内存总量

最大驻留时间是您的程序在给定时间使用的最大内存量。那是19MB。但是，分配的内存总量要多得多，因为这就是 GHC 的工作方式：它 "allocates" 内存用于垃圾收集的对象，几乎是所有未解压缩的对象。

让我们为此检查一个 C 示例：

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

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

每当我们使用malloc时，我们将分配19兆字节的内存。但是，我们会在之后立即释放内存。因此，我们曾经拥有的最高内存量是 19 兆字节（堆栈和程序本身的内存量要多一点）。

但是，我们总共分配了 5 * 19M，总共 95M。不过，我们可以运行我们的小程序只需要 20 兆的 RAM。这就是 总分配内存 和 最大驻留 之间的区别。请注意，时间报告的驻留时间总是至少 du <executable>，因为它也必须驻留在内存中。

也就是说，生成统计信息的最简单方法是 -s，它将显示从 Haskell 程序的角度看最大驻留时间是多少。在您的情况下，它将是 1.9M，您的堆配置文件中的数字（或由于配置文件而增加一倍的数量）。是的，Haskell 可执行文件往往会变得非常大，因为库是静态链接的。

从 GHC 分析器中理解

Making sense from GHC profiler

profiling

haskell

ghc