Skip to content

Commit

Permalink
feat: added patch_ms and setop_ms timings to reconciliation logs (arg…
Browse files Browse the repository at this point in the history 
…oproj#15595)

* feat: added patch_ms to reconciliation logs

Signed-off-by: Soumya Ghosh Dastidar <[email protected]>

* feat: added patch_ms and setop_ms timings to logs

Signed-off-by: Soumya Ghosh Dastidar <[email protected]>

---------

Signed-off-by: Soumya Ghosh Dastidar <[email protected]>
  • Loading branch information
@gdsoumya
gdsoumya authored Sep 21, 2023
1 parent 1a684a7 commit 45c0c2a
Show file tree
Hide file tree
Showing 2 changed files with 42 additions and 28 deletions.
48 changes: 31 additions & 17 deletions controller/appcontroller.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1326,6 +1326,8 @@ func (ctrl *ApplicationController) setOperationState(app *appv1.Application, sta
}

func (ctrl *ApplicationController) processAppRefreshQueueItem() (processNext bool) {
patchMs := time.Duration(0) // time spent in doing patch/update calls
setOpMs := time.Duration(0) // time spent in doing Operation patch calls in autosync
appKey, shutdown := ctrl.appRefreshQueue.Get()
if shutdown {
processNext = false
Expand Down Expand Up @@ -1367,6 +1369,8 @@ func (ctrl *ApplicationController) processAppRefreshQueueItem() (processNext boo
ctrl.metricsServer.IncReconcile(origApp, reconcileDuration)
logCtx.WithFields(log.Fields{
"time_ms": reconcileDuration.Milliseconds(),
"patch_ms": patchMs.Milliseconds(),
"setop_ms": setOpMs.Milliseconds(),
"level": comparisonLevel,
"dest-server": origApp.Spec.Destination.Server,
"dest-name": origApp.Spec.Destination.Name,
Expand All @@ -1388,7 +1392,7 @@ func (ctrl *ApplicationController) processAppRefreshQueueItem() (processNext boo
}
}

ctrl.persistAppStatus(origApp, &app.Status)
patchMs = ctrl.persistAppStatus(origApp, &app.Status)
return
}
}
Expand All @@ -1397,7 +1401,7 @@ func (ctrl *ApplicationController) processAppRefreshQueueItem() (processNext boo
if hasErrors {
app.Status.Sync.Status = appv1.SyncStatusCodeUnknown
app.Status.Health.Status = health.HealthStatusUnknown
ctrl.persistAppStatus(origApp, &app.Status)
patchMs = ctrl.persistAppStatus(origApp, &app.Status)

if err := ctrl.cache.SetAppResourcesTree(app.InstanceName(ctrl.namespace), &appv1.ApplicationTree{}); err != nil {
log.Warnf("failed to set app resource tree: %v", err)
Expand Down Expand Up @@ -1459,7 +1463,8 @@ func (ctrl *ApplicationController) processAppRefreshQueueItem() (processNext boo
}

if project.Spec.SyncWindows.Matches(app).CanSync(false) {
syncErrCond := ctrl.autoSync(app, compareResult.syncStatus, compareResult.resources)
syncErrCond, opMS := ctrl.autoSync(app, compareResult.syncStatus, compareResult.resources)
setOpMs = opMS
if syncErrCond != nil {
app.Status.SetConditions(
[]appv1.ApplicationCondition{*syncErrCond},
Expand Down Expand Up @@ -1487,7 +1492,7 @@ func (ctrl *ApplicationController) processAppRefreshQueueItem() (processNext boo
app.Status.SourceType = compareResult.appSourceType
app.Status.SourceTypes = compareResult.appSourceTypes
app.Status.ControllerNamespace = ctrl.namespace
ctrl.persistAppStatus(origApp, &app.Status)
patchMs = ctrl.persistAppStatus(origApp, &app.Status)
return
}

Expand Down Expand Up @@ -1602,7 +1607,7 @@ func (ctrl *ApplicationController) normalizeApplication(orig, app *appv1.Applica
}

// persistAppStatus persists updates to application status. If no changes were made, it is a no-op
func (ctrl *ApplicationController) persistAppStatus(orig *appv1.Application, newStatus *appv1.ApplicationStatus) {
func (ctrl *ApplicationController) persistAppStatus(orig *appv1.Application, newStatus *appv1.ApplicationStatus) (patchMs time.Duration) {
logCtx := log.WithFields(log.Fields{"application": orig.QualifiedName()})
if orig.Status.Sync.Status != newStatus.Sync.Status {
message := fmt.Sprintf("Updated sync status: %s -> %s", orig.Status.Sync.Status, newStatus.Sync.Status)
Expand Down Expand Up @@ -1631,36 +1636,42 @@ func (ctrl *ApplicationController) persistAppStatus(orig *appv1.Application, new
logCtx.Infof("No status changes. Skipping patch")
return
}
// calculate time for path call
start := time.Now()
defer func() {
patchMs = time.Since(start)
}()
appClient := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(orig.Namespace)
_, err = appClient.Patch(context.Background(), orig.Name, types.MergePatchType, patch, metav1.PatchOptions{})
if err != nil {
logCtx.Warnf("Error updating application: %v", err)
} else {
logCtx.Infof("Update successful")
}
return patchMs
}

// autoSync will initiate a sync operation for an application configured with automated sync
func (ctrl *ApplicationController) autoSync(app *appv1.Application, syncStatus *appv1.SyncStatus, resources []appv1.ResourceStatus) *appv1.ApplicationCondition {
func (ctrl *ApplicationController) autoSync(app *appv1.Application, syncStatus *appv1.SyncStatus, resources []appv1.ResourceStatus) (*appv1.ApplicationCondition, time.Duration) {
if app.Spec.SyncPolicy == nil || app.Spec.SyncPolicy.Automated == nil {
return nil
return nil, 0
}
logCtx := log.WithFields(log.Fields{"application": app.QualifiedName()})

if app.Operation != nil {
logCtx.Infof("Skipping auto-sync: another operation is in progress")
return nil
return nil, 0
}
if app.DeletionTimestamp != nil && !app.DeletionTimestamp.IsZero() {
logCtx.Infof("Skipping auto-sync: deletion in progress")
return nil
return nil, 0
}

// Only perform auto-sync if we detect OutOfSync status. This is to prevent us from attempting
// a sync when application is already in a Synced or Unknown state
if syncStatus.Status != appv1.SyncStatusCodeOutOfSync {
logCtx.Infof("Skipping auto-sync: application status is %s", syncStatus.Status)
return nil
return nil, 0
}

if !app.Spec.SyncPolicy.Automated.Prune {
Expand All @@ -1673,7 +1684,7 @@ func (ctrl *ApplicationController) autoSync(app *appv1.Application, syncStatus *
}
if requirePruneOnly {
logCtx.Infof("Skipping auto-sync: need to prune extra resources only but automated prune is disabled")
return nil
return nil, 0
}
}

Expand Down Expand Up @@ -1702,10 +1713,10 @@ func (ctrl *ApplicationController) autoSync(app *appv1.Application, syncStatus *
if !attemptPhase.Successful() {
logCtx.Warnf("Skipping auto-sync: failed previous sync attempt to %s", desiredCommitSHA)
message := fmt.Sprintf("Failed sync attempt to %s: %s", desiredCommitSHA, app.Status.OperationState.Message)
return &appv1.ApplicationCondition{Type: appv1.ApplicationConditionSyncError, Message: message}
return &appv1.ApplicationCondition{Type: appv1.ApplicationConditionSyncError, Message: message}, 0
}
logCtx.Infof("Skipping auto-sync: most recent sync already to %s", desiredCommitSHA)
return nil
return nil, 0
} else if alreadyAttempted && selfHeal {
if shouldSelfHeal, retryAfter := ctrl.shouldSelfHeal(app); shouldSelfHeal {
for _, resource := range resources {
Expand All @@ -1720,7 +1731,7 @@ func (ctrl *ApplicationController) autoSync(app *appv1.Application, syncStatus *
} else {
logCtx.Infof("Skipping auto-sync: already attempted sync to %s with timeout %v (retrying in %v)", desiredCommitSHA, ctrl.selfHealTimeout, retryAfter)
ctrl.requestAppRefresh(app.QualifiedName(), CompareWithLatest.Pointer(), &retryAfter)
return nil
return nil, 0
}

}
Expand All @@ -1735,19 +1746,22 @@ func (ctrl *ApplicationController) autoSync(app *appv1.Application, syncStatus *
if bAllNeedPrune {
message := fmt.Sprintf("Skipping sync attempt to %s: auto-sync will wipe out all resources", desiredCommitSHA)
logCtx.Warnf(message)
return &appv1.ApplicationCondition{Type: appv1.ApplicationConditionSyncError, Message: message}
return &appv1.ApplicationCondition{Type: appv1.ApplicationConditionSyncError, Message: message}, 0
}
}

appIf := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(app.Namespace)
start := time.Now()
_, err := argo.SetAppOperation(appIf, app.Name, &op)
setOpTime := time.Since(start)
if err != nil {
logCtx.Errorf("Failed to initiate auto-sync to %s: %v", desiredCommitSHA, err)
return &appv1.ApplicationCondition{Type: appv1.ApplicationConditionSyncError, Message: err.Error()}
return &appv1.ApplicationCondition{Type: appv1.ApplicationConditionSyncError, Message: err.Error()}, setOpTime
}
message := fmt.Sprintf("Initiated automated sync to '%s'", desiredCommitSHA)
ctrl.auditLogger.LogAppEvent(app, argo.EventInfo{Reason: argo.EventReasonOperationStarted, Type: v1.EventTypeNormal}, message, "")
logCtx.Info(message)
return nil
return nil, setOpTime
}

// alreadyAttemptedSync returns whether the most recent sync was performed against the
Expand Down
22 changes: 11 additions & 11 deletions controller/appcontroller_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -368,7 +368,7 @@ func TestAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
assert.Nil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand All @@ -385,7 +385,7 @@ func TestAutoSyncNotAllowEmpty(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
assert.NotNil(t, cond)
}

Expand All @@ -398,7 +398,7 @@ func TestAutoSyncAllowEmpty(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
assert.Nil(t, cond)
}

Expand All @@ -412,7 +412,7 @@ func TestSkipAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
assert.Nil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand All @@ -427,7 +427,7 @@ func TestSkipAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeSynced,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
assert.Nil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand All @@ -443,7 +443,7 @@ func TestSkipAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
assert.Nil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand All @@ -460,7 +460,7 @@ func TestSkipAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{})
assert.Nil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand All @@ -486,7 +486,7 @@ func TestSkipAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
assert.NotNil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand All @@ -500,7 +500,7 @@ func TestSkipAutoSync(t *testing.T) {
Status: v1alpha1.SyncStatusCodeOutOfSync,
Revision: "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb",
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{
{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync, RequiresPruning: true},
})
assert.Nil(t, cond)
Expand Down Expand Up @@ -538,7 +538,7 @@ func TestAutoSyncIndicateError(t *testing.T) {
Source: *app.Spec.Source.DeepCopy(),
},
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
assert.NotNil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand Down Expand Up @@ -581,7 +581,7 @@ func TestAutoSyncParameterOverrides(t *testing.T) {
Revision: "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa",
},
}
cond := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
cond, _ := ctrl.autoSync(app, &syncStatus, []v1alpha1.ResourceStatus{{Name: "guestbook", Kind: kube.DeploymentKind, Status: v1alpha1.SyncStatusCodeOutOfSync}})
assert.Nil(t, cond)
app, err := ctrl.applicationClientset.ArgoprojV1alpha1().Applications(test.FakeArgoCDNamespace).Get(context.Background(), "my-app", metav1.GetOptions{})
assert.NoError(t, err)
Expand Down

0 comments on commit 45c0c2a

Please sign in to comment.