Understanding Policy Trace Checkpoint Timing ProxySG or Advanced Secure Gateway

book

Article ID: 168320

calendar_today

Updated On:

Products

Advanced Secure Gateway Software - ASG ProxySG Software - SGOS

Issue/Introduction

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

Resolution

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: [email protected] 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.