Message ID | 4FA345DA4F4AE44899BD2B03EEEC2FA90928DCDD@SACEXCMBX04-PRD.hq.netapp.com (mailing list archive) |
---|---|
State | New, archived |
Headers | show |
On Tue, Oct 23, 2012 at 09:58:35PM +0000, Myklebust, Trond wrote: > The only problem there would be the call to xs_sock_mark_closed() in > xs_abort_connection. As far as I can tell, all we want to do there is > clear all those flags. > > How about the following? Looks good! With all 4 patches applied things recover correctly and I no longer see anything racing. Just to be clear, I took your patches and integrated them into the CentOS 2.6.32-279.5.2.el6.centos.plus kernel. Basically everything was the same except the offsets and perhaps a little of the surrounding context. I do not believe the meaning of the patches was changed at all. If you want me to test your latest git where these commits live, I can, just point me at the git repo url. Thanks for the help! Chris -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
> -----Original Message----- > From: linux-nfs-owner@vger.kernel.org [mailto:linux-nfs- > owner@vger.kernel.org] On Behalf Of Chris Perl > Sent: Wednesday, October 24, 2012 8:41 AM > To: Myklebust, Trond > Cc: linux-nfs@vger.kernel.org > Subject: Re: RPC Race Condition > > On Tue, Oct 23, 2012 at 09:58:35PM +0000, Myklebust, Trond wrote: > > The only problem there would be the call to xs_sock_mark_closed() in > > xs_abort_connection. As far as I can tell, all we want to do there is > > clear all those flags. > > > > How about the following? > > Looks good! With all 4 patches applied things recover correctly and I no > longer see anything racing. > > Just to be clear, I took your patches and integrated them into the CentOS > 2.6.32-279.5.2.el6.centos.plus kernel. Basically everything was the same > except the offsets and perhaps a little of the surrounding context. I do not > believe the meaning of the patches was changed at all. Cool! Would you mind if I add "Tested-by" tags? > If you want me to test your latest git where these commits live, I can, just > point me at the git repo url. Sure. I'll let you know as soon as I push them out later today... Thanks! Trond -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Oct 24, 2012 at 01:04:16PM +0000, Myklebust, Trond wrote: > Cool! Would you mind if I add "Tested-by" tags? Wouldn't mind at all. I've also run several of the filebench [1] workload personalities with this patched kernel for ten minutes a piece (i.e. the `fileserver' and `networkfs' personalities) and experienced no problems. During the tests I also added the blackhole route to the server several times (along with restarting the NFS server) and it recovered each time. I did this for filebench running SCHED_OTHER and SCHED_RR with a priority of 50. > Sure. I'll let you know as soon as I push them out later today... Cool, I'll keep an eye out. Chris [1] http://sourceforge.net/apps/mediawiki/filebench/index.php?title=Filebench -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
> -----Original Message----- > From: Chris Perl [mailto:chris.perl@gmail.com] > Sent: Wednesday, October 24, 2012 10:24 AM > To: Myklebust, Trond > Cc: linux-nfs@vger.kernel.org > Subject: Re: RPC Race Condition > > On Wed, Oct 24, 2012 at 01:04:16PM +0000, Myklebust, Trond wrote: > > Cool! Would you mind if I add "Tested-by" tags? > > Wouldn't mind at all. > > I've also run several of the filebench [1] workload personalities with this > patched kernel for ten minutes a piece (i.e. the `fileserver' and `networkfs' > personalities) and experienced no problems. During the tests I also added > the blackhole route to the server several times (along with restarting the NFS > server) and it recovered each time. I did this for filebench running > SCHED_OTHER and SCHED_RR with a priority of 50. > > > Sure. I'll let you know as soon as I push them out later today... > > Cool, I'll keep an eye out. OK, I've now posted the patches in the "bugfixes" branch of git://git.linux-nfs.org/projects/trondmy/linux-nfs.git By the way, you said that you were using a set of systemtap scripts to debug these races? If you'd be OK sharing those scripts, I'd love to see them. Debugging this kind of race is always difficult... Cheers Trond -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Oct 24, 2012 at 02:56:55PM +0000, Myklebust, Trond wrote: > OK, I've now posted the patches in the "bugfixes" branch of > > git://git.linux-nfs.org/projects/trondmy/linux-nfs.git Cool, I'll try to get that pulled, compiled and tested by the end of the day. > > By the way, you said that you were using a set of systemtap scripts to debug these races? If you'd be OK sharing those scripts, I'd love to see them. Debugging this kind of race is always difficult... > Sure. Attached are a bunch of them. They have very unhelpful names. :) They progressively get more involved. As I watched their output coupled with reading the source code, I found new areas I wanted to explore. The numbered scripts are all aimed at being run with the `-x' flag pointed at the process doing the stat calls, i.e.: # stap 1.stp -x $(pgrep hang.py) The `rpciod.stp' script is just meant to be run without any qualifications to trace the function calls rpciod is making, i.e.: # stap rpciod.stp The script that really allowed me to see the race condition was 14.stp. It produces a lot of output to poke through, but here is basically what its doing: - At the top there are a lot of helper functions. Their basic goals are to translate from numbers to human readable strings. I.e. instead of seeing `xs_tcp_send_request' return 0xffffffffffffffe0, I wanted to see EPIPE. It makes it a lot easier to pour over several pages of output while testing. - Below that there are the actual probes for the functions we want to trace, the gist of which is: - It watches for a call to `__rpc_execute' for the process id we're interested in. Once it fires, we use the address of its task_struct to mark it as being traced via the `trace' array. - This probe also takes the address of the `struct rpc_task' we're currently working with and marks it as being traced via the `task_trace' array. The idea with this is that another one of our probes enables tracing of `rpc_make_runnable' and on entry into that call we make sure we're tracing that task. This way we can catch wake up calls for the task we care about. When we do, we print that fact and a stack backtrace of how we got there. - There are many other functions that I ask to trace, but only if we're tracing the main task via the address of its task_struct being a valid key in the `trace' array. - I do something similiar to tracing calls to `rpc_make_runnable' with sockets. Here we record the `struct sock' address in `xs_tcp_send_request'. In another probe we enable tracing of `tcp_set_state' but only for the `struct sock' that we care about. I'm far from a SystemTap expert, and some of this stuff might not be particularly safe (i.e. if I'm trying to translate tk_runstate to a human readable string while something else is updating it on another CPU). But it all seemed to work "well enough" and give insight into what was actually happening. Here is an example snippet of some of the output produced with 14.stp: -----8<----- 1351091111259227075 [0xffff88060b27d540] 150 hang.py(5560): -> call_transmit: task: tk_status: 0, tk_runstate: RPC_TASK_RUNNING|RPC_TASK_ACTIVE, parms: task=0xffff8806355c9080 1351091111259235702 [0xffff88060b27d540] 159 hang.py(5560): -> xs_tcp_send_request: sock: sock=0xffff880620803140, state: SS_CONNECTING, sk=0xffff880635ded540, sk_state: TCP_ESTABLISHED, sk_err: 0, sk_shutdown: 0, task: tk_status: 0, tk_runstate: RPC_TASK_RUNNING|RPC_TASK_ACTIVE, parms: task=0xffff8806355c9080 1351091111259253562 [0xffff88060b27d540] 177 hang.py(5560): <- xs_tcp_send_request: 0 1351091111259258719 [0xffff88060b27d540] 182 hang.py(5560): -> call_transmit_status: task: tk_status: 0, tk_runstate: RPC_TASK_RUNNING|RPC_TASK_QUEUED|RPC_TASK_ACTIVE, parms: task=0xffff8806355c9080 1351091111259264704 [0xffff88060b27d540] 188 hang.py(5560): <- call_transmit_status: 1351091111259267273 [0xffff88060b27d540] 190 hang.py(5560): <- call_transmit: 1351091111259270415 [0xffff88060b27d540] 193 hang.py(5560): -> out_of_line_wait_on_bit: word: tk_runstate: RPC_TASK_QUEUED|RPC_TASK_ACTIVE, parms: word=0xffff8806355c90f0 bit=0x1 action=0xffffffffa042f930 mode=0x82 1351091111259276940 [0xffff88060b27d540] 200 hang.py(5560): -> rpc_wait_bit_killable: parms: word=0xffff8806355c90f0 1351091117489543178 [0xffff880637daeaa0] swapper -> rpc_make_runnable: task: tk_status: EAGAIN, tk_runstate: RPC_TASK_QUEUED|RPC_TASK_ACTIVE, parms: task=0xffff8806355c9080 0xffffffffa042f840 : rpc_make_runnable+0x0/0x80 [sunrpc] 0xffffffffa042fb5e : rpc_wake_up_task_queue_locked+0x18e/0x270 [sunrpc] 0xffffffffa042fc8e : rpc_wake_up_status+0x4e/0x80 [sunrpc] 0xffffffffa04288ec : xprt_wake_pending_tasks+0x2c/0x30 [sunrpc] 0xffffffffa042b9fd : xs_error_report+0x4d/0x90 [sunrpc] 0xffffffff8148d629 : tcp_reset+0x59/0x70 [kernel] 0xffffffff8148d918 : tcp_validate_incoming+0x2d8/0x3a0 [kernel] 0xffffffff81491006 : tcp_rcv_established+0x2e6/0x800 [kernel] 0xffffffff814990f3 : tcp_v4_do_rcv+0x2e3/0x430 [kernel] 0xffffffff8149a96e : tcp_v4_rcv+0x4fe/0x8d0 [kernel] 0xffffffff8147868d : ip_local_deliver_finish+0xdd/0x2d0 [kernel] 0xffffffff81478918 : ip_local_deliver+0x98/0xa0 [kernel] 0xffffffff81477ddd : ip_rcv_finish+0x12d/0x440 [kernel] 0xffffffff81478365 : ip_rcv+0x275/0x350 [kernel] 0xffffffff81441a5b : __netif_receive_skb+0x49b/0x6f0 [kernel] 0xffffffff81443cd8 : netif_receive_skb+0x58/0x60 [kernel] 0xffffffff81443de0 : napi_skb_finish+0x50/0x70 [kernel] 0xffffffff81446319 : napi_gro_receive+0x39/0x50 [kernel] 0xffffffffa0126f2f [bnx2] 0x0 (inexact) -----8<----- Chris global trace probe module("sunrpc").function("rpc_call_sync").call { if (pid() == target()) { t = task_current() printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), probefunc(), $$parms) trace[t] = 1 } } probe module("sunrpc").function("rpc_call_sync").return { t = task_current() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), $$return) trace[t] = 0 } } probe module("sunrpc").function("*").call { t = task_current() if (trace[t]) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), probefunc(), $$parms) } } probe module("sunrpc").function("*").return { t = task_current() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), $$return) } } # vim: ts=2 sts=2 sw=2 et global trace probe module("sunrpc").function("__rpc_execute").call { t = task_current() if (pid() == target()) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), probefunc(), $$parms) trace[t] = 1 } } probe module("sunrpc").function("__rpc_execute").return { t = task_current() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), $$return) trace[t] = 0 } } global trace probe module("sunrpc").function("__rpc_execute").call { if (pid() == target()) { t = task_current() proc = @cast(&$task->tk_msg, "struct rpc_message")->rpc_proc func = @cast(proc, "struct rpc_procinfo")->p_name serv = @cast($task->tk_client, "struct rpc_clnt")->cl_server func_name = kernel_string(func) serv_name = kernel_string(serv) printf("[0x%x] %s -> %s: %s: proc_name: %s, server: %s\n", t, thread_indent(1), probefunc(), $$parms, func_name, serv_name) trace[t] = 1 } } probe module("sunrpc").function("__rpc_execute").return { t = task_current() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), $$return) trace[t] = 0 } } probe module("sunrpc").function("*").call { t = task_current() if (trace[t]) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), probefunc(), $$parms) } } probe module("sunrpc").function("*").return { t = task_current() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), $$return) } } # vim: ts=2 sts=2 sw=2 et global trace global _errno[134] probe begin { _errno[0] = "0" _errno[1] = "EPERM" _errno[2] = "ENOENT" _errno[3] = "ESRCH" _errno[4] = "EINTR" _errno[5] = "EIO" _errno[6] = "ENXIO" _errno[7] = "E2BIG" _errno[8] = "ENOEXEC" _errno[9] = "EBADF" _errno[10] = "ECHILD" _errno[11] = "EAGAIN" _errno[12] = "ENOMEM" _errno[13] = "EACCES" _errno[14] = "EFAULT" _errno[15] = "ENOTBLK" _errno[16] = "EBUSY" _errno[17] = "EEXIST" _errno[18] = "EXDEV" _errno[19] = "ENODEV" _errno[20] = "ENOTDIR" _errno[21] = "EISDIR" _errno[22] = "EINVAL" _errno[23] = "ENFILE" _errno[24] = "EMFILE" _errno[25] = "ENOTTY" _errno[26] = "ETXTBSY" _errno[27] = "EFBIG" _errno[28] = "ENOSPC" _errno[29] = "ESPIPE" _errno[30] = "EROFS" _errno[31] = "EMLINK" _errno[32] = "EPIPE" _errno[33] = "EDOM" _errno[34] = "ERANGE" _errno[35] = "EDEADLK" _errno[36] = "ENAMETOOLONG" _errno[37] = "ENOLCK" _errno[38] = "ENOSYS" _errno[39] = "ENOTEMPTY" _errno[40] = "ELOOP" _errno[41] = "UNDEF" _errno[42] = "ENOMSG" _errno[43] = "EIDRM" _errno[44] = "ECHRNG" _errno[45] = "EL2NSYNC" _errno[46] = "EL3HLT" _errno[47] = "EL3RST" _errno[48] = "ELNRNG" _errno[49] = "EUNATCH" _errno[50] = "ENOCSI" _errno[51] = "EL2HLT" _errno[52] = "EBADE" _errno[53] = "EBADR" _errno[54] = "EXFULL" _errno[55] = "ENOANO" _errno[56] = "EBADRQC" _errno[57] = "EBADSLT" _errno[58] = "UNDEF" _errno[59] = "EBFONT" _errno[60] = "ENOSTR" _errno[61] = "ENODATA" _errno[62] = "ETIME" _errno[63] = "ENOSR" _errno[64] = "ENONET" _errno[65] = "ENOPKG" _errno[66] = "EREMOTE" _errno[67] = "ENOLINK" _errno[68] = "EADV" _errno[69] = "ESRMNT" _errno[70] = "ECOMM" _errno[71] = "EPROTO" _errno[72] = "EMULTIHOP" _errno[73] = "EDOTDOT" _errno[74] = "EBADMSG" _errno[75] = "EOVERFLOW" _errno[76] = "ENOTUNIQ" _errno[77] = "EBADFD" _errno[78] = "EREMCHG" _errno[79] = "ELIBACC" _errno[80] = "ELIBBAD" _errno[81] = "ELIBSCN" _errno[82] = "ELIBMAX" _errno[83] = "ELIBEXEC" _errno[84] = "EILSEQ" _errno[85] = "ERESTART" _errno[86] = "ESTRPIPE" _errno[87] = "EUSERS" _errno[88] = "ENOTSOCK" _errno[89] = "EDESTADDRREQ" _errno[90] = "EMSGSIZE" _errno[91] = "EPROTOTYPE" _errno[92] = "ENOPROTOOPT" _errno[93] = "EPROTONOSUPPORT" _errno[94] = "ESOCKTNOSUPPORT" _errno[95] = "EOPNOTSUPP" _errno[96] = "EPFNOSUPPORT" _errno[97] = "EAFNOSUPPORT" _errno[98] = "EADDRINUSE" _errno[99] = "EADDRNOTAVAIL" _errno[100] = "ENETDOWN" _errno[101] = "ENETUNREACH" _errno[102] = "ENETRESET" _errno[103] = "ECONNABORTED" _errno[104] = "ECONNRESET" _errno[105] = "ENOBUFS" _errno[106] = "EISCONN" _errno[107] = "ENOTCONN" _errno[108] = "ESHUTDOWN" _errno[109] = "ETOOMANYREFS" _errno[110] = "ETIMEDOUT" _errno[111] = "ECONNREFUSED" _errno[112] = "EHOSTDOWN" _errno[113] = "EHOSTUNREACH" _errno[114] = "EALREADY" _errno[115] = "EINPROGRESS" _errno[116] = "ESTALE" _errno[117] = "EUCLEAN" _errno[118] = "ENOTNAM" _errno[119] = "ENAVAIL" _errno[120] = "EISNAM" _errno[121] = "EREMOTEIO" _errno[122] = "EDQUOT" _errno[123] = "ENOMEDIUM" _errno[124] = "EMEDIUMTYPE" _errno[125] = "ECANCELED" _errno[126] = "ENOKEY" _errno[127] = "EKEYEXPIRED" _errno[128] = "EKEYREVOKED" _errno[129] = "EKEYREJECTED" _errno[130] = "EOWNERDEAD" _errno[131] = "ENOTRECOVERABLE" _errno[132] = "ERFKILL" _errno[133] = "EHWPOISON" } function err_num2str:string (error:long) { error = -error return (error in _errno ? _errno[error] : sprintf("0x%x", -error)) } probe module("sunrpc").function("__rpc_execute").call { if (pid() == target()) { t = task_current() p = probefunc() serv = @cast($task->tk_client, "struct rpc_clnt")->cl_server serv_name = kernel_string(serv) proc = @cast(&$task->tk_msg, "struct rpc_message")->rpc_proc func = @cast(proc, "struct rpc_procinfo")->p_name func_name = kernel_string(func) printf("[0x%x] %s -> %s: func: %s, server: %s, parms: %s\n", t, thread_indent(1), p, func_name, serv_name, $$parms) trace[t] = 1 } } probe module("sunrpc").function("__rpc_execute").return { t = task_current() p = probefunc() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), p, $$return) trace[t] = 0 } } probe module("sunrpc").function("xs_tcp_send_request").call { t = task_current() p = probefunc() if (trace[t]) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), p, $$parms) } } probe module("sunrpc").function("xs_tcp_send_request").return { t = task_current() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), err_num2str($return)) } } # vim: ts=2 sts=2 sw=2 et global trace global _errno[134] probe begin { _errno[0] = "0" _errno[1] = "EPERM" _errno[2] = "ENOENT" _errno[3] = "ESRCH" _errno[4] = "EINTR" _errno[5] = "EIO" _errno[6] = "ENXIO" _errno[7] = "E2BIG" _errno[8] = "ENOEXEC" _errno[9] = "EBADF" _errno[10] = "ECHILD" _errno[11] = "EAGAIN" _errno[12] = "ENOMEM" _errno[13] = "EACCES" _errno[14] = "EFAULT" _errno[15] = "ENOTBLK" _errno[16] = "EBUSY" _errno[17] = "EEXIST" _errno[18] = "EXDEV" _errno[19] = "ENODEV" _errno[20] = "ENOTDIR" _errno[21] = "EISDIR" _errno[22] = "EINVAL" _errno[23] = "ENFILE" _errno[24] = "EMFILE" _errno[25] = "ENOTTY" _errno[26] = "ETXTBSY" _errno[27] = "EFBIG" _errno[28] = "ENOSPC" _errno[29] = "ESPIPE" _errno[30] = "EROFS" _errno[31] = "EMLINK" _errno[32] = "EPIPE" _errno[33] = "EDOM" _errno[34] = "ERANGE" _errno[35] = "EDEADLK" _errno[36] = "ENAMETOOLONG" _errno[37] = "ENOLCK" _errno[38] = "ENOSYS" _errno[39] = "ENOTEMPTY" _errno[40] = "ELOOP" _errno[41] = "UNDEF" _errno[42] = "ENOMSG" _errno[43] = "EIDRM" _errno[44] = "ECHRNG" _errno[45] = "EL2NSYNC" _errno[46] = "EL3HLT" _errno[47] = "EL3RST" _errno[48] = "ELNRNG" _errno[49] = "EUNATCH" _errno[50] = "ENOCSI" _errno[51] = "EL2HLT" _errno[52] = "EBADE" _errno[53] = "EBADR" _errno[54] = "EXFULL" _errno[55] = "ENOANO" _errno[56] = "EBADRQC" _errno[57] = "EBADSLT" _errno[58] = "UNDEF" _errno[59] = "EBFONT" _errno[60] = "ENOSTR" _errno[61] = "ENODATA" _errno[62] = "ETIME" _errno[63] = "ENOSR" _errno[64] = "ENONET" _errno[65] = "ENOPKG" _errno[66] = "EREMOTE" _errno[67] = "ENOLINK" _errno[68] = "EADV" _errno[69] = "ESRMNT" _errno[70] = "ECOMM" _errno[71] = "EPROTO" _errno[72] = "EMULTIHOP" _errno[73] = "EDOTDOT" _errno[74] = "EBADMSG" _errno[75] = "EOVERFLOW" _errno[76] = "ENOTUNIQ" _errno[77] = "EBADFD" _errno[78] = "EREMCHG" _errno[79] = "ELIBACC" _errno[80] = "ELIBBAD" _errno[81] = "ELIBSCN" _errno[82] = "ELIBMAX" _errno[83] = "ELIBEXEC" _errno[84] = "EILSEQ" _errno[85] = "ERESTART" _errno[86] = "ESTRPIPE" _errno[87] = "EUSERS" _errno[88] = "ENOTSOCK" _errno[89] = "EDESTADDRREQ" _errno[90] = "EMSGSIZE" _errno[91] = "EPROTOTYPE" _errno[92] = "ENOPROTOOPT" _errno[93] = "EPROTONOSUPPORT" _errno[94] = "ESOCKTNOSUPPORT" _errno[95] = "EOPNOTSUPP" _errno[96] = "EPFNOSUPPORT" _errno[97] = "EAFNOSUPPORT" _errno[98] = "EADDRINUSE" _errno[99] = "EADDRNOTAVAIL" _errno[100] = "ENETDOWN" _errno[101] = "ENETUNREACH" _errno[102] = "ENETRESET" _errno[103] = "ECONNABORTED" _errno[104] = "ECONNRESET" _errno[105] = "ENOBUFS" _errno[106] = "EISCONN" _errno[107] = "ENOTCONN" _errno[108] = "ESHUTDOWN" _errno[109] = "ETOOMANYREFS" _errno[110] = "ETIMEDOUT" _errno[111] = "ECONNREFUSED" _errno[112] = "EHOSTDOWN" _errno[113] = "EHOSTUNREACH" _errno[114] = "EALREADY" _errno[115] = "EINPROGRESS" _errno[116] = "ESTALE" _errno[117] = "EUCLEAN" _errno[118] = "ENOTNAM" _errno[119] = "ENAVAIL" _errno[120] = "EISNAM" _errno[121] = "EREMOTEIO" _errno[122] = "EDQUOT" _errno[123] = "ENOMEDIUM" _errno[124] = "EMEDIUMTYPE" _errno[125] = "ECANCELED" _errno[126] = "ENOKEY" _errno[127] = "EKEYEXPIRED" _errno[128] = "EKEYREVOKED" _errno[129] = "EKEYREJECTED" _errno[130] = "EOWNERDEAD" _errno[131] = "ENOTRECOVERABLE" _errno[132] = "ERFKILL" _errno[133] = "EHWPOISON" } function err_num2str:string (error:long) { error = -error return (error in _errno ? _errno[error] : sprintf("0x%x", -error)) } probe module("sunrpc").function("__rpc_execute").call { if (pid() == target()) { t = task_current() p = probefunc() serv = @cast($task->tk_client, "struct rpc_clnt")->cl_server serv_name = kernel_string(serv) proc = @cast(&$task->tk_msg, "struct rpc_message")->rpc_proc func = @cast(proc, "struct rpc_procinfo")->p_name func_name = kernel_string(func) printf("[0x%x] %s -> %s: func: %s, server: %s, parms: %s\n", t, thread_indent(1), p, func_name, serv_name, $$parms) trace[t] = 1 } } probe module("sunrpc").function("__rpc_execute").return { t = task_current() p = probefunc() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), p, $$return) trace[t] = 0 } } probe module("sunrpc").function("xs_tcp_send_request").call { t = task_current() p = probefunc() if (trace[t] == 1) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), p, $$parms) trace[t] = 2 } } probe module("sunrpc").function("xs_tcp_send_request").return { t = task_current() if (trace[t] == 2) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), err_num2str($return)) trace[t] = 1 } } probe module("sunrpc").function("*").call, kernel.function("*@net/ipv4/tcp*").call, kernel.function("*@net/core/stream.c").call, kernel.function("*@net/socket.c").call { t = task_current() p = probefunc() if (trace[t] == 2) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), p, $$parms) } } probe module("sunrpc").function("*").return, kernel.function("*@net/ipv4/tcp*").return, kernel.function("*@net/core/stream.c").return, kernel.function("*@net/socket.c").return { t = task_current() p = probefunc() if (trace[t] == 2) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), p, $$return) } } # vim: ts=2 sts=2 sw=2 et global trace global _tcp_state[13] global _sock_state[5] global _errno[134] global _sock_sk_shutdown[2] probe begin { /* from include/net/tcp_states.h */ _tcp_state[0] = "UNDEF" _tcp_state[1] = "TCP_ESTABLISHED" _tcp_state[2] = "TCP_SYN_SENT" _tcp_state[3] = "TCP_SYN_RECV" _tcp_state[4] = "TCP_FIN_WAIT1" _tcp_state[5] = "TCP_FIN_WAIT2" _tcp_state[6] = "TCP_TIME_WAIT" _tcp_state[7] = "TCP_CLOSE" _tcp_state[8] = "TCP_CLOSE_WAIT" _tcp_state[9] = "TCP_LAST_ACK" _tcp_state[10] = "TCP_LISTEN" _tcp_state[11] = "TCP_CLOSING" _tcp_state[12] = "TCP_MAX_STATES" /* from include/linux/net.h */ _sock_state[0] = "SS_FREE" _sock_state[1] = "SS_UNCONNECTED" _sock_state[2] = "SS_CONNECTING" _sock_state[3] = "SS_CONNECTED" _sock_state[4] = "SS_DISCONNECTING" /* from include/asm-generic/errno-base.h * and include/asm-generic/errno.h */ _errno[0] = "0" _errno[1] = "EPERM" _errno[2] = "ENOENT" _errno[3] = "ESRCH" _errno[4] = "EINTR" _errno[5] = "EIO" _errno[6] = "ENXIO" _errno[7] = "E2BIG" _errno[8] = "ENOEXEC" _errno[9] = "EBADF" _errno[10] = "ECHILD" _errno[11] = "EAGAIN" _errno[12] = "ENOMEM" _errno[13] = "EACCES" _errno[14] = "EFAULT" _errno[15] = "ENOTBLK" _errno[16] = "EBUSY" _errno[17] = "EEXIST" _errno[18] = "EXDEV" _errno[19] = "ENODEV" _errno[20] = "ENOTDIR" _errno[21] = "EISDIR" _errno[22] = "EINVAL" _errno[23] = "ENFILE" _errno[24] = "EMFILE" _errno[25] = "ENOTTY" _errno[26] = "ETXTBSY" _errno[27] = "EFBIG" _errno[28] = "ENOSPC" _errno[29] = "ESPIPE" _errno[30] = "EROFS" _errno[31] = "EMLINK" _errno[32] = "EPIPE" _errno[33] = "EDOM" _errno[34] = "ERANGE" _errno[35] = "EDEADLK" _errno[36] = "ENAMETOOLONG" _errno[37] = "ENOLCK" _errno[38] = "ENOSYS" _errno[39] = "ENOTEMPTY" _errno[40] = "ELOOP" _errno[41] = "UNDEF" _errno[42] = "ENOMSG" _errno[43] = "EIDRM" _errno[44] = "ECHRNG" _errno[45] = "EL2NSYNC" _errno[46] = "EL3HLT" _errno[47] = "EL3RST" _errno[48] = "ELNRNG" _errno[49] = "EUNATCH" _errno[50] = "ENOCSI" _errno[51] = "EL2HLT" _errno[52] = "EBADE" _errno[53] = "EBADR" _errno[54] = "EXFULL" _errno[55] = "ENOANO" _errno[56] = "EBADRQC" _errno[57] = "EBADSLT" _errno[58] = "UNDEF" _errno[59] = "EBFONT" _errno[60] = "ENOSTR" _errno[61] = "ENODATA" _errno[62] = "ETIME" _errno[63] = "ENOSR" _errno[64] = "ENONET" _errno[65] = "ENOPKG" _errno[66] = "EREMOTE" _errno[67] = "ENOLINK" _errno[68] = "EADV" _errno[69] = "ESRMNT" _errno[70] = "ECOMM" _errno[71] = "EPROTO" _errno[72] = "EMULTIHOP" _errno[73] = "EDOTDOT" _errno[74] = "EBADMSG" _errno[75] = "EOVERFLOW" _errno[76] = "ENOTUNIQ" _errno[77] = "EBADFD" _errno[78] = "EREMCHG" _errno[79] = "ELIBACC" _errno[80] = "ELIBBAD" _errno[81] = "ELIBSCN" _errno[82] = "ELIBMAX" _errno[83] = "ELIBEXEC" _errno[84] = "EILSEQ" _errno[85] = "ERESTART" _errno[86] = "ESTRPIPE" _errno[87] = "EUSERS" _errno[88] = "ENOTSOCK" _errno[89] = "EDESTADDRREQ" _errno[90] = "EMSGSIZE" _errno[91] = "EPROTOTYPE" _errno[92] = "ENOPROTOOPT" _errno[93] = "EPROTONOSUPPORT" _errno[94] = "ESOCKTNOSUPPORT" _errno[95] = "EOPNOTSUPP" _errno[96] = "EPFNOSUPPORT" _errno[97] = "EAFNOSUPPORT" _errno[98] = "EADDRINUSE" _errno[99] = "EADDRNOTAVAIL" _errno[100] = "ENETDOWN" _errno[101] = "ENETUNREACH" _errno[102] = "ENETRESET" _errno[103] = "ECONNABORTED" _errno[104] = "ECONNRESET" _errno[105] = "ENOBUFS" _errno[106] = "EISCONN" _errno[107] = "ENOTCONN" _errno[108] = "ESHUTDOWN" _errno[109] = "ETOOMANYREFS" _errno[110] = "ETIMEDOUT" _errno[111] = "ECONNREFUSED" _errno[112] = "EHOSTDOWN" _errno[113] = "EHOSTUNREACH" _errno[114] = "EALREADY" _errno[115] = "EINPROGRESS" _errno[116] = "ESTALE" _errno[117] = "EUCLEAN" _errno[118] = "ENOTNAM" _errno[119] = "ENAVAIL" _errno[120] = "EISNAM" _errno[121] = "EREMOTEIO" _errno[122] = "EDQUOT" _errno[123] = "ENOMEDIUM" _errno[124] = "EMEDIUMTYPE" _errno[125] = "ECANCELED" _errno[126] = "ENOKEY" _errno[127] = "EKEYEXPIRED" _errno[128] = "EKEYREVOKED" _errno[129] = "EKEYREJECTED" _errno[130] = "EOWNERDEAD" _errno[131] = "ENOTRECOVERABLE" _errno[132] = "ERFKILL" _errno[133] = "EHWPOISON" } function err_num2str:string (error:long) { error = -error return (error in _errno ? _errno[error] : sprintf("0x%x", -error)) } function sk_state_num2str:string (state:long) { return (state in _tcp_state ? _tcp_state[state] : sprintf("0x%x", state)) } function sock_state_num2str:string (state:long) { return (state in _sock_state ? _sock_state[state] : sprintf("0x%x", state)) } function sk_shutdown_num2str:string (flags:long) { /* from include/net/sock.h */ RCV_SHUTDOWN = 1 SEND_SHUTDOWN = 2 retvalue = "" if (flags & SEND_SHUTDOWN) _sock_sk_shutdown["SEND_SHUTDOWN"] = 1 if (flags & RCV_SHUTDOWN) _sock_sk_shutdown["RCV_SHUTDOWN"] = 1 foreach (key in _sock_sk_shutdown) { sep = retvalue == "" ? "" : "|" retvalue = sprintf("%s%s%s", retvalue, sep, key) } delete _sock_sk_shutdown return retvalue == "" ? "0" : retvalue } function sk2str:string (sk:long) { sk_state = sk_state_num2str(@cast(sk, "struct sock")->__sk_common->skc_state) sk_shutdown = sk_shutdown_num2str(@cast(sk, "struct sock")->sk_shutdown) sk_err = err_num2str(-(@cast(sk, "struct sock")->sk_err)) return sprintf("sk=0x%x, sk_state: %s, sk_err: %s, sk_shutdown: %s", sk, sk_state, sk_err, sk_shutdown) } function sock2str:string (sock:long) { sock_state = @cast(sock, "struct socket")->state sock_sk = @cast(sock, "struct socket")->sk return sprintf("sock=0x%x, state: %s, %s", sock, sock_state_num2str(sock_state), sk2str(sock_sk)) } probe module("sunrpc").function("__rpc_execute").call { if (pid() == target()) { t = task_current() p = probefunc() serv = @cast($task->tk_client, "struct rpc_clnt")->cl_server serv_name = kernel_string(serv) proc = @cast(&$task->tk_msg, "struct rpc_message")->rpc_proc func = @cast(proc, "struct rpc_procinfo")->p_name func_name = kernel_string(func) printf("[0x%x] %s -> %s: func: %s, server: %s, parms: %s\n", t, thread_indent(1), p, func_name, serv_name, $$parms) trace[t] = 1 } } probe module("sunrpc").function("__rpc_execute").return { t = task_current() p = probefunc() if (trace[t]) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), p, $$return) trace[t] = 0 } } probe module("sunrpc").function("xs_tcp_send_request").call { t = task_current() p = probefunc() if (trace[t] == 1) { printf("[0x%x] %s -> %s: %s\n", t, thread_indent(1), p, $$parms) trace[t] = 2 } } probe module("sunrpc").function("xs_tcp_send_request").return { t = task_current() if (trace[t] == 2) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), err_num2str($return)) trace[t] = 1 } } probe kernel.function("tcp_sendmsg").call { t = task_current() if (trace[t] == 2) { printf("[0x%x] %s -> %s: sock: %s\n", t, thread_indent(1), probefunc(), sock2str($sock)) } } probe kernel.function("tcp_sendmsg").return { t = task_current() if (trace[t] == 2) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), err_num2str($return)) } } probe kernel.function("sk_stream_wait_connect").call { t = task_current() if (trace[t] == 2) { printf("[0x%x] %s -> %s: sk: %s, time_out: %ld\n", t, thread_indent(1), probefunc(), sk2str($sk), kernel_long($timeo_p)) } } probe kernel.function("sk_stream_wait_connect").return { t = task_current() if (trace[t] == 2) { printf("[0x%x] %s <- %s: %s\n", t, thread_indent(-1), probefunc(), err_num2str($return)) } } # vim: ts=2 sts=2 sw=2 et global trace global sk_trace global task_trace global _tcp_state[13] global _sock_state[5] global _errno[134] global _task_tk_runstate[3] global _sock_sk_shutdown[2] probe begin { /* from include/net/tcp_states.h */ _tcp_state[0] = "UNDEF" _tcp_state[1] = "TCP_ESTABLISHED" _tcp_state[2] = "TCP_SYN_SENT" _tcp_state[3] = "TCP_SYN_RECV" _tcp_state[4] = "TCP_FIN_WAIT1" _tcp_state[5] = "TCP_FIN_WAIT2" _tcp_state[6] = "TCP_TIME_WAIT" _tcp_state[7] = "TCP_CLOSE" _tcp_state[8] = "TCP_CLOSE_WAIT" _tcp_state[9] = "TCP_LAST_ACK" _tcp_state[10] = "TCP_LISTEN" _tcp_state[11] = "TCP_CLOSING" _tcp_state[12] = "TCP_MAX_STATES" /* from include/linux/net.h */ _sock_state[0] = "SS_FREE" _sock_state[1] = "SS_UNCONNECTED" _sock_state[2] = "SS_CONNECTING" _sock_state[3] = "SS_CONNECTED" _sock_state[4] = "SS_DISCONNECTING" _errno[0] = "0" _errno[1] = "EPERM" _errno[2] = "ENOENT" _errno[3] = "ESRCH" _errno[4] = "EINTR" _errno[5] = "EIO" _errno[6] = "ENXIO" _errno[7] = "E2BIG" _errno[8] = "ENOEXEC" _errno[9] = "EBADF" _errno[10] = "ECHILD" _errno[11] = "EAGAIN" _errno[12] = "ENOMEM" _errno[13] = "EACCES" _errno[14] = "EFAULT" _errno[15] = "ENOTBLK" _errno[16] = "EBUSY" _errno[17] = "EEXIST" _errno[18] = "EXDEV" _errno[19] = "ENODEV" _errno[20] = "ENOTDIR" _errno[21] = "EISDIR" _errno[22] = "EINVAL" _errno[23] = "ENFILE" _errno[24] = "EMFILE" _errno[25] = "ENOTTY" _errno[26] = "ETXTBSY" _errno[27] = "EFBIG" _errno[28] = "ENOSPC" _errno[29] = "ESPIPE" _errno[30] = "EROFS" _errno[31] = "EMLINK" _errno[32] = "EPIPE" _errno[33] = "EDOM" _errno[34] = "ERANGE" _errno[35] = "EDEADLK" _errno[36] = "ENAMETOOLONG" _errno[37] = "ENOLCK" _errno[38] = "ENOSYS" _errno[39] = "ENOTEMPTY" _errno[40] = "ELOOP" _errno[41] = "UNDEF" _errno[42] = "ENOMSG" _errno[43] = "EIDRM" _errno[44] = "ECHRNG" _errno[45] = "EL2NSYNC" _errno[46] = "EL3HLT" _errno[47] = "EL3RST" _errno[48] = "ELNRNG" _errno[49] = "EUNATCH" _errno[50] = "ENOCSI" _errno[51] = "EL2HLT" _errno[52] = "EBADE" _errno[53] = "EBADR" _errno[54] = "EXFULL" _errno[55] = "ENOANO" _errno[56] = "EBADRQC" _errno[57] = "EBADSLT" _errno[58] = "UNDEF" _errno[59] = "EBFONT" _errno[60] = "ENOSTR" _errno[61] = "ENODATA" _errno[62] = "ETIME" _errno[63] = "ENOSR" _errno[64] = "ENONET" _errno[65] = "ENOPKG" _errno[66] = "EREMOTE" _errno[67] = "ENOLINK" _errno[68] = "EADV" _errno[69] = "ESRMNT" _errno[70] = "ECOMM" _errno[71] = "EPROTO" _errno[72] = "EMULTIHOP" _errno[73] = "EDOTDOT" _errno[74] = "EBADMSG" _errno[75] = "EOVERFLOW" _errno[76] = "ENOTUNIQ" _errno[77] = "EBADFD" _errno[78] = "EREMCHG" _errno[79] = "ELIBACC" _errno[80] = "ELIBBAD" _errno[81] = "ELIBSCN" _errno[82] = "ELIBMAX" _errno[83] = "ELIBEXEC" _errno[84] = "EILSEQ" _errno[85] = "ERESTART" _errno[86] = "ESTRPIPE" _errno[87] = "EUSERS" _errno[88] = "ENOTSOCK" _errno[89] = "EDESTADDRREQ" _errno[90] = "EMSGSIZE" _errno[91] = "EPROTOTYPE" _errno[92] = "ENOPROTOOPT" _errno[93] = "EPROTONOSUPPORT" _errno[94] = "ESOCKTNOSUPPORT" _errno[95] = "EOPNOTSUPP" _errno[96] = "EPFNOSUPPORT" _errno[97] = "EAFNOSUPPORT" _errno[98] = "EADDRINUSE" _errno[99] = "EADDRNOTAVAIL" _errno[100] = "ENETDOWN" _errno[101] = "ENETUNREACH" _errno[102] = "ENETRESET" _errno[103] = "ECONNABORTED" _errno[104] = "ECONNRESET" _errno[105] = "ENOBUFS" _errno[106] = "EISCONN" _errno[107] = "ENOTCONN" _errno[108] = "ESHUTDOWN" _errno[109] = "ETOOMANYREFS" _errno[110] = "ETIMEDOUT" _errno[111] = "ECONNREFUSED" _errno[112] = "EHOSTDOWN" _errno[113] = "EHOSTUNREACH" _errno[114] = "EALREADY" _errno[115] = "EINPROGRESS" _errno[116] = "ESTALE" _errno[117] = "EUCLEAN" _errno[118] = "ENOTNAM" _errno[119] = "ENAVAIL" _errno[120] = "EISNAM" _errno[121] = "EREMOTEIO" _errno[122] = "EDQUOT" _errno[123] = "ENOMEDIUM" _errno[124] = "EMEDIUMTYPE" _errno[125] = "ECANCELED" _errno[126] = "ENOKEY" _errno[127] = "EKEYEXPIRED" _errno[128] = "EKEYREVOKED" _errno[129] = "EKEYREJECTED" _errno[130] = "EOWNERDEAD" _errno[131] = "ENOTRECOVERABLE" _errno[132] = "ERFKILL" _errno[133] = "EHWPOISON" } function err_num2str:string (error:long) { error = -error return (error in _errno ? _errno[error] : sprintf("0x%x", -error)) } function sk_state_num2str:string (state:long) { return (state in _tcp_state ? _tcp_state[state] : sprintf("0x%x", state)) } function sock_state_num2str:string (state:long) { return (state in _sock_state ? _sock_state[state] : sprintf("0x%x", state)) } function sk_shutdown_num2str:string (flags:long) { /* from include/net/sock.h */ RCV_SHUTDOWN = 1 SEND_SHUTDOWN = 2 retvalue = "" if (flags & SEND_SHUTDOWN) _sock_sk_shutdown["SEND_SHUTDOWN"] = 1 if (flags & RCV_SHUTDOWN) _sock_sk_shutdown["RCV_SHUTDOWN"] = 1 foreach (key in _sock_sk_shutdown) { sep = retvalue == "" ? "" : "|" retvalue = sprintf("%s%s%s", retvalue, sep, key) } delete _sock_sk_shutdown return retvalue == "" ? "0" : retvalue } function sk2str:string (sk:long) { sk_state = sk_state_num2str(@cast(sk, "struct sock")->__sk_common->skc_state) sk_shutdown = sk_shutdown_num2str(@cast(sk, "struct sock")->sk_shutdown) sk_err = err_num2str(-(@cast(sk, "struct sock")->sk_err)) return sprintf("sk=0x%x, sk_state: %s, sk_err: %s, sk_shutdown: %s", sk, sk_state, sk_err, sk_shutdown) } function sock2str:string (sock:long) { sock_state = @cast(sock, "struct socket")->state sock_sk = @cast(sock, "struct socket")->sk return sprintf("sock=0x%x, state: %s, %s", sock, sock_state_num2str(sock_state), sk2str(sock_sk)) } function task_runstate_num2str:string (word:long) { /* from include/linux/runrpc/sched.h but watch out, needs translation from * the values there for use in '&' as they use `test_bit' */ RPC_TASK_RUNNING = 1 RPC_TASK_QUEUED = 2 RPC_TASK_ACTIVE = 4 retvalue = "" if (word & RPC_TASK_RUNNING) _task_tk_runstate["RPC_TASK_RUNNING"] = 1 if (word & RPC_TASK_QUEUED) _task_tk_runstate["RPC_TASK_QUEUED"] = 1 if (word & RPC_TASK_ACTIVE) _task_tk_runstate["RPC_TASK_ACTIVE"] = 1 foreach (key in _task_tk_runstate) { sep = retvalue == "" ? "" : "|" retvalue = sprintf("%s%s%s", retvalue, sep, key) } delete _task_tk_runstate retvalue = retvalue == "" ? "0" : retvalue return sprintf("tk_runstate: %s", retvalue) } function task2str:string (task:long) { tk_runstate = @cast(task, "struct rpc_task", "kernel<linux/sunrpc/sched.h>")->tk_runstate tk_status = @cast(task, "struct rpc_task", "kernel<linux/sunrpc/sched.h>")->tk_status return sprintf("tk_status: %s, %s", err_num2str(tk_status), task_runstate_num2str(tk_runstate)) } probe module("sunrpc").function("__rpc_execute").call { if (pid() == target()) { t = task_current() p = probefunc() /* pull the server name */ serv = @cast($task->tk_client, "struct rpc_clnt")->cl_server serv_name = kernel_string(serv) proc = @cast(&$task->tk_msg, "struct rpc_message")->rpc_proc func = @cast(proc, "struct rpc_procinfo")->p_name func_name = kernel_string(func) printf("%d [0x%x] %s -> %s: func: %s, server: %s, task: %s, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), p, func_name, serv_name, task2str($task), $$parms) trace[t] = 1 task_trace[$task] = 1 } } probe module("sunrpc").function("__rpc_execute").return { t = task_current() p = probefunc() if (trace[t]) { printf("%d [0x%x] %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), p, $$return) trace[t] = 0 delete task_trace } } probe module("sunrpc").function("call_*").call { t = task_current() p = probefunc() if (trace[t]) { printf("%d [0x%x] %s -> %s: task: %s, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), p, task2str($task), $$parms) } } probe module("sunrpc").function("call_*").return { t = task_current() if (trace[t]) { printf("%d [0x%x] %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc(), $$return) } } probe module("sunrpc").function("xs_tcp_send_request").call { t = task_current() p = probefunc() if (trace[t]) { rq_xprt = @cast($task->tk_rqstp, "struct rpc_rqst")->rq_xprt sock = @cast(rq_xprt - (& @cast(0, "struct sock_xprt")->xprt), "struct sock_xprt")->sock sk = @cast(sock, "struct socket")->sk printf("%d [0x%x] %s -> %s: sock: %s, task: %s, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), p, sock2str(sock), task2str($task), $$parms) sk_trace[sk] = 1 } } probe module("sunrpc").function("xs_tcp_send_request").return { t = task_current() if (trace[t]) { printf("%d [0x%x] %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc(), err_num2str($return)) } } probe module("sunrpc").function("xs_connect").call { t = task_current() if (trace[t]) { rq_xprt = @cast($task->tk_rqstp, "struct rpc_rqst")->rq_xprt sock = @cast(rq_xprt - (& @cast(0, "struct sock_xprt")->xprt), "struct sock_xprt")->sock printf("%d [0x%x] %s -> %s: sock: %s, task: %s, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), probefunc(), sock2str(sock), task2str($task), $$parms) } } probe module("sunrpc").function("xs_connect").return { t = task_current() if (trace[t]) { printf("%d [0x%x] %s <- %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc()) } } probe module("sunrpc").function("rpc_wait_bit_killable").call { t = task_current() if (trace[t]) { printf("%d [0x%x] %s -> %s: parms: %s\n", gettimeofday_ns(), t, thread_indent(1), probefunc(), $$parms) } } probe module("sunrpc").function("rpc_wait_bit_killable").return { t = task_current() if (trace[t]) { printf("%d [0x%x] %s <- %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc()) } } probe kernel.function("sk_stream_wait_connect").call { t = task_current() p = probefunc() if (trace[t]) { printf("%d [0x%x] %s -> %s: sk: %s, time_out: %d, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), p, sk2str($sk), kernel_long($timeo_p), $$parms) } } probe kernel.function("sk_stream_wait_connect").return { t = task_current() if (trace[t]) { printf("%d [0x%x] %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc(), err_num2str($return)) } } probe kernel.function("out_of_line_wait_on_bit").call { t = task_current() if (trace[t]) { printf("%d [0x%x] %s -> %s: word: %s, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), probefunc(), task_runstate_num2str(kernel_long($word)), $$parms) } } probe kernel.function("out_of_line_wait_on_bit").return { t = task_current() if (trace[t]) { printf("%d [0x%x] %s <- %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc()) } } probe module("sunrpc").function("rpc_make_runnable").call { t = task_current() if (task_trace[$task]) { printf("%d [0x%x] %s -> %s: task: %s, parms: %s\n", gettimeofday_ns(), t, execname(), probefunc(), task2str($task), $$parms) print_backtrace() } } probe kernel.function("tcp_set_state").call { if (sk_trace[$sk]) { t = task_current() printf("%d [0x%x] %s -> %s: sk: %s, NEW sk_state: %s\n", gettimeofday_ns(), t, execname(), probefunc(), sk2str($sk), sk_state_num2str($state)) print_backtrace() } } global trace global _tcp_state[13] global _sock_state[5] global _errno[134] global _sock_sk_shutdown[2] probe begin { /* from include/net/tcp_states.h */ _tcp_state[0] = "UNDEF" _tcp_state[1] = "TCP_ESTABLISHED" _tcp_state[2] = "TCP_SYN_SENT" _tcp_state[3] = "TCP_SYN_RECV" _tcp_state[4] = "TCP_FIN_WAIT1" _tcp_state[5] = "TCP_FIN_WAIT2" _tcp_state[6] = "TCP_TIME_WAIT" _tcp_state[7] = "TCP_CLOSE" _tcp_state[8] = "TCP_CLOSE_WAIT" _tcp_state[9] = "TCP_LAST_ACK" _tcp_state[10] = "TCP_LISTEN" _tcp_state[11] = "TCP_CLOSING" _tcp_state[12] = "TCP_MAX_STATES" /* from include/linux/net.h */ _sock_state[0] = "SS_FREE" _sock_state[1] = "SS_UNCONNECTED" _sock_state[2] = "SS_CONNECTING" _sock_state[3] = "SS_CONNECTED" _sock_state[4] = "SS_DISCONNECTING" _errno[0] = "0" _errno[1] = "EPERM" _errno[2] = "ENOENT" _errno[3] = "ESRCH" _errno[4] = "EINTR" _errno[5] = "EIO" _errno[6] = "ENXIO" _errno[7] = "E2BIG" _errno[8] = "ENOEXEC" _errno[9] = "EBADF" _errno[10] = "ECHILD" _errno[11] = "EAGAIN" _errno[12] = "ENOMEM" _errno[13] = "EACCES" _errno[14] = "EFAULT" _errno[15] = "ENOTBLK" _errno[16] = "EBUSY" _errno[17] = "EEXIST" _errno[18] = "EXDEV" _errno[19] = "ENODEV" _errno[20] = "ENOTDIR" _errno[21] = "EISDIR" _errno[22] = "EINVAL" _errno[23] = "ENFILE" _errno[24] = "EMFILE" _errno[25] = "ENOTTY" _errno[26] = "ETXTBSY" _errno[27] = "EFBIG" _errno[28] = "ENOSPC" _errno[29] = "ESPIPE" _errno[30] = "EROFS" _errno[31] = "EMLINK" _errno[32] = "EPIPE" _errno[33] = "EDOM" _errno[34] = "ERANGE" _errno[35] = "EDEADLK" _errno[36] = "ENAMETOOLONG" _errno[37] = "ENOLCK" _errno[38] = "ENOSYS" _errno[39] = "ENOTEMPTY" _errno[40] = "ELOOP" _errno[41] = "UNDEF" _errno[42] = "ENOMSG" _errno[43] = "EIDRM" _errno[44] = "ECHRNG" _errno[45] = "EL2NSYNC" _errno[46] = "EL3HLT" _errno[47] = "EL3RST" _errno[48] = "ELNRNG" _errno[49] = "EUNATCH" _errno[50] = "ENOCSI" _errno[51] = "EL2HLT" _errno[52] = "EBADE" _errno[53] = "EBADR" _errno[54] = "EXFULL" _errno[55] = "ENOANO" _errno[56] = "EBADRQC" _errno[57] = "EBADSLT" _errno[58] = "UNDEF" _errno[59] = "EBFONT" _errno[60] = "ENOSTR" _errno[61] = "ENODATA" _errno[62] = "ETIME" _errno[63] = "ENOSR" _errno[64] = "ENONET" _errno[65] = "ENOPKG" _errno[66] = "EREMOTE" _errno[67] = "ENOLINK" _errno[68] = "EADV" _errno[69] = "ESRMNT" _errno[70] = "ECOMM" _errno[71] = "EPROTO" _errno[72] = "EMULTIHOP" _errno[73] = "EDOTDOT" _errno[74] = "EBADMSG" _errno[75] = "EOVERFLOW" _errno[76] = "ENOTUNIQ" _errno[77] = "EBADFD" _errno[78] = "EREMCHG" _errno[79] = "ELIBACC" _errno[80] = "ELIBBAD" _errno[81] = "ELIBSCN" _errno[82] = "ELIBMAX" _errno[83] = "ELIBEXEC" _errno[84] = "EILSEQ" _errno[85] = "ERESTART" _errno[86] = "ESTRPIPE" _errno[87] = "EUSERS" _errno[88] = "ENOTSOCK" _errno[89] = "EDESTADDRREQ" _errno[90] = "EMSGSIZE" _errno[91] = "EPROTOTYPE" _errno[92] = "ENOPROTOOPT" _errno[93] = "EPROTONOSUPPORT" _errno[94] = "ESOCKTNOSUPPORT" _errno[95] = "EOPNOTSUPP" _errno[96] = "EPFNOSUPPORT" _errno[97] = "EAFNOSUPPORT" _errno[98] = "EADDRINUSE" _errno[99] = "EADDRNOTAVAIL" _errno[100] = "ENETDOWN" _errno[101] = "ENETUNREACH" _errno[102] = "ENETRESET" _errno[103] = "ECONNABORTED" _errno[104] = "ECONNRESET" _errno[105] = "ENOBUFS" _errno[106] = "EISCONN" _errno[107] = "ENOTCONN" _errno[108] = "ESHUTDOWN" _errno[109] = "ETOOMANYREFS" _errno[110] = "ETIMEDOUT" _errno[111] = "ECONNREFUSED" _errno[112] = "EHOSTDOWN" _errno[113] = "EHOSTUNREACH" _errno[114] = "EALREADY" _errno[115] = "EINPROGRESS" _errno[116] = "ESTALE" _errno[117] = "EUCLEAN" _errno[118] = "ENOTNAM" _errno[119] = "ENAVAIL" _errno[120] = "EISNAM" _errno[121] = "EREMOTEIO" _errno[122] = "EDQUOT" _errno[123] = "ENOMEDIUM" _errno[124] = "EMEDIUMTYPE" _errno[125] = "ECANCELED" _errno[126] = "ENOKEY" _errno[127] = "EKEYEXPIRED" _errno[128] = "EKEYREVOKED" _errno[129] = "EKEYREJECTED" _errno[130] = "EOWNERDEAD" _errno[131] = "ENOTRECOVERABLE" _errno[132] = "ERFKILL" _errno[133] = "EHWPOISON" } /**** Helpers ****/ function err_num2str:string (error:long) { error = -error return (error in _errno ? _errno[error] : sprintf("0x%x", -error)) } function sk_state_num2str:string (state:long) { return (state in _tcp_state ? _tcp_state[state] : sprintf("0x%x", state)) } function sock_state_num2str:string (state:long) { return (state in _sock_state ? _sock_state[state] : sprintf("0x%x", state)) } function sk_shutdown_num2str:string (flags:long) { /* from include/net/sock.h */ RCV_SHUTDOWN = 1 SEND_SHUTDOWN = 2 retvalue = "" if (flags & SEND_SHUTDOWN) _sock_sk_shutdown["SEND_SHUTDOWN"] = 1 if (flags & RCV_SHUTDOWN) _sock_sk_shutdown["RCV_SHUTDOWN"] = 1 foreach (key in _sock_sk_shutdown) { sep = retvalue == "" ? "" : "|" retvalue = sprintf("%s%s%s", retvalue, sep, key) } delete _sock_sk_shutdown return retvalue == "" ? "0" : retvalue } function sk2str:string (sk:long) { sk_state = sk_state_num2str(@cast(sk, "struct sock")->__sk_common->skc_state) sk_shutdown = sk_shutdown_num2str(@cast(sk, "struct sock")->sk_shutdown) sk_err = err_num2str(-(@cast(sk, "struct sock")->sk_err)) return sprintf("sk=0x%x, sk_state: %s, sk_err: %s, sk_shutdown: %s", sk, sk_state, sk_err, sk_shutdown) } function sock2str:string (sock:long) { sock_state = @cast(sock, "struct socket")->state sock_sk = @cast(sock, "struct socket")->sk return sprintf("sock=0x%x, state: %s, %s", sock, sock_state_num2str(sock_state), sk2str(sock_sk)) } /**** Actual Probes Below ****/ probe module("sunrpc").function("xs_tcp_setup_socket").call { if (isinstr(execname(), "rpciod")) { t = task_current() trace[t] = 1 printf("%d [0x%x]: %s -> %s: parms: %s\n", gettimeofday_ns(), t, thread_indent(1), probefunc(), $$parms) } } probe module("sunrpc").function("xs_tcp_setup_socket").return { t = task_current() if (trace[t]) { printf("%d [0x%x]: %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc(), $$return) } trace[t] = 0 } probe kernel.function("kernel_connect").call { t = task_current() if (trace[t]) { printf("%d [0x%x]: %s -> %s: sock: %s, parms: %s\n", gettimeofday_ns(), t, thread_indent(1), probefunc(), sock2str($sock), $$parms) } } probe kernel.function("kernel_connect").return { t = task_current() if (trace[t]) { printf("%d [0x%x]: %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc(), err_num2str($return)) } } probe module("sunrpc").function("*").call, kernel.function("*@net/socket.c").call { t = task_current() if (trace[t]) { printf("%d [0x%x]: %s -> %s: parms: %s\n", gettimeofday_ns(), t, thread_indent(1), probefunc(), $$parms) } } probe module("sunrpc").function("*").return, kernel.function("*@net/socket.c").return { t = task_current() if (trace[t]) { printf("%d [0x%x]: %s <- %s: %s\n", gettimeofday_ns(), t, thread_indent(-1), probefunc(), $$return) } }
On Wed, Oct 24, 2012 at 12:10:04PM -0400, Chris Perl wrote: > On Wed, Oct 24, 2012 at 02:56:55PM +0000, Myklebust, Trond wrote: > > OK, I've now posted the patches in the "bugfixes" branch of > > > > git://git.linux-nfs.org/projects/trondmy/linux-nfs.git > > Cool, I'll try to get that pulled, compiled and tested by the end of the > day. Pulled, compiled and tested in the same manner described before without problems. Thanks for getting this resolved! Chris -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c index 7e2dd0d..1f105c2 100644 --- a/net/sunrpc/xprtsock.c +++ b/net/sunrpc/xprtsock.c @@ -1453,7 +1453,7 @@ static void xs_tcp_cancel_linger_timeout(struct rpc_xprt *xprt) xprt_clear_connecting(xprt); } -static void xs_sock_mark_closed(struct rpc_xprt *xprt) +static void xs_sock_reset_connection_flags(struct rpc_xprt *xprt) { smp_mb__before_clear_bit(); clear_bit(XPRT_CONNECTION_ABORT, &xprt->state); @@ -1461,6 +1461,11 @@ static void xs_sock_mark_closed(struct rpc_xprt *xprt) clear_bit(XPRT_CLOSE_WAIT, &xprt->state); clear_bit(XPRT_CLOSING, &xprt->state); smp_mb__after_clear_bit(); +} + +static void xs_sock_mark_closed(struct rpc_xprt *xprt) +{ + xs_sock_reset_connection_flags(xprt); /* Mark transport as closed and wake up all pending tasks */ xprt_disconnect_done(xprt); } @@ -2051,10 +2056,8 @@ static void xs_abort_connection(struct sock_xprt *transport) any.sa_family = AF_UNSPEC; result = kernel_connect(transport->sock, &any, sizeof(any), 0); if (!result) - xs_sock_mark_closed(&transport->xprt); - else - dprintk("RPC: AF_UNSPEC connect return code %d\n", - result); + xs_sock_reset_connection_flags(&transport->xprt); + dprintk("RPC: AF_UNSPEC connect return code %d\n", result); } static void xs_tcp_reuse_connection(struct sock_xprt *transport)