Блог

Я пытаюсь понять смысл из GHC profiler. Существует довольно простое приложение, которое использует werq lens-aeson библиотеки и, и, изучая профилирование GHC, я решил немного поиграть с ним.

Использование различных опций ( time инструмент, RTS -p -RTS и RTS -p -h ) Я приобрел совершенно другие показатели использования моей памяти. Имея все эти цифры, я теперь совершенно запутался, пытаясь понять, что происходит, и сколько памяти на самом деле использует приложение.

Эта ситуация напоминает мне фразу Артура Блоха: «Человек с часами знает, который час. Человек с двумя часами никогда не бывает уверен.

Не могли бы вы, пожалуйста, подсказать мне, как я могу прочитать все эти цифры и каково значение каждой из них.

Вот цифры:

time -l отчеты около 19 миллионов

 #/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 флаговых отчетов составляет около 92 млн. Хотя там написано «total alloc», мне кажется странным, что такое простое приложение, как это, может выделить и выпустить 91 млн.

 # ./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 покажите мне следующую картинку и два числа: 114 КБ в заголовке и что-то около 1,8 Мб на графике.

И, на всякий случай, вот приложение:

 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
 

Человек с часами знает, который час. Человек с двумя часами никогда не уверен.

Ах, но что показывают два наблюдения? Оба предназначены для отображения текущего времени в UTC? Или один из них должен показывать время в UTC, а другой — время в определенной точке на Марсе? Пока они синхронизированы, второй сценарий не будет проблемой, не так ли?

И это именно то, что здесь происходит. Вы сравниваете разные измерения памяти:

• максимальная резидентность
• общий объем выделенной памяти

Максимальный объем памяти — это наибольший объем памяти, который ваша программа когда-либо использовала в данный момент времени. Это 19 МБАЙТ. Однако общий объем выделенной памяти намного больше, поскольку именно так работает GHC: он «выделяет» память для объектов, которые собирают мусор, то есть почти все, что не распаковано.

Давайте рассмотрим пример 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 * 19 млн, итого 95 млн. Тем не менее, мы могли бы нормально запустить нашу маленькую программу, имея всего 20 мегабайт оперативной памяти. В этом разница между общим объемом выделенной памяти и максимальным сроком хранения. Обратите внимание, что резидентность, указываемая временем, всегда как минимум du <executable> , поскольку она тоже должна храниться в памяти.

При этом самый простой способ сгенерировать статистику -s — это показать, каков был максимальный резидент с точки зрения программы Haskell. В вашем случае это будет 1,9M, число в вашем профиле кучи (или удвоенное количество из-за профилирования). И да, исполняемые файлы Haskell, как правило, становятся чрезвычайно большими, поскольку библиотеки статически связаны.