[WIP] Reworked Request timings in protocol/protocol_local Dumpfiles

[tisba]

This is Work in Progress: The basic stuff should work, but I'm running lot's of tests to confirm that all timings are correct.

My goal was to have the following timings to the dumpfile (when using protocol or protocol_local):

1. Timestamp of Start: When was the request started, before a possible TCP connect?
2. Time to Connect: How long did it take to establish the TCP connection?
3. Duration to send request: How long did it take to send the request (headers + payload if any)?
4. Time to First Byte: How long did it take to receive the first byte (indication for server processing time)
5. Request-Response Duration: Connect + Time to First Byte + Time of Remaining Data Transfer

The time of start (1) was not exposed to the dumpfiles previously, 2. was measured but not exposed either, 4. is measured when the first data is received and the HTTP status is not set (see ts_http_common:parse). 5. was already present in dumpfile.

~~I haven't found a good way to get the Duration to send request timing, any hints are welcome.~~

I also added request_size which is the size of the request headers + request payload/body, if any.

I updated the documentation ("6.1. File structure") to reflect the changes to the dumpfile. I also made it more explicit that the previously existing date value is NOT the end of the request, but the point in time when the request was logged. That is almost the same most of the time, but it made me almost crazy when I was trying to adding up the numbers :)

I also made the dumpfile output RFC4180 compliant and added header to protocol_local files.

Please note that I'm an Erlang noob and my changes are probably not very idiomatic Erlang. I appreciate any feedback! When this gets accepted, I'm happy to squash my changes to a single, descriptive commit.

.. code-block:: text

   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 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 (").

[rodo]

Made the datafile RFC compliant is always a good thing, but need a lot of communication to all users before apply it in master. Maybe in 2 different changes, one that do the compliance and after the one adding new fields.

[tisba]

@rodo making it compliant will require a good communication to users (since fields are separated by , now and fields may be quoted). I'm not sure what the benefit is of doing that before adding the new values.

[nniclausse]

Just a few remarks:

• update_time_to_first_byte should only be called in one clause of parse: the one when Status=none; the other called are useless
• reconnect could return ConnectTime to avoid an extra call to now()
• since we compute send_completed_duration independently of the protocol, we could add this to ts_mon also

Otherwise, i'm OK to be RFC compliant

[tisba]

Thanks for the remarks!

I was thinking about adding more of those new timings to ts_mon anyway, since they are also very interesting for larger tests or in situations where protocol or protocol_local cannot be used.