some light performance enhancement

...by replacing time() call with much faster (at least under linux)
gettimeofday() calls.

13 files changed, 57 insertions, 20 deletions

diff --git a/ChangeLog b/ChangeLog
index b484963e..0d9c1b84 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,7 @@
 ---------------------------------------------------------------------------
 Version 5.3.5  [DEVEL] (rgerhards), 2009-11-??
+- some light performance enhancement by replacing time() call with much
+  faster (at least under linux) gettimeofday() calls.
 - some improvement of omfile performance with dynafiles
   saved costly time() calls by employing a logical clock, which is 
   sufficient for the use case
diff --git a/action.c b/action.c
index 5958214f..07f14c24 100644
--- a/action.c
+++ b/action.c
@@ -129,7 +129,7 @@ getActNow(action_t *pThis)
 {
 	assert(pThis != NULL);
 	if(pThis->tActNow == -1) {
-		pThis->tActNow = time(NULL); /* good time call - the only one done */
+		pThis->tActNow = datetime.GetTime(NULL); /* good time call - the only one done */
 		if(pThis->tLastExec > pThis->tActNow) {
 			/* if we are traveling back in time, reset tLastExec */
 			pThis->tLastExec = (time_t) 0;
@@ -254,7 +254,7 @@ rsRetVal actionConstruct(action_t **ppThis)
 	CHKmalloc(pThis = (action_t*) calloc(1, sizeof(action_t)));
 	pThis->iResumeInterval = glbliActionResumeInterval;
 	pThis->iResumeRetryCount = glbliActionResumeRetryCount;
-	pThis->tLastOccur = time(NULL);	/* done once per action on startup only */
+	pThis->tLastOccur = datetime.GetTime(NULL);	/* done once per action on startup only */
 	pthread_mutex_init(&pThis->mutActExec, NULL);
 	SYNC_OBJ_TOOL_INIT(pThis);
 
@@ -470,7 +470,7 @@ static void actionDisable(action_t *pThis)
 static inline void actionSuspend(action_t *pThis, time_t ttNow)
 {
 	if(ttNow == NO_TIME_PROVIDED)
-		time(&ttNow);
+		datetime.GetTime(&ttNow);
 	pThis->ttResumeRtry = ttNow + pThis->iResumeInterval * (pThis->iNbrResRtry / 10 + 1);
 	actionSetState(pThis, ACT_STATE_SUSP);
 	DBGPRINTF("earliest retry=%d\n", (int) pThis->ttResumeRtry);
@@ -538,7 +538,7 @@ static rsRetVal actionTryResume(action_t *pThis)
 		 * is always in the past. So we can not avoid doing a fresh time() call
 		 * here. -- rgerhards, 2009-03-18
 		 */
-		time(&ttNow); /* cache "now" */
+		datetime.GetTime(&ttNow); /* cache "now" */
 		if(ttNow > pThis->ttResumeRtry) {
 			actionSetState(pThis, ACT_STATE_RTRY); /* back to retries */
 		}
@@ -546,7 +546,7 @@ static rsRetVal actionTryResume(action_t *pThis)
 
 	if(pThis->eState == ACT_STATE_RTRY) {
 		if(ttNow == NO_TIME_PROVIDED) /* use cached result if we have it */
-			time(&ttNow);
+			datetime.GetTime(&ttNow);
 		CHKiRet(actionDoRetry(pThis, ttNow));
 	}
 
@@ -1361,7 +1361,7 @@ addAction(action_t **ppAction, modInfo_t *pMod, void *pModData, omodStringReques
 	pAction->eState = ACT_STATE_RDY; /* action is enabled */
 
 	if(bSuspended)
-		actionSuspend(pAction, time(NULL)); /* "good" time call, only during init and unavoidable */
+		actionSuspend(pAction, datetime.GetTime(NULL)); /* "good" time call, only during init and unavoidable */
 
 	CHKiRet(actionConstructFinalize(pAction));
 	
diff --git a/plugins/imudp/imudp.c b/plugins/imudp/imudp.c
index 5fe82470..307b684f 100644
--- a/plugins/imudp/imudp.c
+++ b/plugins/imudp/imudp.c
@@ -252,7 +252,7 @@ processSocket(thrdInfo_t *pThrd, int fd, struct sockaddr_storage *frominetPrev,
 				if(glbl.GetOption_DisallowWarning) {
 					time_t tt;
 
-					time(&tt);
+					datetime.GetTime(&tt);
 					if(tt > ttLastDiscard + 60) {
 						ttLastDiscard = tt;
 						errmsg.LogError(0, NO_ERRCODE,
diff --git a/plugins/ommail/ommail.c b/plugins/ommail/ommail.c
index 3a7669c9..324e1a77 100644
--- a/plugins/ommail/ommail.c
+++ b/plugins/ommail/ommail.c
@@ -50,6 +50,7 @@
 #include "cfsysline.h"
 #include "module-template.h"
 #include "errmsg.h"
+#include "datetime.h"
 #include "glbl.h"
 
 MODULE_TYPE_OUTPUT
@@ -59,6 +60,7 @@ MODULE_TYPE_OUTPUT
 DEF_OMOD_STATIC_DATA
 DEFobjCurrIf(errmsg)
 DEFobjCurrIf(glbl)
+DEFobjCurrIf(datetime)
 
 /* we add a little support for multiple recipients. We do this via a
  * singly-linked list, enqueued from the top. -- rgerhards, 2008-08-04
@@ -478,7 +480,7 @@ mkSMTPTimestamp(uchar *pszBuf, size_t lenBuf)
 	static const char szDay[][4] = {"Sun", "Mon", "Tue", "Wed", "Thu", "Fri", "Sat"};
 	static const char szMonth[][4] = {"Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec"};
 
-	time(&tCurr);
+	datetime.GetTime(&tCurr);
 	gmtime_r(&tCurr, &tmCurr);
 	snprintf((char*)pszBuf, lenBuf, "Date: %s, %2d %s %4d %2d:%02d:%02d UT\r\n", szDay[tmCurr.tm_wday], tmCurr.tm_mday,
 		 szMonth[tmCurr.tm_mon], 1900 + tmCurr.tm_year, tmCurr.tm_hour, tmCurr.tm_min, tmCurr.tm_sec);
@@ -669,6 +671,7 @@ CODESTARTmodExit
 	freeConfigVariables();
 
 	/* release what we no longer need */
+	objRelease(datetime, CORE_COMPONENT);
 	objRelease(glbl, CORE_COMPONENT);
 	objRelease(errmsg, CORE_COMPONENT);
 ENDmodExit
@@ -698,6 +701,7 @@ CODEmodInit_QueryRegCFSLineHdlr
 	/* tell which objects we need */
 	CHKiRet(objUse(errmsg, CORE_COMPONENT));
 	CHKiRet(objUse(glbl, CORE_COMPONENT));
+	CHKiRet(objUse(datetime, CORE_COMPONENT));
 
 	dbgprintf("ommail version %s initializing\n", VERSION);
 
diff --git a/runtime/apc.c b/runtime/apc.c
index c2f61266..3c6b7ec4 100644
--- a/runtime/apc.c
+++ b/runtime/apc.c
@@ -40,9 +40,11 @@
 #include "obj.h"
 #include "apc.h"
 #include "srUtils.h"
+#include "datetime.h"
 
 /* static data */
 DEFobjStaticHelpers
+DEFobjCurrIf(datetime)
 
 /* following is a used to implement a monotonically increasing id for the apcs. That
  * ID can be used to cancel an apc request. Note that the ID is generated with modulo
@@ -200,7 +202,7 @@ unlistCurrent(apc_list_t **ppList)
 	DEFiRet;
 	assert(ppList != NULL);
 
-	time(&tCurr);
+	datetime.GetTime(&tCurr);
 
 	if(apcListRoot == NULL || apcListRoot->pApc->ttExec >  tCurr) {
 		*ppList = NULL;
@@ -375,7 +377,7 @@ ENDobjQueryInterface(apc)
  * rgerhards, 2009-04-06
  */
 BEGINObjClassExit(apc, OBJ_IS_CORE_MODULE) /* class, version */
-	//objRelease(apcstk, CORE_COMPONENT);
+	objRelease(datetime, CORE_COMPONENT);
 	pthread_mutex_destroy(&listMutex);
 ENDObjClassExit(apc)
 
@@ -386,7 +388,7 @@ ENDObjClassExit(apc)
  */
 BEGINObjClassInit(apc, 1, OBJ_IS_CORE_MODULE) /* class, version */
 	/* request objects we use */
-	//CHKiRet(objUse(apcstk, CORE_COMPONENT));
+	CHKiRet(objUse(datetime, CORE_COMPONENT));
 
 	/* set our own handlers */
 	OBJSetMethodHandler(objMethod_DEBUGPRINT, apcDebugPrint);
diff --git a/runtime/datetime.c b/runtime/datetime.c
index 6160bd7c..4ab4318d 100644
--- a/runtime/datetime.c
+++ b/runtime/datetime.c
@@ -127,6 +127,24 @@ static void getCurrTime(struct syslogTime *t, time_t *ttSeconds)
 }
 
 
+/* A fast alternative to getCurrTime() and time() that only obtains
+ * a timestamp like time() does. I was told that gettimeofday(), at
+ * least under Linux, is much faster than time() and I could confirm
+ * this testing. So I created that function as a replacement.
+ * rgerhards, 2009-11-12
+ */
+static time_t
+getTime(time_t *ttSeconds)
+{
+	struct timeval tp;
+
+	if(gettimeofday(&tp, NULL) == -1)
+		return -1;
+
+	if(ttSeconds != NULL)
+		*ttSeconds = tp.tv_sec;
+	return tp.tv_sec;
+}
 
 
 /*******************************************************************
@@ -831,6 +849,7 @@ CODESTARTobjQueryInterface(datetime)
 	 * of course, also affects the "if" above).
 	 */
 	pIf->getCurrTime = getCurrTime;
+	pIf->GetTime = getTime;
 	pIf->ParseTIMESTAMP3339 = ParseTIMESTAMP3339;
 	pIf->ParseTIMESTAMP3164 = ParseTIMESTAMP3164;
 	pIf->formatTimestampToMySQL = formatTimestampToMySQL;
diff --git a/runtime/datetime.h b/runtime/datetime.h
index 8140eb71..1de3db95 100644
--- a/runtime/datetime.h
+++ b/runtime/datetime.h
@@ -41,8 +41,10 @@ BEGINinterface(datetime) /* name must also be changed in ENDinterface macro! */
 	int (*formatTimestamp3339)(struct syslogTime *ts, char* pBuf);
 	int (*formatTimestamp3164)(struct syslogTime *ts, char* pBuf);
 	int (*formatTimestampSecFrac)(struct syslogTime *ts, char* pBuf);
+	/* v3, 2009-11-12 */
+	time_t (*GetTime)(time_t *ttSeconds);
 ENDinterface(datetime)
-#define datetimeCURR_IF_VERSION 2 /* increment whenever you change the interface structure! */
+#define datetimeCURR_IF_VERSION 3 /* increment whenever you change the interface structure! */
 /* interface changes:
  * 1 - initial version
  * 2 - not compatible to 1 - bugfix required ParseTIMESTAMP3164 to accept char ** as
diff --git a/runtime/nsd_gtls.c b/runtime/nsd_gtls.c
index 846b1d89..74c142f2 100644
--- a/runtime/nsd_gtls.c
+++ b/runtime/nsd_gtls.c
@@ -44,6 +44,7 @@
 #include "stringbuf.h"
 #include "errmsg.h"
 #include "net.h"
+#include "datetime.h"
 #include "nsd_ptcp.h"
 #include "nsdsel_gtls.h"
 #include "nsd_gtls.h"
@@ -61,6 +62,7 @@ DEFobjStaticHelpers
 DEFobjCurrIf(errmsg)
 DEFobjCurrIf(glbl)
 DEFobjCurrIf(net)
+DEFobjCurrIf(datetime)
 DEFobjCurrIf(nsd_ptcp)
 
 static int bGlblSrvrInitDone = 0;	/**< 0 - server global init not yet done, 1 - already done */
@@ -1016,7 +1018,7 @@ gtlsChkPeerCertValidity(nsd_gtls_t *pThis)
 	}
 
 	/* get current time for certificate validation */
-	if(time(&ttNow) == -1)
+	if(datetime.GetTime(&ttNow) == -1)
 		ABORT_FINALIZE(RS_RET_SYS_ERR);
 
 	/* as it looks, we need to validate the expiration dates ourselves...
@@ -1694,6 +1696,7 @@ CODESTARTObjClassExit(nsd_gtls)
 	objRelease(nsd_ptcp, LM_NSD_PTCP_FILENAME);
 	objRelease(net, LM_NET_FILENAME);
 	objRelease(glbl, CORE_COMPONENT);
+	objRelease(datetime, CORE_COMPONENT);
 	objRelease(errmsg, CORE_COMPONENT);
 ENDObjClassExit(nsd_gtls)
 
@@ -1705,6 +1708,7 @@ ENDObjClassExit(nsd_gtls)
 BEGINObjClassInit(nsd_gtls, 1, OBJ_IS_LOADABLE_MODULE) /* class, version */
 	/* request objects we use */
 	CHKiRet(objUse(errmsg, CORE_COMPONENT));
+	CHKiRet(objUse(datetime, CORE_COMPONENT));
 	CHKiRet(objUse(glbl, CORE_COMPONENT));
 	CHKiRet(objUse(net, LM_NET_FILENAME));
 	CHKiRet(objUse(nsd_ptcp, LM_NSD_PTCP_FILENAME));
diff --git a/runtime/obj.c b/runtime/obj.c
index 3692b957..45dac776 100644
--- a/runtime/obj.c
+++ b/runtime/obj.c
@@ -48,7 +48,7 @@
  *
  * File begun on 2008-01-04 by RGerhards
  *
- * Copyright 2008 Rainer Gerhards and Adiscon GmbH.
+ * Copyright 2008, 2009 Rainer Gerhards and Adiscon GmbH.
  *
  * This file is part of the rsyslog runtime library.
  *
@@ -90,6 +90,7 @@
 #include "cfsysline.h"
 #include "unicode-helper.h"
 #include "apc.h"
+#include "datetime.h"
 
 /* static data */
 DEFobjCurrIf(obj) /* we define our own interface, as this is expected by some macros! */
@@ -1330,8 +1331,9 @@ objClassInit(modInfo_t *pModInfo)
 	CHKiRet(objGetObjInterface(&obj)); /* get ourselves ;) */
 
 	/* init classes we use (limit to as few as possible!) */
-	CHKiRet(apcClassInit(pModInfo));
 	CHKiRet(errmsgClassInit(pModInfo));
+	CHKiRet(datetimeClassInit(pModInfo));
+	CHKiRet(apcClassInit(pModInfo));
 	CHKiRet(cfsyslineInit());
 	CHKiRet(varClassInit(pModInfo));
 	CHKiRet(moduleClassInit(pModInfo));
diff --git a/runtime/queue.c b/runtime/queue.c
index 1c885925..b29ec7ac 100644
--- a/runtime/queue.c
+++ b/runtime/queue.c
@@ -56,6 +56,7 @@
 #include "msg.h"
 #include "atomic.h"
 #include "errmsg.h"
+#include "datetime.h"
 #include "unicode-helper.h"
 #include "msg.h" /* TODO: remove once we remove MsgAddRef() call */
 
@@ -68,6 +69,7 @@ DEFobjStaticHelpers
 DEFobjCurrIf(glbl)
 DEFobjCurrIf(strm)
 DEFobjCurrIf(errmsg)
+DEFobjCurrIf(datetime)
 
 /* forward-definitions */
 static inline rsRetVal doEnqSingleObj(qqueue_t *pThis, flowControl_t flowCtlType, void *pUsr);
@@ -1526,7 +1528,7 @@ RateLimiter(qqueue_t *pThis)
 	iDelay = 0;
 	if(pThis->iDeqtWinToHr != 25) { /* 25 means disabled */
 		/* time calls are expensive, so only do them when needed */
-		time(&tCurr);
+		datetime.GetTime(&tCurr);
 		localtime_r(&tCurr, &m);
 		iHrCurr = m.tm_hour;
 
@@ -2327,6 +2329,7 @@ BEGINObjClassInit(qqueue, 1, OBJ_IS_CORE_MODULE)
 	/* request objects we use */
 	CHKiRet(objUse(glbl, CORE_COMPONENT));
 	CHKiRet(objUse(strm, CORE_COMPONENT));
+	CHKiRet(objUse(datetime, CORE_COMPONENT));
 	CHKiRet(objUse(errmsg, CORE_COMPONENT));
 
 	/* now set our own handlers */
diff --git a/runtime/rsyslog.c b/runtime/rsyslog.c
index 8c44d16a..a76ae25a 100644
--- a/runtime/rsyslog.c
+++ b/runtime/rsyslog.c
@@ -152,8 +152,6 @@ rsrtInit(char **ppErrObj, obj_if_t *pObjIF)
 		CHKiRet(propClassInit(NULL));
 		if(ppErrObj != NULL) *ppErrObj = "glbl";
 		CHKiRet(glblClassInit(NULL));
-		if(ppErrObj != NULL) *ppErrObj = "datetime";
-		CHKiRet(datetimeClassInit(NULL));
 		if(ppErrObj != NULL) *ppErrObj = "msg";
 		CHKiRet(msgClassInit(NULL));
 		if(ppErrObj != NULL) *ppErrObj = "ctok_token";
diff --git a/tests/execonlyonce.sh b/tests/execonlyonce.sh
index a9b9d932..6ddc89b5 100755
--- a/tests/execonlyonce.sh
+++ b/tests/execonlyonce.sh
@@ -16,6 +16,7 @@ sleep 4 # one more than the once inerval!
 # and inject another couple of messages
 source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 10 100
 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
+source $srcdir/diag.sh wait-shutdown
 
 # now we need your custom logic to see if the result is equal to the
 # expected result
diff --git a/tools/syslogd.c b/tools/syslogd.c
index a8cba185..820cf273 100644
--- a/tools/syslogd.c
+++ b/tools/syslogd.c
@@ -706,7 +706,7 @@ DEFFUNC_llExecFunc(flushRptdMsgsActions)
 	 * the beginn of the llExec(). This makes it slightly less correct, but
 	 * in an acceptable way. -- rgerhards, 2008-09-16
 	 */
-	if (pAction->f_prevcount && time(NULL) >= REPEATTIME(pAction)) {
+	if (pAction->f_prevcount && datetime.GetTime(NULL) >= REPEATTIME(pAction)) {
 		DBGPRINTF("flush %s: repeated %d times, %d sec.\n",
 		    module.GetStateName(pAction->pMod), pAction->f_prevcount,
 		    repeatinterval[pAction->f_repeatcount]);
@@ -735,7 +735,7 @@ static void debug_switch()
 	struct tm tp;
 	struct sigaction sigAct;
 
-	time(&tTime);
+	datetime.GetTime(&tTime);
 	localtime_r(&tTime, &tp);
 	if(debugging_on == 0) {
 		debugging_on = 1;