You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Zhao Yongming (JIRA)" <ji...@apache.org> on 2012/10/08 08:00:09 UTC
[jira] [Commented] (TS-1504) stats should not get a negative value
[ https://issues.apache.org/jira/browse/TS-1504?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13471415#comment-13471415 ]
Zhao Yongming commented on TS-1504:
-----------------------------------
TS-1504
with the following debug patch
{code}
commit 027a61e365b1b1dfb7e4b21bdd21d6e4e81952bf
Author: Zhao Yongming <mi...@gmail.com>
Date: Wed Oct 3 22:02:53 2012 +0800
TS-1504
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index a6678b8..97a0148 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -6260,8 +6260,8 @@ HttpSM::kill_this()
plugin_tunnel = NULL;
}
- ua_session = NULL;
- server_session = NULL;
+ //ua_session = NULL;
+ //server_session = NULL;
// So we don't try to nuke the state machine
// if the plugin receives event we must reset
@@ -6310,6 +6310,9 @@ HttpSM::kill_this()
if (t_state.http_config_param->enable_http_stats)
update_stats();
+ ua_session = NULL;
+ server_session = NULL;
+
HTTP_SM_SET_DEFAULT_HANDLER(NULL);
if (redirect_url != NULL) {
@@ -6380,8 +6383,8 @@ HttpSM::update_stats()
}
// TODO: ZYM: we need to make sure all time >0 ?
- ink_release_assert(milestones.sm_finish > milestones.sm_start);
- ink_release_assert(milestones.ua_close > milestones.ua_read_header_done);
+ ink_release_assert(milestones.sm_finish >= milestones.sm_start);
+ ink_release_assert(milestones.ua_close >= milestones.ua_read_header_done);
ink_hrtime total_time = milestones.sm_finish - milestones.sm_start;
@@ -6390,7 +6393,7 @@ HttpSM::update_stats()
HttpTransact::client_result_stat(&t_state, total_time, request_process_time);
- ink_hrtime ua_write_time;
+ ink_hrtime ua_write_time = 0;
if (milestones.ua_begin_write != 0 && milestones.ua_close != 0) {
ua_write_time = milestones.ua_close - milestones.ua_begin_write;
} else {
{code}
we get the milestone like::
{code}
ua_begin=1349395615523461000
ua_read_header_done=1349395615523515000
ua_begin_write=0
ua_close=1349395615523022000
server_first_connect=1349395615523515000
server_connect=1349395615523515000
server_connect_end=1349395615523515000
server_begin_write=1349395615523515000
server_first_read=1349395615523022000
server_read_header_done=1349395615523022000
server_close=1349395615523022000
cache_open_read_begin=1349395615523515000
cache_open_read_end=1349395615523515000
cache_open_write_begin=1349395615523515000
cache_open_write_end=1349395615523515000
dns_lookup_begin=1349395615523515000
dns_lookup_end=1349395615523515000
sm_start=1349395615523461000
sm_finish=1349395615523911000
{code}
we sort(desc) and group with the time:
{code}
sm_finish=1349395615523911000
ua_read_header_done=1349395615523515000
server_first_connect=1349395615523515000
server_connect_end=1349395615523515000
server_connect=1349395615523515000
server_begin_write=1349395615523515000
dns_lookup_end=1349395615523515000
dns_lookup_begin=1349395615523515000
cache_open_write_end=1349395615523515000
cache_open_write_begin=1349395615523515000
cache_open_read_end=1349395615523515000
cache_open_read_begin=1349395615523515000
ua_begin=1349395615523461000
sm_start=1349395615523461000
ua_begin_write=0
ua_close=1349395615523022000
server_read_header_done=1349395615523022000
server_first_read=1349395615523022000
server_close=1349395615523022000
{code}
question here:
why the ua_begin before server_close & ua_close?
and we go deep of this situation:
{code}
(gdb) p *this.ua_entry
$5 = {vc = 0x0, eos = false, read_buffer = 0x0, write_buffer = 0x0, read_vio = 0x0, write_vio = 0x0, vc_handler = NULL,
vc_type = HTTP_UNKNOWN, in_tunnel = false}
(gdb) p this.ua_session
$6 = (HttpClientSession *) 0x0
(gdb) p this.ua_entry
$7 = (HttpVCTableEntry *) 0x2add036b08e0
(gdb) p this.vc_table
$8 = {vc_table = {{vc = 0x0, eos = false, read_buffer = 0x0, write_buffer = 0x0, read_vio = 0x0, write_vio = 0x0, vc_handler = NULL,
vc_type = HTTP_UNKNOWN, in_tunnel = false}, {vc = 0x0, eos = false, read_buffer = 0x0, write_buffer = 0x0, read_vio = 0x0,
write_vio = 0x0, vc_handler = NULL, vc_type = HTTP_UNKNOWN, in_tunnel = false}, {vc = 0x0, eos = false, read_buffer = 0x0,
write_buffer = 0x0, read_vio = 0x0, write_vio = 0x0, vc_handler = NULL, vc_type = HTTP_UNKNOWN, in_tunnel = false}, {vc = 0x0,
eos = false, read_buffer = 0x0, write_buffer = 0x0, read_vio = 0x0, write_vio = 0x0, vc_handler = NULL, vc_type = HTTP_UNKNOWN,
in_tunnel = false}}}
(gdb) p *this.server_session
$9 = {<VConnection> = {<Continuation> = {<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0x2add10233751}, handler = (
int (Continuation::*)(Continuation * const, int, void *)) 0xefbeaddeefbeadde, this adjustment -1171307680053154338,
handler_name = 0xefbeaddeefbeadde <Address 0xefbeaddeefbeadde out of bounds>, mutex = {m_ptr = 0xefbeaddeefbeadde},
link = {<SLink<Continuation>> = {next = 0xefbeaddeefbeadde}, prev = 0xefbeaddeefbeadde}}, lerrno = -272716322}, server_ip = {sa = {
sa_family = 44510, sa_data = "\276\357\276\357\276\357\276", <incomplete sequence \357>}, sin = {sin_family = 44510,
sin_port = 61374, sin_addr = {s_addr = 4022250974}, sin_zero = "\276\357\276", <incomplete sequence \357>}, sin6 = {
sin6_family = 44510, sin6_port = 61374, sin6_flowinfo = 4022250974, sin6_addr = {__in6_u = {
__u6_addr8 = "\276\357\276\357\276\357\276", <incomplete sequence \357>, __u6_addr16 = {44510, 61374, 44510, 61374, 44510,
61374, 44510, 61374}, __u6_addr32 = {4022250974, 4022250974, 4022250974, 4022250974}}}, sin6_scope_id = 4022250974}},
hostname_hash = {b = {17275436393656397278, 17275436393656397278}}, host_hash_computed = 222, con_id = -1171307680053154338,
transact_count = -272716322, state = 4022250974, to_parent_proxy = 222, server_trans_stat = -272716322, private_session = 222,
share_session = -272716322, lru_link = {<SLink<HttpServerSession>> = {next = 0xefbeaddeefbeadde}, prev = 0xefbeaddeefbeadde},
hash_link = {<SLink<HttpServerSession>> = {next = 0xefbeaddeefbeadde}, prev = 0xefbeaddeefbeadde},
enable_origin_connection_limiting = 222, connection_count = 0xefbeaddeefbeadde, read_buffer = 0xefbeaddeefbeadde,
server_vc = 0xefbeaddeefbeadde, magic = -272716322, buf_reader = 0xefbeaddeefbeadde}
(gdb)
{code}
here is a strange situation, where ua_session is NULL, while we still have a working well server_session
question here:
why the ua_session is gone?
> stats should not get a negative value
> -------------------------------------
>
> Key: TS-1504
> URL: https://issues.apache.org/jira/browse/TS-1504
> Project: Traffic Server
> Issue Type: Bug
> Components: Stats
> Affects Versions: 3.3.0
> Reporter: Zhao Yongming
> Fix For: 3.3.2
>
>
> {code}
> proxy.process.http.transaction_totaltime.hit_fresh.process=-8090340352.000000
> proxy.process.cluster.open_delays=-1568985805836593376
> proxy.process.cluster.connections_avg_time=-76.100204
> proxy.process.cluster.control_messages_avg_send_time=-92.242027
> proxy.process.cluster.open_delay_time=-1147.221313
> proxy.process.cluster.rmt_cache_callback_time=-214.001053
> proxy.process.cluster.remote_connection_time=-259.256744
> {code}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira