This article is a quick reference for an explanation of the values of the transaction and checkpoint timings in policy traces on ProxySG or Advanced Secure Gateway (ASG).
The timings are given in the new policy trace help with understanding how much time it takes for a 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 is rounded to 0ms
Find the provided description for each line below with a separator "<="
url.category: Reference@Blue Coat
total categorization time: 1 <= total time for categorization of URL - if this is slow, include dns in pcap filter to confirm performance. The dns timing shown below is not always included, and it can be reflected here. 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. The proxy may still go to the OCS to verify the object in the cache.
Some notes regarding SSL policy timing values:
total categorization time: 0
static categorization time: 0
The zeroes above are from the fact that the categorization did not happen from the URL, 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
This SSL policy transaction really did not have any bytes transferred and no latency was added. The reason being that this was just the SSL connection that the proxy uses to make the interception decision and to verify the server.
Imported Document ID: 000022825
Subscribing will provide email updates when this Article is updated. Login is required.