Understanding Policy Trace Checkpoint Timing on Edge SWG (formerly ProxySG)
Article ID: 168320
Updated On:
Products
Issue/Introduction
This article is a quick reference for an explanation of the values of the transaction and checkpoint timings in policy traces on Edge SWG (formerly ProxySG) appliances.
Resolution
The timings are given in the new policy trace help with understanding how much time it takes for an Edge SWG (formerly ProxySG) to serve a web request. The timings start at time 0 and for each keyword "start" the time that follows is elapsed milliseconds from the beginning of the request. Any timings under 1ms are rounded to 0ms.
Here's an example trace output with descriptions of each policy review segment:
________________________________________________________________________________________________________________________
url.category: Reference@Blue Coat
total categorization time: 1 ß total time for categorization of URL
static categorization time: 1 ß categorization of URL excluding DRTR
________________________________________________________________________________________________________________________
Transaction timing: total-transaction-time 331 ms ß total time to process the web request
Checkpoint timings:
new-connection: start 1 elapsed 1 ms ß Finished establishing client side TCP conn in 1ms
client-in: start 2 elapsed 104 ms ßclient started sending data 2ms in, finished in 104ms
server-out: start 107 elapsed 0 ms ßServer side conn started at 107ms
server-in: start 318 elapsed 5 ms ßServer started sending response at 318ms and finished in 5ms
client-out: start 329 elapsed 1 ms ß Proxy started sending data to client at 329ms, took 1ms
access-logging: start 330 elapsed 1 ms ß At 330ms, access log entry created and took 1ms to write
stop-transaction: start 331 elapsed 0 ms ß transaction ended at 331ms from the start
Total Policy evaluation time: 112 ms ß took 112ms to evaluate policy
url_categorization complete time: 103 ß URL categorization completed at 103ms from beginning
ICAP Response Scan: start 324 delay 4 finish 329 ß ICAP response started at 324ms and ended 329ms, took 4ms to scan
response categories added: 329 ß Response category assigned at 329ms
server connection: start 107 ß server connection started at 107ms
DNS Lookup: start 107 elapsed 0 ms ß DNS lookup started at 107ms and it took 0ms to complete (probably cached)
server connection: connected 191 first-byte 317 last_byte 324 ß server connection complete at 191ms, first byte recv'ed at 317ms and last byte 324ms
client connection: first-response-byte 330 last-response-byte 330 ß first response byte delivered to client at 330ms and last byte delivered 330ms
________________________________________________________________________________________________________________________
Total time added: 111 ms ß total time added web request with policy, icap, etc
Total latency to first byte: 202 ms ß really, this is Request Latency + OCS connect time + Response latency (first byte)
Request latency: 105 ms ß latency before sending request to server
OCS connect time: 84 ms ß time it took to establish TCP conn with OCS
Response latency (first byte): 13 ms ß delay added by proxy/AV until first byte delivered to client
Response latency (last byte): 6 ms ß delay added by proxy/AV until last byte delivered to client
________________________________________________________________________________________________________________________
For a request that is being served from the cache on the proxy, the value "cache-hit: start 1 elapsed 0 ms" may be present, however, the proxy may still reach out to the OCS to verify the object in the local appliance cache.
Notes regarding SSL policy timing values
In respect to the following variables:
___________________________
total categorization time: 0
static categorization time: 0
___________________________
The zeroes above are from the fact that the categorization did not happen for the URL/Destination in question, since for SSL transactions the categories are determined by server certificate hostname.
Let's look at the timings reported from an SSL transaction:
________________________________________________________________________________________________________________________
Transaction timing: total-transaction-time 478 ms
Checkpoint timings:
new-connection: start 1 elapsed 0 ms
client-in: start 1 elapsed 0 ms
server-out: start 1 elapsed 0 ms
server-in: start 250 elapsed 0 ms
stop-transaction: start 478 elapsed 0 ms
Total Policy evaluation time: 0 ms
ssl server hello complete: 246 ß The SSL server hello handshake completed 246 ms into the transaction
url_categorization complete time: 479 ß this is a bogus value for SSL. This value is really the end time of transaction and policy trace logging
ssl_server started intercept: 250 ß time proxy started SSL intercept
server connection: start 1
DNS Lookup: start 1 elapsed 0 ms
server connection: connected 83
Total time added: 0 ms
Total latency to first byte: 82 ms
Request latency: 0 ms
OCS connect time: 82 ms
Response latency (first byte): 0 ms
Response latency (last byte): 0 ms
________________________________________________________________________________________________________________________
The SSL policy transaction above did not have any bytes transferred and no latency was added. The reason for this was because this is an example of an SSL connection that the proxy uses to conduct an interception decision while also verifying/validating the upstream OCS.
Feedback
