From fdadc942e9c9a7121cbb83c166f6bb75d16dbac0 Mon Sep 17 00:00:00 2001 From: Simone Bordet Date: Mon, 28 Dec 2015 14:30:24 +0100 Subject: [PATCH 1/2] 484818 - Expose interesting HTTP/2 attributes and operations via JMX. Added flow control stall times and improved dump(). --- .../http2/AbstractFlowControlStrategy.java | 47 ++++++++++++++++--- .../http2/BufferingFlowControlStrategy.java | 11 +++++ .../AbstractHTTP2ServerConnectionFactory.java | 3 +- 3 files changed, 52 insertions(+), 9 deletions(-) diff --git a/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/AbstractFlowControlStrategy.java b/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/AbstractFlowControlStrategy.java index 41bba462c4a..fcb5bddb3d9 100644 --- a/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/AbstractFlowControlStrategy.java +++ b/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/AbstractFlowControlStrategy.java @@ -18,6 +18,10 @@ package org.eclipse.jetty.http2; +import java.io.IOException; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; import org.eclipse.jetty.http2.api.Stream; @@ -25,15 +29,20 @@ import org.eclipse.jetty.http2.frames.WindowUpdateFrame; import org.eclipse.jetty.util.annotation.ManagedAttribute; import org.eclipse.jetty.util.annotation.ManagedObject; import org.eclipse.jetty.util.annotation.ManagedOperation; +import org.eclipse.jetty.util.component.ContainerLifeCycle; +import org.eclipse.jetty.util.component.Dumpable; import org.eclipse.jetty.util.log.Log; import org.eclipse.jetty.util.log.Logger; @ManagedObject -public abstract class AbstractFlowControlStrategy implements FlowControlStrategy +public abstract class AbstractFlowControlStrategy implements FlowControlStrategy, Dumpable { protected static final Logger LOG = Log.getLogger(FlowControlStrategy.class); - private final AtomicLong sessionStalls = new AtomicLong(); + private final AtomicLong sessionStall = new AtomicLong(); + private final AtomicLong sessionStallTime = new AtomicLong(); + private final Map streamsStalls = new ConcurrentHashMap<>(); + private final AtomicLong streamsStallTime = new AtomicLong(); private int initialStreamSendWindow; private int initialStreamRecvWindow; @@ -174,38 +183,62 @@ public abstract class AbstractFlowControlStrategy implements FlowControlStrategy protected void onSessionStalled(ISession session) { + sessionStall.set(System.nanoTime()); if (LOG.isDebugEnabled()) LOG.debug("Session stalled {}", session); - sessionStalls.incrementAndGet(); } protected void onStreamStalled(IStream stream) { + streamsStalls.put(stream, System.nanoTime()); if (LOG.isDebugEnabled()) LOG.debug("Stream stalled {}", stream); } protected void onSessionUnstalled(ISession session) { + sessionStallTime.addAndGet(System.nanoTime() - sessionStall.getAndSet(0)); if (LOG.isDebugEnabled()) LOG.debug("Session unstalled {}", session); } protected void onStreamUnstalled(IStream stream) { + Long time = streamsStalls.remove(stream); + if (time != null) + streamsStallTime.addAndGet(System.nanoTime() - time); if (LOG.isDebugEnabled()) LOG.debug("Stream unstalled {}", stream); } - @ManagedAttribute(value = "The number of times the session flow control has stalled", readonly = true) - public long getSessionStallCount() + @ManagedAttribute(value = "The time, in milliseconds, that the session flow control has stalled", readonly = true) + public long getSessionStallTime() { - return sessionStalls.get(); + return TimeUnit.NANOSECONDS.toMillis(sessionStallTime.get()); + } + + @ManagedAttribute(value = "The time, in milliseconds, that the streams flow control has stalled", readonly = true) + public long getStreamsStallTime() + { + return TimeUnit.NANOSECONDS.toMillis(streamsStallTime.get()); } @ManagedOperation(value = "Resets the statistics", impact = "ACTION") public void reset() { - sessionStalls.set(0); + sessionStallTime.set(0); + streamsStallTime.set(0); + } + + @Override + public String dump() + { + return ContainerLifeCycle.dump(this); + } + + @Override + public void dump(Appendable out, String indent) throws IOException + { + out.append(toString()).append(System.lineSeparator()); } } diff --git a/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/BufferingFlowControlStrategy.java b/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/BufferingFlowControlStrategy.java index d540ebd1f9e..26ec9409628 100644 --- a/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/BufferingFlowControlStrategy.java +++ b/jetty-http2/http2-common/src/main/java/org/eclipse/jetty/http2/BufferingFlowControlStrategy.java @@ -198,4 +198,15 @@ public class BufferingFlowControlStrategy extends AbstractFlowControlStrategy Atomics.updateMax(maxSessionRecvWindow, sessionWindow); } } + + @Override + public String toString() + { + return String.format("%s@%x[ratio=%.2f,sessionStallTime=%dms,streamsStallTime=%dms]", + getClass().getSimpleName(), + hashCode(), + bufferRatio, + getSessionStallTime(), + getStreamsStallTime()); + } } diff --git a/jetty-http2/http2-server/src/main/java/org/eclipse/jetty/http2/server/AbstractHTTP2ServerConnectionFactory.java b/jetty-http2/http2-server/src/main/java/org/eclipse/jetty/http2/server/AbstractHTTP2ServerConnectionFactory.java index 899f4721857..2c6bbcad431 100644 --- a/jetty-http2/http2-server/src/main/java/org/eclipse/jetty/http2/server/AbstractHTTP2ServerConnectionFactory.java +++ b/jetty-http2/http2-server/src/main/java/org/eclipse/jetty/http2/server/AbstractHTTP2ServerConnectionFactory.java @@ -34,7 +34,6 @@ import org.eclipse.jetty.server.HttpConfiguration; import org.eclipse.jetty.util.annotation.ManagedAttribute; import org.eclipse.jetty.util.annotation.ManagedObject; import org.eclipse.jetty.util.annotation.Name; -import org.eclipse.jetty.util.component.ContainerLifeCycle; import org.eclipse.jetty.util.component.LifeCycle; @ManagedObject @@ -159,7 +158,7 @@ public abstract class AbstractHTTP2ServerConnectionFactory extends AbstractConne return new ServerParser(connector.getByteBufferPool(), listener, getMaxDynamicTableSize(), getHttpConfiguration().getRequestHeaderSize()); } - private static class ConnectionListener extends ContainerLifeCycle implements Connection.Listener + private class ConnectionListener implements Connection.Listener { @Override public void onOpened(Connection connection) From 6d1027eaff140eb6f3133fd792d3f46323606859 Mon Sep 17 00:00:00 2001 From: Simone Bordet Date: Mon, 4 Jan 2016 12:46:43 +0100 Subject: [PATCH 2/2] Removed caching of debug log level. It is useful to be able to change the log level via JMX for debugging purposes. --- .../eclipse/jetty/io/ssl/SslConnection.java | 29 +++++++++---------- 1 file changed, 14 insertions(+), 15 deletions(-) diff --git a/jetty-io/src/main/java/org/eclipse/jetty/io/ssl/SslConnection.java b/jetty-io/src/main/java/org/eclipse/jetty/io/ssl/SslConnection.java index 6b34201ad85..af5e4dca18b 100644 --- a/jetty-io/src/main/java/org/eclipse/jetty/io/ssl/SslConnection.java +++ b/jetty-io/src/main/java/org/eclipse/jetty/io/ssl/SslConnection.java @@ -77,7 +77,6 @@ import org.eclipse.jetty.util.log.Logger; public class SslConnection extends AbstractConnection { private static final Logger LOG = Log.getLogger(SslConnection.class); - private static final boolean DEBUG = LOG.isDebugEnabled(); // Easy for the compiler to remove the code if DEBUG==false private static final ByteBuffer __FILL_CALLED_FLUSH= BufferUtil.allocate(0); private static final ByteBuffer __FLUSH_CALLED_FILL= BufferUtil.allocate(0); private final ByteBufferPool _bufferPool; @@ -186,7 +185,7 @@ public class SslConnection extends AbstractConnection // to do the fill and/or flush again and these calls will do the actually // filling. - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("onFillable enter {}", _decryptedEndPoint); // We have received a close handshake, close the end point to send FIN. @@ -207,7 +206,7 @@ public class SslConnection extends AbstractConnection } } - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("onFillable exit {}", _decryptedEndPoint); } @@ -270,7 +269,7 @@ public class SslConnection extends AbstractConnection boolean fillable = false; synchronized (DecryptedEndPoint.this) { - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("write.complete {}", SslConnection.this.getEndPoint()); releaseEncryptedOutputBuffer(); @@ -297,7 +296,7 @@ public class SslConnection extends AbstractConnection boolean fail_filler = false; synchronized (DecryptedEndPoint.this) { - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} write.failed", SslConnection.this, x); BufferUtil.clear(_encryptedOutput); releaseEncryptedOutputBuffer(); @@ -373,7 +372,7 @@ public class SslConnection extends AbstractConnection boolean try_again = false; synchronized (DecryptedEndPoint.this) { - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("onIncompleteFlush {}", SslConnection.this); // If we have pending output data, if (BufferUtil.hasContent(_encryptedOutput)) @@ -530,7 +529,7 @@ public class SslConnection extends AbstractConnection { BufferUtil.flipToFlush(app_in, pos); } - if (DEBUG) + if (LOG.isDebugEnabled()) { LOG.debug("{} net={} unwrap {}", SslConnection.this, net_filled, unwrapResult.toString().replace('\n',' ')); LOG.debug("{} filled {}",SslConnection.this,BufferUtil.toHexSummary(buffer)); @@ -593,7 +592,7 @@ public class SslConnection extends AbstractConnection if (unwrapHandshakeStatus == HandshakeStatus.FINISHED && !_handshaken) { _handshaken = true; - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} {} handshook {}/{}", SslConnection.this, _sslEngine.getUseClientMode() ? "client" : "resumed server", _sslEngine.getSession().getProtocol(),_sslEngine.getSession().getCipherSuite()); @@ -602,7 +601,7 @@ public class SslConnection extends AbstractConnection // Check whether renegotiation is allowed if (_handshaken && handshakeStatus != HandshakeStatus.NOT_HANDSHAKING && !isRenegotiationAllowed()) { - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} renegotiation denied", SslConnection.this); closeInbound(); return -1; @@ -729,7 +728,7 @@ public class SslConnection extends AbstractConnection // it is the applications responsibility to call flush again - either in a busy loop // or better yet by using EndPoint#write to do the flushing. - if (DEBUG) + if (LOG.isDebugEnabled()) { for (ByteBuffer b : appOuts) LOG.debug("{} flush {}", SslConnection.this, BufferUtil.toHexSummary(b)); @@ -762,7 +761,7 @@ public class SslConnection extends AbstractConnection { BufferUtil.flipToFlush(_encryptedOutput, pos); } - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} wrap {}", SslConnection.this, wrapResult.toString().replace('\n',' ')); Status wrapResultStatus = wrapResult.getStatus(); @@ -800,13 +799,13 @@ public class SslConnection extends AbstractConnection throw new IllegalStateException(); default: - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} wrap {} {}", SslConnection.this, wrapResultStatus, BufferUtil.toHexSummary(_encryptedOutput)); if (wrapResult.getHandshakeStatus() == HandshakeStatus.FINISHED && !_handshaken) { _handshaken = true; - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} server handshook complete {}/{}", SslConnection.this, _sslEngine.getSession().getProtocol(),_sslEngine.getSession().getCipherSuite()); } @@ -815,7 +814,7 @@ public class SslConnection extends AbstractConnection // Check whether renegotiation is allowed if (_handshaken && handshakeStatus != HandshakeStatus.NOT_HANDSHAKING && !isRenegotiationAllowed()) { - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} renegotiation denied", SslConnection.this); getEndPoint().shutdownOutput(); return allConsumed; @@ -890,7 +889,7 @@ public class SslConnection extends AbstractConnection { boolean ishut = isInputShutdown(); boolean oshut = isOutputShutdown(); - if (DEBUG) + if (LOG.isDebugEnabled()) LOG.debug("{} shutdownOutput: oshut={}, ishut={}", SslConnection.this, oshut, ishut); if (ishut) {