feat(timerng) integrate the `lua-resty-timer-ng` #8912

ADD-SP · 2022-06-07T05:20:05Z

Summary

Integrating https://github.com/Kong/lua-resty-timer-ng into Kong-CE.

Full changelog

fix(plugin_servers) bypass timer library
feat(AdminAPI) add /timers route
chore(rockspec) add resty.timerng as dependency
tests(unit/db/cache_warmup) fix
tests(integration/cmd/quit) fix
tests(integration/hybrid_mode/ocsp) fix
tests(plugin/rate-limiting/access) fix
tests(integration/db/query-semaphore) fix
tests(integration/admin/timers) add tests for http://kong_admin/timers
tests(integration/cmd/start_stop) fix
tests(integration/proxy/router) fix
docs(CHANGELOG) update

Response of `http://kong_admin/timers`

{
    "flamegraph": {
        "running": "@./kong/runloop/balancer/targets.lua:248:Lua() 0\n@./kong/plugins/prometheus/handler.lua:15:Lua();@./kong/plugins/prometheus/exporter.lua:153:init_worker();@./kong/plugins/prometheus/prometheus.lua:673:init_worker();@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new() 0\n@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua() 0\n@./kong/runloop/handler.lua:1087:Lua();@./kong/runloop/balancer/init.lua:228:init();@./kong/runloop/balancer/targets.lua:47:init() 0\n=init_worker_by_lua:2:main();@./kong/init.lua:617:init_worker();@./kong/global.lua:172:init_worker_events();@/build/luarocks/share/lua/5.1/resty/worker/events.lua:620:configure();@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:do_timer() 0\n=init_worker_by_lua:2:main();@./kong/init.lua:706:init_worker();@./kong/runloop/handler.lua:1086:before() 0\n",
        "elapsed_time": "@./kong/runloop/balancer/targets.lua:248:Lua() 0\n@./kong/plugins/prometheus/handler.lua:15:Lua();@./kong/plugins/prometheus/exporter.lua:153:init_worker();@./kong/plugins/prometheus/prometheus.lua:673:init_worker();@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new() 0\n@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua() 0\n@./kong/runloop/handler.lua:1087:Lua();@./kong/runloop/balancer/init.lua:228:init();@./kong/runloop/balancer/targets.lua:47:init() 0\n=init_worker_by_lua:2:main();@./kong/init.lua:617:init_worker();@./kong/global.lua:172:init_worker_events();@/build/luarocks/share/lua/5.1/resty/worker/events.lua:620:configure();@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:do_timer() 2\n=init_worker_by_lua:2:main();@./kong/init.lua:706:init_worker();@./kong/runloop/handler.lua:1086:before() 17\n",
        "pending": "@./kong/runloop/balancer/targets.lua:248:Lua() 0\n@./kong/plugins/prometheus/handler.lua:15:Lua();@./kong/plugins/prometheus/exporter.lua:153:init_worker();@./kong/plugins/prometheus/prometheus.lua:673:init_worker();@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new() 0\n@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua() 0\n@./kong/runloop/handler.lua:1087:Lua();@./kong/runloop/balancer/init.lua:228:init();@./kong/runloop/balancer/targets.lua:47:init() 0\n=init_worker_by_lua:2:main();@./kong/init.lua:617:init_worker();@./kong/global.lua:172:init_worker_events();@/build/luarocks/share/lua/5.1/resty/worker/events.lua:620:configure();@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:do_timer() 0\n=init_worker_by_lua:2:main();@./kong/init.lua:706:init_worker();@./kong/runloop/handler.lua:1086:before() 0\n"
    },
    "sys": {
        "running": 0,
        "runs": 7,
        "pending": 0,
        "waiting": 7,
        "total": 7
    },
    "timers": {
        "unix_timestamp=1654583694012.000000;counter=6:meta=@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new()": {
            "name": "unix_timestamp=1654583694012.000000;counter=6:meta=@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new()",
            "meta": {
                "name": "@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new()",
                "callstack": "@./kong/plugins/prometheus/handler.lua:15:Lua();@./kong/plugins/prometheus/exporter.lua:153:init_worker();@./kong/plugins/prometheus/prometheus.lua:673:init_worker();@/build/luarocks/share/lua/5.1/resty/counter.lua:71:new()"
            },
            "stats": {
                "finish": 2,
                "runs": 2,
                "elapsed_time": {
                    "min": 0,
                    "max": 0,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        },
        "unix_timestamp=1654583693919.000000;counter=0:meta=@./kong/db/init.lua:167:init_worker()": {
            "name": "unix_timestamp=1654583693919.000000;counter=0:meta=@./kong/db/init.lua:167:init_worker()",
            "meta": {
                "name": "@./kong/db/init.lua:167:init_worker()",
                "callstack": "=init_worker_by_lua:2:main();@./kong/init.lua:599:init_worker();@./kong/db/init.lua:167:init_worker()"
            },
            "stats": {
                "finish": 0,
                "runs": 0,
                "elapsed_time": {
                    "min": 9999999,
                    "max": -1,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        },
        "unix_timestamp=1654583694010.000000;counter=5:meta=@./kong/runloop/handler.lua:1181:before()": {
            "name": "unix_timestamp=1654583694010.000000;counter=5:meta=@./kong/runloop/handler.lua:1181:before()",
            "meta": {
                "name": "@./kong/runloop/handler.lua:1181:before()",
                "callstack": "=init_worker_by_lua:2:main();@./kong/init.lua:706:init_worker();@./kong/runloop/handler.lua:1181:before()"
            },
            "stats": {
                "finish": 0,
                "runs": 0,
                "elapsed_time": {
                    "min": 9999999,
                    "max": -1,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        },
        "unix_timestamp=1654583694009.000000;counter=4:meta=@./kong/runloop/handler.lua:1154:before()": {
            "name": "unix_timestamp=1654583694009.000000;counter=4:meta=@./kong/runloop/handler.lua:1154:before()",
            "meta": {
                "name": "@./kong/runloop/handler.lua:1154:before()",
                "callstack": "=init_worker_by_lua:2:main();@./kong/init.lua:706:init_worker();@./kong/runloop/handler.lua:1154:before()"
            },
            "stats": {
                "finish": 0,
                "runs": 0,
                "elapsed_time": {
                    "min": 9999999,
                    "max": -1,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        },
        "unix_timestamp=1654583695942.000000;counter=10:meta=@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua()": {
            "name": "unix_timestamp=1654583695942.000000;counter=10:meta=@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua()",
            "meta": {
                "name": "@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua()",
                "callstack": "@/build/luarocks/share/lua/5.1/resty/worker/events.lua:386:Lua()"
            },
            "stats": {
                "finish": 0,
                "runs": 0,
                "elapsed_time": {
                    "min": 9999999,
                    "max": -1,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        },
        "unix_timestamp=1654583696043.000000;counter=11:meta=@./kong/runloop/balancer/targets.lua:248:Lua()": {
            "name": "unix_timestamp=1654583696043.000000;counter=11:meta=@./kong/runloop/balancer/targets.lua:248:Lua()",
            "meta": {
                "name": "@./kong/runloop/balancer/targets.lua:248:Lua()",
                "callstack": "@./kong/runloop/balancer/targets.lua:248:Lua()"
            },
            "stats": {
                "finish": 0,
                "runs": 0,
                "elapsed_time": {
                    "min": 9999999,
                    "max": -1,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        },
        "unix_timestamp=1654583693982.000000;counter=2:meta=@./kong/cluster_events/init.lua:207:subscribe()": {
            "name": "unix_timestamp=1654583693982.000000;counter=2:meta=@./kong/cluster_events/init.lua:207:subscribe()",
            "meta": {
                "name": "@./kong/cluster_events/init.lua:207:subscribe()",
                "callstack": "=init_worker_by_lua:2:main();@./kong/init.lua:633:init_worker();@./kong/cache/init.lua:138:init_cache();@./kong/cluster_events/init.lua:207:subscribe()"
            },
            "stats": {
                "finish": 0,
                "runs": 0,
                "elapsed_time": {
                    "min": 9999999,
                    "max": -1,
                    "avg": 0,
                    "variance": 0
                },
                "last_err_msg": ""
            }
        }
    }
}

kong/api/routes/kong.lua

Tieske · 2022-06-07T09:37:45Z

spec/fixtures/mocks/lua-resty-dns/resty/dns/resolver.lua

+--     old_post(self, n)
+--     ngx.sleep(0)
+--   end
+-- end


shouldn't this be enabled in case opf legacy timers?

#7704

This patch looks like it's meant to fix some OpenResty bug, and nothing tested wrong when I disabled it. It doesn't seem to be timer-related.

This was a fix for a lot of flaky tests. @javierguerragiraldez might know better if this can be removed or not.

Here's the underlying issue: openresty/lua-resty-core#337

that "some openresty bug" is actually in the docs (https://github.com/openresty/lua-resty-core/blob/master/lib/ngx/semaphore.md#post):

Releases n (default to 1) "resources" to the semaphore instance.
This will not yield the current running "light thread".

but most code seems to assume that yield, and so we get a long runs before the woken-up thread gets some CPU time. if the new time library does include that yield, then yes, this one should be removed. if not, then it does help a lot.

that is not the bug, I would expect the current coro to NOT yield. That is fine. The problem is that if there is nothing else to do, OpenResty simply exits without EVER resuming the released thread.

spec/03-plugins/23-rate-limiting/04-access_spec.lua

spec/02-integration/09-hybrid_mode/05-ocsp_spec.lua

Tieske · 2022-06-07T09:39:55Z

spec/02-integration/02-cmd/08-quit_spec.lua

@@ -31,6 +31,6 @@ describe("kong quit", function()
    assert(helpers.kong_exec("quit --wait 2 --prefix " .. helpers.test_conf.prefix))
    ngx.update_time()
    local duration = ngx.now() - start
-    assert.is.near(2, duration, 1.6)
+    assert.is.near(2, duration, 5)


why does exiting now take more time?

Because the new timer library starts many OpenResty's timers, each timer waits for a semaphore (one-second timeout). Increasing to five seconds is mainly in dealing with the slow CI

Ok, but please note that semaphores are buggy, see the other comment and this issue: openresty/lua-resty-core#337

i don't think this would make any PM happy. slow exits can be considered a low-priority bug. make sure to raise an issue/ticket to fix this.

@ADD-SP let's make sure this behaviour is recorded in JIRA and fix before final release

I have created the FT-3010.

kong/api/routes/kong.lua

kong/conf_loader/init.lua

kong/globalpatches.lua

kong/init.lua

spec/01-unit/01-db/08-cache_warmup_spec.lua

kong/conf_loader/init.lua

kong/globalpatches.lua

spec/01-unit/01-db/08-cache_warmup_spec.lua

spec/02-integration/02-cmd/02-start_stop_spec.lua

spec/03-plugins/23-rate-limiting/04-access_spec.lua

fffonion · 2022-06-09T11:49:54Z

As discussed with @ADD-SP offline, we will first merge in this one, and iterrate on the tests side; Qiqi is working on a determinisitic approach in spec/helpers to ensure timer jobs are executed instead of simply add ngx.sleep. But I don't want to block on this PR and let it become a last minute merge just because of this.

cc @javierguerragiraldez @Tieske how do you feel? (Though you don't leave Request Changes, but I'm asking since your review comments express worry-ness on it)

* fix(plugin_servers) bypass timer library * feat(AdminAPI) add `/timer` route * feat(conf) add new config `legacy_timer_mechanism` (boolean) * chore(rockspec) add `resty.timerng` as dependency * tests(*) add `wait_timers_*()` for helper * tests(plugin/zipkin) fix * tests(unit/db/cache_warmup) fix * tests(integration/cmd/quit) fix * tests(integration/hybrid_mode/ocsp) fix * tests(plugin/rate-limiting/access) fix * tests(integration/db/query-semaphore) fix * tests(integration/admin/timers) add tests for `http://kong_admin/timers` * tests(integration/cmd/start_stop) fix * tests(integration/proxy/router) fix * docs(CHANGELOG) update Co-authored-by: Mayo <i@shoujo.io> Co-authored-by: Wangchong Zhou <fffonion@gmail.com>

pull-request-size bot added the size/L label Jun 7, 2022

ADD-SP requested a review from bungle June 7, 2022 05:20

ADD-SP marked this pull request as ready for review June 7, 2022 05:20

ADD-SP requested a review from a team as a code owner June 7, 2022 05:20

ADD-SP marked this pull request as draft June 7, 2022 05:20

ADD-SP added the pr/do not merge label Jun 7, 2022

ADD-SP added this to the 3.0 milestone Jun 7, 2022

github-actions bot added the core/admin-api label Jun 7, 2022

ADD-SP marked this pull request as ready for review June 7, 2022 06:38

fffonion reviewed Jun 7, 2022

View reviewed changes

kong/api/routes/kong.lua Outdated Show resolved Hide resolved

github-actions bot added core/configuration core/templates labels Jun 7, 2022

Tieske reviewed Jun 7, 2022

View reviewed changes