Skip to content
This repository has been archived by the owner on Sep 30, 2024. It is now read-only.

authz: expose metrics of authzFilter duration #9264

Merged
merged 3 commits into from
Mar 24, 2020
Merged

authz: expose metrics of authzFilter duration #9264

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
42505db
Expose metrics of authzFilter duration
unknwon Mar 24, 2020
ee8cd62
Use time.Since to calculate time took
unknwon Mar 24, 2020
71315fb
Update CHANGELOG
unknwon Mar 24, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 19 additions & 3 deletions cmd/frontend/db/repos_perm.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,11 +2,15 @@ package db

import (
"context"
"strconv"
"sync"
"time"

"github.com/RoaringBitmap/roaring"
otlog "github.com/opentracing/opentracing-go/log"
"github.com/pkg/errors"
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto"
"github.com/sourcegraph/sourcegraph/cmd/frontend/authz"
"github.com/sourcegraph/sourcegraph/cmd/frontend/globals"
"github.com/sourcegraph/sourcegraph/cmd/frontend/types"
Expand All @@ -16,6 +20,13 @@ import (
"gopkg.in/inconshreveable/log15.v2"
)

var authzFilterDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
Namespace: "src",
Subsystem: "frontend",
Name: "authz_filter_duration_seconds",
Help: "Time spent on performing authorization",
}, []string{"success"})

var MockAuthzFilter func(ctx context.Context, repos []*types.Repo, p authz.Perms) ([]*types.Repo, error)

// authzFilter is the enforcement mechanism for repository permissions. It is the root
Expand Down Expand Up @@ -53,9 +64,16 @@ func authzFilter(ctx context.Context, repos []*types.Repo, p authz.Perms) (filte

var currentUser *types.User

began := time.Now()
tr, ctx := trace.New(ctx, "authzFilter", "")
defer func() {
if err != nil {
took := time.Now().Sub(began).Seconds()
unknwon marked this conversation as resolved.
Show resolved Hide resolved
defer tr.Finish()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why is this a defer now?

Copy link
Member Author

@unknwon unknwon Mar 24, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just used the same pattern I did for tr.Finish() in another place. Seems working fine, is there a reason we don't want to use defer tr.Finish()?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

seems like an unnecessary defer since there is no early termination. However, it is correct. Was wondering if there was some other reason you changed the code I didn't spot, but lgtm


success := err == nil
authzFilterDuration.WithLabelValues(strconv.FormatBool(success)).Observe(took)
unknwon marked this conversation as resolved.
Show resolved Hide resolved

if !success {
tr.SetError(err)
}

Expand All @@ -70,8 +88,6 @@ func authzFilter(ctx context.Context, repos []*types.Repo, p authz.Perms) (filte
}

tr.LogFields(fields...)

tr.Finish()
}()

if isInternalActor(ctx) {
Expand Down
2 changes: 1 addition & 1 deletion dev/Procfile
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@ zoekt-indexserver-1: ./dev/zoekt/wrapper indexserver 1
zoekt-webserver-0: ./dev/zoekt/wrapper webserver 0
zoekt-webserver-1: ./dev/zoekt/wrapper webserver 1
keycloak: ./dev/auth-provider/keycloak.sh
jaeger:./dev/jaeger.sh
jaeger: ./dev/jaeger.sh
docsite: ./dev/docsite.sh -config doc/docsite.json serve -http=localhost:5080
lsif-server: yarn --cwd lsif run run:server
lsif-dump-manager: yarn --cwd lsif run run:dump-manager
Expand Down
9 changes: 8 additions & 1 deletion docker-images/grafana/jsonnet/perms_sync.jsonnet
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ local common = import './common.libsonnet';
local timeRange = '1m';

// The duration percentiles to display
local percentiles = ['0.99'];
local percentiles = ['0.95'];

// Colors to pair to percentiles above
local percentileColors = ['#7eb26d'];
Expand Down Expand Up @@ -154,6 +154,10 @@ local queueSizePanel = common.makePanel(
),
]
);
local authzFilterDurationPercentilesPanel = makeDurationPercentilesPanel(
title = 'Authorization duration',
metric = 'src_frontend_authz_filter_duration_seconds_bucket{success="true"}',
);

//
// Dashboard Construction
Expand All @@ -175,4 +179,7 @@ common.makeDashboard(
).addRow(
title = 'Syncer stats',
panels = [queueSizePanel]
).addRow(
title = 'General stats',
panels = [authzFilterDurationPercentilesPanel]
)
3 changes: 1 addition & 2 deletions enterprise/cmd/repo-updater/authz/perms_syncer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -633,8 +633,7 @@ func (s *PermsSyncer) observe(ctx context.Context, family, title string) (contex
tr, ctx := trace.New(ctx, family, title)

return ctx, func(typ requestType, id int32, err *error) {
now := s.clock()
took := now.Sub(began).Seconds()
took := s.clock().Sub(began).Seconds()
unknwon marked this conversation as resolved.
Show resolved Hide resolved

defer tr.Finish()
tr.LogFields(otlog.Int32("id", id))
Expand Down