Fix up the logs a little

main.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"os"
 	"sync"
+	"time"
 
 	"modify/processor"
 	"modify/utils"
@@ -66,6 +67,7 @@ func main() {
 
 	// Then aggregate all the globs and deduplicate them
 	globs := utils.AggregateGlobs(commands)
+	logger.Debug("Aggregated %d globs before deduplication", utils.CountGlobsBeforeDedup(commands))
 
 	// Resolve all the files for all the globs
 	logger.Info("Found %d unique file patterns", len(globs))
@@ -90,6 +92,13 @@ func main() {
 	// Then for each file run all commands associated with the file
 	workers := make(chan struct{}, *utils.ParallelFiles)
 	wg := sync.WaitGroup{}
+
+	// Add performance tracking
+	startTime := time.Now()
+	fileCount := 0
+	modCount := 0
+	var fileMutex sync.Mutex
+
 	for file, commands := range associations {
 		workers <- struct{}{}
 		wg.Add(1)
@@ -97,6 +106,9 @@ func main() {
 			defer func() { <-workers }()
 			defer wg.Done()
 
+			// Track per-file processing time
+			fileStartTime := time.Now()
+
 			fileData, err := os.ReadFile(file)
 			if err != nil {
 				logger.Error("Failed to read file %q: %v", file, err)
@@ -124,6 +136,12 @@ func main() {
 
 			// Sort commands in reverse order for safe replacements
 			fileDataStr, count := utils.ExecuteModifications(modifications, fileDataStr)
+
+			fileMutex.Lock()
+			fileCount++
+			modCount += count
+			fileMutex.Unlock()
+
 			logger.Info("Executed %d modifications for file %q", count, file)
 
 			err = os.WriteFile(file, []byte(fileDataStr), 0644)
@@ -131,10 +149,18 @@ func main() {
 				logger.Error("Failed to write file %q: %v", file, err)
 				return
 			}
+
+			logger.Debug("File %q processed in %v", file, time.Since(fileStartTime))
 		}, file, commands)
 	}
 	wg.Wait()
 
+	processingTime := time.Since(startTime)
+	logger.Info("Processing completed in %v", processingTime)
+	if fileCount > 0 {
+		logger.Info("Average time per file: %v", processingTime/time.Duration(fileCount))
+	}
+
 	// TODO: Also give each command its own logger, maybe prefix it with something... Maybe give commands a name?
 	// Do that with logger.WithField("loglevel", level.String())
 	// Since each command also has its own log level

processor/regex.go

@@ -5,6 +5,7 @@ import (
 	"regexp"
 	"strconv"
 	"strings"
+	"time"
 
 	lua "github.com/yuin/gopher-lua"
 
@@ -23,16 +24,22 @@ type CaptureGroup struct {
 func ProcessRegex(content string, command utils.ModifyCommand) ([]utils.ReplaceCommand, error) {
 	var commands []utils.ReplaceCommand
 	logger.Trace("Processing regex: %q", command.Pattern)
+
+	// Start timing the regex processing
+	startTime := time.Now()
+
 	// We don't HAVE to do this multiple times for a pattern
 	// But it's quick enough for us to not care
 	pattern := resolveRegexPlaceholders(command.Pattern)
 	logger.Debug("Compiling regex pattern: %s", pattern)
+
+	patternCompileStart := time.Now()
 	compiledPattern, err := regexp.Compile(pattern)
 	if err != nil {
 		logger.Error("Error compiling pattern: %v", err)
 		return commands, fmt.Errorf("error compiling pattern: %v", err)
 	}
-	logger.Debug("Compiled pattern successfully: %s", pattern)
+	logger.Debug("Compiled pattern successfully in %v: %s", time.Since(patternCompileStart), pattern)
 
 	// Same here, it's just string concatenation, it won't kill us
 	// More important is that we don't fuck up the command
@@ -42,10 +49,20 @@ func ProcessRegex(content string, command utils.ModifyCommand) ([]utils.ReplaceC
 	logger.Debug("Transformed Lua expression: %q → %q", previous, luaExpr)
 
 	// Process all regex matches
+	matchFindStart := time.Now()
 	indices := compiledPattern.FindAllStringSubmatchIndex(content, -1)
-	logger.Debug("Found %d matches in content of length %d", len(indices), len(content))
+	matchFindDuration := time.Since(matchFindStart)
+
+	logger.Debug("Found %d matches in content of length %d (search took %v)",
+		len(indices), len(content), matchFindDuration)
+
+	// Log pattern complexity metrics
+	patternComplexity := estimatePatternComplexity(pattern)
+	logger.Debug("Pattern complexity estimate: %d", patternComplexity)
+
 	if len(indices) == 0 {
 		logger.Warning("No matches found for regex: %q", pattern)
+		logger.Debug("Total regex processing time: %v", time.Since(startTime))
 		return commands, nil
 	}
 
@@ -184,7 +201,7 @@ func ProcessRegex(content string, command utils.ModifyCommand) ([]utils.ReplaceC
 					modifiedGroups++
 				}
 			}
-			logger.Info("%d of %d capture groups were modified", modifiedGroups, len(captureGroups))
+			logger.Info("%d of %d capture groups identified for modification", modifiedGroups, len(captureGroups))
 
 			for _, capture := range captureGroups {
 				if capture.Value == capture.Updated {
@@ -193,7 +210,7 @@ func ProcessRegex(content string, command utils.ModifyCommand) ([]utils.ReplaceC
 				}
 
 				// Log what changed with context
-				logger.Debug("Modifying group %s: %q → %q",
+				logger.Debug("Capture group %s scheduled for modification: %q → %q",
 					capture.Name, capture.Value, capture.Updated)
 
 				// Indices of the group are relative to content
@@ -214,6 +231,7 @@ func ProcessRegex(content string, command utils.ModifyCommand) ([]utils.ReplaceC
 		}
 	}
 
+	logger.Debug("Total regex processing time: %v", time.Since(startTime))
 	return commands, nil
 }
 
@@ -344,3 +362,21 @@ func fromLua(L *lua.LState, captureGroups []*CaptureGroup) ([]*CaptureGroup, err
 
 	return captureGroups, nil
 }
+
+// estimatePatternComplexity gives a rough estimate of regex pattern complexity
+// This can help identify potentially problematic patterns
+func estimatePatternComplexity(pattern string) int {
+	complexity := len(pattern)
+
+	// Add complexity for potentially expensive operations
+	complexity += strings.Count(pattern, ".*") * 10 // Greedy wildcard
+	complexity += strings.Count(pattern, ".*?") * 5 // Non-greedy wildcard
+	complexity += strings.Count(pattern, "[^") * 3  // Negated character class
+	complexity += strings.Count(pattern, "\\b") * 2 // Word boundary
+	complexity += strings.Count(pattern, "(") * 2   // Capture groups
+	complexity += strings.Count(pattern, "(?:") * 1 // Non-capture groups
+	complexity += strings.Count(pattern, "\\1") * 3 // Backreferences
+	complexity += strings.Count(pattern, "{") * 2   // Counted repetition
+
+	return complexity
+}

utils/modifycommand.go

@@ -160,3 +160,12 @@ func LoadCommandFromArgs(args []string) ([]ModifyCommand, error) {
 func LoadCommandsFromCookFiles(s string) ([]ModifyCommand, error) {
 	return nil, nil
 }
+
+// CountGlobsBeforeDedup counts the total number of glob patterns across all commands before deduplication
+func CountGlobsBeforeDedup(commands []ModifyCommand) int {
+	count := 0
+	for _, cmd := range commands {
+		count += len(cmd.Files)
+	}
+	return count
+}

utils/replacecommand.go

@@ -18,18 +18,18 @@ func ExecuteModifications(modifications []ReplaceCommand, fileData string) (stri
 	sort.Slice(modifications, func(i, j int) bool {
 		return modifications[i].From > modifications[j].From
 	})
-	logger.Trace("Applying %d replacement commands in reverse order", len(modifications))
+	logger.Trace("Preparing to apply %d replacement commands in reverse order", len(modifications))
 
 	executed := 0
 	for _, modification := range modifications {
 		fileData, err = modification.Execute(fileData)
 		if err != nil {
-			logger.Error("Failed to execute modification: %v", err)
+			logger.Error("Failed to execute replacement: %v", err)
 			continue
 		}
 		executed++
 	}
-	logger.Info("Executed %d modifications", executed)
+	logger.Info("Successfully applied %d text replacements", executed)
 	return fileData, executed
 }