ATS 9.0.1: current_server_connections, current_server_transactions metrics broken

[mtorluemke]

Feels similar to #7163 and #7054
Fix for #7054 was #7056.
Fix for #7163 was #7258

Both of these metrics function like a counter, instead of a guage:
proxy.process.http.current_server_connections
proxy.process.http.current_server_transactions

[c-taylor]

This affects both:
proxy.process.http.current_parent_proxy_connections
proxy.process.http.current_server_connections

Behaviour is constantly additive. Do not see decrements.

[zwoop]

proxy.process.http.current_server_connections is a derivative metric too, which derives from

  {"proxy.process.current_server_connections",
   RECD_INT,
   {"proxy.process.http.current_server_connections", "proxy.process.http.current_parent_proxy_connections"}}};

[c-taylor]

I believe this issue also gives a 'false positive' for proxy.config.http.per_server.connection.max.

Trying to confirm this now...

[shinrich]

Interesting, in our 9.0.x build both look ok. From a server running at low time.

proxy.process.http.current_server_transactions 179
proxy.process.http.current_server_connections 526

I'll double check to make sure we have everything pushed forward.

[shinrich]

Hmm. Interestingly enough current_server_transactions is broken on my H2 to origin build. Our build based against 9.0.1 is also looking good. Are you actually leaking Http1ServerSession objects?

[shinrich]

One difference in our environments is that you use parent proxy. Does you proxy.process.http.current_parent_proxy_connections setting look ok?

[c-taylor]

This affects both:
proxy.process.http.current_parent_proxy_connections
proxy.process.http.current_server_connections

Behaviour is constantly additive. Do not see decrements.

[maskit]

What a mess.

$ git grep http_current_server_transactions_stat | grep MENT_DYN
proxy/http/Http1ServerSession.cc:    HTTP_DECREMENT_DYN_STAT(http_current_server_transactions_stat);
proxy/http/HttpSM.cc:    HTTP_DECREMENT_DYN_STAT(http_current_server_transactions_stat);
proxy/http/HttpSM.cc:    HTTP_DECREMENT_DYN_STAT(http_current_server_transactions_stat);
proxy/http/HttpSM.cc:  HTTP_INCREMENT_DYN_STAT(http_current_server_transactions_stat);

[maskit]

It doesn't seem like a stat issue. According to memory usage dump (SIGUSR1), Http1ServerSession is leaking.

[maskit]

This is just a possibility, but I thought it's worth noting.

Seems like removal of sessions from the pool depends on inactivity timeout of sessions (or underlying netvcs). If the timeout didn't happen on a session, the session would stay in the pool forever, unless other controls (e.g. per_server.connection.max) kick in.

This line below is suspecious, because it relies on the inactive timeout value currently set. If inactivity timeout is cancelled or set to 0, it does nothing. I think we need to read the original value from the config.

trafficserver/proxy/http/HttpSessionManager.cc

Line 215 in d4fc16f

ss->set_inactivity_timeout(ss->get_netvc()->get_inactivity_timeout());

trafficserver/iocore/net/P_UnixNetVConnection.h

Lines 348 to 352 in d4fc16f

	inline ink_hrtime
	UnixNetVConnection::get_inactivity_timeout()
	{
	return inactivity_timeout_in;
	}

trafficserver/iocore/net/UnixNetVConnection.cc

Lines 1354 to 1360 in d4fc16f

	TS_INLINE void
	UnixNetVConnection::set_inactivity_timeout(ink_hrtime timeout_in)
	{
	Debug("socket", "Set inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this);
	inactivity_timeout_in = timeout_in;
	next_inactivity_timeout_at = (timeout_in > 0) ? Thread::get_hrtime() + inactivity_timeout_in : 0;
	}

trafficserver/iocore/net/P_UnixNetVConnection.h

Lines 362 to 368 in d4fc16f

	inline void
	UnixNetVConnection::cancel_inactivity_timeout()
	{
	Debug("socket", "Cancel inactive timeout for NetVC=%p", this);
	inactivity_timeout_in = 0;
	next_inactivity_timeout_at = 0;
	}

[vmamidi]

This is just a possibility, but I thought it's worth noting.

Seems like removal of sessions from the pool depends on inactivity timeout of sessions (or underlying netvcs). If the timeout didn't happen on a session, the session would stay in the pool forever, unless other controls (e.g. per_server.connection.max) kick in.

This line below is suspecious, because it relies on the inactive timeout value currently set. If inactivity timeout is cancelled or set to 0, it does nothing. I think we need to read the original value from the config.

isn't that a configuration bug? Why would you set inactive timeout to zero?

trafficserver/proxy/http/HttpSessionManager.cc

Line 215 in d4fc16f

ss->set_inactivity_timeout(ss->get_netvc()->get_inactivity_timeout());

trafficserver/iocore/net/P_UnixNetVConnection.h

Lines 348 to 352 in d4fc16f

	inline ink_hrtime
	UnixNetVConnection::get_inactivity_timeout()
	{
	return inactivity_timeout_in;
	}

trafficserver/iocore/net/UnixNetVConnection.cc

Lines 1354 to 1360 in d4fc16f

	TS_INLINE void
	UnixNetVConnection::set_inactivity_timeout(ink_hrtime timeout_in)
	{
	Debug("socket", "Set inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this);
	inactivity_timeout_in = timeout_in;
	next_inactivity_timeout_at = (timeout_in > 0) ? Thread::get_hrtime() + inactivity_timeout_in : 0;
	}

trafficserver/iocore/net/P_UnixNetVConnection.h

Lines 362 to 368 in d4fc16f

	inline void
	UnixNetVConnection::cancel_inactivity_timeout()
	{
	Debug("socket", "Cancel inactive timeout for NetVC=%p", this);
	inactivity_timeout_in = 0;
	next_inactivity_timeout_at = 0;
	}

[maskit]

isn't that a configuration bug? Why would you set inactive timeout to zero?

There is a couple of lines set it to 0. And as you can see cancel_inactivity_timeout() set it to 0 too.

$ git grep "set_inactivity_timeout(0)"
iocore/net/QUICNetVConnection.cc:    set_inactivity_timeout(0);
iocore/net/QUICNetVConnection.cc:  this->set_inactivity_timeout(0);
iocore/net/QUICNetVConnection.cc:  this->set_inactivity_timeout(0);
iocore/net/UnixNetVConnection.cc:    set_inactivity_timeout(0);
iocore/net/UnixNetVConnection.cc:  set_inactivity_timeout(0);
proxy/PluginVC.cc:  set_inactivity_timeout(0);
proxy/http2/Http2Stream.cc:  set_inactivity_timeout(0);

But I'm not disagreeing that the issue is caused by misconfiguration. There might be something that saves the infinite inactivity timeout case.

[maskit]

I think fb6ca11 has a bug. Making keep_alive_no_activity_timeout_out overridable is fine, but using overridden values after detaching a session from a transaction doesn't make much sense. That behavior means "I want to keep this session in the pool for a shorter/longer time than the default after using it for this transaction".

https://issues.apache.org/jira/browse/TS-863

[maskit]

#7618 didn't work for this.

I checked the number of sessions in session pool by using #7627, and the number seemed reasonable. It didn't keep going up at minimum. So the leak probably happens outside of the pool and there should be a case that doesn't release (or close) server sessions.

[shinrich]

Just making a note that 9.1.x is not showing problems with the current_* metrics in our production environment. But we didn't notice problems with 9.0.1 either. We aren't using the parent selection logic through.