Re: [jgroups-users] Getting high latency!!!

Hi Ibrahim,

On 22/03/16 20:34, Questions/problems related to using JGroups wrote:
> Dear All,
>
> I have implemented state machine protocol on the top of JGroups and run it
> in three servers machines.
> The following is how the protocol works if you are interested.
>
> *Protocol details: *
> Let’s say we have 3-machines clusters A, B and C. A is a leader and B and C
> are followers. The protocol works as following:
> 1.	Clients (from different machine not on A, B, OR C) sends requests (update
> request) to leader one of followers.
> 2.	Upon receiving a request, follower forwards it to the leader.
> 3.	Upon receiving a request either from client or follower, leader prepare
> for a proposal and broadcasts to all replicas (itself and followers).
> 4.	Upon receiving a proposal, followers stores it locally and sends ACK to
> the leader.
> 5.	Upon receiving ACK from a majority of replicas (including itself),  a
> leader sends a commit message to all replicas informing them to deliver a
> request.


Looks like Raft; do you know that I implemented Raft in the jgroups-raft 
protocol?


> *Workload:*
> I did workloads using ten client machines; each generates 10 threads
> (senders). The sender sends the next request as soon as receives the reply
> of the current request.  All workload is write only requests and in total
> the clients send 1000000 requests.

So there can be a max of 100 requests on the servers at any given time, 
correct?

I assume a client picks a random node from the 3 node cluster? I know 
what your problem is (read below).

> I measure latency and throughput. The latency is defined here as t1-t0 where
> t0 is the time at which a follower or leader receives a client request and
> t1 is the time at which the follower or leader delivers that request.
>
> *Problem:*
> 1.	When I look at the result, the majority of 1000000 latencies is ranged
> between 0.5 and 2 millisecond (ms). But there are high latencies which
> affect the latency average. I notice that a large latency happens in
> different times during the workloads. For example, in time T4 latency became
> increase suddenly from 1.281859 ms to 429.9404 ms and then continue to
> increase steeply until reaching 1004.944 ms then decrease until reach to
> normal, 1.276148 ms.
>
> When I compute the average the high latency negatively affect the average.
>
>
> *Try:*
>
> I increased the initial heap size to 900M. This does not help a lot.

No need to do that, read below.

> Note that I did not change Max heap size as the current is very enough which is
> 3gb.
>
> I  am thinking the problem could be JGroups protocols that reside in stack.
> However, you may think the problem can cause by JGroups UFC and MFC
> protocols, no as I do not use them. The following is the protocol stack that
> I use.

I'd add MFC and UFC back into the stack, because your problem is 
something else.

So we have 100 client requests at any time that need to be processed by 
the leader. There are actually more mesages to be processed by the leader:
- 100 client requests
- 100 ACKs to proposals

So 200 messages max at any given time.

The problem is that your thread pools below are too small to process 
this load and thus requests (and acks) get queued in the regular thread 
pool (queue size is 50'000) and the regular pool has a max of 8 threads. 
This introduces latency to each request, depending on how many requests 
are ahead of it in the queue.

If you use OOB messages, then your OOB requests get discarded if you 
have more than 8 threads, and then messages need to be retransmitted, 
adding latency (of 1s per message) as well.

So this can be fixed by using the following thread pool config:

     thread_pool.enabled="true"
     thread_pool.min_threads="2"
     thread_pool.max_threads="200"       // increase to 200
     thread_pool.keep_alive_time="5000"
     thread_pool.queue_enabled="false"   // set to false
     thread_pool.rejection_policy="discard"

     oob_thread_pool.enabled="true"
     oob_thread_pool.min_threads="2"
     oob_thread_pool.max_threads="200"   // changed to 200
     oob_thread_pool.keep_alive_time="5000"
     oob_thread_pool.queue_enabled="false"
     oob_thread_pool.rejection_policy="discard"/>

I'm assuming you use regular (not OOB) messages. Now we can have up to 
200 threads processing messages. We never use more than 100 though as 
messages from the same sender are processed sequentially.

************************
Actually: *CORRECTION*! I'm an idiot, because you don't have a cluster 
of 100 nodes, but only of 3 nodes!!!
************************

Sorry about this!

So the problem is that you get messages from [A,B,C], so the thread pool 
changes above won't help!

The real problem is that you use regular messages. So if A has messages 
A[15-50], B[1-30] and C[7=80], then all messages from B (for example) 
are processed _sequentially_, ie. B20 is processed after B19 which is 
processed after B18 and so on.

This means the time added to the processing time of B20 is the 
accumulated wait time of all requests ahead of B20 in the queue! There 
are 2 solutions:
#1 Use OOB messages which are processed in parallel even if they're sent 
by the same sender. The question is whether your app can tolerate this
#2 Use the async invocation API (check the manual)


Note that we're discussing this extensively in the JGroups workshop ([1] 
April 4-8 in Munich).

Cheers,

[1] https://github.com/belaban/workshop/blob/master/slides/advanced.adoc

> *Any help with such issue?*
>
> Thank you indeed.
>
> Ibrahim
>
> <config xmlns="urn:org:jgroups"
>          xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
>          xsi:schemaLocation="urn:org:jgroups
> http://www.jgroups.org/schema/JGroups-3.3.xsd">
>      <UDP
>              mcast_port="${jgroups.udp.mcast_port:45588}"
>              tos="8"
>              max_bundle_size="64K"
>              max_bundle_timeout="30"
>              enable_diagnostics="true"
>              thread_naming_pattern="cl"
>              ip_mcast="false"
>              timer_type="new3"
>              timer.min_threads="10"
>              timer.max_threads="10"
>              timer.keep_alive_time="3000"
>              timer.queue_max_size="500"
>              timer.rejection_policy="abort"
>              thread_pool.enabled="true"
>              thread_pool.min_threads="2"
>              thread_pool.max_threads="8"
>              thread_pool.keep_alive_time="5000"
>              thread_pool.queue_enabled="true"
>              thread_pool.queue_max_size="10000"
>              thread_pool.rejection_policy="discard"
>              oob_thread_pool.enabled="true"
>              oob_thread_pool.min_threads="1"
>              oob_thread_pool.max_threads="8"
>              oob_thread_pool.keep_alive_time="5000"
>              oob_thread_pool.queue_enabled="false"
>              oob_thread_pool.queue_max_size="100"
>              oob_thread_pool.rejection_policy="discard"/>
>
>
>      <FILE_PING
>              timeout="2000"
>              num_initial_members="20"
>              location="/home/pg/p13/a6915654/"/>
>      <MERGE2 max_interval="30000"
>              min_interval="10000"/>
>      <FD_SOCK/>
>      <FD_ALL/>
>      <VERIFY_SUSPECT timeout="1500"  />
>      <BARRIER/>
>      <pbcast.NAKACK2 xmit_interval="1000"
>                      xmit_table_num_rows="100"
>                      xmit_table_msgs_per_row="2000"
>                      xmit_table_max_compaction_time="30000"
>                      max_msg_batch_size="500"
>                      use_mcast_xmit="false"
>                      discard_delivered_msgs="true"/>
>      <UNICAST3 xmit_interval="500"
>                xmit_table_num_rows="100"
>                xmit_table_msgs_per_row="2000"
>                xmit_table_max_compaction_time="60000"
>                conn_expiry_timeout="0"
>                max_msg_batch_size="500"/>
>      <pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000"
>                     max_bytes="4M"/>
>       <pbcast.GMS print_local_addr="true" join_timeout="3000"
>                  view_bundling="true"/>
>
>
>      <RSVP resend_interval="2000" timeout="10000"/>
>
>      <Myprotocol/>
>      <FRAG2 frag_size="60K"  />
>      <pbcast.STATE_TRANSFER />
> </config>
>
>
>
>
>
>
> --
> View this message in context: http://jgroups.1086181.n5.nabble.com/Getting-high-latency-tp11004.html
> Sent from the JGroups - General mailing list archive at Nabble.com.
>
> ------------------------------------------------------------------------------
> Transform Data into Opportunity.
> Accelerate data analysis in your applications with
> Intel Data Analytics Acceleration Library.
> Click to learn more.
> http://pubads.g.doubleclick.net/gampad/clk?id=278785351&iu=/4140
> _______________________________________________
> javagroups-users mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/javagroups-users
>

-- 
Bela Ban, JGroups lead (http://www.jgroups.org)


------------------------------------------------------------------------------
Transform Data into Opportunity.
Accelerate data analysis in your applications with
Intel Data Analytics Acceleration Library.
Click to learn more.
http://pubads.g.doubleclick.net/gampad/clk?id=278785351&iu=/4140
_______________________________________________
javagroups-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/javagroups-users