I observed something in a log file that I cannot explain:
All code in project is ANSI C, 32bit exe running on Windows 7 64bit
I have a worker function similar to this one, running in a single threaded program, using no recursion. During debugging logging was included as shown:
//This function is called from an event handler
//triggered by a UI timer similar in concept to
//C# `Timer.OnTick` or C++ Timer::OnTick
//with tick period set to a shorter duration
//than this worker function sometimes requires
int LoadState(int state)
{
WriteToLog("Entering ->"); //first call in
//...
//Some additional code - varies in execution time, but typically ~100ms.
//...
WriteToLog("Leaving <-");//second to last call out
return 0;
}
The function above is simplified from our actual code but is sufficient for illustrating the issue.
Occasionally we have seen log entries such as this:
Where the time/date stamp is on the left, then message, the last field is duration in clock()
ticks between calls to logging function. This logging indicates that the function was entered twice in a row before exiting.
Without recursion, and in a single threaded program, how is it (or is it) possible that execution flow can enter a function twice before the first call was completed?
EDIT: (to show top call of logging function)
int WriteToLog(char* str)
{
FILE* log;
char *tmStr;
ssize_t size;
char pn[MAX_PATHNAME_LEN];
char path[MAX_PATHNAME_LEN], base[50], ext[5];
char LocationKeep[MAX_PATHNAME_LEN];
static unsigned long long index = 0;
if(str)
{
if(FileExists(LOGFILE, &size))
{
strcpy(pn,LOGFILE);
ManageLogs(pn, LOGSIZE);
tmStr = calloc(25, sizeof(char));
log = fopen(LOGFILE, "a+");
if (log == NULL)
{
free(tmStr);
return -1;
}
//fprintf(log, "%10llu %s: %s - %d\n", index++, GetTimeString(tmStr), str, GetClockCycles());
fprintf(log, "%s: %s - %d\n", GetTimeString(tmStr), str, GetClockCycles());
//fprintf(log, "%s: %s\n", GetTimeString(tmStr), str);
fclose(log);
free(tmStr);
}
else
{
strcpy(LocationKeep, LOGFILE);
GetFileParts(LocationKeep, path, base, ext);
CheckAndOrCreateDirectories(path);
tmStr = calloc(25, sizeof(char));
log = fopen(LOGFILE, "a+");
if (log == NULL)
{
free(tmStr);
return -1;
}
fprintf(log, "%s: %s - %d\n", GetTimeString(tmStr), str, GetClockCycles());
//fprintf(log, "%s: %s\n", GetTimeString(tmStr), str);
fclose(log);
free(tmStr);
}
}
return 0;
}