一个奇葩bug的解决

公司做的网络视频监控产品正在做测试,这两天测试人员报告说多台设备出现奇怪的问题,现象如下:
(1)PC端接收不到设备端应用程序采集通过网络发送的图像
(2)PC端可以ping通设备端,telnet可以登录设备,设备ping PC端只能通一个数据包


于是我telnet登录异常设备,通过tftp http ftp上传下载文件到PC,发现都正常。

起初怀疑是设备网卡driver出现问题,但是细想网卡driver处于数据链路层,

上层(不管应用层是哪种协议)传下来的数据包对于driver来说是一样的。tftp ftp http能正常工作,说明网卡driver能正常收发数据, ping应该也能正常工作才对。

仔细看ping返回的结果,发现有一些不一样的地方,如下:

# ping 10.0.14.198
PING 10.0.14.198 (10.0.14.198): 56 data bytes
64 bytes from 10.0.14.198: seq=0 ttl=127 time=0.817 ms
^C
--- 10.0.14.198 ping statistics ---
1 packets transmitted, 1 packets received, 0% packet loss
round-trip min/avg/max = 0.817/0.817/0.817 ms

ping通一个icmp包,之后就没有反应,ctrl+c程序退出显示没有丢包。
从现象上来看,并不是ping出现丢包,而是感觉ping好像在完成一次数据包通讯后阻塞。
想到这里,就不再怀疑是网卡driver的问题,想再找找看系统其他的异常现象。

ps查看系统进程时发现异常设备pid已经到了2万多,并且不再增加,而对比正常设备pid在1万多,pid还在增加。
于是想是不是异常设备的图像采集程序产生进程过多,系统进程数到达最大值,无法创建进程导致这个bug
写一段测试代码如下:

#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#define MAXPROCESS 65535
#define SLEEPTIME 1
void main (int argc , char ** argv)
{
    pid_t pid;
    int count = 0;
    int maxprocess = MAXPROCESS;

    if (argc == 2) {
        maxprocess = atoi(argv[1]);
    }

    for (count = 0; count < maxprocess; count++)
    {
        pid = fork();
        if (pid < 0) {
            perror("fork error");
            exit(1);
        } else if (pid == 0) {
            printf("child %d start\n", count);
            sleep(SLEEPTIME);
            printf("child %d end\n", count);
            exit(0);
        }
        printf("parent:create %d child\n", count);
    }

    for (count = 0; count < MAXPROCESS; count++) {
        wait();
    }
    exit(0);
}

创建指定个数子进程sleep 1s,父进程等待子进程退出后回收资源然后退出。
编译运行,结果如下:

# ./fork_test 1
parent:create 0 child
child 0 start
^C
#
发现程序不退出,根据打印发现是子进程sleep没有退出,咦,这是什么情况。
直接在console下执行sleep命令,发现也是阻塞不退出,只能ctrl+c退出。
这是该bug的另一个现象:sleep阻塞。
查看系统的pid限制,如下:

# cat /proc/sys/kernel/pid_max
32768
观察正常设备pid,发现系统pid在达到32768后会从0-32768中再找已释放的pid使用。
所以也不再怀疑是系统进程数限制,还得再找其他线索。

date查看系统时间与hwclock获取的RTC时间对比,发现系统时间跟RTC时间差距较大,但是kernel启动加载RTCdriver后会同步系统时间和RTC时间,系统时间与RTC时间应该一致呀?
观察找到原因,发现又一个重要bug现象,系统时间走的是准的,晚于RTC时间的原因是,系统时间在某个时间值上往前走180s左右就会回跳回来再往前走,来回循环,导致系统时间晚于RTC时间!

到这里,关于这个bug已经发现4种现象:
(1)PC端接收不到设备端应用程序采集通过网络发送的图像
(2)PC端可以ping通设备端,telnet可以登录设备,设备ping PC端只能通一个数据包
(3)设备端sleep会阻塞

(4)设备端date系统时间走180s回跳


直觉感觉要从date这个现象入手,首先找date命令实现,嵌入式设备文件系统中使用的是busybox,其中有简化的date命令,也可以找glibc库来查看完整版本的date命令。这里不再详述date实现,date最终是调用gettimeofday来获取时间。


gettimeofday调用sys_gettimeofday,是kernel的系统调用,kernel产生软中断,进入内核态,根据系统调用号跳转到sys_gettimeofday,调用do_gettimeofday,如下:
void do_gettimeofday(struct timeval *tv)
{
    struct timespec now;

    getnstimeofday(&now);
    tv->tv_sec = now.tv_sec;
    tv->tv_usec = now.tv_nsec/1000;
}

void getnstimeofday(struct timespec *ts)
{
    unsigned long seq;
    s64 nsecs;

    WARN_ON(timekeeping_suspended);

    do {
        seq = read_seqbegin(&timekeeper.lock);

        *ts = timekeeper.xtime;
        nsecs = timekeeping_get_ns();

        /* If arch requires, add in gettimeoffset() */
        nsecs += arch_gettimeoffset();

    } while (read_seqretry(&timekeeper.lock, seq));

    timespec_add_ns(ts, nsecs);
}

static inline s64 timekeeping_get_ns(void)
{
    cycle_t cycle_now, cycle_delta;
    struct clocksource *clock;

    /* read clocksource: */
    clock = timekeeper.clock;
    cycle_now = clock->read(clock);

    /* calculate the delta since the last update_wall_time: */
    cycle_delta = (cycle_now - clock->cycle_last) & clock->mask;

    /* return delta convert to nanoseconds using ntp adjusted mult. */
    return clocksource_cyc2ns(cycle_delta, timekeeper.mult,
                  timekeeper.shift);
}
do_gettimeofday调用getnstimeofday,最关键的是timerkeeper.xtime,这是kernel的墙上时间,xtime的更新是在kernel下clockevent注册的时钟中断,只要kernel时钟中断正常,xtime时间就会不断被更新。
但是由于kernel一般是1/100s产生一次时钟中断(kernel配置默认为100HZ),当然对于tickless sysytem,时钟中断不固定,但是精度都不够高。
为了提高时钟精度,调用timekeeping_get_ns,使用已注册clocksource提供的read函数,来获取距上次update xtime的时间,来作为xtime的补充时间,提高精度。
kernel下xtime的更新和获取机制有时间还需要仔细研究下,这里先说这些。
kernel下xtime的操作流程如下:

gettimeofday <===获取=== xtime <===更新=== clockevent clocksource


现在date出现时间回跳,是哪一步出了问题呢,从上面这个流程我想到有3种可能:
(1)gettimeofday时获取xtime出错
(2)xtime存储出错
(3)更新xtime出错

如何排除,想到了二分法,如果能够直接获取xtime值,与gettimeofday获取的值对比,就可以确定到底是哪一步出了问题。


首先要说明下xtime,在kernel源码的kernel/time/timekeepering.c中定义了struct timekeepering结构体用来表征kernel下与时间相关内容,其中就有xtime成员,结构体定义如下:

struct timespec {
    __kernel_time_t tv_sec;         /* seconds */
    long        tv_nsec;        /* nanoseconds */
};
tv_sec和tv_nsec表示了从1970-1-1以来的时间。

但是xtime并没有留接口给系统调用等,无法从用户空间来直接获取xtime,并且该bug复现难,需要设备运行很长时间,因此也不能修改kernel后再重新启动。
那怎么办,想到了一个办法:driver module + application。
在timekeeping.c中也找到了kernel下来获取xtime的接口,如下:

unsigned long get_seconds(void)
{
    return timekeeper.xtime.tv_sec;
}
EXPORT_SYMBOL(get_seconds);

于是编写如下模块代码:

#include <linux/mm.h>
#include <linux/miscdevice.h>
#include <linux/slab.h>
#include <linux/vmalloc.h>
#include <linux/mman.h>
#include <linux/random.h>
#include <linux/init.h>
#include <linux/raw.h>
#include <linux/tty.h>
#include <linux/capability.h>
#include <linux/ptrace.h>
#include <linux/device.h>
#include <linux/highmem.h>
#include <linux/crash_dump.h>
#include <linux/backing-dev.h>
#include <linux/bootmem.h>
#include <linux/splice.h>
#include <linux/pfn.h>
#include <linux/export.h>

#include <asm/uaccess.h>
#include <asm/io.h>

#define GET_XTIME 0


static int dev_open(struct inode *inode, struct file *filp)
{
    return 0;
}

static ssize_t dev_read(struct file *file, char __user *buf,
            size_t count, loff_t *ppos)
{
    return 0;
}

static ssize_t dev_write(struct file *file, const char __user *buf,
             size_t count, loff_t *ppos)
{
    return 0;
}

static long dev_ioctl(struct file *file, unsigned int cmd, unsigned long arg)
{
    int __user *argp = (int __user *)arg;
    unsigned long now = 0;

    switch (cmd) {
        case GET_XTIME :
            now = get_seconds();
            if (copy_to_user(argp, &now, 4))
                return -EFAULT;
        break;
        default :
            return -EFAULT;
    }

    return 0;
}

static const struct file_operations dev_fops = {
    .read       = dev_read,
    .write      = dev_write,
    .open       = dev_open,
    .unlocked_ioctl = dev_ioctl,
};

static struct cdev char_dev;
static int major;

static int __init char_dev_init(void)
{
    int rc;
    int err;
    dev_t devid;

    rc = alloc_chrdev_region(&devid, 0, 1, "char_dev");
    if (rc != 0)
    {
        printk("alloc chardev region failed\n");
        return -1;
    }
    major = MAJOR(devid);

    cdev_init(&char_dev, &dev_fops);
    cdev_add(&char_dev, devid, 1);

    return 0;
}

static void __exit char_dev_exit(void)
{
    cdev_del(&char_dev);
    unregister_chrdev_region(MKDEV(major,0), 1);
}

module_init(char_dev_init);
module_exit(char_dev_exit);

编译此模块,insmod插入kernel中,接着编写一个应用程序如下:

#include <stdio.h>
#include <sys/ioctl.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/time.h>
#include <fcntl.h>

#define GET_XTIME 0

void main(void)
{
    unsigned long now = 0;

    struct timeval tv;
    struct timezone tz;

    gettimeofday(&tv, &tz);
    printf("tv.tv_sec = %d\n", tv.tv_sec);
    printf("tv.tv_usec = %d\n", tv.tv_usec);

    int fd = open("/dev/char_dev", O_RDWR);
    if (fd < 0)
    {
        printf("open failed\n");
        return;
    }

    ioctl(fd, GET_XTIME, &now);

    printf("xtime.tv_sec = %d\n", now);

    close(fd);
}
分别将gettimeofday获取的时间和kernel中xtime的时间打印出来。
编译程序,在kernel下运行3次,如下:

# ./dev_tool
tv.tv_sec = 1427286832
tv.tv_usec = 617831
xtime.tv_sec = 1427286754
#
#
# ./dev_tool
tv.tv_sec = 1427286835
tv.tv_usec = 17649
xtime.tv_sec = 1427286754
#
#
# ./dev_tool
tv.tv_sec = 1427286840
tv.tv_usec = 281584
xtime.tv_sec = 1427286754
很明显可以看出,xtime的时间是停止的,那为什么gettimeofday时间还会走呢?
上面分析过gettimeofday实现,为了提高精度,gettimeofday的时间 = xtime + 根据clocksource->read获取的cycles换算出来的补充时间

那就来看下我们设备中注册的clocksource什么样,如下:

static cycle_t
timer_get_cycles( struct clocksource *cs )
{
    return __raw_readl( IO_ADDRESS( REG_TIMER_TMR2DL ));
}

static struct clocksource timer_clocksource =
{
    .name   = MTAG_TIMER,
    .rating = 300,
    .read   = timer_get_cycles,
    .mask   = CLOCKSOURCE_MASK( 32 ),
    .flags  = CLOCK_SOURCE_IS_CONTINUOUS,
};
static u32 notrace
update_sched_clock( void )
{
    return __raw_readl(IO_ADDRESS( REG_TIMER_TMR2DL ));
}

static int __init
timer_clocksource_init( void )
{
    u32 val = 0, mode = 0;

    timer_stop( 2 );
    __raw_writel( 0xffffffff, IO_ADDRESS( REG_TIMER_TMR2TGT ));      // free-running timer as clocksource
    val = __raw_readl( IO_ADDRESS( REG_TIMER_TMRMODE ));
    mode = ( val & ~( 0x0f << TIMER2_MODE_OFFSET )) | TIMER2_CONTINUOUS_MODE;
    __raw_writel( mode, IO_ADDRESS( REG_TIMER_TMRMODE ));
    timer_start( 2 );

    setup_sched_clock( update_sched_clock, 32, 24000000 );
    if(clocksource_register_hz( &timer_clocksource, 24000000 ))
    {
        panic("%s: can't register clocksource\n", timer_clocksource.name);
    }

    return 0;
}

可以看出根据该clcoksource->read获取的最大cycles为0xffffffff,而timer的工作频率是24MHZ,因此换算成时间就是178.9s。

看到这个数字我一下就兴奋了,因为前面说过的一个bug现象,date时间走3分钟就跳转回来。这里就可以解释这个现象了:
kernel下的xtime时间停止了,但是由于clocksource的补充精度时间最大可以补充178.9s,
所以gettimeofday获取时间就在xtime基础上最多走178.9s,溢出后重新从0开始计数,时间又回到xtime重新开始!


那么问题来了,为什么xtime停止更新了呢?
xtime的更新是基于kernel时钟中断,具体函数还是在timekeepering.c中的update_wall_time,产生一次时钟中断就会将新增的时间加在xtime上。
难道是没有时钟中断了?
多次查看/proc/interrupts(涉及公司设备内容,这里就不贴了),发现timer的中断果然没有变化啊!

利用kernel下预留的操作寄存器命令查看timer模块寄存器,发现产生时钟中断的timer的状态寄存器是stop。

为了验证是timer中断没有了导致该bug,首先在出现该bug的设备直接再次start timer,发现设备恢复正常。而在正常设备上stop timer,就会复现该bug。这就说明无timer intr就是该bug的本质!

从最开始怀疑网卡driver有问题,经过一连串的推测验证后,终于确定了引起该bug的原因:timer interrupt没有了!
算是有一个阶段性小胜利,哈哈。


但是问题还没有最终解决,kernel代码中哪里导致了timer stop呢?
首先想到要让timer stop,软件只可能去置位stop寄存器。那只需要找出kernel中stop timer的接口,确定哪里会调用它,就可以缩小问题范围了。kernel中timer intr的代码如下:

static void
timer_set_mode( enum clock_event_mode mode, struct clock_event_device *evt )
{
    u32 val = 0, timermode = 0;
    val = __raw_readl( IO_ADDRESS( REG_TIMER_TMRMODE ));
    switch( mode )
    {
    case CLOCK_EVT_MODE_PERIODIC:
        timer_stop( 1 );
        timermode = ( val & ~( 0x0f << TIMER1_MODE_OFFSET )) | TIMER1_PERIODICAL_MODE;
        __raw_writel( TIMER1_TARGET, IO_ADDRESS( REG_TIMER_TMR1TGT ));
        __raw_writel( timermode, IO_ADDRESS( REG_TIMER_TMRMODE ));
        timer_start( 1 );
        break;
    case CLOCK_EVT_MODE_ONESHOT:
        timer_stop( 1 );
        timermode = ( val & ~( 0x0f << TIMER1_MODE_OFFSET )) | TIMER1_ONE_SHOT_MODE;
        __raw_writel( TIMER1_TARGET, IO_ADDRESS( REG_TIMER_TMR1TGT ));
        __raw_writel( timermode, IO_ADDRESS( REG_TIMER_TMRMODE ));
        timer_start( 1 );
        break;
    case CLOCK_EVT_MODE_UNUSED:
    case CLOCK_EVT_MODE_SHUTDOWN:
    default:
        VLOGD( MTAG_TIMER, "time stop and clr src pnd. mode = %d", mode );
        timer_stop(1);
        timer_clr_pnd(1);
        VLOGD( MTAG_TIMER, "REG_TIMER_TMREN is %u; REG_TIMER_TMRPND is %u", \
                            readl(IO_ADDRESS( REG_TIMER_TMREN )), readl(IO_ADDRESS( REG_TIMER_TMRPND )));
        break;
    }

}

static int
timer_set_next_event( unsigned long cycles, struct clock_event_device *evt )
{
    timer_stop( 1 );
    __raw_writel( cycles, IO_ADDRESS( REG_TIMER_TMR1TGT ));
    timer_start( 1 );

    return 0;
}

static struct clock_event_device timer_clockevent =
{
    .name           = MTAG_TIMER,
    .features       = CLOCK_EVT_FEAT_PERIODIC | CLOCK_EVT_FEAT_ONESHOT,
    .rating         = 200,
    .set_mode       = timer_set_mode,
    .set_next_event = timer_set_next_event,
};
static void __init
timer_clockevent_init( void )
{
    clockevents_calc_mult_shift( &timer_clockevent, CLOCK_TICK_RATE, 4 );

    timer_clockevent.max_delta_ns = clockevent_delta2ns( 0xffffffff, &timer_clockevent );
    timer_clockevent.min_delta_ns = clockevent_delta2ns( CLOCKEVENT_MIN_DELTA, &timer_clockevent );
    timer_clockevent.cpumask      = cpumask_of( 0 );
    clockevents_register_device( &timer_clockevent );
}
....
static void
timer_clock_event_interrupt( void )
{
       struct clock_event_device *evt = &timer_clockevent;

       timer_clr_pnd( 1 );
       evt->event_handler( evt );
}


static irqreturn_t
timer_interrupt( int irq, void *dev_id )
{
    u32 srcpnd = 0;
    struct clock_event_device *evt = &timer_clockevent;

    srcpnd = __raw_readl(IO_ADDRESS( REG_TIMER_TMRPND ));
    if( srcpnd & TIMER1_EVENT )
    {
    	timer_clock_event_interrupt();
    }

    __raw_writel( srcpnd, IO_ADDRESS( REG_TIMER_TMRPND ));

    return IRQ_HANDLED;
}

static struct irqaction timer_irq =
{
    .name    = "timer",
    .flags   = IRQF_DISABLED | IRQF_TIMER | IRQF_IRQPOLL,
    .handler = timer_interrupt,
    .dev_id  = NULL,
};

这里只贴出clockevent和timer irq处理相关的部分代码,可以看出涉及到stop timer只有set_next_event和set_mode中,set_next_event会在timer_interrupt中的evt->event_handler中调用,来设置下次触发intr的时间点,set_mode来设置timer的工作模式。
直觉感觉,set_mode应该只在timer初始化时使用,而set_next_event会在每次timer intr中使用。因此想在set_mode中加打印来看下哪里会调用set_mode(猜测set_mode调用少,set_next_event中不能加打印,因为timer intr太多)。

set_mode加打印后重新编译kernel,在一台设备上启动发现set_mode只会在kernel启动中调用,进入console后就不会调用了。
这样其实就排除了set_mode函数的可能性,因为根据观察timer intr停止的时间,都是在用户空间,并且kernel启动中printk打印的时间戳是正常的。
在kernel启动后用户空间发生timer intr停止,软件上来看,只可能是timer中断部分出现问题了。
但是看代码,timer_interrupt中也没有stop timer的操作啊。

不过还是想到了一种场景会导致stop timer现象:

timer_interrupt中调用timer_clock_event_interrupt,其中又调用clockevent->event_handler,该函数会调用clockevent->set_next_event,
在set_next_event中设置完下一次触发时间点后就start timer了,回到timer_interrupt中clear下timer intr就会从中断处理中退出。
如果设置的下次触发时间点足够短(kernel为tickless,每次设置的触发时间都不一样),在clear timer intr之前该次intr就产生了,但是接下来就clear掉了。

这样中断处理函数退出后就不会再次产生timer intr了。

但是有2个地方我觉得需要验证下:

(1)timer计数达到目标后,状态寄存器是否是stop状态
(2)如果是上述场景导致这次bug,那么延长start timer和clear intr之间时间,应该会让该bug更快复现
timer经过测试发现计数达到目标后,状态寄存器就会显示为stop状态。
在time_interrupt中的start timer 和clear intr中间加入一些没用代码做延时(不能用delay,因为现在timer有问题呢),进入console后很快就复现了bug。

所以这个bug的原因就是不应该在set_next_event后再次clear timer intr。于是将上面time_interrupt修改为:

static irqreturn_t
timer_interrupt( int irq, void *dev_id )
{
    u32 srcpnd = 0;
    struct clock_event_device *evt = &timer_clockevent;

    srcpnd = __raw_readl(IO_ADDRESS( REG_TIMER_TMRPND ));
    if( srcpnd & TIMER1_EVENT )
    {
        timer_clr_pnd( 1 );
        evt->event_handler( evt );
    }

    return IRQ_HANDLED;
}

终于解决了这个bug,对于sleep ping的阻塞问题也就可以理解了:

sleep ping实现中都使用了定时器,定时器是由kernel的时钟中断和软中断结合实现的,由时钟中断来触发定时器软中断,在软中断中检查定时是否到了,所以没有了时钟中断,kernel的定时器机制不能工作。


根据kernel代码,kernel调度的时间片是使用ktime_get接口获取的,该函数获取的时间也是使用了clocksource提供的精度补充时间,时间是180s来回跳转,也是走的,所以kernel的调度还是正常的。

记录这次bug调试,并没有详细来说明一些知识的细节,而是重在说明思路,如何从最初怀疑网卡driver问题,一步步分析排查,直到最后彻底找到代码原因。


我想如果要成为一个系统级程序员,解决类似的bug,开阔的思路比知识更重要!





已标记关键词 清除标记
©️2020 CSDN 皮肤主题: 大白 设计师:CSDN官方博客 返回首页