Add duration latencies to AccessRecord

ghaskins · ghaskins · commit cc6b55268a94 · 2026-01-09T19:27:16.000-05:00
Implements three levels of execution timing in nanoseconds:

- BundleReference.duration: Time spent evaluating the Rego AST for each
  individual policy (excludes policy download/compilation time)

- AccessRecord.Duration.phases: Total execution time per authorization
  phase (1=SYSTEM, 2=IDENTITY, 3=RESOURCE, 4=SCOPE)

- AccessRecord.Duration.overall: Total Authorize() execution time,
  excluding the audit record transmission

Uses time.Now()/time.Since() for lightweight nanosecond-granularity
timing via Go monotonic clock.

Signed-off-by: Greg Haskins &lt;greg@manetu.com&gt;
diff --git a/internal/core/phase.go b/internal/core/phase.go
@@ -14,7 +14,8 @@ import (
  * is the anded result from the individual phases
  */
 type phase struct {
-	bundles []*events.AccessRecord_BundleReference
+	bundles  []*events.AccessRecord_BundleReference
+	duration uint64 // total phase duration in nanoseconds
 }
 
 func (p *phase) append(r *events.AccessRecord_BundleReference) {
diff --git a/internal/core/phase1.go b/internal/core/phase1.go
@@ -6,6 +6,7 @@ package core
 
 import (
 	"context"
+	"time"
 
 	"github.com/manetu/policyengine/pkg/common"
 	"github.com/manetu/policyengine/pkg/core/model"
@@ -46,10 +47,16 @@ func getPolicyForOperation(ctx context.Context, pe *PolicyEngine, mrn string) (*
 //
 // Value 0 is an leaves the result to be computed from the evaluation of other phases.
 func (p1 *phase1) exec(ctx context.Context, pe *PolicyEngine, input map[string]interface{}, op string) events.AccessRecord_Decision {
+	phaseStart := time.Now()
+	defer func() {
+		p1.duration = uint64(time.Since(phaseStart).Nanoseconds())
+	}()
+
 	var (
-		result events.AccessRecord_Decision
-		perr   *common.PolicyError
-		policy *model.Policy
+		result       events.AccessRecord_Decision
+		perr         *common.PolicyError
+		policy       *model.Policy
+		evalDuration uint64
 	)
 
 	result = events.AccessRecord_UNSPECIFIED
@@ -64,7 +71,10 @@ func (p1 *phase1) exec(ctx context.Context, pe *PolicyEngine, input map[string]i
 	} else {
 		logger.Debugf(agent, "authorize", "[phase1] got policy: %+v", policy)
 
+		evalStart := time.Now()
 		p1.result, perr = policy.EvaluateInt(ctx, input)
+		evalDuration = uint64(time.Since(evalStart).Nanoseconds())
+
 		if perr != nil {
 			result = events.AccessRecord_DENY
 			logger.Debugf(agent, "authorize", "[phase1] failed(err-%s)", perr)
@@ -84,7 +94,7 @@ func (p1 *phase1) exec(ctx context.Context, pe *PolicyEngine, input map[string]i
 		}
 	}
 
-	p1.append(buildBundleReference(perr, policy, events.AccessRecord_BundleReference_SYSTEM, op, bundleResult))
+	p1.append(buildBundleReference(perr, policy, events.AccessRecord_BundleReference_SYSTEM, op, bundleResult, evalDuration))
 
 	return result
 }
diff --git a/internal/core/phase2.go b/internal/core/phase2.go
@@ -9,6 +9,7 @@ import (
 	"maps"
 	"slices"
 	"sync"
+	"time"
 
 	"github.com/manetu/policyengine/pkg/common"
 	"github.com/manetu/policyengine/pkg/core/model"
@@ -26,6 +27,11 @@ type phase2 struct {
 }
 
 func (p2 *phase2) exec(ctx context.Context, pe *PolicyEngine, principalMap map[string]interface{}, input map[string]interface{}) bool {
+	phaseStart := time.Now()
+	defer func() {
+		p2.duration = uint64(time.Since(phaseStart).Nanoseconds())
+	}()
+
 	logger.Trace(agent, "authorize", "proceeding to phase2")
 
 	var policies []*model.Policy
@@ -52,7 +58,7 @@ func (p2 *phase2) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 			group, perr := pe.backend.GetGroup(ctx, groupMrn)
 			if perr != nil {
 				logger.Tracef(agent, "authorize", "[phase2] get rolebundle failed for group %s", groupMrn)
-				p2.append(buildBundleReference(perr, nil, events.AccessRecord_BundleReference_IDENTITY, groupMrn, events.AccessRecord_DENY))
+				p2.append(buildBundleReference(perr, nil, events.AccessRecord_BundleReference_IDENTITY, groupMrn, events.AccessRecord_DENY, 0))
 			} else {
 				for _, r := range group.Roles {
 					roleMap[r] = struct{}{}
@@ -68,6 +74,7 @@ func (p2 *phase2) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 	policies = make([]*model.Policy, len(rs))
 	decs := make([]bool, len(rs))
 	errs := make([]*common.PolicyError, len(rs))
+	durations := make([]uint64, len(rs))
 
 	// ------------ begin processing policies concurrently ---------------
 	numRoles := len(rs)
@@ -88,7 +95,9 @@ func (p2 *phase2) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 			}
 
 			policies[i] = role.Policy
+			evalStart := time.Now()
 			decs[i], errs[i] = role.Policy.EvaluateBool(ctx, input)
+			durations[i] = uint64(time.Since(evalStart).Nanoseconds())
 		}(ind, roleMrn)
 	}
 
@@ -113,7 +122,7 @@ func (p2 *phase2) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 			desc = events.AccessRecord_GRANT
 		}
 
-		p2.append(buildBundleReference(errs[i], policies[i], events.AccessRecord_BundleReference_IDENTITY, rs[i], desc))
+		p2.append(buildBundleReference(errs[i], policies[i], events.AccessRecord_BundleReference_IDENTITY, rs[i], desc, durations[i]))
 	}
 
 	return result
diff --git a/internal/core/phase3.go b/internal/core/phase3.go
@@ -6,6 +6,7 @@ package core
 
 import (
 	"context"
+	"time"
 
 	"github.com/manetu/policyengine/pkg/common"
 	"github.com/manetu/policyengine/pkg/core/model"
@@ -22,10 +23,16 @@ type phase3 struct {
 // phase3 is executed only if prior resource resolution is successful. ie, either group is provided in PORC or resource
 // MRN is used to fully resolve the resource in "input"
 func (p3 *phase3) exec(ctx context.Context, pe *PolicyEngine, input map[string]interface{}) bool {
+	phaseStart := time.Now()
+	defer func() {
+		p3.duration = uint64(time.Since(phaseStart).Nanoseconds())
+	}()
+
 	var (
-		result bool
-		perr   *common.PolicyError
-		policy *model.Policy
+		result       bool
+		perr         *common.PolicyError
+		policy       *model.Policy
+		evalDuration uint64
 	)
 
 	// ResourceGroup policy check
@@ -37,7 +44,9 @@ func (p3 *phase3) exec(ctx context.Context, pe *PolicyEngine, input map[string]i
 		logger.Debugf(agent, "authorize", "[phase3] error getting group for resource %s (err: %+v)", res.ID, perr)
 	} else {
 		policy = rg.Policy
+		evalStart := time.Now()
 		result, perr = rg.Policy.EvaluateBool(ctx, input)
+		evalDuration = uint64(time.Since(evalStart).Nanoseconds())
 		if perr != nil {
 			logger.Debugf(agent, "authorize", "[phase3] phase3 failed(err-%s)", perr)
 		}
@@ -47,7 +56,7 @@ func (p3 *phase3) exec(ctx context.Context, pe *PolicyEngine, input map[string]i
 	if result {
 		desc = events.AccessRecord_GRANT
 	}
-	p3.append(buildBundleReference(perr, policy, events.AccessRecord_BundleReference_RESOURCE, res.Group, desc))
+	p3.append(buildBundleReference(perr, policy, events.AccessRecord_BundleReference_RESOURCE, res.Group, desc, evalDuration))
 
 	return result
 }
diff --git a/internal/core/phase4.go b/internal/core/phase4.go
@@ -7,6 +7,7 @@ package core
 import (
 	"context"
 	"sync"
+	"time"
 
 	"github.com/manetu/policyengine/pkg/common"
 	"github.com/manetu/policyengine/pkg/core/model"
@@ -26,6 +27,11 @@ type phase4 struct {
 }
 
 func (p4 *phase4) exec(ctx context.Context, pe *PolicyEngine, principalMap map[string]interface{}, input map[string]interface{}) bool {
+	phaseStart := time.Now()
+	defer func() {
+		p4.duration = uint64(time.Since(phaseStart).Nanoseconds())
+	}()
+
 	logger.Trace(agent, "authorize", "proceeding to phase4")
 	scs := []string{}
 	if ss, ok := principalMap[Scopes].([]interface{}); ok {
@@ -54,6 +60,7 @@ func (p4 *phase4) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 	policies := make([]*model.Policy, numScopes)
 	decs := make([]bool, numScopes)
 	errs := make([]*common.PolicyError, numScopes)
+	durations := make([]uint64, numScopes)
 
 	// ------------ begin processing policies concurrently ---------------
 	wg := sync.WaitGroup{}
@@ -72,7 +79,9 @@ func (p4 *phase4) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 			}
 
 			policies[i] = scope.Policy
+			evalStart := time.Now()
 			decs[i], errs[i] = scope.Policy.EvaluateBool(ctx, input)
+			durations[i] = uint64(time.Since(evalStart).Nanoseconds())
 		}(ind, s)
 	}
 
@@ -96,7 +105,7 @@ func (p4 *phase4) exec(ctx context.Context, pe *PolicyEngine, principalMap map[s
 			desc = events.AccessRecord_GRANT
 		}
 
-		p4.append(buildBundleReference(errs[i], policies[i], events.AccessRecord_BundleReference_SCOPE, scs[i], desc))
+		p4.append(buildBundleReference(errs[i], policies[i], events.AccessRecord_BundleReference_SCOPE, scs[i], desc, durations[i]))
 	}
 
 	return result
diff --git a/internal/core/policyengine.go b/internal/core/policyengine.go
@@ -221,6 +221,7 @@ func (pe *PolicyEngine) resolveResource(ctx context.Context, mrn string) (*model
 
 // Authorize is the main function that calls opa
 func (pe *PolicyEngine) Authorize(ctx context.Context, input types.PORC, authOptions *options.AuthzOptions) bool {
+	overallStart := time.Now()
 	logger.Debug(agent, "authorize", "Enter")
 	defer logger.Debug(agent, "authorize", "Exit")
 
@@ -306,8 +307,15 @@ func (pe *PolicyEngine) Authorize(ctx context.Context, input types.PORC, authOpt
 		reason       string
 	}{}
 
+	// Initialize duration tracking
+	ar.Duration = &events.AccessRecord_Duration{
+		Phases: make(map[uint32]uint64),
+	}
+
 	// -------------------------- NOTE: all returns audited -----------------
 	defer func() {
+		// Capture overall duration just before sending audit (excluding audit send time)
+		ar.Duration.Overall = uint64(time.Since(overallStart).Nanoseconds())
 		pe.auditDecision(authOptions, ar, resMrn, auditDecision.reason, input, false, auditDecision.phase1Result)
 	}()
 
@@ -317,7 +325,7 @@ func (pe *PolicyEngine) Authorize(ctx context.Context, input types.PORC, authOpt
 
 		perr := &common.PolicyError{ReasonCode: events.AccessRecord_BundleReference_INVALPARAM_ERROR, Reason: err.Error()}
 
-		ar.References = append(ar.References, buildBundleReference(perr, nil, events.AccessRecord_BundleReference_RESOURCE, resMrn, events.AccessRecord_DENY))
+		ar.References = append(ar.References, buildBundleReference(perr, nil, events.AccessRecord_BundleReference_RESOURCE, resMrn, events.AccessRecord_DENY, 0))
 		ar.Decision = events.AccessRecord_DENY
 
 		auditDecision.reason = "failed to marshal PORC"
@@ -378,6 +386,12 @@ func (pe *PolicyEngine) Authorize(ctx context.Context, input types.PORC, authOpt
 
 	phasesWg.Wait()
 
+	// Collect per-phase durations
+	ar.Duration.Phases[uint32(events.AccessRecord_BundleReference_SYSTEM)] = p1.duration
+	ar.Duration.Phases[uint32(events.AccessRecord_BundleReference_IDENTITY)] = p2.duration
+	ar.Duration.Phases[uint32(events.AccessRecord_BundleReference_RESOURCE)] = p3.duration
+	ar.Duration.Phases[uint32(events.AccessRecord_BundleReference_SCOPE)] = p4.duration
+
 	logger.Debug(agent, "authorize", "phases completed...begin evaulation")
 
 	// include execution records for audit and display purposes
@@ -417,7 +431,7 @@ func (pe *PolicyEngine) Authorize(ctx context.Context, input types.PORC, authOpt
 
 		auditDecision.reason = "error getting resource"
 
-		ar.References = append(ar.References, buildBundleReference(resErr, nil, events.AccessRecord_BundleReference_RESOURCE, resMrn, events.AccessRecord_DENY))
+		ar.References = append(ar.References, buildBundleReference(resErr, nil, events.AccessRecord_BundleReference_RESOURCE, resMrn, events.AccessRecord_DENY, 0))
 
 		return false
 	}
diff --git a/internal/core/utils.go b/internal/core/utils.go
@@ -23,7 +23,7 @@ func getUnsafeBuiltins() map[string]struct{} {
 	return m
 }
 
-func buildBundleReference(policyError *common.PolicyError, policy *model.Policy, phase events.AccessRecord_BundleReference_Phase, id string, result events.AccessRecord_Decision) *events.AccessRecord_BundleReference {
+func buildBundleReference(policyError *common.PolicyError, policy *model.Policy, phase events.AccessRecord_BundleReference_Phase, id string, result events.AccessRecord_Decision, duration uint64) *events.AccessRecord_BundleReference {
 	var policies []*events.AccessRecord_PolicyReference
 
 	event := &events.AccessRecord_PolicyReference{}
@@ -37,6 +37,7 @@ func buildBundleReference(policyError *common.PolicyError, policy *model.Policy,
 		Id:       id,
 		Policies: policies,
 		Phase:    phase,
+		Duration: duration,
 	}
 
 	// error trumps everything
diff --git a/pkg/protos/manetu/policyengine/events/v1/message.pb.go b/pkg/protos/manetu/policyengine/events/v1/message.pb.go
diff --git a/protos/manetu/policyengine/events/v1/message.proto b/protos/manetu/policyengine/events/v1/message.proto

Original file line number	Diff line number	Diff line change
`@@ -14,7 +14,8 @@ import (`
`14`	`14`	`* is the anded result from the individual phases`
`15`	`15`	`*/`
`16`	`16`	`type phase struct {`
`17`		`- bundles []*events.AccessRecord_BundleReference`
	`17`	`+ bundles []*events.AccessRecord_BundleReference`
	`18`	`+ duration uint64 // total phase duration in nanoseconds`
`18`	`19`	`}`
`19`	`20`
`20`	`21`	`func (p phase) append(r events.AccessRecord_BundleReference) {`
Original file line number	Diff line number	Diff line change
`@@ -23,7 +23,7 @@ func getUnsafeBuiltins() map[string]struct{} {`
`23`	`23`	`return m`
`24`	`24`	`}`
`25`	`25`
`26`		`-func buildBundleReference(policyError common.PolicyError, policy model.Policy, phase events.AccessRecord_BundleReference_Phase, id string, result events.AccessRecord_Decision) *events.AccessRecord_BundleReference {`
	`26`	`+func buildBundleReference(policyError common.PolicyError, policy model.Policy, phase events.AccessRecord_BundleReference_Phase, id string, result events.AccessRecord_Decision, duration uint64) *events.AccessRecord_BundleReference {`
`27`	`27`	`var policies []*events.AccessRecord_PolicyReference`
`28`	`28`
`29`	`29`	`event := &events.AccessRecord_PolicyReference{}`
`@@ -37,6 +37,7 @@ func buildBundleReference(policyError common.PolicyError, policy model.Policy,`
`37`	`37`	`Id: id,`
`38`	`38`	`Policies: policies,`
`39`	`39`	`Phase: phase,`
	`40`	`+ Duration: duration,`
`40`	`41`	`}`
`41`	`42`
`42`	`43`	`// error trumps everything`