fprintf have strange effect on timestamp counter

Question

I have two counters:

#define number_of_ccr 1024
unsigned int lpBuffer[number_of_ccr] = {0};
unsigned long nNumberOfBytesToRead =     number_of_ccr*4;
unsigned long lpNumberOfBytesRead;  
unsigned int counter = 0;
unsigned int error = 0;
QueryPerformanceCounter(&fullCounter); // first counter

for(;;) {

  QueryPerformanceCounter(&startCounter); //     second counter 
  error = ReadFile(
    hSerial,
    lpBuffer,
    nNumberOfBytesToRead,
    &lpNumberOfBytesRead,
    NULL
    );

  if(!strcmp(lpBuffer, "end")) {
  CloseHandle(FileHandle);
  //char *copyString = "copy";
  //WriteFile(hSerial, copyString , strlen(copyString), &bytes_written, NULL);
  fprintf(stderr, "end flag was received\n");
  break;
  }
  else if(lpNumberOfBytesRead == nNumberOfBytesToRead) {

  // NOTE(): succeed
  QueryPerformanceCounter(&endCounter);
  time += Win32GetSecondsElapsed(startCounter, endCounter); //second counter

  DWORD BytesWritten;
  // write data to file
  WriteFile(FileHandle, lpBuffer, lpNumberOfBytesRead, &BytesWritten, 0);
    if(!(lpBuffer[0] % 1024)) {
      fprintf(stderr, "bytes %d \r", lpBuffer[0]);// <--- THIS LINE
    }
  }
  else if(lpNumberOfBytesRead < nNumberOfBytesToRead) {
    fprintf(stderr, "bytes %d \n", lpNumberOfBytesRead); 
  }

}// for(;;) 
QueryPerformanceCounter(&fullCounterEnd);
fullTime =   Win32GetSecondsElapsed(fullCounter, fullCounterEnd);           

char DebugBuffer[256];
fprintf(stderr, "time: %f \n", time);
fprintf(stderr, "full time: %f \n", fullTime);

if I will comment fprintf(stderr, "bytes %d \r", lpBuffer[0]);// <--- THIS LINE second counter will be approx same time as fist counter (fullCounter). When this line is uncommented second timer is almost twice less than first counter. Presence of this line is the only difference.

Overall: If fprintfis NOT COMMENTED my counter show BETTER readfile performance --> second counter has LESSER time

If fprintf COMMENTED I have WORSE performance --> second counter has MORE time on it

compiler flags: cl -Z7 -nologo -Fmsource.map ../code/source.c

cmder log:

C:\Documents\work\region\testProject\build (master -> origin)
λ source.exe
Opening serial port...OK
Sending bytes...9 bytes written
end flag was received
time: 0.193245
full time: 0.206170
Closing serial port...OK

C:\Documents\work\region\testProject\build (master -> origin)
λ source.exe
Opening serial port...OK
Sending bytes...9 bytes written
end flag was received
time: 0.115640
full time: 0.204010
Closing serial port...OK

My question is, why is this happen? What kind of effect it have on my program?

Answer 1

While fprintf is executing, the serial keeps accumulating incoming data. The next time you try to read, the data is readily available. Without fprintf, the program has to wait for it inside ReadFile. Therefore a discrepancy.