Heh, answered my own question- this is trivial with FFI. Lulip already
did it ;)
(http://blog.jgc.org/2013/04/lulip-line-level-profiler-for-code.html)
On 10/29/2014 02:33 AM, Robert Paprocki wrote:
> Right, I kinda figured :) My question is, is there an available solution
> within nginx or Lua for sub-millisecond time resolution?
>
> On 10/29/2014 01:27 AM, Vladislav Manchev wrote:
>> You're definitely getting milliseconds timer resolution with the nginx
>> API, not microseconds.
>>
>> What you're seeing is normal for floating point numbers as defined by
>> the IEEE 754 standard, so you can ignore those 0.0009... numbers and
>> consider them to be 1 millisecond.
>>
>>
>> Best,
>> Vladislav
>>
>> On Wed, Oct 29, 2014 at 9:19 AM, Robert Paprocki
>> <rpap...@fearnothingproductions.net
>> <mailto:rpap...@fearnothingproductions.net>> wrote:
>>
>>
>> Hello!
>>
>> I'm using the ngx.now() API to determine runtime of my Lua code in a
>> given phase handler:
>>
>> function finish()
>> ngx.update_time()
>> logger:debug("Finished exec in: " .. ngx.now() -
>> ngx.req.start_time())
>> end
>>
>> Which is working as expected, but when runtimes reach 1 ms, the time
>> difference seems to lose its granularity. For example, we never see
>> runtimes shown below ~ 999 microseconds- they appear as 0. For example:
>>
>> 2014-10-29 02:56:57 DEBUG Finished exec in: 0.0010001659393311
>> 2014-10-29 02:56:57 DEBUG Finished exec in: 0
>> 2014-10-29 02:56:59 DEBUG Finished exec in: 0.00099992752075195
>>
>> We also see time diffs repeated on multiple occasions:
>>
>> 2014-10-29 02:57:48 DEBUG Finished exec in: 0.00099992752075195
>> 2014-10-29 03:16:58 DEBUG Finished exec in: 0.0069999694824219
>> 2014-10-29 03:17:00 DEBUG Finished exec in: 0.00099992752075195
>> 2014-10-29 03:17:00 DEBUG Finished exec in: 0
>> 2014-10-29 03:17:01 DEBUG Finished exec in: 0
>> 2014-10-29 03:17:02 DEBUG Finished exec in: 0
>> 2014-10-29 03:17:02 DEBUG Finished exec in: 0
>> 2014-10-29 03:17:03 DEBUG Finished exec in: 0.0010001659393311
>> 2014-10-29 03:17:04 DEBUG Finished exec in: 0.0010001659393311
>> 2014-10-29 03:17:04 DEBUG Finished exec in: 0.0010001659393311
>>
>> Noting that 0010001659393311 and 00099992752075195 appear multiple
>> times- this would suggest a limitation of the timing API, as times
>> matching that number of digits cannot be coincidence. So, we see
>> runtimes of around 1 ms, but not fewer. Is this a limitation of the
>> timing API? If so, is there a possibility to implement more granular
>> timing information via a third-party module, say, on the level of tens
>> or hundreds of microseconds?.
