diff --git a/server/node.go b/server/node.go index c1b0a63..106695d 100644 --- a/server/node.go +++ b/server/node.go @@ -77,7 +77,7 @@ func (n *Node) startProxyWorker(id int32, cancelContext context.Context) { // Send response _log.Debug("request processed, sending response") - sent := req.SendResponse(SimResponse{Payload: payload, NodeURI: n.URI, SimDuration: requestDuration}) + sent := req.SendResponse(SimResponse{Payload: payload, NodeURI: n.URI, SimDuration: requestDuration, SimAt: timeBeforeProxy}) if !sent { _log.Errorw("couldn't send node response to client (SendResponse returned false)", "secSinceRequestCreated", time.Since(req.CreatedAt).Seconds()) } diff --git a/server/types.go b/server/types.go index 3ffac23..542ff55 100644 --- a/server/types.go +++ b/server/types.go @@ -43,4 +43,5 @@ type SimResponse struct { ShouldRetry bool // When response has an error, whether it should be retried NodeURI string SimDuration time.Duration + SimAt time.Time // time when proxying started } diff --git a/server/webserver.go b/server/webserver.go index 938d2c5..77b7e23 100644 --- a/server/webserver.go +++ b/server/webserver.go @@ -110,21 +110,38 @@ func (s *Webserver) HandleQueueRequest(w http.ResponseWriter, req *http.Request) return } - lenFastTrack, lenHighPrio, lenLowPrio := s.prioQueue.Len() - log.Infow("Request added to queue. prioQueue size:", "requestIsHighPrio", isHighPrio, "requestIsFastTrack", isFastTrack, "fastTrack", lenFastTrack, "highPrio", lenHighPrio, "lowPrio", lenLowPrio) + startQueueSizeFastTrack, startQueueSizeHighPrio, startQueueSizeLowPrio := s.prioQueue.Len() + startItemQueueSize := startQueueSizeLowPrio + if isFastTrack { + startItemQueueSize = startQueueSizeFastTrack + } else if isHighPrio { + startItemQueueSize = startQueueSizeHighPrio + } + + log = log.With( + "requestIsHighPrio", isHighPrio, + "requestIsFastTrack", isFastTrack, + "payloadSize", len(body), + + "startQueueSize", s.prioQueue.NumRequests(), + "startQueueSizeFastTrack", startQueueSizeFastTrack, + "startQueueSizeHighPrio", startQueueSizeHighPrio, + "startQueueSizeLowPrio", startQueueSizeLowPrio, + ) + log.Infow("Request added to queue") // Wait for response or cancel for { select { case <-ctx.Done(): // if user closes connection, cancel the simreq - log.Infow("client closed the connection prematurely", "err", ctx.Err(), "queueItems", s.prioQueue.NumRequests(), "payloadSize", len(body), "requestTries", simReq.Tries, "requestCancelled", simReq.Cancelled) + log.Infow("Client closed the connection prematurely", "err", ctx.Err(), "queueItems", s.prioQueue.NumRequests(), "payloadSize", len(body), "requestTries", simReq.Tries, "requestCancelled", simReq.Cancelled) if ctx.Err() != nil { simReq.Cancelled = true } return case resp := <-simReq.ResponseC: if resp.Error != nil { - log.Infow("HandleSim error", "err", resp.Error, "try", simReq.Tries, "shouldRetry", resp.ShouldRetry, "nodeURI", resp.NodeURI) + log.Infow("Request proxying failed", "err", resp.Error, "try", simReq.Tries, "shouldRetry", resp.ShouldRetry, "nodeURI", resp.NodeURI) if simReq.Tries < RequestMaxTries && resp.ShouldRetry { s.prioQueue.Push(simReq) continue @@ -148,25 +165,41 @@ func (s *Webserver) HandleQueueRequest(w http.ResponseWriter, req *http.Request) resp.StatusCode = http.StatusOK } + queueDurationUs := resp.SimAt.Sub(startTime).Microseconds() + endQueueSizeFastTrack, endQueueSizeHighPrio, endQueueSizeLowPrio := s.prioQueue.Len() + endItemQueueSize := endQueueSizeLowPrio + if isFastTrack { + endItemQueueSize = endQueueSizeFastTrack + } else if isHighPrio { + endItemQueueSize = endQueueSizeHighPrio + } + + // Add additional profiling information about this request as part of the response headers + w.Header().Set("X-PrioLB-QueueDurationUs", fmt.Sprint(queueDurationUs)) + w.Header().Set("X-PrioLB-SimDurationUs", fmt.Sprint(resp.SimDuration.Microseconds())) + w.Header().Set("X-PrioLB-TotalDurationUs", fmt.Sprint(time.Since(startTime).Microseconds())) + w.Header().Set("X-PrioLB-QueueSizeStart", fmt.Sprint(startItemQueueSize)) + w.Header().Set("X-PrioLB-QueueSizeEnd", fmt.Sprint(endItemQueueSize)) + + // Send the response w.Header().Set("Content-Type", "application/json") w.WriteHeader(resp.StatusCode) w.Write(resp.Payload) - lenFastTrack, lenHighPrio, lenLowPrio := s.prioQueue.Len() log.Infow("Request completed", - "durationMs", time.Since(startTime).Milliseconds(), - "durationUs", time.Since(startTime).Microseconds(), - "simDurationUs", resp.SimDuration.Microseconds(), - "requestIsHighPrio", isHighPrio, - "requestIsFastTrack", isFastTrack, - "payloadSize", len(body), + "durationMs", time.Since(startTime).Milliseconds(), // full request duration in milliseconds + "durationUs", time.Since(startTime).Microseconds(), // full request duration in microseconds + "simDurationUs", resp.SimDuration.Microseconds(), // time only for simulation (proxying) + "queueDurationUs", queueDurationUs, // time until request was proxied (queue wait time) + "statusCode", resp.StatusCode, "nodeURI", resp.NodeURI, "requestTries", simReq.Tries, - "queueItems", s.prioQueue.NumRequests(), - "queueItemsFastTrack", lenFastTrack, - "queueItemsHighPrio", lenHighPrio, - "queueItemsLowPrio", lenLowPrio, + + "endQueueSize", s.prioQueue.NumRequests(), + "endQueueSizeFastTrack", endQueueSizeFastTrack, + "endQueueSizeHighPrio", endQueueSizeHighPrio, + "endQueueSizeLowPrio", endQueueSizeLowPrio, ) return }