Rust std fs 比 Python 慢！真的吗！？

我即将分享一个冗长的故事，从opendal^[1] 的 op.read()开始，以一个意想不到的转折结束。这个过程对我来说非常有启发性，我希望你也能感受到。我会尽力重现这个经历，并附上我一路学到的教训。让我们开始吧！

所有的代码片段和脚本都可以在Xuanwo/when-i-find-rust-is-slow^[2]中找到。

OpenDAL Python绑定比Python慢？

OpenDAL^[3] 是一个数据访问层，允许用户以统一的方式从各种存储服务中轻松高效地获取数据。我们通过 pyo3^[4] 为 OpenDAL 提供了 python 绑定。

有一天，@beldathas 在 discord^[5] 向我报告了一个案例，即 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"
defread_file_with_opendal()->bytes:
with op.open(filename,"rb")as fp:
        result = fp.read()
return result
defread_file_with_normal()->bytes:
withopen(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

Emmm, 我对这些结果有点尴尬。以下是一些快速的假设：

• • Python是否有内部缓存可以重复使用相同的内存？

• • Python是否拥有加速文件读取的一些技巧？

• • PyO3是否引入了额外的开销？

我将代码重构如下：

python-fs-read^[6]:

withopen("/tmp/file","rb")as fp:
    result = fp.read()
assertlen(result)==64*1024*1024

python-opendal-read^[7]:

import opendal
op = opendal.Operator("fs", root=str("/tmp"))
result = op.read("file")
assertlen(result)==64*1024*1024

结果显示，Python比 OpenDAL 快得多：

Benchmark1: 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

Benchmark2: 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等。让我们集中精力尝试找出根本原因。

我在rust中通过 opendal fs 服务实现了相同的逻辑：

rust-opendal-fs-read^[8]:

use std::io::Read;
use opendal::services::Fs;
use opendal::Operator;
fnmain(){
letmutcfg=Fs::default();
    cfg.root("/tmp");
letop=Operator::new(cfg).unwrap().finish().blocking();
letmutbs=vec![0;64*1024*1024];
letmutf= op.reader("file").unwrap();
letmutts=0;
loop{
letbuf=&mut bs[ts..];
letn= f.read(buf).unwrap();
letn= n asusize;
if n ==0{
break
}
        ts += n;
}
assert_eq!(ts,64*1024*1024);
}

然而，结果显示即使 opendal 是用rust实现的，它的速度仍然比 python 慢：

Benchmark1: 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

Benchmark2: 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慢。

Rust std fs 比 Python 慢?

OpenDAL通过std::fs^[9]实现文件系统服务。OpenDAL本身会产生额外的开销吗？

我使用 std::fs 在 Rust 中实现了相同逻辑：

rust-std-fs-read^[10]:

use std::io::Read;
use std::fs::OpenOptions;
fnmain(){
letmutbs=vec![0;64*1024*1024];
letmutf=OpenOptions::new().read(true).open("/tmp/file").unwrap();
letmutts=0;
loop{
letbuf=&mut bs[ts..];
letn= f.read(buf).unwrap();
letn= n asusize;
if n ==0{
break
}
        ts += n;
}
assert_eq!(ts,64*1024*1024);
}

但是：

Benchmark1: 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

Benchmark2: 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

哇，Rust的 std fs 比 Python 还慢？这怎么可能呢？无意冒犯，但是这怎么可能呢？

Rust std fs 比 Python 还慢？真的吗！？

我无法相信这个结果：rust std fs的速度竟然比Python还要慢。

我尝试学会了如何使用strace进行系统调用分析。strace^[11]是一个Linux系统调用追踪器，它让我们能够监控系统调用并理解其过程。

strace将包含程序发出的所有系统调用。我们应该关注与/tmp/file相关的方面。每一行strace输出都以系统调用名称开始，后跟输入参数和输出。

比如：

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

这意味着我们使用参数AT_FDCWD，"/tmp/file"和O_RDONLY|O_CLOEXEC调用 openat系统调用。这将返回输出 3, 这是在后续的系统调用中引用的文件描述符。

好了，我们已经掌握了 strace. 让我们开始使用它吧！

rust-std-fs-read 的 strace:

>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
...

python-fs-read 的 strace:

>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：要映射的内存区域的大小。我们在这里分配64MiB + 4KiB内存，额外的页面用于存储此内存区域的元数据。

• • 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, 这有助于缓解内存碎片问题。

默认情况下，所有以目标 x86_64-unknown-linux-gnu 编译的 Rust 程序都使用由 glibc 提供的 malloc 实现。

Python 和 Rust 是否使用相同的内存分配器？

默认情况下，Python使用pymalloc^[12]，这是一个针对小型分配进行优化的内存分配器。Python具有三个内存域，每个代表不同的分配策略，并针对各种目的进行了优化。

pymalloc 有如下行为

Python has a pymalloc allocator optimized for small objects (smaller or equal to 512 bytes) with a short lifetime. It uses memory mappings called “arenas” with a fixed size of either 256 KiB on 32-bit platforms or 1 MiB on 64-bit platforms. It falls back to PyMem_RawMalloc() and PyMem_RawRealloc() for allocations larger than 512 bytes.

Rust默认的内存分配器比Python慢吗？

我怀疑mmap是导致这个问题的原因。如果我切换到jemalloc，会发生什么情况？

rust-std-fs-read-with-jemalloc^[13]:

use std::io::Read;
use std::fs::OpenOptions;
#[global_allocator]
static GLOBAL: jemallocator::Jemalloc= jemallocator::Jemalloc;
fnmain(){
letmutbs=vec![0;64*1024*1024];
letmutf=OpenOptions::new().read(true).open("/tmp/file").unwrap();
letmutts=0;
loop{
letbuf=&mut bs[ts..];
letn= f.read(buf).unwrap();
letn= n asusize;
if n ==0{
break
}
        ts += n;
}
assert_eq!(ts,64*1024*1024);
}

Wooooooooooooooow?!

Benchmark1: 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

Benchmark2: 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
ByteOrder:LittleEndian
CPU(s):32
On-line CPU(s) list:0-31
Vendor ID:AuthenticAMD
Model name:            AMD Ryzen95950X16-CoreProcessor
    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:512KiB(16 instances)
  L1i:512KiB(16 instances)
  L2:8MiB(16 instances)
  L3:64MiB(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.
Handle0x0014, DMI type 16,23 bytes
PhysicalMemoryArray
Location:SystemBoardOrMotherboard
Use:SystemMemory
ErrorCorrectionType:None
MaximumCapacity:64 GB
ErrorInformationHandle:0x0013
NumberOfDevices:4
Handle0x001C, DMI type 17,92 bytes
MemoryDevice
ArrayHandle:0x0014
ErrorInformationHandle:0x001B
TotalWidth:64 bits
DataWidth:64 bits
Size:16 GB
FormFactor: DIMM
Set:None
Locator: DIMM 0
BankLocator: P0 CHANNEL A
Type: DDR4
TypeDetail:SynchronousUnbuffered(Unregistered)
Speed:3200 MT/s
Manufacturer:Unknown
SerialNumber:04904740
AssetTag:NotSpecified
PartNumber: LMKUFG68AHFHD-32A
Rank:2
ConfiguredMemorySpeed:3200 MT/s
MinimumVoltage:1.2 V
MaximumVoltage:1.2 V
ConfiguredVoltage:1.2 V
MemoryTechnology: DRAM
MemoryOperatingModeCapability:Volatile memory
FirmwareVersion:Unknown
ModuleManufacturer ID:Bank9,Hex0xC8
ModuleProduct ID:Unknown
MemorySubsystemControllerManufacturer ID:Unknown
MemorySubsystemControllerProduct ID:Unknown
Non-VolatileSize:None
VolatileSize:16 GB
CacheSize:None
LogicalSize:None

所以我尝试了以下事情：

开启 Mitigations

CPU拥有许多可能将私有数据暴露给攻击者的漏洞，其中Spectre是最知名的之一。Linux内核已经开发了各种缓解这些漏洞的措施，并且默认启用它们。然而，这些缓解措施可能会增加额外的系统成本。因此，Linux内核也为希望禁用它们的用户提供了一个mitigations开关。

我过去禁用了所有的 mitigations：

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

启用它并不能改变结果

调整透明大页

透明大页^[14]可以显著影响性能。大多数现代发行版默认启用它。

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

切换到madvise或never会改变绝对结果，但相对比例保持一致。

Tune CPU 核心亲和度

@Manjusaka^[15] 猜测这可能与CPU核心间距有关。我试图使用core_affinity^[16]将进程绑定到特定的CPU，但结果仍然相同。

使用 eBPF 精确测量 syscall 延迟

@Manjusaka^[17] 也为我创建了一个eBPF程序^[18]，以便我衡量读取系统调用的延迟。研究结果表明，Rust在系统调用级别上就比Python慢。

@Manjusaka 写一篇文章来分享关于这个 eBPF 程序的故事！

# python fs read
Process57555 read file 8134049 ns
Process57555 read file 942 ns

# rust std fs read
Process57634 read file 24636975 ns
Process57634 read file 1052 ns

观察：在我的电脑上，Rust运行速度比Python慢，而且这似乎与软件无关。

C 比 Python 慢?

我感到相当困惑，无法准确指出差异。我怀疑这可能与CPU有关，但我不确定是哪个方面：缓存？频率？核间距？核亲和性？架构？

根据Telegram群组Rust 众^[19]的建议，我开发了一个C版本：

c-fs-read^[20]:

#include<stdio.h>
#include<stdlib.h>
#define FILE_SIZE 64*1024*1024// 64 MiB
intmain(){
FILE*file;
char*buffer;
size_t result;
    file = fopen("/tmp/file","rb");
if(file ==NULL){
fputs("Error opening file",stderr);
return1;
}
    buffer =(char*)malloc(sizeof(char)* FILE_SIZE);
if(buffer ==NULL){
fputs("Memory error",stderr);
        fclose(file);
return2;
}
    result = fread(buffer,1, FILE_SIZE, file);
if(result != FILE_SIZE){
fputs("Reading error",stderr);
        fclose(file);
free(buffer);
return3;
}
    fclose(file);
free(buffer);
return0;
}

但是。。。

Benchmark1: 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
Benchmark2: 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^[21]加入了讨论，并注意到C和Python之间的内存区域偏移存在差异。

strace -e raw=read,mmap ./program被用来打印系统调用的未解码参数：指针地址。

c-fs-read 的 strace:

>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

python-fs-read 的 strace

>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，但是read系统调用使用 0x7f96d1a18010作为起始地址，偏移量是 0x10。在 python-fs-read中， mmap 返回 0x7f27dcfbe000, 并且 read 系统调用使用 0x7f27dcfbe030 作为起始地址, 偏移量是 0x30.

所以@lilydjwg^[22] 尝试用相同的偏移量来调用 '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']
Benchmark1: 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.
Benchmark2: 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
Benchmark3: 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

!!!

在c-fs-read中对buffer应用偏移量可以提高其速度，超过Python！此外，我们已经验证了这个问题在 AMD Ryzen 9 5900X 和 AMD Ryzen 7 5700X 上都能复现。

新的信息让我找到了关于类似问题的其他报告，Std::fs::read slow?^[23]。在这篇帖子中，@ambiso^[24] 发现系统调用性能与内存区域的偏移量有关。他指出当从每页的前 0x10 字节写入时，这款CPU会变慢。

offset milliseconds
...
14130
15130
1646<-----0x10!
1748
...

在指定的偏移量下，AMD Ryzen 9 5900X 很慢！

我们已确认这个问题与CPU有关。然而，我们仍然不确定其可能的原因。@Manjusaka^[25] 已邀请内核开发者 @ryncsn^[26] 加入讨论。

他可以在 AMD Ryzen 9 5900HX 上使用我们的 c-fs-read 和 c-fs-read-with-offset 重现相同的结果。他还尝试使用 perf 对两个程序进行性能分析。

没有 offset:

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%)

有 offset:

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是CPU L1数据缓存的预取。

• • L1-dcache-loads是CPU L1数据缓存的加载。

如果没有指定偏移量，CPU将执行更多的加载和预取操作，导致系统调用时间增加。

他对热点ASM进行了进一步研究：

Samples:15K of event'cycles:P',Event count (approx.):6078132137
ChildrenSelfCommandSharedObjectSymbol
-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 慢!

在这个时候，我的一个朋友给我发送了一个关于 Terrible memcpy performance on Zen 3 when using rep movsb^[27] 的链接。其中也指向了rep movsb：

I've found this using a memcpy benchmark at https://github.com/ska-sa/katgpucbf/blob/69752be58fb8ab0668ada806e0fd809e782cc58b/scratch/memcpy_loop.cpp (compiled with the adjacent Makefile). To demonstrate the issue, run

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

This runs:

• • 2113-byte memory copies

• • 1,000,000 times per timing measurement

• • in memory allocated with mmap

• • with the source 0 bytes from the start of the page

• • with the destination 1 byte from the start of the page

• • on core 0.

It reports about 3.2 GB/s. Change the -b argument to 2111 and it reports over 100 GB/s. So the REP MOVSB case is about 30× slower!

FSRM，即 Fast Short REP MOV，是英特尔最初的创新，近期也被AMD采纳，用以提升 rep movsb 和 rep movsd 的速度。它旨在提高大量内存复制的效率。声明支持它的CPU将在 glibc 中默认使用 FSRM。

@ryncsn^[28] 进一步研究并发现它与L1预取无关。

It seems that rep movsb performance poorly when DATA IS PAGE ALIGNED, and perform better when DATA IS NOT PAGE ALIGNED, this is very funny...

总结

总的来说，这个问题并非与软件有关。由于AMD的一个错误，Python在性能上超过了C/Rust。（我终于可以好好睡觉了。）

然而，我们的用户仍然需要面对这个问题。不幸的是，像FSRM这样的功能将会被实现在ucode中，我们别无选择只能等待AMD的回应。另一种可能的解决方案是不使用FSRM或者提供一个标志来禁用它。Rust开发者可能会考虑切换到 jemallocator以提高性能 ，即使没有AMD CPU Bug 存在，这也是一个好主意！

回顾

我花了近三天的时间来解决这个问题，它始于opendal^[29]用户的投诉，并最终引导我到CPU的微代码。 这次旅程让我对strace、perf和eBPF有了深入的了解。 这是我第一次使用 eBPF进行诊断。 我还探索了各种收效甚微的途径，比如研究rust 的 std::fs 和 Python & CPython 的读取实现细节。 起初，我希望能在更高层面上解决这个问题，但发现有必要深入挖掘。

对于所有参与寻找答案的人，我表示衷心感谢：

• • 感谢opendal的Discord上的@beldathas发现了这个问题。

• • 感谢@datafuselabs^[30]团队提供的建议。

• • 感谢我们在Rust 众^[31] 的朋友们给出的建议和复现努力。

• • 感谢@Manjusaka^[32]复现问题并使用eBPF进行调查，这帮助我们将问题定位到系统调用本身。

• • 感谢@lilydjwg^[33]找出根本原因：内存中0x20偏移量 -感谢 @ryncsn^[34]他对此事进行了彻底分析

• • 还有一位分享了关于FSRM有用链接的朋友

期待我们下次旅程！

引用

• • Xuanwo/when-i-find-rust-is-slow^[35] 有所有的样例和脚本

• • Std::fs::read slow?^[36] 是来自 Rust 社区的汇报

• • Terrible memcpy performance on Zen 3 when using rep movsb^[37] 是来自 ubuntu glibc 的报告

• • binding/python: rust std fs is slower than python fs^[38]

引用链接

[1] opendal: https://github.com/apache/incubator-opendal
[2] Xuanwo/when-i-find-rust-is-slow: https://github.com/Xuanwo/when-i-find-rust-is-slow
[3] OpenDAL: https://github.com/apache/incubator-opendal
[4] pyo3: https://github.com/PyO3/pyo3
[5] discord: https://discord.com/channels/1081052318650339399/1174840499576770560
[6] python-fs-read: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/python-fs-read/test.py
[7] python-opendal-read: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/python-opendal-read/test.py
[8] rust-opendal-fs-read: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/rust-opendal-fs-read/src/main.rs
[9] std::fs: https://doc.rust-lang.org/std/fs/index.html
[10] rust-std-fs-read: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/rust-std-fs-read/src/main.rs
[11] strace: https://strace.io/
[12] pymalloc: https://docs.python.org/3/c-api/memory.html#default-memory-allocators
[13] rust-std-fs-read-with-jemalloc: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/rust-std-fs-read-with-jemalloc/src/main.rs
[14] 透明大页: https://www.kernel.org/doc/html/next/admin-guide/mm/transhuge.html
[15] @Manjusaka: https://github.com/ZheaoLi
[16] core_affinity: https://docs.rs/core_affinity/latest/core_affinity/
[17] @Manjusaka: https://github.com/ZheaoLi
[18] 一个eBPF程序: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/scripts/read-latency.py
[19] Rust 众: https://t.me/rust_zh
[20] c-fs-read: https://github.com/Xuanwo/when-i-find-rust-is-slow/blob/main/c-fs-read/test.c
[21] @lilydjwg: https://github.com/lilydjwg
[22] @lilydjwg: https://github.com/lilydjwg
[23] Std::fs::read slow?: https://users.rust-lang.org/t/std-read-slow/85424
[24] @ambiso: https://github.com/ambiso
[25] @Manjusaka: https://github.com/ZheaoLi
[26] @ryncsn: https://github.com/ryncsn
[27] Terrible memcpy performance on Zen 3 when using rep movsb: https://bugs.launchpad.net/ubuntu/+source/glibc/+bug/2030515
[28] @ryncsn: https://github.com/ryncsn
[29] opendal: https://github.com/apache/incubator-opendal
[30] @datafuselabs: https://github.com/datafuselabs
[31] Rust 众: https://t.me/rust_zh
[32] @Manjusaka: https://github.com/ZheaoLi
[33] @lilydjwg: https://github.com/lilydjwg
[34] @ryncsn: https://github.com/ryncsn
[35] Xuanwo/when-i-find-rust-is-slow: https://github.com/Xuanwo/when-i-find-rust-is-slow
[36] Std::fs::read slow?: https://users.rust-lang.org/t/std-read-slow/85424
[37] Terrible memcpy performance on Zen 3 when using rep movsb: https://bugs.launchpad.net/ubuntu/+source/glibc/+bug/2030515
[38] binding/python: rust std fs is slower than python fs: https://github.com/apache/incubator-opendal/issues/3665