rpc_check_timeout: nnnn callbacks suppressed

3rensho · 12-09-2019, 02:06 AM

Since building the 5.4.2 kernel on my slack64-current machine (KDE5) I have started getting these types of messages in my syslog -

Code:

Dec  8 09:09:47 missi kernel: [14461.599422] call_decode: 193 callbacks suppressed
Dec  8 09:09:52 missi kernel: [14466.494054] rpc_check_timeout: 1221 callbacks suppressed
Dec  8 09:09:52 missi kernel: [14466.619893] call_decode: 208 callbacks suppressed
Dec  8 09:09:57 missi kernel: [14471.511683] rpc_check_timeout: 1036 callbacks suppressed
Dec  8 09:09:57 missi kernel: [14471.659328] call_decode: 208 callbacks suppressed
Dec  8 09:10:02 missi kernel: [14476.513391] rpc_check_timeout: 1017 callbacks suppressed
Dec  8 09:10:02 missi kernel: [14476.668014] call_decode: 206 callbacks suppressed
Dec  8 09:10:07 missi kernel: [14481.529101] rpc_check_timeout: 940 callbacks suppressed
Dec  8 09:10:07 missi kernel: [14481.669568] call_decode: 191 callbacks suppressed
Dec  8 09:10:12 missi kernel: [14486.537991] rpc_check_timeout: 1017 callbacks suppressed
Dec  8 09:10:12 missi kernel: [14486.672636] call_decode: 206 callbacks suppressed
Dec  8 09:10:17 missi kernel: [14491.560034] rpc_check_timeout: 981 callbacks suppressed
Dec  8 09:10:17 missi kernel: [14491.726285] call_decode: 197 callbacks suppressed
Dec  8 09:10:22 missi kernel: [14496.579264] rpc_check_timeout: 1002 callbacks suppressed
Dec  8 09:10:22 missi kernel: [14496.733256] call_decode: 211 callbacks suppressed
Dec  8 09:10:27 missi kernel: [14501.589953] rpc_check_timeout: 996 callbacks suppressed
Dec  8 09:10:27 missi kernel: [14501.739833] call_decode: 202 callbacks suppressed
Dec  8 09:10:32 missi kernel: [14506.604597] rpc_check_timeout: 1040 callbacks suppressed
Dec  8 09:10:32 missi kernel: [14506.759308] call_decode: 210 callbacks suppressed
Dec  8 09:10:37 missi kernel: [14511.609075] rpc_check_timeout: 1128 callbacks suppressed
Dec  8 09:10:37 missi kernel: [14511.776524] call_decode: 209 callbacks suppressed
Dec  8 09:10:42 missi kernel: [14516.619601] rpc_check_timeout: 1326 callbacks suppressed
Dec  8 09:10:42 missi kernel: [14516.797248] call_decode: 206 callbacks suppressed
Dec  8 09:10:47 missi kernel: [14521.642477] rpc_check_timeout: 1470 callbacks suppressed
Dec  8 09:10:47 missi kernel: [14521.812295] call_decode: 197 callbacks suppressed
Dec  8 09:10:52 missi kernel: [14526.658335] rpc_check_timeout: 1553 callbacks suppressed
Dec  8 09:10:52 missi kernel: [14526.829318] call_decode: 210 callbacks suppressed
Dec  8 09:10:57 missi kernel: [14531.663269] rpc_check_timeout: 1811 callbacks suppressed
Dec  8 09:10:57 missi kernel: [14531.852743] call_decode: 209 callbacks suppressed
Dec  8 09:11:02 missi kernel: [14536.680282] rpc_check_timeout: 2116 callbacks suppressed
Dec  8 09:11:02 missi kernel: [14536.905378] call_decode: 213 callbacks suppressed
Dec  8 09:11:07 missi kernel: [14541.690618] rpc_check_timeout: 2296 callbacks suppressed
Dec  8 09:11:07 missi kernel: [14541.911174] call_decode: 217 callbacks suppressed
Dec  8 09:11:12 missi kernel: [14546.703774] rpc_check_timeout: 3114 callbacks suppressed
Dec  8 09:11:12 missi kernel: [14546.931214] call_decode: 205 callbacks suppressed
Dec  8 09:11:17 missi kernel: [14551.739056] rpc_check_timeout: 6356 callbacks suppressed
Dec  8 09:11:17 missi kernel: [14551.932966] call_decode: 211 callbacks suppressed
Dec  8 09:11:32 missi kernel: [14566.462333] call_decode: 141 callbacks suppressed
Dec  8 09:11:37 missi kernel: [14571.546136] call_decode: 10494 callbacks suppressed

Anyone know what might be causing this behavior? System runs fine but am curious about the messages. Thanks for feedback.

allend · 12-09-2019, 06:49 AM

Maybe messages from rpcdebug.
What is in /proc/sys/sunrpc?

3rensho · 12-09-2019, 10:11 AM

ls -l /proc/sys/sunrpc
total 0
-rw-r--r-- 1 root root 0 Dec 9 15:44 max_resvport
-rw-r--r-- 1 root root 0 Dec 9 15:44 min_resvport
-rw-r--r-- 1 root root 0 Dec 9 15:44 tcp_fin_timeout
-rw-r--r-- 1 root root 0 Dec 9 15:44 tcp_max_slot_table_entries
-rw-r--r-- 1 root root 0 Dec 9 15:44 tcp_slot_

$ rpcdebug -vh

rpc xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache all
nfs vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state all
nfsd sock fh export svc proc fileop auth repcache xdr lockd all
nlm svc client clntlock svclock monitor clntsubs svcsubs hostcache xdr all

From rpcdebug -

$ rpcdebug -m rpc
/proc/sys/sunrpc/rpc_debug: No such file or directory
$ rpcdebug -m nfs
/proc/sys/sunrpc/nfs_debug: No such file or directory
$ rpcdebug -m nfsd
/proc/sys/sunrpc/nfsd_debug: No such file or directory
$ rpcdebug -m nlm
/proc/sys/sunrpc/nlm_debug: No such file or directory

upnort · 12-09-2019, 11:28 AM

A quick check shows the message is from the kernel.

3rensho · 12-10-2019, 01:07 AM

Thanks for that upnort. Since it doesn't seem to be causing any problems that I am aware of I'll ignore it for now.

3rensho · 06-08-2020, 06:46 AM

It's been a while since I looked at this and I decided to have another look now that I've upgraded to the 5.7.1 kernel. The messages now occur only in a very specific time frame. I have a number of backup scripts that kickoff at 0730. Logs are normal until 0909. At 0909 these rpc messages start in the syslog and then end at 0913.

Code:

08.06.20 09:12	missi	kernel	[14490.772011] call_decode: 500 callbacks suppressed
08.06.20 09:12	missi	kernel	[14495.628072] rpc_check_timeout: 1092 callbacks suppressed
08.06.20 09:12	missi	kernel	[14495.782052] call_decode: 494 callbacks suppressed
08.06.20 09:12	missi	kernel	[14500.629255] rpc_check_timeout: 1191 callbacks suppressed
08.06.20 09:12	missi	kernel	[14500.791458] call_decode: 496 callbacks suppressed
08.06.20 09:12	missi	kernel	[14505.631030] rpc_check_timeout: 1373 callbacks suppressed

This is when a backup file is being copied to my QNAP NAS box.

From /var/log/messages

Code:

08.06.20 09:12	missi	kernel	[14520.877451] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.888430] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.899181] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.900053] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.907538] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.915701] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.923510] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.941477] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14520.943622] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14525.647708] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.647836] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.647905] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.654529] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.654600] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.654677] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.662814] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.662887] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.662925] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.672165] nfs: server 192.168.1.215 not responding, still trying
08.06.20 09:12	missi	kernel	[14525.878258] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14525.885413] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14525.888782] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14525.901100] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14525.909659] nfs: server 192.168.1.215 OK
08.06.20 09:12	missi	kernel	[14525.918271] nfs: server 192.168.1.215 OK

and from dmesg

Code:

[14350.467279] nfs: server 192.168.1.215 not responding, still trying
[14350.474742] nfs: server 192.168.1.215 not responding, still trying
[14350.474935] nfs: server 192.168.1.215 not responding, still trying
[14350.491404] nfs: server 192.168.1.215 not responding, still trying
[14350.501197] nfs: server 192.168.1.215 not responding, still trying
[14350.501302] nfs: server 192.168.1.215 not responding, still trying
[14350.510765] nfs: server 192.168.1.215 not responding, still trying
[14350.510902] nfs: server 192.168.1.215 not responding, still trying
[14350.518364] nfs: server 192.168.1.215 not responding, still trying
[14350.528381] nfs: server 192.168.1.215 not responding, still trying
[14350.532504] nfs: server 192.168.1.215 OK
[14350.542949] nfs: server 192.168.1.215 OK
[14350.544495] nfs: server 192.168.1.215 OK
[14350.549937] nfs: server 192.168.1.215 OK
[14350.560516] nfs: server 192.168.1.215 OK
[14350.575270] nfs: server 192.168.1.215 OK
[14350.586009] nfs: server 192.168.1.215 OK
[14350.600828] nfs: server 192.168.1.215 OK
[14350.606340] nfs: server 192.168.1.215 OK

Before 0909 other backup files are copied to the NAS and after 0913 more files are copied without any rpc disturbances. The logs are fine until I shutdown in the evening. The times listed actually vary slightly as the backup files change in size. Will check tomorrow to see exactly what is going on with the other backup jobs at these times.

3rensho · 06-09-2020, 03:08 AM

Well, ran backups today with widely staggered starting times to isolate the problem. Seems that when the system copies gb sized files to my NAS the rpc has a hissy fit for a couple of minutes and it gets logged. Files are copied fine. So, for now just something I'll let slide as I haven't found any negative results from this happening.