Skip to content

Commit bb18504

Browse files
author
Thomas Hardy
committed
scheduledlogging: shorten TestCaptureIndexUsageStats run time
Previously, TestCaptureIndexUsageStats ran through 4 iterations of 20 seconds for a run time of over a minute. This change reduces the run time of the test to under 10 seconds. Release note: None
1 parent b6eb2f8 commit bb18504

3 files changed

Lines changed: 80 additions & 67 deletions

File tree

‎pkg/sql/scheduledlogging/BUILD.bazel‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -38,9 +38,7 @@ go_test(
3838
"//pkg/security/securitytest",
3939
"//pkg/server",
4040
"//pkg/settings/cluster",
41-
"//pkg/testutils",
4241
"//pkg/testutils/serverutils",
43-
"//pkg/testutils/skip",
4442
"//pkg/testutils/sqlutils",
4543
"//pkg/testutils/testcluster",
4644
"//pkg/util/leaktest",

‎pkg/sql/scheduledlogging/captured_index_usage_stats.go‎

Lines changed: 16 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -72,6 +72,9 @@ type CaptureIndexUsageStatsTestingKnobs struct {
7272
// scheduled interval in the case that the logging duration exceeds the
7373
// default scheduled interval duration.
7474
getOverlapDuration func() time.Duration
75+
// onScheduleComplete allows tests to hook into when the current schedule
76+
// is completed to check for the expected logs.
77+
onScheduleComplete func()
7578
}
7679

7780
// ModuleTestingKnobs implements base.ModuleTestingKnobs interface.
@@ -104,17 +107,14 @@ func (s *CaptureIndexUsageStatsLoggingScheduler) durationOnOverlap() time.Durati
104107
}
105108

106109
func (s *CaptureIndexUsageStatsLoggingScheduler) durationUntilNextInterval() time.Duration {
107-
// If telemetry is disabled, return the disabled interval duration.
108-
if !telemetryCaptureIndexUsageStatsEnabled.Get(&s.st.SV) {
109-
return telemetryCaptureIndexUsageStatsStatusCheckEnabledInterval.Get(&s.st.SV)
110-
}
110+
loggingDur := s.getLoggingDuration()
111111
// If the previous logging operation took longer than or equal to the set
112112
// schedule interval, schedule the next interval immediately.
113-
if s.getLoggingDuration() >= telemetryCaptureIndexUsageStatsInterval.Get(&s.st.SV) {
113+
if loggingDur >= telemetryCaptureIndexUsageStatsInterval.Get(&s.st.SV) {
114114
return s.durationOnOverlap()
115115
}
116116
// Otherwise, schedule the next interval normally.
117-
return telemetryCaptureIndexUsageStatsInterval.Get(&s.st.SV)
117+
return telemetryCaptureIndexUsageStatsInterval.Get(&s.st.SV) - loggingDur
118118
}
119119

120120
// Start starts the capture index usage statistics logging scheduler.
@@ -146,22 +146,24 @@ func (s *CaptureIndexUsageStatsLoggingScheduler) start(ctx context.Context, stop
146146
case <-stopper.ShouldQuiesce():
147147
return
148148
case <-timer.C:
149+
if !telemetryCaptureIndexUsageStatsEnabled.Get(&s.st.SV) {
150+
timer.Reset(telemetryCaptureIndexUsageStatsStatusCheckEnabledInterval.Get(&s.st.SV))
151+
continue
152+
}
149153
s.currentCaptureStartTime = timeutil.Now()
154+
err := captureIndexUsageStats(ctx, s.ie, stopper, telemetryCaptureIndexUsageStatsLoggingDelay.Get(&s.st.SV))
155+
if err != nil {
156+
log.Warningf(ctx, "error capturing index usage stats: %+v", err)
157+
}
150158
dur := s.durationUntilNextInterval()
151159
if dur < time.Second {
152160
// Avoid intervals that are too short, to prevent a hot
153161
// spot on this task.
154162
dur = time.Second
155163
}
156164
timer.Reset(dur)
157-
158-
if !telemetryCaptureIndexUsageStatsEnabled.Get(&s.st.SV) {
159-
continue
160-
}
161-
162-
err := captureIndexUsageStats(ctx, s.ie, stopper, telemetryCaptureIndexUsageStatsLoggingDelay.Get(&s.st.SV))
163-
if err != nil {
164-
log.Warningf(ctx, "error capturing index usage stats: %+v", err)
165+
if s.knobs != nil && s.knobs.onScheduleComplete != nil {
166+
s.knobs.onScheduleComplete()
165167
}
166168
}
167169
}

‎pkg/sql/scheduledlogging/captured_index_usage_stats_test.go‎

Lines changed: 64 additions & 51 deletions
Original file line numberDiff line numberDiff line change
@@ -22,9 +22,7 @@ import (
2222

2323
"github.com/cockroachdb/cockroach/pkg/base"
2424
"github.com/cockroachdb/cockroach/pkg/settings/cluster"
25-
"github.com/cockroachdb/cockroach/pkg/testutils"
2625
"github.com/cockroachdb/cockroach/pkg/testutils/serverutils"
27-
"github.com/cockroachdb/cockroach/pkg/testutils/skip"
2826
"github.com/cockroachdb/cockroach/pkg/testutils/sqlutils"
2927
"github.com/cockroachdb/cockroach/pkg/util/leaktest"
3028
"github.com/cockroachdb/cockroach/pkg/util/log"
@@ -66,26 +64,22 @@ func (s *stubDurations) getOverlapDuration() time.Duration {
6664

6765
func TestCaptureIndexUsageStats(t *testing.T) {
6866
defer leaktest.AfterTest(t)()
69-
70-
skip.UnderShort(t, "#87772")
71-
7267
sc := log.ScopeWithoutShowLogs(t)
7368
defer sc.Close(t)
7469

7570
cleanup := logtestutils.InstallTelemetryLogFileSink(sc, t)
7671
defer cleanup()
7772

73+
firstScheduleLoggingDuration := 1 * time.Second
7874
sd := stubDurations{}
79-
sd.setLoggingDuration(1 * time.Second)
80-
sd.setOverlapDuration(10 * time.Second)
81-
stubScheduleInterval := 20 * time.Second
82-
stubScheduleCheckEnabledInterval := 1 * time.Second
75+
sd.setLoggingDuration(firstScheduleLoggingDuration)
76+
sd.setOverlapDuration(time.Second)
77+
stubScheduleInterval := 2 * time.Second
78+
stubScheduleCheckEnabledInterval := time.Second
8379
stubLoggingDelay := 0 * time.Second
8480

85-
// timeBuffer is a short time buffer to account for delays in the schedule
86-
// timings when running tests. The time buffer is smaller than the difference
87-
// between each schedule interval to ensure that there is no overlap.
88-
timeBuffer := 5 * time.Second
81+
// timeBuffer is a short time buffer to account for non-determinism in the logging timings.
82+
timeBuffer := time.Second
8983

9084
settings := cluster.MakeTestingClusterSettings()
9185
// Configure capture index usage statistics to be disabled. This is to test
@@ -103,12 +97,18 @@ func TestCaptureIndexUsageStats(t *testing.T) {
10397
// Configure the delay between each emission of index usage stats logs.
10498
telemetryCaptureIndexUsageStatsLoggingDelay.Override(context.Background(), &settings.SV, stubLoggingDelay)
10599

100+
scheduleCompleteChan := make(chan struct{})
101+
106102
s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{
107103
Settings: settings,
108104
Knobs: base.TestingKnobs{
109105
CapturedIndexUsageStatsKnobs: &CaptureIndexUsageStatsTestingKnobs{
110106
getLoggingDuration: sd.getLoggingDuration,
111107
getOverlapDuration: sd.getOverlapDuration,
108+
onScheduleComplete: func() {
109+
scheduleCompleteChan <- struct{}{}
110+
<-scheduleCompleteChan
111+
},
112112
},
113113
},
114114
})
@@ -157,18 +157,19 @@ func TestCaptureIndexUsageStats(t *testing.T) {
157157
expectedTotalNumEntriesInSingleInterval := 8
158158
expectedNumberOfIndividualIndexEntriesInSingleInterval := 1
159159

160-
// Expect index usage statistics logs once the schedule disabled interval has passed.
161-
// Assert that we have the expected number of total logs and expected number
162-
// of logs for each index.
163-
testutils.SucceedsWithin(t, func() error {
164-
return checkNumTotalEntriesAndNumIndexEntries(t,
165-
expectedIndexNames,
166-
expectedTotalNumEntriesInSingleInterval,
167-
expectedNumberOfIndividualIndexEntriesInSingleInterval,
168-
)
169-
}, stubScheduleCheckEnabledInterval+timeBuffer)
170-
171-
// Verify that a second schedule has run after the enabled interval has passed.
160+
// Wait for channel value from end of 1st schedule.
161+
<-scheduleCompleteChan
162+
163+
// Check the expected number of entries from the 1st schedule.
164+
require.NoError(t, checkNumTotalEntriesAndNumIndexEntries(t,
165+
expectedIndexNames,
166+
expectedTotalNumEntriesInSingleInterval,
167+
expectedNumberOfIndividualIndexEntriesInSingleInterval,
168+
scheduleCompleteChan,
169+
), "error encountered checking the number of total entries and number of index entries")
170+
171+
scheduleCompleteChan <- struct{}{}
172+
172173
// Expect number of total entries to hold 2 times the number of entries in a
173174
// single interval.
174175
expectedTotalNumEntriesAfterTwoIntervals := expectedTotalNumEntriesInSingleInterval * 2
@@ -180,37 +181,42 @@ func TestCaptureIndexUsageStats(t *testing.T) {
180181
stubLoggingDuration := stubScheduleInterval * 2
181182
sd.setLoggingDuration(stubLoggingDuration)
182183

183-
// Expect index usage statistics logs once the schedule enabled interval has passed.
184-
// Assert that we have the expected number of total logs and expected number
185-
// of logs for each index.
186-
testutils.SucceedsWithin(t, func() error {
187-
return checkNumTotalEntriesAndNumIndexEntries(t,
188-
expectedIndexNames,
189-
expectedTotalNumEntriesAfterTwoIntervals,
190-
expectedNumberOfIndividualIndexEntriesAfterTwoIntervals,
191-
)
192-
}, stubScheduleInterval+timeBuffer)
193-
194-
// Verify that a third schedule has run after the overlap duration has passed.
184+
// Wait for channel value from end of 2nd schedule.
185+
<-scheduleCompleteChan
186+
187+
// Check the expected number of entries from the 2nd schedule.
188+
require.NoError(t, checkNumTotalEntriesAndNumIndexEntries(t,
189+
expectedIndexNames,
190+
expectedTotalNumEntriesAfterTwoIntervals,
191+
expectedNumberOfIndividualIndexEntriesAfterTwoIntervals,
192+
scheduleCompleteChan,
193+
), "error encountered checking the number of total entries and number of index entries")
194+
195+
scheduleCompleteChan <- struct{}{}
196+
195197
// Expect number of total entries to hold 3 times the number of entries in a
196198
// single interval.
197199
expectedTotalNumEntriesAfterThreeIntervals := expectedTotalNumEntriesInSingleInterval * 3
198200
// Expect number of individual index entries to hold 3 times the number of
199201
// entries in a single interval.
200202
expectedNumberOfIndividualIndexEntriesAfterThreeIntervals := expectedNumberOfIndividualIndexEntriesInSingleInterval * 3
201203

202-
// Assert that we have the expected number of total logs and expected number
203-
// of logs for each index.
204-
testutils.SucceedsWithin(t, func() error {
205-
return checkNumTotalEntriesAndNumIndexEntries(t,
206-
expectedIndexNames,
207-
expectedTotalNumEntriesAfterThreeIntervals,
208-
expectedNumberOfIndividualIndexEntriesAfterThreeIntervals,
209-
)
210-
}, sd.getOverlapDuration()+timeBuffer)
204+
// Wait for channel value from end of 3rd schedule.
205+
<-scheduleCompleteChan
206+
207+
// Check the expected number of entries from the 3rd schedule.
208+
require.NoError(t, checkNumTotalEntriesAndNumIndexEntries(t,
209+
expectedIndexNames,
210+
expectedTotalNumEntriesAfterThreeIntervals,
211+
expectedNumberOfIndividualIndexEntriesAfterThreeIntervals,
212+
scheduleCompleteChan,
213+
), "error encountered checking the number of total entries and number of index entries")
214+
211215
// Stop capturing index usage statistics.
212216
telemetryCaptureIndexUsageStatsEnabled.Override(context.Background(), &settings.SV, false)
213217

218+
scheduleCompleteChan <- struct{}{}
219+
214220
// Iterate through entries, ensure that the timestamp difference between each
215221
// schedule is as expected.
216222
startTimestamp := int64(0)
@@ -234,7 +240,7 @@ func TestCaptureIndexUsageStats(t *testing.T) {
234240
testData := []time.Duration{
235241
0 * time.Second,
236242
// the difference in number of seconds between first and second schedule
237-
stubScheduleInterval,
243+
stubScheduleInterval - firstScheduleLoggingDuration,
238244
// the difference in number of seconds between second and third schedule
239245
sd.getOverlapDuration(),
240246
}
@@ -257,9 +263,9 @@ func TestCaptureIndexUsageStats(t *testing.T) {
257263
}
258264

259265
actualDuration := time.Duration(currentTimestamp-previousTimestamp) * time.Nanosecond
260-
// Use a time window to afford some non-determinisim in the test.
261-
require.Greater(t, expectedDuration, actualDuration-time.Second)
262-
require.Greater(t, actualDuration+time.Second, expectedDuration)
266+
// Use a time window to afford some non-determinism in the test.
267+
require.Greater(t, expectedDuration, actualDuration-timeBuffer)
268+
require.Greater(t, actualDuration+timeBuffer, expectedDuration)
263269
previousTimestamp = currentTimestamp
264270
}
265271
}
@@ -273,7 +279,9 @@ func checkNumTotalEntriesAndNumIndexEntries(
273279
expectedIndexNames []string,
274280
expectedTotalEntries int,
275281
expectedIndividualIndexEntries int,
282+
scheduleCompleteChan chan struct{},
276283
) error {
284+
log.Flush()
277285
// Fetch log entries.
278286
entries, err := log.FetchEntriesFromFiles(
279287
0,
@@ -283,11 +291,13 @@ func checkNumTotalEntriesAndNumIndexEntries(
283291
log.WithMarkedSensitiveData,
284292
)
285293
if err != nil {
294+
close(scheduleCompleteChan)
286295
return err
287296
}
288297

289298
// Assert that we have the correct number of entries.
290299
if expectedTotalEntries != len(entries) {
300+
close(scheduleCompleteChan)
291301
return errors.Newf("expected %d total entries, got %d", expectedTotalEntries, len(entries))
292302
}
293303

@@ -305,6 +315,7 @@ func checkNumTotalEntriesAndNumIndexEntries(
305315
}
306316
err := json.Unmarshal([]byte(e.Message), &s)
307317
if err != nil {
318+
close(scheduleCompleteChan)
308319
t.Fatal(err)
309320
}
310321
countByIndex[s.IndexName] = countByIndex[s.IndexName] + 1
@@ -313,21 +324,23 @@ func checkNumTotalEntriesAndNumIndexEntries(
313324
t.Logf("found index counts: %+v", countByIndex)
314325

315326
if expected, actual := expectedTotalEntries/expectedIndividualIndexEntries, len(countByIndex); actual != expected {
327+
close(scheduleCompleteChan)
316328
return errors.Newf("expected %d indexes, got %d", expected, actual)
317329
}
318330

319331
for idxName, c := range countByIndex {
320332
if c != expectedIndividualIndexEntries {
333+
close(scheduleCompleteChan)
321334
return errors.Newf("for index %s: expected entry count %d, got %d",
322335
idxName, expectedIndividualIndexEntries, c)
323336
}
324337
}
325338

326339
for _, idxName := range expectedIndexNames {
327340
if _, ok := countByIndex[idxName]; !ok {
341+
close(scheduleCompleteChan)
328342
return errors.Newf("no entry found for index %s", idxName)
329343
}
330344
}
331-
332345
return nil
333346
}

0 commit comments

Comments
 (0)