Add metrics

metrics/metrics.go

@@ -21,7 +21,7 @@ import (
 	"time"
 
 	onet "github.com/Jigsaw-Code/outline-ss-server/net"
-	"github.com/oschwald/geoip2-golang"
+	geoip2 "github.com/oschwald/geoip2-golang"
 	"github.com/prometheus/client_golang/prometheus"
 )
 
@@ -30,21 +30,25 @@ type ShadowsocksMetrics interface {
 	GetLocation(net.Addr) (string, error)
 
 	SetNumAccessKeys(numKeys int, numPorts int)
-	AddUDPPacketFromClient(clientLocation, accessKey, status string, clientProxyBytes, proxyTargetBytes int)
-	AddUDPPacketFromTarget(clientLocation, accessKey, status string, targetProxyBytes, proxyClientBytes int)
+
+	// TCP metrics
 	AddOpenTCPConnection(clientLocation string)
-	AddClosedTCPConnection(clientLocation, accessKey, status string, data ProxyMetrics, duration time.Duration)
+	AddClosedTCPConnection(clientLocation, accessKey, status string, data ProxyMetrics, timeToCipher, duration time.Duration)
 
-	AddUdpNatEntry()
-	RemoveUdpNatEntry()
+	// UDP metrics
+	AddUDPPacketFromClient(clientLocation, accessKey, status string, clientProxyBytes, proxyTargetBytes int, timeToCipher time.Duration)
+	AddUDPPacketFromTarget(clientLocation, accessKey, status string, targetProxyBytes, proxyClientBytes int)
+	AddUDPNatEntry()
+	RemoveUDPNatEntry()
 }
 
 type shadowsocksMetrics struct {
 	ipCountryDB *geoip2.Reader
 
-	accessKeys prometheus.Gauge
-	ports      prometheus.Gauge
-	dataBytes  *prometheus.CounterVec
+	accessKeys     prometheus.Gauge
+	ports          prometheus.Gauge
+	dataBytes      *prometheus.CounterVec
+	timeToCipherMs *prometheus.SummaryVec
 	// TODO: Add time to first byte.
 
 	tcpOpenConnections   *prometheus.CounterVec
@@ -87,14 +91,21 @@ func NewShadowsocksMetrics(ipCountryDB *geoip2.Reader) ShadowsocksMetrics {
 				Subsystem:  "tcp",
 				Name:       "connection_duration_ms",
 				Help:       "TCP connection duration distributions.",
-				Objectives: map[float64]float64{0.5: 0.05, 0.9: 0.01, 0.99: 0.001},
+				Objectives: map[float64]float64{0.5: 0.02, 0.9: 0.01, 0.99: 0.005},
 			}, []string{"location", "status", "access_key"}),
 		dataBytes: prometheus.NewCounterVec(
 			prometheus.CounterOpts{
 				Namespace: "shadowsocks",
 				Name:      "data_bytes",
 				Help:      "Bytes transferred by the proxy",
 			}, []string{"dir", "proto", "location", "status", "access_key"}),
+		timeToCipherMs: prometheus.NewSummaryVec(
+			prometheus.SummaryOpts{
+				Namespace:  "shadowsocks",
+				Name:       "time_to_cipher_ms",
+				Help:       "Time needed to find the cipher",
+				Objectives: map[float64]float64{0.5: 0.02, 0.9: 0.01, 0.99: 0.005},
+			}, []string{"proto", "location", "status", "access_key"}),
 		udpAddedNatEntries: prometheus.NewCounter(
 			prometheus.CounterOpts{
 				Namespace: "shadowsocks",
@@ -112,7 +123,7 @@ func NewShadowsocksMetrics(ipCountryDB *geoip2.Reader) ShadowsocksMetrics {
 	}
 	// TODO: Is it possible to pass where to register the collectors?
 	prometheus.MustRegister(m.accessKeys, m.ports, m.tcpOpenConnections, m.tcpClosedConnections, m.tcpConnectionDurationMs,
-		m.dataBytes, m.udpAddedNatEntries, m.udpRemovedNatEntries)
+		m.dataBytes, m.timeToCipherMs, m.udpAddedNatEntries, m.udpRemovedNatEntries)
 	return m
 }
 
@@ -163,16 +174,18 @@ func (m *shadowsocksMetrics) AddOpenTCPConnection(clientLocation string) {
 	m.tcpOpenConnections.WithLabelValues(clientLocation).Inc()
 }
 
-func (m *shadowsocksMetrics) AddClosedTCPConnection(clientLocation, accessKey, status string, data ProxyMetrics, duration time.Duration) {
+func (m *shadowsocksMetrics) AddClosedTCPConnection(clientLocation, accessKey, status string, data ProxyMetrics, timeToCipher, duration time.Duration) {
 	m.tcpClosedConnections.WithLabelValues(clientLocation, status, accessKey).Inc()
 	m.tcpConnectionDurationMs.WithLabelValues(clientLocation, status, accessKey).Observe(duration.Seconds() * 1000)
+	m.timeToCipherMs.WithLabelValues("tcp", clientLocation, status, accessKey).Observe(timeToCipher.Seconds() * 1000)
 	m.dataBytes.WithLabelValues("c>p", "tcp", clientLocation, status, accessKey).Add(float64(data.ClientProxy))
 	m.dataBytes.WithLabelValues("p>t", "tcp", clientLocation, status, accessKey).Add(float64(data.ProxyTarget))
 	m.dataBytes.WithLabelValues("p<t", "tcp", clientLocation, status, accessKey).Add(float64(data.TargetProxy))
 	m.dataBytes.WithLabelValues("c<p", "tcp", clientLocation, status, accessKey).Add(float64(data.ProxyClient))
 }
 
-func (m *shadowsocksMetrics) AddUDPPacketFromClient(clientLocation, accessKey, status string, clientProxyBytes, proxyTargetBytes int) {
+func (m *shadowsocksMetrics) AddUDPPacketFromClient(clientLocation, accessKey, status string, clientProxyBytes, proxyTargetBytes int, timeToCipher time.Duration) {
+	m.timeToCipherMs.WithLabelValues("udp", clientLocation, status, accessKey).Observe(timeToCipher.Seconds() * 1000)
 	m.dataBytes.WithLabelValues("c>p", "udp", clientLocation, status, accessKey).Add(float64(clientProxyBytes))
 	m.dataBytes.WithLabelValues("p>t", "udp", clientLocation, status, accessKey).Add(float64(proxyTargetBytes))
 }
@@ -182,11 +195,11 @@ func (m *shadowsocksMetrics) AddUDPPacketFromTarget(clientLocation, accessKey, s
 	m.dataBytes.WithLabelValues("c<p", "udp", clientLocation, status, accessKey).Add(float64(proxyClientBytes))
 }
 
-func (m *shadowsocksMetrics) AddUdpNatEntry() {
+func (m *shadowsocksMetrics) AddUDPNatEntry() {
 	m.udpAddedNatEntries.Inc()
 }
 
-func (m *shadowsocksMetrics) RemoveUdpNatEntry() {
+func (m *shadowsocksMetrics) RemoveUDPNatEntry() {
 	m.udpRemovedNatEntries.Inc()
 }
 

shadowsocks/tcp.go

@@ -173,21 +173,24 @@ func (s *tcpService) Start() {
 			clientConn.(*net.TCPConn).SetKeepAlive(true)
 			keyID := ""
 			var proxyMetrics metrics.ProxyMetrics
+			var timeToCipher time.Duration
 			clientConn = metrics.MeasureConn(clientConn, &proxyMetrics.ProxyClient, &proxyMetrics.ClientProxy)
 			defer func() {
-				connEnd := time.Now()
-				connDuration := connEnd.Sub(connStart)
+				connDuration := time.Now().Sub(connStart)
 				clientConn.Close()
 				status := "OK"
 				if connError != nil {
 					logger.Debugf("TCP Error: %v: %v", connError.Message, connError.Cause)
 					status = connError.Status
 				}
 				logger.Debugf("Done with status %v, duration %v", status, connDuration)
-				s.m.AddClosedTCPConnection(clientLocation, keyID, status, proxyMetrics, connDuration)
+				s.m.AddClosedTCPConnection(clientLocation, keyID, status, proxyMetrics, timeToCipher, connDuration)
 			}()
 
+			findStartTime := time.Now()
 			keyID, clientConn, err := findAccessKey(clientConn, *s.ciphers)
+			timeToCipher = time.Now().Sub(findStartTime)
+
 			if err != nil {
 				return onet.NewConnectionError("ERR_CIPHER", "Failed to find a valid cipher", err)
 			}

shadowsocks/udp.go

@@ -97,13 +97,14 @@ func (s *udpService) Start() {
 			clientLocation := ""
 			keyID := ""
 			var clientProxyBytes, proxyTargetBytes int
+			var timeToCipher time.Duration
 			defer func() {
 				status := "OK"
 				if connError != nil {
 					logger.Debugf("UDP Error: %v: %v", connError.Message, connError.Cause)
 					status = connError.Status
 				}
-				s.m.AddUDPPacketFromClient(clientLocation, keyID, status, clientProxyBytes, proxyTargetBytes)
+				s.m.AddUDPPacketFromClient(clientLocation, keyID, status, clientProxyBytes, proxyTargetBytes, timeToCipher)
 			}()
 			clientProxyBytes, clientAddr, err := s.clientConn.ReadFrom(cipherBuf)
 			if err != nil {
@@ -119,7 +120,10 @@ func (s *udpService) Start() {
 			logger.Debugf("Got location \"%v\" for IP %v", clientLocation, clientAddr.String())
 			defer logger.Debugf("UDP done with %v", clientAddr.String())
 			logger.Debugf("UDP Request from %v with %v bytes", clientAddr, clientProxyBytes)
+			unpackStart := time.Now()
 			buf, keyID, cipher, err := unpack(textBuf, cipherBuf[:clientProxyBytes], *s.ciphers)
+			timeToCipher = time.Now().Sub(unpackStart)
+
 			if err != nil {
 				return onet.NewConnectionError("ERR_CIPHER", "Failed to upack data from client", err)
 			}
@@ -206,10 +210,10 @@ func (m *natmap) del(key string) net.PacketConn {
 func (m *natmap) Add(clientAddr net.Addr, clientConn net.PacketConn, cipher shadowaead.Cipher, targetConn net.PacketConn, clientLocation, keyID string) {
 	m.set(clientAddr.String(), targetConn)
 
-	m.metrics.AddUdpNatEntry()
+	m.metrics.AddUDPNatEntry()
 	go func() {
 		timedCopy(clientAddr, clientConn, cipher, targetConn, m.timeout, clientLocation, keyID, m.metrics)
-		m.metrics.RemoveUdpNatEntry()
+		m.metrics.RemoveUDPNatEntry()
 		if pc := m.del(clientAddr.String()); pc != nil {
 			pc.Close()
 		}