From 3ee1865f9b1fc81a30416dadb1d7ced9e60b4413 Mon Sep 17 00:00:00 2001 From: koennecke Date: Wed, 29 Jun 2011 07:53:54 +0000 Subject: [PATCH] - Introduced a new trace facility - Fixed performance problems in many protocol drivers. SKIPPED: psi/julprot.c psi/phytron.c psi/pmacprot.c psi/polterwrite.c psi/spss7.c --- ascon.i | 3 +- conman.c | 22 +++ counter.c | 5 + devexec.c | 1 + devser.c | 7 +- devser.h | 2 + exebuf.c | 3 + genbinprot.c | 1 + histmem.c | 2 + hmdata.c | 1 + make_gen | 2 +- motor.c | 6 + motorsec.c | 16 +- nread.c | 6 + nserver.c | 4 + ofac.c | 2 + perfmon.c | 1 + rs232controller.c | 30 ++- scriptcontext.c | 101 ++++++++-- sics.h | 2 +- sicshipadaba.c | 2 +- sicsobj.c | 2 +- sicsutil.c | 86 +++++++++ sicsutil.h | 9 + sicvar.c | 12 +- test/DataNumber | 2 +- test/sicsstat.tcl | 8 +- test/testini.tcl | 46 ++++- testprot.c | 5 + trace.c | 482 ++++++++++++++++++++++++++++++++++++++++++++++ trace.h | 32 +++ 31 files changed, 868 insertions(+), 35 deletions(-) create mode 100644 trace.c create mode 100644 trace.h diff --git a/ascon.i b/ascon.i index df92d82c..02565009 100644 --- a/ascon.i +++ b/ascon.i @@ -88,7 +88,8 @@ struct Ascon { * value should be 1 * when the state was AsconReading, a 1 indicates that a character was read * and the character is stored in the lastChar field. A 0 indicates - * that no character was read. + * that no character was read. And this 0 has to be given, otherwise AsconTask + * goes into an endless loop till timeout is hit! * * * In most cases a custom handler may be a wrapper around AsconBaseHandler diff --git a/conman.c b/conman.c index 4f209a2b..c4d5ad78 100644 --- a/conman.c +++ b/conman.c @@ -114,7 +114,20 @@ static char *ConName(long ident) snprintf(name, sizeof(name), "CON%ld", ident); return name; } +/*--------------------------------------------------------------------------*/ +char *ConID(SConnection *pCon) +{ + static char id[132]; + char host[80]; + if(ANETvalidHandle(pCon->sockHandle)){ + ANETinfo(pCon->sockHandle, host, sizeof(host)); + snprintf(id,sizeof(id),"%s:%2.2d", host, pCon->sockHandle); + } else { + snprintf(id,sizeof(id),"disconnected:%2.2ld", pCon->ident); + } + return id; +} /*--------------------------------------------------------------------------*/ static void FreeConnection(SConnection * pCon) { @@ -576,6 +589,9 @@ int SCWrite(SConnection * self, char *pBuffer, int iOut) if (pBuffer == NULL) { return 0; } + if(!SCinMacro(self)){ + traceCommand(ConID(self),"out:%s", pBuffer); + } return self->write(self, pBuffer, iOut); } @@ -1033,6 +1049,9 @@ int SCWriteUUencoded(SConnection * pCon, char *pName, void *pData, ANETwrite(pCon->sockHandle, pPtr, iLength); } + traceCommand(ConID(pCon),"out:UUData %s %d", pName, iLength); + + #ifdef UUDEB fd = fopen("uubuffer.uu", "w"); fputs(pPtr, fd); @@ -1133,6 +1152,8 @@ int SCWriteZipped(SConnection * self, char *pName, void *pData, SCWrite(self, "ERROR: out of memory in SCWriteZipped", eError); return 0; } + traceCommand(ConID(self),"out:SICSBIN ZIP %s %d", pName, compressedLength); + /* now reset the deflater and do the same with writing data */ compStream.zalloc = (alloc_func) NULL; @@ -1411,6 +1432,7 @@ int SCInvoke(SConnection * self, SicsInterp * pInter, char *pCommand) } strlcpy(pCopy->deviceID, pBueffel, SCDEVIDLEN); /* SCAdvanceContext(self,pBueffel); */ + traceCommand(ConID(self),"in:%s", pCommand); iRet = InterpExecute(pInter, pCopy, pCommand); /* SCPopContext(self); */ SCDeleteConnection(pCopy); diff --git a/counter.c b/counter.c index 6e4ae892..ac9f6e5f 100644 --- a/counter.c +++ b/counter.c @@ -255,6 +255,7 @@ static int CheckCountStatus(void *pData, SConnection * pCon) self->badStatusCount = 0; /* clear: we managed to read OK */ if (self->iCallbackCounter > 20) { InvokeCallBack(self->pCall, MONITOR, &sMon); + tracePar(self->name,"control:%f", fControl); self->iCallbackCounter = 0; } else { self->iCallbackCounter++; @@ -521,11 +522,13 @@ static int SetCounterModeImpl(pCounter self, CounterMode eNew) for (i = 0; i < self->iExponent; i++) { self->pDriv->fPreset /= 10.; } + tracePar(self->name,"mode:timer"); } if (eNew == ePreset) { for (i = 0; i < self->iExponent; i++) { self->pDriv->fPreset *= 10.; } + tracePar(self->name,"mode:monitor"); } self->pDriv->eMode = eNew; return 1; @@ -578,6 +581,8 @@ static int SetCounterPresetImpl(pCounter self, float fVal) fVal = nintf(fVal); } self->pDriv->fPreset = fVal; + tracePar(self->name,"preset:%f", fVal); + return 1; } /*------------------------------------------------------------------------*/ diff --git a/devexec.c b/devexec.c index bd1e4b7d..91f2b8b9 100644 --- a/devexec.c +++ b/devexec.c @@ -115,6 +115,7 @@ void DevexecLog(char *operation, char *device) (long) tv.tv_sec, (long) tv.tv_usec); fflush(devLog); } + traceDevice("devexec","%s:%s",device, operation); } /*======================== internal data structures =======================*/ diff --git a/devser.c b/devser.c index 2418e24f..3deb1131 100644 --- a/devser.c +++ b/devser.c @@ -25,6 +25,7 @@ struct DevSer { double startTime; /* fields for statistics */ double comCount; long nComCount; + int comMaxState; double comMax; long errorCount; int inError; @@ -174,6 +175,9 @@ static void LogResponse(DevSer *self, int error) self->inError = 0; } self->startTime = -1; + if(responseTime > self->comMax/2.){ + self->comMaxState++; + } } static void StartAscon(DevSer *self) { @@ -196,7 +200,7 @@ static void AsconLog(DevSer *self) } } void DevStatistics(DevSer *devser, double *avg, double *max, - long *errCount, int *errState) + int *maxCount, long *errCount, int *errState) { if(devser->nComCount > 0){ *avg = devser->comCount/devser->nComCount; @@ -206,6 +210,7 @@ void DevStatistics(DevSer *devser, double *avg, double *max, *max = devser->comMax; *errCount = devser->errorCount; *errState = devser->inError; + *maxCount = devser->maxCount; } void DevAsconStatistics(DevSer *self, double *avg, \ double *max, int *maxState, int *longCount) diff --git a/devser.h b/devser.h index d0f14a35..a66b34b8 100644 --- a/devser.h +++ b/devser.h @@ -167,10 +167,12 @@ char * DevList(DevSer * devser); * \param devser The device serializer * \param avg The average response time * \param max The maximum response time + * \param maxCount how often the communication took longer then max/2. * \param errCount The count of communication errors detected so far. * \param errFlag A flag if the device is in an error state or not */ void DevStatistics(DevSer *devser, double *avg, double *max, + int *maxCount, long *errCount, int *errFlag); /** * \brief Get Ascon invocation statistics. This can help to stop diff --git a/exebuf.c b/exebuf.c index cb90be08..1ab096e5 100644 --- a/exebuf.c +++ b/exebuf.c @@ -20,6 +20,8 @@ #include "status.h" #include "commandlog.h" +char *ConID(SConnection *pCon); /* in conman.c */ + /*-----------------------------------------------------------------------*/ pExeBuf exeBufCreate(char *name) { @@ -262,6 +264,7 @@ int exeBufProcess(pExeBuf self, SicsInterp * pSics, } } + traceCommand(ConID(pCon),"batch:%s", cmd); status = Tcl_Eval(pTcl, cmd); if (status != TCL_OK) { if (pCon->sicsError == 0) { diff --git a/genbinprot.c b/genbinprot.c index e24d1e09..e6d34157 100644 --- a/genbinprot.c +++ b/genbinprot.c @@ -114,6 +114,7 @@ static int GenBinHandler(Ascon *a) a->state = AsconTimeout; } } + return 0; } } break; diff --git a/histmem.c b/histmem.c index 094fdbef..e026ecb1 100644 --- a/histmem.c +++ b/histmem.c @@ -597,6 +597,7 @@ int HistConfigure(pHistMem self, SConnection * pCon, SicsInterp * pSics) SCWrite(pCon, "ERROR: failed to configure histogram memory", eError); return 0; } + tracePar(self->pDes->name,"initialized"); return 1; } @@ -861,6 +862,7 @@ int GetHistogramDirect(pHistMem self, SConnection * pCon, iRet = self->pDriv->GetHistogram(self->pDriv, pCon, i, iStart, iEnd, lData); if (iRet == OKOK) { + tracePar(self->pDes->name,"!!datachange!!"); break; } else { iRet = self->pDriv->GetError(self->pDriv, &iErr, pError, 79); diff --git a/hmdata.c b/hmdata.c index b4c4edd1..ac6ca649 100644 --- a/hmdata.c +++ b/hmdata.c @@ -299,6 +299,7 @@ static int updateHMbuffer(pHistMem hist, int bank, SConnection * pCon) self->localBuffer); if (status == OKOK) { self->nextUpdate = time(NULL) + self->updateIntervall; + tracePar(hist->pDes->name,"!!datachange!!"); break; } else { status = hist->pDriv->GetError(hist->pDriv, &iErr, pError, 79); diff --git a/make_gen b/make_gen index 39fa66eb..1e53fdf7 100644 --- a/make_gen +++ b/make_gen @@ -41,7 +41,7 @@ SOBJ = network.o ifile.o conman.o SCinter.o splitter.o passwd.o \ sgclib.o sgfind.o sgio.o sgsi.o sghkl.o singlediff.o singlebi.o \ singlenb.o simindex.o simidx.o uselect.o singletas.o motorsec.o \ rwpuffer.o asynnet.o background.o countersec.o hdbtable.o velosec.o \ - histmemsec.o sansbc.o sicsutil.o strlutil.o genbinprot.o + histmemsec.o sansbc.o sicsutil.o strlutil.o genbinprot.o trace.o MOTOROBJ = motor.o simdriv.o COUNTEROBJ = countdriv.o simcter.o counter.o diff --git a/motor.c b/motor.c index f5c770d9..0c13fa1a 100644 --- a/motor.c +++ b/motor.c @@ -362,6 +362,7 @@ static void finishDriving(pMotor self, SConnection * pCon) self->fPosition = sCall.fVal; InvokeCallBack(self->pCall, MOTDRIVE, &sCall); /* send also very last position */ InvokeCallBack(self->pCall, MOTEND, &sCall); + tracePar(self->name,"%f",sCall.fVal); } /*--------------------------------------------------------------------*/ @@ -468,6 +469,7 @@ static void handleMoveCallback(pMotor self, SConnection * pCon) MotorGetSoftPosition(self, pCon, &sCall.fVal); sCall.pName = self->name; InvokeCallBack(self->pCall, MOTDRIVE, &sCall); + tracePar(self->name,"%f",sCall.fVal); self->posCount = 0; } } @@ -572,7 +574,9 @@ static int MotorSetParImpl(pMotor self, SConnection * pCon, char *name, if (iRet == 1) { SCparChange(pCon); InvokeCallBack(self->pCall, HDBVAL, self); + tracePar(self->name,"%s:%f",name, fVal); return iRet; + } } @@ -596,6 +600,7 @@ static int MotorSetParImpl(pMotor self, SConnection * pCon, char *name, ObParSet(self->ParArray, self->name, "softlowerlim", fLimit, pCon); SCparChange(pCon); InvokeCallBack(self->pCall, HDBVAL, self); + tracePar(self->name,"%s:%f",name, fVal); return 1; } @@ -616,6 +621,7 @@ static int MotorSetParImpl(pMotor self, SConnection * pCon, char *name, } InvokeCallBack(self->pCall, HDBVAL, self); SCparChange(pCon); + tracePar(self->name,"%s:%f",name, fVal); return iRet; } diff --git a/motorsec.c b/motorsec.c index 7cf48223..aca6c152 100644 --- a/motorsec.c +++ b/motorsec.c @@ -309,14 +309,10 @@ static int SecMotorStatus(void *sulf, SConnection * pCon) if (SCGetInterrupt(pCon) < (int) interrupt) { SCSetInterrupt(pCon, (int) interrupt); } - if(self->stopped == 0) { - self->errorCount++; - } break; case HWIdle: self->posCount = 10000; handleMoveCallback(self, pCon); - self->errorCount = 0; break; } return status; @@ -355,6 +351,10 @@ static int SecMotorHalt(void *sulf) haltFunc = (SICSOBJFunc) node->value.v.func; assert(haltFunc != NULL); self->stopped = 1; + self->pDrivInt->iErrorCount--; + if(self->pDrivInt->iErrorCount < 0){ + self->pDrivInt->iErrorCount = 0; + } return haltFunc((pSICSOBJ) self, pServ->dummyCon, node, par, 0); } @@ -462,7 +462,7 @@ static hdbCallbackReturn SecMotorCallback(pHdb node, void *userData, * check for alarm condition */ SecMotorGetPar(self, "failafter", &fVal); - if (self->errorCount > (int) fVal) { + if (self->pDrivInt->iErrorCount > (int) fVal) { /* big alarm */ ServerWriteGlobal("ERROR: !!! MOTOR ALARM !!! MOTOR ALARM !!!", eError); @@ -471,7 +471,7 @@ static hdbCallbackReturn SecMotorCallback(pHdb node, void *userData, self->name); ServerWriteGlobal(pBueffel, eError); SCSetInterrupt(pCon, eAbortBatch); - self->errorCount = 0; + self->pDrivInt->iErrorCount = 0; return hdbAbort; } @@ -553,10 +553,10 @@ static hdbCallbackReturn SecMotorSignCallback(pHdb node, void *userData, } SecMotorGetPar(self, "softlowerlim", &limit); limit *= v.v.doubleValue; - SecMotorSetPar(self, pCon, "softlowerlim", limit); + SecMotorSetPar(self, pCon, "softupperlim", limit); SecMotorGetPar(self, "softupperlim", &limit); limit *= v.v.doubleValue; - SecMotorSetPar(self, pCon, "softupperlim", limit); + SecMotorSetPar(self, pCon, "softlowerlim", limit); SecMotorSetPar(self, pCon, "softzero", .0); UpdateHipadabaPar(node, v, pCon); return hdbContinue; diff --git a/nread.c b/nread.c index faa00402..36c77645 100644 --- a/nread.c +++ b/nread.c @@ -41,6 +41,7 @@ #include "nread.h" #include "commandlog.h" #include "uselect.h" +#include "trace.h" extern pServer pServ; extern int VerifyChannel(mkChannel * self); /* defined in network.c */ @@ -62,6 +63,7 @@ typedef enum { tSE } TelnetStatus; +extern char *ConID(SConnection *pCon); /* from conman.c */ /*--------------------------------------------------------------------------*/ typedef struct __netreader { pServer pMain; /* The server ds */ @@ -260,6 +262,7 @@ static int NetReadRead(pNetRead self, pNetItem pItem) if (pPtr) { sscanf(pPtr, "%s %d", pMuell, &iInt); if (SCMatchRights(pItem->pCon, usUser)) { + traceCommand(ConID(pItem->pCon),"interrupt: %d",iInt); TaskSignal(self->pMain->pTasker, SICSINT, &iInt); snprintf(pBueffel,sizeof(pBueffel)-1, "INTERRUPT %d issued on sock %d", iInt, pItem->pCon->pSock->sockid); @@ -451,6 +454,7 @@ static int TelnetRead(pNetRead self, pNetItem pItem) } } TaskSignal(self->pMain->pTasker, SICSINT, &iInt); + traceCommand(ConID(pItem->pCon),"interrupt: %d",iInt); snprintf(pError,sizeof(pError)-1, "INTERRUPT %d issued on sock %d", iInt, pItem->pCon->pSock->sockid); WriteToCommandLog("SYS>", pError); @@ -1015,6 +1019,7 @@ static int testAndInvokeInterrupt(pCommandCBData self, int handle) if ((pInt = strstr(pPtr, "INT1712")) != NULL) { sscanf(pInt, "%s %d", buffer, &iInt); if (SCMatchRights(self->pCon, usUser)) { + traceCommand(ConID(self->pCon),"interrupt:%d",iInt); TaskSignal(pServ->pTasker, SICSINT, &iInt); snprintf(buffer, 512, "INTERRUPT %d issued on sock %d", iInt, handle); @@ -1316,6 +1321,7 @@ static int TelnetAcceptCB(int handle, void *userData) /*------------------------------------------------------------------------------------*/ static void NREADlog(int level, char *txt, void *userData) { + traceSys("anet",txt); puts(txt); } diff --git a/nserver.c b/nserver.c index 3ab906f9..167339c7 100644 --- a/nserver.c +++ b/nserver.c @@ -252,6 +252,10 @@ int InitServer(char *file, pServer * pServ) AddCommand(self->pSics, "Performance", PerfMonWrapper, DeletePerfMon, pMon); TaskRegister(self->pTasker, PerfMonTask, PerfMonSignal, NULL, pMon, 1); + /* Install a second one for higher granularity measurement */ + pMon = CreatePerfMon(2); + TaskRegister(self->pTasker, PerfMonTask, PerfMonSignal, DeletePerfMon, pMon, 1); + /* install telnet port */ InstallTelnet(); diff --git a/ofac.c b/ofac.c index b70e3da1..140a4df7 100644 --- a/ofac.c +++ b/ofac.c @@ -41,6 +41,7 @@ static void InitGeneral(void) INIT(HelpInit); INIT(AddTestProt); INIT(AddGenBinProtocoll); + INIT(MakeTrace); INIT(SiteInit); /* site specific initializations */ } @@ -108,6 +109,7 @@ static void InitIniCommands(SicsInterp * pInter) PCMD("TclReplaceDrivable", TclReplaceDrivable); PCMD("transact", TransactAction); PCMD("wait", UserWait); + PCMD("checksum", CheckSum); /* startup commands in alphabetic order */ SCMD("allowexec", AllowExec); diff --git a/perfmon.c b/perfmon.c index d07554ab..cc5c54c1 100644 --- a/perfmon.c +++ b/perfmon.c @@ -130,6 +130,7 @@ int IncrementPerfMon(pPerfMon self) SICSLogWrite(pBueffel, eValue); } InvokeCallBack(self->pCall, VALUECHANGE, &self->fCPS); + traceSys("perfmon","%d:%f", self->iInteg, self->fCPS); } return 1; } diff --git a/rs232controller.c b/rs232controller.c index 8dd58f99..eaa3b098 100644 --- a/rs232controller.c +++ b/rs232controller.c @@ -20,7 +20,12 @@ #include "nread.h" #include "rs232controller.h" - +/*--------------------------------------------------------------------*/ +static char *MakeID(prs232 self){ + static char id[132]; + snprintf(id,sizeof(id),"%s:%d",self->pHost, self->iPort); + return id; +} /*--------------------------------------------------------------------*/ void setRS232SendTerminator(prs232 self, char *term) { @@ -119,6 +124,11 @@ int writeRS232(prs232 self, void *data, int dataLen) } fflush(stdout); } + if(strlen((char *)data) <= dataLen){ + traceIO(MakeID(self),"out:%s",(char *)data); + } else { + traceIO(MakeID(self),"out:%s","Binary output"); + } if (pPtr != NULL) free(pPtr); @@ -167,6 +177,11 @@ int readRS232(prs232 self, void *data, int *dataLen) } fflush(stdout); } + if(strlen((char *)data) <= *dataLen){ + traceIO(MakeID(self),"in:%s",(char *)data); + } else { + traceIO(MakeID(self),"in:%s","Binary Input"); + } *dataLen = lRead; return 1; } else { @@ -208,11 +223,14 @@ int readRS232TillTerm(prs232 self, void *data, int *datalen) if (self->debug > 0) { printf("RS232 IN/TERM : TIMEOUT:%s\n", (char *) data); } + traceIO(MakeID(self),"in:%s","TIMEOUT"); return TIMEOUT; } else if (iRet == -1) { - printf("Incomplete read: %s, errno = %d\n", (char *) data, errno); + traceIO(MakeID(self),"in:%s %s","Incomplete read", (char *)data); + printf("Incomplete read: %s, errno = %d\n", (char *) data, errno); return INCOMPLETE; } else if (iRet < 0) { + traceIO(MakeID(self),"in:Error %d",errno); return iRet; } if (*self->replyTerminator != 0) { @@ -220,6 +238,7 @@ int readRS232TillTerm(prs232 self, void *data, int *datalen) } else { *datalen = iRet; } + traceIO(MakeID(self),"in:%s",(char *)data); return 1; } @@ -343,11 +362,14 @@ int transactRS232(prs232 self, void *send, int sendLen, } } if (iRet == 0) { + traceIO(MakeID(self),"in:%s", "TIMEOUT"); return TIMEOUT; } else if (iRet == -1) { + traceIO(MakeID(self),"in:%s:%d", "Incomplete read", errno); return INCOMPLETE; } else { - return iRet; + traceIO(MakeID(self),"in:%s", (char *)reply); + return iRet; } } @@ -439,6 +461,8 @@ int initRS232WithFlags(prs232 self, int flags) assert(self); + traceIO(MakeID(self),"connect"); + if (self->pSock != NULL) { if (pServ->pReader != NULL) { NetReadRemoveUserSocket(pServ->pReader, self->pSock->sockid); diff --git a/scriptcontext.c b/scriptcontext.c index 5cd798a4..187aed6c 100644 --- a/scriptcontext.c +++ b/scriptcontext.c @@ -35,6 +35,7 @@ struct SctController { Hdb *node; /* the controller node */ SConnection *conn; int verbose; + FILE *fd; }; /* action data and write callback data */ @@ -284,6 +285,9 @@ int SctCallInContext(SConnection * con, char *script, Hdb * node, if (verbose) { SCPrintf(con, eLog, "%6.3f script: %s", secondsOfMinute(), script); } + if (controller->fd != NULL) { + fprintf(controller->fd,"%6.3f script: %s\n", secondsOfMinute(), script); + } MacroPush(con); l = strlen(script); @@ -298,7 +302,10 @@ int SctCallInContext(SConnection * con, char *script, Hdb * node, } } if (verbose) { - SCPrintf(con, eLog, "%6.3f error: %s", secondsOfMinute(), result); + SCPrintf(con, eLog, "%6.3f error: %s", secondsOfMinute(), result); + } + if(controller->fd != NULL){ + fprintf(controller->fd, "%6.3f error: %s\n", secondsOfMinute(), result); } iRet = 0; } @@ -365,10 +372,17 @@ static char *SctActionHandler(void *actionData, char *lastReply, script = NULL; if (!commError && controller->verbose && lastReply != NULL && *lastReply != '\0') { - SCPrintf(con, eLog, "%6.3f reply : %s\n", secondsOfMinute(), lastReply); - /** - * TODO: This is the end place of any communication for statistics measurement - */ + SCPrintf(con, eLog, "%6.3f reply : %s\n", secondsOfMinute(), lastReply); + } + if(!commError && controller->fd != NULL && lastReply != NULL && *lastReply != '\0'){ + fprintf(controller->fd, "%6.3f reply : %s\n", secondsOfMinute(), lastReply); + } + if(lastReply != NULL && *lastReply != '\0'){ + if(data != NULL && data->controller != NULL){ + traceIO(data->controller->node->name, "reply:%s", lastReply); + } else { + traceIO("sctunknown", "reply:%s", lastReply); + } } /* @@ -511,9 +525,14 @@ static char *SctActionHandler(void *actionData, char *lastReply, if (controller->verbose) { SCPrintf(con, eLog, "%6.3f send : %s", secondsOfMinute(), send); } - /** - * TODO: this is another point where to introduce statistics, this is the start - */ + if (controller->fd != NULL) { + fprintf(controller->fd, "%6.3f send : %s\n", secondsOfMinute(), send); + } + if(data != NULL && data->controller != NULL){ + traceIO(data->controller->node->name, "send:%s", send); + } else { + traceIO("sctunknown", "send:%s", send); + } return send; } } @@ -1115,13 +1134,29 @@ static char *TransactionHandler(void *actionData, char *lastReply, if (st->controller->verbose) { SCPrintf(st->con, eLog, "%6.3f send : %s", secondsOfMinute(), st->command); } + if (st->controller->fd != NULL) { + fprintf(st->controller->fd, "%6.3f send : %s\n", secondsOfMinute(), st->command); + } + if(st->controller != NULL){ + traceIO(st->controller->node->name, "transsend:%s", st->command); + } else { + traceIO("sctunknown", "transsend:%s", st->command); + } return st->command; } else { st->sent = 2; if (st->controller->verbose) { SCPrintf(st->con, eLog, "%6.3f reply : %s", secondsOfMinute(), lastReply); } + if (st->controller->fd != NULL) { + fprintf(st->controller->fd,"%6.3f reply : %s\n", secondsOfMinute(), lastReply); + } /* printf("Transact: %s got %s\n", st->command, lastReply); */ + if(st->controller != NULL){ + traceIO(st->controller->node->name, "transreply:%s", lastReply); + } else { + traceIO("sctunknown", "transreply:%s", lastReply); + } st->reply = strdup(lastReply); return NULL; @@ -1141,6 +1176,11 @@ static int SctTransactCmd(pSICSOBJ ccmd, SConnection * con, c = (SctController *) ccmd->pPrivate; + if(nPar < 1 || par[0] == NULL){ + SCWrite(con,"ERROR: no data to transact found", eError); + return 0; + } + st = calloc(sizeof(SctTransact), 1); if (st == NULL) { SCWrite(con, "ERROR: out of memory in SctTransactCommand", eError); @@ -1239,14 +1279,14 @@ static int SctStatistics(pSICSOBJ ccmd, SConnection * con, char state[16]; c = (SctController *) ccmd->pPrivate; - DevStatistics(c->devser,&avg, &max, &errCount, &errState); + DevStatistics(c->devser,&avg, &max, &maxCount, &errCount, &errState); if(errState == 1){ strcpy(state,"in error"); } else { strcpy(state,"good"); } - SCPrintf(con,eValue,"Average roundtrip time: %lf, maximum roundtrip time %lf, com error count: %ld, com state: %s", - avg, max, errCount, state); + SCPrintf(con,eValue,"Average roundtrip time: %lf, maximum roundtrip time %lf, count max roundtrip/2 %d, com error count: %ld, com state: %s", + avg, max, maxCount, errCount, state); DevAsconStatistics(c->devser,&avg, &max, &maxState, &maxCount); SCPrintf(con,eValue,"Average time in AsconTask: %lf, maximum time spent in AsconTask %lf, state of Ascon on max %d, count > max/2 %d", avg, max, maxState, maxCount); @@ -1254,6 +1294,34 @@ static int SctStatistics(pSICSOBJ ccmd, SConnection * con, return 1; } +static int SctLog(pSICSOBJ ccmd, SConnection * con, + Hdb * cmdNode, Hdb * par[], int nPar) +{ + SctController *c; + char *filename = NULL; + + c = (SctController *) ccmd->pPrivate; + filename = par[0]->value.v.text; + if(strcmp(filename,"close") == 0 ){ + if(c->fd != NULL){ + fclose(c->fd); + c->fd = NULL; + } + } else { + if(c->fd != NULL){ + fclose(c->fd); + } + c->fd = fopen(filename,"w"); + if(c->fd == NULL){ + SCPrintf(con,eError,"ERROR: failed to open %s for logging", filename); + return 0; + } else { + SCPrintf(con,eValue,"Logging to %s", filename); + } + } + return 1; +} + static hdbCallbackReturn SctDebugCallback(Hdb * node, void *userData, hdbMessage * msg) { @@ -1305,6 +1373,12 @@ static void SctKillController(void *c) } DevKill(controller->devser); controller->devser = NULL; + + if(controller->fd != NULL){ + fclose(controller->fd); + controller->fd = NULL; + } + if (pServ->pTasker) { TaskRegister(pServ->pTasker, SctDeferredTask, NULL, SctDeferredFree, controller, 0); @@ -1395,6 +1469,11 @@ static int SctMakeController(SConnection * con, SicsInterp * sics, AddSICSHdbPar(cmd, "prio", usMugger, MakeHdbText("write")); AddSICSHdbPar(cmd, "action", usMugger, MakeHdbText("write")); + + cmd = AddSICSHdbPar(controller->node, + "log", usMugger, MakeSICSFunc(SctLog)); + AddSICSHdbPar(cmd, "filename", usMugger, MakeHdbText("")); + cmd = AddSICSHdbPar(controller->node, "transact", usMugger, MakeSICSFunc(SctTransactCmd)); AddSICSHdbPar(cmd, "data", usMugger, MakeHdbText("")); diff --git a/sics.h b/sics.h index 4a1a33d4..9dce3623 100644 --- a/sics.h +++ b/sics.h @@ -38,7 +38,7 @@ typedef enum { #include "nserver.h" #include "servlog.h" #include "sicsutil.h" - +#include "trace.h" extern pServer pServ; diff --git a/sicshipadaba.c b/sicshipadaba.c index 5672bf1e..026008b9 100644 --- a/sicshipadaba.c +++ b/sicshipadaba.c @@ -2973,7 +2973,7 @@ static int HdbArrayNode(SConnection * pCon, SicsInterp * pSics, void *pData, } if(strcmp(argv[2], "init") == 0){ - v = makeHdbValue(node->value.dataType, length); + v = makeHdbValue(node->value.dataType, node->value.arrayLength); switch(node->value.dataType){ case HIPINTAR: case HIPINTVARAR: diff --git a/sicsobj.c b/sicsobj.c index 306d7cc8..161983fe 100644 --- a/sicsobj.c +++ b/sicsobj.c @@ -543,7 +543,7 @@ pSICSOBJ SetupSICSOBJ(SConnection * pCon, SicsInterp * pSics, void *pData, priv = decodeSICSPriv(argv[3]); /* convert datatype */ type = convertHdbType(argv[4]); - if (type > HIPFLOAT) { + if (type > HIPTEXT) { SCWrite(pCon, "ERROR: invalid type requested: none, int, float supported", eError); diff --git a/sicsutil.c b/sicsutil.c index 89abbe5c..74579732 100644 --- a/sicsutil.c +++ b/sicsutil.c @@ -11,6 +11,10 @@ #include #include "fortify.h" #include "sics.h" +#include "HistMem.h" +#include "sicsdata.h" +#include "SCinter.h" +#include "sicshipadaba.h" static char *aCode[] = { "internal", @@ -49,5 +53,87 @@ double DoubleTime(void) gettimeofday(&now, NULL); return now.tv_sec + now.tv_usec / 1e6; } +/*--------------------------------------------------------------------------*/ +unsigned short fletcher16( char *data, size_t len) +{ + unsigned short sum1 = 0xff, sum2 = 0xff, result; + unsigned char checkA, checkB; + if(data == NULL){ + return 0; + } + while (len) { + size_t tlen = len > 21 ? 21 : len; + len -= tlen; + do { + sum1 += *data++; + sum2 += sum1; + } while (--tlen); + sum1 = (sum1 & 0xff) + (sum1 >> 8); + sum2 = (sum2 & 0xff) + (sum2 >> 8); + } + /* Second reduction step to reduce sums to 8 bits */ + sum1 = (sum1 & 0xff) + (sum1 >> 8); + sum2 = (sum2 & 0xff) + (sum2 >> 8); + checkA = (unsigned char)sum1; + checkB = (unsigned char)sum2; + result = checkA; + result = result << 8 | checkB; + return result ; +} +/*--------------------------------------------------------------------------*/ +int CheckSum(SConnection * pCon, SicsInterp * pSics, void *pData, + int argc, char *argv[]) +{ + pHdb node = NULL; + unsigned short checksum; + pObjectDescriptor pDes = NULL; + pHistMem pHM; + int length; + char *data = NULL; + pSICSData sidata = NULL; + + if(argc < 2){ + SCWrite(pCon,"ERROR: need object to checksum", eError); + return 0; + } + + node = FindHdbNode(NULL,argv[1],NULL); + if(node != NULL){ + checksum = getHdbCheckSum(&node->value); + SCPrintf(pCon,eValue,"%d", checksum); + return 1; + } + + pDes = FindCommandDescriptor(pSics, argv[1]); + if(pDes == NULL){ + SCPrintf(pCon,eError,"ERROR: object %s not found", argv[0]); + return 0; + } + + if(strcmp(pDes->name, "HistMem") == 0){ + pHM = (pHistMem)FindCommandData(pSics,argv[1],"HistMem"); + if(argc < 3){ + length = GetHistLength(pHM); + data = (char *)GetHistogramPointer(pHM,pCon); + checksum = fletcher16(data,length*sizeof(HistInt)); + SCPrintf(pCon,eValue,"%d", checksum); + return 1; + } else { + data = (char *)GetHistTimeBin(pHM,&length); + checksum = fletcher16(data,length*sizeof(float)); + SCPrintf(pCon,eValue,"%d", checksum); + return 1; + } + } + + if(strcmp(pDes->name, "SICSData") == 0){ + sidata = (pSICSData)FindCommandData(pSics,argv[1],"SICSData"); + checksum = fletcher16((char *)sidata->data, sidata->dataUsed*sizeof(int)); + SCPrintf(pCon,eValue,"%d", checksum); + return 1; + } + SCWrite(pCon,"ERROR: object type not recognized", eError); + return 0; +} diff --git a/sicsutil.h b/sicsutil.h index 191c0d7d..bbc50b27 100644 --- a/sicsutil.h +++ b/sicsutil.h @@ -14,4 +14,13 @@ double DoubleTime(void); /* returns time since epoch in seconds the resultion is machine dependent, but mostly better than msec */ +/** + * returns a checksum for data + * /param data pointer to the data to checksum + * /param len The length of data + * /return a checksum + */ +unsigned short fletcher16( char *data, size_t len); + + diff --git a/sicvar.c b/sicvar.c index 5017a660..f33111f0 100644 --- a/sicvar.c +++ b/sicvar.c @@ -55,7 +55,7 @@ static int VarSave(void *pData, char *name, FILE * fd) assert(pData); assert(fd); pVar = (pSicsVariable) pData; - if (pVar->iLock || pVar->iAccessCode == usInternal) { + if (pVar->iAccessCode == usInternal) { return 1; } snprintf(pBueffel,sizeof(pBueffel)-1, "# Variable %s\n", name); @@ -243,6 +243,7 @@ int VarSetFloat(pSicsVariable self, float fNew, int iUserRights) } else { self->fVal = fNew; InvokeCallBack(self->pCall, VALUECHANGE, self); + tracePar(self->name,"%f",fNew); } return 1; } @@ -258,6 +259,7 @@ int VarSetInt(pSicsVariable self, int iNew, int iUserRights) } else { self->iVal = iNew; InvokeCallBack(self->pCall, VALUECHANGE, self); + tracePar(self->name,"%d",iNew); } return 1; } @@ -276,7 +278,8 @@ int VarSetText(pSicsVariable self, char *pNew, int iUserRights) } self->text = strdup(pNew); InvokeCallBack(self->pCall, VALUECHANGE, self); - } + tracePar(self->name,"%s",pNew); + } return 1; } @@ -520,6 +523,11 @@ int VarWrapper(SConnection * pCon, SicsInterp * pInterp, void *pData, DeleteTokenList(pList); SCSendOK(pCon); return 1; + } else if (strcmp(pCurrent->text, "unlock") == 0) { + pVar->iLock = 0; + DeleteTokenList(pList); + SCSendOK(pCon); + return 1; } else if (strcmp(pCurrent->text, "force") == 0) { /* Undocumented feauture: force a set even while driving etc. diff --git a/test/DataNumber b/test/DataNumber index 393d5186..85ca8a81 100644 --- a/test/DataNumber +++ b/test/DataNumber @@ -1,3 +1,3 @@ - 318 + 324 NEVER, EVER modify or delete this file You'll risk eternal damnation and a reincarnation as a cockroach! diff --git a/test/sicsstat.tcl b/test/sicsstat.tcl index 6d591f39..40fc44cf 100644 --- a/test/sicsstat.tcl +++ b/test/sicsstat.tcl @@ -44,6 +44,12 @@ lieselotte SetMode Timer # Counter multi multi SetPreset 0.000000 multi SetMode Timer +sicsdatapath ./ +sicsdatapath setAccess 1 +sicsdataprefix regression +sicsdataprefix setAccess 1 +sicsdatapostfix .dat +sicsdatapostfix setAccess 1 # Motor a1 a1 sign 1.000000 a1 SoftZero 0.000000 @@ -251,7 +257,5 @@ cone qscale 1 cone center unknown simidx sttlim 0.2 simidx anglim 0.5 -apple preset 0 -apple mode monitor simi preset 0 simi mode monitor diff --git a/test/testini.tcl b/test/testini.tcl index 366fe3d8..58124a48 100644 --- a/test/testini.tcl +++ b/test/testini.tcl @@ -215,6 +215,48 @@ hattach target a3 /target/ta3 restore +#================================================== +# ScriptContext testing +#================================================== +proc sendtest {} { + set test [catch {sct target} msg] + if {$test == 0} { + set data $msg + } else { + set data TestDuta + } + sct send $data + return testreply +} +#------------------------------------------------- +proc readtest {} { + set t [doubletime] + sct send "Read:$t" + return testreply +} +#------------------------------------------------- +proc testreply {} { + sct print [sct result] + sct update [sct result] + return idle +} +makesctcontroller testsct testprot +MakeSICSObj testnode Test spy text +hsetprop /sics/testnode read readtest +hsetprop /sics/testnode write sendtest +hsetprop /sics/testnode testreply testreply + +proc testprio {} { + testsct queue /sics/testnode read read + testsct queue /sics/testnode read read + testsct queue /sics/testnode read read + testsct queue /sics/testnode halt write + testsct queue /sics/testnode read read + testsct queue /sics/testnode read read + return [testnode] +} +Publish testprio Spy + #------------------------------------------------- proc farmFormat {par num} { hsetprop /sics/farm/$par lastError none @@ -345,7 +387,7 @@ hsetprop /sics/farm/schneggecon readCommand schget hsetprop /sics/farm/schneggecon replyCommand schreply } -set farm 0 +set farm 1 if {$farm == 1} { #-------------- Test new async protocol controller @@ -432,7 +474,7 @@ farmser poll /sics/farm/schneggerunning hfactory /sics/farm/stone plain spy int hsetprop /sics/farm/stone read farmparcom stone hsetprop /sics/farm/stone parread farmparread -#farmser poll /sics/farm/stone +farmser poll /sics/farm/stone farmser debug -1 diff --git a/testprot.c b/testprot.c index a64e297f..7707c8f7 100644 --- a/testprot.c +++ b/testprot.c @@ -133,6 +133,8 @@ static void findResponse(Ascon *a) /*---------------------------------------------------------------------------*/ static int TestProtHandler(Ascon * a) { + int i; + switch (a->state) { case AsconConnectStart: case AsconConnecting: @@ -146,6 +148,9 @@ static int TestProtHandler(Ascon * a) findResponse(a); break; case AsconReadStart: + for(i = 0; i < 100; i++){ + TaskYield(pServ->pTasker); + } a->state = AsconReading; break; case AsconReading: diff --git a/trace.c b/trace.c new file mode 100644 index 00000000..cd8d2e91 --- /dev/null +++ b/trace.c @@ -0,0 +1,482 @@ +/* + * This is the trace facility for SICS. En detail logging for debugging complex + * problems and more. + * + * This is ugly: I have to copy the code in the trace functions because I can only pass + * down the argptr to lower level functions. But if I need space I have to reinitialize + * that pointer.... + * + * Another ugliness: this works fine as long as the messages are printed immediately. + * Due to the implementation in conman.c and rs232controller.c the id may change if + * there is a delay. If you need a queue, queue copies. + * + * There is another dependency here: the code in getTracePath relies on MakeSICSOBj + * setting the property sicsdev. + * + * trace.c + * + * Created on: Apr 27, 2011 + * Author: koennecke + */ + +#include +#include +#include +#include +#include + +static FILE *log = NULL; +static char *logfile = NULL; +static int hdbInit = 0; +static int filterProv = 0; +static int debug = 0; +/*----------------------------------------------------------------------------------------*/ +static char *GetTracePath(pHdb node) +{ + pHdb nodeStack[64]; + int depth = 0, length = 0, i; + pHdb current = NULL; + char *pPtr = NULL; + char sicsdev[80]; + + /** + * build a nodestack and find out required string length for path + */ + current = node; + while (current != NULL && GetHdbProperty(current,"sicsdev",sicsdev,sizeof(sicsdev)) == 0) { + length += strlen(current->name) + 1; + nodeStack[depth] = current; + depth++; + assert(depth < 64); + current = current->mama; + } + if(current != NULL){ + length += strlen(current->name) + 2; + nodeStack[depth] = current; + depth++; + } + + pPtr = malloc(length * sizeof(char)); + if (pPtr == NULL) { + return NULL; + } + memset(pPtr, 0, length * sizeof(char)); + + /* + * we wish to decremement by one because above loop + * increments one to many and we wish to ignore the + * root node + */ + for (i = depth - 1; i >= 0; i--) { + strcat(pPtr, "/"); + strcat(pPtr, nodeStack[i]->name); + } + return pPtr; +} +/*----------------------------------------------------------------------------------------*/ +static hdbCallbackReturn TraceCallback(pHdb node, void *userData, + pHdbMessage message) +{ + pHdbDataMessage mm = NULL; + char *pPath = NULL; + pDynString result, printedData; + + if ((mm = GetHdbUpdateMessage(message)) == NULL) { + return hdbContinue; + } + + if(getHdbCheckSum(&node->value) == getHdbCheckSum(mm->v)){ + return hdbContinue; + } + + pPath = GetTracePath(node); + if(pPath == NULL){ + return hdbContinue; + } + + if (mm->v->arrayLength < 20) { + printedData = formatValue(*(mm->v), node); + if (printedData == NULL ) { + return hdbContinue; + } + tracePar(pPath,"%s",GetCharArray(printedData)); + DeleteDynString(printedData); + } else { + tracePar(pPath,"!!datachange!!"); + } + free(pPath); + + return hdbContinue; +} +/*---------------------------------------------------------------------------*/ +int InstallTrace(pHdb node) +{ + pHdb currentChild = NULL; + pHdbCallback noty = NULL; + + if(node->value.dataType == HIPOBJ || node->value.dataType == HIPFUNC){ + return 1; + } + + noty = MakeHipadabaCallback(TraceCallback, NULL, NULL); + if (noty == NULL ) { + return 0; + } + AppendHipadabaCallback(node, noty); + + currentChild = node->child; + while (currentChild != NULL) { + InstallTrace(currentChild); + currentChild = currentChild->next; + } + return 1; +} +/*-----------------------------------------------------------------*/ +static void TraceObjects(void) +{ + CommandList *com = NULL; + pDummy dum = NULL; + + com = pServ->pSics->pCList; + while(com != NULL){ + dum = (pDummy)com->pData; + if(dum->pDescriptor->parNode != NULL){ + InstallTrace(dum->pDescriptor->parNode); + } + com = com->pNext; + } +} +/*-----------------------------------------------------------------*/ +static int filterProvenance(char *sub, char *id) +{ + if(strstr(sub,"io") != NULL){ + return 0; + } + if(strstr(sub,"sys") != NULL && strstr(id,"perfmon") != NULL){ + return 0; + } + return 1; +} +/*-----------------------------------------------------------------*/ +static int filter(char *sub, char *id) +{ + if(filterProv != 0){ + return filterProvenance(sub,id); + } else { + return 1; + } +} +/*-----------------------------------------------------------------*/ +static int strrepc(char *pszStr, char cFrom, char cTo) +{ + char *ptr ; /* Pointer to string */ + int iReturn = 0 ; /* No of replacements */ + + /*----------------------------------------------------------------*/ + + while( 0 != ( ptr = strchr( pszStr, cFrom ) ) ) + + { /* WHILE cFrom occurs in pszStr */ + + pszStr[ (int) ptr - (int) pszStr ] = cTo ; + + /*- Replace next cFrom with cTo */ + + iReturn++ ; /*- count */ + } + + return( iReturn ) ; +} +/*-----------------------------------------------------------------*/ +void traceprint(char *sub, char *id, char *data) +{ + if(log != NULL && filter(sub,id)){ + strrepc(data,'\n',':'); + fprintf(log,"%s:%s:%lf:%s\n", sub,id,DoubleTime(),data); + } +} +/*-----------------------------------------------------------------*/ +void traceIO(char *id, char *format, ...) +{ + va_list argptr; + char buffer[1024], *buf = NULL; + int len; + + if(log != NULL && filter("io","id")){ + va_start(argptr,format); + len = vsnprintf(buffer, sizeof(buffer),format,argptr); + va_end(argptr); + if(len >= sizeof(buffer)){ + buf = malloc(len+1); + memset(buf,0,len+1); + if(buf != NULL){ + va_start(argptr,format); + len = vsnprintf(buf, len+1,format,argptr); + va_end(argptr); + traceprint("io",id,buf); + free(buf); + } + } else { + traceprint("io",id,buffer); + } + } +} +/*-----------------------------------------------------------------*/ +void traceDevice(char *id, char *format, ...) +{ + va_list argptr; + char buffer[1024], *buf = NULL; + int len; + + if(log != NULL && filter("dev","id")){ + va_start(argptr,format); + len = vsnprintf(buffer, sizeof(buffer),format,argptr); + va_end(argptr); + if(len >= sizeof(buffer)){ + buf = malloc(len+1); + memset(buf,0,len+1); + if(buf != NULL){ + va_start(argptr,format); + len = vsnprintf(buf, len+1,format,argptr); + va_end(argptr); + traceprint("dev",id,buf); + } + } else { + traceprint("dev",id,buffer); + } + } +} +/*-----------------------------------------------------------------*/ +void traceCommand(char *id, char *format, ...) +{ + va_list argptr; + char buffer[1024], *buf = NULL; + int len; + + if(log != NULL && filter("com","id")){ + va_start(argptr,format); + len = vsnprintf(buffer, sizeof(buffer),format,argptr); + va_end(argptr); + if(len >= sizeof(buffer)){ + buf = malloc(len+1); + memset(buf,0,len+1); + if(buf != NULL){ + va_start(argptr,format); + len = vsnprintf(buf, len+1,format,argptr); + va_end(argptr); + traceprint("com",id,buf); + } + } else { + traceprint("com",id,buffer); + } + } +} +/*-----------------------------------------------------------------*/ +void tracePar(char *id, char *format, ...) +{ + va_list argptr; + char buffer[1024], *buf = NULL; + int len; + + if(log != NULL && filter("par","id")){ + va_start(argptr,format); + len = vsnprintf(buffer, sizeof(buffer),format,argptr); + va_end(argptr); + if(len >= sizeof(buffer)){ + buf = malloc(len+1); + memset(buf,0,len+1); + if(buf != NULL){ + va_start(argptr,format); + len = vsnprintf(buf, len+1,format,argptr); + va_end(argptr); + traceprint("par",id,buf); + } + } else { + traceprint("par",id,buffer); + } + } +} +/*-----------------------------------------------------------------*/ +void traceSys(char *id, char *format, ...) +{ + va_list argptr; + char buffer[1024], *buf = NULL; + int len; + + if(log != NULL && filter("sys","id")){ + va_start(argptr,format); + len = vsnprintf(buffer, sizeof(buffer),format,argptr); + va_end(argptr); + if(len >= sizeof(buffer)){ + buf = malloc(len+1); + memset(buf,0,len+1); + if(buf != NULL){ + va_start(argptr,format); + len = vsnprintf(buf, len+1,format,argptr); + va_end(argptr); + traceprint("sys",id,buf); + } + } else { + traceprint("sys",id,buffer); + } + } +} +/*-----------------------------------------------------------------*/ +void traceDebug(char *id, char *format, ...) +{ + va_list argptr; + char buffer[1024], *buf = NULL; + int len; + + if(log != NULL && debug == 1){ + va_start(argptr,format); + len = vsnprintf(buffer, sizeof(buffer),format,argptr); + va_end(argptr); + if(len >= sizeof(buffer)){ + buf = malloc(len+1); + memset(buf,0,len+1); + if(buf != NULL){ + va_start(argptr,format); + len = vsnprintf(buf, len+1,format,argptr); + va_end(argptr); + traceprint("debug",id,buf); + } + } else { + traceprint("debug",id,buffer); + } + } +} +/*----------------------------------------------------------------*/ +static void saveInitialParameters() +{ + CommandList *pCom = NULL; + char prefix[512]; + pIDrivable pDriv = NULL; + float value; + pDummy pDum = NULL; + + if(log == NULL){ + return; + } + + pCom = pServ->pSics->pCList; + while(pCom != NULL){ + if(strcmp(pCom->pName,"restore") == 0){ + pCom = pCom->pNext; + continue; + } + snprintf(prefix,sizeof(prefix),"par:start:%s", pCom->pName); + pDum = (pDummy)pCom->pData; + if(pDum != NULL){ + pDum->pDescriptor->SaveStatus(pCom->pData,prefix, log); + pDriv = pDum->pDescriptor->GetInterface(pCom->pData, DRIVEID); + if(pDriv != NULL){ + value = pDriv->GetValue(pCom->pData,pServ->dummyCon); + fprintf(log,"%s:%f\n", prefix,value); + } + } + pCom = pCom->pNext; + } + fprintf(log,"par:start:EOF\n"); +} +/*----------------------------------------------------------------*/ +static int TraceLog(pSICSOBJ ccmd, SConnection * con, + Hdb * cmdNode, Hdb * par[], int nPar) +{ + char *filename = NULL; + + if(nPar < 1) { + if(log != NULL){ + SCPrintf(con,eValue,"Tracing to %s", logfile); + } else { + SCWrite(con,"Tracing is off", eValue); + } + return 1; + } + + filename = par[0]->value.v.text; + if(strcmp(filename,"close") == 0 ){ + if(log != NULL){ + fclose(log); + log = NULL; + SCPrintf(con,eValue,"Tracing to %s closed", logfile); + free(logfile); + } + } else { + if(log != NULL){ + fclose(log); + free(logfile); + } + log = fopen(filename,"w"); + if(log == NULL){ + SCPrintf(con,eError,"ERROR: failed to open %s for logging", filename); + return 0; + } else { + logfile = strdup(filename); + saveInitialParameters(); + SCPrintf(con,eValue,"Logging to %s", filename); + if(hdbInit == 0){ + TraceObjects(); + hdbInit = 1; + } + } + } + return 1; +} +/*-----------------------------------------------------------------------------*/ +static int TraceDebug(pSICSOBJ ccmd, SConnection * con, + Hdb * cmdNode, Hdb * par[], int nPar) +{ + if(nPar >= 1){ + debug = par[0]->value.v.intValue; + } + SCPrintf(con,eValue, "trace.debug = %d", debug); + return 1; +} +/*-----------------------------------------------------------------------------*/ +static int TraceFilter(pSICSOBJ ccmd, SConnection * con, + Hdb * cmdNode, Hdb * par[], int nPar) +{ + if(nPar >= 1){ + filterProv = par[0]->value.v.intValue; + } + SCPrintf(con,eValue, "trace.filter = %d", filterProv); + return 1; +} +/*-----------------------------------------------------------------------------*/ +static void KillTrace(void *data) +{ + if(log != NULL){ + fclose(log); + free(logfile); + log = NULL; + logfile = NULL; + } +} +/*-----------------------------------------------------------------------------------------*/ +void MakeTrace(void) +{ + SICSOBJ *ccmd; + pHdb cmd; + + ccmd = MakeSICSOBJv("trace", "SicsTrace", HIPNONE, usSpy); + if(ccmd == NULL){ + SCWrite(pServ->dummyCon,"ERROR: out of memory creating trace", eError); + return; + } + + cmd = AddSICSHdbPar(ccmd->objectNode, + "log", usMugger, MakeSICSFunc(TraceLog)); + AddSICSHdbPar(cmd, "filename", usMugger, MakeHdbText("")); + + cmd = AddSICSHdbPar(ccmd->objectNode, + "filter", usMugger, MakeSICSFunc(TraceFilter)); + AddSICSHdbPar(cmd, "selection", usMugger, MakeHdbInt(0)); + + cmd = AddSICSHdbPar(ccmd->objectNode, + "debug", usMugger, MakeSICSFunc(TraceDebug)); + AddSICSHdbPar(cmd, "switch", usMugger, MakeHdbInt(0)); + + AddCommand(pServ->pSics, "trace", InterInvokeSICSOBJ, KillTrace, ccmd); + +} diff --git a/trace.h b/trace.h new file mode 100644 index 00000000..91334d1b --- /dev/null +++ b/trace.h @@ -0,0 +1,32 @@ +/* + * This is the trace facility for SICS. En detail logging for debugging complex + * problems and more. + * + * trace.h + * + * Created on: Apr 27, 2011 + * Author: koennecke + */ + +#ifndef TRACE_H_ +#define TRACE_H_ +#include + +/** + * printf style functions for printing trace information + * from various sub systems. The id field is something like + * the socket number, a host:port or something appropriate + * which tells us where the stuff is going to or coming from. + */ +void traceIO(char *id, char *format, ...); +void traceDevice(char *id, char *format, ...); +void traceCommand(char *id, char *format, ...); +void tracePar(char *id, char *format, ...); +void traceSys(char *id, char *format, ...); +void traceprint(char *sub, char *id,char *data); + +/** + * A debugging trace. This has to be switched on separately + */ +void traceDebug(char *id, char *format, ...); +#endif /* TRACE_H_ */