ykrocku

Less is more.

Unwind_frame函数导致内核内存访问错误

环境

  • 内核版本: 3.0.8
  • CPU信息:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
# cat /proc/cpuinfo 
Processor       : ARMv7 Processor rev 0 (v7l)
processor       : 0
BogoMIPS        : 1849.75

processor       : 1
BogoMIPS        : 1856.30

Features        : swp half thumb fastmult vfp edsp vfpv3 vfpv3d16 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x3
CPU part        : 0xc09
CPU revision    : 0

问题

2013年8月份的时候,在一些板子(海思3531平台)上面出现了一些奇怪的问题,查看dmesg都出现了如下打印:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
[283986.090810] Unable to handle kernel paging request at virtual address fffffff3
[283986.090844] pgd = 848b0000
[283986.090855] [fffffff3] *pgd=8cdfe821, *pte=00000000, *ppte=00000000
[283986.090878] Internal error: Oops: 17 [#1] SMP
[283986.090891] Modules linked in: option usb_wwan usbserial hi_ir 8192cu nvp1918 buzzer led regpro debugs_drv ds3231 0104 msdos vfat fat configfs raid1 md_mod sg sr_mod
m ahci_sys libahci sd_mod libata scsi_wait_scan scsi_mod hi3531_adec(P) hi3531_aenc(P) hi3531_ao(P) hi3531_ai(P) hi3531_sio(P) hidmac jpeg hi3531_hdmi(P) hi3531_vfmw(P) h
_vda(P) hi3531_ive(P) hi3531_region(P) hi3531_vpss(P) hi3531_vou(P) hi3531_viu(P) hi3531_mpeg4e(P) hi3531_jpege(P) hi3531_rc(P) hi3531_h264e(P) hi3531_chnl(P) hi3531_grou
(P) hi3531_tde hi3531_sys hi3531_base(P) mmz pca955_driver i2c_module stmmac
[283986.091116] CPU: 0    Tainted: P             (3.0.8 #1)
[283986.091148] PC is at unwind_frame+0x48/0x68
[283986.091163] LR is at get_wchan+0x8c/0x298
[283986.091178] pc : [<8003d120>]    lr : [<8003a660>]    psr: a0000013
[283986.091183] sp : 824dbcc8  ip : 00000003  fp : 824dbcd4
[283986.091204] r10: 00000001  r9 : 00000000  r8 : 80493c34
[283986.091219] r7 : 00000000  r6 : 00000000  r5 : 8b64df40  r4 : 824dbcd8
[283986.091235] r3 : 824dbcd8  r2 : ffffffff  r1 : 80490000  r0 : 8049003f
[283986.091252] Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
[283986.091271] Control: 10c53c7d  Table: 848b004a  DAC: 00000015
[283986.091285]
----cuted----
[283986.094045] Process pidof (pid: 18711, stack limit = 0x824da2f0)
[283986.09[283986.094663] 
----cuted----
Backtrace:
[283986.094685] [<8003d0d8>] (unwind_frame+0x0/0x68) from [<8003a660>] (get_wchan+0x8c/0x298)
[283986.094714] [<8003a5d4>] (get_wchan+0x0/0x298) from [<8011f700>] (do_task_stat+0x548/0x5ec)
[283986.094733]  r4:00000000
[283986.094750] [<8011f1b8>] (do_task_stat+0x0/0x5ec) from [<8011f7c0>] (proc_tgid_stat+0x1c/0x24)
[283986.094787] [<8011f7a4>] (proc_tgid_stat+0x0/0x24) from [<8011b7f0>] (proc_single_show+0x54/0x98)
[283986.094823] [<8011b79c>] (proc_single_show+0x0/0x98) from [<800e9024>] (seq_read+0x1b4/0x4e4)
[283986.094842]  r8:824dbf08 r7:824dbf70 r6:00000001 r5:8673bbe0 r4:86c88120
[283986.094864] r3:00000000
[283986.094888] [<800e8e70>] (seq_read+0x0/0x4e4) from [<800c8c54>] (vfs_read+0xb4/0x19c)
[283986.094913] [<800c8ba0>] (vfs_read+0x0/0x19c) from [<800c8e18>] (sys_read+0x44/0x74)
[283986.094931]  r8:00000000 r7:00000003 r6:000003ff r5:7ebe3818 r4:8673bbe0
[283986.094963] [<800c8dd4>] (sys_read+0x0/0x74) from [<800393c0>] (ret_fast_syscall+0x0/0x30)
[283986.094982]  r9:824da000 r8:80039568 r6:7ebe3c8f r5:0000000e r4:7ebe3818
[283986.095011] Code: e3c10d7f e3c0103f e151000c 9afffff6 (e512100c)
[283986.095094] ---[ end trace bc07a2a11408a6af ]---

分析

针对上面的dmesg信息进行分析后,得出了如下结论:

  1. 导致出错的当前(current)进程是pidof
  2. pidof程序的原理就是:遍历所有进程的stat(/proc/PID/stat)文件,找出和参数一样的进程ID(pid)。
  3. /proc/PID/stat文件的内容是由do_task_stat(见fs/proc/array.c)函数生成
  4. do_task_stat会调用get_wchan(见arch/arm/kernel/process.c),来获取进程的Waiting Channnel
  5. get_wchan函数使用unwind_frame(见arch/arm/kernel/stacktrace.c)函数回溯进程的栈指针(fp/sp),试图获取进程最后一个非调度函数的函数调用
  6. unwind_frame却导致了一个内核paging错误

根据上面的初步分析,结合我们自己的应用程序,推测造成这个问题的应用层场景如下: 1. 有两个进程p1/busy_worker 2. busy_worker有30多个线程 3. p1不停执行system(pidof(“busy_worker”))

根据内核打印出来的PC/LR寄存器,可以知道,是unwind_frame函数中出现的内存访问错误:

1
[734212.113523] PC is at unwind_frame+0x48/0x68

反汇编内核代码(#号开头的行, 是c语言注释)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
8003d0d8 <unwind_frame>:
8003d0d8:       e1a0c00d        mov     ip, sp
8003d0dc:       e92dd800        push    {fp, ip, lr, pc}
8003d0e0:       e24cb004        sub     fp, ip, #4

#r1 = frame->sp
#low = frame->sp;
8003d0e4:       e5901004        ldr     r1, [r0, #4]

#r3 = r0 = frame
8003d0e8:       e1a03000        mov     r3, r0

#r2 = unsigned long fp = frame->fp;
8003d0ec:       e5902000        ldr     r2, [r0]

#r0 = low + 12
8003d0f0:       e281000c        add     r0, r1, #12

#if (fp < low+12)
8003d0f4:       e1520000        cmp     r2, r0
8003d0f8:       2a000001        bcs     8003d104 <unwind_frame+0x2c>
8003d0fc:       e3e00015        mvn     r0, #21
8003d100:       e89da800        ldm     sp, {fp, sp, pc}
8003d104:       e2810d7f        add     r0, r1, #8128   ; 0x1fc0
8003d108:       e282c004        add     ip, r2, #4
8003d10c:       e280103f        add     r1, r0, #63     ; 0x3f
8003d110:       e3c10d7f        bic     r0, r1, #8128   ; 0x1fc0
8003d114:       e3c0103f        bic     r1, r0, #63     ; 0x3f
8003d118:       e151000c        cmp     r1, ip
8003d11c:       9afffff6        bls     8003d0fc <unwind_frame+0x24>

#r1 = *(r2-12)
#r1 = *(fp-12)
8003d120:       e512100c        ldr     r1, [r2, #-12]

8003d124:       e3a00000        mov     r0, #0

#frame->fp = *(unsigned long *)(fp - 12);
8003d128:       e5831000        str     r1, [r3]

8003d12c:       e512c008        ldr     ip, [r2, #-8]
8003d130:       e583c004        str     ip, [r3, #4]
8003d134:       e5122004        ldr     r2, [r2, #-4]
8003d138:       e583200c        str     r2, [r3, #12]
8003d13c:       e89da800        ldm     sp, {fp, sp, pc}

反汇编结合内核源代码, 可知出错的时候执行到下面的语句:

1
2
/* restore the registers from the stack frame */
frame->fp = *(unsigned long *)(fp - 12);

出错时候的平台寄存器如下:

1
2
3
4
5
[734212.113557] pc : [<8003d120>]    lr : [<8003a660>]    psr: a0000013
[734212.113561] sp : 845d1cc8  ip : 00000003  fp : 845d1cd4
[734212.113583] r10: 00000001  r9 : 00000000  r8 : 80493c34
[734212.113597] r7 : 00000000  r6 : 00000000  r5 : 83354960  r4 : 845d1cd8
[734212.113613] r3 : 845d1cd8  r2 : ffffffff  r1 : 80490000  r0 : 8049003f

在出现的内存访问错误之前, fp寄存器值已经保存在寄存器r2中了, 对应的值是ffffffff。 也就是说, 传递给unwind_frame函数的stackframe->fp = 0xffffffff。 出现问题的情况下应用层的用法都是没有问题的,所以这应该是一个内核BUG。 虽然是很清楚导致此内核Bug的原因,但是相关内核函数都没有处理竞争情况,当时就怀疑这个BUG应该和抢占有关系。 由于不太确定,就去Stack Overflow上面问了个问题: unwind_frame cause a kernel paging error,不过也一直没有任何有价值的回复。

巧合

时隔3个月的后,又想起了这个问题,于是去kernel git上搜索了一番,发现2013年后针对unwind_frame函数的修改挺多。 其中Konstantin Khlebnikov提交的一个patch就解决了这个内核Bug。 更巧的是:修改日志中引用了我在Stack Overflow上提的问题。

Root cause

Konstantin Khlebnikov在修改日志中写道:

get_wchan() is lockless. Task may wakeup at any time and change its own stack, thus each next stack frame may be overwritten and filled with random stuff. /proc/$pid/stack interface had been disabled for non-current tasks, see [1] But ‘wchan’ still allows to trigger stack frame unwinding on volatile stack. This patch fixes oops in unwind_frame() by adding stack pointer validation on each step (as x86 code do), unwind_frame() already checks frame pointer.

大意就是: get_wchan()是没有加锁的,而进程可以在任何时候执行并修改自己的栈,所以进程的栈可能会被修改并填充随机的值。

假设我们的pidof进程PID为100,记做pidof(100),busy_worker进程PID为99,记做busy_worker(99), 我们碰到的问题就是: * pidof(100)通过读/proc/99/stat文件触发了内核去获取busy_worker(99)的Waiting Channnel(get_wchan) * busy_worker(99)执行到获取文件系统信息时候被抢占,此时其调用栈看起来可能是这个样子:

1
2
3
4
5
6
main
    busy_worker_main
        fun1
            fun2
                fun3
                   __kernel_routines_xxxx__
  • get_wchan将busy_worker(99)的fp/sp/lr/pc都保存在stackframe结构体中
1
2
3
4
frame.fp = thread_saved_fp(p);
frame.sp = thread_saved_sp(p);
frame.lr = 0;          /* recovered from the stack */
frame.pc = thread_saved_pc(p);
  • 由于没有锁,此时busy_worker(99)又开始在CPU上执行(抢占),它可能又去执行其他功能代码,调用栈可能是:
1
2
3
4
5
6
main
    busy_worker_main
        fun5
            fun6
                fun7
                   __kernel_routines_yyyy__
  • 内核调用unwind_frame开始回溯busy_worker_main(99)的栈。 这个时候问题出现了,此时busy_worker_main(99)的栈已经和第2步中完全不一样了,内核再调用下面语句去访问上次记录的栈里面内存,有点类似于访问已经释放了的内存:
1
2
3
frame->fp = *(unsigned long *)(fp - 12);
frame->sp = *(unsigned long *)(fp - 8);
frame->pc = *(unsigned long *)(fp - 4);

这个时候,这块内存保存的可能是某个函数的局部变量、或者被push进来的其他寄存器。 总而言之,访问这块内存会得到一个随机值,而这里恰好是0xffffffff,导致了内核访问错误的内存,从而出现paging error.

参考

深入分析diskstats

背景

内核很多重要子系统均通过proc文件的方式,将自身的一些统计信息输出,方便最终用户查看各子系统的运行状态,这些统计信息被称为metrics。 直接查看metrics并不能获取到有用的信息,一般都是由特定的应用程序(htop/sar/iostat等)每隔一段时间读取相关metrics,并进行相应计算,给出更具用户可读性的输出。 常见的metrics文件有:

  • cpu调度统计信息的/proc/stat
  • cpu负载统计信息的/proc/loadavg

通用块设备层也有一个重要的统计信息

  • /proc/diskstats 内核通过diskstats文件,将通用块设备层的一些重要指标以文件的形式呈现给用户。

因为本文档牵涉到通用块设备层很多细节,建议先了解IO调度器的相关知识。

初探diskstats

首先来看下diskstats里面都有些什么,下面截取的是一个diskstats文件内容:

1
2
3
4
5
6
7
8
9
# cat /proc/diskstats 
   8       0 sda 8567 1560 140762 3460 0 0 0 0 0 2090 3440
   8       1 sda1 8565 1557 140722 3210 0 0 0 0 0 1840 3190
   8      16 sdb 8157 1970 140762 2940 0 0 0 0 0 1710 2890
   8      17 sdb1 8155 1967 140722 2900 0 0 0 0 0 1670 2850
   8      32 sdc 8920 1574 206410 7870 430 0 461 250 0 6820 8120
   8      33 sdc1 8918 1571 206370 7840 430 0 461 250 0 6790 8090
   8      48 sdd 209703 1628 341966 1318450 3109063 331428 943042901 9728000 0 8943570 11015280
   8      49 sdd1 209701 1625 341926 1318200 3109063 331428 943042901 9728000 0 8943320 11015030

虽然如上面提到的,这些数字看上去完全没有规律。不过若想研究内核通用块设备层的统计实现方式,还是得一个一个字段的分析。

简单的说,每一行对应一个块设备,分别有ram0-ram15、loop0-loop7、mtdblock0-mtdblock5,剩下的sdxx就是硬盘和分区了。 这里以sda设备的数据为例,分别列举各字段的意义:

1
8       0 sda 8567 1560 140762 3460 0 0 0 0 0 2090 3440

根据内核文档iostats.txt中描述,各字段意义如下:

Value Quoted 解释
F1 8 major number 此块设备的主设备号
F2 0 minor mumber 此块设备的次设备号
F3 sda device name 此块设备名字
F4 8567 reads completed successfully 成功完成的读请求次数
F5 1560 reads merged 读请求的次数
F6 140762 sectors read 读请求的扇区数总和
F7 3460 time spent reading (ms) 读请求花费的时间总和
F8 0 writes completed 成功完成的写请求次数
F9 0 writes merged 写请求合并的次数
F10 0 sectors written 写请求的扇区数总和
F11 0 time spent writing (ms) 写请求花费的时间总和
F12 0 I/Os currently in progress 次块设备队列中的IO请求数
F13 2090 time spent doing I/Os (ms) 块设备队列非空时间总和
F14 3440 weighted time spent doing I/Os (ms) 块设备队列非空时间加权总和

基本上都是数量、时间的累加值,按照读、写分开统计。

流程图

下图是Linux内核通用块设备层IO请求处理的完整流程,如图例所示,所有的统计相关处理均有用不同颜色标注。 在进行深入分析前,请大致浏览图片,对整个流程有一个大致印象。

实现分析

proc入口

在内核代码中grep “diskstats”即可找到定义在block/genhd.c中的diskstats_show函数。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
while ((hd = disk_part_iter_next(&piter))) {
  cpu = part_stat_lock();
  part_round_stats(cpu, hd);
  part_stat_unlock();
  seq_printf(seqf, "%4d %7d %s %lu %lu %llu "
         "%u %lu %lu %llu %u %u %u %u\n",
         MAJOR(part_devt(hd)), MINOR(part_devt(hd)),
         disk_name(gp, hd->partno, buf),
         part_stat_read(hd, ios[READ]),
         part_stat_read(hd, merges[READ]),
         (unsigned long long)part_stat_read(hd, sectors[READ]),
         jiffies_to_msecs(part_stat_read(hd, ticks[READ])),
         part_stat_read(hd, ios[WRITE]),
         part_stat_read(hd, merges[WRITE]),
         (unsigned long long)part_stat_read(hd, sectors[WRITE]),
         jiffies_to_msecs(part_stat_read(hd, ticks[WRITE])),
         part_in_flight(hd),
         jiffies_to_msecs(part_stat_read(hd, io_ticks)),
         jiffies_to_msecs(part_stat_read(hd, time_in_queue))
      );

此段代码用seq_printf函数将保存在hd_struct结构体内的统计信息组成了diskstats文件。

数据结构

用到的数据结构都定义在<linux/genhd.h>中,主要有disk_stats和hd_struct两个结构体,意义见注释:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
struct disk_stats {
    /*
     *sectors[0] <--> F6 
     *sectors[1] <--> F10
     */
    unsigned long sectors[2];    /* READs and WRITEs */

    /*
     *ios[0] <--> F4 
     *ios[1] <--> F8
     */
    unsigned long ios[2];

    /*
     *merges[0] <--> F5 
     *merges[1] <--> F9
     */
    unsigned long merges[2];

    /*
     *ticks[0] <--> F7 
     *ticks[1] <--> F11
     */
    unsigned long ticks[2];

    /*F13, time spent doing IOs*/
    unsigned long io_ticks;

    /*F14, weighted time spent doing I/Os (ms)  */
    unsigned long time_in_queue;
};

struct hd_struct {
  unsigned long stamp;

    /*F12 I/Os currently in progress*/
  atomic_t in_flight[2];

    /*如果支持SMP则需要使用“每CPU”变量,否则需要加锁*/
#ifdef   CONFIG_SMP
  struct disk_stats __percpu *dkstats;
#else
  struct disk_stats dkstats;
#endif
  atomic_t ref;
  struct rcu_head rcu_head;
};

F7/F11 ticks

见下一节

F4/F8 ios

如流程图所示,在每个IO结束后,都会调用blk_account_io_done函数,来对完成的IO进行统计。 blk_account_io_done统计了 ios(F4/F8)ticks(F7/F11),还处理了in_flight(后续节有分析)。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
static void blk_account_io_done(struct request *req)
{
  /*
     * 不统计Flush请求,见 http://en.wikipedia.org/wiki/Disk_buffer#Cache_flushing
  */
  if (blk_do_io_stat(req) && !(req->cmd_flags & REQ_FLUSH_SEQ)) {
        /*
         * duration是当前时间(IO完成时间)减去此IO的入队时间(见流程图)
         */
      unsigned long duration = jiffies - req->start_time;

        /*从req获取请求类型:R / W*/
      const int rw = rq_data_dir(req);
      struct hd_struct *part;
      int cpu;

      cpu = part_stat_lock();
        /*获取请求对应的partition(part)*/
      part = req->part;
        /*
         * 该partition的ios[rw]加1
         * part_stat_inc定义在<linux/genhd.h>中
         * part_stat_inc这个宏用来处理SMP和非SMP的细节,见上面的结构体定义
         */
      part_stat_inc(cpu, part, ios[rw]);

        /*
         * 将此IO的存活时间加进ticks
         */
      part_stat_add(cpu, part, ticks[rw], duration);

      part_round_stats(cpu, part);

        /*
         *完成了一个IO,也就是in_flight(正在进行)的IO少了一个
         */
      part_dec_in_flight(part, rw);

      hd_struct_put(part);
      part_stat_unlock();
  }
}

F5/F9 merges

内核每执行一次Back Merge或Front Merge,都会调用drive_stat_acct。 其实in_flight也是在这个函数中统计的,new_io参数用来区分是新的IO,如果不是新IO则是在merge的时候调用的:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
static void drive_stat_acct(struct request *rq, int new_io)
{
  struct hd_struct *part;
    /*从req获取请求类型:R / W*/
  int rw = rq_data_dir(rq);
  int cpu;

  if (!blk_do_io_stat(rq))
      return;

  cpu = part_stat_lock();

  if (!new_io) {
      part = rq->part;
        /*
         * 非新IO,merges[rw]加1
         */
      part_stat_inc(cpu, part, merges[rw]);
  } else {
        .....
      part_round_stats(cpu, part);
        /*
         * 新提交了一个IO,也就是in_flight(正在进行)的IO多了一个
         */
      part_inc_in_flight(part, rw);
  }

  part_stat_unlock();
}

F6/F10 sectors

读写扇区总数是在blk_account_io_completion函数中统计的,如流程图中所示,这个函数在每次IO结束后调用:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
static void blk_account_io_completion(struct request *req, unsigned int bytes)
{
    if (blk_do_io_stat(req)) {
        const int rw = rq_data_dir(req);
        struct hd_struct *part;
        int cpu;

        cpu = part_stat_lock();
        part = req->part;
        /*
         *bytes是此IO请求的数据长度,右移9位等同于除以512,即转换成扇区数
         *然后加到sectors[rw]中
         */
        part_stat_add(cpu, part, sectors[rw], bytes >> 9);
        part_stat_unlock();
    }
}

F12 in_flight

in_flight这个统计比较特别,因为其他统计都是计算累加值,而它是记录当前队列中IO请求的个数。统计方法则是:

  • 新IO请求插入队列(被merge的不算)后加1
  • 完成一个IO后减1 实现见上面章节中的blk_account_io_done和drive_stat_acct函数内的注释。

F14 time_in_queue

见下一节。

F13 io_ticks

io_ticks统计块设备请求队列非空的总时间,统计时间点与in_flight相同,统计代码实现在part_round_stats_single函数中:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
static void part_round_stats_single(int cpu, struct hd_struct *part,
                  unsigned long now)
{
  if (now == part->stamp)
      return;
    /*
     *块设备队列非空
     */
  if (part_in_flight(part)) {
        /*
         *统计加权时间 队列中IO请求个数 * 耗费时间
         */
      __part_stat_add(cpu, part, time_in_queue,
              part_in_flight(part) * (now - part->stamp));

        /*
         *统计队列非空时间
         */
      __part_stat_add(cpu, part, io_ticks, (now - part->stamp));
  }
  part->stamp = now;
}

整个代码实现的逻辑比较简单,在新IO请求插入队列(被merge不算),或完成一个IO请求的时候均执行如下操作:

  • 队列为空

    1. 记下时间stamp = t1
  • 队列不为空

    1. io_ticks[rw] += t2-t1
    2. time_in_queue += in_flight * (t2-t1)
    3. 记下时间stamp = t2

下面是一个实际的例子,示例io_ticks和time_in_queue的计算过程:

ID Time Ops in_flight stamp gap io_ticks time_in_queue
0 100.00 新IO请求入队 0 0 —– 0 0
1 100.10 新IO请求入队 1 100.00 0.10 0.10 0.10
3 101.20 完成一个IO请求 2 100.10 0.80 1.20 1.70
4 103.50 完成一个IO请求 1 100.20 1.30 2.50 3.00
5 153.50 新IO请求入队 0 103.50 —– 2.50 3.00
6 154.50 完成一个IO请求 1 153.50 1.00 3.50 4.00

总共时间 54.50s, IO队列非空时间3.50s

Hello World

1
2
3
4
5
int main(int argc, char *argv[])
{
  printf("Hello World!\n");
  return 0;
}