All CPU stuck, server hang with IO to reiser4 partition

[daemonserj]

Всем привет. Ребята, надеюсь на вашу помощь.

Есть сервер dl360g8 с Debian Buster с партицией 1Tb reiser4. На этой партиции расположена БД postgresql+timescaledb, идёт постоянный INSERT Сегодня сервер завис намертво, на консоли были записи что-то вроде postgres такой-то stuck on CPU > 120 sec, жаль не заскринил.

Ядро 5.13.12 пропатчено по инструкции[https://reiser4.wiki.kernel.org/index.php/Reiser4_patchsets] Партиция создана как mkfs.reiser4 -L STORAGE -o create=ccreg40,compress=zstd1 /dev/sda3

Монтируется как mount -t reiser4 -o txmod=journal,noatime,onerror=remount-ro,dont_load_bitmap /dev/sda3 /storage

Всего в сжатом виде содержит где-то 100Гб, в несжатом ~300Гб. В логе kern.log есть такие записи:

Feb  2 15:34:46 cdrdb kernel: [4915804.032542] reiser4[postgres(35612)]: commit_current_atom (fs/reiser4/txnmgr.c:1052)[nikita-3176]:
Feb  2 15:34:46 cdrdb kernel: [4915804.032542] WARNING: Flushing like mad: 16384
Feb  2 20:02:55 cdrdb kernel: [4931892.721424] reiser4[postgres(8960)]: commit_current_atom (fs/reiser4/txnmgr.c:1052)[nikita-3176]:
Feb  2 20:02:55 cdrdb kernel: [4931892.721424] WARNING: Flushing like mad: 16384

Запустил пока fsck в дефолтном режиме без фикса. БД не в проде, скорее для тех нужд, цель моего тикета по возможности спасти данные и/или зафиксить какие-то баги. Что посоветуете?

[edward6]

Добрый день. Присылайте результаты проверки fsck.

[daemonserj]

Судя по всему, обошлось легким испугом. Настрою kdump если повторится.

fsck.reiser4 started at Thu Feb  3 19:47:07 2022

Reiser4 fs was detected on /dev/sda3.                                                                                                                                                                                                      
Master super block (16): 
magic:          ReIsEr4 
blksize:        4096 
format:         0x0 (format40) 
uuid:           feee38f7-2579-47d6-9c32-0f5194d61e4b 
label:          STORAGE 

Format super block (17): 
plugin:         format40 
description:    Disk-format plugin. 
version:        2 
magic:          ReIsEr40FoRmAt 
mkfs id:        0x1336d0f 
flushes:        0 
blocks:         277145088 
free blocks:    250378607 
root block:     14656180 
tail policy:    0x2 (smart) 
next oid:       0x17767 
file count:     4866 
tree height:    6 
key policy:     LARGE 

CHECKING THE STORAGE TREE                                                                                                                                                                                                                  
        Read nodes 26751355                                                                                                                                                                                                                
        Nodes left in the tree 26751355 
                Leaves of them 26419976, Twigs of them 325752 
        Time interval: Thu Feb  3 19:47:33 2022 - Thu Feb  3 23:51:24 2022 
CHECKING EXTENT REGIONS.                                                                                                                                                                                                                   
        Read twigs 325752                                                                                                                                                                                                                  
        Time interval: Thu Feb  3 23:51:24 2022 - Thu Feb  3 23:52:28 2022 
CHECKING THE SEMANTIC TREE                                                                                                                                                                                                                 
        Found 4865 objects (some could be encountered more then once).                                                                                                                                                                     
        Time interval: Thu Feb  3 23:52:28 2022 - Fri Feb  4 00:23:01 2022 
***** fsck.reiser4 finished at Fri Feb  4 00:23:01 2022
Closing fs...done

FS is consistent.

[edward6]

Скорее всего, повторится. Поскольку пока некому этой проблемой заниматься, я всё же бы порекомендовал сменить ФС.

[daemonserj]

Очень жаль,конечно. В любом случае респект за проделанную работу!

[daemonserj]

Переоткрою, вдруг пригодится. Появились снова зависающие таски. kern.log.zip

[edward6]

Спасибо за логи. Как часто это случается?

[daemonserj]

По логу получается, что чуть-ли не каждый день, 8-го и 9-го. 10-го не было ничего. Запись идет постоянно, с дневными пиками активности. Хранилка скромная: raid 1+1 из 15k HDD. По ioping выдает около 10k iops на 8кб.

Закинул на gdrive дебаг+релиз ядро: https://drive.google.com/file/d/1PCFiMJK8xtTOIkiVAlm6PpGyCZp0S1d2/view?usp=sharing

[edward6]

Судя по логам, несколько зависимых процессов ждут завершения записи атома (транзакции) на диск. Эта запись видимо прогрессирует, но по какой-то причине очень медленно. По какой именно, по этим логам понять невозможно.

К сожалению, без стабильного воспроизведения провести диагностику и понять причину медленного прогресса достаточно сложно. Я постараюсь создать начальные отладочные средства для этой проблемы. Как правило, это накопление и печать некоторой статистики по команде с консоли. С первого (и порой с двадцатого раза) обычно ничего не видно, так что придётся этот инструментарий многократно модифицировать прежде чем мы поймём в чём тут дело.

[daemonserj]

Скорее всего процессы postgres, в которых идет bulk INSERT, ждут процесс postgres checkpointer, который постоянно пишет контрольную точку. Скорости хранилки не хватает чтобы он быстро отрабатывал. Так то это не кейс ФС, если бы не предыдущее зависание сервера. Зависаний процессов с 9-го больше нет, но "Flushing like mad" продолжается.

[Kokokokoka]

возможно, у меня похожая проблема. Разворачивал генту с патчсетом для 5.16 на ядре 5.16.20.монтируется с noatime, discard. всё уже +- работало (хотя, после обновления портажа, порой висло, но тогда не обратил внимание, возможно, это ошибка как тут, если нет, то создам отдельный репорт) "чинилось" патчем: https://files.catbox.moe/5z4srr.jpg после того, как не запатчил вызов, система стала виснуть с завидной регулярностью, даже не успел сохранить на сторонний раздел лог ядра. Если потребуется, могу пересобрать с дебагом или другими опциями. https://files.catbox.moe/hda2tc.jpg https://files.catbox.moe/902esm.jpg https://files.catbox.moe/m7kcxp.jpg последнее, что видел перед этими жёсткими зависаниями: "nikita-3176"

фактически, система стала виснуть после любой активности портежа. сделал фсчк:

FSCK: cde40_repair.c: 754: cde40_check_struct: Node (2099280), item (0), [2d19ec:0(NAME):0:0:0]: wrong order of units [2, 3]. The whole item is to be removed.
FSCK: node.c: 95: repair_node_items_check: Node (2099280), item (0), [2d19ec:0(NAME):0:0:0]: broken item found.
FSCK: node.c: 108: repair_node_items_check: Node (2099280), items (2) and (3): Wrong order of keys.
FSCK: filter.c: 409: repair_filter_update_traverse: Node (2099280): the node is broken. Pointed from the node (2099142), item (60), unit (0). The whole subtree is skipped.
FSCK: cde40_repair.c: 754: cde40_check_struct: Node (2099307), item (0), [2d19ed:0(NAME):0:0:0]: wrong order of units [2, 3]. The whole item is to be removed.
FSCK: node.c: 95: repair_node_items_check: Node (2099307), item (0), [2d19ed:0(NAME):0:0:0]: broken item found.
FSCK: filter.c: 409: repair_filter_update_traverse: Node (2099307): the node is broken. Pointed from the node (2099331), item (0), unit (0). The whole subtree is skipped.
FSCK: cde40_repair.c: 754: cde40_check_struct: Node (2099319), item (0), [2d19ff:0(NAME):0:0:0]: wrong order of units [2, 3]. The whole item is to be removed.
FSCK: node.c: 95: repair_node_items_check: Node (2099319), item (0), [2d19ff:0(NAME):0:0:0]: broken item found.
FSCK: node.c: 108: repair_node_items_check: Node (2099319), items (1) and (2): Wrong order of keys.
FSCK: filter.c: 409: repair_filter_update_traverse: Node (2099319): the node is broken. Pointed from the node (2099331), item (3), unit (0). The whole subtree is skipped.
FSCK: node.c: 108: repair_node_items_check: Node (2099323), items (1) and (2): Wrong order of keys.
FSCK: filter.c: 409: repair_filter_update_traverse: Node (2099323): the node is broken. Pointed from the node (2099331), item (7), unit (0). The whole subtree is skipped.
FSCK: cde40_repair.c: 754: cde40_ch
eck_struct: Node (2099325), item (0), [2d1a08:0(NAME):0:0:0]: wrong order of units [2, 3]. The whole item is to be removed.
FSCK: node.c: 95: repair_node_items_check: Node (2099325), item (0), [2d1a08:0(NAME):0:0:0]: broken item found.
FSCK: node.c: 108: repair_node_items_check: Node (2099325), items (1) and (2): Wrong order of keys.
FSCK: filter.c: 409: repair_filter_update_traverse: Node (2099325): the node is broken. Pointed from the node (2099331), item (9), unit (0). The whole subtree is skipped.
        Read nodes 45087
        Nodes left in the tree 14878
                Leaves of them 10128, Twigs of them 4674
        Broken of them 30197
                Leaves of them 29738, Twigs of them 456
        Nodes with wrong delimiting keys 12
                Leaves of them 7, Twigs of them 5
        Time interval: Mon Jul 11 22:08:09 2022 - Mon Jul 11 22:08:48 2022
CHECKING EXTENT REGIONS.
        Read twigs 4674
        Time interval: Mon Jul 11 22:08:48 2022 - Mon Jul 11 22:08:48 2022
Warn : Fatal corruptions were found. Semantic pass is skipped.
* fsck.reiser4 finished at Mon Jul 11 22:08:48 2022
Closing fs...done

30209 fatal corruptions were detected in FileSystem. Run with --build-fs option to fix them.

после --build-fs:

Reiser4 fs was detected on /dev/nvme0n1p9.
Master super block (16):
magic:          ReIsEr4
blksize:        4096
volume:         0x1 (asym)
distrib:        0x1 (fsx32m)
format:         0x1 (format41)
description:    Standard layout for logical volumes.
stripe bits:    21
mirror id:      0
replicas:       0
volume uuid:    46feef66-6265-457d-b66f-e7629ebc098b
subvol uuid:    940cd58a-eb10-49d5-8083-45164a66db25
label:          <none>

Format super block (17):
version:        3
magic:          ReIsEr40FoRmAt
mkfs id:        0x9b02f2
flushes:        0
blocks:         9968640
free blocks:    7890400
root block:     552185
tail policy:    0x2 (smart)
next oid:       0x2d1ac8
file count:     374114
tree height:    4
key policy:     LARGE
brick id:       0
data capacity:  7008959
system blocks:  342
volinfo loc:    0
nr segments:    1024
nr mslots:      1

CHECKING THE STORAGE TREE
        Read nodes 22852
        Nodes left in the tree 22852
                Leaves of them 18102, Twigs of them 4674
        Time interval: Mon Jul 11 22:19:24 2022 - Mon Jul 11 22:19:26 2022
CHECKING EXTENT REGIONS.
        Read twigs 4674
        Time interval: Mon Jul 11 22:19:26 2022 - Mon Jul 11 22:19:26 2022
CHECKING THE SEMANTIC TREE
FSCK: semantic.c: 573: repair_semantic_dir_open: Failed to recognize the plugin for the directory [29:0:2a].
FSCK: semantic.c: 652: repair_semantic_root_prepare: No root directory opened.
        Time interval: Mon Jul 11 22:19:26 2022 - Mon Jul 11 22:19:26 2022
FSCK: repair.c: 545: repair_sem_fini: On-disk used block bitmap and really used block bitmap differ.
* fsck.reiser4 finished at Mon Jul 11 22:19:26 2022
Closing fs...done

2 fatal corruptions were detected in FileSystem. Run with --build-fs option to fix them.

[edward-ibm]

Согласно логам ядра kernel panic происходит в контексте файловой системы FAT. У вас в системе имеются разделы отформатированные такой ФС? Если да - отмонтируйте их и попробуйте воспроизвести проблему.

По поводу фсчк. У вас формат 5.X.Y с расширяемыми томами. Для него fsck ещё не работает. Тут моя вина: я забыл сделать так, чтобы эта утилита не собиралась в пакетах соответствующих релизов.

[Kokokokoka]

да, верно, у меня есть фат раздел с бутом. попробую без него. по глупости выстрелил фс в ногу и теперь уже буду развлекаться только на выходных, воспроизводя систему (благо, часть сохранил). далее буду уже тестировать без бута в фстабе. спасибо!

[edward-ibm]

Вообще, идея убрать fsck из reiser4progs 5.X.Y не сильно поможет - начнут "чинить" утилитами из стабильных версий (4.X.Y). Добавил предупреждения на видных местах: https://reiser4.wiki.kernel.org/index.php/Logical_Volumes_Howto https://reiser4.wiki.kernel.org/index.php/Logical_Volumes_Administration

[Kokokokoka]

после того, как убрал фат раздел из фстаба, стало сильно лучше. сегодня снова поймал nikita-3176, когда собирал пакет (браузер) не в тмпфс(не подрубил), а на диске. если это будет воспроизводимо, могут ли помочь репорты с дебагом или лучше так: каким образом можно помочь в распутывании данного бага?

[edward-ibm]

Тут такое дело: это предупреждение стоит для того, чтобы распознать повреждённый раздел. К сожалению, точная диагностика здесь невозможна (т. е. получение верхней оценки для числа неудачных попыток менеджера транзакций запустить flush-процедуру при здоровом разделе), поэтому решили ограничиться приблизительной, суть которой в следующем. Спорадические сообщения (т.е. с момента последнего сообщения прошло значительное время и ощутимых проблем нет) нужно игнорировать. Если же наблюдается их беспрерывный флуд (обычно сопровождаемый зависаниями системы), то это указывает на повреждённый раздел.

[Metztli]

https://github.com/edward6/reiser4/issues/10#issuecomment-1039823859

On Reiser4 Software Framework Release Number (SFRN) 4.0.2 Yandex translation: На платформе программного обеспечения Reiser4 Номер выпуска (SFRN) 4.0.2

By empirical observation and/or experience, MySQL/MariaDB -- and perhaps by extension, PostgreSQL, may be affected by the file system in /tmp . If /tmp is not Reiser4, do a test by formatting a partition in reiser4 (no compression) and mounting the partition at mount point /tmp . Analyze subsequently your database function/performance for improvement and/or lack of thereof.

Yandex translation:

Согласно эмпирическим наблюдениям и/или опыту, файловая система в /tmp может влиять на MySQL/MariaDB и, возможно, в качестве расширения, PostgreSQL. Если /tmp не является Reiser4, выполните тест, отформатировав раздел в reiser4 (без сжатия) и смонтировав раздел в точке монтирования /tmp . Впоследствии проанализируйте функцию / производительность вашей базы данных на предмет улучшения и /или его отсутствия.

Running MariaDB and PostgreSQL here:

Yandex translation: Запуск MariaDB и PostgreSQL здесь: