[
https://issues.apache.org/jira/browse/TS-4244?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15173420#comment-15173420
]
gehaijiang commented on TS-4244:
--------------------------------
50ms long time problem！
1. squid.log
[01/Mar/2016:15:58:57 +0800] 51 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 2 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 2 10.17.21.79 TCP_MISS/200 395 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 2 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 2 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 2 10.17.21.79 TCP_MISS/200 395 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 2 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 48 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
[01/Mar/2016:15:58:57 +0800] 55 10.17.21.79 TCP_MISS/200 396 GET
http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
2. debug log
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (log-buffer) Nothing to
log, bytes_needed = 0
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (http) [509] deallocating
sm
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (http_cs) [509]
[&HttpClientSession::state_keep_alive, VC_EVENT_EOS]
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (http_cs) [509] session
closed
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (http_cs) [509] session
destroy
[Mar 1 15:58:57.060] Server {0x2b9e73a8bd20} DEBUG: (socket)
UnixNetVConnection::remove_from_keep_alive_lru NetVC=0x2b9e84016080
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (StatProInit)
[StatProcessor] Processing Statistics....
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.hostdb.total_hits is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.hostdb.total_lookups is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.user_agent_request_document_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.user_agent_request_header_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.user_agent_response_document_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.user_agent_response_header_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.origin_server_request_document_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.origin_server_request_header_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.origin_server_response_document_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.origin_server_response_header_total_size is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_hit_fresh is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_hit_revalidated is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_hit_ims is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_hit_stale_served is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_miss_cold is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_miss_changed is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_miss_client_no_cache is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_miss_ims is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.http.cache_read_error is of type 4
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.cache.bytes_total is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.cache.bytes_used is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.cache.bytes_total is of type 1
[Mar 1 15:58:57.268] Manager {0x7fee57df67e0} DEBUG: (RecOp) [varType]
proxy.process.cache.bytes_total is of type 1
[Mar 1 15:58:57.404] Server {0x2b9e73a8bd20} DEBUG: (statsproc)
config_update_cont() processed
[Mar 1 15:58:57.445] Server {0x2b9e73a8bd20} DEBUG: (inactivity_cop_verbose)
vc: 0x2b9e84016340 now: 1456819137445321593 timeout at: 1456820037 timeout in:
900
[Mar 1 15:58:57.445] Server {0x2b9e73a8bd20} DEBUG: (inactivity_cop_verbose)
vc: 0x2b9e84015b00 now: 1456819137445321593 timeout at: 1456820037 timeout in:
900
[Mar 1 15:58:57.445] Server {0x2b9e79fb5700} DEBUG: (log-logbuffer) prepared 0
buffers
[Mar 1 15:58:57.445] Server {0x2b9e79fb5700} DEBUG: (log-logbuffer) prepared 0
buffers
[Mar 1 15:58:57.445] Server {0x2b9e79fb5700} DEBUG: (log-api-mutex) A
LogObjectManager::preproc_buffers
[Mar 1 15:58:57.445] Server {0x2b9e79fb5700} DEBUG: (log-api-mutex) R
LogObjectManager::preproc_buffers
[Mar 1 15:58:57.445] Server {0x2b9e79fb5700} DEBUG: (log-preproc) 0 buffers
preprocessed from LogConfig 0x1b71360 (refcount=2) this round
[Mar 1 15:58:57.509] Manager {0x7fee510c0700} DEBUG: (ts_main) [ts_ctrl_main]
add fd 12 to select set
[Mar 1 15:58:57.533] Manager {0x7fee4bfff700} DEBUG: (event)
[event_callback_main] NO EVENTS TO PROCESS
[Mar 1 15:58:57.533] Manager {0x7fee4bfff700} DEBUG: (event)
[event_callback_main] add fd 8 to select set
> ATS have performance problem！
> ------------------------------
>
> Key: TS-4244
> URL: https://issues.apache.org/jira/browse/TS-4244
> Project: Traffic Server
> Issue Type: Bug
> Reporter: gehaijiang
>
> press ats meet performance problem！
> Why are some requests are processed to 50ms.
> 01/Mar/2016:11:23:47 +0800] 1 10.17.21.79 TCP_MISS/200 377 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
> [01/Mar/2016:11:23:47 +0800] 1 10.17.21.79 TCP_MISS/200 378 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
> [01/Mar/2016:11:23:47 +0800] 1 10.17.21.79 TCP_MISS/200 378 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
> [01/Mar/2016:11:23:47 +0800] 1 10.17.21.79 TCP_MISS/200 377 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
> [01/Mar/2016:11:23:47 +0800] 51 10.17.21.79 TCP_MISS/200 378 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
> [01/Mar/2016:11:23:47 +0800] 1 10.17.21.79 TCP_MISS/200 378 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
> [01/Mar/2016:11:23:47 +0800] 51 10.17.21.79 TCP_MISS/200 377 GET
> http://127.0.0.1/time.php - DIRECT/127.0.0.1 text/html
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
