20602: Report queue time for pos/neg/zero-priority reqs.

Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@curii.com>

diff --git a/lib/service/cmd.go b/lib/service/cmd.go
index c66c279432dc2f0ae6d5777f6776a1c2a3d063fb..f4d4ec8efe4b8878d97fafdfc70ba6e364f92689 100644 (file)
--- a/lib/service/cmd.go
+++ b/lib/service/cmd.go
@@ -264,13 +264,17 @@ func (c *command) requestPriority(req *http.Request, queued time.Time) int64 {
                return httpserver.IneligibleForQueuePriority
        case req.Method == http.MethodPost && strings.HasPrefix(req.URL.Path, "/arvados/v1/logs"):
                // "Create log entry" is the most harmless kind of
-               // request to drop.
-               return 0
+               // request to drop. Negative priority is called "low"
+               // in aggregate metrics.
+               return -1
        case req.Header.Get("Origin") != "":
-               // Handle interactive requests first.
-               return 2
-       default:
+               // Handle interactive requests first. Positive
+               // priority is called "high" in aggregate metrics.
                return 1
+       default:
+               // Zero priority is called "normal" in aggregate
+               // metrics.
+               return 0
        }
 }
 

diff --git a/sdk/go/httpserver/request_limiter.go b/sdk/go/httpserver/request_limiter.go
index f9f94ff987e2b23feafdee0c38d0abbe705ad0a4..724a26fa25f7c43758d60b3e014b9ae6b3410c84 100644 (file)
--- a/sdk/go/httpserver/request_limiter.go
+++ b/sdk/go/httpserver/request_limiter.go
@@ -47,10 +47,11 @@ type RequestLimiter struct {
        // registered with Registry, if it is not nil.
        Registry *prometheus.Registry
 
-       setupOnce sync.Once
-       mtx       sync.Mutex
-       handling  int
-       queue     queue
+       setupOnce   sync.Once
+       mQueueDelay *prometheus.SummaryVec
+       mtx         sync.Mutex
+       handling    int
+       queue       queue
 }
 
 type qent struct {
@@ -147,13 +148,13 @@ func (rl *RequestLimiter) setup() {
                        },
                        func() float64 { return float64(rl.MaxQueue) },
                ))
-               rl.mQueueDelay = prometheus.NewSummary(prometheus.SummaryOpts{
+               rl.mQueueDelay = prometheus.NewSummaryVec(prometheus.SummaryOpts{
                        Namespace:  "arvados",
                        Name:       "queue_delay_seconds",
-                       Help:       "Number of seconds spent in the incoming request queue",
+                       Help:       "Time spent in the incoming request queue",
                        Objectives: map[float64]float64{0.5: 0.05, 0.9: 0.01, 0.95: 0.005, 0.99: 0.001},
-               })
-               reg.MustRegister(rl.mQueueDelay)
+               }, []string{"priority"})
+               rl.Registry.MustRegister(rl.mQueueDelay)
        }
 }
 
@@ -230,8 +231,10 @@ func (rl *RequestLimiter) ServeHTTP(resp http.ResponseWriter, req *http.Request)
        ent := rl.enqueue(req)
        SetResponseLogFields(req.Context(), logrus.Fields{"priority": ent.priority})
        var ok bool
+       var abandoned bool
        select {
        case <-req.Context().Done():
+               abandoned = true
                rl.remove(ent)
                // we still need to wait for ent.ready, because
                // sometimes runqueue() will have already decided to
@@ -240,6 +243,24 @@ func (rl *RequestLimiter) ServeHTTP(resp http.ResponseWriter, req *http.Request)
                ok = <-ent.ready
        case ok = <-ent.ready:
        }
+
+       // report time spent in queue
+       var qlabel string
+       switch {
+       case abandoned:
+       case !ok && ent.priority == IneligibleForQueuePriority:
+               // don't pollute stats
+       case ent.priority < 0:
+               qlabel = "low"
+       case ent.priority > 0:
+               qlabel = "high"
+       default:
+               qlabel = "normal"
+       }
+       if qlabel != "" && rl.mQueueDelay != nil {
+               rl.mQueueDelay.WithLabelValues(qlabel).Observe(time.Now().Sub(ent.queued).Seconds())
+       }
+
        if !ok {
                resp.WriteHeader(http.StatusServiceUnavailable)
                return