From eefac5e4df520993bf6e4640e05d5237cbe9e840 Mon Sep 17 00:00:00 2001
From: csoler <retroshare.project@gmail.com>
Date: Tue, 28 Oct 2014 20:37:48 +0000
Subject: [PATCH] added more time measurements in RsMutex, so as to measure
 locking time and waiting time. Only enabled with RSMUTEX_DEBUG

git-svn-id: http://svn.code.sf.net/p/retroshare/code/trunk@7646 b45a01b8-16f6-495d-af2f-9b41ad6348cc
---
 libretroshare/src/util/rsthreads.cc | 52 +++++++++++++++++++++++++----
 libretroshare/src/util/rsthreads.h  | 19 +++--------
 2 files changed, 50 insertions(+), 21 deletions(-)

diff --git a/libretroshare/src/util/rsthreads.cc b/libretroshare/src/util/rsthreads.cc
index 3852c1b1e..713dfcf5d 100644
--- a/libretroshare/src/util/rsthreads.cc
+++ b/libretroshare/src/util/rsthreads.cc
@@ -33,6 +33,7 @@
 
 #ifdef RSMUTEX_DEBUG
 #include <stdio.h>
+#include <sys/time.h>
 #endif
 
 /*******
@@ -176,10 +177,32 @@ void RsQueueThread::run()
 	}
 }
 
+void RsMutex::unlock()
+{ 
+#ifdef RSTHREAD_SELF_LOCKING_GUARD
+	if(--_cnt == 0)
+	{
+#endif
+#ifndef WIN32
+		_thread_id = 0 ;
+#endif
+#ifdef RSMUTEX_DEBUG
+		double ts = getCurrentTS() ;
+
+		if(ts - _time_stamp > 1.0)	// locked for more than 0.5 seconds => somthing fishy is happenning
+			std::cerr << "Mutex " << (void*)this << " got locked for " << ts - _time_stamp << " seconds in thread " << pthread_self() << std::endl;
+#endif
+		pthread_mutex_unlock(&realMutex); 
+
+#ifdef RSTHREAD_SELF_LOCKING_GUARD
+	}
+#endif
+}
+
 void RsMutex::lock()
 {
 #ifdef RSMUTEX_DEBUG
-	clock_t t1 = clock();
+	_time_stamp = getCurrentTS() ;
 #endif
 
 	int retval = 0;
@@ -189,6 +212,12 @@ void RsMutex::lock()
 #endif
 			retval = pthread_mutex_lock(&realMutex);
 
+#ifdef RSMUTEX_DEBUG
+	double ts = getCurrentTS() ;
+
+	if(ts - _time_stamp > 1.0)
+		std::cerr << "Mutex " << (void*)this << " waited for " << ts - _time_stamp << " seconds in thread " << pthread_self() << std::endl;
+#endif
 	switch(retval)
 	{
 		case 0:
@@ -246,13 +275,22 @@ void RsMutex::lock()
 #ifdef RSTHREAD_SELF_LOCKING_GUARD
 	++_cnt ;
 #endif
+}
 
 #ifdef RSMUTEX_DEBUG
-	clock_t t2 = clock();
-	double duration = (double) (t2 - t1) / CLOCKS_PER_SEC;
-	if (duration * 1000 > RSMUTEX_DEBUG) {
-		fprintf(stderr, "RsMutex::lock() %s --> %.3fs\n", name.c_str(), duration);
-		fflush(stderr);
-	}
+double RsMutex::getCurrentTS()
+{
+
+#ifndef WINDOWS_SYS
+        struct timeval cts_tmp;
+        gettimeofday(&cts_tmp, NULL);
+        double cts =  (cts_tmp.tv_sec) + ((double) cts_tmp.tv_usec) / 1000000.0;
+#else
+        struct _timeb timebuf;
+        _ftime( &timebuf);
+        double cts =  (timebuf.time) + ((double) timebuf.millitm) / 1000.0;
 #endif
+        return cts;
 }
+#endif
+
diff --git a/libretroshare/src/util/rsthreads.h b/libretroshare/src/util/rsthreads.h
index bd42b453a..c8ce9f035 100644
--- a/libretroshare/src/util/rsthreads.h
+++ b/libretroshare/src/util/rsthreads.h
@@ -35,6 +35,7 @@
 
 #undef RSTHREAD_SELF_LOCKING_GUARD
 //#define RSMUTEX_DEBUG 300 // Milliseconds for print in the stderr
+//#define RSMUTEX_DEBUG 
 
 class RsMutex
 {
@@ -67,20 +68,7 @@ class RsMutex
 #endif
 
 	void	lock();
-	void	unlock() 
-	{ 
-#ifdef RSTHREAD_SELF_LOCKING_GUARD
-		if(--_cnt == 0)
-		{
-#endif
-#ifndef WIN32
-			_thread_id = 0 ;
-#endif
-			pthread_mutex_unlock(&realMutex); 
-#ifdef RSTHREAD_SELF_LOCKING_GUARD
-		}
-#endif
-	}
+	void	unlock();
 	bool	trylock() { return (0 == pthread_mutex_trylock(&realMutex)); }
 
 	private:
@@ -90,7 +78,10 @@ class RsMutex
 		uint32_t _cnt ;
 #endif
 #ifdef RSMUTEX_DEBUG
+		static double getCurrentTS() ;
+
 		std::string name;
+		double _time_stamp ;
 #endif
 };