Подозрение на утечку памяти
akosyrev opened this issue · 18 comments
Версия 0.30.9
Сценарий, на котором хорошо воспроизводится: раз в час find обходит бакет (около 230 000 файлов), удаляет попавшие под условие.
В таком режиме за 5 дней процесс geesefs отъедает 25Гб памяти и убивается ООМ.
Использованные опции:
-o rw,allow_other,--file-mode=0666,--dir-mode=0777,--uid=yyy,--gid=xxx,--shared-config=/etc/passwd-geesefs,--endpoint=http://host:port,--http-timeout=10s,--retry-interval=5s,--list-type=2,dev,suid,--debug,--log-file=/tmp/log111.txt
Нашел тикет #23 , прочитал про переменную PPROF, но почему-то порт не открывается, в дебаг-логе только "2022/04/28 13:42:11.549886 main.INFO File system has been successfully mounted."
Почитал в /proc/21217/environ , переменная есть:
xargs --null --max-args=1 echo < /proc/21217/environ | grep PPROF
PPROF=6060
S3 не от яндекса.
Еще заметил, что --list-type=1 работает в несколько раз медленнее, чем использовавшийся до этого s3fs. А --list-type=2 дает ускорение примерно в 2 раза для find по тем же объектам по сравнению с s3fs.
По какой-то причине PPROF порт открылся при добавлении -f.
Привет. PPROF возможно я сам проверял только с -f, почему он в бэкграунде не запускается, проверю...
Про медленный list-type=1: в несколько раз медленнее по сравнению с s3fs - это сколько в числах и при какой операции? Для сравнения, у меня листинг ~56000 файлов в тестовом бакете в яндексовом S3 с ноутбука через wifi занимает порядка 20 секунд. Это медленно или быстро? :)
По поводу утечки понял, надо искать, если скинете в итоге профиль от pprof будет полезно, да
Привет. PPROF получился такой
inuse_space:
File: geesefs
Type: inuse_space
Time: May 3, 2022 at 11:20pm (MSK)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 17.87GB, 99.87% of 17.90GB total
Dropped 24 nodes (cum <= 0.09GB)
Showing top 10 nodes out of 20
flat flat% sum% cum cum%
7.80GB 43.59% 43.59% 7.80GB 43.59% github.com/yandex-cloud/geesefs/internal.NewInode
7.30GB 40.78% 84.37% 7.30GB 40.78% github.com/yandex-cloud/geesefs/internal.(*Inode).SetFromBlobItem
2.03GB 11.36% 95.73% 2.03GB 11.36% github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.XMLToStruct
0.60GB 3.34% 99.07% 0.60GB 3.34% github.com/yandex-cloud/geesefs/internal.(*Goofys).insertInode
0.14GB 0.81% 99.87% 0.14GB 0.81% github.com/yandex-cloud/geesefs/internal.(*Goofys).Flusher
0 0% 99.87% 2.03GB 11.36% github.com/aws/aws-sdk-go/aws/request.(*HandlerList).Run
0 0% 99.87% 2.03GB 11.36% github.com/aws/aws-sdk-go/aws/request.(*Request).Send
0 0% 99.87% 2.03GB 11.36% github.com/aws/aws-sdk-go/aws/request.(*Request).sendRequest
0 0% 99.87% 2.03GB 11.36% github.com/aws/aws-sdk-go/private/protocol/restxml.Unmarshal
0 0% 99.87% 2.03GB 11.36% github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.UnmarshalXML
(pprof)
inuse_objects:
(pprof) sample_index=inuse_objects
(pprof) top
Showing nodes accounting for 124285833, 100% of 124324223 total
Dropped 26 nodes (cum <= 621621)
Showing top 10 nodes out of 18
flat flat% sum% cum cum%
47447095 38.16% 38.16% 47447095 38.16% github.com/yandex-cloud/geesefs/internal.(*Inode).SetFromBlobItem
38843083 31.24% 69.41% 38843083 31.24% github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.XMLToStruct
37995655 30.56% 100% 37995655 30.56% github.com/yandex-cloud/geesefs/internal.NewInode
0 0% 100% 38875851 31.27% github.com/aws/aws-sdk-go/aws/request.(*HandlerList).Run
0 0% 100% 38875851 31.27% github.com/aws/aws-sdk-go/aws/request.(*Request).Send
0 0% 100% 38875851 31.27% github.com/aws/aws-sdk-go/aws/request.(*Request).sendRequest
0 0% 100% 38875851 31.27% github.com/aws/aws-sdk-go/private/protocol/restxml.Unmarshal
0 0% 100% 38875851 31.27% github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.UnmarshalXML
0 0% 100% 124324064 100% github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).handleOp
0 0% 100% 124318602 100% github.com/yandex-cloud/geesefs/api/common.FusePanicLogger.ReadDir
Про медленный list-type=1: в несколько раз медленнее по сравнению с s3fs - это сколько в числах и при какой операции? Для сравнения, у меня листинг ~56000 файлов в тестовом бакете в яндексовом S3 с ноутбука через wifi занимает порядка 20 секунд.
У меня видимо не быстрый S3. Около 700 000 объектов, find по файлам, сравнение ctime и удаление старых - около 2 часов на s3fs, до 1 часа на geesefs list-type=2 и более 7 часов с list-type=1 (не стал дожидаться завершения).
По поводу скорости - а можно по дебаг логу посмотреть, там случайно не происходит лишних запросов HEAD? Должны быть только запросы листингов. Ну в целом, выдержку из лога какую-нибудь если бы скинули, могло бы быть полезно
По поводу скорости - а можно по дебаг логу посмотреть, там случайно не происходит лишних запросов HEAD? Должны быть только запросы листингов. Ну в целом, выдержку из лога какую-нибудь если бы скинули, могло бы быть полезно
Дебаг-логи надо с list-type=2 или с list-type=1?
По поводу pprof - кроме вывода top я могу скинуть и бинарник. Есть необходимость?
Я думаю с любым можно, хоть 2 хоть 1, т.к. и час и 7 часов крайне медленно. Достаточно небольшого отрывка лога, дожидаться завершения не нужно
pprof скиньте, да
небольшого отрывка лога
Скинул на "многократно публично запаленный" ящик
Привет, сорри что немного пропал. Ну в логе, который ты скинул, 133 запроса листинга и заняли они примерно 10 секунд. В одном запросе, по идее, возвращается 1000 файлов. То есть 133000 файлов получилось с сервера за 10 секунд. Таким образом, листинг 700000 файлов должен занять секунд 50. С часом вроде не вяжется... Т.е. надо смотреть, что происходит уже после листинга.
Утечку у себя пока не воспроизвёл, попробую ещё.
Возможно поможет для поиска утечки: у меня воспроизводится на сервере, где один и тот же бакет смонтирован в 2 точки монтирования. Одна точка - рабочий каталог демона, вторая - каталог для cron+find. Утекает geesefs исключительно на второй точке.
В общем, есть подозрение, что дело было в утечке инодов из-за отсутствия batch forget. Попробуйте 0.31.4, там добавил поддержку batch forget.
У меня 0.31.6 и на нодах, где производится запись в бакет средних файлов (несколько мегабайт) периодически стреляет OOM:
Nov 1 11:15:34 host kernel: [9739104.856291] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/user.slice/user-1000.slice/session-113021.scope,task=geesefs,pid=1738138,uid=0
Nov 1 11:15:34 host kernel: [9739104.856332] Out of memory: Killed process 1738138 (geesefs) total-vm:1268780kB, anon-rss:452428kB, file-rss:0kB, shmem-rss:0kB, UID:0 pgtables:1228kB oom_score_adj:0
Nov 1 11:15:34 host kernel: [9739104.883773] oom_reaper: reaped process 1738138 (geesefs), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
total-vm:1268780kB - это 1.2 ГБ, это не много. Дефолтный лимит кэша 1 ГБ, по факту получается больше, ибо +метаданные +GC.
У меня довольно слабая виртуалка. В большем количестве памяти нет потребности. Да и запись в FS не сильно интенсивна. Я же могу его уменьшить через memory-limit=500К например?
500K нет, этого не хватит для работы вообще никак, это память, которая используется и для чтения с сервера, и для записи на сервер, читаются с сервера данные кусками по --read-ahead (5 МБ по дефолту), а если читаешь линейно - то переходит к чтению по --read-ahead-large (100 МБ причём 5-ю параллельными запросами). Заливается частями размеров, указанных в --part-sizes.
Причём из этого следует, что если с дефолтными настройками 10+ параллельных процессов будут линейно читать каждый свой файл, то им не хватит памяти под буферы и кто-то получит ENOMEM.
Минимум, который можно попытаться поставить - это, наверное, --memory-limit 100 --read-ahead-large 5120 --read-ahead-parallel 1 --part-sizes 5, но при этом уже частично производительность просядет.
Ой, сорри, я хотел сказать memory-limit=500M.
Да, спасибо, я все понял