Compact reports deleting more rows than revisions

After running a load test against the cluster, compaction reports deleting more rows than revisions. I'm not sure if this is a bug or what, but it merits investigation.

INFO[10800] COMPACT compactRev=570142 targetCompactRev=571142 currentRev=575816
INFO[10800] COMPACT deleted 1967 rows from 1000 revisions in 64.858348ms - compacted to 571142/575816
INFO[10800] COMPACT compactRev=571142 targetCompactRev=572142 currentRev=575817
INFO[10800] COMPACT deleted 1965 rows from 1000 revisions in 64.937484ms - compacted to 572142/575817
INFO[10800] COMPACT compactRev=572142 targetCompactRev=573142 currentRev=575818
INFO[10800] COMPACT deleted 1968 rows from 1000 revisions in 61.562873ms - compacted to 573142/575818
INFO[10800] COMPACT compactRev=573142 targetCompactRev=574142 currentRev=575819
INFO[10800] COMPACT deleted 1969 rows from 1000 revisions in 395.45276ms - compacted to 574142/575819
INFO[10800] COMPACT compactRev=574142 targetCompactRev=574824 currentRev=575824
INFO[10800] COMPACT deleted 1343 rows from 682 revisions in 41.083903ms - compacted to 574824/575824
INFO[10800] COMPACT compactRev=574824 targetCompactRev=574825 currentRev=575825
INFO[10800] COMPACT deleted 2 rows from 1 revisions in 81.61197ms - compacted to 574825/575825
INFO[10800] COMPACT compactRev=574825 targetCompactRev=574828 currentRev=575828
INFO[10800] COMPACT deleted 6 rows from 3 revisions in 10.927536ms - compacted to 574828/575828
INFO[10800] COMPACT revision 574828 has already been compacted

INFO[11100] COMPACT compactRev=574828 targetCompactRev=575828 currentRev=577945
INFO[11100] COMPACT deleted 1970 rows from 1000 revisions in 144.060248ms - compacted to 575828/577945
INFO[11100] COMPACT compactRev=575828 targetCompactRev=576828 currentRev=577945
INFO[11100] COMPACT deleted 1978 rows from 1000 revisions in 120.049635ms - compacted to 576828/577945
INFO[11100] COMPACT compactRev=576828 targetCompactRev=576945 currentRev=577945
INFO[11100] COMPACT deleted 232 rows from 117 revisions in 5.256438ms - compacted to 576945/577945
INFO[11100] COMPACT revision 576945 has already been compacted

INFO[11400] COMPACT compactRev=576945 targetCompactRev=577097 currentRev=578097
INFO[11400] COMPACT deleted 301 rows from 152 revisions in 5.880181ms - compacted to 577097/578097
INFO[11400] COMPACT revision 577097 has already been compacted

INFO[11700] COMPACT compactRev=577097 targetCompactRev=577247 currentRev=578247
INFO[11700] COMPACT deleted 297 rows from 150 revisions in 5.36026ms - compacted to 577247/578247
INFO[11700] COMPACT revision 577247 has already been compacted

INFO[12000] COMPACT compactRev=577247 targetCompactRev=577397 currentRev=578397
INFO[12000] COMPACT deleted 295 rows from 150 revisions in 5.281118ms - compacted to 577397/578397
INFO[12000] COMPACT revision 577397 has already been compacted

INFO[12300] COMPACT compactRev=577397 targetCompactRev=577547 currentRev=578547
INFO[12300] COMPACT deleted 296 rows from 150 revisions in 4.074243ms - compacted to 577547/578547
INFO[12300] COMPACT revision 577547 has already been compacted

INFO[12600] COMPACT compactRev=577547 targetCompactRev=577698 currentRev=578698
INFO[12600] COMPACT deleted 298 rows from 151 revisions in 3.981763ms - compacted to 577698/578698
INFO[12600] COMPACT revision 577698 has already been compacted

INFO[12900] COMPACT compactRev=577698 targetCompactRev=577849 currentRev=578849
INFO[12900] COMPACT deleted 291 rows from 151 revisions in 3.780366ms - compacted to 577849/578849
INFO[12900] COMPACT revision 577849 has already been compacted

INFO[13200] COMPACT compactRev=577849 targetCompactRev=577998 currentRev=578998
INFO[13200] COMPACT deleted 149 rows from 149 revisions in 2.059911ms - compacted to 577998/578998
INFO[13200] COMPACT revision 577998 has already been compacted

INFO[13500] COMPACT compactRev=577998 targetCompactRev=578150 currentRev=579150
INFO[13500] COMPACT deleted 152 rows from 152 revisions in 2.167049ms - compacted to 578150/579150
INFO[13500] COMPACT revision 578150 has already been compacted

Note that it does eventually settle out after some, a while after the load test is done. Perhaps related to rows with TTLs expiring? These would be deleted directly from the datastore, without a new resource version being written with a deletion timestamp.

kine/pkg/logstructured/logstructured.go

Lines 332 to 351 in 7966aec

    
           func (l *LogStructured) deleteTTLEvent(ctx context.Context, rwMutex *sync.RWMutex, queue workqueue.DelayingInterface, store map[string]*ttlEventKV, preEventKV *ttlEventKV) { 
        
           	logrus.Tracef("TTL delete key=%v, modRev=%v", preEventKV.key, preEventKV.modRevision) 
        
           	_, _, _, err := l.Delete(ctx, preEventKV.key, preEventKV.modRevision) 
        
           	rwMutex.Lock() 
        
           	defer rwMutex.Unlock() 
        
           	curEventKV := store[preEventKV.key] 
        
           	if expires := time.Until(preEventKV.expiredAt); expires > 0 { 
        
           		logrus.Tracef("TTL changed for key=%v, ttl=%v, requeuing", curEventKV.key, expires) 
        
           		queue.AddAfter(curEventKV.key, expires) 
        
           		return 
        
           	} 
        
           	if err != nil { 
        
           		logrus.Errorf("TTL delete trigger failed for key=%v: %v, requeuing", curEventKV.key, err) 
        
           		queue.AddAfter(curEventKV.key, retryInterval) 
        
           		return 
        
           	} 
        
           	delete(store, curEventKV.key) 
        
           }

We should probably have some metrics around workqueue depth and delay to see if massive loading of events (one of the things that the load test does) is pushing the TTL workqueue harder than it currently handles well.

Also - with the change from #360 the inner loop will keep moving the target ahead if additional revisions are created while it's running. Note the last few iterations only compact 1 or 2 revisions:

INFO[53412] COMPACT deleted 862 rows from 1000 revisions in 2.947247152s - compacted to 1096826/1099604
INFO[53412] COMPACT compactRev=1096826 targetCompactRev=1097826 currentRev=1099837
INFO[53413] COMPACT deleted 843 rows from 1000 revisions in 648.104571ms - compacted to 1097826/1099837
INFO[53413] COMPACT compactRev=1097826 targetCompactRev=1098826 currentRev=1099845
INFO[53413] Slow SQL (started: 2024-11-09 21:22:58.174645676 +0000 UTC m=+53412.401320151) (total time: 1.440060519s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53413] Slow SQL (started: 2024-11-09 21:22:58.289642821 +0000 UTC m=+53412.516317299) (total time: 1.341544461s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53413] Slow SQL (started: 2024-11-09 21:22:58.197540114 +0000 UTC m=+53412.424214592) (total time: 1.445241296s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53413] Slow SQL (started: 2024-11-09 21:22:58.314585121 +0000 UTC m=+53412.541259599) (total time: 1.335857041s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53413] Slow SQL (started: 2024-11-09 21:22:58.315111221 +0000 UTC m=+53412.541785695) (total time: 1.338622485s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53413] COMPACT deleted 853 rows from 1000 revisions in 812.318136ms - compacted to 1098826/1099845
INFO[53413] COMPACT compactRev=1098826 targetCompactRev=1098858 currentRev=1099858
INFO[53414] COMPACT deleted 26 rows from 32 revisions in 160.392819ms - compacted to 1098858/1099858
INFO[53414] COMPACT compactRev=1098858 targetCompactRev=1098863 currentRev=1099863
INFO[53414] COMPACT deleted 6 rows from 5 revisions in 129.711591ms - compacted to 1098863/1099863
INFO[53414] COMPACT compactRev=1098863 targetCompactRev=1098867 currentRev=1099867
INFO[53414] COMPACT deleted 3 rows from 4 revisions in 129.218484ms - compacted to 1098867/1099867
INFO[53414] Slow SQL (started: 2024-11-09 21:22:59.047867499 +0000 UTC m=+53413.274541981) (total time: 1.034245771s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] COMPACT compactRev=1098867 targetCompactRev=1098871 currentRev=1099871
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.314224416 +0000 UTC m=+53412.540898899) (total time: 1.952776121s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.333228445 +0000 UTC m=+53412.559902915) (total time: 1.938591024s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.328184702 +0000 UTC m=+53412.554859190) (total time: 1.94796984s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.223311306 +0000 UTC m=+53412.449985790) (total time: 2.06053351s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.857216924 +0000 UTC m=+53413.083891396) (total time: 1.4370368s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.344998712 +0000 UTC m=+53412.571673193) (total time: 2.046882668s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.856962434 +0000 UTC m=+53413.083636894) (total time: 1.543905423s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.851456057 +0000 UTC m=+53413.078130536) (total time: 1.742267497s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53414] Slow SQL (started: 2024-11-09 21:22:58.849080401 +0000 UTC m=+53413.075754870) (total time: 1.746377914s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53415] COMPACT deleted 4 rows from 4 revisions in 705.579236ms - compacted to 1098871/1099871
INFO[53415] COMPACT compactRev=1098871 targetCompactRev=1098943 currentRev=1099943
INFO[53415] COMPACT deleted 51 rows from 72 revisions in 289.25054ms - compacted to 1098943/1099943
INFO[53415] COMPACT compactRev=1098943 targetCompactRev=1098958 currentRev=1099958
INFO[53416] COMPACT deleted 12 rows from 15 revisions in 753.832119ms - compacted to 1098958/1099958
INFO[53416] COMPACT compactRev=1098958 targetCompactRev=1098960 currentRev=1099960
INFO[53416] COMPACT deleted 2 rows from 2 revisions in 129.563549ms - compacted to 1098960/1099960
INFO[53416] COMPACT compactRev=1098960 targetCompactRev=1098962 currentRev=1099962
INFO[53416] COMPACT deleted 2 rows from 2 revisions in 94.541446ms - compacted to 1098962/1099962
INFO[53416] COMPACT compactRev=1098962 targetCompactRev=1098963 currentRev=1099963
INFO[53416] COMPACT deleted 1 rows from 1 revisions in 110.428183ms - compacted to 1098963/1099963
INFO[53416] COMPACT compactRev=1098963 targetCompactRev=1098964 currentRev=1099964
INFO[53416] COMPACT deleted 1 rows from 1 revisions in 95.891528ms - compacted to 1098964/1099964
INFO[53416] COMPACT compactRev=1098964 targetCompactRev=1098965 currentRev=1099965
INFO[53416] Slow SQL (started: 2024-11-09 21:23:00.852904861 +0000 UTC m=+53415.079579343) (total time: 1.569605744s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] COMPACT deleted 1 rows from 1 revisions in 85.956708ms - compacted to 1098965/1099965
INFO[53416] COMPACT revision 1098965 has already been compacted
INFO[53416] Slow SQL (started: 2024-11-09 21:23:01.477361719 +0000 UTC m=+53415.704036199) (total time: 1.084286539s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:00.877062254 +0000 UTC m=+53415.103736741) (total time: 1.700905452s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:01.410976822 +0000 UTC m=+53415.637651303) (total time: 1.170574172s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:00.894390494 +0000 UTC m=+53415.121064981) (total time: 1.710018944s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:00.937511315 +0000 UTC m=+53415.164185786) (total time: 1.713459244s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:00.913917946 +0000 UTC m=+53415.140592435) (total time: 1.781935429s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:01.430844352 +0000 UTC m=+53415.657518833) (total time: 1.276350372s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53416] Slow SQL (started: 2024-11-09 21:23:00.875963678 +0000 UTC m=+53415.102638145) (total time: 1.896441629s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53417] Slow SQL (started: 2024-11-09 21:23:01.411000502 +0000 UTC m=+53415.637674976) (total time: 1.374890372s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53417] Slow SQL (started: 2024-11-09 21:23:00.880423509 +0000 UTC m=+53415.107097987) (total time: 1.920489603s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)
INFO[53417] Slow SQL (started: 2024-11-09 21:23:00.915218952 +0000 UTC m=+53415.141893422) (total time: 1.99156104s): INSERT INTO kine(name, created, deleted, create_revision, prev_revision, lease, value, old_value) values(?, ?, ?, ?, ?, ?, ?, ?)

Confirmed that the additional deleted rows are from resources deleted by TTL.
The rolling target revision is a regression though.

	func (l LogStructured) deleteTTLEvent(ctx context.Context, rwMutex sync.RWMutex, queue workqueue.DelayingInterface, store map[string]ttlEventKV, preEventKV ttlEventKV) {
	logrus.Tracef("TTL delete key=%v, modRev=%v", preEventKV.key, preEventKV.modRevision)
	_, _, _, err := l.Delete(ctx, preEventKV.key, preEventKV.modRevision)

	rwMutex.Lock()
	defer rwMutex.Unlock()
	curEventKV := store[preEventKV.key]
	if expires := time.Until(preEventKV.expiredAt); expires > 0 {
	logrus.Tracef("TTL changed for key=%v, ttl=%v, requeuing", curEventKV.key, expires)
	queue.AddAfter(curEventKV.key, expires)
	return
	}
	if err != nil {
	logrus.Errorf("TTL delete trigger failed for key=%v: %v, requeuing", curEventKV.key, err)
	queue.AddAfter(curEventKV.key, retryInterval)
	return
	}

	delete(store, curEventKV.key)
	}