From fc9668baa51a3652db961f3f1a617a3eade160f9 Mon Sep 17 00:00:00 2001
From: Aditya Manthramurthy <donatello@users.noreply.github.com>
Date: Wed, 30 Mar 2022 17:02:59 -0700
Subject: [PATCH] Increase IAM refresh rate to every 10 mins (#14661)

Add timing information for IAM init and refresh
---
 cmd/globals.go |  2 +-
 cmd/iam.go     | 19 +++++++++++++++++--
 2 files changed, 18 insertions(+), 3 deletions(-)

diff --git a/cmd/globals.go b/cmd/globals.go
index 55d0b0617..e3ad41f1d 100644
--- a/cmd/globals.go
+++ b/cmd/globals.go
@@ -102,7 +102,7 @@ const (
 	GlobalStaleUploadsCleanupInterval = time.Hour * 6 // 6 hrs.
 
 	// Refresh interval to update in-memory iam config cache.
-	globalRefreshIAMInterval = 30 * time.Minute
+	globalRefreshIAMInterval = 10 * time.Minute
 
 	// Limit of location constraint XML for unauthenticated PUT bucket operations.
 	maxLocationConstraintSize = 3 * humanize.MiByte
diff --git a/cmd/iam.go b/cmd/iam.go
index caefb9fb1..0c7a34b3e 100644
--- a/cmd/iam.go
+++ b/cmd/iam.go
@@ -199,6 +199,8 @@ func (sys *IAMSys) Load(ctx context.Context) error {
 
 // Init - initializes config system by reading entries from config/iam
 func (sys *IAMSys) Init(ctx context.Context, objAPI ObjectLayer, etcdClient *etcd.Client, iamRefreshInterval time.Duration) {
+	iamInitStart := time.Now()
+
 	sys.Lock()
 	defer sys.Unlock()
 
@@ -269,6 +271,8 @@ func (sys *IAMSys) Init(ctx context.Context, objAPI ObjectLayer, etcdClient *etc
 		break
 	}
 
+	iamLoadStart := time.Now()
+
 	// Load IAM data from storage.
 	for {
 		if err := sys.Load(retryCtx); err != nil {
@@ -334,7 +338,8 @@ func (sys *IAMSys) Init(ctx context.Context, objAPI ObjectLayer, etcdClient *etc
 
 	sys.printIAMRoles()
 
-	logger.Info("Finished loading IAM sub-system.")
+	now := time.Now()
+	logger.Info("Finished loading IAM sub-system (took %.1fs of %.1fs to load data).", now.Sub(iamLoadStart).Seconds(), now.Sub(iamInitStart).Seconds())
 }
 
 // Prints IAM role ARNs.
@@ -373,15 +378,25 @@ func (sys *IAMSys) watch(ctx context.Context) {
 		return
 	}
 
+	var maxRefreshDurationSecondsForLog float64 = 10
+
 	// Fall back to loading all items periodically
 	ticker := time.NewTicker(sys.iamRefreshInterval)
 	defer ticker.Stop()
 	for {
 		select {
 		case <-ticker.C:
+			refreshStart := time.Now()
 			if err := sys.Load(ctx); err != nil {
-				logger.LogIf(ctx, fmt.Errorf("Failure in periodic refresh for IAM: %v", err))
+				logger.LogIf(ctx, fmt.Errorf("Failure in periodic refresh for IAM (took %.2fs): %v", time.Since(refreshStart).Seconds(), err))
+			} else {
+				took := time.Since(refreshStart).Seconds()
+				if took > maxRefreshDurationSecondsForLog {
+					// Log if we took a lot of time to load.
+					logger.Info("IAM refresh took %.2fs", took)
+				}
 			}
+
 		case <-ctx.Done():
 			return
 		}