Open leowkong opened 4 months ago
If you provide the iterator stats after performing the seek, we can tell you where the slowness is coming from. The returned IteratorStats
implements fmt.Stringer
, so you can just print out the string representation.
OK, here is some logs to show the iterator stats info.
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:308869 BlockBytesInCache:248176 BlockReadDuration:848.993µs KeyBytes:111 ValueBytes:608 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:334641 BlockBytesInCache:240726 BlockReadDuration:2.074989ms KeyBytes:111 ValueBytes:618 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:307889 BlockBytesInCache:279406 BlockReadDuration:5.573µs KeyBytes:111 ValueBytes:611 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:276894 BlockBytesInCache:215776 BlockReadDuration:1.029304ms KeyBytes:148 ValueBytes:611 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:276894 BlockBytesInCache:215776 BlockReadDuration:979.14µs KeyBytes:148 ValueBytes:611 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:373075 BlockBytesInCache:313171 BlockReadDuration:407.92µs KeyBytes:111 ValueBytes:619 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:22:01+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:307519 BlockBytesInCache:246493 BlockReadDuration:1.05922ms KeyBytes:111 ValueBytes:618 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:351193 BlockBytesInCache:258374 BlockReadDuration:1.104673ms KeyBytes:111 ValueBytes:604 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:351193 BlockBytesInCache:258374 BlockReadDuration:1.119691ms KeyBytes:111 ValueBytes:604 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:348769 BlockBytesInCache:255409 BlockReadDuration:1.289193ms KeyBytes:148 ValueBytes:676 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:348769 BlockBytesInCache:288091 BlockReadDuration:1.23295ms KeyBytes:148 ValueBytes:676 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:351013 BlockBytesInCache:258087 BlockReadDuration:1.113111ms KeyBytes:148 ValueBytes:601 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:351013 BlockBytesInCache:290397 BlockReadDuration:1.067829ms KeyBytes:148 ValueBytes:601 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 3] InternalStats:{BlockBytes:348297 BlockBytesInCache:255582 BlockReadDuration:450.414µs KeyBytes:188 ValueBytes:681 PointCount:5 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 3] InternalStats:{BlockBytes:348297 BlockBytesInCache:320647 BlockReadDuration:343.945µs KeyBytes:188 ValueBytes:681 PointCount:5 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 5] InternalStats:{BlockBytes:301614 BlockBytesInCache:208847 BlockReadDuration:834.793µs KeyBytes:268 ValueBytes:673 PointCount:7 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T08:24:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 5] InternalStats:{BlockBytes:301614 BlockBytesInCache:241402 BlockReadDuration:815.624µs KeyBytes:268 ValueBytes:673 PointCount:7 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
It seems that the cost of BlockReadDuration fluctuates greatly, ranging from of 5 us to 6ms.
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:331887 BlockBytesInCache:305925 BlockReadDuration:624.219µs KeyBytes:113 ValueBytes:681 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:373996 BlockBytesInCache:288980 BlockReadDuration:6.559067ms KeyBytes:24 ValueBytes:1094 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:259141 BlockBytesInCache:198431 BlockReadDuration:3.014409ms KeyBytes:110 ValueBytes:648 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:259208 BlockBytesInCache:165742 BlockReadDuration:28.924µs KeyBytes:108 ValueBytes:712 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:258697 BlockBytesInCache:197955 BlockReadDuration:490.077µs KeyBytes:147 ValueBytes:645 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:195676 BlockBytesInCache:80008 BlockReadDuration:35.506µs KeyBytes:143 ValueBytes:737 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:326256 BlockBytesInCache:267856 BlockReadDuration:697.337µs KeyBytes:153 ValueBytes:662 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:223263 BlockBytesInCache:131552 BlockReadDuration:588.208µs KeyBytes:106 ValueBytes:631 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:387865 BlockBytesInCache:270562 BlockReadDuration:497.407µs KeyBytes:18 ValueBytes:719 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:149475 BlockBytesInCache:84965 BlockReadDuration:394.151µs KeyBytes:102 ValueBytes:233 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:180236 BlockBytesInCache:10778 BlockReadDuration:523.125µs KeyBytes:148 ValueBytes:733 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:179873 BlockBytesInCache:120597 BlockReadDuration:570.834µs KeyBytes:110 ValueBytes:620 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:180319 BlockBytesInCache:120597 BlockReadDuration:921.173µs KeyBytes:109 ValueBytes:664 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:229384 BlockBytesInCache:108078 BlockReadDuration:507.112µs KeyBytes:105 ValueBytes:614 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:390134 BlockBytesInCache:214696 BlockReadDuration:2.215816ms KeyBytes:153 ValueBytes:657 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:395996 BlockBytesInCache:212594 BlockReadDuration:2.054499ms KeyBytes:112 ValueBytes:639 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:332594 BlockBytesInCache:210256 BlockReadDuration:531.138µs KeyBytes:150 ValueBytes:683 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 1] InternalStats:{BlockBytes:332540 BlockBytesInCache:242560 BlockReadDuration:568.109µs KeyBytes:111 ValueBytes:616 PointCount:3 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:389161 BlockBytesInCache:266747 BlockReadDuration:1.410233ms KeyBytes:149 ValueBytes:731 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:252947 BlockBytesInCache:194011 BlockReadDuration:1.063252ms KeyBytes:150 ValueBytes:660 PointCount:4 PointsCoveredByRangeTombstones:0 SeparatedPointValue:{Count:0 ValueBytes:0 ValueBytesFetched:0}} RangeKeyStats:{Count:0 ContainedPoints:0 SkippedPoints:0}}"
t=2024-05-07T10:00:00+0000 lvl=info msg="iterator stat" stat="{ForwardSeekCount:[1 1] ReverseSeekCount:[1 1] ForwardStepCount:[0 0] ReverseStepCount:[0 2] InternalStats:{BlockBytes:227402 BlockBytesInCac
I tried to seek LT a key In a pebble DB which is about 600G. The code is as follows. I tested that the seek overhead takes about 1.5ms, which seems a bit slow. Is there any way to improve the performance of seek ?
pebble.Iterator.SeekLT(key)
Jira issue: PEBBLE-91