add metrics

README.md

@@ -415,7 +415,7 @@ The metrics include Go runtime information, as well as texd specific metrics:
 | `texd_processed_total{status="rejected"}` | counter | Number of rejected requests, due to full job queue. |
 | `texd_processed_total{status="aborted"}` | counter | Number of aborted requests, usually due to timeouts. |
 | `texd_processing_duration_seconds` | histogram | Overview of processing time per document. |
-| `texd_input_file_size_bytes{type=?}` | histogram | Overview of input file sizes. Type is either "tex" (for .tex, .cls, .sty, and similar files), "asset" (for images), "data" (for CSV files), or "other" (for unknown files) |
+| `texd_input_file_size_bytes{type=?}` | histogram | Overview of input file sizes. Type is either "tex" (for .tex, .cls, .sty, and similar files), "asset" (for images and fonts), "data" (for CSV files), or "other" (for unknown files) |
 | `texd_output_file_size_bytes` | histogram | Overview of output file sizes. |
 | `texd_job_queue_length` | gauge | Length of rendering queue, i.e. how many documents are waiting for processing. |
 | `texd_job_queue_usage_ratio` | gauge | Queue capacity indicator (0.0 = empty, 1.0 = full). |

go.mod

@@ -8,6 +8,7 @@ require (
 	github.com/gorilla/handlers v1.5.1
 	github.com/gorilla/mux v1.8.0
 	github.com/moby/term v0.0.0-20210619224110-3f7ff695adc6
+	github.com/prometheus/client_golang v1.11.0
 	github.com/spf13/afero v1.8.1
 	github.com/spf13/pflag v1.0.5
 	github.com/stretchr/testify v1.7.0
@@ -18,18 +19,24 @@ require (
 require (
 	github.com/Azure/go-ansiterm v0.0.0-20210617225240-d185dfc1b5a1 // indirect
 	github.com/Microsoft/go-winio v0.5.2 // indirect
+	github.com/beorn7/perks v1.0.1 // indirect
+	github.com/cespare/xxhash/v2 v2.1.2 // indirect
 	github.com/containerd/containerd v1.6.1 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/docker/distribution v2.8.1+incompatible // indirect
 	github.com/docker/go-connections v0.4.0 // indirect
 	github.com/felixge/httpsnoop v1.0.2 // indirect
 	github.com/gogo/protobuf v1.3.2 // indirect
 	github.com/golang/protobuf v1.5.2 // indirect
+	github.com/matttproud/golang_protobuf_extensions v1.0.2-0.20181231171920-c182affec369 // indirect
 	github.com/morikuni/aec v1.0.0 // indirect
 	github.com/opencontainers/go-digest v1.0.0 // indirect
 	github.com/opencontainers/image-spec v1.0.2 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
+	github.com/prometheus/client_model v0.2.0 // indirect
+	github.com/prometheus/common v0.30.0 // indirect
+	github.com/prometheus/procfs v0.7.3 // indirect
 	github.com/sirupsen/logrus v1.8.1 // indirect
 	go.uber.org/atomic v1.9.0 // indirect
 	go.uber.org/multierr v1.8.0 // indirect

go.sum

@@ -115,6 +115,7 @@ github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZx
 github.com/beorn7/perks v0.0.0-20160804104726-4c0e84591b9a/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
 github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8=
+github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
 github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw=
 github.com/bgentry/speakeasy v0.1.0/go.mod h1:+zsyZBPWlz7T6j88CTgSN5bM796AkVf0kBD4zp0CCIs=
 github.com/bitly/go-simplejson v0.5.0/go.mod h1:cXHtHw4XUPsvGaxgjIAn8PhEWG9NfngEKAMDJEczWVA=
@@ -136,6 +137,7 @@ github.com/certifi/gocertifi v0.0.0-20191021191039-0944d244cd40/go.mod h1:sGbDF6
 github.com/certifi/gocertifi v0.0.0-20200922220541-2c3bb06c6054/go.mod h1:sGbDF6GwGcLpkNXPUTkMRoywsNa/ol15pxFe6ERfguA=
 github.com/cespare/xxhash v1.1.0/go.mod h1:XrSqR1VqqWfGrhpAt58auRo0WTKS1nRRg3ghfAqPWnc=
 github.com/cespare/xxhash/v2 v2.1.1/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
+github.com/cespare/xxhash/v2 v2.1.2 h1:YRXhKfTDauu4ajMg1TPgFO5jnlC2HCbmLXMcTG5cbYE=
 github.com/cespare/xxhash/v2 v2.1.2/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
 github.com/checkpoint-restore/go-criu/v4 v4.1.0/go.mod h1:xUQBLp4RLc5zJtWY++yjOoMoB5lihDt7fai+75m+rGw=
 github.com/checkpoint-restore/go-criu/v5 v5.0.0/go.mod h1:cfwC0EG7HMUenopBsUf9d89JlCLQIfgVcNsNN0t6T2M=
@@ -587,6 +589,7 @@ github.com/mattn/go-shellwords v1.0.3/go.mod h1:3xCvwCdWdlDJUrvuMn7Wuy9eWs4pE8vq
 github.com/mattn/go-shellwords v1.0.6/go.mod h1:3xCvwCdWdlDJUrvuMn7Wuy9eWs4pE8vqg+NOMyg4B2o=
 github.com/mattn/go-shellwords v1.0.12/go.mod h1:EZzvwXDESEeg03EKmM+RmDnNOPKG4lLtQsUlTZDWQ8Y=
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
+github.com/matttproud/golang_protobuf_extensions v1.0.2-0.20181231171920-c182affec369 h1:I0XW9+e1XWDxdcEniV4rQAIOPUGDq67JSCiRCgGCZLI=
 github.com/matttproud/golang_protobuf_extensions v1.0.2-0.20181231171920-c182affec369/go.mod h1:BSXmuO+STAnVfrANrmjBb36TMTDstsz7MSK+HVaYKv4=
 github.com/maxbrunsfeld/counterfeiter/v6 v6.2.2/go.mod h1:eD9eIE7cdwcMi9rYluz88Jz2VyhSmden33/aXg4oVIY=
 github.com/miekg/dns v1.0.14/go.mod h1:W1PPwlIAgtquWBMBEV9nkV9Cazfe8ScdGz/Lj7v3Nrg=
@@ -707,11 +710,13 @@ github.com/prometheus/client_golang v0.9.3/go.mod h1:/TN21ttK/J9q6uSwhBd54HahCDf
 github.com/prometheus/client_golang v1.0.0/go.mod h1:db9x61etRT2tGnBNRi70OPL5FsnadC4Ky3P0J6CfImo=
 github.com/prometheus/client_golang v1.1.0/go.mod h1:I1FGZT9+L76gKKOs5djB6ezCbFQP1xR9D75/vuwEF3g=
 github.com/prometheus/client_golang v1.7.1/go.mod h1:PY5Wy2awLA44sXw4AOSfFBetzPP4j5+D6mVACh+pe2M=
+github.com/prometheus/client_golang v1.11.0 h1:HNkLOAEQMIDv/K+04rukrLx6ch7msSRwf3/SASFAGtQ=
 github.com/prometheus/client_golang v1.11.0/go.mod h1:Z6t4BnS23TR94PD6BsDNk8yVqroYurpAkEiz0P2BEV0=
 github.com/prometheus/client_model v0.0.0-20171117100541-99fa1f4be8e5/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
 github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
 github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
 github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
+github.com/prometheus/client_model v0.2.0 h1:uq5h0d+GuxiXLJLNABMgp2qUWDPiLvgCzz2dUR+/W/M=
 github.com/prometheus/client_model v0.2.0/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
 github.com/prometheus/common v0.0.0-20180110214958-89604d197083/go.mod h1:daVV7qP5qjZbuso7PdcryaAu0sAZbrN9i7WWcTMWvro=
 github.com/prometheus/common v0.0.0-20181113130724-41aa239b4cce/go.mod h1:daVV7qP5qjZbuso7PdcryaAu0sAZbrN9i7WWcTMWvro=
@@ -720,6 +725,7 @@ github.com/prometheus/common v0.4.1/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y8
 github.com/prometheus/common v0.6.0/go.mod h1:eBmuwkDJBwy6iBfxCBob6t6dR6ENT/y+J+Zk0j9GMYc=
 github.com/prometheus/common v0.10.0/go.mod h1:Tlit/dnDKsSWFlCLTWaA1cyBgKHSMdTB80sz/V91rCo=
 github.com/prometheus/common v0.26.0/go.mod h1:M7rCNAaPfAosfx8veZJCuw84e35h3Cfd9VFqTh1DIvc=
+github.com/prometheus/common v0.30.0 h1:JEkYlQnpzrzQFxi6gnukFPdQ+ac82oRhzMcIduJu/Ug=
 github.com/prometheus/common v0.30.0/go.mod h1:vu+V0TpY+O6vW9J44gczi3Ap/oXXR10b+M/gUGO4Hls=
 github.com/prometheus/procfs v0.0.0-20180125133057-cb4147076ac7/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
 github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
@@ -732,6 +738,7 @@ github.com/prometheus/procfs v0.0.8/go.mod h1:7Qr8sr6344vo1JqZ6HhLceV9o3AJ1Ff+Gx
 github.com/prometheus/procfs v0.1.3/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4OA4YeYWdaU=
 github.com/prometheus/procfs v0.2.0/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4OA4YeYWdaU=
 github.com/prometheus/procfs v0.6.0/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1xBZuNvfVA=
+github.com/prometheus/procfs v0.7.3 h1:4jVXhlkAyzOScmCkXBTOLRLTz8EeU+eyjrwB/EPq0VU=
 github.com/prometheus/procfs v0.7.3/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1xBZuNvfVA=
 github.com/prometheus/tsdb v0.7.1/go.mod h1:qhTCs0VvXwvX/y3TZrWD7rabWM+ijKTux40TwIPHuXU=
 github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6SoW27p1b0cqNHllgS5HIMJraePCO15w5zCzIWYg=

metrics/metrics.go

@@ -0,0 +1,58 @@
+// Package metrics centralizes Prometheus metric definitions.
+package metrics
+
+import (
+	"github.com/digineo/texd"
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+var (
+	processedTotal = promauto.NewCounterVec(prometheus.CounterOpts{
+		Name: "texd_processed_total",
+		Help: "Number of jobs processed, by status",
+	}, []string{"status"})
+
+	ProcessedSuccess  = processedTotal.WithLabelValues("success")
+	ProcessedFailure  = processedTotal.WithLabelValues("failure")
+	ProcessedRejected = processedTotal.WithLabelValues("rejected")
+	ProcessedAborted  = processedTotal.WithLabelValues("aborted")
+
+	ProcessingDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+		Name: "texd_processing_duration_seconds",
+		Help: "Overview of processing time per job",
+		Buckets: []float64{
+			.05, .1, .5, // expected range for errors to occur while processing input files
+			1, 1.5, 2, 2.5, 3, 3.5, 4, 4.5, 5, // some jobs are fast
+			6, 7, 8, 9, 10, 20, 30, 60, // other jobs might take time
+		},
+	})
+
+	InputSize = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Name:    "texd_input_file_size_bytes",
+		Help:    "Overview of input file sizes by category",
+		Buckets: prometheus.ExponentialBuckets(512, 2, 13), // 0.5 KiB .. 2 MiB
+	}, []string{"type"})
+
+	OutputSize = promauto.NewHistogram(prometheus.HistogramOpts{
+		Name:    "texd_output_file_size_bytes",
+		Help:    "Overview of genereted document sizes, success only",
+		Buckets: prometheus.ExponentialBuckets(2048, 2, 13), // 2 KiB .. 8 MiB
+	})
+
+	JobsQueueLength = promauto.NewGauge(prometheus.GaugeOpts{
+		Name: "texd_job_queue_length",
+		Help: "Length of rendering queue, i.e. how many documents are waiting for processing",
+	})
+
+	JobQueueRatio = promauto.NewGauge(prometheus.GaugeOpts{
+		Name: "texd_job_queue_ratio",
+		Help: "Queue capacity indicator, with 0 meaning empty and 1 meaning full queue",
+	})
+
+	Info = promauto.NewGaugeVec(prometheus.GaugeOpts{
+		Name:        "texd_info",
+		Help:        "Various runtime and configuration information",
+		ConstLabels: prometheus.Labels{"version": texd.Version()},
+	}, []string{"mode"})
+)

service/renderer.go

@@ -12,7 +12,9 @@ import (
 	"net/http"
 	"sort"
 	"strings"
+	"time"
 
+	"github.com/digineo/texd/metrics"
 	"github.com/digineo/texd/refstore"
 	"github.com/digineo/texd/service/middleware"
 	"github.com/digineo/texd/tex"
@@ -33,6 +35,7 @@ func (svc *service) HandleRender(res http.ResponseWriter, req *http.Request) {
 
 	log := svc.Logger().With(middleware.RequestIDField(req.Context()))
 	if err := svc.render(log, res, req); err != nil {
+		metrics.ProcessedFailure.Inc()
 		errorResponse(log, res, err)
 	}
 }
@@ -56,6 +59,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R
 	// Add a new job to the queue and bail if we're over capacity.
 	if err = svc.acquire(req.Context()); err != nil {
 		log.Error("failed enter queue", zap.Error(err))
+		metrics.ProcessedRejected.Inc()
 		return err
 	}
 	defer svc.release()
@@ -65,6 +69,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R
 		if svc.shouldKeepJobs(err) {
 			return
 		}
+		observeRenderMetrics(doc)
 		if err := doc.Cleanup(); err != nil {
 			log.Error("cleanup failed", zap.Error(err))
 		}
@@ -94,9 +99,11 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R
 
 	if err := req.Context().Err(); err != nil {
 		log.Error("cancel render job, client is gone", zap.Error(err))
+		metrics.ProcessedAborted.Inc()
 		return err
 	}
 
+	startProcessing := time.Now()
 	if err = svc.executor(doc).Run(req.Context(), log); err != nil {
 		switch format := params.Get("errors"); format {
 		case "full", "condensed":
@@ -110,6 +117,8 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R
 		}
 		return err
 	}
+	metrics.ProcessingDuration.Observe(time.Since(startProcessing).Seconds())
+	metrics.ProcessedSuccess.Inc()
 
 	pdf, err := doc.GetResult()
 	if err != nil {
@@ -121,9 +130,11 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R
 	// Send PDF
 	res.Header().Set("Content-Type", mimeTypePDF)
 	res.WriteHeader(http.StatusOK)
-	if _, err = io.Copy(res, pdf); err != nil {
+	n, err := io.Copy(res, pdf)
+	if err != nil {
 		log.Error("failed to send results", zap.Error(err))
 	}
+	metrics.OutputSize.Observe(float64(n))
 	return nil // header is already written
 }
 
@@ -284,3 +295,23 @@ func logfileResponse(log *zap.Logger, res http.ResponseWriter, format string, lo
 		log.Error("failed to read logs", zap.Error(err))
 	}
 }
+
+func observeRenderMetrics(doc tex.Document) {
+	m := doc.Metrics()
+
+	observe := func(category string, vs []int) {
+		o := metrics.InputSize.WithLabelValues(category)
+		for _, v := range vs {
+			o.Observe(float64(v))
+		}
+	}
+
+	observe("tex", m.TexFiles)
+	observe("asset", m.AssetFiles)
+	observe("data", m.DataFiles)
+	observe("other", m.OtherFiles)
+
+	if m.Result >= 0 {
+		metrics.OutputSize.Observe(float64(m.Result))
+	}
+}

service/service.go

@@ -10,12 +10,14 @@ import (
 	"time"
 
 	"github.com/digineo/texd/exec"
+	"github.com/digineo/texd/metrics"
 	"github.com/digineo/texd/refstore"
 	"github.com/digineo/texd/refstore/nop"
 	"github.com/digineo/texd/service/middleware"
 	"github.com/digineo/texd/tex"
 	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
+	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"go.uber.org/zap"
 )
 
@@ -90,7 +92,7 @@ func (svc *service) routes() http.Handler {
 	r.Handle("/render", render).Methods(http.MethodPost)
 
 	r.HandleFunc("/status", svc.HandleStatus).Methods(http.MethodGet)
-	r.HandleFunc("/metrics", svc.HandleMetrics).Methods(http.MethodGet)
+	r.Handle("/metrics", svc.newMetricsHandler()).Methods(http.MethodGet)
 
 	// r.Use(handlers.RecoveryHandler())
 	r.Use(middleware.RequestID)
@@ -142,9 +144,18 @@ func (svc *service) Logger() *zap.Logger {
 	return svc.log
 }
 
-// TODO: collect metrics for prometheus.
-func (svc *service) HandleMetrics(res http.ResponseWriter, req *http.Request) {
-	res.WriteHeader(http.StatusOK)
+func (svc *service) newMetricsHandler() http.Handler {
+	prom := promhttp.Handler()
+
+	return http.HandlerFunc(func(res http.ResponseWriter, req *http.Request) {
+		qlen, qcap := float64(len(svc.jobs)), float64(cap(svc.jobs))
+		metrics.JobsQueueLength.Set(qlen)
+		metrics.JobQueueRatio.Set(qlen / qcap)
+
+		metrics.Info.WithLabelValues(svc.mode).Set(1)
+
+		prom.ServeHTTP(res, req)
+	})
 }
 
 func errorResponse(log *zap.Logger, res http.ResponseWriter, err error) {

service/service_test.go

@@ -374,15 +374,15 @@ func addFile(w *multipart.Writer, dir, name string, ref refAction) error {
 	panic("not reached")
 }
 
-// taken from GOROOT/src/mime/multipart/writer.go
+// taken from GOROOT/src/mime/multipart/writer.go.
 var quoteEscaper = strings.NewReplacer("\\", "\\\\", `"`, "\\\"")
 
-// taken from GOROOT/src/mime/multipart/writer.go
+// taken from GOROOT/src/mime/multipart/writer.go.
 func escapeQuotes(s string) string {
 	return quoteEscaper.Replace(s)
 }
 
-// taken from GOROOT/src/mime/multipart/writer.go
+// taken from GOROOT/src/mime/multipart/writer.go.
 func createFormField(w *multipart.Writer, name string, ref refAction) (io.Writer, error) {
 	h := make(textproto.MIMEHeader)
 	h.Set("Content-Disposition",
@@ -397,5 +397,4 @@ func createFormField(w *multipart.Writer, name string, ref refAction) (io.Writer
 		h.Set("Content-Type", "application/octet-stream")
 	}
 	return w.CreatePart(h)
-
 }

tex/document.go

@@ -38,6 +38,7 @@ const (
 type File struct {
 	name  string
 	flags candidateFlags
+	size  int
 }
 
 func (f *File) isCandidate() bool      { return f.flags&flagCandidate > 0 }
@@ -68,7 +69,9 @@ func (w *fileWriter) Write(p []byte) (int, error) {
 		}
 	}
 
-	return w.wc.Write(p)
+	n, err := w.wc.Write(p)
+	w.file.size += n
+	return n, err
 }
 
 func (w *fileWriter) Close() error {
@@ -160,6 +163,9 @@ type Document interface {
 	// returns an error, GetLogs will wrap it in an InputError. If the
 	// log file does not exist, GetLogs will return a CompilationError.
 	GetLogs() (io.ReadCloser, error)
+
+	// Metrics reports file sizes.
+	Metrics() Metrics
 }
 
 type document struct {

tex/document_test.go

@@ -128,6 +128,7 @@ func (h *documentHelper) addFile(name, content string, flags candidateFlags) {
 	require.EqualValues(h.t, h.files[name], &File{
 		name:  name,
 		flags: flags,
+		size:  len(content),
 	})
 }
 
@@ -190,7 +191,7 @@ func TestFile_flags(t *testing.T) {
 	t.Parallel()
 	assert := assert.New(t)
 
-	subject := File{"", 0}
+	subject := File{"", 0, 0}
 	assert.False(subject.isCandidate())
 	assert.False(subject.hasDocumentClass())
 	assert.False(subject.hasTexdMark())