Skip to content

Commit 4bb9009

Browse files
CodeReaperCodeReaper
authored
chore: adjust performance monitoring and tests (#208)
1 parent 945a30a commit 4bb9009

File tree

5 files changed

+81
-72
lines changed

5 files changed

+81
-72
lines changed

‎internal/command/updater.go‎

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import (
88
"os"
99
"path"
1010
"runtime"
11+
"time"
1112

1213
"github.com/CustomResourceDefinition/catalog/internal/configuration"
1314
"github.com/CustomResourceDefinition/catalog/internal/crd"
@@ -78,19 +79,25 @@ func (cmd Updater) Run() error {
7879
return err
7980
}
8081

82+
totalStats := timing.NewStats()
83+
84+
start := time.Now()
8185
configurations, err := readConfiguration(cmd.Configuration)
8286
if err != nil {
8387
return err
8488
}
89+
totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "read", time.Since(start), true, start)
8590

8691
if cmd.registry != nil {
92+
start = time.Now()
8793
validKeys := validSourceKeys(configurations)
8894
for key := range cmd.registry.Sources {
8995
if !validKeys[key] {
9096
delete(cmd.registry.Sources, key)
9197
fmt.Fprintf(cmd.Logger, "Removing stale registry entry: %s\n", key)
9298
}
9399
}
100+
totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "valid_keys", time.Since(start), true, start)
94101
}
95102

96103
tmpDir, err := os.MkdirTemp("", "output")
@@ -99,14 +106,13 @@ func (cmd Updater) Run() error {
99106
}
100107
defer os.RemoveAll(tmpDir)
101108

102-
totalStats := timing.NewStats()
103-
104109
if err := totalStats.OpenLogFile(cmd.performanceLog); err != nil {
105110
return fmt.Errorf("failed to open performance log: %w", err)
106111
}
107112
defer totalStats.CloseLogFile()
108113

109114
for _, config := range splitConfigurations(configurations) {
115+
start = time.Now()
110116
runtime.GC()
111117

112118
build, err := generator.NewBuilder(config, cmd.reader, tmpDir, cmd.Schema, cmd.Definitions, cmd.Logger, cmd.registry)
@@ -116,6 +122,7 @@ func (cmd Updater) Run() error {
116122
}
117123

118124
err = build.Build()
125+
totalStats.Record(timing.CategoryMisc, timing.OperationTypeBuild, config.Name, time.Since(start), true, start)
119126
if err != nil {
120127
fmt.Fprintf(cmd.Logger, "::warning:: build of %s failed: %v\n", config.Name, err)
121128
continue
@@ -128,19 +135,28 @@ func (cmd Updater) Run() error {
128135
}
129136

130137
if cmd.registry != nil && cmd.registryPath != "" {
138+
start = time.Now()
131139
if err := cmd.registry.Save(cmd.registryPath); err != nil {
132140
fmt.Fprintf(cmd.Logger, "::warning:: failed to save registry: %v\n", err)
133141
}
142+
totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "save_registry", time.Since(start), true, start)
134143
}
135144

145+
start = time.Now()
146+
err = merge(tmpDir, cmd.Schema)
147+
if err != nil {
148+
return err
149+
}
150+
totalStats.Record(timing.CategoryMisc, timing.OperationTypeMerge, "files", time.Since(start), true, start)
151+
136152
writer, closer, err := cmd.createSummaryWriter()
137153
if err != nil {
138154
return err
139155
}
140156
defer closer()
141157
totalStats.PrintSummary(writer)
142158

143-
return merge(tmpDir, cmd.Schema)
159+
return nil
144160
}
145161

146162
func (cmd Updater) validate() error {

‎internal/command/updater_test.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -329,7 +329,7 @@ func TestRunAggregatesStats(t *testing.T) {
329329
assert.Nil(t, err)
330330

331331
outStr := output.String()
332-
assert.Contains(t, outStr, "Update Statistics")
332+
assert.Contains(t, outStr, "### Statistics")
333333
assert.Contains(t, outStr, "**Overall:**")
334334
assert.Contains(t, outStr, "operations")
335335
assert.Contains(t, outStr, "#### Http")

‎internal/generator/factory.go‎

Lines changed: 5 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -72,18 +72,6 @@ func (builder Builder) Build() error {
7272
fmt.Fprintf(logger, " - using prepared git generator\n")
7373
}
7474

75-
buildStart := time.Now()
76-
defer func() {
77-
builder.stats.Record(
78-
timing.CategoryMisc,
79-
timing.OperationTypeUpdate,
80-
fmt.Sprintf("build_%s", builder.config.Name),
81-
time.Since(buildStart),
82-
true,
83-
buildStart,
84-
)
85-
}()
86-
8775
start := time.Now()
8876
latestVersion, isUpdated, err := builder.registryStatus()
8977
builder.stats.Record(timing.CategoryMisc, timing.OperationTypeStatus, "registry_status", time.Since(start), err == nil, start)
@@ -114,9 +102,7 @@ func (builder Builder) Build() error {
114102
}
115103

116104
for _, version := range versions {
117-
start := time.Now()
118105
runtime.GC()
119-
builder.stats.Record(timing.CategoryMisc, timing.OperationTypeGC, "gc", time.Since(start), true, start)
120106

121107
if err := builder.renderVersion(logger, version); err != nil {
122108
continue
@@ -133,8 +119,7 @@ func (builder Builder) Build() error {
133119
func (builder Builder) fetchVersions(logger io.Writer) ([]string, error) {
134120
start := time.Now()
135121
versions, err := builder.generator.Versions()
136-
cat := builder.operationCategory()
137-
builder.stats.Record(cat, timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start)
122+
builder.stats.Record(builder.operationCategory(), timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start)
138123
if err != nil {
139124
return nil, err
140125
}
@@ -147,8 +132,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([]
147132
fmt.Fprintf(logger, " - checking version %s for completeness.\n", latestVersion)
148133
start := time.Now()
149134
metadata, err := builder.generator.MetaData(latestVersion)
150-
cat := builder.operationCategory()
151-
builder.stats.Record(cat, timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start)
135+
builder.stats.Record(builder.operationCategory(), timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start)
152136
if err != nil {
153137
fmt.Fprintf(logger, " ! failed: %s\n", err.Error())
154138
return nil, err
@@ -159,7 +143,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([]
159143
func (builder Builder) renderVersion(logger io.Writer, version string) error {
160144
fmt.Fprintf(logger, " - render version %s.\n", version)
161145

162-
crds, err := builder.generateCrds(logger, version)
146+
crds, err := builder.generateCrds(version)
163147
if err != nil {
164148
fmt.Fprintf(logger, " - - discarded due to error: %s.\n", err.Error())
165149
return err
@@ -182,11 +166,10 @@ func (builder Builder) renderVersion(logger io.Writer, version string) error {
182166
return nil
183167
}
184168

185-
func (builder Builder) generateCrds(logger io.Writer, version string) ([]crd.Crd, error) {
169+
func (builder Builder) generateCrds(version string) ([]crd.Crd, error) {
186170
start := time.Now()
187171
crds, err := builder.generator.Crds(version)
188-
cat := builder.operationCategory()
189-
builder.stats.Record(cat, timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start)
172+
builder.stats.Record(builder.operationCategory(), timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start)
190173
return crds, err
191174
}
192175

‎internal/timing/stats.go‎

Lines changed: 9 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -25,23 +25,14 @@ const (
2525
type OperationType string
2626

2727
const (
28-
OperationTypeAPIFetch OperationType = "api_fetch"
29-
OperationTypeAuth OperationType = "auth"
30-
OperationTypeBranches OperationType = "branches"
31-
OperationTypeCheckout OperationType = "checkout"
32-
OperationTypeClone OperationType = "clone"
33-
OperationTypeDownload OperationType = "download"
34-
OperationTypeFetch OperationType = "fetch"
35-
OperationTypeGC OperationType = "gc"
36-
OperationTypeGenerate OperationType = "generate"
37-
OperationTypeIndex OperationType = "index"
38-
OperationTypePull OperationType = "pull"
39-
OperationTypeRender OperationType = "render"
40-
OperationTypeStatus OperationType = "status"
41-
OperationTypeSubmodule OperationType = "submodule"
42-
OperationTypeTags OperationType = "tags"
43-
OperationTypeUpdate OperationType = "update"
44-
OperationTypeWrite OperationType = "write"
28+
OperationTypeAPIFetch OperationType = "api_fetch"
29+
OperationTypeBuild OperationType = "build"
30+
OperationTypeConfiguration OperationType = "configuration"
31+
OperationTypeGenerate OperationType = "generate"
32+
OperationTypeMerge OperationType = "merge"
33+
OperationTypeStatus OperationType = "status"
34+
OperationTypeUpdate OperationType = "update"
35+
OperationTypeWrite OperationType = "write"
4536
)
4637

4738
type Operation struct {
@@ -235,7 +226,7 @@ func (s *Stats) PrintSummary(writer io.Writer) {
235226
s.mu.RLock()
236227
defer s.mu.RUnlock()
237228

238-
fmt.Fprintf(writer, "\n### Update Statistics\n\n")
229+
fmt.Fprintf(writer, "\n### Statistics\n\n")
239230
fmt.Fprintf(writer, "**Overall:** %s (%d operations)\n\n", formatDuration(s.totalTime), s.totalOps)
240231

241232
categoryOrder := []Category{CategoryHTTP, CategoryGit, CategoryHelm, CategoryOCI, CategoryGeneration, CategoryMisc}

‎internal/timing/stats_test.go‎

Lines changed: 47 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
package timing
22

33
import (
4-
"io"
54
"os"
65
"strings"
76
"sync"
@@ -21,14 +20,14 @@ func TestNewStats(t *testing.T) {
2120
func TestRecord(t *testing.T) {
2221
s := NewStats()
2322

24-
s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now())
23+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "test-op", 100*time.Millisecond, true, time.Now())
2524

2625
assert.Equal(t, 1, s.TotalOperations())
2726
assert.Equal(t, 100*time.Millisecond, s.TotalTime())
2827

2928
ops := s.GetCategoryStats(CategoryHTTP)
3029
assert.Len(t, ops, 1)
31-
assert.Equal(t, OperationTypeFetch, ops[0].Type)
30+
assert.Equal(t, OperationTypeAPIFetch, ops[0].Type)
3231
assert.Equal(t, "test-op", ops[0].Name)
3332
assert.Equal(t, 100*time.Millisecond, ops[0].Duration)
3433
assert.True(t, ops[0].Success)
@@ -37,9 +36,9 @@ func TestRecord(t *testing.T) {
3736
func TestRecordMultipleCategories(t *testing.T) {
3837
s := NewStats()
3938

40-
s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 50*time.Millisecond, true, time.Now())
41-
s.Record(CategoryGit, OperationTypeClone, "git-op", 100*time.Millisecond, true, time.Now())
42-
s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 75*time.Millisecond, true, time.Now())
39+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "http-op", 50*time.Millisecond, true, time.Now())
40+
s.Record(CategoryGit, OperationTypeWrite, "git-op", 100*time.Millisecond, true, time.Now())
41+
s.Record(CategoryHelm, OperationTypeGenerate, "helm-op", 75*time.Millisecond, true, time.Now())
4342

4443
assert.Equal(t, 3, s.TotalOperations())
4544
assert.Equal(t, 225*time.Millisecond, s.TotalTime())
@@ -52,9 +51,9 @@ func TestRecordMultipleCategories(t *testing.T) {
5251
func TestRecordMultipleOperationsSameCategory(t *testing.T) {
5352
s := NewStats()
5453

55-
s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now())
56-
s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true, time.Now())
57-
s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true, time.Now())
54+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now())
55+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op2", 20*time.Millisecond, true, time.Now())
56+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op3", 30*time.Millisecond, true, time.Now())
5857

5958
ops := s.GetCategoryStats(CategoryHTTP)
6059
assert.Len(t, ops, 3)
@@ -63,7 +62,7 @@ func TestRecordMultipleOperationsSameCategory(t *testing.T) {
6362
func TestRecordFailure(t *testing.T) {
6463
s := NewStats()
6564

66-
s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false, time.Now())
65+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "failed-op", 100*time.Millisecond, false, time.Now())
6766

6867
ops := s.GetCategoryStats(CategoryHTTP)
6968
assert.Len(t, ops, 1)
@@ -79,7 +78,7 @@ func TestGetCategoryStatsEmpty(t *testing.T) {
7978

8079
func TestGetCategoryStatsUnknownCategory(t *testing.T) {
8180
s := NewStats()
82-
s.Record(CategoryHTTP, OperationTypeFetch, "test", 100*time.Millisecond, true, time.Now())
81+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "test", 100*time.Millisecond, true, time.Now())
8382

8483
ops := s.GetCategoryStats(CategoryOCI)
8584
assert.Nil(t, ops)
@@ -154,43 +153,63 @@ func TestFormatDuration(t *testing.T) {
154153
func TestPrintSummaryEmpty(t *testing.T) {
155154
s := NewStats()
156155

157-
s.PrintSummary(io.Discard)
156+
var buf strings.Builder
157+
s.PrintSummary(&buf)
158+
159+
assert.Contains(t, buf.String(), "### Statistics")
160+
assert.Contains(t, buf.String(), "**Overall:** 0µs (0 operations)")
158161
}
159162

160163
func TestPrintSummaryWithData(t *testing.T) {
161164
s := NewStats()
162165

163-
s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now())
164-
s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true, time.Now())
165-
s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true, time.Now())
166-
s.Record(CategoryGit, OperationTypeClone, "repo1", 100*time.Millisecond, true, time.Now())
167-
s.Record(CategoryGit, OperationTypeClone, "repo2", 200*time.Millisecond, true, time.Now())
166+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now())
167+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op2", 20*time.Millisecond, true, time.Now())
168+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op3", 30*time.Millisecond, true, time.Now())
169+
s.Record(CategoryGit, OperationTypeGenerate, "repo1", 100*time.Millisecond, true, time.Now())
170+
s.Record(CategoryGit, OperationTypeGenerate, "repo2", 200*time.Millisecond, true, time.Now())
171+
172+
var buf strings.Builder
173+
s.PrintSummary(&buf)
168174

169-
s.PrintSummary(io.Discard)
175+
assert.Contains(t, buf.String(), "### Statistics")
176+
assert.Contains(t, buf.String(), "**Overall:** 360ms (5 operations)")
177+
assert.Contains(t, buf.String(), "#### Http")
178+
assert.Contains(t, buf.String(), "#### Git")
170179
}
171180

172181
func TestPrintSummaryAllCategories(t *testing.T) {
173182
s := NewStats()
174183

175-
s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 10*time.Millisecond, true, time.Now())
176-
s.Record(CategoryGit, OperationTypeClone, "git-op", 20*time.Millisecond, true, time.Now())
177-
s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 30*time.Millisecond, true, time.Now())
178-
s.Record(CategoryOCI, OperationTypePull, "oci-op", 40*time.Millisecond, true, time.Now())
184+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "http-op", 10*time.Millisecond, true, time.Now())
185+
s.Record(CategoryGit, OperationTypeGenerate, "git-op", 20*time.Millisecond, true, time.Now())
186+
s.Record(CategoryHelm, OperationTypeGenerate, "helm-op", 30*time.Millisecond, true, time.Now())
187+
s.Record(CategoryOCI, OperationTypeGenerate, "oci-op", 40*time.Millisecond, true, time.Now())
179188
s.Record(CategoryGeneration, OperationTypeWrite, "gen-op", 50*time.Millisecond, true, time.Now())
180189
s.Record(CategoryMisc, OperationTypeUpdate, "misc-op", 60*time.Millisecond, true, time.Now())
181190

182-
s.PrintSummary(io.Discard)
191+
var buf strings.Builder
192+
s.PrintSummary(&buf)
193+
194+
assert.Contains(t, buf.String(), "### Statistics")
195+
assert.Contains(t, buf.String(), "**Overall:** 210ms (6 operations)")
196+
assert.Contains(t, buf.String(), "#### Http")
197+
assert.Contains(t, buf.String(), "#### Git")
198+
assert.Contains(t, buf.String(), "#### Helm")
199+
assert.Contains(t, buf.String(), "#### Oci")
200+
assert.Contains(t, buf.String(), "#### Generation")
201+
assert.Contains(t, buf.String(), "#### Misc")
183202
}
184203

185204
func TestConcurrentRecording(t *testing.T) {
186205
s := NewStats()
187206

188207
var wg sync.WaitGroup
189-
for i := 0; i < 100; i++ {
208+
for i := range 100 {
190209
wg.Add(1)
191210
go func(n int) {
192211
defer wg.Done()
193-
s.Record(CategoryHTTP, OperationTypeFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now())
212+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now())
194213
}(i)
195214
}
196215
wg.Wait()
@@ -228,7 +247,7 @@ func TestOpenLogFileThenRecord(t *testing.T) {
228247
err := s.OpenLogFile(tmpFile)
229248
assert.NoError(t, err)
230249

231-
s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now())
250+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "test-op", 100*time.Millisecond, true, time.Now())
232251
s.CloseLogFile()
233252

234253
content, err := os.ReadFile(tmpFile)
@@ -248,12 +267,12 @@ func TestOpenLogFileInvalidPath(t *testing.T) {
248267
func TestPrintSummaryWriter(t *testing.T) {
249268
s := NewStats()
250269

251-
s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now())
270+
s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now())
252271

253272
var buf strings.Builder
254273
s.PrintSummary(&buf)
255274

256-
assert.Contains(t, buf.String(), "Update Statistics")
275+
assert.Contains(t, buf.String(), "### Statistics")
257276
assert.Contains(t, buf.String(), "**Overall:**")
258277
assert.Contains(t, buf.String(), "#### Http")
259278
}

0 commit comments

Comments
 (0)