В этой статье я поделюсь с вами долгой историей, которая начинается с op.read() opendal, а заканчивается неожиданным поворотом. Это путешествие оказалось для меня достаточно поучительным, надеюсь, и для вас оно будет таким же. Я постараюсь максимально точно воссоздать свой опыт и дополню его выводами, которые сделал в процессе.

Все фрагменты кода и скрипты выложены в Xuanwo/when-i-find-rust-is-slow

TL;DR

Если вам срочно нужно знать ответ, сразу перейдите к разделу «Вывод».

Привязка OpenDAL к Python медленнее, чем Python?

OpenDAL — это слой доступа к данным, позволяющий удобно и эффективно получать данные из различных сервисов хранения единым образом. Мы предоставляем для OpenDAL привязку к Python при помощи pyo3.

Однажды @beldathas написал мне в discord о том, что привязка OpenDAL к python медленее, чем python:

import pathlib
import timeit

import opendal

root = pathlib.Path(__file__).parent
op = opendal.Operator("fs", root=str(root))
filename = "lorem_ipsum_150mb.txt"

def read_file_with_opendal() -> bytes:
    with op.open(filename, "rb") as fp:
        result = fp.read()
    return result

def read_file_with_normal() -> bytes:
    with open(root / filename, "rb") as fp:
        result = fp.read()
    return result

if __name__ == "__main__":
    print("normal: ", timeit.timeit(read_file_with_normal, number=100))
    print("opendal: ", timeit.timeit(read_file_with_opendal, number=100))

Результаты демонстрируют следующее:

(venv) $ python benchmark.py
normal:  4.470868484000675
opendal:  8.993250704006641

Так-так-так. Меня неприятно поразили эти результаты. У меня быстро возникло несколько гипотез:

• У Python есть внутренний кэш, способный многократно использовать одну и ту же память?

• У Python есть какой-то трюк, ускоряющий чтение файлов?

• Лишняя трата ресурсов возникает из-за PyO3?

Я отрефакторил код:

python-fs-read:

with open("/tmp/file", "rb") as fp:
    result = fp.read()
assert len(result) == 64 * 1024 * 1024

python-opendal-read:

import opendal

op = opendal.Operator("fs", root=str("/tmp"))

result = op.read("file")
assert len(result) == 64 * 1024 * 1024

Результаты показывают, что python намного быстрее opendal:

Benchmark 1: python-fs-read/test.py
  Time (mean ± σ):      15.9 ms ±   0.7 ms    [User: 5.6 ms, System: 10.1 ms]
  Range (min … max):    14.9 ms …  21.6 ms    180 runs
  
Benchmark 2: python-opendal-read/test.py
  Time (mean ± σ):      32.9 ms ±   1.3 ms    [User: 6.1 ms, System: 26.6 ms]
  Range (min … max):    31.4 ms …  42.6 ms    85 runs
  
Summary
  python-fs-read/test.py ran
    2.07 ± 0.12 times faster than python-opendal-read/test.py

Привязка OpenDAL к Python кажется более медленной, чем сам Python, и это печальная новость. Давайте разберёмся, в чём причина.

Сервис OpenDAL Fs медленнее, чем Python?

В этом пазле задействовано множество элементов, в том числе rust, opendal, python и pyo3. Попробуем выявить первопричину.

Я реализовал ту же логику через сервис opendal fs на rust:

rust-opendal-fs-read:

use std::io::Read;
use opendal::services::Fs;
use opendal::Operator;

fn main() {
    let mut cfg = Fs::default();
    cfg.root("/tmp");
    let op = Operator::new(cfg).unwrap().finish().blocking();

    let mut bs = vec![0; 64 * 1024 * 1024];

    let mut f = op.reader("file").unwrap();
    let mut ts = 0;
    loop {
        let buf = &mut bs[ts..];
        let n = f.read(buf).unwrap();
        let n = n as usize;
        if n == 0 {
            break
        }
        ts += n;
    }

    assert_eq!(ts, 64 * 1024 * 1024);
}

Однако результат показывает, что opendal медленнее, чем python, даже если opendal реализован на rust:

Benchmark 1: rust-opendal-fs-read/target/release/test
  Time (mean ± σ):      23.8 ms ±   2.0 ms    [User: 0.4 ms, System: 23.4 ms]
  Range (min … max):    21.8 ms …  34.6 ms    121 runs
 
Benchmark 2: python-fs-read/test.py
  Time (mean ± σ):      15.6 ms ±   0.8 ms    [User: 5.5 ms, System: 10.0 ms]
  Range (min … max):    14.4 ms …  20.8 ms    166 runs
 
Summary
  python-fs-read/test.py ran
    1.52 ± 0.15 times faster than rust-opendal-fs-read/target/release/test

Хотя показателиrust-opendal-fs-read немного лучше, чем у python-opendal-read, что демонстрирует потенциал совершенствования привязки и pyo3, всё это не первопричины проблемы. Нам нужно двигаться глубже.

Сервис opendal fs медленнее, чем python.

std fs Rust медленнее, чем Python?

OpenDAL реализует сервис fs через std::fs. Возможно, дополнительные затраты вызваны самим OpenDAL?

Мы реализуем ту же логику через std::fs rust:

rust-std-fs-read:

use std::io::Read;
use std::fs::OpenOptions;

fn main() {
    let mut bs = vec![0; 64 * 1024 * 1024];
    let mut f = OpenOptions::new().read(true).open("/tmp/file").unwrap();
    let mut ts = 0;
    loop {
        let buf = &mut bs[ts..];
        let n = f.read(buf).unwrap();
        let n = n as usize;
        if n == 0 {
            break
        }
        ts += n;
    }

    assert_eq!(ts, 64 * 1024 * 1024);
}

Но...

Benchmark 1: rust-std-fs-read/target/release/test
  Time (mean ± σ):      23.1 ms ±   2.5 ms    [User: 0.3 ms, System: 22.8 ms]
  Range (min … max):    21.0 ms …  37.6 ms    124 runs
 
Benchmark 2: python-fs-read/test.py
  Time (mean ± σ):      15.2 ms ±   1.1 ms    [User: 5.4 ms, System: 9.7 ms]
  Range (min … max):    14.3 ms …  21.4 ms    178 runs

Summary
  python-fs-read/test.py ran
    1.52 ± 0.20 times faster than rust-std-fs-read/target/release/test

Ого, std fs Rust медленнее, чем Python? Как такое возможно?

std fs Rust медленнее, чем Python? Серьёзно?!

Не могу поверить этим результатам: std fs rust неожиданно медленнее, чем Python.

Я разобрался, как использовать strace для анализа системных вызовов. strace — это трассировщик системных вызовов для Linux, позволяющий выполнять мониторинг системных вызовов и понимать их процессы.

strace исследует все системные вызовы, диспетчеризируемые программой. Нас должны интересовать аспекты, связанные с/tmp/file. Каждая строка вывода strace начинается с имени системного вызова, за которым идут входные аргументы и вывод.

Например:

openat(AT_FDCWD, "/tmp/file", O_RDONLY|O_CLOEXEC) = 3

Это значит, что мы вызываем системный вызов openat , указав аргументы AT_FDCWD, "/tmp/file" и O_RDONLY|O_CLOEXEC. При этом возвращается вывод 3 — дескриптор файла, на который выполняется ссылка в последующем системном вызове.

Отлично, мы в совершенстве освоили strace. Давайте воспользуемся им!

Результаты strace для rust-std-fs-read:

> strace ./rust-std-fs-read/target/release/test
...
mmap(NULL, 67112960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f290dd40000
openat(AT_FDCWD, "/tmp/file", O_RDONLY|O_CLOEXEC) = 3
read(3, "\tP\201A\225\366>\260\270R\365\313\220{E\372\274\6\35\"\353\204\220s\2|7C\205\265\6\263"..., 67108864) = 67108864
read(3, "", 0)                          = 0
close(3)                                = 0
munmap(0x7f290dd40000, 67112960)        = 0
...

Результаты strace для python-fs-read:

> strace ./python-fs-read/test.py
...
openat(AT_FDCWD, "/tmp/file", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=67108864, ...}, AT_EMPTY_PATH) = 0
ioctl(3, TCGETS, 0x7ffe9f844ac0)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                   = 0
lseek(3, 0, SEEK_CUR)                   = 0
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=67108864, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 67112960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13277ff000
read(3, "\tP\201A\225\366>\260\270R\365\313\220{E\372\274\6\35\"\353\204\220s\2|7C\205\265\6\263"..., 67108865) = 67108864
read(3, "", 1)                          = 0
close(3)                                = 0
rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK, sa_restorer=0x7f132be5c710}, {sa_handler=0x7f132c17ac36, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK, sa_restorer=0x7f132be5c710}, 8) = 0
munmap(0x7f13277ff000, 67112960)        = 0
...

Из анализа strace становится понятно, что в python-fs-read имеется больше системных вызовов, чем в rust-std-fs-read, и оба они используют mmap. Так почему же python быстрее, чем rust?

Зачем мы используем здесь mmap?

Изначально я думал, что mmap нужна только для отображения файлов в память, что позволяет получать доступ к файлам через память. Однако mmap применяется и иным образом. Часто её используют для распределения больших областей памяти для приложений.

Это можно увидеть в результатах strace:

mmap(NULL, 67112960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13277ff000

Этот системный вызов означает следующее:

• NULL: первый аргумент — это начальный адрес области памяти для отображения. NULL позволяет операционной системе самой выбрать подходящий адрес.

• 67112960: размер области памяти для отображения. Здесь мы распределяем 64 МиБ + 4 КиБ памяти, дополнительная страница используется для хранения метаданных этой области памяти.

• PROT_READ|PROT_WRITE: область памяти доступна для чтения и записи.

• MAP_PRIVATE|MAP_ANONYMOUS:

  • MAP_PRIVATE означает, что изменения в этой области памяти не будут видимы для других процессов, выполняющих отображение в ту же область, и что они не переносятся в соответствующий файл (если он есть).

  • MAP_ANONYMOUS означает, что мы распределяем анонимную память, не связанную с файлом.

• -1: дескриптор файла, отображение которого мы выполняем. -1 означает, что мы не отображаем файл.

• 0: смещение в файле, с которого нужно выполнять отображение. Здесь использован 0, потому что мы не отображаем файл.

Но я не использую mmap в своём коде.

Системный вызовmmap диспетчеризируется библиотекойglibc. Мы используем malloc для запроса памяти у системы, а в ответ glibc задействует системные вызовы brk и mmap для распределения памяти согласно запрошенному нами размеру. Если запрошенный размер достаточно велик, то glibc применяет mmap, которая позволяет устранять проблемы фрагментации памяти.

По умолчанию все программы на Rust, компилируемые под целевую платформу x86_64-unknown-linux-gnu, используют malloc, предоставляемую glibc.

Использует ли Python тот же распределитель памяти, что и Rust?

По умолчанию Python использует pymalloc — распределитель памяти, оптимизированный под небольшие распределения. Python имеет три диапазона памяти, каждый из который отражает разные стратегии распределения и оптимизирован под разные цели.

pymalloc имеет следующее поведение:

У Python есть распределительpymalloc , оптимизированный под мелкие объекты (меньше или равные 512 байтам) с коротким временем жизни. Он использует отображения памяти, называемые «аренами» (arena) c фиксированным размером 256 КиБ (на 32-битных платформах) или 1 МиБ на 64-битных платформах. Если распределения больше 512 байтов, он возвращается к использованию PyMem_RawMalloc() и PyMem_RawRealloc().

Rust медленнее, чем Python со стандартным распределителем памяти?

Я подозреваю, что эта проблема вызвана mmap. Что, если мы перейдём на jemalloc?

rust-std-fs-read-with-jemalloc:

use std::io::Read;
use std::fs::OpenOptions;

#[global_allocator]
static GLOBAL: jemallocator::Jemalloc = jemallocator::Jemalloc;

fn main() {
    let mut bs = vec![0; 64 * 1024 * 1024];
    let mut f = OpenOptions::new().read(true).open("/tmp/file").unwrap();
    let mut ts = 0;
    loop {
        let buf = &mut bs[ts..];
        let n = f.read(buf).unwrap();
        let n = n as usize;
        if n == 0 {
            break
        }
        ts += n;
    }

    assert_eq!(ts, 64 * 1024 * 1024);
}

Ого-о-о!

Benchmark 1: rust-std-fs-read-with-jemalloc/target/release/test
  Time (mean ± σ):       9.7 ms ±   0.6 ms    [User: 0.3 ms, System: 9.4 ms]
  Range (min … max):     9.0 ms …  12.4 ms    259 runs
 
Benchmark 2: python-fs-read/test.py
  Time (mean ± σ):      15.8 ms ±   0.9 ms    [User: 5.9 ms, System: 9.8 ms]
  Range (min … max):    15.0 ms …  21.8 ms    169 runs

Summary
  rust-std-fs-read-with-jemalloc/target/release/test ran
    1.64 ± 0.14 times faster than python-fs-read/test.py

Что?! Я понимаю, что jemalloc — качественный распределитель памяти, но как он может быть настолько успешным? Это совершенно невероятно.

Rust медленнее, чем Python только на моей машине!

Когда к обсуждению присоединились мои друзья, выяснилось, что Rust работает медленнее, чем Python только на моей машине.

Мой CPU:

> lscpu
Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         48 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  32
  On-line CPU(s) list:   0-31
Vendor ID:               AuthenticAMD
  Model name:            AMD Ryzen 9 5950X 16-Core Processor
    CPU family:          25
    Model:               33
    Thread(s) per core:  2
    Core(s) per socket:  16
    Socket(s):           1
    Stepping:            0
    Frequency boost:     enabled
    CPU(s) scaling MHz:  53%
    CPU max MHz:         5083.3979
    CPU min MHz:         2200.0000
    BogoMIPS:            6787.49
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm con
                         stant_tsc rep_good nopl nonstop_tsc cpuid extd_apicid aperfmperf rapl pni pclmulqdq monitor ssse3 fma cx16 sse4_1 sse4_2 movbe popcnt aes xsave avx f
                         16c rdrand lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt tce topoext perfctr_core perfctr_nb bpex
                         t perfctr_llc mwaitx cpb cat_l3 cdp_l3 hw_pstate ssbd mba ibrs ibpb stibp vmmcall fsgsbase bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a rdseed adx smap
                          clflushopt clwb sha_ni xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local user_shstk clzero irperf xsaveerptr rdpru wb
                         noinvd arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold avic v_vmsave_vmload vgif v_spec_ctrl
                         umip pku ospke vaes vpclmulqdq rdpid overflow_recov succor smca fsrm debug_swap
Virtualization features:
  Virtualization:        AMD-V
Caches (sum of all):
  L1d:                   512 KiB (16 instances)
  L1i:                   512 KiB (16 instances)
  L2:                    8 MiB (16 instances)
  L3:                    64 MiB (2 instances)
NUMA:
  NUMA node(s):          1
  NUMA node0 CPU(s):     0-31
Vulnerabilities:
  Gather data sampling:  Not affected
  Itlb multihit:         Not affected
  L1tf:                  Not affected
  Mds:                   Not affected
  Meltdown:              Not affected
  Mmio stale data:       Not affected
  Retbleed:              Not affected
  Spec rstack overflow:  Vulnerable
  Spec store bypass:     Vulnerable
  Spectre v1:            Vulnerable: __user pointer sanitization and usercopy barriers only; no swapgs barriers
  Spectre v2:            Vulnerable, IBPB: disabled, STIBP: disabled, PBRSB-eIBRS: Not affected
  Srbds:                 Not affected
  Tsx async abort:       Not affected

Моя память:

> sudo dmidecode --type memory
# dmidecode 3.5
Getting SMBIOS data from sysfs.
SMBIOS 3.3.0 present.

Handle 0x0014, DMI type 16, 23 bytes
Physical Memory Array
        Location: System Board Or Motherboard
        Use: System Memory
        Error Correction Type: None
        Maximum Capacity: 64 GB
        Error Information Handle: 0x0013
        Number Of Devices: 4

Handle 0x001C, DMI type 17, 92 bytes
Memory Device
        Array Handle: 0x0014
        Error Information Handle: 0x001B
        Total Width: 64 bits
        Data Width: 64 bits
        Size: 16 GB
        Form Factor: DIMM
        Set: None
        Locator: DIMM 0
        Bank Locator: P0 CHANNEL A
        Type: DDR4
        Type Detail: Synchronous Unbuffered (Unregistered)
        Speed: 3200 MT/s
        Manufacturer: Unknown
        Serial Number: 04904740
        Asset Tag: Not Specified
        Part Number: LMKUFG68AHFHD-32A
        Rank: 2
        Configured Memory Speed: 3200 MT/s
        Minimum Voltage: 1.2 V
        Maximum Voltage: 1.2 V
        Configured Voltage: 1.2 V
        Memory Technology: DRAM
        Memory Operating Mode Capability: Volatile memory
        Firmware Version: Unknown
        Module Manufacturer ID: Bank 9, Hex 0xC8
        Module Product ID: Unknown
        Memory Subsystem Controller Manufacturer ID: Unknown
        Memory Subsystem Controller Product ID: Unknown
        Non-Volatile Size: None
        Volatile Size: 16 GB
        Cache Size: None
        Logical Size: None

Я попробовал следующие решения:

Включение мер защиты

В CPU есть множество уязвимостей, способных раскрывать нападающим приватные данные; самая известная из них — это Spectre. Для ядра Linux было разработано множество мер защиты для борьбы с этими уязвимостями, и по умолчанию они включены. Однако эти меры могут накладывать на систему дополнительную нагрузку. Поэтому ядро Linux представляет желающим отключить их пользователям флаг mitigations.

Раньше я отключал все mitigations следующим образом:

title Arch Linux
linux /vmlinuz-linux-zen
initrd /amd-ucode.img
initrd /initramfs-linux-zen.img
options root="PARTUUID=206e7750-2b89-419d-978e-db0068c79c52" rw mitigations=off

Их включение никак не изменило результат.

Настройка Transparent Hugepage

Transparent Hugepage может существенно влиять на производительность. Большинство современных сборок включает это по умолчанию.

> cat /sys/kernel/mm/transparent_hugepage/enabled
[always] madvise never

Переключение на madvise или never влияет на абсолютный результат, но относительное соотношение остаётся неизменным.

Настройка CPU Core Affinity

@Manjusaka предположил, что это связано с CPU Core Spacing.

Я попробовал воспользоваться core_affinity , чтобы привязать процесс к конкретному CPU, но результат оказался таким же.

Измерение задержек системных вызовов при помощи eBPF

@Manjusaka написал для меня программу eBPF, измеряющую задержки системных вызовов чтения. Из её показателей следует, что Rust медленнее, чем Python и на уровне системных вызовов.

Об этой программе eBPF тоже есть длинная история, которую @Manjusaka должен рассказать в отдельном посте!

# python fs read
Process 57555 read file 8134049 ns
Process 57555 read file 942 ns

# rust std fs read
Process 57634 read file 24636975 ns
Process 57634 read file 1052 ns

Наблюдение: на моём компьютере Rust работает медленнее, чем Python и, похоже, это не связано с ПО.

C медленнее, чем Python?

Я зашёл в тупик и не мог понять, в чём разница. Подозреваю, это как-то связано с CPU, но не уверен, в каком аспекте: кэш? частота? core spacing? core affinity? архитектура?

По рекомендациям из Telegram-группы @rust_zh я разработал версию на C:

c-fs-read:

#include <stdio.h>
#include <stdlib.h>

#define FILE_SIZE 64 * 1024 * 1024  // 64 MiB

int main() {
    FILE *file;
    char *buffer;
    size_t result;

    file = fopen("/tmp/file", "rb");
    if (file == NULL) {
        fputs("Error opening file", stderr);
        return 1;
    }

    buffer = (char *)malloc(sizeof(char) * FILE_SIZE);
    if (buffer == NULL) {
        fputs("Memory error", stderr);
        fclose(file);
        return 2;
    }

    result = fread(buffer, 1, FILE_SIZE, file);
    if (result != FILE_SIZE) {
        fputs("Reading error", stderr);
        fclose(file);
        free(buffer);
        return 3;
    }

    fclose(file);
    free(buffer);

    return 0;
}

Однако...

Benchmark 1: c-fs-read/test
  Time (mean ± σ):      23.8 ms ±   0.9 ms    [User: 0.3 ms, System: 23.6 ms]
  Range (min … max):    23.0 ms …  27.1 ms    120 runs

Benchmark 2: python-fs-read/test.py
  Time (mean ± σ):      19.1 ms ±   0.3 ms    [User: 8.6 ms, System: 10.4 ms]
  Range (min … max):    18.6 ms …  20.6 ms    146 runs

Summary
  python-fs-read/test.py ran
    1.25 ± 0.05 times faster than c-fs-read/test

Версия на C тоже медленнее, чем на Python! У Python есть какая-то магия?

C медленнее, чем Python без указанного смещения!

В этот момент к обсуждению присоединился @lilydjwg и заметил разницу в смещении области памяти между C и Python.

Для вывода недекодированных аргументов системных вызовов используется strace -e raw=read,mmap ./program : адрес указателя.

strace дляc-fs-read:

> strace -e raw=read,mmap ./c-fs-read/test
...
mmap(0, 0x4001000, 0x3, 0x22, 0xffffffff, 0) = 0x7f96d1a18000
read(0x3, 0x7f96d1a18010, 0x4000000)    = 0x4000000
close(3)                                = 0

strace для python-fs-read

> strace -e raw=read,mmap ./python-fs-read/test.py
...
mmap(0, 0x4001000, 0x3, 0x22, 0xffffffff, 0) = 0x7f27dcfbe000
read(0x3, 0x7f27dcfbe030, 0x4000001)    = 0x4000000
read(0x3, 0x7f27e0fbe030, 0x1)          = 0
close(3)                                = 0

Вc-fs-read mmap возвращает 0x7f96d1a18000, но системный вызов чтения использует в качестве начального адреса0x7f96d1a18010 , смещение равно 0x10. В python-fs-read mmap возвращает 0x7f27dcfbe000, а системный вызов чтения использует в качестве начального адреса 0x7f27dcfbe030, смещение равно 0x30.

Поэтому @lilydjwg попробовал вызвать read с тем же смещением:

:) ./bench c-fs-read c-fs-read-with-offset python-fs-read
['hyperfine', 'c-fs-read/test', 'c-fs-read-with-offset/test', 'python-fs-read/test.py']
Benchmark 1: c-fs-read/test
  Time (mean ± σ):      23.7 ms ±   0.8 ms    [User: 0.2 ms, System: 23.6 ms]
  Range (min … max):    23.0 ms …  25.5 ms    119 runs

  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet system without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

Benchmark 2: c-fs-read-with-offset/test
  Time (mean ± σ):       8.9 ms ±   0.4 ms    [User: 0.2 ms, System: 8.8 ms]
  Range (min … max):     8.3 ms …  10.6 ms    283 runs

Benchmark 3: python-fs-read/test.py
  Time (mean ± σ):      19.1 ms ±   0.3 ms    [User: 8.6 ms, System: 10.4 ms]
  Range (min … max):    18.6 ms …  20.0 ms    147 runs

Summary
  c-fs-read-with-offset/test ran
    2.15 ± 0.11 times faster than python-fs-read/test.py
    2.68 ± 0.16 times faster than c-fs-read/test

!!!

Применив смещение к buffer в c-fs-read , мы повысили его скорость, обогнав Python! Кроме того, мы подтвердили, что проблема воспроизводится и наAMD Ryzen 9 5900X, и на AMD Ryzen 7 5700X.

Новая информация привела меня к другим отчётам о похожей проблеме: Std::fs::read slow? В этом посте @ambiso обнаружил, что производительность системных вызовов связана со смещением области памяти. Он показал, что CPU замедляется, выполняя запись из первых 0x10 байтов каждой страницы:

offset milliseconds
 ...
 14   130
 15   130
 16    46   <----- 0x10!
 17    48
 ...

AMD Ryzen 9 5900X медленный без указания смещения!

Мы доказали, что эта проблема связана с CPU, однако до сих пор не в курсе потенциальных причин. @Manjusaka пригласил присоединиться к обсуждению разработчика ядра @ryncsn.

Он смог воспроизвести тот же результат, запустив демо c-fs-read и c-fs-read-with-offset на AMD Ryzen 9 5900HX. Также он попробовал профилировать эти две программы при помощи perf.

Без смещения:

perf stat -d -d -d --repeat 20 ./a.out
 Performance counter stats for './a.out' (20 runs):

             30.89 msec task-clock                       #    0.968 CPUs utilized               ( +-  1.35% )
                 0      context-switches                 #    0.000 /sec
                 0      cpu-migrations                   #    0.000 /sec
               598      page-faults                      #   19.362 K/sec                       ( +-  0.05% )
        90,321,344      cycles                           #    2.924 GHz                         ( +-  1.12% )  (40.76%)
           599,640      stalled-cycles-frontend          #    0.66% frontend cycles idle        ( +-  2.19% )  (42.11%)
           398,016      stalled-cycles-backend           #    0.44% backend cycles idle         ( +- 22.41% )  (41.88%)
        43,349,705      instructions                     #    0.48  insn per cycle
                                                  #    0.01  stalled cycles per insn     ( +-  1.32% )  (41.91%)
         7,526,819      branches                         #  243.701 M/sec                       ( +-  5.01% )  (41.22%)
            37,541      branch-misses                    #    0.50% of all branches             ( +-  4.62% )  (41.12%)
       127,845,213      L1-dcache-loads                  #    4.139 G/sec                       ( +-  1.14% )  (39.84%)
         3,172,628      L1-dcache-load-misses            #    2.48% of all L1-dcache accesses   ( +-  1.34% )  (38.46%)
   <not supported>      LLC-loads
   <not supported>      LLC-load-misses
           654,651      L1-icache-loads                  #   21.196 M/sec                       ( +-  1.71% )  (38.72%)
             2,828      L1-icache-load-misses            #    0.43% of all L1-icache accesses   ( +-  2.35% )  (38.67%)
            15,615      dTLB-loads                       #  505.578 K/sec                       ( +-  1.28% )  (38.82%)
            12,825      dTLB-load-misses                 #   82.13% of all dTLB cache accesses  ( +-  1.15% )  (38.88%)
                16      iTLB-loads                       #  518.043 /sec                        ( +- 27.06% )  (38.82%)
             2,202      iTLB-load-misses                 # 13762.50% of all iTLB cache accesses  ( +- 23.62% )  (39.38%)
         1,843,493      L1-dcache-prefetches             #   59.688 M/sec                       ( +-  3.36% )  (39.40%)
   <not supported>      L1-dcache-prefetch-misses

          0.031915 +- 0.000419 seconds time elapsed  ( +-  1.31% )

Со смещением:

perf stat -d -d -d --repeat 20 ./a.out
 Performance counter stats for './a.out' (20 runs):

             15.39 msec task-clock                       #    0.937 CPUs utilized               ( +-  3.24% )
                 1      context-switches                 #   64.972 /sec                        ( +- 17.62% )
                 0      cpu-migrations                   #    0.000 /sec
               598      page-faults                      #   38.854 K/sec                       ( +-  0.06% )
        41,239,117      cycles                           #    2.679 GHz                         ( +-  1.95% )  (40.68%)
           547,465      stalled-cycles-frontend          #    1.33% frontend cycles idle        ( +-  3.43% )  (40.60%)
           413,657      stalled-cycles-backend           #    1.00% backend cycles idle         ( +- 20.37% )  (40.50%)
        37,009,429      instructions                     #    0.90  insn per cycle
                                                  #    0.01  stalled cycles per insn     ( +-  3.13% )  (40.43%)
         5,410,381      branches                         #  351.526 M/sec                       ( +-  3.24% )  (39.80%)
            34,649      branch-misses                    #    0.64% of all branches             ( +-  4.04% )  (39.94%)
        13,965,813      L1-dcache-loads                  #  907.393 M/sec                       ( +-  3.37% )  (39.44%)
         3,623,350      L1-dcache-load-misses            #   25.94% of all L1-dcache accesses   ( +-  3.56% )  (39.52%)
   <not supported>      LLC-loads
   <not supported>      LLC-load-misses
           590,613      L1-icache-loads                  #   38.374 M/sec                       ( +-  3.39% )  (39.67%)
             1,995      L1-icache-load-misses            #    0.34% of all L1-icache accesses   ( +-  4.18% )  (39.67%)
            16,046      dTLB-loads                       #    1.043 M/sec                       ( +-  3.28% )  (39.78%)
            14,040      dTLB-load-misses                 #   87.50% of all dTLB cache accesses  ( +-  3.24% )  (39.78%)
                11      iTLB-loads                       #  714.697 /sec                        ( +- 29.56% )  (39.77%)
             3,657      iTLB-load-misses                 # 33245.45% of all iTLB cache accesses  ( +- 14.61% )  (40.30%)
           395,578      L1-dcache-prefetches             #   25.702 M/sec                       ( +-  3.34% )  (40.10%)
   <not supported>      L1-dcache-prefetch-misses

          0.016429 +- 0.000521 seconds time elapsed  ( +-  3.17% )

Он обнаружил, что значение L1-dcache-prefetches и L1-dcache-loads сильно различается.

• L1-dcache-prefetches — выборки с упреждением кэша данных L1 CPU.

• L1-dcache-loads — загрузки кэша данных L1 CPU.

Без указания смещения CPU выполняет больше загрузок и выборок с упреждением L1-dcache, что приводит к увеличению времени системных вызовов.

Он провёл углублённое исследование горячей точки ASM:

Samples: 15K of event 'cycles:P', Event count (approx.): 6078132137
  Children      Self  Command    Shared Object         Symbol
-   94.11%     0.00%  a.out      [kernel.vmlinux]      [k] entry_SYSCALL_64_after_hwframe                                                                                                                        ◆
   - entry_SYSCALL_64_after_hwframe                                                                                                                                                                              ▒
      - 94.10% do_syscall_64                                                                                                                                                                                     ▒
         - 86.66% __x64_sys_read                                                                                                                                                                                 ▒
              ksys_read                                                                                                                                                                                          ▒
            - vfs_read                                                                                                                                                                                           ▒
               - 85.94% shmem_file_read_iter                                                                                                                                                                     ▒
                  - 77.17% copy_page_to_iter                                                                                                                                                                     ▒
                     - 75.80% _copy_to_iter                                                                                                                                                                      ▒
                        + 19.41% asm_exc_page_fault                                                                                                                                                              ▒
                       0.71% __might_fault                                                                                                                                                                       ▒
                  + 4.87% shmem_get_folio_gfp                                                                                                                                                                    ▒
                    0.76% folio_mark_accessed                                                                                                                                                                    ▒
         + 4.38% __x64_sys_munmap                                                                                                                                                                                ▒
         + 1.02% 0xffffffffae6f6fe8                                                                                                                                                                              ▒
         + 0.79% __x64_sys_execve                                                                                                                                                                                ▒
         + 0.58% __x64_sys_mmap                                                                                                                                                                                  ▒

Внутри_copy_to_iter ASM выглядит так:

       │     copy_user_generic():
  2.19 │       mov    %rdx,%rcx
       │       mov    %r12,%rsi
 92.45 │       rep    movsb %ds:(%rsi),%es:(%rdi)
  0.49 │       nop
       │       nop
       │       nop

Главное различие здесь — производительность rep movsb.

AMD Ryzen 9 5900X медленный при FSRM!

В это время один из моих друзей отправил мне ссылку об ужасной производительности memcpy на Zen 3 при использовании rep movsb. В ней тоже упоминалась rep movsb:

Я обнаружил это при помощи бенчмарка memcpy https://github.com/ska-sa/katgpucbf/blob/69752be58fb8ab0668ada806e0fd809e782cc58b/scratch/memcpy_loop.cpp (скомпилированного при помощи находящегося там же Makefile). Для демонстрации проблемы выполните

./memcpy_loop -b 2113 -p 1000000 -t mmap -S 0 -D 1 0

При этом происходит следующее:

• 2113-байтные копирования в памяти

• 1000000 раз за измеряемое время

• в памяти, распределённой при помощи mmap

• с 0 байтами источника от начала страницы

• с 1 байтом адресата от начала страницы

• в ядре 0.

Результат равен примерно 3,2 ГБ/с. Если изменить аргумент на 2111, то результат станет больше 100 ГБ/с. То есть случай с REP MOVSB примерно в тридцать раз медленнее!

FSRM (Fast Short REP MOV) — это инновация Intel, недавно внедрённая и в архитектуры AMD; она повышает скорость rep movsb и rep movsd. Она спроектирована с целью повышения эффективности больших объёмов памяти. CPU, в которых заявлена её поддержка, по умолчанию используют glibc в FSRM.

@ryncsn провёл дополнительные исследования и обнаружил, что это не связано с упреждающими выборками L1.

Похоже, производительность rep movsb низка, когда данные выровнены по страницам, и она выше, когда данные не выровнены по страницам, что очень забавно...

Вывод

Проблема не связана с ПОconclusion. Python обгоняет по производительности C/Rust из-за бага в процессоре AMD. (И я наконец-то могу спать спокойно.)

Однако наши пользователи по-прежнему испытывают трудности с этой проблемой. К сожалению, функции наподобие FSRM будут реализованы в ucode, не оставляя нам никакого выбора, кроме как ждать ответа AMD. Альтернативное решение может заключаться в том, чтобы не использовать FSRM или предоставить флаг для её отключения. Разработчикам на Rust стоит задуматься о переходе jemallocator для повышения производительности, это выигрышный ход даже без наличия багов в процессорах AMD.

Дополнения

На разбор этой проблемы я потратил почти три дня. Всё началось с жалоб пользователей opendal и в конечном итоге привело меня к ucode CPU.

В ходе анализа я многое узнал о strace, perf и eBPF. Я впервые использовал eBPF для диагностики. Также я исследовал множество различных бесплодных догадок, например, изучил реализацииstd::fs в Rust и подробности реализации чтения в Python и CPython. Поначалу я надеялся разрешить проблему на высоком уровне, но оказалось, что нужно погрузиться глубже.

Большое спасибо всем тем, кто поучаствовал в поиске ответа:

• @beldathas из discord opendal за выявление проблемы.

• Команде @datafuselabs за её полезные рекомендации.

• Нашим друзьям из @rust_zh (telegram-группа по Rust, которая в основном ведётся на ханьском языке) за советы и попытки воспроизведения проблемы.

• @Manjusaka за воспроизведение проблемы и использование eBPF для её изучения, что помогло сузить круг поисков до самого системного вызова.

• @lilydjwg за выявление первопричины: смещения 0x20 в памяти

• @ryncsn за его тщательный анализ

• И другу, который поделился полезными ссылками о FSRM

Ссылки

• Xuanwo/when-i-find-rust-is-slow — все фрагменты кода и скрипты.

• Std::fs::read slow? — отчёт из сообщества Rust

• Terrible memcpy performance on Zen 3 when using rep movsb — отчёт по ubuntu glibc

• binding/python: rust std fs is slower than python fs

---

Обновления

Эта статья, написанная 29 ноября 2023 года, привлекла большое внимание! Чтобы не запутывать читателей, я решил не изменять оригинальное содержание; обеспечивать актуальность информации и отвечать на популярные вопросы я буду в обновлениях.

1 декабря 2023 года: знает ли AMD об этом баге?

TL;DR: Да

Насколько я знаю, AMD было известно об этом баге ещё с 2021 года. После публикации статьи многие читатели отправили ссылку в AMD, так что я уверен, что компания о ней проинформирована.

Я уверен, что AMD должна взять на себя ответственность за этот баг и устранить его в amd-ucode. Однако из неподтверждённых источников стало известно, что исправление через amd-ucode маловероятно (по крайней мере, для Zen 3) из-за ограниченного пространства в патче. Если у вас есть какая-то информация по этому вопросу, прошу написать мне.

Наша единственная надежда — изменения в glibc, позволяющие по необходимости отключать FSRM. На этом фронте заметен прогресс: x86: Improve ERMS usage on Zen3. Следите за обновлениями.

1 декабря 2023 года: jemalloc или pymalloc быстрее, чем malloc из glibc?

TL;DR: Нет

Прошу прощения за то, что подробно не написал о связи между распределителем памяти и этим багом. Из поста может показаться, что jemalloc (pymalloc, mimalloc) существенно быстрее, чем malloc из glibc. Однако это не так. Проблема не связана с распределителем памяти. Разница в скорости, из-за которой jemalloc и pymalloc обгоняют malloc glibc, возникла из-за разных смещений области памяти.

Давайте проанализируем strace rust-std-fs-read и rust-std-fs-read-with-jemalloc:

strace для rust-std-fs-read:

> strace -e raw=read,mmap ./rust-std-fs-read/target/release/test
...
mmap(0, 0x4001000, 0x3, 0x22, 0xffffffff, 0) = 0x7f39a6e49000
openat(AT_FDCWD, "/tmp/file", O_RDONLY|O_CLOEXEC) = 3
read(0x3, 0x7f39a6e49010, 0x4000000)    = 0x4000000
read(0x3, 0x7f39aae49010, 0)            = 0
close(3)                                = 0

strace для rust-std-fs-read-with-jemalloc:

> strace -e raw=read,mmap ./rust-std-fs-read-with-jemalloc/target/release/test
...
mmap(0, 0x200000, 0x3, 0x4022, 0xffffffff, 0) = 0x7f7a5a400000
mmap(0, 0x5000000, 0x3, 0x4022, 0xffffffff, 0) = 0x7f7a55400000
openat(AT_FDCWD, "/tmp/file", O_RDONLY|O_CLOEXEC) = 3
read(0x3, 0x7f7a55400740, 0x4000000)    = 0x4000000
read(0x3, 0x7f7a59400740, 0)            = 0
close(3)                                = 0

В rust-std-fs-read mmap возвращает 0x7f39a6e49000, но системный вызов чтения использует в качестве начального адреса 0x7f39a6e49010, смещение равно 0x10. В rust-std-fs-read-with-jemalloc mmap возвращает 0x7f7a55400000, а системный вызов чтения использует в качестве начального адреса 0x7f7a55400740, смещение равно0x740.

rust-std-fs-read-with-jemalloc обгоняетrust-std-fs-read из-за большего смещения, которое выходит за пределы проблемного интервала: 0x00..0x10 страницы. Эту проблему можно воспроизвести и с jemalloc.