ngx.timer.at()没有按照预期执行

yongjianchn

Hi，

我碰到了一个诡异的问题，代码如下，设计目标是每分钟的第0秒执行一个handler。

local function handler(premature)

if premature then

return

end

local now = ngx.time()

local next_time_slot = math.floor(now / 60 + 1) * 60

local sleep_time = next_time_slot - now

ngx.log(ngx.INFO, "now: "..now.." next_slot: "..next_time_slot.." sleep: "..sleep_time)

local ok, err = ngx.timer.at(sleep_time, handler)

if not ok and err ~= "process exiting" then

ngx.log(ngx.ERR, logtag, "failed to create timer: ", err)

return

end

-- real work

end

为了更快的发现问题，我把60改成了3，也就是每3秒执行一次，且执行时刻的unix时间戳可以被3整除。

结果显示，有很小的概率会跳过一个timer，日志中会出现：

2018/04/16 21:48:57 [info] 823#0: *8126 [lua] test.lua:107: now: 1523886537 next_slot: 1523886540 sleep: 3, context: ngx.timer

2018/04/16 21:49:00 [info] 823#0: *8132 [lua] test.lua:107: now: 1523886540 next_slot: 1523886543 sleep: 3, context: ngx.timer

// 这里缺少21:49:03秒的timer日志

2018/04/16 21:49:06 [info] 823#0: *8135 [lua] test.lua:107: now: 1523886546 next_slot: 1523886549 sleep: 3, context: ngx.timer

2018/04/16 21:49:09 [info] 823#0: *8140 [lua] test.lua:107: now: 1523886549 next_slot: 1523886552 sleep: 3, context: ngx.timer

请大家帮忙分析一下原因！

zchao1995

Hello!

请问你用的是什么版本的 OpenResty？我用了你的配置，没有复现问题。

yongjianchn

2018-04-18 17:55 GMT+08:00 tokers <zcha...@gmail.com>:
> Hello!
>
> 请问你用的是什么版本的 OpenResty？我用了你的配置，没有复现问题。
我用的不是OpenResty套装，是Nginx1.12.1+lua-nginx-module-1.10.10，问题发生概率较低，我按3秒的间隔跑了一天才发生过1次。


>
> --
>

yuansheng_335c

On Tuesday, April 17, 2018 at 11:01:57 AM UTC+8, yongj...@gmail.com wrote:

Hi，

我碰到了一个诡异的问题，代码如下，设计目标是每分钟的第0秒执行一个handler。

local function handler(premature)
if premature then
return
end

local now = ngx.time()
local next_time_slot = math.floor(now / 60 + 1) * 60
local sleep_time = next_time_slot - now
ngx.log(ngx.INFO, "now: "..now.." next_slot: "..next_time_slot.." sleep: "..sleep_time)

local ok, err = ngx.timer.at(sleep_time, handler)
if not ok and err ~= "process exiting" then
ngx.log(ngx.ERR, logtag, "failed to create timer: ", err)
return
end
-- real work
end

为了更快的发现问题，我把60改成了3，也就是每3秒执行一次，且执行时刻的unix时间戳可以被3整除。

结果显示，有很小的概率会跳过一个timer，日志中会出现：
2018/04/16 21:48:57 [info] 823#0: *8126 [lua] test.lua:107: now: 1523886537 next_slot: 1523886540 sleep: 3, context: ngx.timer
2018/04/16 21:49:00 [info] 823#0: *8132 [lua] test.lua:107: now: 1523886540 next_slot: 1523886543 sleep: 3, context: ngx.timer
// 这里缺少21:49:03秒的timer日志
2018/04/16 21:49:06 [info] 823#0: *8135 [lua] test.lua:107: now: 1523886546 next_slot: 1523886549 sleep: 3, context: ngx.timer
2018/04/16 21:49:09 [info] 823#0: *8140 [lua] test.lua:107: now: 1523886549 next_slot: 1523886552 sleep: 3, context: ngx.timer

你需要排除一下这段时间你的 Nginx 服务是否有 block 操作，这个可能性比较大。

请大家帮忙分析一下原因！

yongjianchn

抱歉浪费大家时间了，查了一圈，最后的结论是系统在那个时刻更新了时间。。

Apr 16 21:49:01 S-LAB-53 CROND[9367]: (root) CMD (/usr/sbin/ntpdate
tiger.sina.com.cn >/dev/null)

在 2018年4月19日 下午9:16，Yuansheng <yuan...@openresty.com> 写道：
>
> On Tuesday, April 17, 2018 at 11:01:57 AM UTC+8, yongj...@gmail.com wrote:
>>
>> Hi，
>>
>> 我碰到了一个诡异的问题，代码如下，设计目标是每分钟的第0秒执行一个handler。
>>
>> local function handler(premature)
>>     if premature then
>>         return
>>     end
>>
>>     local now = ngx.time()
>>     local next_time_slot = math.floor(now / 60 + 1) * 60
>>     local sleep_time = next_time_slot - now
>>     ngx.log(ngx.INFO, "now: "..now.." next_slot: "..next_time_slot.."
>> sleep: "..sleep_time)
>>
>>     local ok, err = ngx.timer.at(sleep_time, handler)
>>     if not ok and err ~= "process exiting" then
>>         ngx.log(ngx.ERR, logtag, "failed to create timer: ", err)
>>         return
>>     end
>>     -- real work
>> end
>>
>> 为了更快的发现问题，我把60改成了3，也就是每3秒执行一次，且执行时刻的unix时间戳可以被3整除。
>>
>> 结果显示，有很小的概率会跳过一个timer，日志中会出现：
>> 2018/04/16 21:48:57 [info] 823#0: *8126 [lua] test.lua:107: now:
>> 1523886537 next_slot: 1523886540 sleep: 3, context: ngx.timer
>> 2018/04/16 21:49:00 [info] 823#0: *8132 [lua] test.lua:107: now:
>> 1523886540 next_slot: 1523886543 sleep: 3, context: ngx.timer
>> // 这里缺少21:49:03秒的timer日志
>> 2018/04/16 21:49:06 [info] 823#0: *8135 [lua] test.lua:107: now:
>> 1523886546 next_slot: 1523886549 sleep: 3, context: ngx.timer
>> 2018/04/16 21:49:09 [info] 823#0: *8140 [lua] test.lua:107: now:
>> 1523886549 next_slot: 1523886552 sleep: 3, context: ngx.timer
>
>
> 你需要排除一下这段时间你的 Nginx 服务是否有 block 操作，这个可能性比较大。
>
>>
>>
>> 请大家帮忙分析一下原因！
>
> --
>