记一次 Redis 延时毛刺问题定位


  1. 背景
  2. 问题定位
  3. 根因分析
    1. seq_file
    2. smaps
    3. smaps_rollup
  4. 定位策略/工具
    1. 用户空间耗时
    2. 内核空间耗时
  5. 总结

背景

该问题发生于八月份,业务发现部分线上集群出现 10 分钟一次的耗时毛刺。整个系统的架构很简单:

在 Redis Proxy 可以观察到明显的请求耗时毛刺,因此可以确定问题确实出现在 Redis Proxy 调用 Redis 的某个环节

然而,为了定位该问题,仍然花费了很长的时间:

  • 该问题非必现,且不固定于某台机器
  • 问题发现时,相同/类似毛刺现象涉及众多集群
  • 在线的 Redis 版本缺少 P99 指标(耗时指标仅包括执行耗时,不包括包括等待耗时)耗时毛刺被平均之后无法观察到

问题定位

由于无法利用现有指标缩小问题的范围,只能按照可能性从高到底排查:业务请求 > 网络 > 系统 > 应用。

  • 业务层面:部分集群发现少量 LUA script 相关的慢速日志
  • 网络层面:使用 mtr 观测出现问题的时间点网络状态,并排查上层交换机之后未见异常
  • 系统层面:根据业务反馈之前有类似故障出现,原因是 atop 采集进程 PSS 导致延迟增加。该 case 可以稳定复现,现象略有不同;抽查有异常机器检查未发现有安装 atop。
  • 应用层:相关集群已经较长时间没有版本更新,使用 perf record 很难发现毛刺类型问题

在针对某一个集群的 master failover 到其他节点,请求延迟毛刺消失。对比前后两台机器发现 atop 进程的差异。

$> ps aux|grep atop
root       2442  0.0  0.0   2500  1628 ?        S<    2022  42:21 /usr/sbin/atopacctd
root      11530  0.0  0.0  18024  2068 pts/0    S+   22:08   0:00 grep --color=auto atop
root     182181  1.5  0.0  33784 33184 ?        S<Ls 00:00  20:51 /usr/bin/atop -R -w /var/log/atop/atop_20230807 600

$> ps aux|grep atop
root     403334  0.0  0.0  16572  2016 pts/0    S+   22:09   0:00 grep --color=auto atop

停止所有 atop 之后,请求延迟消失

原来,线上部分机器部署的 atop 版本 默认启用了 -R 选项。在 atop 读 /proc/${pid}/smaps 时,会遍历整个进程的页表,期间会持有内存页表的锁。如果在此期间进程发生虚拟内存地址分配,也需要获取锁,就需要等待锁释放。具体到应用层面就是请求耗时毛刺。

除了 atop,cadvisor 等应用也会读取 /proc/${pid}/smaps,虽然默认关闭。由于关闭的方式是通过 disable_metrics 来指定关闭。如果自定义参数时遗漏相关参数,还是会打开该功能触发耗时毛刺

根因分析

当读取 /proc/${pid}/smaps 获得某个进程虚拟内存区间信息时,究竟发生了什么?

seq_file

Linux 使用文件将内核里面数据结构通过文件导出到用户空间, smaps 使用到的文件类型就是 seq_file 文件。

// linux/include/linux/seq_file.h

struct seq_file {
    char *buf;    // 指向包含要读取或写入的数据的缓冲区
    size_t size;  // 缓冲区的大小
    size_t from;  // 缓冲区中读取或写入的起始位置
    size_t count; // 读取或写入的字节数
    size_t pad_until;  // 将输出填充到某个位置
    loff_t index; // 序列中的当前位置
    loff_t read_pos;   // 当前的读取位置
    u64 version;  // 文件版本
    struct mutex lock; // 锁,确保对 seq_file 操作是线程安全的
    const struct seq_operations *op; // 该结构定义了可以对 proc 执行的操作
    int poll_event;    // 用于 poll 和 select 系统调用
    const struct file *file; // 指向文件结构的指针,即 seq_file 关联的 proc
    void *private; // 私有数据字段,存储特定于文件的数据
};

struct seq_operations {
    // 开始读数据项,通常需要加锁,以防止并行访问数据
	void * (*start) (struct seq_file *m, loff_t *pos);
	
	// 停止读数据项,通常需要解锁
	void (*stop) (struct seq_file *m, void *v);
    
    // 找到下一个要处理的数据项
	void * (*next) (struct seq_file *m, void *v, loff_t *pos);
    
    // 打印数据项到临时缓冲区
	int (*show) (struct seq_file *m, void *v);
};

seq_file 使用 file 存储需要关联的进程,seq_operations 定义读取进程数据的操作。使用全局函数 seq_open 把进程与 seq_operations 关联起来

用户态: open(“/proc/pid/smaps”) –> 内核态: proc_pid_smaps_operations.open()
用户态: read(fd) –> 内核态: proc_pid_smaps_operations.read()

smaps

具体到 smaps,也是一样的实现 file 相关的方法,在内核中是定义在 proc_pid_smaps_operations 结构:

// linux/fs/proc/base.c

REG("smaps",      S_IRUGO, proc_pid_smaps_operations)


// linux/fs/proc/task_mmu.c
// `file_operations` 结构的一个实例,定义 `/proc/PID/smaps` 文件的操作,当操作`/proc/PID/smaps` 文件时被调用
const struct file_operations proc_pid_smaps_operations = {
	.open		= pid_smaps_open, // 打开文件的函数
	.read		= seq_read,       // 读取文件的函数
	.llseek		= seq_lseek,      // 定位文件的函数
	.release	= proc_map_release, // 释放文件的函数
};

其中 open() 函数最终会返回一个文件描述符 fd 供后续 read(fd) 函数使用。

// linux/fs/proc/task_mmu.c    pid_smaps_open()
//     --->linux/fs/proc/task_mmu.c    do_maps_open()
//         --->linux/fs/proc/task_mmu.c    proc_maps_open()

// `seq_operations`结构的实例,定义了一系列的操作函数,在处理`/proc/PID/smaps`文件时被调用
static const struct seq_operations proc_pid_smaps_op = {
	.start	= m_start,  // 开始操作的函数
	.next	= m_next,   // 下一步操作的函数
	.stop	= m_stop,   // 停止操作的函数
	.show	= show_smap // 显示操作的函数
};

static int pid_smaps_open(struct inode *inode, struct file *file)
{
	return do_maps_open(inode, file, &proc_pid_smaps_op);
}

static int do_maps_open(struct inode *inode, struct file *file,
			const struct seq_operations *ops)
{
	return proc_maps_open(inode, file, ops,
				sizeof(struct proc_maps_private));
}

static int proc_maps_open(struct inode *inode, struct file *file,
			const struct seq_operations *ops, int psize)
{
    // 调用`__seq_open_private`函数来打开一个序列文件,并返回一个指向`proc_maps_private`结构的指针。该结构包含了处理`/proc/PID/maps`文件所需的私有数据
	struct proc_maps_private *priv = __seq_open_private(file, ops, psize);

	if (!priv)
		return -ENOMEM;
        
	priv->inode = inode; // 将输入参数`inode`赋值给`priv->inode`
	
	// 调用`proc_mem_open`函数以读取模式打开`inode`指向的内存对象,并将返回的内存描述符赋值给`priv->mm`
	priv->mm = proc_mem_open(inode, PTRACE_MODE_READ);
	if (IS_ERR(priv->mm)) {
		int err = PTR_ERR(priv->mm);

		seq_release_private(inode, file);
		return err;
	}

	return 0;
}

// 打开序列文件并分配私有数据所需的基本操作
void *__seq_open_private(struct file *f, const struct seq_operations *ops,
		int psize)
{
	int rc;
	void *private;
	struct seq_file *seq;

	private = kzalloc(psize, GFP_KERNEL);
	if (private == NULL)
		goto out;

	rc = seq_open(f, ops); // 调用`seq_open`函数打开一个序列文件
	if (rc < 0)
		goto out_free;、
		
	seq = f->private_data; // 获取文件的私有数据,并将其转换为`seq_file`结构的指针
	seq->private = private;
	return private;

out_free:
	kfree(private);
out:
	return NULL;
}

/**
 *	seq_open -	initialize sequential file
 *	@file: file we initialize
 *	@op: method table describing the sequence
 *
 *	seq_open() sets @file, associating it with a sequence described
 *	by @op.  @op->start() sets the iterator up and returns the first
 *	element of sequence. @op->stop() shuts it down.  @op->next()
 *	returns the next element of sequence.  @op->show() prints element
 *	into the buffer.  In case of error ->start() and ->next() return
 *	ERR_PTR(error).  In the end of sequence they return %NULL. ->show()
 *	returns 0 in case of success and negative number in case of error.
 *	Returning SEQ_SKIP means "discard this element and move on".
 */
int seq_open(struct file *file, const struct seq_operations *op)
{
	struct seq_file *p = file->private_data;

	if (!p) {
		p = kmalloc(sizeof(*p), GFP_KERNEL);
		if (!p)
			return -ENOMEM;
		file->private_data = p;
	}
	memset(p, 0, sizeof(*p));
	mutex_init(&p->lock); // 初始化`seq_file`结构的锁
	p->op = op; // 将输入参数`op`赋值给`seq_file`结构的`op`成员
	
    // ... 
    
	return 0;
}

struct mm_struct *proc_mem_open(struct inode *inode, unsigned int mode)
{
	// 调用`get_proc_task`函数获取`inode`对应的进程的任务结构
	struct task_struct *task = get_proc_task(inode);
	struct mm_struct *mm = ERR_PTR(-ESRCH);
	
    // ... 
    
	return mm;
}

pid_smaps_open 函数通过参数 inode 找到进程相关的结构并放到 file 的私有数据结构。

read 时,调用 seq_read() 函数,它是内核的一个通用架构的函数,特定的 proc 文件(如:smaps)需要提供自己特有的操作方法供通用的 seq_read() 调用。smaps 即是 pid_smaps_open() 函数的 file_operations 参数 &proc_pid_smaps_op,专门为读取进程虚拟内存区(vma)信息的方法。

/**
 *	seq_read -	->read() method for sequential files.
 *	@file: the file to read from
 *	@buf: the buffer to read to
 *	@size: the maximum number of bytes to read
 *	@ppos: the current position in the file
 *
 *	Ready-made ->f_op->read()
 */
ssize_t seq_read(struct file *file, char __user *buf, size_t size, loff_t *ppos)
{
	struct seq_file *m = file->private_data;
	size_t copied = 0;
	loff_t pos;
	size_t n;
	void *p;
	int err = 0;

	mutex_lock(&m->lock); // 锁定`seq_file`结构,以确保线程安全

	/*
	 * seq_file->op->..m_start/m_stop/m_next may do special actions
	 * or optimisations based on the file->f_version, so we want to
	 * pass the file->f_version to those methods.
	 *
	 * seq_file->version is just copy of f_version, and seq_file
	 * methods can treat it simply as file version.
	 * It is copied in first and copied out after all operations.
	 * It is convenient to have it as  part of structure to avoid the
	 * need of passing another argument to all the seq_file methods.
	 */
	m->version = file->f_version;

	/* Don't assume *ppos is where we left it */
	if (unlikely(*ppos != m->read_pos)) {
		while ((err = traverse(m, *ppos)) == -EAGAIN)
			;
		if (err) {
			/* With prejudice... */
			m->read_pos = 0;
			m->version = 0;
			m->index = 0;
			m->count = 0;
			goto Done;
		} else {
			m->read_pos = *ppos;
		}
	}

	/* grab buffer if we didn't have one */
	// 如果`seq_file`结构没有缓冲区,需要分配一个
	if (!m->buf) {
		m->buf = seq_buf_alloc(m->size = PAGE_SIZE);
		if (!m->buf)
			goto Enomem;
	}
	/* if not empty - flush it first */
	// 如果`seq_file`结构的缓冲区不为空,需要先将其内容复制到用户空间
	if (m->count) {
		n = min(m->count, size);
		err = copy_to_user(buf, m->buf + m->from, n);
		if (err)
			goto Efault;
		m->count -= n;
		m->from += n;
		size -= n;
		buf += n;
		copied += n;
		if (!m->count)
			m->index++;
		if (!size)
			goto Done;
	}
	/* we need at least one record in buffer */
	pos = m->index;
	p = m->op->start(m, &pos);
	// 从序列文件中读取记录,直到出错或缓冲区满
	while (1) {
		err = PTR_ERR(p);
		if (!p || IS_ERR(p))
			break;
		err = m->op->show(m, p);
		if (err < 0)
			break;
		if (unlikely(err))
			m->count = 0;
		if (unlikely(!m->count)) {
			p = m->op->next(m, p, &pos);
			m->index = pos;
			continue;
		}
		if (m->count < m->size)
			goto Fill;
		m->op->stop(m, p);
		kvfree(m->buf);
		m->count = 0;
		m->buf = seq_buf_alloc(m->size <<= 1);
		if (!m->buf)
			goto Enomem;
		m->version = 0;
		pos = m->index;
		p = m->op->start(m, &pos);
	}
	m->op->stop(m, p);
	m->count = 0;
	goto Done;
Fill:
	/* they want more? let's try to get some more */
	// 尝试获取更多的记录,直到出错、缓冲区溢出或缓冲区满
	while (m->count < size) {
		size_t offs = m->count;
		loff_t next = pos;
		p = m->op->next(m, p, &next);
		if (!p || IS_ERR(p)) {
			err = PTR_ERR(p);
			break;
		}
		err = m->op->show(m, p);
		if (seq_has_overflowed(m) || err) {
			m->count = offs;
			if (likely(err <= 0))
				break;
		}
		pos = next;
	}
	m->op->stop(m, p);
	n = min(m->count, size);
	err = copy_to_user(buf, m->buf, n);
	if (err)
		goto Efault;
	copied += n;
	m->count -= n;
	if (m->count)
		m->from = n;
	else
		pos++;
	m->index = pos;
Done:
	if (!copied)
		copied = err;
	else {
		*ppos += copied;
		m->read_pos += copied;
	}
	file->f_version = m->version;
	mutex_unlock(&m->lock); // 解锁`seq_file`结构
	return copied;
Enomem:
	err = -ENOMEM;
	goto Done;
Efault:
	err = -EFAULT;
	goto Done;
}

seq_read() 函数的参数:文件对应的内核数据结构 file,用户态 buf 用于存放读取到的信息,size 和ppos 分别是大小和偏移。通用的 seq_read() 函数要将进程的 vma 信息读取给用户的 buf

在开始读取时,m_start 会调用 mmap_read_lock_killable 给整个 mm 结构体加锁;在读取结束时, m_stop 会调用 mmap_read_unlock 解锁。通过 m_nextshow_smap 每次读取一个 VMA,最终完成所有所有区域的打印。

// linux/fs/proc/task_mmu.c

static void *m_start(struct seq_file *m, loff_t *ppos)
{
	// 获取`seq_file`结构的私有数据,并将其转换为`proc_maps_private`结构的指针
	struct proc_maps_private *priv = m->private;
	unsigned long last_addr = *ppos;
	struct mm_struct *mm;

	/* See m_next(). Zero at the start or after lseek. */
	if (last_addr == -1UL)
		return NULL;

	// 调用`get_proc_task`函数来获取`inode`对应的进程的任务结构
	priv->task = get_proc_task(priv->inode);
	if (!priv->task)
		return ERR_PTR(-ESRCH);

	mm = priv->mm;
	if (!mm || !mmget_not_zero(mm)) {
		put_task_struct(priv->task);
		priv->task = NULL;
		return NULL;
	}
	
	// 尝试获取内存描述符的读锁。如果无法获取,函数释放内存描述符和任务结构并返回错误指针
	if (mmap_read_lock_killable(mm)) {
		mmput(mm);
		put_task_struct(priv->task);
		priv->task = NULL;
		return ERR_PTR(-EINTR);
	}
	
	// 初始化虚拟内存区域的迭代器
	vma_iter_init(&priv->iter, mm, last_addr);
	hold_task_mempolicy(priv); // 获取任务的内存策略
	if (last_addr == -2UL)
		return get_gate_vma(mm);
		
	// 获取虚拟内存区域
	return proc_get_vma(priv, ppos);
}

static void *m_next(struct seq_file *m, void *v, loff_t *ppos)
{
	if (*ppos == -2UL) {
		*ppos = -1UL;
		return NULL;
	}
	return proc_get_vma(m->private, ppos);
}

static void m_stop(struct seq_file *m, void *v)
{
	struct proc_maps_private *priv = m->private;
	struct mm_struct *mm = priv->mm;

	if (!priv->task)
		return;

	release_task_mempolicy(priv); // 释放任务的内存策略
	mmap_read_unlock(mm); // 解锁内存描述符的读锁
	mmput(mm); // 减少内存描述符的引用计数,如果引用计数为零,释放内存描述符
	put_task_struct(priv->task); // 减少任务结构的引用计数,如果引用计数为零,释放任务结构
	priv->task = NULL;
}


static int show_smap(struct seq_file *m, void *v)
{
	struct vm_area_struct *vma = v;
	struct mem_size_stats mss;

	memset(&mss, 0, sizeof(mss));

	smap_gather_stats(vma, &mss, 0);

	show_map_vma(m, vma);

	SEQ_PUT_DEC("Size:           ", vma->vm_end - vma->vm_start);
	SEQ_PUT_DEC(" kB\nKernelPageSize: ", vma_kernel_pagesize(vma));
	SEQ_PUT_DEC(" kB\nMMUPageSize:    ", vma_mmu_pagesize(vma));
	seq_puts(m, " kB\n");

	__show_smap(m, &mss, false);

	seq_printf(m, "THPeligible:    %8u\n",
		   hugepage_vma_check(vma, vma->vm_flags, true, false, true));

	if (arch_pkeys_enabled())
		seq_printf(m, "ProtectionKey:  %8u\n", vma_pkey(vma));
	show_smap_vma_flags(m, vma);

	return 0;
}

/* Show the contents common for smaps and smaps_rollup */
static void __show_smap(struct seq_file *m, const struct mem_size_stats *mss,
	bool rollup_mode)
{
	SEQ_PUT_DEC("Rss:            ", mss->resident);
	SEQ_PUT_DEC(" kB\nPss:            ", mss->pss >> PSS_SHIFT);
	SEQ_PUT_DEC(" kB\nPss_Dirty:      ", mss->pss_dirty >> PSS_SHIFT);
	if (rollup_mode) {
		/*
		 * These are meaningful only for smaps_rollup, otherwise two of
		 * them are zero, and the other one is the same as Pss.
		 */
		SEQ_PUT_DEC(" kB\nPss_Anon:       ",
			mss->pss_anon >> PSS_SHIFT);
		SEQ_PUT_DEC(" kB\nPss_File:       ",
			mss->pss_file >> PSS_SHIFT);
		SEQ_PUT_DEC(" kB\nPss_Shmem:      ",
			mss->pss_shmem >> PSS_SHIFT);
	}
	SEQ_PUT_DEC(" kB\nShared_Clean:   ", mss->shared_clean);
	SEQ_PUT_DEC(" kB\nShared_Dirty:   ", mss->shared_dirty);
	SEQ_PUT_DEC(" kB\nPrivate_Clean:  ", mss->private_clean);
	SEQ_PUT_DEC(" kB\nPrivate_Dirty:  ", mss->private_dirty);
	SEQ_PUT_DEC(" kB\nReferenced:     ", mss->referenced);
	SEQ_PUT_DEC(" kB\nAnonymous:      ", mss->anonymous);
	SEQ_PUT_DEC(" kB\nKSM:            ", mss->ksm);
	SEQ_PUT_DEC(" kB\nLazyFree:       ", mss->lazyfree);
	SEQ_PUT_DEC(" kB\nAnonHugePages:  ", mss->anonymous_thp);
	SEQ_PUT_DEC(" kB\nShmemPmdMapped: ", mss->shmem_thp);
	SEQ_PUT_DEC(" kB\nFilePmdMapped:  ", mss->file_thp);
	SEQ_PUT_DEC(" kB\nShared_Hugetlb: ", mss->shared_hugetlb);
	seq_put_decimal_ull_width(m, " kB\nPrivate_Hugetlb: ",
				  mss->private_hugetlb >> 10, 7);
	SEQ_PUT_DEC(" kB\nSwap:           ", mss->swap);
	SEQ_PUT_DEC(" kB\nSwapPss:        ",
					mss->swap_pss >> PSS_SHIFT);
	SEQ_PUT_DEC(" kB\nLocked:         ",
					mss->pss_locked >> PSS_SHIFT);
	seq_puts(m, " kB\n");
}

static struct vm_area_struct *proc_get_vma(struct proc_maps_private *priv,
						loff_t *ppos)
{
	struct vm_area_struct *vma = vma_next(&priv->iter);

	if (vma) {
		*ppos = vma->vm_start;
	} else {
		*ppos = -2UL;
		vma = get_gate_vma(priv->mm);
	}

	return vma;
}


// linux/include/linux/mmap_lock.h
static inline int mmap_read_lock_killable(struct mm_struct *mm)
{
	int ret;

	__mmap_lock_trace_start_locking(mm, false);
	ret = down_read_killable(&mm->mmap_lock);
	__mmap_lock_trace_acquire_returned(mm, false, ret == 0);
	return ret;
}

static inline void mmap_read_unlock(struct mm_struct *mm)
{
	__mmap_lock_trace_released(mm, false);
	up_read(&mm->mmap_lock);
}

smaps 读取的重点在于:

  • mmap_lock 锁粒度: 该锁的粒度很大,当进程发生 vma 操作都需要持有该锁,如内存分配和释放。
  • 遍历 VMA 耗时:如果进程的内存比较大,就会长时间持有该锁,影响进程的内存管理。

smaps_rollup

有时只是想获取一下进程的 PSS 占用,是不是可以省去遍历 VMA 的部分呢? google 的优化是增加 /proc/pid/smaps_rollup,据 Patch 描述性能改善了 12 倍,节省几百毫秒。

By using smaps_rollup instead of smaps, a caller can avoid the
significant overhead of formatting, reading, and parsing each of a
large process’s potentially very numerous memory mappings. For
sampling system_server’s PSS in Android, we measured a 12x speedup,
representing a savings of several hundred milliseconds.

smaps_rollup 的具体实现如下,可以看到持锁的粒度和时长都大大降低,当有写入请求等待锁时,还会临时释放锁。

static int show_smaps_rollup(struct seq_file *m, void *v)
{
	// 获取`seq_file`结构的私有数据,并将其转换为`proc_maps_private`结构的指针
	struct proc_maps_private *priv = m->private;
	struct mem_size_stats mss = {};
	struct mm_struct *mm = priv->mm;
	struct vm_area_struct *vma;
	unsigned long vma_start = 0, last_vma_end = 0;
	int ret = 0;
	VMA_ITERATOR(vmi, mm, 0);
	// 调用`get_proc_task`函数来获取`inode`对应的进程的任务结构
	priv->task = get_proc_task(priv->inode);
	if (!priv->task)
		return -ESRCH;
	if (!mm || !mmget_not_zero(mm)) {
		ret = -ESRCH;
		goto out_put_task;
	}
	// 尝试获取内存描述符的读锁。如果无法获取,函数返回错误码
	ret = mmap_read_lock_killable(mm);
	if (ret)
		goto out_put_mm;
	hold_task_mempolicy(priv); // 获取任务的内存策略
	vma = vma_next(&vmi); // 获取下一个虚拟内存区域
	if (unlikely(!vma))
		goto empty_set;
	vma_start = vma->vm_start;
	// 遍历所有的虚拟内存区域,并收集统计信息
	do {
		// 调用`smap_gather_stats`函数来收集当前VMA的统计信息
		smap_gather_stats(vma, &mss, 0);
		last_vma_end = vma->vm_end;
		/*
		 * Release mmap_lock temporarily if someone wants to
		 * access it for write request.
		 */
		 // 如果内存映射的锁存在争用,需要暂时释放锁以允许其他线程进行写操作
		if (mmap_lock_is_contended(mm)) {
			vma_iter_invalidate(&vmi);
			mmap_read_unlock(mm);
			ret = mmap_read_lock_killable(mm);
			if (ret) {
				release_task_mempolicy(priv);
				goto out_put_mm;
			}
			/*
			 * After dropping the lock, there are four cases to
			 * consider. See the following example for explanation.
			 *
			 *   +------+------+-----------+
			 *   | VMA1 | VMA2 | VMA3      |
			 *   +------+------+-----------+
			 *   |      |      |           |
			 *  4k     8k     16k         400k
			 *
			 * Suppose we drop the lock after reading VMA2 due to
			 * contention, then we get:
			 *
			 *	last_vma_end = 16k
			 *
			 * 1) VMA2 is freed, but VMA3 exists:
			 *
			 *    vma_next(vmi) will return VMA3.
			 *    In this case, just continue from VMA3.
			 *
			 * 2) VMA2 still exists:
			 *
			 *    vma_next(vmi) will return VMA3.
			 *    In this case, just continue from VMA3.
			 *
			 * 3) No more VMAs can be found:
			 *
			 *    vma_next(vmi) will return NULL.
			 *    No more things to do, just break.
			 *
			 * 4) (last_vma_end - 1) is the middle of a vma (VMA'):
			 *
			 *    vma_next(vmi) will return VMA' whose range
			 *    contains last_vma_end.
			 *    Iterate VMA' from last_vma_end.
			 */
			vma = vma_next(&vmi); // 获取下一个VMA
			/* Case 3 above */
			if (!vma) // 如果没有更多的VMA,跳出循环
				break;
			/* Case 1 and 2 above */
			if (vma->vm_start >= last_vma_end) // 如果下一个 VMA 的开始地址大于或等于上一个 VMA 的结束地址,跳过当前迭代
				continue;
			/* Case 4 above */
			if (vma->vm_end > last_vma_end) // 如果下一个 VMA 的结束地址大于上一个 VMA 的结束地址,从上一个 VMA 的结束地址开始收集下一个 VMA 的统计信息
				smap_gather_stats(vma, &mss, last_vma_end);
		}
	} for_each_vma(vmi, vma);
empty_set:
	// 显示虚拟内存区域的头部前缀
	show_vma_header_prefix(m, vma_start, last_vma_end, 0, 0, 0, 0);
	seq_pad(m, ' ');
	seq_puts(m, "[rollup]\n");
	// 显示内存映射的统计信息
	__show_smap(m, &mss, true);
	release_task_mempolicy(priv); // 释放任务的内存策略
	mmap_read_unlock(mm); // 解锁内存描述符的读锁
out_put_mm:
	// 减少内存描述符的引用计数,如果引用计数为零,释放内存描述符
	mmput(mm); 
out_put_task:
	// 减少任务结构的引用计数,如果引用计数为零,释放任务结构
	put_task_struct(priv->task);
	priv->task = NULL;
	return ret;
}

定位策略/工具

正如前面提到,整个故障定位过程耗时较长,定位方式也不具备普适性。针对延迟毛刺性问题,是否有什么普适的定位方法呢?

首先,定位非必现的问题,首要条件就是获取问题发生的现场快照,获取更多的问题细节。针对非必现的问题最好的方式,就是在可能出现问题的现场部署合适的脚本获取现场快照。

其次,最重要的是定位工具。本问题之所以定位耗时较长,是因为没有使用合适的工具缩小故障的范围。就进程的调用耗时而言,由两部分耗时组成:用户空间内核空间

用户空间耗时

由于在线的 Redis 版本缺少 P99 指标,可以使用 funcslower(bcc) 可以定位或排除 Redis 执行毛刺,将范围缩小到网络或者单机问题。

$> funcslower -UK -u 5000 -p 324568 '/var/lib/docker/overlay2/69e6c3d262a1aed8db1a8b16ddfc34c7c78999f527e028857dc2e5248ae5704a/merged/usr/local/bin/redis-server:processCommand'

内核空间耗时

使用系统调用性能测试工具,通过查看系统调用的长尾延迟,可以确定系统层面是否存在问题。满足要求的工具可能有:

syscount(bcc)

syscount 并不能直接查看 outliner,但可以通过对比不同时间区间的延迟变化发现问题。使用它在问题现场,抓取到延迟前后 mmap 系统调用前后变化,问题出现前耗时为 11 us,问题发生时耗时为 177 ms,如下所示:

# ebpf 抓取故障前后 mmap 耗时
$> syscount -L -i 30  -p $PID
[21:39:27]
SYSCALL                   COUNT        TIME (us)
epoll_pwait               24952      4322184.374
write                     34458       331600.262
read                      26400        59001.053
open                         50          527.602
epoll_ctl                    70           93.506
getpid                       50           39.793
close                        50           35.262
munmap                        1           26.372
getpeername                  12           15.252
mmap                          1           11.003

[21:40:14]
SYSCALL                   COUNT        TIME (us)
epoll_pwait               24371      4189948.513
write                     34110       296551.821
mmap                          1       177477.938
read                      25878        57099.880
open                         48          504.271
epoll_ctl                    68          104.834
getpid                       49           45.939
close                        49           37.919
getpeername                   8           13.127
accept                        2            7.896

perf trace

另外一个更好用的工具是 perf trace,相较于 syscount 提供了 histogram 图,可以直观的发现长尾问题,使用示例如下所示(非问题现场):

# perf trace 示例
$> perf trace -p $PID -s

   syscall            calls    total       min       avg       max      stddev
                               (msec)    (msec)    (msec)    (msec)        (%)
   --------------- -------- --------- --------- --------- ---------     ------
   epoll_pwait        53841 14561.545     0.000     0.270     4.538      0.53%
   write              56177   757.799     0.005     0.013     0.047      0.09%
   read               55591   219.250     0.001     0.004     0.702      0.67%
   open                 170     2.468     0.012     0.015     0.043      1.69%
   getpid               171     1.668     0.002     0.010     1.069     63.91%
   mmap                  76     0.795     0.007     0.010     0.018      2.14%
   munmap                77     0.643     0.003     0.008     0.030      7.91%
   epoll_ctl            151     0.533     0.001     0.004     0.014      4.26%
   close                173     0.291     0.001     0.002     0.012      3.87%
   getpeername           24     0.064     0.002     0.003     0.004      4.76%
   accept                 8     0.045     0.003     0.006     0.011     18.34%
   setsockopt            20     0.040     0.001     0.002     0.003      5.50%
   fcntl                 16     0.029     0.001     0.002     0.006     15.83%
   getrusage              3     0.008     0.001     0.003     0.006     48.77%
   getcwd                 1     0.006     0.006     0.006     0.006      0.00%

定位到 mmap 耗时异常之后,其实相关工作就可以交给内核同事处理了,毕竟术业有专攻。要想查看慢在哪里,可以通过 func_graph 工具定位到耗时异常的函数

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |

 0)               |  sys_open() {
 0)               |    do_sys_open() {
 0)               |      getname() {
 0)               |        kmem_cache_alloc() {
 0)   1.382 us    |          __might_sleep();
 0)   2.478 us    |        }
 0)               |        strncpy_from_user() {
 0)               |          might_fault() {
 0)   1.389 us    |            __might_sleep();
 0)   2.553 us    |          }
 0)   3.807 us    |        }
 0)   7.876 us    |      }
 0)               |      alloc_fd() {
 0)   0.668 us    |        _spin_lock();
 0)   0.570 us    |        expand_files();
 0)   0.586 us    |        _spin_unlock();

针对于 mmap_lock 的锁占用,要想排查持有该锁的进程列表。在内核高版本中封装了 mmap_lock 相关函数,并在其中增加了 tracepoint,可以使用 bpftrace 等工具统计持有写锁的进程、调用栈等

$> perf list |grep mmap
  mmap:vm_unmapped_area                              [Tracepoint event]
  mmap_lock:mmap_lock_acquire_returned               [Tracepoint event]
  mmap_lock:mmap_lock_released                       [Tracepoint event]
  mmap_lock:mmap_lock_start_locking                  [Tracepoint event]
  syscalls:sys_enter_mmap                            [Tracepoint event]
  syscalls:sys_exit_mmap                             [Tracepoint event]

$> bpftrace -e 'tracepoint:mmap_lock:mmap_lock_start_locking /args->write == true/{ @[comm, kstack] = count();}'

相关 perf 命令来自 字节跳动SYSTech 分享,遗憾的是由于发生问题的内核版本较旧,并未实操相关该定位过程。

当然,从 持锁这个更宽泛的观测纬度来看,可以找出有相关动作的进程,如下所示:

$> trace 'rwsem_down_read_slowpath(struct rw_semaphore *sem, int state) "count=0x%lx owner=%s", sem->count.counter, ((struct task_struct *)((sem->owner.counter)&~0x7))->comm'
/virtual/main.c:44:66: warning: comparison of array '((struct task_struct *)((sem->owner.counter) & ~7))->comm' not equal to a null pointer is always true [-Wtautological-pointer-compare]
        if (((struct task_struct *)((sem->owner.counter)&~0x7))->comm != 0) {
            ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~~    ~
1 warning generated.
PID     TID     COMM            FUNC             -
195453  195458  monitor         rwsem_down_read_slowpath count=0x100 owner=
195453  195458  monitor         rwsem_down_read_slowpath count=0x101 owner=ip
195453  195756  monitor         rwsem_down_read_slowpath count=0x101 owner=sh
195453  195458  monitor         rwsem_down_read_slowpath count=0x101 owner=python
195453  195458  monitor         rwsem_down_read_slowpath count=0x101 owner=python
195453  195458  monitor         rwsem_down_read_slowpath count=0x101 owner=python
212360  212360  runc            rwsem_down_read_slowpath count=0x100 owner=
212360  212360  runc            rwsem_down_read_slowpath count=0x101 owner=runc
...

然而,加锁解锁耗时跟持锁耗时是两个完全不同的概念,因此并不能直接定位到持锁耗时较长的进程,所以仍需额外的工作进一步排查。

总结

下次遇到同步调用场景下的延迟毛刺,就可以选择合适的工具根据函数执行耗时快速定位。然而采用 streaming 模式的异步请求/响应的延迟问题,仍然需要再深入学习探索。

本文作者 : cyningsun
本文地址https://www.cyningsun.com/12-22-2023/redis-latency-spike.html
版权声明 :本博客所有文章除特别声明外,均采用 CC BY-NC-ND 3.0 CN 许可协议。转载请注明出处!

# Performance