[Ocfs2-commits] zab commits r2556 - branches/ocfs2-1.0/fs/ocfs2/cluster

[svn-commits at oss.oracle.com]

Author: zab
Signed-off-by: mfasheh
Date: 2005-08-29 19:26:33 -0500 (Mon, 29 Aug 2005)
New Revision: 2556

Modified:
   branches/ocfs2-1.0/fs/ocfs2/cluster/tcp.c
   branches/ocfs2-1.0/fs/ocfs2/cluster/tcp_internal.h
Log:
o bring in commit 2555 from trunk to help idle timeout debugging

  [2555] include informative timestamps in idle net timeout message

Signed-off-by: mfasheh
  


Modified: branches/ocfs2-1.0/fs/ocfs2/cluster/tcp.c
===================================================================
--- branches/ocfs2-1.0/fs/ocfs2/cluster/tcp.c	2005-08-30 00:07:04 UTC (rev 2555)
+++ branches/ocfs2-1.0/fs/ocfs2/cluster/tcp.c	2005-08-30 00:26:33 UTC (rev 2556)
@@ -473,6 +473,7 @@
 	if (sk->sk_user_data) {
 		struct o2net_sock_container *sc = sk->sk_user_data;
 		sclog(sc, "data_ready hit\n");
+		do_gettimeofday(&sc->sc_tv_data_ready);
 		o2net_sc_queue_work(sc, &sc->sc_rx_work);
 		ready = sc->sc_data_ready;
 	} else {
@@ -1096,8 +1097,12 @@
 	if (syserr != O2NET_ERR_NONE)
 		goto out_respond;
 
+	do_gettimeofday(&sc->sc_tv_func_start);
+	sc->sc_msg_key = hdr->key;
+	sc->sc_msg_type = hdr->msg_type;
 	handler_status = (nmh->nh_func)(hdr, sizeof(o2net_msg) + hdr->data_len,
 					nmh->nh_func_data);
+	do_gettimeofday(&sc->sc_tv_func_stop);
 
 out_respond:
 	/* this destroys the hdr, so don't use it after this */
@@ -1165,6 +1170,7 @@
 	size_t datalen;
 
 	sclog(sc, "receiving\n");
+	do_gettimeofday(&sc->sc_tv_advance_start);
 
 	/* do we need more header? */
 	if (sc->sc_page_off < sizeof(o2net_msg)) {
@@ -1231,6 +1237,7 @@
 
 out:
 	sclog(sc, "ret = %d\n", ret);
+	do_gettimeofday(&sc->sc_tv_advance_stop);
 	return ret;
 }
 
@@ -1312,12 +1319,26 @@
 static void o2net_idle_timer(unsigned long data)
 {
 	struct o2net_sock_container *sc = (struct o2net_sock_container *)data;
+	struct timeval now;
 
+	do_gettimeofday(&now);
+
 	mlog(ML_NOTICE, "connection to node %s num %u at %u.%u.%u.%u:%d has "
 	     "been idle for 10 seconds, shutting it down.\n",
 	     sc->sc_node->nd_name, sc->sc_node->nd_num,
 	     NIPQUAD(sc->sc_node->nd_ipv4_address),
 	     ntohs(sc->sc_node->nd_ipv4_port));
+	mlog(ML_NOTICE, "here are some times that might help debug the "
+	     "situation: (tmr %ld.%ld now %ld.%ld dr %ld.%ld adv "
+	     "%ld.%ld:%ld.%ld func (%08x:%u) %ld.%ld:%ld.%ld)\n",
+	     sc->sc_tv_timer.tv_sec, sc->sc_tv_timer.tv_usec, 
+	     now.tv_sec, now.tv_usec,
+	     sc->sc_tv_data_ready.tv_sec, sc->sc_tv_data_ready.tv_usec, 
+	     sc->sc_tv_advance_start.tv_sec, sc->sc_tv_advance_start.tv_usec, 
+	     sc->sc_tv_advance_stop.tv_sec, sc->sc_tv_advance_stop.tv_usec, 
+	     sc->sc_msg_key, sc->sc_msg_type,
+	     sc->sc_tv_func_start.tv_sec, sc->sc_tv_func_start.tv_usec,
+	     sc->sc_tv_func_stop.tv_sec, sc->sc_tv_func_stop.tv_usec);
 
 	o2net_sc_queue_work(sc, &sc->sc_shutdown_work);
 }
@@ -1327,6 +1348,7 @@
 	o2net_sc_cancel_delayed_work(sc, &sc->sc_keepalive_work);
 	o2net_sc_queue_delayed_work(sc, &sc->sc_keepalive_work,
 				    O2NET_KEEPALIVE_DELAY_SECS * HZ);
+	do_gettimeofday(&sc->sc_tv_timer);
 	mod_timer(&sc->sc_idle_timeout,
 		  jiffies + (O2NET_IDLE_TIMEOUT_SECS * HZ));
 }

Modified: branches/ocfs2-1.0/fs/ocfs2/cluster/tcp_internal.h
===================================================================
--- branches/ocfs2-1.0/fs/ocfs2/cluster/tcp_internal.h	2005-08-30 00:07:04 UTC (rev 2555)
+++ branches/ocfs2-1.0/fs/ocfs2/cluster/tcp_internal.h	2005-08-30 00:26:33 UTC (rev 2556)
@@ -127,6 +127,15 @@
 	void			(*sc_data_ready)(struct sock *sk, int bytes);
 
 	struct list_head	sc_net_proc_item;
+
+	struct timeval 		sc_tv_timer;
+	struct timeval 		sc_tv_data_ready;
+	struct timeval 		sc_tv_advance_start;
+	struct timeval 		sc_tv_advance_stop;
+	struct timeval 		sc_tv_func_start;
+	struct timeval 		sc_tv_func_stop;
+	u32			sc_msg_key;
+	u16			sc_msg_type;
 };
 
 struct o2net_msg_handler {