consolidated time() calls in rule engine

... but did not manage to avoid doing at least one call. So
this change introduced performance benefit only in a few
non-common situations. Anyhow, it hopefully levels ground
for better things to come.

3 files changed, 74 insertions, 34 deletions

diff --git a/action.c b/action.c
index 4cfe5f07..5c5bdbe9 100644
--- a/action.c
+++ b/action.c
@@ -91,6 +91,44 @@ static int iActionNbr = 0;
 
 /* ------------------------------ methods ------------------------------ */ 
 
+/* This function returns the "current" time for this action. Current time
+ * is not necessarily real-time. In order to enhance performance, current
+ * system time is obtained the first time an action needs to know the time
+ * and then kept cached inside the action structure. Later requests will
+ * always return that very same time. Wile not totally accurate, it is far
+ * accurate in most cases and considered "acurate enough" for all cases.
+ * When changing the threading model, please keep in mind that this
+ * logic needs to be changed should we once allow more than one parallel
+ * call into the same action (object). As this is currently not supported,
+ * we simply cache the time inside the action object itself, after it
+ * is under mutex protection.
+ * Side-note: the value -1 is used as tActNow, because it also is the
+ * error return value of time(). So we would do a retry with the next
+ * invocation if time() failed. Then, of course, we would probably already
+ * be in trouble, but for the sake of performance we accept this very,
+ * very slight risk.
+ * This logic has been added as part of an overall performance improvment
+ * effort inspired by David Lang. -- rgerhards, 2008-09-16
+ * Note: this function does not use the usual iRet call conventions
+ * because that would provide little to no benefit but complicate things
+ * a lot. So we simply return the system time.
+ */
+static inline time_t
+getActNow(action_t *pThis)
+{
+	assert(pThis != NULL);
+	if(pThis->tActNow == -1) {
+		pThis->tActNow = time(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;
+		}
+	}
+
+	return pThis->tActNow;
+}
+
+
 /* resets action queue parameters to their default values. This happens
  * after each action has been created in order to prevent any wild defaults
  * to be used. It is somewhat against the original spirit of the config file
@@ -176,7 +214,7 @@ rsRetVal actionConstruct(action_t **ppThis)
 
 	pThis->iResumeInterval = glbliActionResumeInterval;
 	pThis->iResumeRetryCount = glbliActionResumeRetryCount;
-	pThis->tLastOccur = time(NULL);
+	pThis->tLastOccur = time(NULL);	/* done once per action on startup only */
 	pthread_mutex_init(&pThis->mutActExec, NULL);
 	SYNC_OBJ_TOOL_INIT(pThis);
 
@@ -290,30 +328,31 @@ rsRetVal actionSetGlobalResumeInterval(int iNewVal)
 
 /* suspend an action -- rgerhards, 2007-08-02
  */
-rsRetVal actionSuspend(action_t *pThis)
+static rsRetVal actionSuspend(action_t *pThis, time_t tNow)
 {
 	DEFiRet;
 
 	ASSERT(pThis != NULL);
 	pThis->bSuspended = 1;
-	pThis->ttResumeRtry = time(NULL) + pThis->iResumeInterval;
+	pThis->ttResumeRtry = tNow + pThis->iResumeInterval;
 	pThis->iNbrResRtry = 0; /* tell that we did not yet retry to resume */
 
 	RETiRet;
 }
 
+
 /* try to resume an action -- rgerhards, 2007-08-02
  * returns RS_RET_OK if resumption worked, RS_RET_SUSPEND if the
  * action is still suspended.
  */
-rsRetVal actionTryResume(action_t *pThis)
+static rsRetVal actionTryResume(action_t *pThis)
 {
 	DEFiRet;
 	time_t ttNow;
 
 	ASSERT(pThis != NULL);
 
-	ttNow = time(NULL); /* do the system call just once */
+	ttNow = getActNow(pThis); /* cache "now" */
 
 	/* first check if it is time for a re-try */
 	if(ttNow > pThis->ttResumeRtry) {
@@ -432,7 +471,7 @@ actionCallDoAction(action_t *pAction, msg_t *pMsg)
 			iRet = pAction->pMod->mod.om.doAction(ppMsgs, pMsg->msgFlags, pAction->pModData);
 			if(iRet == RS_RET_SUSPENDED) {
 				dbgprintf("Action requested to be suspended, done that.\n");
-				actionSuspend(pAction);
+				actionSuspend(pAction, getActNow(pAction));
 			}
 		}
 
@@ -509,15 +548,9 @@ actionWriteToAction(action_t *pAction)
 {
 	msg_t *pMsgSave;	/* to save current message pointer, necessary to restore
 				   it in case it needs to be updated (e.g. repeated msgs) */
-	time_t now;
 	DEFiRet;
 
 	pMsgSave = NULL;	/* indicate message poiner not saved */
-	time(&now); /* we need this for several use cases, but obtain it once for performance reasons */
-	if(pAction->tLastExec > now) {
-		/* if we are traveling back in time, reset tLastExec */
-		pAction->tLastExec = (time_t) 0;
-	}
 
 	/* first, we check if the action should actually be called. The action-specific
 	 * $ActionExecOnlyEveryNthTime permits us to execute an action only every Nth
@@ -529,11 +562,11 @@ actionWriteToAction(action_t *pAction)
 	if(pAction->iExecEveryNthOccur > 1) {
 		/* we need to care about multiple occurences */
 		if(   pAction->iExecEveryNthOccurTO > 0
-		   && (now - pAction->tLastOccur) > pAction->iExecEveryNthOccurTO) {
+		   && (getActNow(pAction) - pAction->tLastOccur) > pAction->iExecEveryNthOccurTO) {
 		  	dbgprintf("n-th occurence handling timed out (%d sec), restarting from 0\n",
-				  (int) (now - pAction->tLastOccur));
+				  (int) (getActNow(pAction) - pAction->tLastOccur));
 			pAction->iNbrNoExec = 0;
-			pAction->tLastOccur = now;
+			pAction->tLastOccur = getActNow(pAction);
 		   }
 		if(pAction->iNbrNoExec < pAction->iExecEveryNthOccur - 1) {
 			++pAction->iNbrNoExec;
@@ -570,7 +603,7 @@ actionWriteToAction(action_t *pAction)
 		 * signatures inside the message are also invalidated.
 		 */
 		datetime.getCurrTime(&(pMsg->tRcvdAt));
-		datetime.getCurrTime(&(pMsg->tTIMESTAMP));
+		memcpy(&pMsg->tTIMESTAMP, &pMsg->tRcvdAt, sizeof(struct syslogTime));
 		MsgSetMSG(pMsg, (char*)szRepMsg);
 		MsgSetRawMsg(pMsg, (char*)szRepMsg);
 
@@ -582,17 +615,23 @@ actionWriteToAction(action_t *pAction)
 
 	/* now check if we need to drop the message because otherwise the action would be too
 	 * frequently called. -- rgerhards, 2008-04-08
+	 * Note that the check for "pAction->iSecsExecOnceInterval > 0" is not necessary from
+	 * a purely logical point of view. However, if safes us to check the system time in
+	 * (those common) cases where ExecOnceInterval is not used. -- rgerhards, 2008-09-16
 	 */
-	if(pAction->f_time != 0 && pAction->iSecsExecOnceInterval + pAction->tLastExec > now) {
+	if(pAction->f_time != 0 && pAction->iSecsExecOnceInterval > 0 &&
+	   pAction->iSecsExecOnceInterval + pAction->tLastExec > getActNow(pAction)) {
 		/* in this case we need to discard the message - its not yet time to exec the action */
 		dbgprintf("action not yet ready again to be executed, onceInterval %d, tCurr %d, tNext %d\n",
-			  (int) pAction->iSecsExecOnceInterval, (int) now,
+			  (int) pAction->iSecsExecOnceInterval, (int) getActNow(pAction),
 			  (int) (pAction->iSecsExecOnceInterval + pAction->tLastExec));
 		FINALIZE;
 	}
 
-	pAction->tLastExec = now; /* we need this OnceInterval */
-	pAction->f_time = now; /* we need this for message repeation processing */
+	pAction->f_time = pAction->tLastExec = getActNow(pAction); /* re-init time flags */
+	/* Note: tLastExec could be set in the if block above, but f_time causes us a hard time
+	 * so far, I do not see a solution to getting rid of it. -- rgerhards, 2008-09-16
+	 */
 
 	/* When we reach this point, we have a valid, non-disabled action.
 	 * So let's enqueue our message for execution. -- rgerhards, 2007-07-24
@@ -623,6 +662,10 @@ finalize_it:
 
 /* call the configured action. Does all necessary housekeeping.
  * rgerhards, 2007-08-01
+ * FYI: currently, this function is only called from the queue
+ * consumer. So we (conceptually) run detached from the input
+ * threads (which also means we may run much later than when the
+ * message was generated).
  */
 #pragma GCC diagnostic ignored "-Wempty-body"
 rsRetVal
@@ -657,13 +700,14 @@ actionCallAction(action_t *pAction, msg_t *pMsg)
 		ABORT_FINALIZE(RS_RET_OK);
 	}
 
-	/* don't output marks to recently written files */
-	if ((pMsg->msgFlags & MARK) && (time(NULL) - pAction->f_time) < MarkInterval / 2) {
+	pAction->tActNow = -1; /* we do not yet know our current time (clear prev. value) */
+
+	/* don't output marks to recently written outputs */
+	if((pMsg->msgFlags & MARK) && (getActNow(pAction) - pAction->f_time) < MarkInterval / 2) {
 		ABORT_FINALIZE(RS_RET_OK);
 	}
 
-	/* suppress duplicate messages
-	 */
+	/* suppress duplicate messages */
 	if ((pAction->f_ReduceRepeated == 1) && pAction->f_pMsg != NULL &&
 	    (pMsg->msgFlags & MARK) == 0 && getMSGLen(pMsg) == getMSGLen(pAction->f_pMsg) &&
 	    !strcmp(getMSG(pMsg), getMSG(pAction->f_pMsg)) &&
@@ -672,7 +716,7 @@ actionCallAction(action_t *pAction, msg_t *pMsg)
 	    !strcmp(getAPPNAME(pMsg), getAPPNAME(pAction->f_pMsg))) {
 		pAction->f_prevcount++;
 		dbgprintf("msg repeated %d times, %ld sec of %d.\n",
-		    pAction->f_prevcount, (long) time(NULL) - pAction->f_time,
+		    pAction->f_prevcount, (long) getActNow(pAction) - pAction->f_time,
 		    repeatinterval[pAction->f_repeatcount]);
 		/* use current message, so we have the new timestamp (means we need to discard previous one) */
 		msgDestruct(&pAction->f_pMsg);
@@ -680,12 +724,11 @@ actionCallAction(action_t *pAction, msg_t *pMsg)
 		/* If domark would have logged this by now, flush it now (so we don't hold
 		 * isolated messages), but back off so we'll flush less often in the future.
 		 */
-		if(time(NULL) > REPEATTIME(pAction)) {
+		if(getActNow(pAction) > REPEATTIME(pAction)) {
 			iRet = actionWriteToAction(pAction);
 			BACKOFF(pAction);
 		}
-	} else {
-		/* new message, save it */
+	} else {/* new message, save it */
 		/* first check if we have a previous message stored
 		 * if so, emit and then discard it first
 		 */
@@ -830,7 +873,7 @@ addAction(action_t **ppAction, modInfo_t *pMod, void *pModData, omodStringReques
 	pAction->bEnabled = 1; /* action is enabled */
 
 	if(bSuspended)
-		actionSuspend(pAction);
+		actionSuspend(pAction, time(NULL)); /* "good" time call, only during init and unavoidable */
 
 	CHKiRet(actionConstructFinalize(pAction));
 	
diff --git a/action.h b/action.h
index c910fc1c..d26d15b6 100644
--- a/action.h
+++ b/action.h
@@ -40,6 +40,8 @@ extern int glbliActionResumeRetryCount;
  */
 struct action_s {
 	time_t	f_time;		/* used for "message repeated n times" - be careful, old, old code */
+	time_t	tActNow;	/* the current time for an action execution. Initially set to -1 and
+				   populated on an as-needed basis. This is a performance optimization. */
 	time_t	tLastExec;	/* time this action was last executed */
 	int	bExecWhenPrevSusp;/* execute only when previous action is suspended? */
 	int	iSecsExecOnceInterval; /* if non-zero, minimum seconds to wait until action is executed again */
@@ -78,8 +80,6 @@ rsRetVal actionConstruct(action_t **ppThis);
 rsRetVal actionConstructFinalize(action_t *pThis);
 rsRetVal actionDestruct(action_t *pThis);
 rsRetVal actionAddCfSysLineHdrl(void);
-rsRetVal actionTryResume(action_t *pThis);
-rsRetVal actionSuspend(action_t *pThis);
 rsRetVal actionDbgPrint(action_t *pThis);
 rsRetVal actionSetGlobalResumeInterval(int iNewVal);
 rsRetVal actionDoAction(action_t *pAction);
diff --git a/tools/syslogd.c b/tools/syslogd.c
index f51947bf..b6e1d826 100644
--- a/tools/syslogd.c
+++ b/tools/syslogd.c
@@ -1167,9 +1167,6 @@ processMsg(msg_t *pMsg)
 /* The consumer of dequeued messages. This function is called by the
  * queue engine on dequeueing of a message. It runs on a SEPARATE
  * THREAD.
- * NOTE: Having more than one worker requires guarding of some
- * message object structures and potentially others - need to be checked
- * before we support multiple worker threads on the message queue.
  * Please note: the message object is destructed by the queue itself!
  */
 static rsRetVal