diff --git a/docs/conf-file.rst b/docs/conf-file.rst index f3f7dcadd..78b5298d2 100644 --- a/docs/conf-file.rst +++ b/docs/conf-file.rst @@ -22,7 +22,7 @@ Scenarios are enclosed into **tsung** tags: .. index:: dumptraffic If you add the attribute **dumptraffic="true"**, all the -traffic will be logged to a file. +traffic will be logged to a file. .. warning:: @@ -32,31 +32,40 @@ traffic will be logged to a file. Since version **1.4.0**, you have also a specific logging per protocol, using **dumptraffic="protocol"**. It's currently -only implemented for HTTP: this will log all requests in a CSV file, +only implemented for HTTP: this will log all requests in a CSV (RFC4180) file, with the following data: .. code-block:: text - #date;pid;id;http method;host;URL;HTTP status;size;duration;transaction;match;error;tag + date,pid,id,start,connect,request_duration,time_to_first_byte,duration,host,http_method,relative_url,http_status,request_size,response_size,transaction,match,error,tag Where: -=========== ===================================================================================== -field description -=========== ===================================================================================== -date timestamp at the end of the request (seconds since 1970-01-01 00:00:00 UTC) -pid erlang process id -id tsung user id -host server hostname -url URL (relative) -HTTP status HTTP reponse status (200, 304, etc.) -size reponse size (in bytes) -duration request duration (msec) -transaction name of the transaction (if any) this request was made in -match if a match is defined in the request: match|nomatch (last if several are defined) -error name of http error (or empty) -tag tag name if the request was tagged; empty otherwise -=========== ===================================================================================== +==================== ============================================================================================================ +field description +==================== ============================================================================================================ +date timestamp of log entry +pid erlang process id +id tsung user id +start timestamp when request was started +connect duration in msec to establish the TCP connection, 0 if the connection was already established +request_duration duration in msec to send the request headers and payload if any +time_to_first_byte duration in msec it took after request was send, before first response byte was received +duration duration in msec for the entire request to complete (connect + sending request + time to first byte + rest of transfer) +host server host name +http_method HTTP Method/Verb (GET, POST, PUT, etc.) +relative_url Relative URL +http_status status HTTP response status (200, 304, etc.) +request_size request size, headers and payload, if any (in bytes) +response_size response size (in bytes) +transaction name of the transaction (if any) this request was made in +match if a match is defined in the request: match|nomatch (last if several are defined) +error name of http error (or empty) +tag tag name if the request was tagged; empty otherwise +==================== ============================================================================================================ + +Timestamps are always in epoch, seconds with fractions since 1970-01-01 00:00:00 UTC. Field values are unquoted unless they +contain a comma or quote ("). .. warning:: diff --git a/include/ts_http.hrl b/include/ts_http.hrl index 6a81af73e..cb20662bd 100644 --- a/include/ts_http.hrl +++ b/include/ts_http.hrl @@ -66,18 +66,19 @@ %% use by the client process to store information about the current request during %% the parsing of the response, and for the whole session (user_agent and cookies) --record(http, {content_length= 0, % HTTP header: content length - body_size = 0, % current size of body, - chunk_toread = -1, % chunk data to be read (-1 = not chunked, -2 = not chunked, but last response was) - status = {none,none}, % HTTP resp. status :200, etc. 'none' - % if no current cnx. - close = false, % true if HTTP/1.0 or 'connection: close' - % has been received - partial=false, % true if headers are partially received - compressed={false,false}, % type of compression if body is compressed - cookie=[], %cookies of the current request +-record(http, {content_length = 0, % HTTP header: content length + body_size = 0, % current size of body, + time_to_first_byte = {0,0}, % time when first byte was received for last request (current and previous) + chunk_toread = -1, % chunk data to be read (-1 = not chunked, -2 = not chunked, but last response was) + status = {none,none}, % HTTP resp. status :200, etc. 'none' + % if no current cnx. + close = false, % true if HTTP/1.0 or 'connection: close' + % has been received + partial = false, % true if headers are partially received + compressed = {false,false}, % type of compression if body is compressed + cookie = [], %cookies of the current request user_agent, - session_cookies = [] % Cookies of the session + session_cookies = [] % Cookies of the session }). diff --git a/include/ts_profile.hrl b/include/ts_profile.hrl index a764e142d..fa6d121d2 100644 --- a/include/ts_profile.hrl +++ b/include/ts_profile.hrl @@ -99,10 +99,13 @@ persistent, % if true, don't exit when connexion is closed timestamp, % previous message date starttime, % date of the beginning of the session + duration_to_connect, % duration for establishing the connection count, % number of requests waiting to be sent maxcount, % number of requests waiting to be sent ack_done=false, % 'true' if the ack was sent, else 'false' (unused if ack=no_ack) - send_timestamp, % date when the 'request' was sent + send_timestamp, % date when the sending the request begun + send_completed_duration, % date when the 'request' was completely sent + completed_timestamp, % date when the 'request' was completed page_timestamp=0,% date when the first 'request' of a page was sent acc=[], % Accumulator to store temporary unparsable data % (Waiting for more data) @@ -110,6 +113,7 @@ % all the response to do pattern matching) session, % record of session status; depends on 'clienttype' (cas be used to store data dynamically generated during the % session (Cookies for examples)) + request_size = 0, % size of request headers + payload datasize=0, id, % user id size_mon_thresh=?size_mon_thresh, % if rcv data is > to this, update stats diff --git a/src/tsung/ts_client.erl b/src/tsung/ts_client.erl index 9b8afa2e0..75115b6ce 100644 --- a/src/tsung/ts_client.erl +++ b/src/tsung/ts_client.erl @@ -786,7 +786,8 @@ handle_next_request(Request, State) -> %% reconnect if needed ProtoOpts = State#state_rcv.proto_opts, case reconnect(Socket,Host,Port,{Protocol,ProtoOpts},State#state_rcv.ip) of - {ok, NewSocket} -> + {ok, NewSocket, DurationToConnect} -> + ConnectTime = ?NOW, case catch send(Protocol, NewSocket, Message, Host, Port) of ok -> PageTimeStamp = case State#state_rcv.page_timestamp of @@ -794,7 +795,8 @@ handle_next_request(Request, State) -> _ -> %page already started State#state_rcv.page_timestamp end, - ts_mon:add({ sum, size_sent, size_msg(Message)}), + MessageSize = size_msg(Message), + ts_mon:add({ sum, size_sent, MessageSize}), ts_mon:sendmes({State#state_rcv.dump, self(), Message}), NewState = State#state_rcv{socket = NewSocket, protocol = Protocol, @@ -806,6 +808,9 @@ handle_next_request(Request, State) -> proto_opts = ProtoOpts#proto_opts{is_first_connect = false}, page_timestamp= PageTimeStamp, send_timestamp= Now, + send_completed_duration= ts_utils:elapsed(ConnectTime, ?NOW), + request_size= MessageSize, + duration_to_connect= DurationToConnect, timestamp= Now }, case Request#ts_request.ack of no_ack -> @@ -976,10 +981,10 @@ reconnect(none, ServerName, Port, {Protocol, Proto_opts}, {IP,CPort, Try}) when ts_mon:add({ sample, connect, Elapsed }), set_connected_status(true), ?Debug("(Re)connected~n"), - {ok, Socket}; + {ok, Socket, Elapsed}; {error, timeout} -> % don't handle connect timeouts at this level - {error, timeout}; + {error, timeout, 0}; {error, Reason} -> {A,B,C,D} = IP, %% LOG only at INFO level since we report also an error to ts_mon @@ -1004,7 +1009,7 @@ reconnect(none, ServerName, Port, {Protocol, Proto_opts}, {IP,CPort, Try}) when CountName="error_connect_"++atom_to_list(Reason), ts_mon:add({ count, list_to_atom(CountName) }) end, - {error, Reason} + {error, Reason, 0} end; reconnect(none, ServerName, Port, {Protocol, Proto_opts}, {IP,CPortServer}) -> CPort = case catch ts_cport:get_port(CPortServer,IP) of @@ -1016,7 +1021,7 @@ reconnect(none, ServerName, Port, {Protocol, Proto_opts}, {IP,CPortServer}) -> end, reconnect(none, ServerName, Port, {Protocol, Proto_opts}, {IP,CPort,CPortServer}); reconnect(Socket, _Server, _Port, _Protocol, _IP) -> - {ok, Socket}. + {ok, Socket, 0}. %% set options for local socket ip/ports @@ -1095,8 +1100,20 @@ handle_data_msg(Data,State=#state_rcv{dump=Dump,request=Req,id=Id,clienttype=Typ NewState#state_rcv.session_id, Id}, NewDynVars=ts_dynvars:merge(DynVars,NewState#state_rcv.dynvars), NewCount =ts_search:match(Req#ts_request.match,NewBuffer,MatchArgs,NewDynVars,Transactions), - Type:dump(Dump,{Req,NewState#state_rcv.session,Id, - NewState#state_rcv.host,NewState#state_rcv.datasize,Elapsed,Transactions}), + Type:dump(Dump, { + Req, % http_request + NewState#state_rcv.session, % session + Id, % client id + NewState#state_rcv.host, % target host + NewState#state_rcv.request_size, % request size + NewState#state_rcv.datasize, % response size + NewState#state_rcv.send_timestamp, % time when request was started + NewState#state_rcv.duration_to_connect, % time required to establish the TCP connection or 0 + NewState#state_rcv.send_completed_duration, % duration to send the request + NewState#state_rcv.completed_timestamp, % time when request was finished + Elapsed, % duration of total request-response duration, excluding connect time + Transactions + }), case Close of true -> @@ -1233,9 +1250,9 @@ update_stats_noack(#state_rcv{page_timestamp=PageTime,request=Request}) -> %% Purpose: update the statistics %%---------------------------------------------------------------------- update_stats(S=#state_rcv{size_mon_thresh=T,page_timestamp=PageTime, - send_timestamp=SendTime,datasize=Datasize})-> + send_timestamp=SendTime,completed_timestamp=CompletedTime,datasize=Datasize})-> Now = ?NOW, - Elapsed = ts_utils:elapsed(SendTime, Now), + Elapsed = ts_utils:elapsed(SendTime, CompletedTime), Stats = case S#state_rcv.size_mon > T of true -> diff --git a/src/tsung/ts_http.erl b/src/tsung/ts_http.erl index 9a647f088..10064770f 100644 --- a/src/tsung/ts_http.erl +++ b/src/tsung/ts_http.erl @@ -92,7 +92,7 @@ dump(protocol_local, Args)-> dump(_,_) -> ok. -dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,Duration,Transactions})-> +dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,RequestSize,ResponseSize,StartTime,DurationToConnect,RequestDuration,_EndTime,Duration,Transactions})-> Status = case element(2,HttpResp#http.status) of none -> "error_no_http_status"; % something is really wrong here ... http 0.9 response ? Int when is_integer(Int) -> @@ -111,12 +111,30 @@ dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,Duration,Transa atom_to_list(Err) end, Tr=ts_utils:log_transaction(Transactions), - ts_utils:join(";",[integer_to_list(UserId), - atom_to_list(HttpReq#http_request.method), Server, - get(last_url), Status,integer_to_list(Size), - Duration,Tr,Match,Error, - HttpReq#http_request.tag] - ). + TimeToFirstByte = case HttpResp#http.time_to_first_byte of + {0,0} -> + ""; + {_,Time} -> + ts_utils:elapsed(StartTime, Time) + end, + ts_utils:join(",", [ + integer_to_list(UserId), + ts_utils:time2sec_hires(StartTime) - DurationToConnect/1000, + DurationToConnect, + RequestDuration, + TimeToFirstByte, + Duration + DurationToConnect, + Server, + atom_to_list(HttpReq#http_request.method), + erlang:iolist_to_binary([<<"\"">>, get(last_url), <<"\"">>]), + Status, + integer_to_list(RequestSize), + integer_to_list(ResponseSize), + Tr, + Match, + Error, + HttpReq#http_request.tag + ]). %%---------------------------------------------------------------------- diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index c0238415d..da4f8d8e9 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -269,16 +269,20 @@ matchdomain_url(Cookie, Host, URL) -> %% Purpose: parse the response from the server and keep information %% about the response if State#state_rcv.session %%---------------------------------------------------------------------- -parse(closed, State=#state_rcv{session=Http}) -> - {State#state_rcv{session=reset_session(Http), ack_done = true}, [], true}; +parse(closed, State) -> + Http = update_time_to_first_byte(State), -parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == none; - HTTP#http.partial == true -> + {State#state_rcv{session=reset_session(Http), ack_done = true, completed_timestamp=?NOW}, [], true}; + +parse(Data, State=#state_rcv{session=#http{status={Status,_}, partial=Partial}}) when Status == none; + Partial == true -> List = binary_to_list(Data), TotalSize = size(Data), Header = State#state_rcv.acc ++ List, + HTTP = update_time_to_first_byte(State), + case parse_headers(HTTP, Header, State#state_rcv.host) of %% Partial header: {more, HTTPRec, Tail} -> @@ -309,28 +313,41 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == %% continued chunked transfer parse(Data, State=#state_rcv{session=Http}) when Http#http.chunk_toread >=0 -> + NewHttp = update_time_to_first_byte(State), + ?DebugF("Parse chunk data = [~s]~n", [Data]), - case read_chunk_data(Data,State,Http#http.chunk_toread,Http#http.body_size) of + case read_chunk_data(Data,State,NewHttp#http.chunk_toread,NewHttp#http.body_size) of {NewState=#state_rcv{ack_done=false}, NewOpts}-> {NewState, NewOpts, false}; {NewState, NewOpts}-> - {NewState#state_rcv{acc=[]}, NewOpts, Http#http.close} + {NewState#state_rcv{acc=[]}, NewOpts, NewHttp#http.close} end; %% continued normal transfer -parse(Data, State=#state_rcv{session=Http, datasize=PreviousSize}) -> +parse(Data, State=#state_rcv{datasize=PreviousSize}) -> + Http = update_time_to_first_byte(State), + DataSize = size(Data), ?DebugF("HTTP Body size=~p ~n",[DataSize]), CLength = Http#http.content_length, case Http#http.body_size + DataSize of CLength -> % end of response - {State#state_rcv{session=reset_session(Http), acc=[], ack_done = true, datasize = DataSize+PreviousSize}, + {State#state_rcv{session=reset_session(Http), acc=[], ack_done = true, datasize = DataSize+PreviousSize, completed_timestamp=?NOW}, [], Http#http.close}; Size -> {State#state_rcv{session = Http#http{body_size = Size}, ack_done = false, datasize = DataSize+PreviousSize}, [], false} end. +update_time_to_first_byte(#state_rcv{acc=Acc, session=Http}) -> + case {Acc, Http#http.status} of + {[], {none, _}} -> + {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, + Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; + _ -> + Http + end. + %%---------------------------------------------------------------------- %% Func: check_resp_size/5 %% Purpose: Check response size @@ -339,14 +356,15 @@ parse(Data, State=#state_rcv{session=Http, datasize=PreviousSize}) -> check_resp_size(Http=#http{content_length=CLength, close=Close}, CLength, State, DataSize, _Dump) -> %% end of response - {State#state_rcv{session= reset_session(Http), ack_done = true, datasize = DataSize }, [], Close}; + {State#state_rcv{session= reset_session(Http), ack_done = true, datasize = DataSize, completed_timestamp=?NOW}, [], Close}; check_resp_size(Http=#http{content_length=CLength, close=Close}, BodySize, State, DataSize, Dump) when BodySize > CLength -> ?LOGF("Error: HTTP Body (~p)> Content-Length (~p) !~n", [BodySize, CLength], ?ERR), log_error(Dump, error_http_bad_content_length), {State#state_rcv{session= reset_session(Http), ack_done = true, - datasize = DataSize }, [], Close}; + datasize = DataSize, + completed_timestamp=?NOW}, [], Close}; check_resp_size(Http=#http{}, BodySize, State, DataSize,_Dump) -> %% need to read more data {State#state_rcv{session = Http#http{body_size = BodySize}, @@ -386,7 +404,8 @@ read_chunk(<>, State=#state_rcv{session=Http}, Int, <> when Int==0, size(Data) == 3 -> %% should be the end of transfer ?DebugF("Finish tranfer chunk ~p~n", [binary_to_list(Data)]), {State#state_rcv{session= reset_session(Http), ack_done = true, - datasize = Acc %% FIXME: is it the correct size? + datasize = Acc, %% FIXME: is it the correct size? + completed_timestamp=?NOW }, []}; <> when Int==0, size(Data) < 3 -> % lack ?CRLF, continue { State#state_rcv{acc = <<48, ?CR , Data/binary>>, ack_done=false }, [] }; @@ -396,7 +415,7 @@ read_chunk(<>, State=#state_rcv{session=Http}, Int, _Other -> ?LOGF("Unexpected error while parsing chunk ~p~n", [_Other] ,?WARN), log_error(State#state_rcv.dump, error_http_unexpected_chunkdata), - {State#state_rcv{session= reset_session(Http), ack_done = true}, []} + {State#state_rcv{session= reset_session(Http), ack_done = true, completed_timestamp=?NOW}, []} end. @@ -667,11 +686,27 @@ get_line([], _, _) -> %% Headers are fragmented ... We need more data %% we need to keep the compressed value of the current request reset_session(#http{user_agent=UA,session_cookies=Cookies, - compressed={Compressed,_}, status= {Status,_}, chunk_toread=Val}) when Val > -1 -> - #http{session_cookies=Cookies,user_agent=UA,compressed={false,Compressed}, chunk_toread=-2, status={none,Status}} ; -reset_session(#http{user_agent=UA,session_cookies=Cookies, - compressed={Compressed,_}, status= {Status,_}}) -> - #http{session_cookies=Cookies,user_agent=UA,compressed={false,Compressed}, status={none,Status}}. + compressed={Compressed,_}, + status= {Status,_}, + chunk_toread=Val, + time_to_first_byte={PrevTimeToFirstByte, _}}) when Val > -1 -> + #http{session_cookies=Cookies, + user_agent=UA, + compressed={false,Compressed}, + chunk_toread=-2, + status={none,Status}, + time_to_first_byte={0, PrevTimeToFirstByte}}; + +reset_session(#http{user_agent=UA, + session_cookies=Cookies, + compressed={Compressed,_}, + status= {Status,_}, + time_to_first_byte={PrevTimeToFirstByte, _}}) -> + #http{session_cookies=Cookies, + user_agent=UA, + compressed={false,Compressed}, + status={none,Status}, + time_to_first_byte={0, PrevTimeToFirstByte}}. log_error(protocol,Error) -> put(protocol_error,Error), diff --git a/src/tsung/ts_local_mon.erl b/src/tsung/ts_local_mon.erl index 9948163bd..15e7f20cc 100644 --- a/src/tsung/ts_local_mon.erl +++ b/src/tsung/ts_local_mon.erl @@ -91,6 +91,8 @@ init([]) -> ts_utils:make_dir_raw(LogDir), case file:open(FileName,[write,raw, delayed_write]) of {ok, IODev} -> + Header = io_lib:format("date,pid,id,start,connect,request_duration,time_to_first_byte,duration,host,http_method,relative_url,http_status,request_size,response_size,transaction,match,error,tag~n",[]), + file:write(IODev, Header), {ok, #state{dump_iodev=IODev}}; {error, Reason} -> ?LOGF("Can't open dump file ~p on node ~p: ~p",[FileName, node(), Reason],?ERR), @@ -122,7 +124,7 @@ handle_cast(_, State=#state{dump_iodev=undefined}) -> {noreply, State}; handle_cast({dump, Who, When, What}, State=#state{dump_iodev=IODev}) -> - Data = io_lib:format("~w;~w;~s~n",[ts_utils:time2sec_hires(When),Who,What]), + Data = io_lib:format("~w,~w,~s~n",[ts_utils:time2sec_hires(When),Who,What]), file:write(IODev,Data), {noreply, State}; diff --git a/src/tsung/ts_mon_cache.erl b/src/tsung/ts_mon_cache.erl index 7df26320f..3090fab08 100644 --- a/src/tsung/ts_mon_cache.erl +++ b/src/tsung/ts_mon_cache.erl @@ -138,7 +138,7 @@ handle_cast({add_match, Data=[First|_Tail],{UserId,SessionId,RequestId,TimeStamp {noreply, State#state{stats = lists:append(Data, List), match = NewMatchList}}; handle_cast({dump, Who, When, What}, State=#state{protocol=Cache}) -> - Log = io_lib:format("~w;~w;~s~n",[ts_utils:time2sec_hires(When),Who,What]), + Log = io_lib:format("~w,~w,~s~n",[ts_utils:time2sec_hires(When),Who,What]), {noreply, State#state{protocol=[Log|Cache]}}; handle_cast(_Msg, State) -> diff --git a/src/tsung_controller/ts_mon.erl b/src/tsung_controller/ts_mon.erl index 2fdd49715..7eaae78d3 100644 --- a/src/tsung_controller/ts_mon.erl +++ b/src/tsung_controller/ts_mon.erl @@ -321,7 +321,7 @@ handle_cast({sendmsg, Who, When, What}, State=#state{type=full,dumpfile=Log}) -> {noreply, State}; handle_cast({dump, Who, When, What}, State=#state{type=protocol,dumpfile=Log}) -> - io:format(Log,"~w;~w;~s~n",[ts_utils:time2sec_hires(When),Who,What]), + io:format(Log,"~w,~w,~s~n",[ts_utils:time2sec_hires(When),Who,What]), {noreply, State}; handle_cast({dump, cached, Data}, State=#state{type=protocol,dumpfile=Log}) -> @@ -456,7 +456,7 @@ start_dump(State=#state{type=Type}) -> ?LOG("dump file opened, starting monitor~n",?INFO), case Type of protocol -> - io:format(Stream,"#date;pid;id;http method;host;URL;HTTP status;size;duration;transaction;match;error;tag~n",[]); + io:format(Stream,"date,pid,id,start,connect,request_duration,time_to_first_byte,duration,host,http_method,relative_url,http_status,request_size,response_size,transaction,match,error,tag~n",[]); _ -> ok end,