Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: added patch_ms and setop_ms timings to reconciliation logs #15595

Merged
merged 3 commits into from
Sep 21, 2023
+42 −28
Merged

feat: added patch_ms and setop_ms timings to reconciliation logs #15595

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
c2e462a
feat: added patch_ms to reconciliation logs
gdsoumya Sep 19, 2023
f9ed680
feat: added patch_ms and setop_ms timings to logs
gdsoumya Sep 20, 2023
511c332
Merge branch 'master' into feat/add_patch_ms
gdsoumya Sep 20, 2023
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
48 changes: 31 additions & 17 deletions controller/appcontroller.go
View file
Open in desktop
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
Open in desktop
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
Loading