Appending to a file.

[Peter Lameijn]

With an older application I made, I have some problems I can't really explain. It's a Voice response system for ISDN (T1/E1), which works fine, except for one thing.
When the system is very busy, it get's slow. (You can see by the delayed updating of the GUI on the screen, and the delayed voicetexts)
I think it is caused by the logfile the program keeps. Interesting events are logged in a logfile. If very busy, this could be 10 or 20 events a second.
The logfile is opened (for append) and closed on every event. This to make it easy to copy / delete the logfile periodically.

I thought that Windows 'shadows' the file in memory, and writes it to disk after a time-out. So I didn't think a lot of opening and closing would have any impact on the PC...

Can this indeed have a lot of impact, and is there a way to avoid / minimize this?

(Using PbWin 8.04 / W2KSP4)

[Marco Pontello]

Just a tought but... maybe an antivirus is finding that file interesting and loose a lot of time checking it?

Bye!

[Michael Mattias]

Farm out the write to a queue. Search 'queue' in source code forum. I think you'll find the version using the anonymous pipe pretty much exactly what you are looking for.

[Mike Doty]

Curious if you found the slow-down (anti-virus checking?)
The log file could be in another thread or lock/flush/unlock
could be used and other processes could read it.

[Michael Mattias]

>Can this indeed have a lot of impact, and is there a way to avoid / minimize this?

Yes and not really.

About all you can do is arrange for the "slow" activity to occur somewhere it does not affect your GUI... eg in another thread of execution running at a lower priority.

(as shown in the queue demo to which I pointed you).

Or, I guess you could just launch a thread to execute ...

THREAD FUNCTION AppendtoLogFile (BYVAL pS AS STRING PTR ) AS LONG 

  SetThreadPriority GetCurrentThread(), %THREAD PRIORITY_LOWEST 
  szFile = $LOG_FILE_NAME 
  hFile = FREFILE
  OPEN .....
  PRINT #hFile, @PS 
  CLOSE hFile
 
END FUNCTION 

....
    LOCAL LogText AS STRING                     ' see SCOPE NOTE BELOW 
    LogText = "Really interesting stuff here"  
   THREAD CREATE AppendToLogFile (BYVAL VARPTR (logText)) TO hThread 
   THREAD CLOSE hThread TO hThread 
.....

SCOPE NOTE: If your calling function is going to terminate, you'll have to make logtext STATIC or GLOBAL lest it go out of scope by the time it's called upon to write to the disk file. That or add a ready event and suspend the calling thread until you have copied the data to a variable LOCAL to the thread function and then signalled that event. (Most of my demos of multi-threaded stuff include this event code).


MCM

[Peter Lameijn]

Curious if you found the slow-down (anti-virus checking?)

No, tested on a bare machine with same result. I have an option to enable/disable logging, and when disabled, program runs fine...
But I'll give Michaels suggestion a try.
I just found it curious that a lot of open/closes of a file had such an impact on the operation of the system...

[John Gleason]

Peter, you also might try writing a little less frequently to the disk, while writing to a string in the meantime:

#COMPILE EXE
#DIM ALL
%WRITEiNTERVAL = 15 'write to disk ~ every 15 sec.

FUNCTION PBMAIN () AS LONG
   LOCAL eventString, interestEvent AS STRING, startPos AS QUAD, ii AS LONG
   
   eventString = SPACE$(1000000)
   startPos = 1
   
   FOR ii = 1 TO 4000
      interestEvent = FORMAT$(ii) & "th Interesting event to be logged, and now, without slowing system." & $CRLF
      MID$(eventString, startPos) = interestEvent
      startPos += LEN(interestEvent)  'aka. startPos = startPos + LEN(intrestEvent)
      SLEEP 50                        '20 per second
      IF ii MOD 40 = 39 THEN          'check every 2 seconds to see if write interval is reached
         IF logEvents(eventString) = 1 THEN
            startPos = 1
            eventString = SPACE$(1000000)
         END IF
      END IF
   NEXT
   ? "3,999 events have been logged hopefully unnoticed by system"
END FUNCTION

FUNCTION logEvents(eventString AS STRING) AS LONG
   STATIC t AS SINGLE
   IF t = 0 THEN t = TIMER
   
    IF TIMER - t >= %WRITEiNTERVAL THEN 'write to disk at selected second interval
       DO
          TRY                           'let program wait if you're, say, viewing the file
             OPEN "c:\interestingEvent.log" FOR APPEND AS #1
             EXIT DO
          CATCH
             SLEEP 200
          END TRY
       LOOP
       PRINT #1, RTRIM$(eventString);
       CLOSE #1
       FUNCTION = 1
       t = TIMER
    END IF
END FUNCTION

[Gösta H. Lovgren-2]

You might try setting up a Ram Disk. Peter. That should eliminate lost time. From your description, the slowing down is not a constant (slows some times more than others, indicating the OS is the cuplrit flushing the cache or something, requiring seek time for the drive head) and a Ram Disk would get around that.

Just a thought.

====================================================
"From the moment I picked your book up
until I laid it down I was convulsed with laughter.
Some day I intend reading it."
Groucho Marx (1895-1977)
====================================================

[Brian Chirgwin]

Open/Close to fast?

Windows as a Write cache which is usually enabled. Disabling it makes the computer really slow.

Is it possible Windows has not finished flushing the write cache/closing the file before your application is requesting to have the file open again?

You could try running SysInternals DiskMon and see if it indicates any delays/timeouts/errors/etc... Not sure if it will, but worth a shot.

[Mike Doty]

Write after so many events or whenever you want

#COMPILE EXE
#DIM ALL
 
FUNCTION PBMAIN () AS LONG
  LOCAL EventCounter AS LONG
  KILL "\LOG.TXT"            'get rid of previous log
 
  FOR EventCounter = 1 TO 1073
    UpdateLog "Event"+ STR$(EventCounter) + " time " + TIME$
    IF EventCounter MOD 20 = 0 THEN UpdateLog ""     'flush whenever you want
  NEXT
 
  UpdateLog ""  'flush events still in StaticString
  SHELL "NOTEPAD \LOG.TXT"   'view results
END FUNCTION
 
SUB UpdateLog(sText AS STRING)
 
  STATIC StaticString  AS STRING
  LOCAL hLog           AS LONG
 
  IF LEN(sText)THEN
    StaticString = StaticString + sText + $CRLF
  ELSE
    hLog = FREEFILE  'added this line 4/18/09 4:31 AM CST
    OPEN "\LOG.TXT" FOR APPEND AS hLOG
    PRINT #hLog, LEFT$(StaticString,LEN(StaticString)-2) 'dont need extra $CRLF after each close
    CLOSE #hLog
    StaticString = ""
  END IF
END SUB

[Mike Doty]

Added hLog = FREEFILE

SUB UpdateLog(sText AS STRING)
 
  STATIC StaticString  AS STRING
  LOCAL hLog           AS LONG
 
  IF LEN(sText)THEN
    StaticString = StaticString + sText + $CRLF
  ELSE
    hLog = FREEFILE  'added this line 4/18/09 4:31 AM CST
    OPEN "\LOG.TXT" FOR APPEND AS hLOG
    PRINT #hLog, LEFT$(StaticString,LEN(StaticString)-2) 'dont need extra $CRLF after each close
    CLOSE #hLog
    StaticString = ""
  END IF
END SUB

[Edwin Knoppert]

>Windows as a Write cache which is usually enabled.
This does not help during the close, this will flush the data to disk before it returns from close.

[Michael Mattias]

Peter, you also might try writing a little less frequently to the disk, while writing to a string in the meantime..

Risks losing log information if 'something bad' happens to program.

Worst of all, what will be missing are the events immediately preceding that something bad - more than likely the exact information required to isolate the problem.

Not that this cannot occur when you farm out the log writes to another thread of execution, because it can. But IMO using OPEN/WRITE/CLOSE either within the context of the primary TOE or in a worker TOE offers the best chance of preserving all the log information.

[Michael Mattias]

Then again, perhaps instead of farming out the writes to an additional TOE of the primary executable, you could use a separate server EXE to handle it. That way anything which has been sent to the server for "write to the log" purposes would be unaffected by 'something bad' happening in the client program.

A lot more work to implement, but depending on the application it may be the very best way to support log writing.

[Mike Doty]

Writing less frequently code is posted above.

[Mike Doty]

Here is another

$LogFile = "\LOG.TXT"
FUNCTION PBMAIN () AS LONG
  FOR EventCounter& = 1 TO 1073
    sBuffer$ = sBuffer$ + "Event"+ STR$(EventCounter&) + " time " + TIME$ + $CRLF
    IF EventCounter& MOD 100 = 0 THEN FlushBuffer(sBuffer$):sBuffer$ = ""
  NEXT
  FlushBuffer(sBuffer$):sBuffer$ = ""
  SHELL "NOTEPAD " + $LogFile
END FUNCTION
SUB FlushBuffer(sBuffer AS STRING)
  hLog& = FREEFILE
  OPEN $LogFile FOR APPEND AS hLog&
  PRINT #hLog&, LEFT$(sBuffer$,LEN(sBuffer$)-2)
  CLOSE #hLog&
END SUB