From ba7ac07001e2eabd7410171d89b833bff72dfbd5 Mon Sep 17 00:00:00 2001 From: PhatPhuckDave Date: Thu, 27 Mar 2025 23:35:39 +0100 Subject: [PATCH] Fix up the logs a little --- main.go | 26 ++++++++++++++++++++++++ processor/regex.go | 44 +++++++++++++++++++++++++++++++++++++---- utils/modifycommand.go | 9 +++++++++ utils/replacecommand.go | 6 +++--- 4 files changed, 78 insertions(+), 7 deletions(-) diff --git a/main.go b/main.go index ed194df..22c96c0 100644 --- a/main.go +++ b/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 diff --git a/processor/regex.go b/processor/regex.go index 9a1369b..3edf96f 100644 --- a/processor/regex.go +++ b/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 +} diff --git a/utils/modifycommand.go b/utils/modifycommand.go index 192fb3e..0630809 100644 --- a/utils/modifycommand.go +++ b/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 +} diff --git a/utils/replacecommand.go b/utils/replacecommand.go index c071861..c6273ce 100644 --- a/utils/replacecommand.go +++ b/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 }