Issue 6884: Random Read Perf Tuning - Token Cache #6885

yaol7 · 2022-09-26T06:39:48Z

Change log description

Add one SimpleCache for DelegationTokenProvider for every segment to avoid the time cost operation, namely token fetch from controller and token parse and so on.
When the EventSegmentReader is created, it should be initialized with the correct read offset from the EventPointer.
Fix one bug in the SegmentStore side for ReadSegment operation. Here is the error message. This issue will result in that there is no ReplyProcessor for the response of ReadSegment operation. The error handler won't be triggered as normal.

2022-08-26 07:42:36,610 398197 [ClientSocketReaders-5] WARN io.pravega.client.connection.impl.FlowHandler: [] - No ReplyProcessor found for the provided flowId 0. Ignoring response

Purpose of the change
Fixes #6884

What the code does
(Detailed description of the code changes)

Test Result
//before perf tuning, result of query result.

50th percentile latency,term,53123.77484299941,ms
90th percentile latency,term,56851.09998769185,ms
99th percentile latency,term,57644.67728016287,ms
100th percentile latency,term,57716.90405299887,ms
50th percentile service time,term,86.67103000334464,ms
90th percentile service time,term,129.02330341166817,ms
99th percentile service time,term,170.20670108206104,ms
100th percentile service time,term,183.68700201972388,ms

//After perf tuning

50th percentile latency,term,15752.61373948888,ms
90th percentile latency,term,17127.619731408777,ms
99th percentile latency,term,17377.725965366117,ms
100th percentile latency,term,17410.35679000197,ms
50th percentile service time,term,64.25273600325454,ms
90th percentile service time,term,73.91316668363288,ms
99th percentile service time,term,84.0185228383052,ms
100th percentile service time,term,89.00812402134761,ms

client/src/main/java/io/pravega/client/segment/impl/EventSegmentReaderImpl.java

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

tkaitchuck · 2022-09-28T03:29:06Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

+
+    protected DelegationTokenProvider getDelegationTokenProvider(Segment segment) {
+        log.debug("getDelegationTokenProvider, scopedName: {}, cacheInfo: {}", segment.getScopedName(), tokenProviderCache.printCache());
+        DelegationTokenProvider tokenProvider = tokenProviderCache.get(segment.getScopedName());


Rather than using a per-segment cache it makes more sense to have a per stream cache. It is possible to create a DelegationTokenProvider given a stream. If we take advantage of this we will be able to consolidate entries in the cache.

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

tkaitchuck · 2022-09-28T03:41:44Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

+    }
+
+    protected DelegationTokenProvider createDelegationTokenProvider(Segment segment) {
+        return DelegationTokenProviderFactory.create(controller, segment, AccessOperation.READ);


Use the stream rather than the segment. (See above)

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

client/src/test/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImplTest.java

tkaitchuck · 2022-09-28T03:50:27Z

client/src/test/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImplTest.java

+        DelegationTokenProvider mockDelegationTokenProvider = mock(DelegationTokenProvider.class);
+        tokenProviderSimpleCache.put("1", mockDelegationTokenProvider);
+
+        Thread.sleep(60000);


Sleep is not allowed in unit tests. We run over 800 tests and they complete in 13 minutes. Please insure that your tests do not take disproportionate time. They should run in a few milliseconds. To do this we need all tests operated based on time to use a Supplier<Long> instead of just using systemTimeMillis that was an alternate implementation can be provided, or alternatively find a way to use a mock or have test methods to make the test deterministic without relying on time.

common/src/main/java/io/pravega/common/util/SimpleCache.java

client/src/test/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImplTest.java

ShwethaSNayak · 2022-10-03T12:55:19Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

-
+    private static final Logger log = LoggerFactory.getLogger(SegmentInputStreamFactoryImpl.class);
+    private static final int CACHE_MAX_SIZE = 100;
+    private static final int EXPIRATION_TIME_MINUTE = 60;


Is it for every 60 minutes token gets evicted from cache? and cache is updated with new token in very next call?

Perhaps this should be in milis. That is more standard.

ShwethaSNayak · 2022-10-03T13:09:38Z

Looks like client Junit test is failing SegmentInputStreamFactoryImplTest.unnecessary Mockito stubbings FAILED, Check https://github.com/pravega/pravega/actions/runs/3150227954/jobs/5122840362 for more details

tkaitchuck · 2022-11-29T04:54:32Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

    private final Controller controller;
    private final ConnectionPool cp;
+    private SimpleCache<String, DelegationTokenProvider> tokenProviderCache;


RaulGracia

Looks good, I have some comments:

Client tests are failing because they are terminating with code 99. If you look to our guidelines (https://github.com/pravega/pravega/wiki/Contributing#builddebugging), this may indicate that at some point of your test some resource is being left open. Please, check this when you have the time.
Have we executed a performance regression test with this change? That would be important to do before being safe when merging this PR.
What would be the performance implication of this change when security is enabled compared to when it is not? Maybe we need to test Pravega with this change and security enabled.

RaulGracia · 2023-01-04T15:31:57Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

 public class SegmentInputStreamFactoryImpl implements SegmentInputStreamFactory {
-
+    private static final Logger log = LoggerFactory.getLogger(SegmentInputStreamFactoryImpl.class);


Normally we use @Slf4j annotation that creates the logger transparently.

RaulGracia · 2023-01-04T15:33:23Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

+        this.controller = controller;
+        this.cp = cp;
+        this.tokenProviderCache = new SimpleCache<>(CACHE_MAX_SIZE,
+                Duration.ofMillis(EXPIRATION_TIME_MILLIS), (k, v) -> log.info("key: {} is evicted from tokenProviderCache.", k));


Do we really need this log to be info level? I think it may be too verbose, so please consider making it debug

RaulGracia · 2023-01-04T15:34:34Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

 public class SegmentInputStreamFactoryImpl implements SegmentInputStreamFactory {
-
+    private static final Logger log = LoggerFactory.getLogger(SegmentInputStreamFactoryImpl.class);
+    private static final int CACHE_MAX_SIZE = 100;


Do we know the heap space of the cache with 100 elements? Why 100 concretely? Do we have an idea of when elements are added or removed from this cache to ensure that this number is good enough?

RaulGracia · 2023-01-04T15:54:08Z

client/src/main/java/io/pravega/client/segment/impl/SegmentInputStreamFactoryImpl.java

@@ -88,4 +108,23 @@ public SegmentInputStream createInputStreamForSegment(Segment segment, Delegatio
        async.getConnection();
        return new SegmentInputStreamImpl(async, startOffset);
    }
+
+    DelegationTokenProvider getDelegationTokenProvider(final String scope, final String streamName) {
+        final String scopedStreamName = NameUtils.getScopedStreamName(scope, streamName);


Do we know how expensive this String operation is? This is being executed on a per-read basis? If so, we may want to think how to get rid of this string operation.

tkaitchuck requested review from tkaitchuck and a6dulaleem September 28, 2022 03:13

tkaitchuck requested changes Sep 28, 2022

View reviewed changes

ShwethaSNayak reviewed Oct 3, 2022

View reviewed changes

tkaitchuck mentioned this pull request Oct 6, 2022

Issue 6884: Optimize reading from an event pointer #6908

Merged

yaol7 force-pushed the issue-6884-PSEARCH-perf-token-cache branch 3 times, most recently from 008c6e2 to 8b5caec Compare October 10, 2022 09:38

yaol7 added 3 commits October 11, 2022 10:16

merge commits

6320fd1

fix checkstyle

7d84a7c

fix checkstyle again

f0faab0

yaol7 force-pushed the issue-6884-PSEARCH-perf-token-cache branch from 6411a61 to f0faab0 Compare October 11, 2022 02:21

yaol7 and others added 3 commits October 11, 2022 16:43

change cache timeout

d7c22db

fix UT

043482d

Merge branch 'master' into issue-6884-PSEARCH-perf-token-cache

f31f0ab

tkaitchuck approved these changes Nov 29, 2022

View reviewed changes

Merge branch 'master' into issue-6884-PSEARCH-perf-token-cache

c146b3b

RaulGracia requested changes Jan 4, 2023

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issue 6884: Random Read Perf Tuning - Token Cache #6885

Issue 6884: Random Read Perf Tuning - Token Cache #6885

yaol7 commented Sep 26, 2022 •

edited by RaulGracia

tkaitchuck Sep 28, 2022

tkaitchuck Sep 28, 2022

tkaitchuck Sep 28, 2022

ShwethaSNayak Oct 3, 2022

tkaitchuck Oct 6, 2022

ShwethaSNayak commented Oct 3, 2022

tkaitchuck Nov 29, 2022

RaulGracia left a comment

RaulGracia Jan 4, 2023

RaulGracia Jan 4, 2023

RaulGracia Jan 4, 2023

RaulGracia Jan 4, 2023

		public class SegmentInputStreamFactoryImpl implements SegmentInputStreamFactory {

		private static final Logger log = LoggerFactory.getLogger(SegmentInputStreamFactoryImpl.class);

Issue 6884: Random Read Perf Tuning - Token Cache #6885

Are you sure you want to change the base?

Issue 6884: Random Read Perf Tuning - Token Cache #6885

Conversation

yaol7 commented Sep 26, 2022 • edited by RaulGracia

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ShwethaSNayak commented Oct 3, 2022

Choose a reason for hiding this comment

RaulGracia left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yaol7 commented Sep 26, 2022 •

edited by RaulGracia