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.

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.