In looking for ways to further optimize my poorly-written Lua WAF (don’t worry, we’ll get there eventually), I’ve recently found that Openresty’s timing API is a bit lacking. Specifically, the time calls used within each transaction seems to only have millisecond granularity. This is fine for more complex applications which run over tens or hundreds of milliseconds, but in analyzing small sections of framework code, I wanted to have a more clear picture of how long each phase handler was taking (and the patronizingly PR-esque phrase “sub-millisecond processing time” was getting really annoying to hear in my head). A quick bounce to the Openresty mailing list got me on the right track:

Rather than relying on the API exposed by Lua, we can leverage the ability to work directly with the C library. This, of course, requires an additional syscall, but the tighter resolution is worth this trade-off in baseline analysis environments. This is the same method used by the line-level profiler lulip. Examples of both usages follow:

So why does ngx.now() only expose millisecond precision? Well, it’s a wrapper for ngx_timeofday, which uses ngx_cached_time to return specific time info without the need for a syscall. The Lua module provides ngx.update_time(), itself a wrapper for ngx_time_update(), eventually snaking down to the C standard lib gettimeofday() call. However, ngx_time_update() removes precision from the returned tv_usec from (dividing by 1000; see http://lxr.nginx.org/source/src/core/ngx_times.c#0094). I assume this is done to keep the size of ngx_current_msec down, but at this point I’ve been up for 24 hours, so… yeah, we’ll go with that.