Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Raghavendra Gowdappa]

adding gluster-users and glusterdevel as the discussion has some generic
points

+Gluster-users  +Gluster Devel


On Mon, Mar 4, 2019 at 11:43 PM Raghavendra Gowdappa 
wrote:

>
>
> On Mon, Mar 4, 2019 at 11:26 PM Yaniv Kaul  wrote:
>
>> Is it that busy that it cannot reply for so many seconds to a simple
>> ping? That starved of CPU resources / threads, or are locks taken?
>>
>
While I had answered giving some specific examples, my previous answer
missed some general observations:
ping timer is designed with following goals:

1. identifying ungraceful shutdown of bricks (hard power shutdown, pulling
of n/w cable etc)
2. identifying slow bricks and avoiding traffic to them (If connection is
shutdown, clients will not use it till reconnection happens)

When we consider point 2, ping packet is not a special packet. Instead it
experiences same delays as any other regular fs traffic. So, the question
asked above doesn't apply (as ping is not treated "specially" wrt fs
traffic, if the brick is overloaded processing fs traffic, it is overloaded
to respond a "simple ping" too)

While the implementation/design neatly caters to the first goal, second
goal is not completely met and sort of partly implemented/designed. If goal
2 is to be completely fulfilled, I can think of at least 2 things to be
done currently:

1. reconnect logic in client should make intelligent decision whether to
reconnect to an overloaded brick and I guess identifying whether the brick
is no longer overloaded is not a trivial task
2. As a "fix" to ping-timer expiries, we introduced a "request queue" to
glusterfs program. Event threads, which read requests from network will
only queue them to this "request queue" and processing of them is done in
different threads. This (at least in theory) makes event-threads to read
and respond ping packets faster. However, this means ping responses are no
longer indicative of "load" on brick. With hindsight, to me this fix is
more symptomatic (users no longer see ENOTCONN errors - which pushes the
responsibility out of module handling "ping" :), but they might experience
slow performance) than address the underlying root cause of what made
bricks unresponsive at first. For eg., Manoj suggested suboptimal
event-threads might be one reason and in fact that was a correct
observation (at least for some setups).


> It looks to be the case. I remember following scenarios from various
> users/customers:
>
> * One customer implemented the suggestion of increasing the number of
> event-threads (that read msgs from network) and reported back it fixed
> ping-timer-expiry issues
> * Once Pranith and Krutika identified that an xattrop (basically a
> getxattr and setxattr done atomically holding a global inode lock) took
> more than 42 seconds (default ping timeout value) - identified through
> strace output - ping timer expiries were co-related at around the same
> time. In this case, event-threads were contending on the same lock and
> hence were blocked from reading further messages from network (that
> included ping requests). This issue (of global critical sections) are fixed
> currently.
> * Preventing event-threads from executing any code from glusterfs brick
> stack seem to have solved the issue. This code is present in master and is
> targeted for 3.4.4
> * I've heard reports saying when rebalance/quota heal is in progress ping
> timer expiries are more likely to occur.
>
>> Y.
>>
>> On Mon, Mar 4, 2019, 7:47 PM Raghavendra Gowdappa 
>> wrote:
>>
>>>
>>> +Gluster Devel , +Gluster-users
>>> 
>>>
>>> I would like to point out another issue. Even if what I suggested
>>> prevents disconnects, part of the solution would be only symptomatic
>>> treatment and doesn't address the root cause of the problem. In most of the
>>> ping-timer-expiry issues, the root cause is the increased load on bricks
>>> and the inability of bricks to be responsive under high load. So, the
>>> actual solution would be doing any or both of the following:
>>> * identify the source of increased load and if possible throttle it.
>>> Internal heal processes like self-heal, rebalance, quota heal are known to
>>> pump traffic into bricks without much throttling (io-threads _might_ do
>>> some throttling, but my understanding is its not sufficient).
>>> * identify the reason for bricks to become unresponsive during load.
>>> This may be fixable issues like not enough event-threads to read from
>>> network or difficult to fix issues like fsync on backend fs freezing the
>>> process or semi fixable issues (in code) like lock contention.
>>>
>>> So any genuine effort to fix ping-timer-issues (to be honest most of the
>>> times they are not issues related to rpc/network) would involve performance
>>> characterization of various subsystems on bricks and clients. Various
>>> subsystems can include (but not necessarily limited to), underlying
>>> OS/filesystem, glusterfs processes, CPU consumption etc
>>>
>>> regards,
>>> Raghavendra
>>>
>>> On Mon, Mar 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Raghavendra Gowdappa]

On Thu, Mar 21, 2019 at 4:10 PM Mauro Tridici  wrote:

> Hi Raghavendra,
>
> the number of errors reduced, but during last days I received some error
> notifications from Nagios server similar to the following one:
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> ** Nagios *Notification Type: PROBLEMService: Brick -
> /gluster/mnt5/brickHost: s04Address: s04-stgState: CRITICALDate/Time: Mon
> Mar 18 19:56:36 CET 2019Additional Info:CHECK_NRPE STATE CRITICAL: Socket
> timeout after 10 seconds.*
>
> The error was related only to s04 gluster server.
>
> So, following your suggestions,  I executed, on s04 node, the top command.
> In attachment, you can find the related output.
>

top output doesn't contain cmd/thread names. Was there anything wrong.


> Thank you very much for your help.
> Regards,
> Mauro
>
>
>
> On 14 Mar 2019, at 13:31, Raghavendra Gowdappa 
> wrote:
>
> Thanks Mauro.
>
> On Thu, Mar 14, 2019 at 3:38 PM Mauro Tridici 
> wrote:
>
>> Hi Raghavendra,
>>
>> I just changed the client option value to 8.
>> I will check the volume behaviour during the next hours.
>>
>> The GlusterFS version is 3.12.14.
>>
>> I will provide you the logs as soon as the activity load will be high.
>> Thank you,
>> Mauro
>>
>> On 14 Mar 2019, at 04:57, Raghavendra Gowdappa 
>> wrote:
>>
>>
>>
>> On Wed, Mar 13, 2019 at 3:55 PM Mauro Tridici 
>> wrote:
>>
>>> Hi Raghavendra,
>>>
>>> Yes, server.event-thread has been changed from 4 to 8.
>>>
>>
>> Was client.event-thread value too changed to 8? If not, I would like to
>> know the results of including this tuning too. Also, if possible, can you
>> get the output of following command from problematic clients and bricks
>> (during the duration when load tends to be high and ping-timer-expiry is
>> seen)?
>>
>> # top -bHd 3
>>
>> This will help us to know  CPU utilization of event-threads.
>>
>> And I forgot to ask, what version of Glusterfs are you using?
>>
>> During last days, I noticed that the error events are still here although
>>> they have been considerably reduced.
>>>
>>> So, I used grep command against the log files in order to provide you a
>>> global vision about the warning, error and critical events appeared today
>>> at 06:xx (may be useful I hope).
>>> I collected the info from s06 gluster server, but the behaviour is the
>>> the almost the same on the other gluster servers.
>>>
>>> *ERRORS:  *
>>> *CWD: /var/log/glusterfs *
>>> *COMMAND: grep " E " *.log |grep "2019-03-13 06:"*
>>>
>>> (I can see a lot of this kind of message in the same period but I'm
>>> notifying you only one record for each type of error)
>>>
>>> glusterd.log:[2019-03-13 06:12:35.982863] E [MSGID: 101042]
>>> [compat.c:569:gf_umount_lazy] 0-management: Lazy unmount of
>>> /var/run/gluster/tier2_quota_list/
>>>
>>> glustershd.log:[2019-03-13 06:14:28.666562] E
>>> [rpc-clnt.c:350:saved_frames_unwind] (-->
>>> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4a71ddcebb] (-->
>>> /lib64/libgfr
>>> pc.so.0(saved_frames_unwind+0x1de)[0x7f4a71ba1d9e] (-->
>>> /lib64/libgfrpc.so.0(saved_frames_destroy+0xe)[0x7f4a71ba1ebe] (-->
>>> /lib64/libgfrpc.so.0(rpc_clnt_connection_cleanup
>>> +0x90)[0x7f4a71ba3640] (-->
>>> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x2a0)[0x7f4a71ba4130] )
>>> 0-tier2-client-55: forced unwinding frame type(GlusterFS 3.3)
>>> op(INODELK(29))
>>> called at 2019-03-13 06:14:14.858441 (xid=0x17fddb50)
>>>
>>> glustershd.log:[2019-03-13 06:17:48.883825] E
>>> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
>>> 192.168.0.55:49158 failed (Connection timed out); disco
>>> nnecting socket
>>> glustershd.log:[2019-03-13 06:19:58.931798] E
>>> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
>>> 192.168.0.55:49158 failed (Connection timed out); disco
>>> nnecting socket
>>> glustershd.log:[2019-03-13 06:22:08.979829] E
>>> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
>>> 192.168.0.55:49158 failed (Connection timed out); disco
>>> nnecting socket
>>> glustershd.log:[2019-03-13 06:22:36.226847] E [MSGID: 114031]
>>> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
>>> operation failed [Transport endpoint
>>> is not connected]
>>> glustershd.log:[2019-03-13 06:22:36.306669] E [MSGID: 114031]
>>> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
>>> operation failed [Transport endpoint
>>> is not connected]
>>> glustershd.log:[2019-03-13 06:22:36.385257] E [MSGID: 114031]
>>> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
>>> operation failed [Transport endpoint
>>> is not connected]
>>>
>>> *WARNINGS:*
>>> *CWD: /var/log/glusterfs *
>>> *COMMAND: grep " W " *.log |grep "2019-03-13 06:"*
>>>
>>> (I can see a lot of this kind of message in the same period but I'm
>>> notifying you only one record for each type of warnings)
>>>
>>> glustershd.log:[2019-03-13 06:14:28.666772] W [MSGID: 114031]
>>> [client-rpc-fops.c:1080:client3_3_getxattr_cbk] 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Mauro Tridici]

Hi Raghavendra,

Yes, server.event-thread has been changed from 4 to 8.
During last days, I noticed that the error events are still here although they 
have been considerably reduced.

So, I used grep command against the log files in order to provide you a global 
vision about the warning, error and critical events appeared today at 06:xx 
(may be useful I hope).
I collected the info from s06 gluster server, but the behaviour is the the 
almost the same on the other gluster servers.

ERRORS:  
CWD: /var/log/glusterfs 
COMMAND: grep " E " *.log |grep "2019-03-13 06:"

(I can see a lot of this kind of message in the same period but I'm notifying 
you only one record for each type of error)

glusterd.log:[2019-03-13 06:12:35.982863] E [MSGID: 101042] 
[compat.c:569:gf_umount_lazy] 0-management: Lazy unmount of 
/var/run/gluster/tier2_quota_list/

glustershd.log:[2019-03-13 06:14:28.666562] E 
[rpc-clnt.c:350:saved_frames_unwind] (--> 
/lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4a71ddcebb] (--> 
/lib64/libgfr
pc.so.0(saved_frames_unwind+0x1de)[0x7f4a71ba1d9e] (--> 
/lib64/libgfrpc.so.0(saved_frames_destroy+0xe)[0x7f4a71ba1ebe] (--> 
/lib64/libgfrpc.so.0(rpc_clnt_connection_cleanup
+0x90)[0x7f4a71ba3640] (--> 
/lib64/libgfrpc.so.0(rpc_clnt_notify+0x2a0)[0x7f4a71ba4130] ) 
0-tier2-client-55: forced unwinding frame type(GlusterFS 3.3) op(INODELK(29)) 
called at 2019-03-13 06:14:14.858441 (xid=0x17fddb50) 

glustershd.log:[2019-03-13 06:17:48.883825] E 
[socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to 
192.168.0.55:49158 failed (Connection timed out); disco
nnecting socket
glustershd.log:[2019-03-13 06:19:58.931798] E 
[socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to 
192.168.0.55:49158 failed (Connection timed out); disco
nnecting socket
glustershd.log:[2019-03-13 06:22:08.979829] E 
[socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to 
192.168.0.55:49158 failed (Connection timed out); disco
nnecting socket
glustershd.log:[2019-03-13 06:22:36.226847] E [MSGID: 114031] 
[client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote 
operation failed [Transport endpoint 
is not connected]
glustershd.log:[2019-03-13 06:22:36.306669] E [MSGID: 114031] 
[client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote 
operation failed [Transport endpoint 
is not connected]
glustershd.log:[2019-03-13 06:22:36.385257] E [MSGID: 114031] 
[client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote 
operation failed [Transport endpoint 
is not connected]

WARNINGS:
CWD: /var/log/glusterfs 
COMMAND: grep " W " *.log |grep "2019-03-13 06:"

(I can see a lot of this kind of message in the same period but I'm notifying 
you only one record for each type of warnings)

glustershd.log:[2019-03-13 06:14:28.666772] W [MSGID: 114031] 
[client-rpc-fops.c:1080:client3_3_getxattr_cbk] 0-tier2-client-55: remote 
operation failed. Path:  (b6b35d0f-f34d-4c25-bbe8-74bde0248d7e). Key: 
(null) [Transport endpoint is not connected]

glustershd.log:[2019-03-13 06:14:31.421576] W [MSGID: 122035] 
[ec-common.c:571:ec_child_select] 0-tier2-disperse-9: Executing operation with 
some subvolumes unavailable (2)

glustershd.log:[2019-03-13 06:15:31.547417] W [MSGID: 122032] 
[ec-heald.c:266:ec_shd_index_sweep] 0-tier2-disperse-9: unable to get index-dir 
on tier2-client-55 [Operation 
now in progress]

quota-mount-tier2.log:[2019-03-13 06:12:36.116277] W [MSGID: 101002] 
[options.c:995:xl_opt_validate] 0-glusterfs: option 'address-family' is 
deprecated, preferred is 'trans
port.address-family', continuing with correction
quota-mount-tier2.log:[2019-03-13 06:12:36.198430] W [MSGID: 101174] 
[graph.c:363:_log_if_unknown_option] 0-tier2-readdir-ahead: option 
'parallel-readdir' is not recognized
quota-mount-tier2.log:[2019-03-13 06:12:37.945007] W 
[glusterfsd.c:1375:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x7e25) 
[0x7f340892be25] -->/usr/sbin/glusterfs(gluste
rfs_sigwaiter+0xe5) [0x55ef010164b5] 
-->/usr/sbin/glusterfs(cleanup_and_exit+0x6b) [0x55ef0101632b] ) 0-: received 
signum (15), shutting down

CRITICALS:
CWD: /var/log/glusterfs 
COMMAND: grep " C " *.log |grep "2019-03-13 06:"

no critical errors at 06:xx
only one critical error during the day

[root@s06 glusterfs]# grep " C " *.log |grep "2019-03-13"
glustershd.log:[2019-03-13 02:21:29.126279] C 
[rpc-clnt-ping.c:166:rpc_clnt_ping_timer_expired] 0-tier2-client-55: server 
192.168.0.55:49158 has not responded in the last 42 seconds, disconnecting.


Thank you very much for your help.
Regards,
Mauro

> On 12 Mar 2019, at 05:17, Raghavendra Gowdappa  wrote:
> 
> Was the suggestion to increase server.event-thread values tried? If yes, what 
> were the results?
> 
> On Mon, Mar 11, 2019 at 2:40 PM Mauro Tridici  > wrote:
> Dear All,
> 
> do you have any suggestions about the right way to "debug" this issue?
> In attachment, the updated logs of “s06" 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Mauro Tridici]

Hi Raghavendra,

I just changed the client option value to 8.
I will check the volume behaviour during the next hours.

The GlusterFS version is 3.12.14.

I will provide you the logs as soon as the activity load will be high.
Thank you,
Mauro

> On 14 Mar 2019, at 04:57, Raghavendra Gowdappa  wrote:
> 
> 
> 
> On Wed, Mar 13, 2019 at 3:55 PM Mauro Tridici  > wrote:
> Hi Raghavendra,
> 
> Yes, server.event-thread has been changed from 4 to 8.
> 
> Was client.event-thread value too changed to 8? If not, I would like to know 
> the results of including this tuning too. Also, if possible, can you get the 
> output of following command from problematic clients and bricks (during the 
> duration when load tends to be high and ping-timer-expiry is seen)?
> 
> # top -bHd 3
>  
> This will help us to know  CPU utilization of event-threads.
> 
> And I forgot to ask, what version of Glusterfs are you using?
> 
> During last days, I noticed that the error events are still here although 
> they have been considerably reduced.
> 
> So, I used grep command against the log files in order to provide you a 
> global vision about the warning, error and critical events appeared today at 
> 06:xx (may be useful I hope).
> I collected the info from s06 gluster server, but the behaviour is the the 
> almost the same on the other gluster servers.
> 
> ERRORS:  
> CWD: /var/log/glusterfs 
> COMMAND: grep " E " *.log |grep "2019-03-13 06:"
> 
> (I can see a lot of this kind of message in the same period but I'm notifying 
> you only one record for each type of error)
> 
> glusterd.log:[2019-03-13 06:12:35.982863] E [MSGID: 101042] 
> [compat.c:569:gf_umount_lazy] 0-management: Lazy unmount of 
> /var/run/gluster/tier2_quota_list/
> 
> glustershd.log:[2019-03-13 06:14:28.666562] E 
> [rpc-clnt.c:350:saved_frames_unwind] (--> 
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4a71ddcebb] (--> 
> /lib64/libgfr
> pc.so.0(saved_frames_unwind+0x1de)[0x7f4a71ba1d9e] (--> 
> /lib64/libgfrpc.so.0(saved_frames_destroy+0xe)[0x7f4a71ba1ebe] (--> 
> /lib64/libgfrpc.so.0(rpc_clnt_connection_cleanup
> +0x90)[0x7f4a71ba3640] (--> 
> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x2a0)[0x7f4a71ba4130] ) 
> 0-tier2-client-55: forced unwinding frame type(GlusterFS 3.3) op(INODELK(29)) 
> called at 2019-03-13 06:14:14.858441 (xid=0x17fddb50) 
> 
> glustershd.log:[2019-03-13 06:17:48.883825] E 
> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to 
> 192.168.0.55:49158  failed (Connection timed 
> out); disco
> nnecting socket
> glustershd.log:[2019-03-13 06:19:58.931798] E 
> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to 
> 192.168.0.55:49158  failed (Connection timed 
> out); disco
> nnecting socket
> glustershd.log:[2019-03-13 06:22:08.979829] E 
> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to 
> 192.168.0.55:49158  failed (Connection timed 
> out); disco
> nnecting socket
> glustershd.log:[2019-03-13 06:22:36.226847] E [MSGID: 114031] 
> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote 
> operation failed [Transport endpoint 
> is not connected]
> glustershd.log:[2019-03-13 06:22:36.306669] E [MSGID: 114031] 
> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote 
> operation failed [Transport endpoint 
> is not connected]
> glustershd.log:[2019-03-13 06:22:36.385257] E [MSGID: 114031] 
> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote 
> operation failed [Transport endpoint 
> is not connected]
> 
> WARNINGS:
> CWD: /var/log/glusterfs 
> COMMAND: grep " W " *.log |grep "2019-03-13 06:"
> 
> (I can see a lot of this kind of message in the same period but I'm notifying 
> you only one record for each type of warnings)
> 
> glustershd.log:[2019-03-13 06:14:28.666772] W [MSGID: 114031] 
> [client-rpc-fops.c:1080:client3_3_getxattr_cbk] 0-tier2-client-55: remote 
> operation failed. Path:  0f-f34d-4c25-bbe8-74bde0248d7e> (b6b35d0f-f34d-4c25-bbe8-74bde0248d7e). Key: 
> (null) [Transport endpoint is not connected]
> 
> glustershd.log:[2019-03-13 06:14:31.421576] W [MSGID: 122035] 
> [ec-common.c:571:ec_child_select] 0-tier2-disperse-9: Executing operation 
> with some subvolumes unavailable (2)
> 
> glustershd.log:[2019-03-13 06:15:31.547417] W [MSGID: 122032] 
> [ec-heald.c:266:ec_shd_index_sweep] 0-tier2-disperse-9: unable to get 
> index-dir on tier2-client-55 [Operation 
> now in progress]
> 
> quota-mount-tier2.log:[2019-03-13 06:12:36.116277] W [MSGID: 101002] 
> [options.c:995:xl_opt_validate] 0-glusterfs: option 'address-family' is 
> deprecated, preferred is 'trans
> port.address-family', continuing with correction
> quota-mount-tier2.log:[2019-03-13 06:12:36.198430] W [MSGID: 101174] 
> [graph.c:363:_log_if_unknown_option] 0-tier2-readdir-ahead: option 
> 'parallel-readdir' is not recognized
> 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Raghavendra Gowdappa]

Thanks Mauro.

On Thu, Mar 14, 2019 at 3:38 PM Mauro Tridici  wrote:

> Hi Raghavendra,
>
> I just changed the client option value to 8.
> I will check the volume behaviour during the next hours.
>
> The GlusterFS version is 3.12.14.
>
> I will provide you the logs as soon as the activity load will be high.
> Thank you,
> Mauro
>
> On 14 Mar 2019, at 04:57, Raghavendra Gowdappa 
> wrote:
>
>
>
> On Wed, Mar 13, 2019 at 3:55 PM Mauro Tridici 
> wrote:
>
>> Hi Raghavendra,
>>
>> Yes, server.event-thread has been changed from 4 to 8.
>>
>
> Was client.event-thread value too changed to 8? If not, I would like to
> know the results of including this tuning too. Also, if possible, can you
> get the output of following command from problematic clients and bricks
> (during the duration when load tends to be high and ping-timer-expiry is
> seen)?
>
> # top -bHd 3
>
> This will help us to know  CPU utilization of event-threads.
>
> And I forgot to ask, what version of Glusterfs are you using?
>
> During last days, I noticed that the error events are still here although
>> they have been considerably reduced.
>>
>> So, I used grep command against the log files in order to provide you a
>> global vision about the warning, error and critical events appeared today
>> at 06:xx (may be useful I hope).
>> I collected the info from s06 gluster server, but the behaviour is the
>> the almost the same on the other gluster servers.
>>
>> *ERRORS:  *
>> *CWD: /var/log/glusterfs *
>> *COMMAND: grep " E " *.log |grep "2019-03-13 06:"*
>>
>> (I can see a lot of this kind of message in the same period but I'm
>> notifying you only one record for each type of error)
>>
>> glusterd.log:[2019-03-13 06:12:35.982863] E [MSGID: 101042]
>> [compat.c:569:gf_umount_lazy] 0-management: Lazy unmount of
>> /var/run/gluster/tier2_quota_list/
>>
>> glustershd.log:[2019-03-13 06:14:28.666562] E
>> [rpc-clnt.c:350:saved_frames_unwind] (-->
>> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4a71ddcebb] (-->
>> /lib64/libgfr
>> pc.so.0(saved_frames_unwind+0x1de)[0x7f4a71ba1d9e] (-->
>> /lib64/libgfrpc.so.0(saved_frames_destroy+0xe)[0x7f4a71ba1ebe] (-->
>> /lib64/libgfrpc.so.0(rpc_clnt_connection_cleanup
>> +0x90)[0x7f4a71ba3640] (-->
>> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x2a0)[0x7f4a71ba4130] )
>> 0-tier2-client-55: forced unwinding frame type(GlusterFS 3.3)
>> op(INODELK(29))
>> called at 2019-03-13 06:14:14.858441 (xid=0x17fddb50)
>>
>> glustershd.log:[2019-03-13 06:17:48.883825] E
>> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
>> 192.168.0.55:49158 failed (Connection timed out); disco
>> nnecting socket
>> glustershd.log:[2019-03-13 06:19:58.931798] E
>> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
>> 192.168.0.55:49158 failed (Connection timed out); disco
>> nnecting socket
>> glustershd.log:[2019-03-13 06:22:08.979829] E
>> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
>> 192.168.0.55:49158 failed (Connection timed out); disco
>> nnecting socket
>> glustershd.log:[2019-03-13 06:22:36.226847] E [MSGID: 114031]
>> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
>> operation failed [Transport endpoint
>> is not connected]
>> glustershd.log:[2019-03-13 06:22:36.306669] E [MSGID: 114031]
>> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
>> operation failed [Transport endpoint
>> is not connected]
>> glustershd.log:[2019-03-13 06:22:36.385257] E [MSGID: 114031]
>> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
>> operation failed [Transport endpoint
>> is not connected]
>>
>> *WARNINGS:*
>> *CWD: /var/log/glusterfs *
>> *COMMAND: grep " W " *.log |grep "2019-03-13 06:"*
>>
>> (I can see a lot of this kind of message in the same period but I'm
>> notifying you only one record for each type of warnings)
>>
>> glustershd.log:[2019-03-13 06:14:28.666772] W [MSGID: 114031]
>> [client-rpc-fops.c:1080:client3_3_getxattr_cbk] 0-tier2-client-55: remote
>> operation failed. Path: > 0f-f34d-4c25-bbe8-74bde0248d7e> (b6b35d0f-f34d-4c25-bbe8-74bde0248d7e).
>> Key: (null) [Transport endpoint is not connected]
>>
>> glustershd.log:[2019-03-13 06:14:31.421576] W [MSGID: 122035]
>> [ec-common.c:571:ec_child_select] 0-tier2-disperse-9: Executing operation
>> with some subvolumes unavailable (2)
>>
>> glustershd.log:[2019-03-13 06:15:31.547417] W [MSGID: 122032]
>> [ec-heald.c:266:ec_shd_index_sweep] 0-tier2-disperse-9: unable to get
>> index-dir on tier2-client-55 [Operation
>> now in progress]
>>
>> quota-mount-tier2.log:[2019-03-13 06:12:36.116277] W [MSGID: 101002]
>> [options.c:995:xl_opt_validate] 0-glusterfs: option 'address-family' is
>> deprecated, preferred is 'trans
>> port.address-family', continuing with correction
>> quota-mount-tier2.log:[2019-03-13 06:12:36.198430] W [MSGID: 101174]
>> [graph.c:363:_log_if_unknown_option] 0-tier2-readdir-ahead: option
>> 'parallel-readdir' is not 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Raghavendra Gowdappa]

On Wed, Mar 13, 2019 at 3:55 PM Mauro Tridici  wrote:

> Hi Raghavendra,
>
> Yes, server.event-thread has been changed from 4 to 8.
>

Was client.event-thread value too changed to 8? If not, I would like to
know the results of including this tuning too. Also, if possible, can you
get the output of following command from problematic clients and bricks
(during the duration when load tends to be high and ping-timer-expiry is
seen)?

# top -bHd 3

This will help us to know  CPU utilization of event-threads.

And I forgot to ask, what version of Glusterfs are you using?

During last days, I noticed that the error events are still here although
> they have been considerably reduced.
>
> So, I used grep command against the log files in order to provide you a
> global vision about the warning, error and critical events appeared today
> at 06:xx (may be useful I hope).
> I collected the info from s06 gluster server, but the behaviour is the the
> almost the same on the other gluster servers.
>
> *ERRORS:  *
> *CWD: /var/log/glusterfs *
> *COMMAND: grep " E " *.log |grep "2019-03-13 06:"*
>
> (I can see a lot of this kind of message in the same period but I'm
> notifying you only one record for each type of error)
>
> glusterd.log:[2019-03-13 06:12:35.982863] E [MSGID: 101042]
> [compat.c:569:gf_umount_lazy] 0-management: Lazy unmount of
> /var/run/gluster/tier2_quota_list/
>
> glustershd.log:[2019-03-13 06:14:28.666562] E
> [rpc-clnt.c:350:saved_frames_unwind] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4a71ddcebb] (-->
> /lib64/libgfr
> pc.so.0(saved_frames_unwind+0x1de)[0x7f4a71ba1d9e] (-->
> /lib64/libgfrpc.so.0(saved_frames_destroy+0xe)[0x7f4a71ba1ebe] (-->
> /lib64/libgfrpc.so.0(rpc_clnt_connection_cleanup
> +0x90)[0x7f4a71ba3640] (-->
> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x2a0)[0x7f4a71ba4130] )
> 0-tier2-client-55: forced unwinding frame type(GlusterFS 3.3)
> op(INODELK(29))
> called at 2019-03-13 06:14:14.858441 (xid=0x17fddb50)
>
> glustershd.log:[2019-03-13 06:17:48.883825] E
> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
> 192.168.0.55:49158 failed (Connection timed out); disco
> nnecting socket
> glustershd.log:[2019-03-13 06:19:58.931798] E
> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
> 192.168.0.55:49158 failed (Connection timed out); disco
> nnecting socket
> glustershd.log:[2019-03-13 06:22:08.979829] E
> [socket.c:2376:socket_connect_finish] 0-tier2-client-55: connection to
> 192.168.0.55:49158 failed (Connection timed out); disco
> nnecting socket
> glustershd.log:[2019-03-13 06:22:36.226847] E [MSGID: 114031]
> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
> operation failed [Transport endpoint
> is not connected]
> glustershd.log:[2019-03-13 06:22:36.306669] E [MSGID: 114031]
> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
> operation failed [Transport endpoint
> is not connected]
> glustershd.log:[2019-03-13 06:22:36.385257] E [MSGID: 114031]
> [client-rpc-fops.c:1508:client3_3_inodelk_cbk] 0-tier2-client-55: remote
> operation failed [Transport endpoint
> is not connected]
>
> *WARNINGS:*
> *CWD: /var/log/glusterfs *
> *COMMAND: grep " W " *.log |grep "2019-03-13 06:"*
>
> (I can see a lot of this kind of message in the same period but I'm
> notifying you only one record for each type of warnings)
>
> glustershd.log:[2019-03-13 06:14:28.666772] W [MSGID: 114031]
> [client-rpc-fops.c:1080:client3_3_getxattr_cbk] 0-tier2-client-55: remote
> operation failed. Path:  0f-f34d-4c25-bbe8-74bde0248d7e> (b6b35d0f-f34d-4c25-bbe8-74bde0248d7e).
> Key: (null) [Transport endpoint is not connected]
>
> glustershd.log:[2019-03-13 06:14:31.421576] W [MSGID: 122035]
> [ec-common.c:571:ec_child_select] 0-tier2-disperse-9: Executing operation
> with some subvolumes unavailable (2)
>
> glustershd.log:[2019-03-13 06:15:31.547417] W [MSGID: 122032]
> [ec-heald.c:266:ec_shd_index_sweep] 0-tier2-disperse-9: unable to get
> index-dir on tier2-client-55 [Operation
> now in progress]
>
> quota-mount-tier2.log:[2019-03-13 06:12:36.116277] W [MSGID: 101002]
> [options.c:995:xl_opt_validate] 0-glusterfs: option 'address-family' is
> deprecated, preferred is 'trans
> port.address-family', continuing with correction
> quota-mount-tier2.log:[2019-03-13 06:12:36.198430] W [MSGID: 101174]
> [graph.c:363:_log_if_unknown_option] 0-tier2-readdir-ahead: option
> 'parallel-readdir' is not recognized
> quota-mount-tier2.log:[2019-03-13 06:12:37.945007] W
> [glusterfsd.c:1375:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x7e25)
> [0x7f340892be25] -->/usr/sbin/glusterfs(gluste
> rfs_sigwaiter+0xe5) [0x55ef010164b5]
> -->/usr/sbin/glusterfs(cleanup_and_exit+0x6b) [0x55ef0101632b] ) 0-:
> received signum (15), shutting down
>
> *CRITICALS:*
> *CWD: /var/log/glusterfs *
> *COMMAND: grep " C " *.log |grep "2019-03-13 06:"*
>
> no critical errors at 06:xx
> only one critical error during the day
>
> *[root@s06 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Raghavendra Gowdappa]

Was the suggestion to increase server.event-thread values tried? If yes,
what were the results?

On Mon, Mar 11, 2019 at 2:40 PM Mauro Tridici  wrote:

> Dear All,
>
> do you have any suggestions about the right way to "debug" this issue?
> In attachment, the updated logs of “s06" gluster server.
>
> I noticed a lot of intermittent warning and error messages.
>
> Thank you in advance,
> Mauro
>
>
>
> On 4 Mar 2019, at 18:45, Raghavendra Gowdappa  wrote:
>
>
> +Gluster Devel , +Gluster-users
> 
>
> I would like to point out another issue. Even if what I suggested prevents
> disconnects, part of the solution would be only symptomatic treatment and
> doesn't address the root cause of the problem. In most of the
> ping-timer-expiry issues, the root cause is the increased load on bricks
> and the inability of bricks to be responsive under high load. So, the
> actual solution would be doing any or both of the following:
> * identify the source of increased load and if possible throttle it.
> Internal heal processes like self-heal, rebalance, quota heal are known to
> pump traffic into bricks without much throttling (io-threads _might_ do
> some throttling, but my understanding is its not sufficient).
> * identify the reason for bricks to become unresponsive during load. This
> may be fixable issues like not enough event-threads to read from network or
> difficult to fix issues like fsync on backend fs freezing the process or
> semi fixable issues (in code) like lock contention.
>
> So any genuine effort to fix ping-timer-issues (to be honest most of the
> times they are not issues related to rpc/network) would involve performance
> characterization of various subsystems on bricks and clients. Various
> subsystems can include (but not necessarily limited to), underlying
> OS/filesystem, glusterfs processes, CPU consumption etc
>
> regards,
> Raghavendra
>
> On Mon, Mar 4, 2019 at 9:31 PM Mauro Tridici 
> wrote:
>
>> Thank you, let’s try!
>> I will inform you about the effects of the change.
>>
>> Regards,
>> Mauro
>>
>> On 4 Mar 2019, at 16:55, Raghavendra Gowdappa 
>> wrote:
>>
>>
>>
>> On Mon, Mar 4, 2019 at 8:54 PM Mauro Tridici 
>> wrote:
>>
>>> Hi Raghavendra,
>>>
>>> thank you for your reply.
>>> Yes, you are right. It is a problem that seems to happen randomly.
>>> At this moment, server.event-threads value is 4. I will try to increase
>>> this value to 8. Do you think that it could be a valid value ?
>>>
>>
>> Yes. We can try with that. You should see at least frequency of
>> ping-timer related disconnects  reduce with this value (even if it doesn't
>> eliminate the problem completely).
>>
>>
>>> Regards,
>>> Mauro
>>>
>>>
>>> On 4 Mar 2019, at 15:36, Raghavendra Gowdappa 
>>> wrote:
>>>
>>>
>>>
>>> On Mon, Mar 4, 2019 at 8:01 PM Nithya Balachandran 
>>> wrote:
>>>
 Hi Mauro,

 It looks like some problem on s06. Are all your other nodes ok? Can you
 send us the gluster logs from this node?

 @Raghavendra G  , do you have any idea as to
 how this can be debugged? Maybe running top ? Or debug brick logs?

>>>
>>> If we can reproduce the problem, collecting tcpdump on both ends of
>>> connection will help. But, one common problem is these bugs are
>>> inconsistently reproducible and hence we may not be able to capture tcpdump
>>> at correct intervals. Other than that, we can try to collect some evidence
>>> that poller threads were busy (waiting on locks). But, not sure what debug
>>> data provides that information.
>>>
>>> From what I know, its difficult to collect evidence for this issue and
>>> we could only reason about it.
>>>
>>> We can try a workaround though - try increasing server.event-threads and
>>> see whether ping-timer expiry issues go away with an optimal value. If
>>> that's the case, it kind of provides proof for our hypothesis.
>>>
>>>

 Regards,
 Nithya

 On Mon, 4 Mar 2019 at 15:25, Mauro Tridici 
 wrote:

> Hi All,
>
> some minutes ago I received this message from NAGIOS server
>
>
>
>
>
>
>
>
>
>
>
>
>
> ** Nagios *Notification Type: PROBLEMService: Brick -
> /gluster/mnt2/brickHost: s06Address: s06-stgState: CRITICALDate/Time: Mon
> Mar 4 10:25:33 CET 2019Additional Info:CHECK_NRPE STATE CRITICAL: Socket
> timeout after 10 seconds.*
>
> I checked the network, RAM and CPUs usage on s06 node and everything
> seems to be ok.
> No bricks are in error state. In /var/log/messages, I detected again a
> crash of “check_vol_utili” that I think it is a module used by NRPE
> executable (that is the NAGIOS client).
>
> Mar  4 10:15:29 s06 kernel: traps: check_vol_utili[161224] general
> protection ip:7facffa0a66d sp:7ffe9f4e6fc0 error:0 in
> libglusterfs.so.0.0.1[7facff9b7000+f7000]
> Mar  4 10:15:29 s06 abrt-hook-ccpp: Process 161224 (python2.7) of user
> 0 killed by SIGSEGV - dumping core
> Mar  4 

Re: [Gluster-devel] [Gluster-users] "rpc_clnt_ping_timer_expired" errors

[Raghavendra Gowdappa]

+Gluster Devel , +Gluster-users


I would like to point out another issue. Even if what I suggested prevents
disconnects, part of the solution would be only symptomatic treatment and
doesn't address the root cause of the problem. In most of the
ping-timer-expiry issues, the root cause is the increased load on bricks
and the inability of bricks to be responsive under high load. So, the
actual solution would be doing any or both of the following:
* identify the source of increased load and if possible throttle it.
Internal heal processes like self-heal, rebalance, quota heal are known to
pump traffic into bricks without much throttling (io-threads _might_ do
some throttling, but my understanding is its not sufficient).
* identify the reason for bricks to become unresponsive during load. This
may be fixable issues like not enough event-threads to read from network or
difficult to fix issues like fsync on backend fs freezing the process or
semi fixable issues (in code) like lock contention.

So any genuine effort to fix ping-timer-issues (to be honest most of the
times they are not issues related to rpc/network) would involve performance
characterization of various subsystems on bricks and clients. Various
subsystems can include (but not necessarily limited to), underlying
OS/filesystem, glusterfs processes, CPU consumption etc

regards,
Raghavendra

On Mon, Mar 4, 2019 at 9:31 PM Mauro Tridici  wrote:

> Thank you, let’s try!
> I will inform you about the effects of the change.
>
> Regards,
> Mauro
>
> On 4 Mar 2019, at 16:55, Raghavendra Gowdappa  wrote:
>
>
>
> On Mon, Mar 4, 2019 at 8:54 PM Mauro Tridici 
> wrote:
>
>> Hi Raghavendra,
>>
>> thank you for your reply.
>> Yes, you are right. It is a problem that seems to happen randomly.
>> At this moment, server.event-threads value is 4. I will try to increase
>> this value to 8. Do you think that it could be a valid value ?
>>
>
> Yes. We can try with that. You should see at least frequency of ping-timer
> related disconnects  reduce with this value (even if it doesn't eliminate
> the problem completely).
>
>
>> Regards,
>> Mauro
>>
>>
>> On 4 Mar 2019, at 15:36, Raghavendra Gowdappa 
>> wrote:
>>
>>
>>
>> On Mon, Mar 4, 2019 at 8:01 PM Nithya Balachandran 
>> wrote:
>>
>>> Hi Mauro,
>>>
>>> It looks like some problem on s06. Are all your other nodes ok? Can you
>>> send us the gluster logs from this node?
>>>
>>> @Raghavendra G  , do you have any idea as to
>>> how this can be debugged? Maybe running top ? Or debug brick logs?
>>>
>>
>> If we can reproduce the problem, collecting tcpdump on both ends of
>> connection will help. But, one common problem is these bugs are
>> inconsistently reproducible and hence we may not be able to capture tcpdump
>> at correct intervals. Other than that, we can try to collect some evidence
>> that poller threads were busy (waiting on locks). But, not sure what debug
>> data provides that information.
>>
>> From what I know, its difficult to collect evidence for this issue and we
>> could only reason about it.
>>
>> We can try a workaround though - try increasing server.event-threads and
>> see whether ping-timer expiry issues go away with an optimal value. If
>> that's the case, it kind of provides proof for our hypothesis.
>>
>>
>>>
>>> Regards,
>>> Nithya
>>>
>>> On Mon, 4 Mar 2019 at 15:25, Mauro Tridici 
>>> wrote:
>>>
 Hi All,

 some minutes ago I received this message from NAGIOS server













 ** Nagios *Notification Type: PROBLEMService: Brick -
 /gluster/mnt2/brickHost: s06Address: s06-stgState: CRITICALDate/Time: Mon
 Mar 4 10:25:33 CET 2019Additional Info:CHECK_NRPE STATE CRITICAL: Socket
 timeout after 10 seconds.*

 I checked the network, RAM and CPUs usage on s06 node and everything
 seems to be ok.
 No bricks are in error state. In /var/log/messages, I detected again a
 crash of “check_vol_utili” that I think it is a module used by NRPE
 executable (that is the NAGIOS client).

 Mar  4 10:15:29 s06 kernel: traps: check_vol_utili[161224] general
 protection ip:7facffa0a66d sp:7ffe9f4e6fc0 error:0 in
 libglusterfs.so.0.0.1[7facff9b7000+f7000]
 Mar  4 10:15:29 s06 abrt-hook-ccpp: Process 161224 (python2.7) of user
 0 killed by SIGSEGV - dumping core
 Mar  4 10:15:29 s06 abrt-server: Generating core_backtrace
 Mar  4 10:15:29 s06 abrt-server: Error: Unable to open './coredump': No
 such file or directory
 Mar  4 10:16:01 s06 systemd: Created slice User Slice of root.
 Mar  4 10:16:01 s06 systemd: Starting User Slice of root.
 Mar  4 10:16:01 s06 systemd: Started Session 201010 of user root.
 Mar  4 10:16:01 s06 systemd: Starting Session 201010 of user root.
 Mar  4 10:16:01 s06 systemd: Removed slice User Slice of root.
 Mar  4 10:16:01 s06 systemd: Stopping User Slice of root.
 Mar  4 10:16:24 s06 abrt-server: Duplicate: UUID