一个奇葩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问题，一步步分析排查，直到最后彻底找到代码原因。
————————————————
版权声明：本文为CSDN博主「kerneler_」的原创文章，遵循CC 4.0 BY-SA版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/skyflying2012/article/details/44623515