当前位置：首页>python>python GIL 竞争导致I/O超时

python GIL 竞争导致I/O超时

2026-08-18 23:11:40

有个需求，需要在虚机上测试 kafka 性能，使用 kafka-python 包编写 python 多线程程序发送 kafka 数据，每次测试数据发送一段时间会出现超时。

Connection lost:KafkaConnectionError:Connection timed outRequestTimedOutError: Request timed out after 3791 ms

查看 kafka 日志和状态，没有任何异常😓，经过一番调研，是 python GIL 机制造成客户端自身超时。

排查过程

启动 kafka 客户端进程发送数据，这里给它绑定8个 CPU 核16~23，启动8个发送任务，最终创建17个线程。1个主线程，8个 work 线程用于生成数据并 json 序列化，8 个 network 线程用于 lz4 压缩数据并发送给 kafka。

# DUR=15000 ./run_experiments.sh############ 环境快照 ############2026-08-02 16:53:23kafka-python 3.0.8 | confluent librdkafka 2.15.0sender cpuset=16-23  时长=15000s  本机 72 核broker: Up 2 days 0.0.0.0:39092->9092/tcp, [::]:39092->9092/tcp############ 场景:1 进程 × 8 kafka-python 线程(一把 GIL) ############2026-08-02 16:53:24>>> 对活着的进程 pid=221875 采集 GIL 四手段证据

首先使用 py-spy 抓拍线程状态，看谁持 GIL ，网络线程是否被饿。检查发现只有一个线程是 active 状态，其他都是 idle，真是够闲的。

# venv/bin/py-spy dump --pid 221875 | tee /tmp/py-spy.dumpProcess 221875: /test/python-gil/venv/bin/python -u sender.py --bootstrap localhost:39092 --topic gil-test --max-message-bytes 8192 --measurepoints 200 --compression-type lz4 --acks 1 --request-timeout-ms 30000 --max-pending 2500 --out-dir /test/python-gil/results --report-interval 30 --client kafka-python --tasks 8 --duration 15000 --tag APython v3.11.15 (/test/.local/share/uv/python/cpython-3.11.15-linux-x86_64-gnu/bin/python3.11)Thread 221875 (idle): "MainThread"      main (sender.py:445)      <module> (sender.py:486)Thread 221886 (idle): "worker-0"      enter (threading.py:272)      acquire (threading.py:468)      worker (sender.py:333)  。。。省略部分内容。。。Thread 221953 (active+gil): "A-t8-network-thread"      crc_update (kafka/record/_crc32c.py:130)      crc (kafka/record/_crc32c.py:153)      calc_crc32c (kafka/record/util.py:128)#  grep -oE '((idle|active<span class="code-snippet__operator">+gil|active))' /tmp/py-spy.dump(idle)(idle)(idle)(idle)(idle)(idle)(idle)(idle)(idle)(active+gil)(idle)(idle)(idle)(idle)(idle)(idle)(idle)

查看客户端进程使用了多少 CPU，16个线程仅用了1个多点。即使我们在启动程序时给它绑定了8个 CPU 核16-23。

# pidstat -p 221875 1Linux 5.15.0-139-generic (EnDSCPU)      08/02/2026      _x86_64_        (72 CPU)05:28:35 PM   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command05:28:36 PM  1005    221875  100.00    3.00    0.00    0.00  103.00    19  python05:28:37 PM  1005    221875  100.00    4.00    0.00    0.00  104.00    19  python05:28:38 PM  1005    221875   97.00    7.00    0.00    0.00  104.00    19  python

逐个线程看下 CPU 使用率，也是少的可怜。

# pidstat -p 221875 -t 1Linux 5.15.0-139-generic (EnDSCPU)      08/02/2026      x86_64        (72 CPU)05:43:51 PM   UID      TGID       TID    %usr %system  %guest   %wait    %CPU   CPU  Command05:43:52 PM  1005    221875         -   98.00    7.00    0.00    0.00  105.00    22  python05:43:52 PM  1005         -    221875    0.00    0.00    0.00    0.00    0.00    22  |__python05:43:52 PM  1005         -    221886    5.00    0.00    0.00    1.00    5.00    17  |__python05:43:52 PM  1005         -    221887    5.00    0.00    0.00    0.00    5.00    16  |__python05:43:52 PM  1005         -    221888    4.00    1.00    0.00    0.00    5.00    16  |__python05:43:52 PM  1005         -    221889    4.00    1.00    0.00    1.00    5.00    16  |__python05:43:52 PM  1005         -    221890    5.00    0.00    0.00    0.00    5.00    16  |__python05:43:52 PM  1005         -    221891    5.00    0.00    0.00    0.00    5.00    16  |__python05:43:52 PM  1005         -    221892    5.00    0.00    0.00    0.00    5.00    21  |__python05:43:52 PM  1005         -    221893    5.00    0.00    0.00    0.00    5.00    17  |__python05:43:52 PM  1005         -    221934    7.00    1.00    0.00    0.00    8.00    20  |__python05:43:52 PM  1005         -    221935    6.00    0.00    0.00    0.00    6.00    16  |__python05:43:52 PM  1005         -    221938    7.00    1.00    0.00    0.00    8.00    23  |__python05:43:52 PM  1005         -    221940    8.00    0.00    0.00    1.00    8.00    22  |__python05:43:52 PM  1005         -    221941    7.00    1.00    0.00    1.00    8.00    16  |__python05:43:52 PM  1005         -    221942    8.00    0.00    0.00    0.00    8.00    18  |__python05:43:52 PM  1005         -    221943    7.00    1.00    0.00    1.00    8.00    17  |__python05:43:52 PM  1005         -    221953    7.00    0.00    0.00    0.00    7.00    19  |__python

strace 抓包看下，客户端进程到底干啥。原来绝大部分时间耗在 futex 系统调用，futex 用于内核完成线程阻塞/唤醒。即客户端进程大部分系统调用花在线程切换上了。

# sudo -n timeout -s INT 8 strace -f -p 221875 -c \  -e trace=futex,sendto,recvfrom,poll,epoll_wait 2>&1 | tail -20strace: Process 221890 detached。。。% time     seconds  usecs/call     calls    errors syscall------ ----------- ----------- --------- --------- ---------------- 99.86    9.395245         166     56578      4663 futex  0.10    0.009588           4      2092           sendto  0.03    0.002415           2       820       240 recvfrom  0.01    0.001368           2       619           epoll_wait------ ----------- ----------- --------- --------- ----------------100.00    9.408616                 60109      4903 total