Утечки памяти и как их отследить

[Андрей Никифоров]

Ситуация такова:

Есть краулер. Полный код тут https://github.com/adnikiforov/go_crawler

Логика работы такова: сперва читается большой (порядка 300Мб) CSV файл с доменами, парсится и кладется целиком в буферизованный канал:

queueSize := len(rawCSVdata)
queueChannel = make(chan string, queueSize)
for _, each := range rawCSVdata {
    queueChannel <- each[0]
}
close(queueChannel)

Ничего лучше в голову не пришло, к сожалению.

Затем запускаются воркеры (роутины), количеством порядка 1000 штук, и читают из канала домены, запрашивают главную страницу и обрабатывают ее регулярками.

Проблема вот в чем: сразу после запуска резко подскакивает потребление памяти: htop показывает сразу порядка 7Гб занятой памяти (еще до запуска воркеров), ps -e -orss=,args= -m показывает порядка 2Гб, cacti - 7Гб, pprof же показывает совсем другое:

223.19MB of 224.23MB total (99.53%)

Dropped 8 nodes (cum <= 1.12MB)

     flat  flat%   sum%        cum   cum%

 175.51MB 78.27% 78.27%   175.51MB 78.27%  encoding/csv.(*Reader).parseRecord

  47.67MB 21.26% 99.53%   223.19MB 99.53%  encoding/csv.(*Reader).ReadAll

        0     0% 99.53%   223.19MB 99.53%  crawler.Run

        0     0% 99.53%   223.19MB 99.53%  crawler.startQueue

        0     0% 99.53%   175.51MB 78.27%  encoding/csv.(*Reader).Read

        0     0% 99.53%   223.19MB 99.53%  main.main

        0     0% 99.53%   223.73MB 99.78%  runtime.goexit

        0     0% 99.53%   223.73MB 99.78%  runtime.main

Чуть дальше картина немного меняется, но htop продолжает показывать 7Гб, ps уже кажет около 3Гб и растет.

522.09MB of 535.09MB total (97.57%)

Dropped 185 nodes (cum <= 2.68MB)

Showing top 10 nodes out of 29 (cum >= 56.22MB)

     flat  flat%   sum%        cum   cum%

 221.20MB 41.34% 41.34%   221.20MB 41.34%  compress/flate.NewReader

     91MB 17.01% 58.34%       91MB 17.01%  encoding/csv.(*Reader).parseRecord

  74.54MB 13.93% 72.27%   165.54MB 30.94%  crawler.startQueue

  56.22MB 10.51% 82.78%    56.22MB 10.51%  bufio.NewReaderSize

  32.51MB  6.08% 88.86%    32.51MB  6.08%  bytes.makeSlice

  30.12MB  5.63% 94.49%    30.12MB  5.63%  bufio.NewWriter

   9.50MB  1.78% 96.26%     9.50MB  1.78%  compress/flate.(*huffmanDecoder).init

   3.50MB  0.65% 96.92%   247.79MB 46.31%  compress/gzip.NewReader

   3.50MB  0.65% 97.57%    69.25MB 12.94%  net/http.(*Transport).dialConn

        0     0% 97.57%    56.22MB 10.51%  bufio.NewReader

А дальше еще веселее (ps 6Гб, htop/cacti 13Гб)

1.86GB of 1.91GB total (97.58%)

Dropped 242 nodes (cum <= 0.01GB)

Showing top 10 nodes out of 40 (cum >= 0.02GB)

     flat  flat%   sum%        cum   cum%

   1.11GB 57.99% 57.99%     1.11GB 57.99%  compress/flate.NewReader

   0.30GB 15.50% 73.49%     0.30GB 15.50%  bufio.NewReaderSize

   0.16GB  8.53% 82.02%     0.16GB  8.53%  bufio.NewWriter

   0.09GB  4.64% 86.66%     0.09GB  4.64%  encoding/csv.(*Reader).parseRecord

   0.07GB  3.82% 90.48%     0.16GB  8.45%  crawler.startQueue

   0.05GB  2.59% 93.06%     0.05GB  2.59%  compress/flate.(*huffmanDecoder).init

   0.03GB  1.65% 94.72%     0.03GB  1.65%  bytes.makeSlice

   0.02GB  1.23% 95.94%     0.38GB 19.97%  net/http.(*Transport).dialConn

   0.02GB  1.03% 96.97%     1.24GB 65.18%  compress/gzip.NewReader

   0.01GB  0.61% 97.58%     0.02GB  1.08%  net/http.(*persistConn).readLoop

Как это понимать, как интерпретировать и как бороться с такими аппетитами? Это не выглядит нормальным потреблением памяти.

go version go1.4.2 linux/amd64

Linux vs08.host 2.6.32-042stab090.5 #1 SMP Sat Jun 21 00:15:09 MSK 2014 x86_64 x86_64 x86_64 GNU/Linux
CentOS release 6.6 (Final)

cpe:/o:centos:linux:6:GA

Заранее спасибо.

[Dmitry Vyukov]

Сколько вы ожидаете программа должна потреблять?

Снимите MemStats и gctrace:
https://software.intel.com/en-us/blogs/2014/05/10/debugging-performance-issues-in-go-programs
там будет видно куда идет память

> --
> Вы получили это сообщение, поскольку подписаны на группу "Golang Russian".
> Чтобы отменить подписку на эту группу и больше не получать от нее сообщения,
> отправьте письмо на электронный адрес
> golang-ru+...@googlegroups.com.
> Чтобы настроить другие параметры, перейдите по ссылке
> https://groups.google.com/d/optout.

[Андрей Никифоров]

Я ожидаю потребление как около 75-100Мб на очередь задач (список доменов, скажем по 16байт на домен, 4.8кк доменов - около 75Мб + накладные расходы) + какое-то константное потребление воркерами, порядка 1-2Мб на воркер.

MemStat я снял через net/http/pprof, вот результат в установившемся режиме работы:

3.52GB of 3.59GB total (98.04%)

Dropped 275 nodes (cum <= 0.02GB)

Showing top 10 nodes out of 43 (cum >= 0.03GB)

     flat  flat%   sum%        cum   cum%

   2.22GB 61.85% 61.85%     2.22GB 61.85%  compress/flate.NewReader

   0.58GB 16.09% 77.94%     0.58GB 16.09%  bufio.NewReaderSize

   0.33GB  9.15% 87.09%     0.33GB  9.15%  bufio.NewWriter

   0.09GB  2.60% 89.69%     0.09GB  2.60%  compress/flate.(*huffmanDecoder).init

   0.09GB  2.45% 92.14%     0.09GB  2.45%  encoding/csv.(*Reader).parseRecord

   0.07GB  2.03% 94.17%     0.16GB  4.48%  crawler.startQueue

   0.06GB  1.55% 95.72%     0.73GB 20.29%  net/http.(*Transport).dialConn

   0.04GB  0.99% 96.72%     2.51GB 70.04%  compress/gzip.NewReader

   0.03GB  0.77% 97.49%     0.03GB  0.77%  bytes.makeSlice

   0.02GB  0.54% 98.04%     0.03GB  0.94%  net/http.(*persistConn).readLoop

Из того, что я вижу - память ест compress/flate.NewReader. Я даже нашел баг с этой штукой, но он давно закрыт.

gctrace снял, вот результат: http://pastebin.com/U1tHkZDf

Из него я смог понять только то, что в каком-то месте экспоненциально растет количество объектов, видимо мелких, но много, судя по цифрам total in heap и memory allocation.

Я предполагаю, что проблема кроется где-то в воркерах, где-то в цикле создается объект(ы) и не прибивается GC. Как это можно продебажить?

вторник, 3 марта 2015 г., 7:51:34 UTC+3 пользователь Dmitry Vyukov написал:

[Dmitry Vyukov]

2015-03-03 9:37 GMT+03:00 Андрей Никифоров <a.d.ni...@gmail.com>:
> Я ожидаю потребление как около 75-100Мб на очередь задач (список доменов,
> скажем по 16байт на домен, 4.8кк доменов - около 75Мб + накладные расходы) +
> какое-то константное потребление воркерами, порядка 1-2Мб на воркер.
>
> MemStat я снял через net/http/pprof, вот результат в установившемся режиме
> работы:

Это не MemStats. Через net/http/pprof его можно получит, если открыть
debug/pprof/heap?debug=2, он там будет в низу. Однако тут он не
поможет.

Насколько я вижу память потребляется compress/flate.NewReader. Вы
можете их колчиество ограничить с помощью семафора.

[Alexandr Lurye]

Вы создаете канал с буфером 300M элементов (если я правильно интерпретирую rawCSVdata). Он у вас на запуске съедает слишком много памяти. Правильно делать не так:

1. Создать канал с небольшим буфером (1 тыс элементов попробуйте, это на глаз)
2. Запустить воркеры
3. Записывать строчки в канал
4. Закрыть канал

--

[Dmitry Vyukov]

for t := range ticker.C {
t.String() //Prevent compile "variable not used" error

В 1.4 это пишется как:

for range ticker.C {

2015-03-03 0:42 GMT+03:00 Андрей Никифоров <a.d.ni...@gmail.com>:

[Андрей Никифоров]

Я не совсем понимаю, как это можно сделать, сейчас у меня получается так: воркеры (100 воркеров) обрабатывают примерно 300 записей из канала и после этого работа практически встает - в канал ничего не пишется, из канала воркеры ничего не читают. Иногда (очень редко) читают одну запись и снова встают. При этом в канал записано аккурат 1000+количество обработанных записей, то есть буфер заполнен, но воркеры оттуда ничего не читают.

Я уже пытался сделать что-то подобное, но ничего не получилось, единственный рабочий вариант - полностью уместить записи в буфер.

Подозреваю, что делаю что-то не так, но не пойму, в чем ошибка.

вторник, 3 марта 2015 г., 10:35:24 UTC+3 пользователь Alexandr Lurye написал:

[Dmitry Vyukov]

c := make(chan Item, runtime.GOMAXPROCS() * 4)
go func() {
for ... {
c <- ...
}
close(c)
}()

// workers
for i := range c {
}

Если это будет виснуть, то это не оно, а что-то другое.
Убейте процесс kill -6 и по стекам будет понятно, где они висят.

[Андрей Никифоров]

Получил вот что:

goroutine 0 [idle]:

runtime.futex(0x9794d8, 0x0, 0x0, 0x0, 0x0, 0x978b60, 0x1, 0x40c1af, 0x40c3ce, 0x9794d8, ...)

       /usr/local/go/src/runtime/sys_linux_amd64.s:277 +0x21

runtime.futexsleep(0x9794d8, 0x0, 0xffffffffffffffff)

       /usr/local/go/src/runtime/os_linux.c:49 +0x4

runtime.notesleep(0x9794d8)

       /usr/local/go/src/runtime/lock_futex.go:145 +0xae

stopm()

       /usr/local/go/src/runtime/proc.c:1178 +0x119

findrunnable(0xc208012000)

       /usr/local/go/src/runtime/proc.c:1487 +0x562

schedule()

       /usr/local/go/src/runtime/proc.c:1575 +0x151

runtime.park_m(0xc20810fc20)

       /usr/local/go/src/runtime/proc.c:1654 +0x113

runtime.mcall(0x434a84)

       /usr/local/go/src/runtime/asm_amd64.s:186 +0x5a

Основной поток висит на WaitGroup.Wait(), парсер CSV на chan send, воркеры на IO wait. А вот как интерпретировать idle на runtime.futex - не понимаю.

вторник, 3 марта 2015 г., 12:51:52 UTC+3 пользователь Dmitry Vyukov написал:

[Dmitry Vyukov]

2015-03-03 13:44 GMT+03:00 Андрей Никифоров <a.d.ni...@gmail.com>:
> Получил вот что:
>
> goroutine 0 [idle]:
>
> runtime.futex(0x9794d8, 0x0, 0x0, 0x0, 0x0, 0x978b60, 0x1, 0x40c1af,
> 0x40c3ce, 0x9794d8, ...)
>
> /usr/local/go/src/runtime/sys_linux_amd64.s:277 +0x21
>
> runtime.futexsleep(0x9794d8, 0x0, 0xffffffffffffffff)
>
> /usr/local/go/src/runtime/os_linux.c:49 +0x4
>
> runtime.notesleep(0x9794d8)
>
> /usr/local/go/src/runtime/lock_futex.go:145 +0xae
>
> stopm()
>
> /usr/local/go/src/runtime/proc.c:1178 +0x119
>
> findrunnable(0xc208012000)
>
> /usr/local/go/src/runtime/proc.c:1487 +0x562
>
> schedule()
>
> /usr/local/go/src/runtime/proc.c:1575 +0x151
>
> runtime.park_m(0xc20810fc20)
>
> /usr/local/go/src/runtime/proc.c:1654 +0x113
>
> runtime.mcall(0x434a84)
>
> /usr/local/go/src/runtime/asm_amd64.s:186 +0x5a
>
>
> Основной поток висит на WaitGroup.Wait(), парсер CSV на chan send, воркеры
> на IO wait. А вот как интерпретировать idle на runtime.futex - не понимаю.

Значит все воркеры ждут сети.

[Alexandr Lurye]

Покажите полный код.

--
Вы получили это сообщение, поскольку подписаны на группу Golang Russian.

Чтобы отменить подписку на эту группу и больше не получать от нее сообщения, отправьте письмо на электронный адрес golang-ru+unsubscribe@googlegroups.com.
Настройки подписки и доставки писем: https://groups.google.com/d/optout.

[Андрей Никифоров]

func workerRoutine(channel <-chan string) {
   statWorkersCount++
   defer waitGroup.Done()
   for {
      domain := <-channel
      statOverall++
      response, error := client.Get(string(strings.Join([]string{"http://", domain}, "")))
      if error != nil {
         statDomainError++
         break
      }
      defer response.Body.Close()
      body, error := ioutil.ReadAll(response.Body)
      if error != nil {
         statHttpError++
         break
      }
      applyRegexps(body, domain)
   }
}

Это код воркера.

Вообще полный код https://github.com/adnikiforov/go_crawler/tree/master/src/crawler, чтобы не загромождать топик.

вторник, 3 марта 2015 г., 15:07:44 UTC+3 пользователь Alexandr Lurye написал:

Покажите полный код.

Чтобы отменить подписку на эту группу и больше не получать от нее сообщения, отправьте письмо на электронный адрес golang-ru+...@googlegroups.com.

[Вячеслав Бахмутов]

defer response.Body.Close() 

сработает только когда workerRoutine завершит своё выполнение

вторник, 3 марта 2015 г., 10:24:17 UTC-3 пользователь Андрей Никифоров написал:

[Alexandr Lurye]

Я не нашёл логики, которая бы прерывала saveRoutine. Поэтому последний раз waitGroup.Done никто не вызывает, и программа не завершается.