Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP
Browse files

Documented and implemented logging of latency. Included in every line…

… sent by elli_access_log.
  • Loading branch information...
commit 8dc044740d3690de1155cd2523875347c2786494 1 parent 45838ea
@knutin authored
Showing with 64 additions and 11 deletions.
  1. +58 −9 src/elli_access_log.erl
  2. +6 −2 src/elli_http.erl
View
67 src/elli_access_log.erl
@@ -1,3 +1,30 @@
+%% @doc HTTP access and error long, sending to syslog over UDP
+%%
+%% Sends a simple log line for every request, even errors, to
+%% syslog. The line includes the following timings, all specified in
+%% wall-clock microseconds:
+%%
+%% RequestLine/Headers/Body/User/Response/Total
+%%
+%% * RequestLine: time between accept returning and complete receive
+%% of the request line, ie. "GET /foo HTTP/1.1". If keep-alive is
+%% used, this will be the time since the initial accept so it might
+%% be very high.
+%%
+%% * Headers: Time to receive all headers
+%%
+%% * Body: Time to receive the entire body into memory, not including
+%% any decoding
+%%
+%% * User: Time spent in the callback. If middleware is used, the
+%% runtime of the middleware is included in this number
+%%
+%% * Response: Time taken to send the response to the client
+%%
+%% * Total: The time between the request line was received and the
+%% response was sent. This is as close we can get to the actual time
+%% of the request as seen by the server.
+
-module(elli_access_log).
-behaviour(elli_handler).
-export([handle/2, handle_event/3]).
@@ -6,28 +33,47 @@
handle(_Req, _Args) ->
ignore.
+
handle_event(request_complete, [Req, ResponseCode, _ResponseHeaders,
- ResponseBody, _Timings], Config) ->
+ ResponseBody, Timings], Config) ->
+
+ Accepted = proplists:get_value(accepted, Timings),
+ RequestStart = proplists:get_value(request_start, Timings),
+ HeadersEnd = proplists:get_value(headers_end, Timings),
+ BodyEnd = proplists:get_value(body_end, Timings),
+ UserStart = proplists:get_value(user_start, Timings),
+ UserEnd = proplists:get_value(user_end, Timings),
+ RequestEnd = proplists:get_value(request_end, Timings),
+
+ TimeStr = io_lib:format("~w/~w/~w/~w/~w/~w",
+ [timer:now_diff(RequestStart, Accepted),
+ timer:now_diff(HeadersEnd, RequestStart),
+ timer:now_diff(BodyEnd, HeadersEnd),
+ timer:now_diff(UserEnd, UserStart),
+ timer:now_diff(RequestEnd, UserEnd),
+ timer:now_diff(RequestEnd, RequestStart)]),
- Msg = io_lib:format("~s \"~s ~s\" ~w ~w",
+ Msg = io_lib:format("~s ~s ~w ~w \"~s ~s\"",
[elli_request:peer(Req),
- elli_request:method(Req),
- elli_request:raw_path(Req),
+ TimeStr,
ResponseCode,
- byte_size(ResponseBody)]),
+ byte_size(ResponseBody),
+ elli_request:method(Req),
+ elli_request:raw_path(Req)
+ ]),
- syslog:send(proplists:get_value(name, Config), Msg, [{ident, node()}]),
+ log(Msg, Config),
ok;
handle_event(request_throw, [_Req, Exception, Stack], _Config) ->
- error_logger:error_msg("exception: ~p~n stack: ~p~n", [Exception, Stack]),
+ error_logger:error_msg("exception: ~p~nstack: ~p~n", [Exception, Stack]),
ok;
handle_event(request_exit, [_Req, Exit, Stack], _Config) ->
- error_logger:error_msg("exit: ~p~n stack: ~p~n", [Exit, Stack]),
+ error_logger:error_msg("exit: ~p~nstack: ~p~n", [Exit, Stack]),
ok;
handle_event(request_error, [_Req, Error, Stack], _Config) ->
- error_logger:error_msg("error: ~p~n stack: ~p~n", [Error, Stack]),
+ error_logger:error_msg("error: ~p~nstack: ~p~n", [Error, Stack]),
ok;
handle_event(request_parse_error, [_Data], _Args) ->
@@ -52,3 +98,6 @@ handle_event(elli_startup, [], Config) ->
+
+log(Msg, Config) ->
+ syslog:send(proplists:get_value(name, Config), Msg, [{ident, node()}]).
View
8 src/elli_http.erl
@@ -13,6 +13,7 @@ start_link(Server, ListenSocket, Callback) ->
accept(Server, ListenSocket, Callback) ->
case catch gen_tcp:accept(ListenSocket, 1000) of
{ok, Socket} ->
+ t(accepted),
gen_server:cast(Server, accepted),
?MODULE:handle_request(Socket, Callback),
ok;
@@ -27,7 +28,6 @@ accept(Server, ListenSocket, Callback) ->
%% socket. If nothing happens within the keep alive timeout, the
%% connection is closed.
handle_request(Socket, {Mod, Args} = Callback) ->
- t(accept_start),
{Method, RawPath, V, B0} = get_request(Socket, Callback), t(request_start),
{RequestHeaders, B1} = get_headers(Socket, V, B0, Callback), t(headers_end),
RequestBody = get_body(Socket, RequestHeaders, B1, Callback), t(body_end),
@@ -38,6 +38,7 @@ handle_request(Socket, {Mod, Args} = Callback) ->
headers = RequestHeaders, body = RequestBody,
pid = self(), peer = get_peer(Socket, RequestHeaders)},
+ t(user_start),
case execute_callback(Req, Callback) of
{ResponseCode, UserHeaders, UserBody} ->
t(user_end),
@@ -215,7 +216,10 @@ t(Key) ->
get_timings() ->
lists:flatmap(fun ({{time, Key}, Val}) ->
- erase({time, Key}),
+ if
+ Key =:= accepted -> ok;
+ true -> erase({time, Key})
+ end,
[{Key, Val}];
(_) ->
[]
Please sign in to comment.
Something went wrong with that request. Please try again.