Added extended debug outputs of times in RsDataService.

libretroshare/src/gxs/rsdataservice.cc

@@ -24,11 +24,19 @@
  *
  */
 
+/*****
+ * #define RS_DATA_SERVICE_DEBUG       1
+ * #define RS_DATA_SERVICE_DEBUG_TIME  1
+ ****/
 
 #include <fstream>
 #include <util/rsdir.h>
 #include <algorithm>
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+#include <util/rsscopetimer.h>
+#endif
+
 #include "rsdataservice.h"
 
 #define MSG_TABLE_NAME std::string("MESSAGES")
@@ -141,10 +149,6 @@
 #define COL_IDENTITY 4
 #define COL_HASH 5
 
-/*****
- * #define RS_DATA_SERVICE_DEBUG  1
- ****/
-
 const std::string RsGeneralDataService::GRP_META_SERV_STRING = KEY_NXS_SERV_STRING;
 const std::string RsGeneralDataService::GRP_META_STATUS = KEY_GRP_STATUS;
 const std::string RsGeneralDataService::GRP_META_SUBSCRIBE_FLAG = KEY_GRP_SUBCR_FLAG;
@@ -900,7 +904,13 @@ bool RsDataService::validSize(RsNxsGrp* grp) const
 	return false;
 }
 
-int RsDataService::retrieveNxsGrps(std::map<RsGxsGroupId, RsNxsGrp *> &grp, bool withMeta, bool /* cache */){
+int RsDataService::retrieveNxsGrps(std::map<RsGxsGroupId, RsNxsGrp *> &grp, bool withMeta, bool /* cache */)
+{
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    RsScopeTimer timer("");
+    int resultCount = 0;
+    int requestedGroups = grp.size();
+#endif
 
     if(grp.empty()){
 
@@ -914,6 +924,10 @@ int RsDataService::retrieveNxsGrps(std::map<RsGxsGroupId, RsNxsGrp *> &grp, bool
                 locked_retrieveGroups(c, grps);
                 std::vector<RsNxsGrp*>::iterator vit = grps.begin();
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+                resultCount = grps.size();
+#endif
+
                 for(; vit != grps.end(); ++vit)
                 {
                         grp[(*vit)->grpId] = *vit;
@@ -943,6 +957,10 @@ int RsDataService::retrieveNxsGrps(std::map<RsGxsGroupId, RsNxsGrp *> &grp, bool
                 {
                         RsNxsGrp* ng = grps.front();
                         grp[ng->grpId] = ng;
+
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+                        ++resultCount;
+#endif
                 }else{
                         toRemove.push_back(grpId);
                 }
@@ -958,6 +976,10 @@ int RsDataService::retrieveNxsGrps(std::map<RsGxsGroupId, RsNxsGrp *> &grp, bool
         }
     }
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    std::cerr << "RsDataService::retrieveNxsGrps() Requests: " << requestedGroups << ", Results: " << resultCount << ", Time: " << timer.duration() << std::endl;
+#endif
+
     if(withMeta && !grp.empty())
     {
         std::map<RsGxsGroupId, RsGxsGrpMetaData*> metaMap;
@@ -980,6 +1002,10 @@ int RsDataService::retrieveNxsGrps(std::map<RsGxsGroupId, RsNxsGrp *> &grp, bool
 	    std::cerr << std::endl;
 #endif
         }
+
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+        std::cerr << "RsDataService::retrieveNxsGrps() Time with meta: " << timer.duration() << std::endl;
+#endif
     }
 
     return 1;
@@ -1005,6 +1031,10 @@ void RsDataService::locked_retrieveGroups(RetroCursor* c, std::vector<RsNxsGrp*>
 
 int RsDataService::retrieveNxsMsgs(const GxsMsgReq &reqIds, GxsMsgResult &msg, bool /* cache */, bool withMeta)
 {
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    RsScopeTimer timer("");
+    int resultCount = 0;
+#endif
 
     GxsMsgReq::const_iterator mit = reqIds.begin();
 
@@ -1026,8 +1056,14 @@ int RsDataService::retrieveNxsMsgs(const GxsMsgReq &reqIds, GxsMsgResult &msg, b
             RetroCursor* c = mDb->sqlQuery(MSG_TABLE_NAME, msgColumns, KEY_GRP_ID+ "='" + grpId.toStdString() + "'", "");
 
             if(c)
+            {
                 locked_retrieveMessages(c, msgSet);
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+                resultCount += msgSet.size();
+#endif
+            }
+
             delete c;
         }else{
 
@@ -1043,8 +1079,14 @@ int RsDataService::retrieveNxsMsgs(const GxsMsgReq &reqIds, GxsMsgResult &msg, b
                                                + "' AND " + KEY_MSG_ID + "='" + msgId.toStdString() + "'", "");
 
                 if(c)
+                {
                     locked_retrieveMessages(c, msgSet);
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+                    resultCount += c->getResultCount();
+#endif
+                }
+
                 delete c;
             }
         }
@@ -1066,6 +1108,10 @@ int RsDataService::retrieveNxsMsgs(const GxsMsgReq &reqIds, GxsMsgResult &msg, b
         msgSet.clear();
     }
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    std::cerr << "RsDataService::retrieveNxsMsgs() Requests: " << reqIds.size() << "Results: " << resultCount << ", Time: " << timer.duration() << std::endl;
+#endif
+
     // tres expensive !?
     if(withMeta)
     {
@@ -1117,6 +1163,10 @@ int RsDataService::retrieveNxsMsgs(const GxsMsgReq &reqIds, GxsMsgResult &msg, b
                 meta_lit = msgMetaV.erase(meta_lit);
             }
         }
+
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+        std::cerr << "RsDataService::retrieveNxsMsgs() Time with meta: " << timer.duration() << std::endl;
+#endif
     }
 
     return 1;
@@ -1129,7 +1179,7 @@ void RsDataService::locked_retrieveMessages(RetroCursor *c, std::vector<RsNxsMsg
         RsNxsMsg* m = locked_getMessage(*c);
 
         if(m){
-            msgs.push_back(m);;
+            msgs.push_back(m);
         }
 
         valid = c->moveToNext();
@@ -1139,9 +1189,13 @@ void RsDataService::locked_retrieveMessages(RetroCursor *c, std::vector<RsNxsMsg
 
 int RsDataService::retrieveGxsMsgMetaData(const GxsMsgReq& reqIds, GxsMsgMetaResult &msgMeta)
 {
-
     RsStackMutex stack(mDbMutex);
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    RsScopeTimer timer("");
+    int resultCount = 0;
+#endif
+
     GxsMsgReq::const_iterator mit = reqIds.begin();
 
     for(; mit != reqIds.end(); ++mit)
@@ -1156,8 +1210,14 @@ int RsDataService::retrieveGxsMsgMetaData(const GxsMsgReq& reqIds, GxsMsgMetaRes
         if(msgIdV.empty()){
             RetroCursor* c = mDb->sqlQuery(MSG_TABLE_NAME, msgMetaColumns, KEY_GRP_ID+ "='" + grpId.toStdString() + "'", "");
 
+            if (c)
+            {
                 locked_retrieveMsgMeta(c, metaSet);
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+                resultCount += metaSet.size();
+#endif
+            }
         }else{
 
             // request each grp
@@ -1168,13 +1228,24 @@ int RsDataService::retrieveGxsMsgMetaData(const GxsMsgReq& reqIds, GxsMsgMetaRes
                 RetroCursor* c = mDb->sqlQuery(MSG_TABLE_NAME, msgMetaColumns, KEY_GRP_ID+ "='" + grpId.toStdString()
                                                + "' AND " + KEY_MSG_ID + "='" + msgId.toStdString() + "'", "");
 
+                if (c)
+                {
                     locked_retrieveMsgMeta(c, metaSet);
+
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+                    resultCount += c->getResultCount();
+#endif
+                }
             }
         }
 
         msgMeta[grpId] = metaSet;
     }
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    std::cerr << "RsDataService::retrieveGxsMsgMetaData() Requests: " << reqIds.size() << ", Results: " << resultCount << ", Time: " << timer.duration() << std::endl;
+#endif
+
     return 1;
 }
 
@@ -1205,6 +1276,10 @@ int RsDataService::retrieveGxsGrpMetaData(std::map<RsGxsGroupId, RsGxsGrpMetaDat
 
     RsStackMutex stack(mDbMutex);
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    RsScopeTimer timer("");
+#endif
+
     if(grp.empty()){
 
 #ifdef RS_DATA_SERVICE_DEBUG
@@ -1260,6 +1335,9 @@ int RsDataService::retrieveGxsGrpMetaData(std::map<RsGxsGroupId, RsGxsGrpMetaDat
 
       }
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+    std::cerr << "RsDataService::retrieveGxsGrpMetaData() Time: " << timer.duration() << std::endl;
+#endif
 
     return 1;
 }
@@ -1450,6 +1528,11 @@ int RsDataService::retrieveGroupIds(std::vector<RsGxsGroupId> &grpIds)
 {
     RsStackMutex stack(mDbMutex);
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+	RsScopeTimer timer("");
+	int resultCount = 0;
+#endif
+
 	RetroCursor* c = mDb->sqlQuery(GRP_TABLE_NAME, grpIdColumn, "", "");
 
 	if(c)
@@ -1462,6 +1545,10 @@ int RsDataService::retrieveGroupIds(std::vector<RsGxsGroupId> &grpIds)
 			c->getString(0, grpId);
 			grpIds.push_back(RsGxsGroupId(grpId));
 			valid = c->moveToNext();
+
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+			++resultCount;
+#endif
 		}
 		delete c;
 	}else
@@ -1469,11 +1556,19 @@ int RsDataService::retrieveGroupIds(std::vector<RsGxsGroupId> &grpIds)
 		return 0;
 	}
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+	std::cerr << "RsDataService::retrieveGroupIds() Results: " << resultCount << ", Time: " << timer.duration() << std::endl;
+#endif
+
 	return 1;
 }
 
-int RsDataService::retrieveMsgIds(const RsGxsGroupId& grpId,
+int RsDataService::retrieveMsgIds(const RsGxsGroupId& grpId, RsGxsMessageId::std_vector& msgIds)
-		RsGxsMessageId::std_vector& msgIds) {
+{
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+	RsScopeTimer timer("");
+	int resultCount = 0;
+#endif
 
 	RetroCursor* c = mDb->sqlQuery(MSG_TABLE_NAME, mMsgIdColumn, KEY_GRP_ID+ "='" + grpId.toStdString() + "'", "");
 
@@ -1491,6 +1586,10 @@ int RsDataService::retrieveMsgIds(const RsGxsGroupId& grpId,
 
 			msgIds.push_back(RsGxsMessageId(msgId));
 			valid = c->moveToNext();
+
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+			++resultCount;
+#endif
 		}
 		delete c;
 	}else
@@ -1498,6 +1597,10 @@ int RsDataService::retrieveMsgIds(const RsGxsGroupId& grpId,
 		return 0;
 	}
 
+#ifdef RS_DATA_SERVICE_DEBUG_TIME
+	std::cerr << "RsDataService::retrieveNxsGrps() Results: " << resultCount << ", Time: " << timer.duration() << std::endl;
+#endif
+
 	return 1;
 
 }

libretroshare/src/libretroshare.pro

@@ -483,6 +483,7 @@ HEADERS +=	util/folderiterator.h \
 			util/rsmemcache.h \
 			util/rstickevent.h \
 			util/rsrecogn.h \
+			util/rsscopetimer.h
 
 SOURCES +=	dbase/cachestrapper.cc \
 			dbase/fimonitor.cc \
@@ -632,6 +633,7 @@ SOURCES +=	util/folderiterator.cc \
 			util/rsrandom.cc \
 			util/rstickevent.cc \
 			util/rsrecogn.cc \
+			util/rsscopetimer.cc
 
 
 upnp_miniupnpc {

libretroshare/src/util/rsscopetimer.cc

@@ -0,0 +1,59 @@
+/*
+ * libretroshare/src/util: rsscopetimer.cc
+ *
+ * 3P/PQI network interface for RetroShare.
+ *
+ * Copyright 2013-     by Cyril Soler
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Library General Public
+ * License Version 2 as published by the Free Software Foundation.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Library General Public License for more details.
+ *
+ * You should have received a copy of the GNU Library General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307
+ * USA.
+ *
+ * Please report all bugs and problems to "retroshare@lunamutt.com".
+ *
+ */
+
+#include <iostream>
+#include <sys/time.h>
+#include "rsscopetimer.h"
+
+RsScopeTimer::RsScopeTimer(const std::string& name)
+{
+	_name = name ;
+	start();
+}
+
+RsScopeTimer::~RsScopeTimer()
+{
+	if (!_name.empty())
+	{
+		std::cerr << "Time for \"" << _name << "\": " << duration() << std::endl;
+	}
+}
+
+double RsScopeTimer::currentTime()
+{
+	timeval tv ;
+	gettimeofday(&tv,NULL) ;
+	return (tv.tv_sec % 10000) + tv.tv_usec/1000000.0f ;	// the %1000 is here to allow double precision to cover the decimals.
+}
+
+void RsScopeTimer::start()
+{
+	_seconds = currentTime();
+}
+
+double RsScopeTimer::duration()
+{
+	return currentTime() - _seconds;
+}

libretroshare/src/util/rsscopetimer.h

@@ -31,27 +31,20 @@
 //     callToMeasure() ;
 // }
 //
-#include <sys/time.h>
+
+#include <string>
 
 class RsScopeTimer
 {
 public:
-		RsScopeTimer(const std::string& name)
+	RsScopeTimer(const std::string& name);
-		{
+	~RsScopeTimer();
-			timeval tv ;
-			gettimeofday(&tv,NULL) ;
-			_seconds = (tv.tv_sec % 10000) + tv.tv_usec/1000000.0f ;	// the %1000 is here to allow double precision to cover the decimals.
-			_name = name ;
-		}
 
-		~RsScopeTimer()
+	void start();
-		{
+	double duration();
-			timeval tv ;
-			gettimeofday(&tv,NULL) ;
-			double ss = (tv.tv_sec % 10000) + tv.tv_usec/1000000.0f ;
 
-			std::cerr << "Time for \"" << _name << "\": " << ss - _seconds << std::endl;
+private:
-		}
+	double currentTime();
 
 private:
 	std::string _name ;