Thread Surge When Writing Logs During Log Rotation

[wuxi889]

When writing to a log file during log rotation, a sudden surge in thread count may occur.
在日志轮转的同时写入日志文件时，可能引起线程暴涨

In our production environment, logs are rotated daily based on the date, and this setup has been working fine for a long time. However, after I recently set maxFiles to 2, we’ve encountered two incidents where threads got stuck, causing a sharp increase in the number of threads. The same issue was also observed during simulated testing.
在生产环境中日志的写入是根据日期进行轮转的，之前一直都没有问题，直至我最近设置了 maxFiles 为 2。目前已经出现了 2 次线程 hang 住的情况，导致了线程数暴涨，在模拟测试时也出现了相同的问题。

20250611171351_rec_.mp4

配置信息：

• worker_num = 1
• aio_core_worker_num = 2
• max_wait_time = 15

日志写入用的是 Monolog/Handler/RotatingFileHandler

swoole 信息：

# php --ri swoole

swoole

Swoole => enabled
Author => Swoole Team <team@swoole.com>
Version => 5.1.2
Built => Jan 24 2024 05:51:34
coroutine => enabled with boost asm context
epoll => enabled
eventfd => enabled
signalfd => enabled
spinlock => enabled
rwlock => enabled
openssl => OpenSSL 3.1.4 24 Oct 2023
dtls => enabled
http2 => enabled
json => enabled
curl-native => enabled
pcre => enabled
c-ares => 1.19.1
zlib => 1.2.13
brotli => E16777225/D16777225
mutex_timedlock => enabled
pthread_barrier => enabled
async_redis => enabled
coroutine_pgsql => enabled
coroutine_odbc => enabled
coroutine_sqlite => enabled

Directive => Local Value => Master Value
swoole.enable_coroutine => On => On
swoole.enable_library => On => On
swoole.enable_fiber_mock => Off => Off
swoole.enable_preemptive_scheduler => Off => Off
swoole.display_errors => On => On
swoole.use_shortname => Off => Off
swoole.unixsock_buffer_size => 8388608 => 8388608

[NathanFreeman]

如果模拟测试能够复现出来，用strace看看阻塞的线程在等待什么。
我看你的配置worker_num = 1，CPU是24个，那么异步线程最大就是 1 * 8 * 24 = 192，这个受到aio_worker_num配置的影响

[wuxi889]

如果模拟测试能够复现出来，用strace看看阻塞的线程在等待什么。 我看你的配置worker_num = 1，CPU是24个，那么异步线程最大就是 1 * 8 * 24 = 192，这个受到aio_worker_num配置的影响

1. 我测试的时候线程超出限值是一瞬间的事情，用 strace 基本观测不到堆栈等待；

2. “异步线程最大就是 1 * 8 * 24 = 192” 我看过相关代码，而且我在测试时是 aio_core_worker_num = 2，但依旧会有超出限值的线程数出现
   https://github.com/swoole/swoole-src/blob/master/src/os/async_thread.cc#L85

[NathanFreeman]

我看上面的视频，你用的是SWOOLE_PROCESS模式吗？
我看最下面的php是worker进程，线程增长的位置不是在worker进程中，而是在master或者manager进程里

[wuxi889]

我看上面的视频，你用的是SWOOLE_PROCESS模式吗？ 我看最下面的php是worker进程，线程增长的位置不是在worker进程中，而是在master或者manager进程里

对，使用的是 SWOOLE_PROCESS 模式，视频不方便设置，但线程的增长是在 Worker 进程下

[NathanFreeman]

我试试看能不能复现出来

[wuxi889]

我试试看能不能复现出来

因为生产环境是里是按天切割日志的，但测试时按天七个就不合适了。所以我是重载了 Monolog/Handler/RotatingFileHandler 这个类，增加了按分钟切割日志

// composer.lock
        {
            "name": "monolog/monolog",
            "version": "3.8.1",
            "source": {
                "type": "git",
                "url": "https://github.com/Seldaek/monolog.git",
                "reference": "aef6ee73a77a66e404dd6540934a9ef1b3c855b4"
            },
        }

<?php

declare(strict_types=1);

namespace App\Override\Monolog\Handler;

use InvalidArgumentException;
use Monolog\Handler\RotatingFileHandler as BaseHandler;
use Monolog\Level;

class RotatingFileHandler extends BaseHandler
{
    // 按小时分割日志
    public const FILE_PER_HOUR = 'Y-m-d-H';
    public const FILE_PER_MINUTE = 'Y-m-d-H-i';

    public function __construct(
        string $filename, 
        int $maxFiles = 0, 
        int|string|Level $level = Level::Debug, 
        bool $bubble = true, 
        ?int $filePermission = null, 
        bool $useLocking = false, 
        string $dateFormat = self::FILE_PER_MINUTE, 
        string $filenameFormat  = '{filename}-{date}'
    )
    {
        parent::__construct($filename, $maxFiles, $level, $bubble, $filePermission, $useLocking, $dateFormat, $filenameFormat);
    }

    protected function getGlobPattern(): string
    {
        $fileInfo = pathinfo($this->filename);
        $glob = str_replace(
            ['{filename}', '{date}'],
            [$fileInfo['filename'], str_replace(
                ['Y', 'y', 'm', 'd', 'H', 'i'],
                ['[0-9][0-9][0-9][0-9]', '[0-9][0-9]', '[0-1][0-9]', '[0-3][0-9]', '[0-2][0-9]', '[0-5][0-9]'],
                $this->dateFormat)
            ],
            ($fileInfo['dirname'] ?? '') . '/' . $this->filenameFormat
        );
        if (isset($fileInfo['extension'])) {
            $glob .= '.'.$fileInfo['extension'];
        }

        return $glob;
    }

    protected function setDateFormat(string $dateFormat): void
    {
        if (0 === preg_match('{^[Yy]([/_.-]?m)?([/_.-]?d)?([/_.-]?H)?([/_.-]?i)?$}', $dateFormat)) {
            throw new InvalidArgumentException(
                'Invalid date format - format must be one of '.
                'RotatingFileHandler::FILE_PER_DAY ("Y-m-d"), RotatingFileHandler::FILE_PER_MONTH ("Y-m") '.
                'or RotatingFileHandler::FILE_PER_YEAR ("Y"), or you can set one of the '.
                'date formats using slashes, underscores and/or dots instead of dashes.'
            );
        }
        $this->dateFormat = $dateFormat;
    }

    protected function getNextRotation(): \DateTimeImmutable
    {
        return match (str_replace(['/','_','.'], '-', $this->dateFormat)) {
            self::FILE_PER_MINUTE => (new \DateTimeImmutable('next minute'))->setTime((int) date('H') + 1, (int) date('i') + 1, 0),
            self::FILE_PER_HOUR => (new \DateTimeImmutable('next hour'))->setTime((int) date('H') + 1, 0, 0),
            self::FILE_PER_DAY => (new \DateTimeImmutable('tomorrow'))->setTime(0, 0, 0),
            self::FILE_PER_MONTH => (new \DateTimeImmutable('first day of next month'))->setTime(0, 0, 0),
            self::FILE_PER_YEAR => (new \DateTimeImmutable('first day of January next year'))->setTime(0, 0, 0),
            default => (new \DateTimeImmutable('tomorrow'))->setTime(0, 0, 0),
        };
    }
}

[NathanFreeman]

我没能复现出这个问题，我这边情况压测的情况下写入日志才会导致线程数增加。
pstree -p worker进程id | wc -l 查看一下问题发生时的php线程数，看看线程增长的数量是否在aio_worker_num范围内。
如果线程增长之后经过aio_max_idle_time设置的秒数后就退出了，那估计是增加线程数来删除多余的日志文件。

但是issue有提及到线程会有挂起的情况，这个时候尝试用strace检查这些挂起的线程在阻塞在哪里

[NathanFreeman]

你应用有用sqlite或者odbc的数据库吗

[wuxi889]

你应用有用sqlite或者odbc的数据库吗

没有使用，使用的是 pgsql-swoole

[wuxi889]

那估计是增加线程数来删除多余的日志文件

我这里也是压测（maxFiles = 3）的情况导致了线程数的增加并超出了 aio_worker_num 设置范围。若果线程增长是用来删除多余日志文件的，那么有没有可能是这些线程进入了 D 状态，导致了一直有增长线程来想要处理这个删除文件。

另外，删除文件的线程不受限于 aio_worker_num 控制吗？

[NathanFreeman]

要看一下超过 aio_worker_num 设置范围多少。
删除文件的线程数受限于aio_worker_num。
我遇到最多状态D的进程是因为在访问CFS或者NAS这类挂载磁盘导致I/O速率很慢，进程一直在等待IO操作。

或者你看看代码还有没有哪里设置了aio_worker_num

[wuxi889]

要看一下超过 aio_worker_num 设置范围多少。 删除文件的线程数受限于aio_worker_num。 我遇到最多状态D的进程是因为在访问CFS或者NAS这类挂载磁盘导致I/O速率很慢，进程一直在等待IO操作。

或者你看看代码还有没有哪里设置了aio_worker_num

配置上没有进行额外的配置了。

aio_core_worker_num = 2

worker_num = 1

超出时的线程数总数为 34，扣除掉 reactor_num 的默认 min(8, cpu_num)，实际 worker 里的线程有 26。

[NathanFreeman]

如果你没设置aio_worker_num的话，那么线程一共增加到了226是吗

[wuxi889]

如果你没设置aio_worker_num的话，那么线程一共增加到了226是吗

只到 26，对 aio_worker_num 配置做限制是否会复现我今天测试下看看