最近在做一些框架的优化工作,其中一个就是完善测试用例,在进行http模块测试的时候,我注意到输出的时间有异常

[T1LP10-20 19:25:09]http(s) test
[T1LP10-20 19:25:19][  OK] http get example.com (25ms)
[T1LP10-20 19:25:19]21 passing, 0 failing (1962ms)

可以看到get example.com这个测试花25ms,但实际这个测试花了10秒时间,这说明测试输出的时间是错误的。

由于整个框架的代码都是自己写的,包括测试模块的代码。首先怀疑是测试模块的代码写得有问题,但是检查了一遍,代码里都是直接用的os.clock(),没有发现问题。第二,测试模块里使用了coroutine,怀疑是os.clock()coroutine下有什么设定,查了资料也没有发现。第三,测试是在Virtual Box虚拟机里进行的,怀疑是不是虚拟机里得到的时间不一样,于是去了另一台win7的机子上测试,结果发现在win7上时间是正确的。于是简化代码,拿到另一台linux真机上测试,结果发现时间还是不对。

# cat test.lua

print("before", os.clock(), os.date())

os.execute("sleep 5")

print("after", os.clock(), os.date())
root@debian:/home/xzc/local_code# lua test.lua
before  0.001295        Wed Oct 21 10:42:41 2020
after   0.001688        Wed Oct 21 10:42:46 2020

这说明不是虚拟机的问题,于是查了下os.clock()的源码,极其简单

// loslib.c
static int os_clock(lua_State *L) {
    lua_pushnumber(L, ((lua_Number)clock())/(lua_Number)CLOCKS_PER_SEC);
    return 1;
}

直接调用C标准库的clock函数。我对这个函数的印象就是它会溢出,但这里程序启动才几秒钟,显然不是溢出的情况,但为啥在linux下时间不对。在搜索clock linux time这个关键字的时候,才发现自己忽略了这个函数的另一个问题

linux

The clock() function returns an approximation of processor time used by the program.

windows

The clock function tells how much wall-clock time has passed since the CRT initialization during process start. Note that this function does not strictly conform to ISO C, which specifies net CPU time as the return value.

linux下该函数返回cpu消耗的时间(不包括sleep、epoll_wait等不消耗cpu函数所用的时间),而win返回整个程序运行的时间,详见stackoverflow的讨论

因此,测试中日志的时间虽然和预期不太一样,但“并不算是一个bug”。如果要转换成经过的时间,就需要额外处理了。

posted on 2020-10-24 14:57  coding my life  阅读(644)  评论(0编辑  收藏  举报