请问一个关于syslog中时间记录的问题

俞二侠 2021-03-20 02:27:50

有个bug这两天一直没有解决掉，请各位大佬帮帮忙，分析一下
主函数是这样的：
int main(int argc,char *argv[])
{
pthread_t tid_0,tid_1,tid_2,tid_3,tid_exit;
//ParaOfCommandPtr=createPetSystem();
GlobalState=createPetSystem();
sigset_t set;
sem_init(&sem_sym,0,0);
sigemptyset(&set);
sigaddset(&set, SIGALRM);
sigaddset(&set, SIGPIPE);
pthread_sigmask(SIG_SETMASK, &set, NULL);
sleep(1);
pthread_create(&tid_0,NULL,tcp_dispatch,NULL);
pthread_create(&tid_1,NULL,local_dispatch,NULL);
pthread_create(&tid_2,NULL,local_task_timer,argv[0]);
local_unix_connfd=connnect_local_socket();
pthread_create(&tid_3,NULL,local_server_loop,NULL);
if(pthread_create(&tid_exit,NULL,wait_exit,argv[0])!=0){
perror("pthread_exit_create");
}
tcp_server_loop(local_unix_connfd);
destroyPetSystem(GlobalState);
return 0;
}

其中local_task_timer函数：
void *local_task_timer(void * arg)
{
int connect_fd;
int ret;
char buffer[4]={0};
char bufferReceive[4]={0};
static struct sockaddr_un srv_addr;
pthread_detach(pthread_self());
connect_fd=socket(PF_UNIX,SOCK_STREAM,0);
if(connect_fd<0){
perror("cannot creat socket");
pthread_exit(NULL);
}
srv_addr.sun_family=AF_UNIX;
strcpy(srv_addr.sun_path,UNIX_LOCAL_DOMAIN);
while(1)
{
ret=connect(connect_fd,(struct sockaddr*)&srv_addr,sizeof(srv_addr));
if (ret<0){
perror("cannot connect server");
sleep(1);
//close(connect_fd);
}
else
break;
}
printf("timer connect success %d\n",ret);
if(arg!=NULL)
{
if(strcmp((char *)arg,"swift"))
{
mesgid2buffer(buffer,C_INIT);
}
else
{
mesgid2buffer(buffer,C_INIT_SWIFT);
}
}
//mesgid2buffer(buffer,C_INIT);
send(connect_fd,buffer,4,MSG_DONTWAIT);
printf("connect local tcp server is %d\n",connect_fd);
ret=read(connect_fd,bufferReceive,sizeof(bufferReceive));
if(ret>0)
printf("receive init responce successfully.\n");
int nbytes=0;
struct timeval timeout={30,0};
fd_set fdR;
for(;;)
{
//printf("system start.\n");
timeout.tv_sec=1;
timeout.tv_usec=0;
FD_ZERO(&fdR);
FD_SET(connect_fd,&fdR);
switch(select(connect_fd+1,&fdR,NULL,NULL,&timeout))
{
case -1:
DEV_PRINT("no input\n");
syslog(LOG_LOCAL0 | LOG_INFO,"UnixTimerState: socket no input.");
//goto disconnect;
break;
case 0:
DEV_PRINT("time is out\n");
mesgid2buffer(buffer,C_Read_SystemStatus);
send(connect_fd,buffer,4,MSG_DONTWAIT);
mesgid2buffer(buffer,C_SystemMonitor);
send(connect_fd,buffer,4,MSG_DONTWAIT);
mesgid2buffer(buffer,C_Internal_PscStatus);
send(connect_fd,buffer,4,MSG_DONTWAIT);
//syslog(LOG_LOCAL0 | LOG_INFO,"TcpState: Tcp connection time out.");
//goto disconnect;
continue;
default:
if(FD_ISSET(connect_fd,&fdR)==0)
{
DEV_PRINT("nothing to read\n");
syslog(LOG_LOCAL0 | LOG_INFO,"UnixTimerState: socket connection nothing to read.");
//goto disconnect;
}
//解析数据包
else
{
if((nbytes=read(connect_fd,bufferReceive,sizeof(bufferReceive)))==-1)// read failed
{
fprintf(stderr,"Read Error:%s\a\n",strerror(errno));
syslog(LOG_LOCAL0 | LOG_INFO,"UnixTimerState: Socket Read Error.TCP pthread exit.");
//goto disconnect;
}
else if(nbytes==0)//read nothing
{
DEV_PRINT("transmit nothing.TCP connection broken\n");
syslog(LOG_LOCAL0 | LOG_INFO,"UnixTimerState: transmit nothing.socket connection broken.socket pthread release.\n");
//goto disconnect;
}
else // read success
{
send(connect_fd,bufferReceive,4,MSG_DONTWAIT);
}
}
}
}
/*
while(1)
{
mesgid2buffer(buffer,C_Read_SystemStatus);
send(connect_fd,buffer,4,MSG_DONTWAIT);
mesgid2buffer(buffer,C_SystemMonitor);
send(connect_fd,buffer,4,MSG_DONTWAIT);
sleep(1);
}
*/
close(connect_fd);
pthread_exit(NULL);
}
这段函数就是一秒钟发送一次系统状态查询给到自己，其中的 C_Read_SystemStatus和C_SystemMonitor用于查询系统状态和系统错误信息

struct CommandIDAction CommandMap[COMMAND_COUNT]={
{C_ErrorMessage,errorSystem},
{C_SystemMode,configSystem},
{C_CTStart,ctonSystem},
{C_CTEnd,ctoffSystem},
{C_PETPlan,planSystem},
{C_PETPlay,playSystem},
{C_ACQRawData,acqSystem},
{C_Stop,stopSystem},
{C_EndExam,endSystem},
{C_ShutDown,shutSystem},
{C_Reboot,rebootSystem},
{C_WriteFlash,wflashSystem},
{C_ReadFlash,rflashSystem},
{C_FileImport,importSystem},
{C_TempCalibration,tempcalibrationSystem},
{C_UpdateHyper,uhyperSystem},
{C_ReadTestPattern,tpatternSystem},
{C_ReadSignalPattern,spatternSystem},
{C_ReadBlockRate,blockrateSystem},
{C_FrontParaConfigure,frontparaSystem},
{C_TDCCalibrationOutputEnable,tdconSystem},
{C_TDCCalibrationOutputDisable,tdcoffSystem},
{C_WriteComponentPost,writecomponentpostSystem},
{C_ReadComponentPost,readcomponentpostSystem},
{C_No_ShutDown,NoshutSystem},
{C_INIT,initSystem},
{C_Read_SystemStatus,systemStatusSystem},
{C_SystemMonitor,systemMonitorSystem},
{C_Internal_PowerOff,InternalPoweOffSystem},
{C_INIT_SWIFT,initSystemSwift},
{C_Internal_SystemConfigure,InternalConfigureSystem},
{C_HandShake,HandShakeSystem},
{C_FrontParaConfigure_Parallel,frontparaParallelSystem},
{C_TempcalibrationResult,tempcalibrationresultSystem},
{C_CcbLogicUpdate,CcbUpdateSystem},
{C_Internal_PscStatus,PscStatusStatus},
{C_Cross_Acq_Configure,crossAcqConfigureSystem}
};

systemMonitorSystem和PscStatusStatus对应的函数分别为：
void* systemMonitorSystem(void *arg)
{
//DigitalPetSystemPtr instance=(DigitalPetSystemPtr) arg;
struct TcpCommandState* state=(struct TcpCommandState*) arg;
system_monitor(state->rsystemmonitor(state));
}
void* PscStatusStatus(void *arg)
{
struct TcpCommandState* state=(struct TcpCommandState*) arg;
psc_system_status_monitor(state->rpscstatus(state));
}

void system_monitor(int state_code)
{
DEV_PRINT("system monitor init end\n");
//struct timespec outtime;
struct timeval start,end;
static xmlChar buffer[307200];
static int size=0;
//int ret=0;
ProtobufCBinaryData data;

if(state_code<0)
{
gettimeofday(&start,NULL);
sem_wait(&sem_sym);
system_monitor_read(buffer,&size,ProductType);
gettimeofday(&end,NULL);
syslog(LOG_LOCAL0 | LOG_INFO,"ReadSystemMonitor: TimeUsed is %ld usec.",(end.tv_sec-start.tv_sec)*1000000+end.tv_usec-start.tv_usec);
}
data.len=size;
data.data=malloc(size);
memcpy(data.data,buffer,size);
pack_message_layer(data,0,C_SystemMonitor);
free(data.data);
}

void psc_system_status_monitor(int state_code)
{
DEV_PRINT("system psc init end\n");
struct timeval start,end;
static xmlChar buffer[102400]; //for storage last read data
ProtobufCBinaryData data;
static int size=0;
if(get_psc_monitor_start_flag()==1)
{
if(state_code<0)
{
gettimeofday(&start,NULL);
psc_status_read(buffer,&size);
gettimeofday(&end,NULL);
syslog(LOG_LOCAL0 | LOG_INFO,"ReadPscStatus: TimeUsed is %ld usec.",(end.tv_sec-start.tv_sec)*1000000+end.tv_usec-start.tv_usec);
}
data.len=size;
data.data=malloc(size);
memcpy(data.data,buffer,size);
pack_message_layer(data,0,C_Internal_PscStatus);
free(data.data);
//syslog(LOG_LOCAL0 | LOG_INFO,"SendPscStatus: work is done.length is %d",size);
}
}

通过syslog记录程序中的log发现时间跳跃了6秒并且在接下来的后三秒里每秒钟系统状态的打印出现多次：
这是时间跳跃的记录，这个log是芯片对底层的探测器的命令发送进行记录，每次发送的时间间隔其实非常短
Mar 5 15:06:59:536950 SCCB local0.info normal: Calibration para cmd data is 100d0
Mar 5 15:07:05:470621 SCCB local0.info normal: Calibration para cmd data is 100d0
Mar 5 15:07:05:470676 SCCB local0.info normal: Calibration para cmd data is 100d0
Mar 5 15:07:05:470704 SCCB local0.info normal: Calibration para cmd data is 100d0
Mar 5 15:07:05:470727 SCCB local0.info normal: Calibration para cmd data is 100d0
这是对sysmonitor的log记录：
Line 117599: Mar 5 15:06:58:612861 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 330477 usec.
Line 50: Mar 5 15:07:05:565273 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 6281469 usec.
Line 176: Mar 5 15:07:05:744703 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 263892 usec.
Line 655: Mar 5 15:07:05:995302 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 249506 usec.
Line 816: Mar 5 15:07:06:178203 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 217916 usec.
Line 1122: Mar 5 15:07:06:418760 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 239407 usec.
Line 1488: Mar 5 15:07:06:769160 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 277948 usec.
Line 1694: Mar 5 15:07:07:68534 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 125060 usec.
Line 2059: Mar 5 15:07:07:309927 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 240559 usec.
Line 2426: Mar 5 15:07:07:667140 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 197846 usec.
Line 2794: Mar 5 15:07:08:644053 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 351568 usec.
Line 3160: Mar 5 15:07:09:645036 SCCB local0.info normal: ReadSystemMonitor: TimeUsed is 351520 usec.
这是对systemstatus的log记录：
Line 117601: Mar 5 15:06:58:682515 SCCB local0.info normal: ReadPscStatus: TimeUsed is 400299 usec.
Line 46: Mar 5 15:07:05:480271 SCCB local0.info normal: ReadPscStatus: TimeUsed is 6196600 usec.
Line 560: Mar 5 15:07:05:900299 SCCB local0.info normal: ReadPscStatus: TimeUsed is 61795 usec.
Line 650: Mar 5 15:07:05:959540 SCCB local0.info normal: ReadPscStatus: TimeUsed is 393358 usec.
Line 1200: Mar 5 15:07:06:490233 SCCB local0.info normal: ReadPscStatus: TimeUsed is 494076 usec.
Line 1591: Mar 5 15:07:06:942952 SCCB local0.info normal: ReadPscStatus: TimeUsed is 326260 usec.
Line 1607: Mar 5 15:07:06:948688 SCCB local0.info normal: ReadPscStatus: TimeUsed is 662791 usec.
syslog中记录的日志时间明显有一段时间没记，并且后面每秒的记录中出现一秒钟记录多次系统时间的问题，请问各位大佬这是什么原因如何解决？？在此万分感谢！！！

...全文