From 7fa841b541225c10f8758e3ee77f84b3e6c1aa9d Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Wed, 25 Jun 2014 15:30:51 +0200 Subject: [PATCH 01/13] reindented http record and added time_to_first_byte --- include/ts_http.hrl | 23 ++++++++++++----------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/include/ts_http.hrl b/include/ts_http.hrl index 6a81af73e..19f6af745 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, % time when first byte was received + 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 }). From 7296c25f360508f18d041635086ac9c747520046 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Wed, 25 Jun 2014 15:36:20 +0200 Subject: [PATCH 02/13] set time to first byte --- src/tsung/ts_http_common.erl | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index c0238415d..423cbac86 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -279,7 +279,14 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == TotalSize = size(Data), Header = State#state_rcv.acc ++ List, - case parse_headers(HTTP, Header, State#state_rcv.host) of + NewHttp = case HTTP#http.body_size of + 0 -> + HTTP#http{time_to_first_byte=?NOW}; + _ -> + HTTP + end, + + case parse_headers(NewHttp, Header, State#state_rcv.host) of %% Partial header: {more, HTTPRec, Tail} -> ?LOGF("Partial Header: [HTTP=~p : Tail=~p]~n",[HTTPRec, Tail],?DEB), From 6e6e47d38e171da5f88674dcc1e26ba7d0b0cdc4 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Wed, 25 Jun 2014 16:08:32 +0200 Subject: [PATCH 03/13] added missing parts to catch time to first byte --- include/ts_http.hrl | 2 +- src/tsung/ts_http.erl | 25 ++++++++++++++----- src/tsung/ts_http_common.erl | 48 +++++++++++++++++++++++++----------- 3 files changed, 54 insertions(+), 21 deletions(-) diff --git a/include/ts_http.hrl b/include/ts_http.hrl index 19f6af745..57666d589 100644 --- a/include/ts_http.hrl +++ b/include/ts_http.hrl @@ -68,7 +68,7 @@ %% 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, - time_to_first_byte = 0, % time when first byte was received + time_to_first_byte = 0, % time when first byte was received for last request 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. diff --git a/src/tsung/ts_http.erl b/src/tsung/ts_http.erl index 9a647f088..b28f9e3d0 100644 --- a/src/tsung/ts_http.erl +++ b/src/tsung/ts_http.erl @@ -111,12 +111,25 @@ 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 -> + ""; + Time -> + ts_utils:time2sec_hires(Time) + end, + ts_utils:join(";",[ + TimeToFirstByte, + 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 + ]). %%---------------------------------------------------------------------- diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index 423cbac86..dd1ee3e94 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -270,7 +270,13 @@ matchdomain_url(Cookie, Host, URL) -> %% 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}; + NewHttp = case State#state_rcv.acc == [] of + 0 -> + Http#http{time_to_first_byte=?NOW}; + _ -> + Http + end, + {State#state_rcv{session=reset_session(NewHttp), ack_done = true}, [], true}; parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == none; HTTP#http.partial == true -> @@ -279,8 +285,8 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == TotalSize = size(Data), Header = State#state_rcv.acc ++ List, - NewHttp = case HTTP#http.body_size of - 0 -> + NewHttp = case State#state_rcv.acc of + [] -> HTTP#http{time_to_first_byte=?NOW}; _ -> HTTP @@ -316,25 +322,39 @@ 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 = case State#state_rcv.acc of + [] -> + Http#http{time_to_first_byte=?NOW}; + _ -> + Http + end, + ?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}) -> + NewHttp = case Http#http.body_size of + [] -> + Http#http{time_to_first_byte=?NOW}; + _ -> + Http + end, + DataSize = size(Data), ?DebugF("HTTP Body size=~p ~n",[DataSize]), - CLength = Http#http.content_length, - case Http#http.body_size + DataSize of + CLength = NewHttp#http.content_length, + case NewHttp#http.body_size + DataSize of CLength -> % end of response - {State#state_rcv{session=reset_session(Http), acc=[], ack_done = true, datasize = DataSize+PreviousSize}, - [], Http#http.close}; + {State#state_rcv{session=reset_session(NewHttp), acc=[], ack_done = true, datasize = DataSize+PreviousSize}, + [], NewHttp#http.close}; Size -> - {State#state_rcv{session = Http#http{body_size = Size}, ack_done = false, + {State#state_rcv{session = NewHttp#http{body_size = Size}, ack_done = false, datasize = DataSize+PreviousSize}, [], false} end. @@ -674,11 +694,11 @@ 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}} ; + compressed={Compressed,_}, status= {Status,_}, chunk_toread=Val, time_to_first_byte=TimeToFirstByte}) when Val > -1 -> + #http{session_cookies=Cookies,user_agent=UA,compressed={false,Compressed}, chunk_toread=-2, status={none,Status}, time_to_first_byte=TimeToFirstByte} ; 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,_}, time_to_first_byte=TimeToFirstByte}) -> + #http{session_cookies=Cookies,user_agent=UA,compressed={false,Compressed}, status={none,Status}, time_to_first_byte=TimeToFirstByte}. log_error(protocol,Error) -> put(protocol_error,Error), From 46ef7db1acf1b55afdb1a7fb73a9b8d921ec5aee Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Wed, 25 Jun 2014 16:29:16 +0200 Subject: [PATCH 04/13] only set time_to_first_byte when status is none --- src/tsung/ts_http_common.erl | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index dd1ee3e94..d64007bb9 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -270,8 +270,8 @@ matchdomain_url(Cookie, Host, URL) -> %% about the response if State#state_rcv.session %%---------------------------------------------------------------------- parse(closed, State=#state_rcv{session=Http}) -> - NewHttp = case State#state_rcv.acc == [] of - 0 -> + NewHttp = case {State#state_rcv.acc, Http#http.status} of + {[], none} -> Http#http{time_to_first_byte=?NOW}; _ -> Http @@ -285,8 +285,8 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == TotalSize = size(Data), Header = State#state_rcv.acc ++ List, - NewHttp = case State#state_rcv.acc of - [] -> + NewHttp = case {State#state_rcv.acc, HTTP#http.status} of + {[], {none, _}} -> HTTP#http{time_to_first_byte=?NOW}; _ -> HTTP @@ -322,8 +322,8 @@ 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 = case State#state_rcv.acc of - [] -> + NewHttp = case {State#state_rcv.acc, Http#http.status} of + {[], {none, _}} -> Http#http{time_to_first_byte=?NOW}; _ -> Http @@ -339,8 +339,8 @@ parse(Data, State=#state_rcv{session=Http}) when Http#http.chunk_toread >=0 -> %% continued normal transfer parse(Data, State=#state_rcv{session=Http, datasize=PreviousSize}) -> - NewHttp = case Http#http.body_size of - [] -> + NewHttp = case {State#state_rcv.acc, Http#http.status} of + {[], {none, _}} -> Http#http{time_to_first_byte=?NOW}; _ -> Http From fa964d85995923bdac3c2a7dfe4fe6abde32a029 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Wed, 25 Jun 2014 17:48:08 +0200 Subject: [PATCH 05/13] added start time and time to connect to dump --- include/ts_http.hrl | 2 +- include/ts_profile.hrl | 1 + src/tsung/ts_client.erl | 25 ++++++++++++++++++------- src/tsung/ts_http.erl | 11 +++++++---- src/tsung/ts_http_common.erl | 20 ++++++++++++-------- 5 files changed, 39 insertions(+), 20 deletions(-) diff --git a/include/ts_http.hrl b/include/ts_http.hrl index 57666d589..cb20662bd 100644 --- a/include/ts_http.hrl +++ b/include/ts_http.hrl @@ -68,7 +68,7 @@ %% 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, - time_to_first_byte = 0, % time when first byte was received for last request + 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. diff --git a/include/ts_profile.hrl b/include/ts_profile.hrl index a764e142d..a9331f867 100644 --- a/include/ts_profile.hrl +++ b/include/ts_profile.hrl @@ -99,6 +99,7 @@ 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) diff --git a/src/tsung/ts_client.erl b/src/tsung/ts_client.erl index 9b8afa2e0..c05ebfe4d 100644 --- a/src/tsung/ts_client.erl +++ b/src/tsung/ts_client.erl @@ -786,7 +786,7 @@ 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} -> case catch send(Protocol, NewSocket, Message, Host, Port) of ok -> PageTimeStamp = case State#state_rcv.page_timestamp of @@ -806,6 +806,7 @@ handle_next_request(Request, State) -> proto_opts = ProtoOpts#proto_opts{is_first_connect = false}, page_timestamp= PageTimeStamp, send_timestamp= Now, + duration_to_connect= DurationToConnect, timestamp= Now }, case Request#ts_request.ack of no_ack -> @@ -976,10 +977,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 +1005,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 +1017,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 +1096,18 @@ 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.datasize, % response size + % TODO add request size + NewState#state_rcv.starttime, % time when request was started + NewState#state_rcv.duration_to_connect, % time required to establish the TCP connection or 0 + Elapsed, % total request-response duration + Transactions + }), case Close of true -> diff --git a/src/tsung/ts_http.erl b/src/tsung/ts_http.erl index b28f9e3d0..27686d05a 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,Size,StartTime,DurationToConnect,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) -> @@ -112,18 +112,21 @@ dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,Duration,Transa end, Tr=ts_utils:log_transaction(Transactions), TimeToFirstByte = case HttpResp#http.time_to_first_byte of - 0 -> + {0,0} -> ""; - Time -> - ts_utils:time2sec_hires(Time) + {_,Time} -> + ts_utils:elapsed(StartTime, Time) + % ts_utils:time2sec_hires(Time) end, ts_utils:join(";",[ + ts_utils:time2sec_hires(StartTime), TimeToFirstByte, integer_to_list(UserId), atom_to_list(HttpReq#http_request.method), Server, get(last_url), Status,integer_to_list(Size), + DurationToConnect, Duration, Tr, Match, diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index d64007bb9..2b752f30b 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -272,7 +272,8 @@ matchdomain_url(Cookie, Host, URL) -> parse(closed, State=#state_rcv{session=Http}) -> NewHttp = case {State#state_rcv.acc, Http#http.status} of {[], none} -> - Http#http{time_to_first_byte=?NOW}; + {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, + Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; _ -> Http end, @@ -287,7 +288,8 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == NewHttp = case {State#state_rcv.acc, HTTP#http.status} of {[], {none, _}} -> - HTTP#http{time_to_first_byte=?NOW}; + {_, PrevTimeToFirstByte} = HTTP#http.time_to_first_byte, + HTTP#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; _ -> HTTP end, @@ -324,7 +326,8 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == parse(Data, State=#state_rcv{session=Http}) when Http#http.chunk_toread >=0 -> NewHttp = case {State#state_rcv.acc, Http#http.status} of {[], {none, _}} -> - Http#http{time_to_first_byte=?NOW}; + {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, + Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; _ -> Http end, @@ -341,7 +344,8 @@ parse(Data, State=#state_rcv{session=Http}) when Http#http.chunk_toread >=0 -> parse(Data, State=#state_rcv{session=Http, datasize=PreviousSize}) -> NewHttp = case {State#state_rcv.acc, Http#http.status} of {[], {none, _}} -> - Http#http{time_to_first_byte=?NOW}; + {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, + Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; _ -> Http end, @@ -694,11 +698,11 @@ 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, time_to_first_byte=TimeToFirstByte}) when Val > -1 -> - #http{session_cookies=Cookies,user_agent=UA,compressed={false,Compressed}, chunk_toread=-2, status={none,Status}, time_to_first_byte=TimeToFirstByte} ; + 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=TimeToFirstByte}) -> - #http{session_cookies=Cookies,user_agent=UA,compressed={false,Compressed}, status={none,Status}, time_to_first_byte=TimeToFirstByte}. + 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), From b93e9bb3ceb2bd95a816cad2a1d45599b3133242 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 10:17:19 +0200 Subject: [PATCH 06/13] fixed clauses --- src/tsung/ts_http_common.erl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index 2b752f30b..2a598ad52 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -271,7 +271,7 @@ matchdomain_url(Cookie, Host, URL) -> %%---------------------------------------------------------------------- parse(closed, State=#state_rcv{session=Http}) -> NewHttp = case {State#state_rcv.acc, Http#http.status} of - {[], none} -> + {[], {none, _}} -> {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; _ -> @@ -303,10 +303,10 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == {ok, Http=#http{content_length=0, chunk_toread=0}, Tail} -> NewCookies = concat_cookies(Http#http.cookie, Http#http.session_cookies), case parse_chunked(Tail, State#state_rcv{session=Http, acc=[]}) of - {NewState=#state_rcv{ack_done=false, session=NewHttp}, Opts} -> - {NewState#state_rcv{session=NewHttp#http{session_cookies=NewCookies}}, Opts, false}; - {NewState=#state_rcv{session=NewHttp}, Opts} -> - {NewState#state_rcv{acc=[],session=NewHttp#http{session_cookies=NewCookies}}, Opts, Http#http.close} + {NewState=#state_rcv{ack_done=false, session=Http}, Opts} -> + {NewState#state_rcv{session=Http#http{session_cookies=NewCookies}}, Opts, false}; + {NewState=#state_rcv{session=NewHttp2}, Opts} -> + {NewState#state_rcv{acc=[],session=NewHttp2#http{session_cookies=NewCookies}}, Opts, Http#http.close} end; {ok, Http=#http{content_length=0, close=true}, _} -> %% no content length, close=true: the server will close the connection From af52dcbe9633207010f64a5dfba527c6eb17b6cb Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 12:11:07 +0200 Subject: [PATCH 07/13] added all timing data to dumpfile * updated documentation * "fixed" duration in dumpfile --- docs/conf-file.rst | 45 +++++++++++++++++++-------------- include/ts_profile.hrl | 1 + src/tsung/ts_client.erl | 22 ++++++++-------- src/tsung/ts_http.erl | 18 ++++++------- src/tsung/ts_http_common.erl | 40 +++++++++++++++++++++-------- src/tsung/ts_local_mon.erl | 2 +- src/tsung_controller/ts_mon.erl | 2 +- 7 files changed, 78 insertions(+), 52 deletions(-) diff --git a/docs/conf-file.rst b/docs/conf-file.rst index f3f7dcadd..72b90089f 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,38 @@ 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,time_to_first_byte,duration,host,http_method,relative_url,http_status,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 +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 + 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.) +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_profile.hrl b/include/ts_profile.hrl index a9331f867..0f81d7fc7 100644 --- a/include/ts_profile.hrl +++ b/include/ts_profile.hrl @@ -104,6 +104,7 @@ 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 + 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) diff --git a/src/tsung/ts_client.erl b/src/tsung/ts_client.erl index c05ebfe4d..fe9c32ee6 100644 --- a/src/tsung/ts_client.erl +++ b/src/tsung/ts_client.erl @@ -1097,15 +1097,15 @@ handle_data_msg(Data,State=#state_rcv{dump=Dump,request=Req,id=Id,clienttype=Typ 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, % http_request - NewState#state_rcv.session, % session - Id, % client id - NewState#state_rcv.host, % target host - NewState#state_rcv.datasize, % response size - % TODO add request size - NewState#state_rcv.starttime, % time when request was started - NewState#state_rcv.duration_to_connect, % time required to establish the TCP connection or 0 - Elapsed, % total request-response duration + Req, % http_request + NewState#state_rcv.session, % session + Id, % client id + NewState#state_rcv.host, % target host + NewState#state_rcv.datasize, % response size, TODO add request (req. header + payload) 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.completed_timestamp, % time when request was finished + Elapsed, % duration of total request-response duration, excluding connect time Transactions }), @@ -1244,9 +1244,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 27686d05a..66e54f5de 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,StartTime,DurationToConnect,Duration,Transactions})-> +dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,StartTime,DurationToConnect,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) -> @@ -116,18 +116,18 @@ dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,StartTime,Durat ""; {_,Time} -> ts_utils:elapsed(StartTime, Time) - % ts_utils:time2sec_hires(Time) end, - ts_utils:join(";",[ - ts_utils:time2sec_hires(StartTime), - TimeToFirstByte, + ts_utils:join(",", [ integer_to_list(UserId), - atom_to_list(HttpReq#http_request.method), - Server, - get(last_url), - Status,integer_to_list(Size), + ts_utils:time2sec_hires(StartTime) - DurationToConnect/1000, DurationToConnect, + TimeToFirstByte, Duration, + Server, + atom_to_list(HttpReq#http_request.method), + erlang:iolist_to_binary([<<"\"">>, get(last_url), <<"\"">>]), + Status, + integer_to_list(Size), Tr, Match, Error, diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index 2a598ad52..435cbb006 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -277,7 +277,7 @@ parse(closed, State=#state_rcv{session=Http}) -> _ -> Http end, - {State#state_rcv{session=reset_session(NewHttp), ack_done = true}, [], true}; + {State#state_rcv{session=reset_session(NewHttp), ack_done = true, completed_timestamp=?NOW}, [], true}; parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == none; HTTP#http.partial == true -> @@ -355,7 +355,7 @@ parse(Data, State=#state_rcv{session=Http, datasize=PreviousSize}) -> CLength = NewHttp#http.content_length, case NewHttp#http.body_size + DataSize of CLength -> % end of response - {State#state_rcv{session=reset_session(NewHttp), acc=[], ack_done = true, datasize = DataSize+PreviousSize}, + {State#state_rcv{session=reset_session(NewHttp), acc=[], ack_done = true, datasize = DataSize+PreviousSize, completed_timestamp=?NOW}, [], NewHttp#http.close}; Size -> {State#state_rcv{session = NewHttp#http{body_size = Size}, ack_done = false, @@ -370,14 +370,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}, @@ -417,7 +418,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 }, [] }; @@ -427,7 +429,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. @@ -698,11 +700,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, 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}}. + 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..32beb4e99 100644 --- a/src/tsung/ts_local_mon.erl +++ b/src/tsung/ts_local_mon.erl @@ -122,7 +122,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_controller/ts_mon.erl b/src/tsung_controller/ts_mon.erl index 2fdd49715..0a050dad4 100644 --- a/src/tsung_controller/ts_mon.erl +++ b/src/tsung_controller/ts_mon.erl @@ -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,time_to_first_byte,duration,host,http_method,relative_url,http_status,response_size,transaction,match,error,tag~n",[]); _ -> ok end, From 157edaedf113cbd4fd3acbd5d89b2b1387ce0c09 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 12:26:50 +0200 Subject: [PATCH 08/13] added proper CSV headers to dumpfiles --- src/tsung/ts_local_mon.erl | 2 ++ src/tsung/ts_mon_cache.erl | 2 +- src/tsung_controller/ts_mon.erl | 2 +- 3 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/tsung/ts_local_mon.erl b/src/tsung/ts_local_mon.erl index 32beb4e99..a722c5679 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,time_to_first_byte,duration,host,http_method,relative_url,http_status,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), 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 0a050dad4..8bf77cee5 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}) -> From dddf3306971d9a66c4db353538992176d08eb5a7 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 16:22:12 +0200 Subject: [PATCH 09/13] move time to first byte extraction to it's own function (DRY) --- src/tsung/ts_http_common.erl | 72 +++++++++++++++--------------------- 1 file changed, 29 insertions(+), 43 deletions(-) diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index 435cbb006..ea3deca24 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -269,32 +269,21 @@ 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}) -> - NewHttp = case {State#state_rcv.acc, Http#http.status} of - {[], {none, _}} -> - {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, - Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; - _ -> - Http - end, - {State#state_rcv{session=reset_session(NewHttp), ack_done = true, completed_timestamp=?NOW}, [], true}; +parse(closed, State) -> + Http = update_time_to_first_byte(State), + + {State#state_rcv{session=reset_session(Http), ack_done = true, completed_timestamp=?NOW}, [], true}; -parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == none; - HTTP#http.partial == 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, - NewHttp = case {State#state_rcv.acc, HTTP#http.status} of - {[], {none, _}} -> - {_, PrevTimeToFirstByte} = HTTP#http.time_to_first_byte, - HTTP#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; - _ -> - HTTP - end, + HTTP = update_time_to_first_byte(State), - case parse_headers(NewHttp, Header, State#state_rcv.host) of + case parse_headers(HTTP, Header, State#state_rcv.host) of %% Partial header: {more, HTTPRec, Tail} -> ?LOGF("Partial Header: [HTTP=~p : Tail=~p]~n",[HTTPRec, Tail],?DEB), @@ -303,10 +292,10 @@ parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status) == {ok, Http=#http{content_length=0, chunk_toread=0}, Tail} -> NewCookies = concat_cookies(Http#http.cookie, Http#http.session_cookies), case parse_chunked(Tail, State#state_rcv{session=Http, acc=[]}) of - {NewState=#state_rcv{ack_done=false, session=Http}, Opts} -> - {NewState#state_rcv{session=Http#http{session_cookies=NewCookies}}, Opts, false}; - {NewState=#state_rcv{session=NewHttp2}, Opts} -> - {NewState#state_rcv{acc=[],session=NewHttp2#http{session_cookies=NewCookies}}, Opts, Http#http.close} + {NewState=#state_rcv{ack_done=false, session=NewHttp}, Opts} -> + {NewState#state_rcv{session=NewHttp#http{session_cookies=NewCookies}}, Opts, false}; + {NewState=#state_rcv{session=NewHttp}, Opts} -> + {NewState#state_rcv{acc=[],session=NewHttp#http{session_cookies=NewCookies}}, Opts, Http#http.close} end; {ok, Http=#http{content_length=0, close=true}, _} -> %% no content length, close=true: the server will close the connection @@ -324,13 +313,7 @@ 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 = case {State#state_rcv.acc, Http#http.status} of - {[], {none, _}} -> - {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, - Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; - _ -> - Http - end, + NewHttp = update_time_to_first_byte(State), ?DebugF("Parse chunk data = [~s]~n", [Data]), case read_chunk_data(Data,State,NewHttp#http.chunk_toread,NewHttp#http.body_size) of @@ -341,27 +324,30 @@ parse(Data, State=#state_rcv{session=Http}) when Http#http.chunk_toread >=0 -> end; %% continued normal transfer -parse(Data, State=#state_rcv{session=Http, datasize=PreviousSize}) -> - NewHttp = case {State#state_rcv.acc, Http#http.status} of - {[], {none, _}} -> - {_, PrevTimeToFirstByte} = Http#http.time_to_first_byte, - Http#http{time_to_first_byte={?NOW, PrevTimeToFirstByte}}; - _ -> - Http - end, +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 = NewHttp#http.content_length, - case NewHttp#http.body_size + DataSize of + CLength = Http#http.content_length, + case Http#http.body_size + DataSize of CLength -> % end of response - {State#state_rcv{session=reset_session(NewHttp), acc=[], ack_done = true, datasize = DataSize+PreviousSize, completed_timestamp=?NOW}, - [], NewHttp#http.close}; + {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 = NewHttp#http{body_size = Size}, ack_done = false, + {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 From 7dd1e0cc6a18fc06198555adf40900c51b835618 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 18:33:55 +0200 Subject: [PATCH 10/13] fixed warning --- src/tsung/ts_http.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/tsung/ts_http.erl b/src/tsung/ts_http.erl index 66e54f5de..f4496042a 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,StartTime,DurationToConnect,EndTime,Duration,Transactions})-> +dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,StartTime,DurationToConnect,_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) -> From 7d73d307d433bda34ff53f02277046d01181d38c Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 18:59:03 +0200 Subject: [PATCH 11/13] fixed ts_http_common:parse function claused --- src/tsung/ts_http_common.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/tsung/ts_http_common.erl b/src/tsung/ts_http_common.erl index ea3deca24..da4f8d8e9 100644 --- a/src/tsung/ts_http_common.erl +++ b/src/tsung/ts_http_common.erl @@ -274,7 +274,7 @@ parse(closed, State) -> {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; +parse(Data, State=#state_rcv{session=#http{status={Status,_}, partial=Partial}}) when Status == none; Partial == true -> List = binary_to_list(Data), From 6dcc4bed3e627579b65519a024109458964cdf4e Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 19:03:40 +0200 Subject: [PATCH 12/13] added request size and duration to dump files --- docs/conf-file.rst | 4 +++- include/ts_profile.hrl | 4 +++- src/tsung/ts_client.erl | 25 +++++++++++++++---------- src/tsung/ts_http.erl | 6 ++++-- src/tsung/ts_local_mon.erl | 2 +- src/tsung_controller/ts_mon.erl | 2 +- 6 files changed, 27 insertions(+), 16 deletions(-) diff --git a/docs/conf-file.rst b/docs/conf-file.rst index 72b90089f..c45291b83 100644 --- a/docs/conf-file.rst +++ b/docs/conf-file.rst @@ -37,7 +37,7 @@ with the following data: .. code-block:: text - date,pid,id,start,connect,time_to_first_byte,duration,host,http_method,relative_url,http_status,response_size,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: @@ -49,12 +49,14 @@ 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 + 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) diff --git a/include/ts_profile.hrl b/include/ts_profile.hrl index 0f81d7fc7..fa6d121d2 100644 --- a/include/ts_profile.hrl +++ b/include/ts_profile.hrl @@ -103,7 +103,8 @@ 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 @@ -112,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 fe9c32ee6..f0ab6a5e7 100644 --- a/src/tsung/ts_client.erl +++ b/src/tsung/ts_client.erl @@ -794,7 +794,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 +807,8 @@ 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(Now, ?NOW), + request_size= MessageSize, duration_to_connect= DurationToConnect, timestamp= Now }, case Request#ts_request.ack of @@ -1097,15 +1100,17 @@ handle_data_msg(Data,State=#state_rcv{dump=Dump,request=Req,id=Id,clienttype=Typ 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, % http_request - NewState#state_rcv.session, % session - Id, % client id - NewState#state_rcv.host, % target host - NewState#state_rcv.datasize, % response size, TODO add request (req. header + payload) 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.completed_timestamp, % time when request was finished - Elapsed, % duration of total request-response duration, excluding connect time + 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 }), diff --git a/src/tsung/ts_http.erl b/src/tsung/ts_http.erl index f4496042a..d3477cfed 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,StartTime,DurationToConnect,_EndTime,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) -> @@ -121,13 +121,15 @@ dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,Size,StartTime,Durat integer_to_list(UserId), ts_utils:time2sec_hires(StartTime) - DurationToConnect/1000, DurationToConnect, + RequestDuration, TimeToFirstByte, Duration, Server, atom_to_list(HttpReq#http_request.method), erlang:iolist_to_binary([<<"\"">>, get(last_url), <<"\"">>]), Status, - integer_to_list(Size), + integer_to_list(RequestSize), + integer_to_list(ResponseSize), Tr, Match, Error, diff --git a/src/tsung/ts_local_mon.erl b/src/tsung/ts_local_mon.erl index a722c5679..15e7f20cc 100644 --- a/src/tsung/ts_local_mon.erl +++ b/src/tsung/ts_local_mon.erl @@ -91,7 +91,7 @@ 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,time_to_first_byte,duration,host,http_method,relative_url,http_status,response_size,transaction,match,error,tag~n",[]), + 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} -> diff --git a/src/tsung_controller/ts_mon.erl b/src/tsung_controller/ts_mon.erl index 8bf77cee5..7eaae78d3 100644 --- a/src/tsung_controller/ts_mon.erl +++ b/src/tsung_controller/ts_mon.erl @@ -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,start,connect,time_to_first_byte,duration,host,http_method,relative_url,http_status,response_size,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, From 099afc4f4907e676798318238cc99d23a56bf134 Mon Sep 17 00:00:00 2001 From: Sebastian Cohnen Date: Thu, 26 Jun 2014 19:24:31 +0200 Subject: [PATCH 13/13] fixed "duration", time to connect was missing --- docs/conf-file.rst | 2 +- src/tsung/ts_client.erl | 3 ++- src/tsung/ts_http.erl | 2 +- 3 files changed, 4 insertions(+), 3 deletions(-) diff --git a/docs/conf-file.rst b/docs/conf-file.rst index c45291b83..78b5298d2 100644 --- a/docs/conf-file.rst +++ b/docs/conf-file.rst @@ -51,7 +51,7 @@ 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 + time to first byte + rest of transfer) +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 diff --git a/src/tsung/ts_client.erl b/src/tsung/ts_client.erl index f0ab6a5e7..75115b6ce 100644 --- a/src/tsung/ts_client.erl +++ b/src/tsung/ts_client.erl @@ -787,6 +787,7 @@ handle_next_request(Request, State) -> ProtoOpts = State#state_rcv.proto_opts, case reconnect(Socket,Host,Port,{Protocol,ProtoOpts},State#state_rcv.ip) of {ok, NewSocket, DurationToConnect} -> + ConnectTime = ?NOW, case catch send(Protocol, NewSocket, Message, Host, Port) of ok -> PageTimeStamp = case State#state_rcv.page_timestamp of @@ -807,7 +808,7 @@ 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(Now, ?NOW), + send_completed_duration= ts_utils:elapsed(ConnectTime, ?NOW), request_size= MessageSize, duration_to_connect= DurationToConnect, timestamp= Now }, diff --git a/src/tsung/ts_http.erl b/src/tsung/ts_http.erl index d3477cfed..10064770f 100644 --- a/src/tsung/ts_http.erl +++ b/src/tsung/ts_http.erl @@ -123,7 +123,7 @@ dump2str({#ts_request{param=HttpReq},HttpResp,UserId,Server,RequestSize,Response DurationToConnect, RequestDuration, TimeToFirstByte, - Duration, + Duration + DurationToConnect, Server, atom_to_list(HttpReq#http_request.method), erlang:iolist_to_binary([<<"\"">>, get(last_url), <<"\"">>]),