search

pravega / pravega-operator

Pravega Kubernetes Operator
Apache License 2.0
41 stars 38 forks source link

Write latency is very high when external connectivity enabled on Pravega in PKS #168

Closed deenav closed 5 years ago

deenav commented 5 years ago

Observing very high latency for write events while running pravega-benchmark on external-connectivity enabled Pravega cluster. For writing events of size 1KB and 100 events/sec it takes more than 250ms whereas for read events it is only ~2ms.

./bin/pravega-benchmark -controller tcp://10.240.124.123:9090  --stream test1  -producers 1 --size 1000  -events 100 --time 120 -randomkey true -consumers 1

Deployment Details:- bookkeeper: 0.5.0-2222.8ba5431 pravega: 0.5.0-2222.8ba5431 zookeeper: 3.5.4-beta-operator pravega-operator: 0.3.2 zookeeper-operator: 0.2.1 External-connectivity enabled

Environment details: PKS / K8 with medium cluster: 3 master: xlarge: 4 CPU, 16 GB Ram, 32 GB Disk 5 worker: 2xlarge: 8 CPU, 32 GB Ram, 64 GB Disk Tier-1 storage is from VSAN datastore Tier-2 storage curved on NFS Client provisioner using Isilon as backend

Pravega-Benchmark logs

# ./bin/pravega-benchmark -controller tcp://10.240.124.123:9090  --stream test1  -producers 1 --size 1000  -events 100 --time 120 -randomkey true -consumers 1
[main] INFO io.pravega.client.stream.impl.ControllerImpl - Controller client connecting to server at 10.240.124.123:9090
[main] INFO io.pravega.client.stream.impl.ControllerImpl - Controller client connecting to server at 10.240.124.123:9090
[main] INFO io.pravega.client.admin.impl.StreamManagerImpl - Creating scope: Scope
[StreamManager-Controller-1] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=3831340591459511631] Tagging client request (createScope-Scope).
[StreamManager-Controller-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Updating client with controllers: [[[/10.240.124.123:9090]/{}]]
[grpc-default-executor-0] WARN io.pravega.client.stream.impl.ControllerImpl - [requestId=3831340591459511631] Scope already exists: Scope
[main] INFO io.pravega.client.admin.impl.StreamManagerImpl - Creating scope/stream: Scope/test1 with configuration: StreamConfiguration(scalingPolicy=ScalingPolicy(scaleType=FIXED_NUM_SEGMENTS, targetRate=0, scaleFactor=0, minNumSegments=1), retentionPolicy=null)
[StreamManager-Controller-1] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=4731260475901389123] Tagging client request (createStream-Scope-test1).
[grpc-default-executor-0] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=4731260475901389123] Stream created successfully: test1
[main] INFO io.pravega.client.stream.impl.ControllerImpl - Controller client connecting to server at 10.240.124.123:9090
[main] INFO io.pravega.client.admin.impl.ReaderGroupManagerImpl - Creating reader group: test1 for streams: [StreamImpl(scope=Scope, streamName=test1)] with configuration: ReaderGroupConfig(groupRefreshTimeMillis=3000, automaticCheckpointIntervalMillis=120000, startingStreamCuts={StreamImpl(scope=Scope, streamName=test1)=UNBOUNDED}, endingStreamCuts={StreamImpl(scope=Scope, streamName=test1)=UNBOUNDED}, maxOutstandingCheckpointRequest=3)
[clientInternal-1] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=3619522339018480726] Tagging client request (createStream-Scope-_RGtest1).
[clientInternal-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Updating client with controllers: [[[/10.240.124.123:9090]/{}]]
[grpc-default-executor-0] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=3619522339018480726] Stream created successfully: _RGtest1
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating state synchronizer with stream: _RGtest1 and configuration: SynchronizerConfig(eventWriterConfig=EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999))
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating revisioned stream client for stream: _RGtest1 with synchronizer configuration: SynchronizerConfig(eventWriterConfig=EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999))
[epollEventLoopGroup-5-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x8d4b6888]
[clientInternal-4] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/_RGtest1/0.#epoch.0, writerID: 0f0be887-fb98-4080-b582-bd3dcb14c162
[epollEventLoopGroup-5-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 1 for endpoint 10.240.124.125. The current Channel is [id: 0x8d4b6888, L:/10.31.14.27:46428 - R:10.240.124.125/10.240.124.125:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=10.240.124.125, port=12345) for Scope/_RGtest1/0.#epoch.0, writerID: 0f0be887-fb98-4080-b582-bd3dcb14c162
[epollEventLoopGroup-5-2] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x3cbc0ac9]
[epollEventLoopGroup-5-2] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 2 for endpoint 10.240.124.125. The current Channel is [id: 0x3cbc0ac9, L:/10.31.14.27:46430 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-5-1] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-5-3] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x418aafc0]
[epollEventLoopGroup-5-2] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-5-3] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 3 for endpoint 10.240.124.125. The current Channel is [id: 0x418aafc0, L:/10.31.14.27:46432 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-5-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=8589934592, segment=Scope/_RGtest1/0.#epoch.0, writerId=0f0be887-fb98-4080-b582-bd3dcb14c162, lastEventNumber=-9223372036854775808)
[epollEventLoopGroup-5-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 0f0be887-fb98-4080-b582-bd3dcb14c162
[epollEventLoopGroup-5-3] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-5-4] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x98b89f03]
[epollEventLoopGroup-5-4] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 4 for endpoint 10.240.124.125. The current Channel is [id: 0x98b89f03, L:/10.31.14.27:46434 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-5-4] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[main] INFO io.pravega.client.state.impl.StateSynchronizerImpl - Closing stateSynchronizer
[main] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 2 for endpoint 10.240.124.125
[main] INFO io.pravega.client.segment.impl.ConditionalOutputStreamImpl - Closing segment metadata connection for Scope/_RGtest1/0.#epoch.0
[main] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 4 for endpoint 10.240.124.125
[main] INFO io.pravega.client.segment.impl.SegmentMetadataClientImpl - Closing segment metadata connection for Scope/_RGtest1/0.#epoch.0
[main] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 3 for endpoint 10.240.124.125
[main] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/_RGtest1/0.#epoch.0
[main] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/_RGtest1/0.#epoch.0
[main] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 1 for endpoint 10.240.124.125
[main] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating state synchronizer with stream: _RGtest1 and configuration: SynchronizerConfig(eventWriterConfig=EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999))
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating revisioned stream client for stream: _RGtest1 with synchronizer configuration: SynchronizerConfig(eventWriterConfig=EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999))
[grpc-default-executor-0] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 5 for endpoint 10.240.124.125. The current Channel is [id: 0x8d4b6888, L:/10.31.14.27:46428 - R:10.240.124.125/10.240.124.125:12345].
[clientInternal-3] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/_RGtest1/0.#epoch.0, writerID: 75f8b71b-ac5d-45e9-a04c-26d4790a9988
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating reader: 0 under readerGroup: test1 with configuration: ReaderConfig(initialAllocationDelay=0)
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating reader: 0 under readerGroup: test1 with configuration: ReaderConfig(initialAllocationDelay=0)
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating state synchronizer with stream: _RGtest1 and configuration: SynchronizerConfig(eventWriterConfig=EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999))
[pool-1-thread-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Updating client with controllers: [[[/10.240.124.123:9090]/{}]]
[clientInternal-3] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=10.240.124.125, port=12345) for Scope/_RGtest1/0.#epoch.0, writerID: 75f8b71b-ac5d-45e9-a04c-26d4790a9988
[clientInternal-3] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 6 for endpoint 10.240.124.125. The current Channel is [id: 0x3cbc0ac9, L:/10.31.14.27:46430 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-5-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=25769803776, segment=Scope/_RGtest1/0.#epoch.0, writerId=75f8b71b-ac5d-45e9-a04c-26d4790a9988, lastEventNumber=-9223372036854775808)
[epollEventLoopGroup-5-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 75f8b71b-ac5d-45e9-a04c-26d4790a9988
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating revisioned stream client for stream: _RGtest1 with synchronizer configuration: SynchronizerConfig(eventWriterConfig=EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999))
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/_RGtest1/0.#epoch.0, writerID: 1061007e-903a-4f6f-9878-2d0ad6adda58
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x758ac940]
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 7 for endpoint 10.240.124.125. The current Channel is [id: 0x758ac940, L:/10.31.14.27:46438 - R:10.240.124.125/10.240.124.125:12345].
[clientInternal-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=10.240.124.125, port=12345) for Scope/_RGtest1/0.#epoch.0, writerID: 1061007e-903a-4f6f-9878-2d0ad6adda58
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x6a7984e1]
[epollEventLoopGroup-4-3] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x89a8bb9b]
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 8 for endpoint 10.240.124.125. The current Channel is [id: 0x6a7984e1, L:/10.31.14.27:46440 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-4-1] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-3] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 9 for endpoint 10.240.124.125. The current Channel is [id: 0x89a8bb9b, L:/10.31.14.27:46442 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-3] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=34359738368, segment=Scope/_RGtest1/0.#epoch.0, writerId=1061007e-903a-4f6f-9878-2d0ad6adda58, lastEventNumber=-9223372036854775808)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 1061007e-903a-4f6f-9878-2d0ad6adda58
[epollEventLoopGroup-4-4] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.125 on ChannelId [id: 0x849ecca3]
[epollEventLoopGroup-4-4] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 10 for endpoint 10.240.124.125. The current Channel is [id: 0x849ecca3, L:/10.31.14.27:46444 - R:10.240.124.125/10.240.124.125:12345].
[epollEventLoopGroup-4-4] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating writer for stream: test1 with configuration: EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, transactionTimeoutTime=29999)
[main] INFO io.pravega.client.stream.impl.SegmentSelector - Refreshing segments for stream StreamImpl(scope=Scope, streamName=test1)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test1/0.#epoch.0, writerID: a73a921b-60f3-476e-a638-180567389e96
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=10.240.124.124, port=12345) for Scope/test1/0.#epoch.0, writerID: a73a921b-60f3-476e-a638-180567389e96
[epollEventLoopGroup-4-5] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.124 on ChannelId [id: 0xb338db38]
[epollEventLoopGroup-4-5] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 11 for endpoint 10.240.124.124. The current Channel is [id: 0xb338db38, L:/10.31.14.27:45872 - R:10.240.124.124/10.240.124.124:12345].
[epollEventLoopGroup-4-5] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[ForkJoinPool-1-worker-1] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint b5545e63-ad99-460b-99cc-9bc4cbce1634
[epollEventLoopGroup-4-5] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=47244640256, segment=Scope/test1/0.#epoch.0, writerId=a73a921b-60f3-476e-a638-180567389e96, lastEventNumber=-9223372036854775808)
[epollEventLoopGroup-4-5] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer a73a921b-60f3-476e-a638-180567389e96
[ForkJoinPool-1-worker-1] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) acquiring segments {Scope/test1/0.#epoch.0=0}
       0 records Reading,       0.0 records/sec,   0.00 MB/sec,     NaN ms avg latency,     0.0 ms max latency
[epollEventLoopGroup-4-6] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 10.240.124.124 on ChannelId [id: 0x6bcf42d1]
[epollEventLoopGroup-4-6] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 12 for endpoint 10.240.124.124. The current Channel is [id: 0x6bcf42d1, L:/10.31.14.27:45874 - R:10.240.124.124/10.240.124.124:12345].
[epollEventLoopGroup-4-6] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
    1472 records Writing,     293.9 records/sec,   0.28 MB/sec,   484.5 ms avg latency,  1041.0 ms max latency
    1632 records Reading,     325.9 records/sec,   0.31 MB/sec,     0.6 ms avg latency,   410.0 ms max latency
     480 records Writing,      95.8 records/sec,   0.09 MB/sec,   259.7 ms avg latency,   316.0 ms max latency
     480 records Reading,      96.0 records/sec,   0.09 MB/sec,     2.1 ms avg latency,   416.0 ms max latency
     480 records Writing,      95.9 records/sec,   0.09 MB/sec,   261.1 ms avg latency,   348.0 ms max latency
     441 records Reading,      87.4 records/sec,   0.08 MB/sec,     2.2 ms avg latency,   409.0 ms max latency
     470 records Writing,      93.9 records/sec,   0.09 MB/sec,   259.9 ms avg latency,   316.0 ms max latency
     509 records Reading,     101.6 records/sec,   0.10 MB/sec,     1.2 ms avg latency,   411.0 ms max latency
     488 records Writing,      97.4 records/sec,   0.09 MB/sec,   259.5 ms avg latency,   316.0 ms max latency
     478 records Reading,      95.5 records/sec,   0.09 MB/sec,     2.0 ms avg latency,   409.0 ms max latency
     480 records Writing,      95.8 records/sec,   0.09 MB/sec,   266.5 ms avg latency,   397.0 ms max latency
     490 records Reading,      98.0 records/sec,   0.09 MB/sec,     1.1 ms avg latency,   409.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   260.1 ms avg latency,   315.0 ms max latency
     480 records Reading,      96.0 records/sec,   0.09 MB/sec,     2.0 ms avg latency,   408.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   259.6 ms avg latency,   310.0 ms max latency
     471 records Reading,      94.2 records/sec,   0.09 MB/sec,     1.1 ms avg latency,   409.0 ms max latency
     480 records Writing,      95.9 records/sec,   0.09 MB/sec,   259.3 ms avg latency,   311.0 ms max latency
     499 records Reading,      99.6 records/sec,   0.10 MB/sec,     1.9 ms avg latency,   408.0 ms max latency
     490 records Writing,      98.0 records/sec,   0.09 MB/sec,   259.3 ms avg latency,   310.0 ms max latency
     481 records Reading,      91.3 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   409.0 ms max latency
     480 records Writing,      95.9 records/sec,   0.09 MB/sec,   259.4 ms avg latency,   313.0 ms max latency
     509 records Reading,     101.8 records/sec,   0.10 MB/sec,     1.1 ms avg latency,   407.0 ms max latency
     490 records Writing,      98.0 records/sec,   0.09 MB/sec,   259.4 ms avg latency,   316.0 ms max latency
     490 records Reading,      97.8 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   408.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   259.4 ms avg latency,   321.0 ms max latency
     500 records Reading,     100.0 records/sec,   0.10 MB/sec,     1.1 ms avg latency,   408.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   259.6 ms avg latency,   316.0 ms max latency
     480 records Reading,      96.0 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   407.0 ms max latency
     490 records Writing,      98.0 records/sec,   0.09 MB/sec,   259.0 ms avg latency,   307.0 ms max latency
     500 records Reading,      99.8 records/sec,   0.10 MB/sec,     1.0 ms avg latency,   407.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   259.4 ms avg latency,   309.0 ms max latency
     470 records Reading,      93.9 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   407.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   265.1 ms avg latency,   360.0 ms max latency
     481 records Reading,      91.5 records/sec,   0.09 MB/sec,     2.0 ms avg latency,   407.0 ms max latency
     490 records Writing,      98.0 records/sec,   0.09 MB/sec,   259.2 ms avg latency,   310.0 ms max latency
     519 records Reading,     103.8 records/sec,   0.10 MB/sec,     1.0 ms avg latency,   407.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   259.0 ms avg latency,   309.0 ms max latency
     480 records Reading,      95.9 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   407.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   259.3 ms avg latency,   315.0 ms max latency
     500 records Reading,     100.0 records/sec,   0.10 MB/sec,     1.1 ms avg latency,   407.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   265.9 ms avg latency,   374.0 ms max latency
     479 records Reading,      95.7 records/sec,   0.09 MB/sec,     2.0 ms avg latency,   407.0 ms max latency
     489 records Writing,      97.7 records/sec,   0.09 MB/sec,   263.3 ms avg latency,   349.0 ms max latency
[ForkJoinPool-1-worker-1] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - Closing reader EventStreamReaderImpl( id=0)
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/test1/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/test1/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 12 for endpoint 10.240.124.124
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
[ForkJoinPool-1-worker-1] INFO io.pravega.client.state.impl.StateSynchronizerImpl - Closing stateSynchronizer
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 8 for endpoint 10.240.124.125
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.ConditionalOutputStreamImpl - Closing segment metadata connection for Scope/_RGtest1/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 10 for endpoint 10.240.124.125
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.SegmentMetadataClientImpl - Closing segment metadata connection for Scope/_RGtest1/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 9 for endpoint 10.240.124.125
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/_RGtest1/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/_RGtest1/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 7 for endpoint 10.240.124.125
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
11766 records Writing, 105.661 records/sec, 1000 bytes record size, 0.10 MB/sec, 288.6 ms avg latency, 1041.0 ms max latency, 265 ms 50th, 545 ms 95th, 670 ms 99th, 705 ms 99.9th.
11719 records Reading, 101.916 records/sec, 1000 bytes record size, 0.10 MB/sec, 1.5 ms avg latency, 416.0 ms max latency, 0 ms 50th, 1 ms 95th, 9 ms 99th, 408 ms 99.9th.
Richa-Srivastava commented 5 years ago

Experiencing high Read(1465.0000 ms max latency)/Write(618.5000 ms max latency) latency issue even without external connectivity: Benchmark logs:

[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException for connection io.pravega.client.netty.impl.ClientConnectionImpl@67ff36ec on writer 81c02a67-1cf2-4020-bd41-a4b92c977a8f. SetupCompleted: false, Closed: false
[epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/1.#epoch.0 on writer 81c02a67-1cf2-4020-bd41-a4b92c977a8f failed due to: class io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - 81c02a67-1cf2-4020-bd41-a4b92c977a8f Failed to connect: 
java.util.concurrent.CompletionException: io.pravega.shared.protocol.netty.ConnectionFailedException
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
        at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:874)
        at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:852)
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.failConnection(SegmentOutputStreamImpl.java:202)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.access$700(SegmentOutputStreamImpl.java:94)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.failConnection(SegmentOutputStreamImpl.java:516)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.access$500(SegmentOutputStreamImpl.java:68)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$ResponseProcessor.connectionDropped(SegmentOutputStreamImpl.java:286)
        at io.pravega.client.netty.impl.FlowHandler.lambda$channelUnregistered$0(FlowHandler.java:174)
        at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1597)
        at io.pravega.client.netty.impl.FlowHandler.channelUnregistered(FlowHandler.java:173)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1412)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
Caused by: io.pravega.shared.protocol.netty.ConnectionFailedException
        ... 30 more
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 99 for endpoint 172.24.80.30
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer 2c9ee744-6f79-45d8-aab3-1ba28f3fd775 with exception io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException for connection io.pravega.client.netty.impl.ClientConnectionImpl@5709ddb3 on writer 2c9ee744-6f79-45d8-aab3-1ba28f3fd775. SetupCompleted: false, Closed: false
[epollEventLoopGroup-4-2] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/2.#epoch.0 on writer 2c9ee744-6f79-45d8-aab3-1ba28f3fd775 failed due to: class io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-2] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - 2c9ee744-6f79-45d8-aab3-1ba28f3fd775 Failed to connect: 
java.util.concurrent.CompletionException: io.pravega.shared.protocol.netty.ConnectionFailedException
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
        at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:874)
        at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:852)
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.failConnection(SegmentOutputStreamImpl.java:202)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.access$700(SegmentOutputStreamImpl.java:94)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.failConnection(SegmentOutputStreamImpl.java:516)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.access$500(SegmentOutputStreamImpl.java:68)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$ResponseProcessor.connectionDropped(SegmentOutputStreamImpl.java:286)
        at io.pravega.client.netty.impl.FlowHandler.lambda$channelUnregistered$0(FlowHandler.java:174)
        at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1597)
        at io.pravega.client.netty.impl.FlowHandler.channelUnregistered(FlowHandler.java:173)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1412)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
Caused by: io.pravega.shared.protocol.netty.ConnectionFailedException
        ... 30 more
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 70 for endpoint 172.24.80.30
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: 81c02a67-1cf2-4020-bd41-a4b92c977a8f
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: 81c02a67-1cf2-4020-bd41-a4b92c977a8f
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 99 for endpoint 172.24.80.30. The current Channel is null.
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0x80cc69e6]
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer 81c02a67-1cf2-4020-bd41-a4b92c977a8f with exception io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException for connection io.pravega.client.netty.impl.ClientConnectionImpl@22739aa6 on writer 81c02a67-1cf2-4020-bd41-a4b92c977a8f. SetupCompleted: false, Closed: false
[epollEventLoopGroup-4-2] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/1.#epoch.0 on writer 81c02a67-1cf2-4020-bd41-a4b92c977a8f failed due to: class io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-2] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - 81c02a67-1cf2-4020-bd41-a4b92c977a8f Failed to connect: 
java.util.concurrent.CompletionException: io.pravega.shared.protocol.netty.ConnectionFailedException
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
        at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:874)
        at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:852)
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.failConnection(SegmentOutputStreamImpl.java:202)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.access$700(SegmentOutputStreamImpl.java:94)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.failConnection(SegmentOutputStreamImpl.java:516)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.access$500(SegmentOutputStreamImpl.java:68)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$ResponseProcessor.connectionDropped(SegmentOutputStreamImpl.java:286)
        at io.pravega.client.netty.impl.FlowHandler.lambda$channelUnregistered$0(FlowHandler.java:174)
        at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1597)
        at io.pravega.client.netty.impl.FlowHandler.channelUnregistered(FlowHandler.java:173)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1412)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
Caused by: io.pravega.shared.protocol.netty.ConnectionFailedException
        ... 30 more
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 99 for endpoint 172.24.80.30
     179 records Writing,     168.4 records/sec,     0.016 MB/sec,  5.9385 ms avg latency.
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 2c9ee744-6f79-45d8-aab3-1ba28f3fd775
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 2c9ee744-6f79-45d8-aab3-1ba28f3fd775
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 70 for endpoint 172.24.80.30. The current Channel is null.
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0xe4d95adf]
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer 2c9ee744-6f79-45d8-aab3-1ba28f3fd775 with exception io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException for connection io.pravega.client.netty.impl.ClientConnectionImpl@142ac5e on writer 2c9ee744-6f79-45d8-aab3-1ba28f3fd775. SetupCompleted: false, Closed: false
[epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/2.#epoch.0 on writer 2c9ee744-6f79-45d8-aab3-1ba28f3fd775 failed due to: class io.pravega.shared.protocol.netty.ConnectionFailedException
[epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - 2c9ee744-6f79-45d8-aab3-1ba28f3fd775 Failed to connect: 
java.util.concurrent.CompletionException: io.pravega.shared.protocol.netty.ConnectionFailedException
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
        at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:874)
        at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:852)
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.failConnection(SegmentOutputStreamImpl.java:202)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.access$700(SegmentOutputStreamImpl.java:94)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.failConnection(SegmentOutputStreamImpl.java:516)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl.access$500(SegmentOutputStreamImpl.java:68)
        at io.pravega.client.segment.impl.SegmentOutputStreamImpl$ResponseProcessor.connectionDropped(SegmentOutputStreamImpl.java:286)
        at io.pravega.client.netty.impl.FlowHandler.lambda$channelUnregistered$0(FlowHandler.java:174)
        at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1597)
        at io.pravega.client.netty.impl.FlowHandler.channelUnregistered(FlowHandler.java:173)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1412)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167)
        at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
Caused by: io.pravega.shared.protocol.netty.ConnectionFailedException
        ... 30 more
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 70 for endpoint 172.24.80.30
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: 81c02a67-1cf2-4020-bd41-a4b92c977a8f
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: 81c02a67-1cf2-4020-bd41-a4b92c977a8f
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 99 for endpoint 172.24.80.30. The current Channel is null.
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0xb68771e4]
[epollEventLoopGroup-4-2] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=425201762304, segment=Scope/test2Day/1.#epoch.0, writerId=81c02a67-1cf2-4020-bd41-a4b92c977a8f, lastEventNumber=17721)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: ef8eb0bb-653b-46bb-8e05-c9d4a4cc4872
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: f74eab0f-c3d2-4947-b7de-3c55b4d08de6
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: ef8eb0bb-653b-46bb-8e05-c9d4a4cc4872
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 60 for endpoint 172.24.80.30. The current Channel is null.
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0xd2044c85]
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: c7197be2-7b07-4dad-b1bb-4619fa5aba39
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: f74eab0f-c3d2-4947-b7de-3c55b4d08de6
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 80 for endpoint 172.24.80.30. The current Channel is null.
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0x39757ac9]
[epollEventLoopGroup-4-2] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: bff2960b-a2f0-41cc-b2b1-cd55d60c1ee7
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: c7197be2-7b07-4dad-b1bb-4619fa5aba39
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 50 for endpoint 172.24.80.30. The current Channel is null.
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: 15c4e2cc-e539-4d0b-aee4-ae42f16b611c
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: e6699bab-e9d6-4aff-8e94-f3c94cc2df33
[epollEventLoopGroup-4-1] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=257698037760, segment=Scope/test2Day/2.#epoch.0, writerId=ef8eb0bb-653b-46bb-8e05-c9d4a4cc4872, lastEventNumber=18087)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: 15c4e2cc-e539-4d0b-aee4-ae42f16b611c
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=343597383680, segment=Scope/test2Day/2.#epoch.0, writerId=f74eab0f-c3d2-4947-b7de-3c55b4d08de6, lastEventNumber=18155)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer f74eab0f-c3d2-4947-b7de-3c55b4d08de6
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345)
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 69 for endpoint 172.24.80.30. The current Channel is null.
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: e6699bab-e9d6-4aff-8e94-f3c94cc2df33
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@694e815a, connected=java.util.concurrent.CompletableFuture@6b9672b6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 103 for endpoint 172.24.80.30. The current Channel is [id: 0xb68771e4, L:/172.24.80.18:36866 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0x15807b39]
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint 172.24.80.30 on ChannelId [id: 0xa39172f8]
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=442381631488, segment=Scope/test2Day/5.#epoch.0, writerId=e6699bab-e9d6-4aff-8e94-f3c94cc2df33, lastEventNumber=18255)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: bff2960b-a2f0-41cc-b2b1-cd55d60c1ee7
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@6c11f669, connected=java.util.concurrent.CompletableFuture@20d505b3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 109 for endpoint 172.24.80.30. The current Channel is [id: 0xd2044c85, L:/172.24.80.18:36870 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=296352743424, segment=Scope/test2Day/1.#epoch.0, writerId=15c4e2cc-e539-4d0b-aee4-ae42f16b611c, lastEventNumber=18147)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 15c4e2cc-e539-4d0b-aee4-ae42f16b611c
[epollEventLoopGroup-4-1] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=214748364800, segment=Scope/test2Day/2.#epoch.0, writerId=c7197be2-7b07-4dad-b1bb-4619fa5aba39, lastEventNumber=119151)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer c7197be2-7b07-4dad-b1bb-4619fa5aba39
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=468151435264, segment=Scope/test2Day/1.#epoch.0, writerId=bff2960b-a2f0-41cc-b2b1-cd55d60c1ee7, lastEventNumber=17753)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: 2424698f-1b55-4c59-a762-08488d461b43
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: 2424698f-1b55-4c59-a762-08488d461b43
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@3d0c14a2, connected=java.util.concurrent.CompletableFuture@6557c277[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 113 for endpoint 172.24.80.30. The current Channel is [id: 0x39757ac9, L:/172.24.80.18:36872 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=485331304448, segment=Scope/test2Day/5.#epoch.0, writerId=2424698f-1b55-4c59-a762-08488d461b43, lastEventNumber=17908)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer 8d7b84d5-c254-4179-9809-88df2b99de96 with exception io.pravega.shared.protocol.netty.ConnectionFailedException: WireCommands.WrongHost(type=WRONG_HOST, requestId=472446402560, segment=Scope/test2Day/2.#epoch.0, correctHost=, serverStackTrace=)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException: WireCommands.WrongHost(type=WRONG_HOST, requestId=472446402560, segment=Scope/test2Day/2.#epoch.0, correctHost=, serverStackTrace=) for connection io.pravega.client.netty.impl.ClientConnectionImpl@9185cb9 on writer 8d7b84d5-c254-4179-9809-88df2b99de96. SetupCompleted: true, Closed: false
[epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/2.#epoch.0 on writer 8d7b84d5-c254-4179-9809-88df2b99de96 failed due to: WireCommands.WrongHost(type=WRONG_HOST, requestId=472446402560, segment=Scope/test2Day/2.#epoch.0, correctHost=, serverStackTrace=)
[epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 110 for endpoint 172.24.80.19
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 8d7b84d5-c254-4179-9809-88df2b99de96
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 8d7b84d5-c254-4179-9809-88df2b99de96
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@616c20a, connected=java.util.concurrent.CompletableFuture@e66a7e6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 110 for endpoint 172.24.80.30. The current Channel is [id: 0x15807b39, L:/172.24.80.18:36874 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=472446402560, segment=Scope/test2Day/2.#epoch.0, writerId=8d7b84d5-c254-4179-9809-88df2b99de96, lastEventNumber=17738)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 1534c66c-c3c9-4cf1-bfec-051d0bed758f
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 024d7148-1e70-4f1f-a757-53a5997c0fae
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 1534c66c-c3c9-4cf1-bfec-051d0bed758f
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@53121b8c, connected=java.util.concurrent.CompletableFuture@80d2fe3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 100 for endpoint 172.24.80.30. The current Channel is [id: 0xa39172f8, L:/172.24.80.18:36876 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 024d7148-1e70-4f1f-a757-53a5997c0fae
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@694e815a, connected=java.util.concurrent.CompletableFuture@6b9672b6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 90 for endpoint 172.24.80.30. The current Channel is [id: 0xb68771e4, L:/172.24.80.18:36866 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=429496729600, segment=Scope/test2Day/2.#epoch.0, writerId=1534c66c-c3c9-4cf1-bfec-051d0bed758f, lastEventNumber=17670)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=386547056640, segment=Scope/test2Day/2.#epoch.0, writerId=024d7148-1e70-4f1f-a757-53a5997c0fae, lastEventNumber=18087)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 024d7148-1e70-4f1f-a757-53a5997c0fae
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: d7ab1951-0de5-4b2c-93ca-0cd36bc99e29
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: d7ab1951-0de5-4b2c-93ca-0cd36bc99e29
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@6c11f669, connected=java.util.concurrent.CompletableFuture@20d505b3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 49 for endpoint 172.24.80.30. The current Channel is [id: 0xd2044c85, L:/172.24.80.18:36870 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: 105cce0f-3c86-4880-a60b-3377ddfda363
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 28beccb2-b9b6-442e-9825-330ccc1dbfef
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: 38fd4824-e389-4626-afb3-4d60796b0e5b
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: e4329ab1-ca57-4ed5-b569-dbd621266780
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=210453397504, segment=Scope/test2Day/1.#epoch.0, writerId=d7ab1951-0de5-4b2c-93ca-0cd36bc99e29, lastEventNumber=119485)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: 105cce0f-3c86-4880-a60b-3377ddfda363
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@3d0c14a2, connected=java.util.concurrent.CompletableFuture@6557c277[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 129 for endpoint 172.24.80.30. The current Channel is [id: 0x39757ac9, L:/172.24.80.18:36872 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: 38fd4824-e389-4626-afb3-4d60796b0e5b
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@616c20a, connected=java.util.concurrent.CompletableFuture@e66a7e6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 79 for endpoint 172.24.80.30. The current Channel is [id: 0x15807b39, L:/172.24.80.18:36874 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: e4329ab1-ca57-4ed5-b569-dbd621266780
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@53121b8c, connected=java.util.concurrent.CompletableFuture@80d2fe3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 139 for endpoint 172.24.80.30. The current Channel is [id: 0xa39172f8, L:/172.24.80.18:36876 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 28beccb2-b9b6-442e-9825-330ccc1dbfef
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@694e815a, connected=java.util.concurrent.CompletableFuture@6b9672b6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 140 for endpoint 172.24.80.30. The current Channel is [id: 0xb68771e4, L:/172.24.80.18:36866 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=554050781184, segment=Scope/test2Day/1.#epoch.0, writerId=105cce0f-3c86-4880-a60b-3377ddfda363, lastEventNumber=18110)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 105cce0f-3c86-4880-a60b-3377ddfda363
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=339302416384, segment=Scope/test2Day/1.#epoch.0, writerId=38fd4824-e389-4626-afb3-4d60796b0e5b, lastEventNumber=17957)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 38fd4824-e389-4626-afb3-4d60796b0e5b
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 3ec60382-2079-446c-bfa1-21fb046952a8
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: eaa964d7-2b76-4a49-8fd4-ecd21dc818e3
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: b36a8c5e-ba54-4a7b-a9f0-d884fca8a041
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: eaa964d7-2b76-4a49-8fd4-ecd21dc818e3
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@6c11f669, connected=java.util.concurrent.CompletableFuture@20d505b3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 119 for endpoint 172.24.80.30. The current Channel is [id: 0xd2044c85, L:/172.24.80.18:36870 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: b36a8c5e-ba54-4a7b-a9f0-d884fca8a041
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@3d0c14a2, connected=java.util.concurrent.CompletableFuture@6557c277[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 59 for endpoint 172.24.80.30. The current Channel is [id: 0x39757ac9, L:/172.24.80.18:36872 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 3ec60382-2079-446c-bfa1-21fb046952a8
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@616c20a, connected=java.util.concurrent.CompletableFuture@e66a7e6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 130 for endpoint 172.24.80.30. The current Channel is [id: 0x15807b39, L:/172.24.80.18:36874 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=511101108224, segment=Scope/test2Day/1.#epoch.0, writerId=eaa964d7-2b76-4a49-8fd4-ecd21dc818e3, lastEventNumber=18165)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=597000454144, segment=Scope/test2Day/1.#epoch.0, writerId=e4329ab1-ca57-4ed5-b569-dbd621266780, lastEventNumber=18078)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer e4329ab1-ca57-4ed5-b569-dbd621266780
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=601295421440, segment=Scope/test2Day/2.#epoch.0, writerId=28beccb2-b9b6-442e-9825-330ccc1dbfef, lastEventNumber=17976)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=253403070464, segment=Scope/test2Day/1.#epoch.0, writerId=b36a8c5e-ba54-4a7b-a9f0-d884fca8a041, lastEventNumber=18013)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer b36a8c5e-ba54-4a7b-a9f0-d884fca8a041
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer cfd04b8d-81c9-482a-b7b8-065cdba83665 with exception io.pravega.shared.protocol.netty.ConnectionFailedException: WireCommands.WrongHost(type=WRONG_HOST, requestId=614180323328, segment=Scope/test2Day/5.#epoch.0, correctHost=, serverStackTrace=)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException: WireCommands.WrongHost(type=WRONG_HOST, requestId=614180323328, segment=Scope/test2Day/5.#epoch.0, correctHost=, serverStackTrace=) for connection io.pravega.client.netty.impl.ClientConnectionImpl@24a15cd6 on writer cfd04b8d-81c9-482a-b7b8-065cdba83665. SetupCompleted: true, Closed: false
[epollEventLoopGroup-4-2] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/5.#epoch.0 on writer cfd04b8d-81c9-482a-b7b8-065cdba83665 failed due to: WireCommands.WrongHost(type=WRONG_HOST, requestId=614180323328, segment=Scope/test2Day/5.#epoch.0, correctHost=, serverStackTrace=)
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 143 for endpoint 172.24.80.16
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer f9f0de4e-2131-44e9-803e-bb089a5a85e2 with exception io.pravega.shared.protocol.netty.ConnectionFailedException: WireCommands.WrongHost(type=WRONG_HOST, requestId=356482285568, segment=Scope/test2Day/5.#epoch.0, correctHost=, serverStackTrace=)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException: WireCommands.WrongHost(type=WRONG_HOST, requestId=356482285568, segment=Scope/test2Day/5.#epoch.0, correctHost=, serverStackTrace=) for connection io.pravega.client.netty.impl.ClientConnectionImpl@2b1fec1a on writer f9f0de4e-2131-44e9-803e-bb089a5a85e2. SetupCompleted: true, Closed: false
[epollEventLoopGroup-4-2] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment Scope/test2Day/5.#epoch.0 on writer f9f0de4e-2131-44e9-803e-bb089a5a85e2 failed due to: WireCommands.WrongHost(type=WRONG_HOST, requestId=356482285568, segment=Scope/test2Day/5.#epoch.0, correctHost=, serverStackTrace=)
[epollEventLoopGroup-4-2] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 83 for endpoint 172.24.80.16
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=558345748480, segment=Scope/test2Day/2.#epoch.0, writerId=3ec60382-2079-446c-bfa1-21fb046952a8, lastEventNumber=18186)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 3ec60382-2079-446c-bfa1-21fb046952a8
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: cfd04b8d-81c9-482a-b7b8-065cdba83665
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: f9f0de4e-2131-44e9-803e-bb089a5a85e2
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: cfd04b8d-81c9-482a-b7b8-065cdba83665
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@53121b8c, connected=java.util.concurrent.CompletableFuture@80d2fe3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 143 for endpoint 172.24.80.30. The current Channel is [id: 0xa39172f8, L:/172.24.80.18:36876 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: f9f0de4e-2131-44e9-803e-bb089a5a85e2
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@694e815a, connected=java.util.concurrent.CompletableFuture@6b9672b6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 83 for endpoint 172.24.80.30. The current Channel is [id: 0xb68771e4, L:/172.24.80.18:36866 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=356482285568, segment=Scope/test2Day/5.#epoch.0, writerId=f9f0de4e-2131-44e9-803e-bb089a5a85e2, lastEventNumber=18061)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=614180323328, segment=Scope/test2Day/5.#epoch.0, writerId=cfd04b8d-81c9-482a-b7b8-065cdba83665, lastEventNumber=18111)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: c3a6553c-7e6c-4410-ad4e-68bb287c65bb
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/1.#epoch.0, writerID: b16689cd-ebd9-4366-94c8-d9c00effae0b
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: 74c266d1-0ead-42db-923f-b2f62a708f56
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: c55476da-68c2-424e-8092-68840bae348e
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: cac5bbb7-3a26-484f-8013-a8b18fe099da
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: 77d2c928-17f4-4590-ab65-9ae45f9b5f68
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: c3a6553c-7e6c-4410-ad4e-68bb287c65bb
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@6c11f669, connected=java.util.concurrent.CompletableFuture@20d505b3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 63 for endpoint 172.24.80.30. The current Channel is [id: 0xd2044c85, L:/172.24.80.18:36870 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/1.#epoch.0, writerID: b16689cd-ebd9-4366-94c8-d9c00effae0b
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@3d0c14a2, connected=java.util.concurrent.CompletableFuture@6557c277[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 89 for endpoint 172.24.80.30. The current Channel is [id: 0x39757ac9, L:/172.24.80.18:36872 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=270582939648, segment=Scope/test2Day/5.#epoch.0, writerId=c3a6553c-7e6c-4410-ad4e-68bb287c65bb, lastEventNumber=17846)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer c3a6553c-7e6c-4410-ad4e-68bb287c65bb
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=382252089344, segment=Scope/test2Day/1.#epoch.0, writerId=b16689cd-ebd9-4366-94c8-d9c00effae0b, lastEventNumber=18053)
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: b08dc312-f482-4331-a57d-a38534e2c022
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: 74c266d1-0ead-42db-923f-b2f62a708f56
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@616c20a, connected=java.util.concurrent.CompletableFuture@e66a7e6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 123 for endpoint 172.24.80.30. The current Channel is [id: 0x15807b39, L:/172.24.80.18:36874 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: cac5bbb7-3a26-484f-8013-a8b18fe099da
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@53121b8c, connected=java.util.concurrent.CompletableFuture@80d2fe3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 120 for endpoint 172.24.80.30. The current Channel is [id: 0xa39172f8, L:/172.24.80.18:36876 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: c55476da-68c2-424e-8092-68840bae348e
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@694e815a, connected=java.util.concurrent.CompletableFuture@6b9672b6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 53 for endpoint 172.24.80.30. The current Channel is [id: 0xb68771e4, L:/172.24.80.18:36866 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=528280977408, segment=Scope/test2Day/5.#epoch.0, writerId=74c266d1-0ead-42db-923f-b2f62a708f56, lastEventNumber=18103)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 74c266d1-0ead-42db-923f-b2f62a708f56
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: 77d2c928-17f4-4590-ab65-9ae45f9b5f68
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@6c11f669, connected=java.util.concurrent.CompletableFuture@20d505b3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 73 for endpoint 172.24.80.30. The current Channel is [id: 0xd2044c85, L:/172.24.80.18:36870 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=227633266688, segment=Scope/test2Day/5.#epoch.0, writerId=c55476da-68c2-424e-8092-68840bae348e, lastEventNumber=118889)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer c55476da-68c2-424e-8092-68840bae348e
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/5.#epoch.0, writerID: a89c1ccc-c910-4ca7-ba21-1a3288f5ac65
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=313532612608, segment=Scope/test2Day/5.#epoch.0, writerId=77d2c928-17f4-4590-ab65-9ae45f9b5f68, lastEventNumber=17962)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer 77d2c928-17f4-4590-ab65-9ae45f9b5f68
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=515396075520, segment=Scope/test2Day/2.#epoch.0, writerId=cac5bbb7-3a26-484f-8013-a8b18fe099da, lastEventNumber=17991)
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer cac5bbb7-3a26-484f-8013-a8b18fe099da
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: b08dc312-f482-4331-a57d-a38534e2c022
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@3d0c14a2, connected=java.util.concurrent.CompletableFuture@6557c277[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 93 for endpoint 172.24.80.30. The current Channel is [id: 0x39757ac9, L:/172.24.80.18:36872 - R:172.24.80.30/172.24.80.30:12345].
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/5.#epoch.0, writerID: a89c1ccc-c910-4ca7-ba21-1a3288f5ac65
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@616c20a, connected=java.util.concurrent.CompletableFuture@e66a7e6[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 133 for endpoint 172.24.80.30. The current Channel is [id: 0x15807b39, L:/172.24.80.18:36874 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=399431958528, segment=Scope/test2Day/5.#epoch.0, writerId=b08dc312-f482-4331-a57d-a38534e2c022, lastEventNumber=18144)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=571230650368, segment=Scope/test2Day/5.#epoch.0, writerId=a89c1ccc-c910-4ca7-ba21-1a3288f5ac65, lastEventNumber=18034)
[epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection setup complete for writer a89c1ccc-c910-4ca7-ba21-1a3288f5ac65
    1166 records Writing,    1166.0 records/sec,     0.111 MB/sec,  0.8576 ms avg latency.
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment Scope/test2Day/2.#epoch.0, writerID: 2c9ee744-6f79-45d8-aab3-1ba28f3fd775
[clientInternal-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=172.24.80.30, port=12345) for Scope/test2Day/2.#epoch.0, writerID: 2c9ee744-6f79-45d8-aab3-1ba28f3fd775
[clientInternal-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Reusing connection: Connection(uri=PravegaNodeUri(endpoint=172.24.80.30, port=12345), flowHandler=io.pravega.client.netty.impl.FlowHandler@53121b8c, connected=java.util.concurrent.CompletableFuture@80d2fe3[Completed normally])
[clientInternal-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 70 for endpoint 172.24.80.30. The current Channel is [id: 0xa39172f8, L:/172.24.80.18:36876 - R:172.24.80.30/172.24.80.30:12345].
[epollEventLoopGroup-4-2] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Received AppendSetup WireCommands.AppendSetup(type=APPEND_SETUP, requestId=300647710720, segment=Scope/test2Day/2.#epoch.0, writerId=2c9ee744-6f79-45d8-aab3-1ba28f3fd775, lastEventNumber=17708)
    1091 records Writing,    1081.3 records/sec,     0.103 MB/sec,  0.9248 ms avg latency.
    1129 records Writing,    1129.0 records/sec,     0.108 MB/sec,  0.8857 ms avg latency.
     835 records Writing,     830.0 records/sec,     0.079 MB/sec,  1.2048 ms avg latency.
     932 records Writing,     927.4 records/sec,     0.088 MB/sec,  1.0783 ms avg latency.
    1060 records Writing,    1048.5 records/sec,     0.100 MB/sec,  0.9538 ms avg latency.
    1154 records Writing,    1150.5 records/sec,     0.110 MB/sec,  0.8692 ms avg latency.
    1040 records Writing,    1033.8 records/sec,     0.099 MB/sec,  0.9673 ms avg latency.
     853 records Writing,     850.4 records/sec,     0.081 MB/sec,  1.1758 ms avg latency.
    1114 records Writing,    1105.2 records/sec,     0.105 MB/sec,  0.9048 ms avg latency.
    1034 records Writing,     610.8 records/sec,     0.058 MB/sec,  1.6373 ms avg latency.
    1000 records Writing,     997.0 records/sec,     0.095 MB/sec,  1.0030 ms avg latency.
    1001 records Writing,     994.0 records/sec,     0.095 MB/sec,  1.0060 ms avg latency.
    1002 records Writing,     999.0 records/sec,     0.095 MB/sec,  1.0010 ms avg latency.
    1004 records Writing,    1003.0 records/sec,     0.096 MB/sec,  0.9970 ms avg latency.
     997 records Writing,     994.0 records/sec,     0.095 MB/sec,  1.0060 ms avg latency.
     998 records Writing,     998.0 records/sec,     0.095 MB/sec,  1.0020 ms avg latency.
    1006 records Writing,    1002.0 records/sec,     0.096 MB/sec,  0.9980 ms avg latency.
     998 records Writing,     998.0 records/sec,     0.095 MB/sec,  1.0020 ms avg latency.
     994 records Writing,     993.0 records/sec,     0.095 MB/sec,  1.0070 ms avg latency.
    1008 records Writing,    1008.0 records/sec,     0.096 MB/sec,  0.9921 ms avg latency.
    1011 records Writing,    1008.0 records/sec,     0.096 MB/sec,  0.9921 ms avg latency.
    1007 records Writing,    1004.0 records/sec,     0.096 MB/sec,  0.9960 ms avg latency.
     975 records Writing,     973.1 records/sec,     0.093 MB/sec,  1.0277 ms avg latency.
    1014 records Writing,    1013.0 records/sec,     0.097 MB/sec,  0.9872 ms avg latency.
     992 records Writing,     990.0 records/sec,     0.094 MB/sec,  1.0101 ms avg latency.
    1020 records Writing,    1011.9 records/sec,     0.097 MB/sec,  0.9882 ms avg latency.
     991 records Writing,     991.0 records/sec,     0.095 MB/sec,  1.0091 ms avg latency.
    1024 records Writing,    1023.0 records/sec,     0.098 MB/sec,  0.9775 ms avg latency.
     982 records Writing,     981.0 records/sec,     0.094 MB/sec,  1.0193 ms avg latency.
     991 records Writing,     982.2 records/sec,     0.094 MB/sec,  1.0182 ms avg latency.
    1026 records Writing,    1026.0 records/sec,     0.098 MB/sec,  0.9747 ms avg latency.
     999 records Writing,     999.0 records/sec,     0.095 MB/sec,  1.0010 ms avg latency.
     969 records Writing,     969.0 records/sec,     0.092 MB/sec,  1.0320 ms avg latency.
    1077 records Writing,    1069.5 records/sec,     0.102 MB/sec,  0.9350 ms avg latency.
     942 records Writing,     941.1 records/sec,     0.090 MB/sec,  1.0626 ms avg latency.
     993 records Writing,     989.0 records/sec,     0.094 MB/sec,  1.0111 ms avg latency.
    1017 records Writing,    1017.0 records/sec,     0.097 MB/sec,  0.9833 ms avg latency.
    1037 records Writing,    1037.0 records/sec,     0.099 MB/sec,  0.9643 ms avg latency.
2847629 records Writing, 237.360 records/sec, 100 bytes record size, 0.023 MB/sec, 9.2698 ms avg latency, 618.5000 ms max latency
1835137 records Reading, 152.952 records/sec, 100 bytes record size, 0.015 MB/sec, 10.1846 ms avg latency, 1465.0000 ms max latency
RaulGracia commented 5 years ago

I think that @deenav and @Richa-Srivastava are pointing to two separate aspects: 1) The problem that @deenav is showing is a consistent difference between read and write average latency. In this sense, have you verified that this is a problem only related to "external access" or you are seeing low latency in PKS internally as well (e.g., executing the benchmark from a pod inside the cluster)? In the former case, it may be a networking-related issue, whereas in the latter one it may be a performance problem of storage volumes that we are already investigating. 2) @Richa-Srivastava if you look at the logs that you have posted, you are not talking about the same issue (in fact, don't see the issue in your logs). If you realize, your readers and writers are consistently showing a similar performance throughout the experiment. The "max latency" in this case may be just one read/write operation that could be delayed by some reason, perhaps at the beginning of the experiment when the system is "cold", and it is not representative.

For you both @deenav and @Richa-Srivastava, please capture the percentiles for latency (the benchmark tools already provides them), as they are more descriptive and representative than the "average" (it can be highly biased by long tail latency distributions) or the "max" (may be a single, non-representative outlier value).

RaulGracia commented 5 years ago

FYI, I have executed 3 benchmarks to verify this issue (Pravega r0.5):

1) On a pod within the K8 cluster where Pravega is running:

root@benchmark-pod:/tmp/pravega-benchmark/build/distributions/pravega-benchmark# ./bin/pravega-benchmark -controller tcp://xxx:9090 -stream test2  -producers 1 -size 1000  -events 100 -time 120 -consumers 1
...
[ForkJoinPool-2-worker-0] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint 7cf4eeab-5eda-4f49-9645-90fd0276f5fc
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.4 ms avg latency,    21.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.2 ms avg latency,    22.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.1 ms avg latency,    13.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.2 ms avg latency,    16.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     4.2 ms avg latency,    16.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.3 ms avg latency,    16.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.3 ms avg latency,    16.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     4.1 ms avg latency,    15.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    12.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    12.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.1 ms avg latency,    30.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    13.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    12.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    15.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.1 ms avg latency,    16.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    15.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    18.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    15.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    13.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    12.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    11.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.2 ms avg latency,    16.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    13.0 ms max latency
...
11721 records Write/Reading, 100.002 records/sec, 1000 bytes record size, 0.10 MB/sec, 4.1 ms avg latency, 30.0 ms max latency, 4 ms 50th, 4 ms 75th, 6 ms 95th, 12 ms 99th, 15 ms 99.9th

2) On a pod of another K8 cluster in the same infrastructure:

root@benchmark-pod:/tmp/pravega-benchmark/build/distributions/pravega-benchmark# ./bin/pravega-benchmark -controller tcp://xxx:9090 -stream test3  -producers 1 -size 1000  -events 100 -time 120 -consumers 1
...
[ForkJoinPool-2-worker-0] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint 469354fc-b224-4041-8921-dc9cb686d638
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.3 ms avg latency,    26.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.1 ms avg latency,    39.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     3.8 ms avg latency,    15.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    18.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    13.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.1 ms avg latency,    15.0 ms max latency
[ForkJoinPool-2-worker-0] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint c3b5f123-f623-443f-9a91-f1e0c1bc5bc0
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.8 ms avg latency,    12.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    13.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     3.8 ms avg latency,    15.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    12.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     3.8 ms avg latency,     9.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     4.0 ms avg latency,    14.0 ms max latency
[ForkJoinPool-2-worker-0] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint c0abd20a-455e-4e35-841d-5243ade794e3
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    12.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    12.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.8 ms avg latency,    12.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    14.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    15.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    13.0 ms max latency
[ForkJoinPool-2-worker-0] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint ef507a69-9fd0-4aed-b64f-c3197c33ddbc
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    15.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    16.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,     3.8 ms avg latency,    11.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.9 ms avg latency,    11.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,     3.8 ms avg latency,    15.0 ms max latency
...
11771 records Write/Reading, 99.992 records/sec, 1000 bytes record size, 0.10 MB/sec, 3.9 ms avg latency, 39.0 ms max latency, 4 ms 50th, 4 ms 75th, 5 ms 95th, 8 ms 99th, 13 ms 99.9th

3) Outside the the infrastructure where K8 clusters are running (i.e., from my laptop):

λ bash ./bin/pravega-benchmark -controller tcp://xxx:9090 -stream test4  -producers 1 -size 1000  -events 100 -time 120 -consumers 1
...
[grpc-default-executor-0] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 12 for endpoint 10.247.113.58. The current Channel is [id: 0xf7134b05, L:/10.41.53.249:65432 - R:/10.247.113.58:12345].
     445 records Write/Reading,      89.0 records/sec,   0.08 MB/sec,   582.7 ms avg latency,  1584.0 ms max latency
     480 records Write/Reading,      96.0 records/sec,   0.09 MB/sec,   556.2 ms avg latency,   867.0 ms max latency
     541 records Write/Reading,     108.2 records/sec,   0.10 MB/sec,   532.7 ms avg latency,   850.0 ms max latency
     505 records Write/Reading,     101.0 records/sec,   0.10 MB/sec,   356.1 ms avg latency,   660.0 ms max latency
     492 records Write/Reading,      98.4 records/sec,   0.09 MB/sec,   346.3 ms avg latency,   619.0 ms max latency
     485 records Write/Reading,      97.0 records/sec,   0.09 MB/sec,   523.2 ms avg latency,  1121.0 ms max latency
[ForkJoinPool-2-worker-2] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint 5dd68dbf-7d7f-4884-8608-6883960d80ff
     483 records Write/Reading,      96.6 records/sec,   0.09 MB/sec,   669.9 ms avg latency,   979.0 ms max latency
     522 records Write/Reading,     104.4 records/sec,   0.10 MB/sec,   559.7 ms avg latency,   920.0 ms max latency
     434 records Write/Reading,      86.8 records/sec,   0.08 MB/sec,   436.9 ms avg latency,  1025.0 ms max latency
     548 records Write/Reading,     109.6 records/sec,   0.10 MB/sec,   685.6 ms avg latency,  1149.0 ms max latency
     463 records Write/Reading,      92.6 records/sec,   0.09 MB/sec,  1456.9 ms avg latency,  2284.0 ms max latency
     526 records Write/Reading,     105.2 records/sec,   0.10 MB/sec,   979.5 ms avg latency,  1831.0 ms max latency
[ForkJoinPool-2-worker-2] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint 0cd0453f-0178-46cc-b0f1-13333b6dd9b1
     310 records Write/Reading,      62.0 records/sec,   0.06 MB/sec,  2257.2 ms avg latency,  3498.0 ms max latency
     438 records Write/Reading,      87.6 records/sec,   0.08 MB/sec,  3985.6 ms avg latency,  5608.0 ms max latency
     317 records Write/Reading,      63.4 records/sec,   0.06 MB/sec,  5423.8 ms avg latency,  7007.0 ms max latency
     374 records Write/Reading,      74.8 records/sec,   0.07 MB/sec,  5602.1 ms avg latency,  7468.0 ms max latency
     909 records Write/Reading,     181.8 records/sec,   0.17 MB/sec,  4188.8 ms avg latency,  6792.0 ms max latency
     667 records Write/Reading,     133.3 records/sec,   0.13 MB/sec,  1966.2 ms avg latency,  3773.0 ms max latency
[ForkJoinPool-2-worker-2] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint 7f566df9-cad2-4a17-8760-5c505ffac7ab
     478 records Write/Reading,      95.6 records/sec,   0.09 MB/sec,   647.4 ms avg latency,  1163.0 ms max latency
     504 records Write/Reading,     100.8 records/sec,   0.10 MB/sec,   764.0 ms avg latency,  1332.0 ms max latency
     527 records Write/Reading,     105.4 records/sec,   0.10 MB/sec,   537.6 ms avg latency,  1125.0 ms max latency
     519 records Write/Reading,     103.8 records/sec,   0.10 MB/sec,   448.3 ms avg latency,   850.0 ms max latency
...
11001 records Write/Reading, 99.492 records/sec, 1000 bytes record size, 0.09 MB/sec, 1489.9 ms avg latency, 7468.0 ms max latency, 645 ms 50th, 1084 ms 75th, 2492 ms 95th, 2890 ms 99th, 2993 ms 99.9th

Naturally, case 3 is the one exhibiting the highest latency (i.e., via Internet). But for the other two cases the performance is virtually the same. So, how/from where did you execute the benchmark to have only writes exhibiting high latency? Is this behavior consistent/reproducible? cc/ @deenav

RaulGracia commented 5 years ago

@deenav I'm also suspicious of the -randomkey true flag, which is not in the benchmark anymore and may hit the performance of the client (e.g., selecting the appropriate segment for every write).

deenav commented 5 years ago

@RaulGracia I am able to consistently reproducible this behavior (only writes exhibiting high latency) from a Linux VM (10.31.x.x) hosted on Bangalore lab. And I am seeing the same behavior while running benchmark test without -randomkey true flag.

[epollEventLoopGroup-4-6] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 12 for endpoint 10.240.119.90. The current Channel is [id: 0x8aaf1ebb, L:/10.31.14.27:46170 - R:10.240.119.90/10.240.119.90:12345].
[epollEventLoopGroup-4-6] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
    1564 records Writing,     312.5 records/sec,   0.30 MB/sec,   449.6 ms avg latency,  1080.0 ms max latency
    1694 records Reading,     338.7 records/sec,   0.32 MB/sec,     0.7 ms avg latency,   409.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   259.9 ms avg latency,   311.0 ms max latency
     490 records Reading,      97.8 records/sec,   0.09 MB/sec,     2.0 ms avg latency,   409.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   259.9 ms avg latency,   312.0 ms max latency
     451 records Reading,      87.8 records/sec,   0.08 MB/sec,     2.1 ms avg latency,   410.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   260.1 ms avg latency,   311.0 ms max latency
     519 records Reading,     103.7 records/sec,   0.10 MB/sec,     1.0 ms avg latency,   408.0 ms max latency
     477 records Writing,      95.3 records/sec,   0.09 MB/sec,   259.7 ms avg latency,   314.0 ms max latency
     477 records Reading,      95.3 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   410.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   258.6 ms avg latency,   310.0 ms max latency
     490 records Reading,      97.9 records/sec,   0.09 MB/sec,     1.1 ms avg latency,   408.0 ms max latency
     480 records Writing,      95.8 records/sec,   0.09 MB/sec,   259.1 ms avg latency,   310.0 ms max latency
     480 records Reading,      95.9 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   409.0 ms max latency
     480 records Writing,      96.0 records/sec,   0.09 MB/sec,   259.4 ms avg latency,   321.0 ms max latency
     490 records Reading,      97.9 records/sec,   0.09 MB/sec,     1.0 ms avg latency,   409.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   258.6 ms avg latency,   308.0 ms max latency
     480 records Reading,      96.0 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   408.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   258.3 ms avg latency,   308.0 ms max latency
     481 records Reading,      91.3 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   408.0 ms max latency
     480 records Writing,      95.9 records/sec,   0.09 MB/sec,   257.8 ms avg latency,   307.0 ms max latency
     519 records Reading,     103.8 records/sec,   0.10 MB/sec,     1.0 ms avg latency,   405.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   257.8 ms avg latency,   314.0 ms max latency
     490 records Reading,      97.9 records/sec,   0.09 MB/sec,     1.8 ms avg latency,   406.0 ms max latency
     489 records Writing,      97.8 records/sec,   0.09 MB/sec,   258.2 ms avg latency,   310.0 ms max latency
     489 records Reading,      97.7 records/sec,   0.09 MB/sec,     1.0 ms avg latency,   406.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   258.5 ms avg latency,   308.0 ms max latency
     480 records Reading,      96.0 records/sec,   0.09 MB/sec,     1.9 ms avg latency,   407.0 ms max latency
     480 records Writing,      95.9 records/sec,   0.09 MB/sec,   258.4 ms avg latency,   308.0 ms max latency
     490 records Reading,      98.0 records/sec,   0.09 MB/sec,     1.0 ms avg latency,   406.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   258.2 ms avg latency,   309.0 ms max latency
     490 records Reading,      97.8 records/sec,   0.09 MB/sec,     1.8 ms avg latency,   406.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   265.7 ms avg latency,   520.0 ms max latency
     481 records Reading,      90.4 records/sec,   0.09 MB/sec,     2.0 ms avg latency,   470.0 ms max latency
     490 records Writing,      98.0 records/sec,   0.09 MB/sec,   258.0 ms avg latency,   308.0 ms max latency
     519 records Reading,     103.7 records/sec,   0.10 MB/sec,     1.0 ms avg latency,   406.0 ms max latency
     480 records Writing,      95.8 records/sec,   0.09 MB/sec,   258.6 ms avg latency,   311.0 ms max latency
     490 records Reading,      98.0 records/sec,   0.09 MB/sec,     1.8 ms avg latency,   406.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   258.3 ms avg latency,   311.0 ms max latency
     490 records Reading,      98.0 records/sec,   0.09 MB/sec,     1.0 ms avg latency,   406.0 ms max latency
     490 records Writing,      97.9 records/sec,   0.09 MB/sec,   258.0 ms avg latency,   307.0 ms max latency
     490 records Reading,      97.9 records/sec,   0.09 MB/sec,     1.8 ms avg latency,   406.0 ms max latency
     490 records Writing,      97.8 records/sec,   0.09 MB/sec,   258.3 ms avg latency,   308.0 ms max latency
[ForkJoinPool-1-worker-1] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - Closing reader EventStreamReaderImpl( id=0)
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/extern-test11/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/extern-test11/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 12 for endpoint 10.240.119.90
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
[ForkJoinPool-1-worker-1] INFO io.pravega.client.state.impl.StateSynchronizerImpl - Closing stateSynchronizer
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 8 for endpoint 10.240.119.88
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.ConditionalOutputStreamImpl - Closing segment metadata connection for Scope/_RGextern-test11/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 10 for endpoint 10.240.119.88
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.SegmentMetadataClientImpl - Closing segment metadata connection for Scope/_RGextern-test11/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 9 for endpoint 10.240.119.88
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/_RGextern-test11/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/_RGextern-test11/0.#epoch.0
[ForkJoinPool-1-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 7 for endpoint 10.240.119.88
[ForkJoinPool-1-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
11927 records Writing, 106.656 records/sec, 1000 bytes record size, 0.10 MB/sec, 284.0 ms avg latency, 1080.0 ms max latency, 264 ms 50th, 507 ms 95th, 559 ms 99th, 583 ms 99.9th.
11890 records Reading, 103.138 records/sec, 1000 bytes record size, 0.10 MB/sec, 1.4 ms avg latency, 470.0 ms max latency, 0 ms 50th, 1 ms 95th, 7 ms 99th, 408 ms 99.9th.
deenav commented 5 years ago

@RaulGracia I was using pravega-benchmark with commit id a047765 where it shows only writes are exhibiting high latency. With that version of Pravega benchmark, we are seeing the output of separate write and read latency in output.

But with latest Pravega benchmark commit id 169fa2b, we are not distinguishing between write and read latency. Below are the results for latest benchmark from my setup.

epollEventLoopGroup-4-6] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 12 for endpoint 10.240.119.89. The current Channel is [id: 0x855043f4, L:/10.31.14.27:56590 - R:10.240.119.89/10.240.119.89:12345].
[epollEventLoopGroup-4-6] INFO io.pravega.shared.protocol.netty.FailingReplyProcessor - Received hello: WireCommands.Hello(type=HELLO, highVersion=8, lowVersion=5)
     460 records Write/Reading,      92.0 records/sec,   0.09 MB/sec,   907.0 ms avg latency,  2476.0 ms max latency
     491 records Write/Reading,      98.2 records/sec,   0.09 MB/sec,   414.0 ms avg latency,   779.0 ms max latency
     503 records Write/Reading,     100.6 records/sec,   0.10 MB/sec,   441.0 ms avg latency,   793.0 ms max latency
     484 records Write/Reading,      96.8 records/sec,   0.09 MB/sec,   409.2 ms avg latency,   752.0 ms max latency
     523 records Write/Reading,     104.6 records/sec,   0.10 MB/sec,   420.4 ms avg latency,   749.0 ms max latency
     489 records Write/Reading,      97.8 records/sec,   0.09 MB/sec,   424.5 ms avg latency,   736.0 ms max latency
     511 records Write/Reading,     102.2 records/sec,   0.10 MB/sec,   401.8 ms avg latency,   740.0 ms max latency
     364 records Write/Reading,      72.8 records/sec,   0.07 MB/sec,   429.1 ms avg latency,  1602.0 ms max latency
     741 records Write/Reading,     148.2 records/sec,   0.14 MB/sec,   669.9 ms avg latency,  2074.0 ms max latency
     450 records Write/Reading,      90.0 records/sec,   0.09 MB/sec,   378.8 ms avg latency,   743.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,   404.3 ms avg latency,   766.0 ms max latency
     510 records Write/Reading,     102.0 records/sec,   0.10 MB/sec,   417.8 ms avg latency,   800.0 ms max latency
     470 records Write/Reading,      94.0 records/sec,   0.09 MB/sec,   392.8 ms avg latency,   774.0 ms max latency
     482 records Write/Reading,      96.4 records/sec,   0.09 MB/sec,   411.0 ms avg latency,   763.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,   402.7 ms avg latency,   797.0 ms max latency
     480 records Write/Reading,      96.0 records/sec,   0.09 MB/sec,   415.1 ms avg latency,   773.0 ms max latency
     480 records Write/Reading,      96.0 records/sec,   0.09 MB/sec,   390.8 ms avg latency,   723.0 ms max latency
     520 records Write/Reading,     104.0 records/sec,   0.10 MB/sec,   423.2 ms avg latency,   809.0 ms max latency
     460 records Write/Reading,      92.0 records/sec,   0.09 MB/sec,   421.3 ms avg latency,   817.0 ms max latency
[ForkJoinPool-2-worker-1] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - Closing reader EventStreamReaderImpl( id=0)
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/extern-test-latest-bm/0.#epoch.0
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/extern-test-latest-bm/0.#epoch.0
[ForkJoinPool-2-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 12 for endpoint 10.240.119.89
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
[ForkJoinPool-2-worker-1] INFO io.pravega.client.state.impl.StateSynchronizerImpl - Closing stateSynchronizer
[ForkJoinPool-2-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 9 for endpoint 10.240.119.88
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.ConditionalOutputStreamImpl - Closing segment metadata connection for Scope/_RGextern-test-latest-bm/0.#epoch.0
[ForkJoinPool-2-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 11 for endpoint 10.240.119.88
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.SegmentMetadataClientImpl - Closing segment metadata connection for Scope/_RGextern-test-latest-bm/0.#epoch.0
[ForkJoinPool-2-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 10 for endpoint 10.240.119.88
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing reader for Scope/_RGextern-test-latest-bm/0.#epoch.0
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Closing connection to segment: Scope/_RGextern-test-latest-bm/0.#epoch.0
[ForkJoinPool-2-worker-1] INFO io.pravega.client.netty.impl.FlowHandler - Closing Flow 8 for endpoint 10.240.119.88
[ForkJoinPool-2-worker-1] INFO io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.
9839 records Write/Reading, 99.269 records/sec, 1000 bytes record size, 0.09 MB/sec, 454.7 ms avg latency, 2476.0 ms max latency, 392 ms 50th, 460 ms 75th, 683 ms 95th, 744 ms 99th, 763 ms 99.9th
RaulGracia commented 5 years ago

I have executed a fourth benchmark from a node outside but closer to the infrastructure where the PKS cluster is running. As expected, the latency values are higher than executing the benchmark from within the PKS infrastructure, but lower compared to executing the benchmark from the Internet: 

[root@redhook-master-1 pravega-benchmark]# ./bin/pravega-benchmark -controller tcp://xxx:9090 -stream test11  -producers 1 -size 1000  -events 100 -time 120 -consumers 1
...
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,    17.3 ms avg latency,    76.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    16.1 ms avg latency,    44.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,    17.7 ms avg latency,    73.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,    17.6 ms avg latency,    71.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    18.3 ms avg latency,    62.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,    16.5 ms avg latency,    51.0 ms max latency
[ForkJoinPool-2-worker-50] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint 46e11c64-a6e2-4ea7-b34b-632df3051472
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    17.2 ms avg latency,    44.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    15.3 ms avg latency,    37.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    20.1 ms avg latency,    60.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    18.9 ms avg latency,    44.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    18.1 ms avg latency,    44.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    27.1 ms avg latency,   292.0 ms max latency
[ForkJoinPool-2-worker-50] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint e0f6b481-6439-45d6-b60b-eae38b798ca9
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    17.5 ms avg latency,    52.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,    16.2 ms avg latency,    53.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,    27.9 ms avg latency,   331.0 ms max latency
     502 records Write/Reading,     100.4 records/sec,   0.10 MB/sec,    17.2 ms avg latency,    46.0 ms max latency
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,    16.4 ms avg latency,    45.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,    16.3 ms avg latency,    49.0 ms max latency
[ForkJoinPool-2-worker-50] INFO io.pravega.client.stream.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=0) at checkpoint f7ae0d99-3ec4-43e2-a439-b2fa468d47d5
     499 records Write/Reading,      99.8 records/sec,   0.10 MB/sec,    17.8 ms avg latency,    45.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    18.6 ms avg latency,    56.0 ms max latency
     501 records Write/Reading,     100.2 records/sec,   0.10 MB/sec,    15.9 ms avg latency,    46.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    14.2 ms avg latency,    24.0 ms max latency
     500 records Write/Reading,     100.0 records/sec,   0.10 MB/sec,    16.5 ms avg latency,    34.0 ms max latency
...
11770 records Write/Reading, 99.979 records/sec, 1000 bytes record size, 0.10 MB/sec, 18.0 ms avg latency, 331.0 ms max latency, 15 ms 50th, 19 ms 75th, 27 ms 95th, 41 ms 99th, 62 ms 99.9th

In summary, the latency behavior we are observing is the expected one. Moreover, the different behavior between writes and reads seems also expected given their different workflows: each write requires an ACK from Pravega and therefore induces latency on each operation, whereas the client performs read-ahead operations that minimize latency for most reads (1-2 ms of avg latency), with the exception of the first read (max read latency in your experiments is around 400ms).

Given that all this seems expected, I'm closing this issue. Please, re-open it if you find any other related problem.

RaulGracia commented 5 years ago

To summarize the knowledge collected in this issue, the external connectivity (i.e., use the public IP of the Controller in a client) latency behaves as following:

This behavior is the expected one.