Menu
▾
▴
Home
============
INTRODUCTION
============
This tool is designed to help administrators identify application latency.
While the intention is to maximize usefulness by being protocol agnostic,
this also means that the tool may not be effective in analyzing all kinds
of application latencies. Note that ping should be used to measure network
latencies.
In order to measure service latencies, this tool captures packets of interest
off the wire, and observes the timing together with the direction of the
payload. A client is defined as the node which initiates a conversation,
and the server is the machine to which the conversation is initiated with.
Whatever the client sends will be called a request, and whatever the server
sends will be called the response.
Let's begin with a simple example with a DNS service on udp :
CLIENT SERVER
8:40:26.000 A? www.facebook.com -->
8:40:26.220 <-- A 69.171.224.12
From the above example, we can see that the DNS service took 220 ms to
respond. Let's take a look at a slightly more complicated example. In this
case, an LDAP search. If we strip away the SYN handshake, ACK responses with
no payload and the FIN teardown, the packet trace looks like this :
CLIENT SERVER
8:46:28.164 bind request -->
8:46:28.179 <-- bind response success
8:46:28:180 search request -->
8:46:28:198 <-- search result
8:46:28:199 unbind request -->
In the above example, we see a total of 2 requests and 2 replies. The unbind
request did not result in a layer 7 response so we ignore this. For the first
request (ie, the bind request), the service latency was 15ms and for the
second request (ie, the search), the service latency was 18ms. Let's say we
modified the LDAP search such that more than 1 packet is needed for the entire
results to be returned. The packet trace now looks like this :
CLIENT SERVER
8:55:43.594 bind request -->
8:55:43.608 <-- bind response success
8:55:43:609 search request -->
8:55:43:628 <-- search result
8:55:43:629 <-- search result
8:55:43:630 <-- search result
8:55:43:649 <-- search result
8:55:43:650 <-- search result
8:55:43:651 <-- search result
8:55:43:652 unbind request -->
Now, the first request received a response in 14ms. The second request
received a response after 19ms, and packets continued to arrive until 42ms
later. Thus, for requests involving multiple packets in the response, we have
2 timings of interest, we call these the "reply_start" and "reply_complete".
Note that "reply_complete" is the timing of the last response packet. Let's
now take a look at a typical SMTP transaction :
Message CLIENT SERVER
1. <-- 220 foo.com
2. HELO bar -->
3. <-- 250 example.com
4. MAIL FROM foo@bar.com -->
5. <-- 250 ok
6. RCPT TO: bar@foo.com -->
7. <-- 250 ok
8. DATA -->
9. <-- 354 end data with .
10. From: me -->
11. To: you -->
12. Subject: boo -->
13. <NL> -->
14. body -->
15. "." -->
16. <-- 250 queued as 12345
17. QUIT -->
18. <-- 221 bye
In the above example, the session starts off with a "unsolicited" response
from the server, thus we ignore this. The first request starts with the
"HELO" followed by a "250" response. Subsequently the client sends the
"MAIL FROM", "RCPT TO", and "DATA" requests, each of which triggers an
immediate response from the server. The client then sends several packets
of data before the server reponds with the "250 queued as 12345". Since we
are tracking service responses, the service latency is measured as the time
between the last transmitted request message (ie, message 15), and the time
of the server's response (ie, message 16). From this entire SMTP transaction,
we are able to make the following measurements :
- total number of requests/responses (in this case 6).
- total response wait time so far
- total bytes in requests
- total bytes in responses
- minimum response latency so far
- average response latency so far
- maximum response latency so far
Note that in the case of TCP, there is a very definite start and end of the
session (marked by the SYN and FIN packets). However in UDP, while the start
of a "session" can be determined by the first packet sent, the end of the
"session" is not easily determined unless an inactivity period elapses.
==============
IMPLEMENTATION
==============
In order to track a particular service's latency, the minimum required
information we need is :
a) IP address where the service runs
b) port number where the service runs
c) the protocol (ie, tcp or udp)
For both TCP and UDP, a session is uniquely identified based on a composite
key derrived from
<source IP>:<source port> <destination IP:destination port>
This tool may track multiple sessions on a host. Each time a packet is pulled
from the wire, we match it against an existing session (or create a new one)
and then update some session information, including monitoring the session
state. The "session state" is one of the following :
STATE NOTES
----- -----
request_sent at least 1 request packet has been sent
receiving_response at least 1 response packet has been received
closed FIN handshake detected or idle time out
Each time there is a state change, we may update session counters for tracking
response latency, byte counters and so on. This program utilizes a dedicated
thread to pull packets and update data structures (data capture thread), and
another thread for performing reporting and clean up (reporting thread). The
role of the reporting thread is to examine all sessions being tracked (bear
in mind some may have been closed), consolidate the results and write a report
to disk. Once the report is written, memory allocated to closed sessions can
be released.
Since we want to track a (potentially) high number of concurrent sessions,
individual data structures should be arranged in a manner that is quickly
accessible (ie, reduce search and update time). The "best" algorithm for
implementing this storage really depends on the magnitude of sessions we're
realistically tracking. Storage could be implemented as linked lists, array
of pointers, a hash table, etc. Accessing individual session structures has
been implemented as a number of architecture agnostic function prototypes :
int stor_init (int debug_level)
- initialize internal storage for use.
int stor_add (Session *ses)
- add a new "ses" data structure (note, data in "ses" is privately copied).
int stor_get (Session ses, struct in_addr ip, unsigned short port)
- copies the Session data structure for ip:port into the "ses" buffer.
int stor_update (Session *ses)
- locate an existing session and update it with the supplied structure.
int stor_delete (struct in_addr *ip, unsigned short port)
- removes the data structure identified by ip:port from internal storage.
int stor_report (int fd)
- report contents of internal storage to the specified file descriptor.
int stor_list (struct in_addr addr_list, unsigned char port_list)
- writes a null terminated list of <ip>:<port> elements (ie, last element
is zero'ed). The caller must free() these arrays when no longer needed.</port></ip>
All functions return 0 on success, non-zero if an error was encountered.
Despite this program being multi-threaded, we do not use locks which may
lead to blocking. Instead, we rely on the atomicity of changing pointers to
ensure consistency of data as it is being manipulated in flight.
=========
REPORTING
=========
Recall that the purpose of this app is to monitor a particular application's
latency every interval of time. Thus, whenever it is time to generate a report,
we consolidate all completed session statistics and then clear all session
counters. As long as 1 request/response transaction occured over the last time
interval, each report will consist of the following findings :
- total transactions in the last reporting interval
- minimum latency for first response
- maximum latency for first response
- average latency for first response
- average latency for complete response
For example :
2012-01-26 20:40:10 transacts:46 min:48 max:890 ave_start:482 ave_complete:492
The time units in the above report are in milliseconds.
=======
RUNTIME
=======
The capture engine consumes about 3.5MB of memory (not including buffers
allocated for session tracking). It utilizes 1.0 seconds of CPU time for
every 100,000 packets pulled from the wire (on an Intel Core 2 Q8200 cpu),
this is will debugging turned off.
====
BUGS
====
- IP fragments are not correctly handled.
- TCP retransmissions are not handled correctly.
- If a host resolves to more than 1 IP address, this program aborts.
Project Admins:
