[WIP] Reworked Request timings in protocol/protocol_local Dumpfiles

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 <match> 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 <match> 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::
 

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
               }).
 
 

include/ts_profile.hrl

@@ -99,17 +99,21 @@
          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)
          buffer = <<>>, % buffer when we have to keep the response (we need
                      % 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

src/tsung/ts_client.erl

@@ -786,15 +786,17 @@ 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
                                         0 -> Now; %first request of a page
                                         _ -> %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 ->

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
+    ]).
 
 
 %%----------------------------------------------------------------------