Log performance concern

martin.gee · 2014-12-09T09:06:40+00:00

Hello! On Tue, Dec 9, 2014 at 3:01 AM, Andrei Belov wrote: > I also spent some time surfing through the luajit mailing list archives, > but haven't fo...

Log performance concern

martin.gee

I have many debug statements in my lua code.

e.g.

local debugFormat = "server: " .. ngx.var.server_name .. " "

ngx.log(ngx.DEBUG, debugFormat .. "*** NEW REQUEST")

local debug = string.format("Retrieved uuid:%s content:%s",uuid, res)

ngx.log(ngx.DEBUG, debugFormat .. debug)

I'm unsure if this will cause a bunch of string concatenation for nothing if the log_level is ERR for example.

In Java I'd use a guard : if (loglevel == DEBUG) do logging stuff.

Q) Should I guard these log statements? If so, how do I check the log level?

agentzh

Hello!

On Mon, Dec 8, 2014 at 5:06 PM, Martin Gee wrote:
> I have many debug statements in my lua code.
> e.g.
> local debugFormat = "server: " .. ngx.var.server_name .. " "
> ngx.log(ngx.DEBUG, debugFormat .. "*** NEW REQUEST")
[...]
> I'm unsure if this will cause a bunch of string concatenation for nothing if
> the log_level is ERR for example.
>

Yes, it introduces overhead due to the "eager evaluation" policy in
Lua (and almost all the other imperative languages). What makes it
worse is that ngx.log() cannot be JIT compiled so it aborts the trace
in the containing Lua code path (can be seen via jit.v or jit.dump).

Usually we put an "if" guard so that the tracing JIT compiler can skip
that logging Lua code path completely in production, for example,

    if DEBUG then ngx.log(ngx.DEBUG, ...) end

You can use the following debug flag:

    https://github.com/openresty/lua-nginx-module#ngxconfigdebug

which indicates whether your current nginx build is a debug build.
(You should not use nginx/openresty builds with ./configure
--with-debug in production anyway.)

A more flexible approach is having an application level configuration
file that can be toggle the debug option even with the production
build of nginx/openresty. This is the approach we use in CloudFlare's
Lua apps :)

Regards,
-agentzh

martin.gee

Thanks agentzh,

I'm setting the log level in a parent conf file:

error_log /var/log/nginx/debug-default.log debug;

Just curious, if this "debug" setting is available to do the IF statement, so I don't have to roll my own.

Might be useful to expose this in the LUA module.

Cheers,
Martin

On Monday, December 8, 2014 7:06:39 PM UTC-6, Martin Gee wrote:

I have many debug statements in my lua code.

e.g.

local debugFormat = "server: " .. ngx.var.server_name .. " "
ngx.log(ngx.DEBUG, debugFormat .. "*** NEW REQUEST")

or

local debug = string.format("Retrieved uuid:%s content:%s",uuid, res)

ngx.log(ngx.DEBUG, debugFormat .. debug)
I'm unsure if this will cause a bunch of string concatenation for nothing if the log_level is ERR for example.
In Java I'd use a guard : if (loglevel == DEBUG) do logging stuff.
Q) Should I guard these log statements? If so, how do I check the log level?

agentzh

Hello!

On Mon, Dec 8, 2014 at 8:28 PM, Martin Gee wrote:
> Just curious, if this  "debug" setting is available to do the IF statement,
> so I don't have to roll my own.
>
> Might be useful to expose this in the LUA module.
>

It's on a different level and you will always pay the price of the
(eager) Lua function argument evaluation and the Lua function call
itself when you call ngx.log(), no matter what. Nothing can be as
cheap as your own Lua "if" statement here.

Regards,
-agentzh

lazy.dogtown

what about this one (we have a lot of debug_statements all over the place
and are just calling print_debug(MSG) whenever we need it)

debug is configured in a config-file on a per-site-basis and stored in
a lua_shared_dict that gets read via get_waf_config()

it's a little overhead, but probably better than to write the same
code everywhere when you have 100+ debug-points, no?


function print_debug(msg)
  local debug = get_waf_config("waf_debug")
  if not debug then
    debug = "off"
  end
  if debug = "off" then
    return
  end
  if debug == "on" then
    ngx.log(ngx.ERR, "[LUWAF.Debug]["..tostring(msg).."]")
  end
end


cheers,

mex

2014-12-09 6:46 GMT+01:00 Yichun Zhang (agentzh) <age...@gmail.com>:
> Hello!
>
> On Mon, Dec 8, 2014 at 8:28 PM, Martin Gee wrote:
>> Just curious, if this  "debug" setting is available to do the IF statement,
>> so I don't have to roll my own.
>>
>> Might be useful to expose this in the LUA module.
>>
>
> It's on a different level and you will always pay the price of the
> (eager) Lua function argument evaluation and the Lua function call
> itself when you call ngx.log(), no matter what. Nothing can be as
> cheap as your own Lua "if" statement here.
>
> Regards,
> -agentzh.

agentzh

Hello!

On Tue, Dec 9, 2014 at 5:14 AM, mex wrote:
> function print_debug(msg)
>   local debug = get_waf_config("waf_debug")
>   if not debug then
>     debug = "off"
>   end
>   if debug = "off" then
>     return
>   end
>   if debug == "on" then
>     ngx.log(ngx.ERR, "[LUWAF.Debug]["..tostring(msg).."]")
>   end
> end
>

Why not just

 function print_debug(msg)
   local debug = get_waf_config("waf_debug")
   if debug then
     ngx.log(ngx.ERR, "[LUWAF.Debug]["..tostring(msg).."]")
   end
 end

?

I don't see why you need the "on" and "off" values assigned and tested here.

Alas, your get_waf_config function always reads shdict, which is not
really cheap as compared to many other things on the Lua land. I'd say
it's more than orders of magnitude slower than my previous "if DEBUG
then ngx.log(...) end' suggestion (especially when you have many of
them in your hot Lua code paths).

Regards,
-agentzh

lazy.dogtown

hi agentzh,


>
> Alas, your get_waf_config function always reads shdict, which is not
> really cheap as compared to many other things on the Lua land. I'd say
> it's more than orders of magnitude slower than my previous "if DEBUG
> then ngx.log(...) end' suggestion (especially when you have many of
> them in your hot Lua code paths).

point is, we have a per-server {} based configuration, so these values must
be evaluated on each request, but there's probably much room for improvements
and performance-tuning.

i'll release the code for our lua-waf-approach later this month during BsidesHH,
it is not more than a POC atm.



cheers,


mex



>
> Regards,
> -agentzh.