[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Nils Goroll]

> What would you think about a fix following your idea of always putting 
> the last used entry upfront the list, but removing the time stamp code?

Sorry for the language mistake: I meant putting the last used entry to the 
front 
of the list, not upfront the list (whatever that could mean ;-).

Nils

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Nils Goroll]

Hi Dai,

>> In this particular case, however, I think we should really aim for a 
>> solution which also does away with some legacy code with sets an 
>> initial barrier for understanding the code. By not removing this code, 
>> that barrier would be raised, IMHO, because the solution you suggested 
>> adds even more complexity.
> I respectfully disagree.

That's fine. A constructive technical discussion is always welcome.

> The original logic for load balancing is pretty straight forward
> and easy to understand. Unfortunately, the time stamp resolution used is 
> not fine enough causing the side effect resulting in the last entry
 > always being selected for the remainder of the clock tick.

I fear I repeat myself, but I really don't think that a two level load 
balancing 
algorithm (first by LU timestamp, then round robin) is a good solution when 
simple round robin will just do the job.

What would you think about a fix following your idea of always putting the last 
used entry upfront the list, but removing the time stamp code?

> Perhaps the suggested fix should be better commented 
> to point out the
> problem and how the change addresses it.

Better comments are always a good idea, whatever will be implemented in the 
end. :-)

Nils

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Nils Goroll]

Hi Dai,

>> * Besides clnt_max_conns, there are other static declarations, which 
>> need to be removed. Your proposed changed does not fix these.
> Yes, this webrev was intended to show the proposed change for the load 
> balancing issue.
> I removed only the static declaration for clnt_max_conns for testing 
> purpose.

OK.

> My main concern is the stability and performance of the system when 
> changes are made to a sensitive
> area such as rpcmod. Simpler change is easier to understand and verify, 
> less chance of introducing new
> bug, less impact to performance of the code.

Now I got your point and I agree in the general case. I am also aware of the 
significance of this piece of code and I do definitely want to avoid any 
regressions here.

In this particular case, however, I think we should really aim for a solution 
which also does away with some legacy code with sets an initial barrier for 
understanding the code. By not removing this code, that barrier would be 
raised, 
IMHO, because the solution you suggested adds even more complexity.

>> I would also like to point our that I have reduced the complexity for 
>> dooming entries (will be done in one go trough the list rather than 
>> starting all over when an entry is doomed), that I hope to have made 
>> the function more concise and that I hope to improve on maintenance by 
>> adding comments.
> I'm not sure if we need to address this since clnt_max_conns is not 
> expected to change frequently.

Agree. I did this because the change was straight forward and contributed to 
code clarity, IMHO.

By the way, I just noticed that it is probably required to hold 
cm_entry->x_lock 
when juggling with list linkage pointers.

Nils

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Nils Goroll]

Dai,

> I think we can achieve the same result with a simpler change
> by removing and re-inserting the entry to the head of the list
> once it was selected. The webrev for that change is here:
> 
> http://cr.opensolaris.org/~dain/6817942/ 
> 

First of all, sorry for the delay which was on my side this time.

Regarding your suggested change:

* Besides clnt_max_conns, there are other static declarations, which need to be 
removed. Your proposed changed does not fix these.

* The change you propose changes the way the last used cm_xprt entry is saved - 
but this does not have anything to do with the root cause of the issue, which 
is 
that using timestamps is inappropriate. I do not like the fact that your change 
exploits an unintentional side effect of the original solution (the fact that 
the last of the entries with equivalent x_time is selected) to implement round 
robin behavior without doing away the the flawed implementation in the first 
place.

On a meta-layer, I think we can come up with hundreds of alternative solutions 
to this issue. I have asked for reviews of my proposed solution and I have not 
received any. What was your motivation to propose a completely different 
approach?

I would also like to point our that I have reduced the complexity for dooming 
entries (will be done in one go trough the list rather than starting all over 
when an entry is doomed), that I hope to have made the function more concise 
and 
that I hope to improve on maintenance by adding comments.

Nils

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Dai Ngo]

Nils,
>> My main concern is the stability and performance of the system when 
>> changes are made to a sensitive
>> area such as rpcmod. Simpler change is easier to understand and 
>> verify, less chance of introducing new
>> bug, less impact to performance of the code.
>
> Now I got your point and I agree in the general case. I am also aware 
> of the significance of this piece of code and I do definitely want to 
> avoid any regressions here.
>
> In this particular case, however, I think we should really aim for a 
> solution which also does away with some legacy code with sets an 
> initial barrier for understanding the code. By not removing this code, 
> that barrier would be raised, IMHO, because the solution you suggested 
> adds even more complexity.
I respectfully disagree. The original logic for load balancing is pretty 
straight forward
and easy to understand. Unfortunately, the time stamp resolution used is 
not fine enough
causing the side effect resulting in the last entry always being 
selected for the remainder
of the clock tick. Perhaps the suggested fix should be better commented 
to point out the
problem and how the change addresses it.

-Dai

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Dai Ngo]

Hi Nils,

Nils Goroll wrote:
> Dai,
>
>> I think we can achieve the same result with a simpler change
>> by removing and re-inserting the entry to the head of the list
>> once it was selected. The webrev for that change is here:
>>
>> http://cr.opensolaris.org/~dain/6817942/ 
>> 
>
> First of all, sorry for the delay which was on my side this time.
>
> Regarding your suggested change:
>
> * Besides clnt_max_conns, there are other static declarations, which 
> need to be removed. Your proposed changed does not fix these.
Yes, this webrev was intended to show the proposed change for the load 
balancing issue.
I removed only the static declaration for clnt_max_conns for testing 
purpose.
>
> * The change you propose changes the way the last used cm_xprt entry 
> is saved - but this does not have anything to do with the root cause 
> of the issue, which is that using timestamps is inappropriate. I do 
> not like the fact that your change exploits an unintentional side 
> effect of the original solution (the fact that the last of the entries 
> with equivalent x_time is selected) to implement round robin behavior 
> without doing away the the flawed implementation in the first place.
You can look at this as an exploitation, or compensation for a defect, 
or fixing a flaw, etc.
To me it's the end effect with minimal risk.
>
> On a meta-layer, I think we can come up with hundreds of alternative 
> solutions to this issue. I have asked for reviews of my proposed 
> solution and I have not received any. What was your motivation to 
> propose a completely different approach?
My main concern is the stability and performance of the system when 
changes are made to a sensitive
area such as rpcmod. Simpler change is easier to understand and verify, 
less chance of introducing new
bug, less impact to performance of the code.
>
> I would also like to point our that I have reduced the complexity for 
> dooming entries (will be done in one go trough the list rather than 
> starting all over when an entry is doomed), that I hope to have made 
> the function more concise and that I hope to improve on maintenance by 
> adding comments.
I'm not sure if we need to address this since clnt_max_conns is not 
expected to change frequently.

Thanks,
-Dai

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Dai Ngo]

Hi Nils,

Have you had a chance to take a look at the proposed changed?

Thanks,
-Dai

Dai Ngo wrote:
> Hi Nils,
>
> Thank you for your effort to fix these issues.
>
> I think we can achieve the same result with a simpler change
> by removing and re-inserting the entry to the head of the list
> once it was selected. The webrev for that change is here:
>
> http://cr.opensolaris.org/~dain/6817942/ 
> 
>
> I tested the change and verified it OK with dtrace:
>
> #!/usr/sbin/dtrace -s
>
> fbt:rpcmod:connmgr_get:return
> {
>   @a[((struct cm_xprt *)arg1)]=count()
> }
>
> [BEFORE]
>
> pnfs-18-21.root[510] ./rpc.d
> dtrace: script './rpc.d' matched 2 probes
> ^C
>
>  -10910719461764
>  -10893033518724
>  -10909809704325
>  -10893032338565
>  -1091352342336 4208
>  -1091352346816 4225
>  -1091277309824 4237
>  -109127731020821463
> pnfs-18-21.root[511]
>
>
> [AFTER]
>
> dtrace: script './rpc.d' matched 2 probes
> ^C
>
>  -10910719461761
>  -10909809704321
>  -10893033518722
>  -10893032338562
>  -1091277310208 8539
>  -1091352346816 8540
>  -1091352342336 8540
>  -1091277309824 8540
> pnfs-18-21.root[512]
>
> Thanks,
> -Dai
>
>
> Nils Goroll wrote:
>> Hi All,
>>
>> Peter Memishian has recommended that I ask the NFS community rather 
>> than the networking community, see 
>> http://opensolaris.org/jive/thread.jspa?threadID=97367&tstart=0 for 
>> the original thread.
>>
>> I have written a fix for the issue initially documented in 6696163, 
>> for which I
>> have now opened 6817942 to get one bug for one issue.
>>
>> The root cause is documented in 6696163: When choosing a connection 
>> for an RPC
>> call, the old connmgr_get code used lbolt timestamps which don't have 
>> enough
>> precision (nowadays) to yield proper load balancing.
>>
>> I have implemented round robin load balancing: Whenever a connection is
>> requested via connmgr_get, it is noted as last used. Upon the next 
>> connection
>> request, the connection which comes next in the list of connections 
>> (or the
>> first one if the last one was used last) is returned.
>>
>> I have left a comment in the code explaining why I chose the 
>> particular approach
>> and what I think should be done when someone comes to do a larger 
>> rewrite of the
>> code in question.
>>
>> I would appreciate reviews of my suggested fix, which is available at
>>
>> http://cr.opensolaris.org/~nigoroll/rpc_loadbalancing_6817942/
>>
>> Thanks, Nils
>>
>> -- 
>>
>> Tests I conducted:
>>
>>  PREPARATIONS
>>
>>> clnt_max_conns/D
>> clnt_max_conns:
>> clnt_max_conns: 4
>>
>>> rpclog/W b
>> rpclog: 0   =   0xb
>>
>> ifconfig e1000g0 addif 192.168.77.100/24 up deprecated
>> share -o rw=localhost:192.168.77.29,root=localhost:192.168.77.29 \
>> /var/tmp/s
>> mkdir /tmp/c
>> cd ; umount /tmp/c ; \
>> mount -o vers=3,proto=tcp 192.168.77.100:/var/tmp/s /tmp/c ; \
>> cd /tmp/c
>>
>>  TEST BALANCING
>>
>>> rpclog/W 2
>> rpclog: 0   =   0x2
>>> clnt_max_conns/D
>> clnt_max_conns:
>> clnt_max_conns: 4
>>
>> - mount share (see above)
>> - ls -als
>>
>> haggis:/tmp/c# egrep '19:57:.*call going out' /var/adm/messages
>> Mar 16 19:58:10 haggis rpcmod: [ID 595603 kern.notice] 
>> clnt_tli_kinit: COTS selected
>> Mar 16 19:58:10 haggis rpcmod: [ID 359612 kern.notice] 
>> clnt_cots_kcallit, procnum 4
>> Mar 16 19:58:10 haggis rpcmod: [ID 832978 kern.notice] 
>> clnt_cots_kcallit:
>> wait.tv_sec: 60
>> Mar 16 19:58:10 haggis rpcmod: [ID 359371 kern.notice] 
>> clnt_cots_kcallit:
>> wait.tv_usec: 0
>> Mar 16 19:57:22 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f4598c38
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b3c8
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b5f0
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b760
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f4598c38
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b3c8
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b5f0
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b760
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f4598c38
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
>> call going
>> out on ff01f459b3c8
>> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Dai Ngo]

Hi Nils,

Thank you for your effort to fix these issues.

I think we can achieve the same result with a simpler change
by removing and re-inserting the entry to the head of the list
once it was selected. The webrev for that change is here:

http://cr.opensolaris.org/~dain/6817942/ 


I tested the change and verified it OK with dtrace:

#!/usr/sbin/dtrace -s

fbt:rpcmod:connmgr_get:return
{
   @a[((struct cm_xprt *)arg1)]=count()
}

[BEFORE]

pnfs-18-21.root[510] ./rpc.d
dtrace: script './rpc.d' matched 2 probes
^C

  -10910719461764
  -10893033518724
  -10909809704325
  -10893032338565
  -1091352342336 4208
  -1091352346816 4225
  -1091277309824 4237
  -109127731020821463
pnfs-18-21.root[511]


[AFTER]

dtrace: script './rpc.d' matched 2 probes
^C

  -10910719461761
  -10909809704321
  -10893033518722
  -10893032338562
  -1091277310208 8539
  -1091352346816 8540
  -1091352342336 8540
  -1091277309824 8540
pnfs-18-21.root[512]

Thanks,
-Dai


Nils Goroll wrote:
> Hi All,
>
> Peter Memishian has recommended that I ask the NFS community rather 
> than the networking community, see 
> http://opensolaris.org/jive/thread.jspa?threadID=97367&tstart=0 for 
> the original thread.
>
> I have written a fix for the issue initially documented in 6696163, 
> for which I
> have now opened 6817942 to get one bug for one issue.
>
> The root cause is documented in 6696163: When choosing a connection 
> for an RPC
> call, the old connmgr_get code used lbolt timestamps which don't have 
> enough
> precision (nowadays) to yield proper load balancing.
>
> I have implemented round robin load balancing: Whenever a connection is
> requested via connmgr_get, it is noted as last used. Upon the next 
> connection
> request, the connection which comes next in the list of connections 
> (or the
> first one if the last one was used last) is returned.
>
> I have left a comment in the code explaining why I chose the 
> particular approach
> and what I think should be done when someone comes to do a larger 
> rewrite of the
> code in question.
>
> I would appreciate reviews of my suggested fix, which is available at
>
> http://cr.opensolaris.org/~nigoroll/rpc_loadbalancing_6817942/
>
> Thanks, Nils
>
> -- 
>
> Tests I conducted:
>
>  PREPARATIONS
>
>> clnt_max_conns/D
> clnt_max_conns:
> clnt_max_conns: 4
>
>> rpclog/W b
> rpclog: 0   =   0xb
>
> ifconfig e1000g0 addif 192.168.77.100/24 up deprecated
> share -o rw=localhost:192.168.77.29,root=localhost:192.168.77.29 \
> /var/tmp/s
> mkdir /tmp/c
> cd ; umount /tmp/c ; \
> mount -o vers=3,proto=tcp 192.168.77.100:/var/tmp/s /tmp/c ; \
> cd /tmp/c
>
>  TEST BALANCING
>
>> rpclog/W 2
> rpclog: 0   =   0x2
>> clnt_max_conns/D
> clnt_max_conns:
> clnt_max_conns: 4
>
> - mount share (see above)
> - ls -als
>
> haggis:/tmp/c# egrep '19:57:.*call going out' /var/adm/messages
> Mar 16 19:58:10 haggis rpcmod: [ID 595603 kern.notice] clnt_tli_kinit: 
> COTS selected
> Mar 16 19:58:10 haggis rpcmod: [ID 359612 kern.notice] 
> clnt_cots_kcallit, procnum 4
> Mar 16 19:58:10 haggis rpcmod: [ID 832978 kern.notice] clnt_cots_kcallit:
> wait.tv_sec: 60
> Mar 16 19:58:10 haggis rpcmod: [ID 359371 kern.notice] clnt_cots_kcallit:
> wait.tv_usec: 0
> Mar 16 19:57:22 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b3c8
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b5f0
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b760
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b3c8
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b5f0
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b760
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b3c8
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b5f0
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b760
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> [...etc...]
>
>  Test balancing t

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Nils Goroll]

Hi Mahesh,

>> I have written a fix for the issue initially documented in 6696163, 
>> for which I
>> have now opened 6817942 to get one bug for one issue.
>>
> Nils, I'll take a look at this and get back to you early next week.

Thank you.

> Just for my understanding, whats the background/motivation in
> your interest in increasing the max number of connections?

My personal motivation is that I try to spread NFS load between a single 
Solaris 
NFS client and a single NFS Server (NetApp in this case, but that shouldn't 
matter) over several Gigabit Ethernet links. The main insight is that you need 
to spread NFS calls over several source IPs in order to achieve load balancing 
(Channeling/Trunking needs to balance by IP or source MAC, unless you do RR on 
Layer2, which will lead to out-of-order delivery and kill performance. Some 
implementations also allow to hash by TCP/UDP port, which also makes it 
necessary to spread NFS load over several connections).

Another, similar motivation is documented in 6696163. If I understand 
correctly, 
the person who opened the bug initially observed that multiple TX ring capacity 
can not be exploited unless NFS load is spread over several connections.

Nils

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Mahesh Siddheshwar]

Nils Goroll wrote:
> Hi All,
>
> Peter Memishian has recommended that I ask the NFS community rather 
> than the networking community, see 
> http://opensolaris.org/jive/thread.jspa?threadID=97367&tstart=0 for 
> the original thread.
>
> I have written a fix for the issue initially documented in 6696163, 
> for which I
> have now opened 6817942 to get one bug for one issue.
>
Nils, I'll take a look at this and get back to you early next week.

Just for my understanding, whats the background/motivation in
your interest in increasing the max number of connections?

Mahesh
> The root cause is documented in 6696163: When choosing a connection 
> for an RPC
> call, the old connmgr_get code used lbolt timestamps which don't have 
> enough
> precision (nowadays) to yield proper load balancing.
>
> I have implemented round robin load balancing: Whenever a connection is
> requested via connmgr_get, it is noted as last used. Upon the next 
> connection
> request, the connection which comes next in the list of connections 
> (or the
> first one if the last one was used last) is returned.
>
> I have left a comment in the code explaining why I chose the 
> particular approach
> and what I think should be done when someone comes to do a larger 
> rewrite of the
> code in question.
>
> I would appreciate reviews of my suggested fix, which is available at
>
> http://cr.opensolaris.org/~nigoroll/rpc_loadbalancing_6817942/
>
> Thanks, Nils
>
> -- 
>
> Tests I conducted:
>
>  PREPARATIONS
>
>> clnt_max_conns/D
> clnt_max_conns:
> clnt_max_conns: 4
>
>> rpclog/W b
> rpclog: 0   =   0xb
>
> ifconfig e1000g0 addif 192.168.77.100/24 up deprecated
> share -o rw=localhost:192.168.77.29,root=localhost:192.168.77.29 \
> /var/tmp/s
> mkdir /tmp/c
> cd ; umount /tmp/c ; \
> mount -o vers=3,proto=tcp 192.168.77.100:/var/tmp/s /tmp/c ; \
> cd /tmp/c
>
>  TEST BALANCING
>
>> rpclog/W 2
> rpclog: 0   =   0x2
>> clnt_max_conns/D
> clnt_max_conns:
> clnt_max_conns: 4
>
> - mount share (see above)
> - ls -als
>
> haggis:/tmp/c# egrep '19:57:.*call going out' /var/adm/messages
> Mar 16 19:58:10 haggis rpcmod: [ID 595603 kern.notice] clnt_tli_kinit: 
> COTS selected
> Mar 16 19:58:10 haggis rpcmod: [ID 359612 kern.notice] 
> clnt_cots_kcallit, procnum 4
> Mar 16 19:58:10 haggis rpcmod: [ID 832978 kern.notice] clnt_cots_kcallit:
> wait.tv_sec: 60
> Mar 16 19:58:10 haggis rpcmod: [ID 359371 kern.notice] clnt_cots_kcallit:
> wait.tv_usec: 0
> Mar 16 19:57:22 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b3c8
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b5f0
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b760
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b3c8
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b5f0
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b760
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b3c8
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b5f0
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f459b760
> Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: 
> call going
> out on ff01f4598c38
> [...etc...]
>
>  Test balancing throughput (can't to a real performance test on a 
> single
>  laptop, this is more a test against massive performance regression)
>
> haggis:/tmp/c# iostat -xznM 5 & dd if=1g_1 of=/dev/zero 
> bs=$((1024*1024))&
> [2] 100689
> [3] 100690
> haggis:/tmp/c# extended device statistics
> r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
>24.17.51.10.1  0.8  0.3   24.38.1  12  20 c5t0d0
> 0.00.00.00.0  0.0  0.00.0  122.5   0   0
> 192.168.77.100:/var/tmp/s
> extended device statistics
> r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
>   486.4   10.9   60.60.1  2.4 28.14.7   56.5  77 100 c5t0d0
>  1907.10.0   59.60.0  0.4  1.80.20.9  18  97
> 192.168.77.100:/var/tmp/s
> extended device statistics
> r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
>   206.51.2   25.80.0  2.4 11.8   11.7   56.7  40  40 c5t0d0
>  4199.20.0  131.2 

[nfs-discuss] Please review my fix for: 6817942 RPC loadbalancing with clnt_max_conns >1 does not work (includes notes on tests)

[Nils Goroll]

Hi All,

Peter Memishian has recommended that I ask the NFS community rather than the 
networking community, see 
http://opensolaris.org/jive/thread.jspa?threadID=97367&tstart=0 for the 
original 
thread.

I have written a fix for the issue initially documented in 6696163, for which I
have now opened 6817942 to get one bug for one issue.

The root cause is documented in 6696163: When choosing a connection for an RPC
call, the old connmgr_get code used lbolt timestamps which don't have enough
precision (nowadays) to yield proper load balancing.

I have implemented round robin load balancing: Whenever a connection is
requested via connmgr_get, it is noted as last used. Upon the next connection
request, the connection which comes next in the list of connections (or the
first one if the last one was used last) is returned.

I have left a comment in the code explaining why I chose the particular approach
and what I think should be done when someone comes to do a larger rewrite of the
code in question.

I would appreciate reviews of my suggested fix, which is available at

http://cr.opensolaris.org/~nigoroll/rpc_loadbalancing_6817942/

Thanks, Nils

--

Tests I conducted:

 PREPARATIONS

> clnt_max_conns/D
clnt_max_conns:
clnt_max_conns: 4

> rpclog/W b
rpclog: 0   =   0xb

ifconfig e1000g0 addif 192.168.77.100/24 up deprecated
share -o rw=localhost:192.168.77.29,root=localhost:192.168.77.29 \
/var/tmp/s
mkdir /tmp/c
cd ; umount /tmp/c ; \
mount -o vers=3,proto=tcp 192.168.77.100:/var/tmp/s /tmp/c ; \
cd /tmp/c

 TEST BALANCING

> rpclog/W 2
rpclog: 0   =   0x2
> clnt_max_conns/D
clnt_max_conns:
clnt_max_conns: 4

- mount share (see above)
- ls -als

haggis:/tmp/c# egrep '19:57:.*call going out' /var/adm/messages
Mar 16 19:58:10 haggis rpcmod: [ID 595603 kern.notice] clnt_tli_kinit: COTS 
selected
Mar 16 19:58:10 haggis rpcmod: [ID 359612 kern.notice] clnt_cots_kcallit, 
procnum 4
Mar 16 19:58:10 haggis rpcmod: [ID 832978 kern.notice] clnt_cots_kcallit:
wait.tv_sec: 60
Mar 16 19:58:10 haggis rpcmod: [ID 359371 kern.notice] clnt_cots_kcallit:
wait.tv_usec: 0
Mar 16 19:57:22 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f4598c38
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b3c8
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b5f0
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b760
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f4598c38
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b3c8
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b5f0
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b760
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f4598c38
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b3c8
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b5f0
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f459b760
Mar 16 19:57:26 haggis rpcmod: [ID 757553 kern.notice] connmgr_get: call going
out on ff01f4598c38
[...etc...]

 Test balancing throughput (can't to a real performance test on a single
 laptop, this is more a test against massive performance regression)

haggis:/tmp/c# iostat -xznM 5 & dd if=1g_1 of=/dev/zero bs=$((1024*1024))&
[2] 100689
[3] 100690
haggis:/tmp/c# extended device statistics
 r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
24.17.51.10.1  0.8  0.3   24.38.1  12  20 c5t0d0
 0.00.00.00.0  0.0  0.00.0  122.5   0   0
192.168.77.100:/var/tmp/s
 extended device statistics
 r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
   486.4   10.9   60.60.1  2.4 28.14.7   56.5  77 100 c5t0d0
  1907.10.0   59.60.0  0.4  1.80.20.9  18  97
192.168.77.100:/var/tmp/s
 extended device statistics
 r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
   206.51.2   25.80.0  2.4 11.8   11.7   56.7  40  40 c5t0d0
  4199.20.0  131.20.0  0.5  2.20.10.5  33  97
192.168.77.100:/var/tmp/s
1024+0 records in
1024+0 records out
 extended device statistics
 r/sw/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
 0.40.00.00.0  0.0  0.00.05.4   0   0 c5t0d0
   461.00.0   14.40.0  0.1  0.20.10.4   4   8
192.168.77.100:/var/tmp/s

 Is Dooming working OK?

> rpclog/W 8
rpclog: 0   =   0x8
> clnt_max_conns/W 8