Массовый трафик метаданных NFS, наводняющий сервер NFSv4.1 (AWS EFS)

Мы наблюдаем огромный рост запросов метаданных к сетевому диску NFSv4.1 (AWS EFS), который связан с одним или несколькими веб-серверами. Это начало происходить около недели назад в ряде стеков.

Я сделал кучу диагностик;

nfsiostatпоказывает 60-450 операций в секунду на серверах, где это происходит.

nfstrace --mode=live --verbose=2показывает, что одни и те же операции происходят неоднократно с 2-3 дескрипторами файлов;

         CALL  [ operations: 4 tag: void minor version: 1
       [ SEQUENCE(53) [ sessionid: 0xeab1201a93b669600000000000000001 sequenceid: 0xfc12c slotid: 2 cache this: 0 ]
       [ PUTFH(22) [ object: 839c9918169aed49bd6f96adab5438bc47b1460162fe4a739cd8c98405868b2b5de303ed1f4ecfa82c26f5ca1db4cce8e63aad38fe72a397bdae51d8a7e93eb118ad8c736b30323165273b9c805db85936cf3be626b6ba4165ecf9755a54fdd174a535e217ffee4fa0166feea6e86becf9fa16280fd877b3545e07fe03aede08 ]
       [ ACCESS(3) [ READ LOOKUP MODIFY EXTEND DELETE  ]
       [ GETATTR(9) [ mask: 0x18300000 CHANGE SIZE TIME_METADATA TIME_MODIFY ]  ]
   REPLY [  operations: 4 status: OK tag: void
       [ SEQUENCE(53) [ status: OK session: 0xeab1201a93b669600000000000000001 sequenceid: 0xfc12c slotid: 2 highest slotid: 63 target highest slotid: 63 status flags: 0 ]
       [ PUTFH(22) [ status: OK ]
       [ ACCESS(3) [ status: OK supported: READ LOOKUP MODIFY EXTEND DELETE  access: READ LOOKUP MODIFY EXTEND DELETE  ]
       [ GETATTR(9) [ status: OK mask: 0x18300000 CHANGE SIZE TIME_METADATA TIME_MODIFY ]  ]

lsof -Nничего не показывает, используя файлы с диска NFS.

iotopне раскрывает ничего очевидного

tcpdump -s 0 -w /tmp/nfs.pcap port 2049а затем загрузка этого в Wireshark для декодирования дескриптора файла ни к чему не привела, поскольку декодирование, похоже, выдает бессмысленные значения (несуществующие индексные дескрипторы и т. д.).

Хотя мне удалось смягчить проблему, изменив режим пропускной способности на эластичный в AWS, эта проблема вызывает проблемы с производительностью и сбои в производстве.

NB: Эта проблема очень похожа на эту: веб-сервер nginx заполняет NFS запросами метаданных.

ОБНОВЛЕНИЕ 1

Я обнаружил, что могу определить, какие файлы были повреждены, просматривая пакеты ответов и открывая дамп TCP с помощью tshark (tshark -r /tmp/nfs.pcap -V) было достаточно, чтобы получить временные метки изменения файла;

              Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x00000018 (Change, Size)
                reqd_attr: Change (3)
                    changeid: 1626
                reqd_attr: Size (4)
                    size: 38912
            Attr mask[1]: 0x00300000 (Time_Metadata, Time_Modify)
                reco_attr: Time_Metadata (52)
                    seconds: 1678928064
                    nseconds: 8000000
                reco_attr: Time_Modify (53)
                    seconds: 1678928064
                    nseconds: 8000000

тогда я мог бы использоватьfindчтобы найти файлы, которые были изменены, напримерfind /path/to/mount/point/ -newermt "15 Mar 2023" ! -newermt "17 Mar 2023" -ls | grep 13:54. Это выявило то, что он снова, по-видимому, застрял на определенных файлах. Хотя это на самом деле не помогло мне отследить источник проблемы, но стало более ясно, что все, что он делал, — это неоднократные попытки обновить метаданные в 2-5, казалось бы, случайных файлах, которые загружаются на главной странице веб-сайта. обсуждаемый.

Еще немного почитав, я обнаружил, что в Linux Kernel 4.0 есть опция под названием «доступная». Этот параметр сохраняет больше информации в ОЗУ и уменьшает количество операций записи метаданных. Я провел небольшой эксперимент с этим и применил этот параметр монтирования к/etc/fstabфайл на одном сервере в кластере, а затем применил «плацебо» к другому. Наблюдения приведены ниже;

• Сервер 1:
  • проверенные параметры монтирования - с использованием relatime
  • проверил статистику nfs - 460,982 операций/с
  • обновлены параметры монтирования
  • отмонтировал и смонтировал диск NFS
  • проверил статистику nfs - 1.400 операций/с
  • перезагрузился
  • проверил статистику nfs - 1,316 операций/с
• Сервер 2:
  • проверенные параметры монтирования - с использованием relatime
  • проверил статистику nfs - 390,998 операций/с
  • не обновлены параметры монтирования
  • отмонтировал и смонтировал диск NFS
  • проверил статистику nfs - 1.750 операций/с
  • перезагрузился
  • проверил статистику nfs - 531,932 операций/с

Вывод из этого такой;

• Отключение и повторное монтирование диска временно устраняет проблему.
• lazytimeвариант, кажется, частично смягчает проблему
• Проблема, похоже, связана с загрузкой, это связано с другими наблюдениями.

ОБНОВЛЕНИЕ 2

Здесь я нашел гораздо более эффективный способ устранения неполадок;

      # enable debugging
rpcdebug -m nfs -s all

# watch debug output
tail -f /var/log/syslog

# disable debugging
rpcdebug -m nfs -c all

На самом деле это дает некоторый полезный результат;

      Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213426] NFS: nfs_update_inode(0:55/1440391441734181492 fh_crc=0xc29dd48a ct=2 info=0x26040)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213428] NFS: permission(0:55/1440391441734181492), mask=0x1, res=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213430] NFS: nfs_lookup_revalidate_done(/Components) is valid
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213432] --> nfs41_call_sync_prepare data->seq_server 000000008a198bb4
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213433] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213433] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213436] encode_sequence: sessionid=1354075206:678036945:0:16777216 seqid=238661 slotid=0 max_slotid=0 cache_this=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213842] decode_attr_type: type=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213843] decode_attr_change: change attribute=2153
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213844] decode_attr_size: file size=71680
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213845] decode_attr_fsid: fsid=(0x0/0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213845] decode_attr_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213846] decode_attr_fs_locations: fs_locations done, error = 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213846] decode_attr_mode: file mode=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213847] decode_attr_nlink: nlink=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213848] decode_attr_rdev: rdev=(0x0:0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213848] decode_attr_space_used: space used=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213849] decode_attr_time_access: atime=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213849] decode_attr_time_metadata: ctime=1677729393
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213850] decode_attr_time_modify: mtime=1677729393
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213851] decode_attr_mounted_on_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213851] decode_getfattr_attrs: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213852] decode_getfattr_generic: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213853] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213854] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213855] nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213855] nfs41_sequence_process: Error 0 free the slot
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213856] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213860] NFS: nfs_update_inode(0:55/10743289300410127521 fh_crc=0xb5c7d895 ct=1 info=0x26040)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213862] NFS: permission(0:55/10743289300410127521), mask=0x1, res=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213864] NFS: nfs_lookup_revalidate_done(Components/Image.png) is valid
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213867] NFS: dentry_delete(Components/Image.png, 48084c)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214000] NFS: permission(0:55/1440391441734181492), mask=0x81, res=-10
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214003] --> nfs41_call_sync_prepare data->seq_server 000000008a198bb4
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214004] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214005] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214009] encode_sequence: sessionid=1354075206:678036945:0:16777216 seqid=238662 slotid=0 max_slotid=0 cache_this=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214472] decode_attr_type: type=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214473] decode_attr_change: change attribute=1626
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214473] decode_attr_size: file size=38912
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214474] decode_attr_fsid: fsid=(0x0/0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214475] decode_attr_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214475] decode_attr_fs_locations: fs_locations done, error = 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214476] decode_attr_mode: file mode=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214476] decode_attr_nlink: nlink=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214477] decode_attr_rdev: rdev=(0x0:0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214477] decode_attr_space_used: space used=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214478] decode_attr_time_access: atime=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214479] decode_attr_time_metadata: ctime=1678928064
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214479] decode_attr_time_modify: mtime=1678928064
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214480] decode_attr_mounted_on_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214480] decode_getfattr_attrs: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214481] decode_getfattr_generic: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214483] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214483] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214484] nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214485] nfs41_sequence_process: Error 0 free the slot