Output File Append Line running slow on server 2016 as text file gets larger - Unipaas


Peter Ashworth
 

Hi all,

We have various log files that we create for troubleshooting purposes. Its a fairly basic central program we wrote which does a Form output with the IO set to file append line, for a line up to 9999 in length.

In most of our client installations have server 2012 running as a virtual server.
They can see these logs files grow over time if not archived away up to 500mb sometimes. When writing 10 extra lines to the file, each with a separate call to the program that does the IO so we aren't holding the IO open, the timestamps we print on each line show from start to finish it happening within 1 second, or 2 seconds.

One of our customers recently upgraded to a server 2016 virtual server. When the log files are newly created everything runs as fast as it should, however even when the log file has hit 25mb the time taken to write these log lines is 5 or 6 seconds. and when it hit 50mb about 8 or 9 seconds. This is a problem for us because it increases the time it takes to respond to a waiting web request (not broker all magic is doing is writing an encrypted xml to disc which something else handles passing back to the web request) which can cause web applications to then timeout. If we disable the logs then the processing speeds right back up and the web requests stop timing out so we are certain it is the process of writing to a log file which is hanging everything up.

Is it possible that server 2016 somehow handles magic append line operation differently and its having to scan through the file first? Has anyone else had something like this? The customers IT says they haven't deployed anti virus yet which we thought might be a culprit. And they are newly created files by unipaas running on the new server, which eliminates a suspicion that the culprit was file owner permissions from the log files originally being copied over from the old server.

Any thoughts are appreciated as we are a bit flummoxed as to what might cause this

Thanks

Peter


Andreas Sedlmeier
 
Edited

Hi Peter,

There was a discussion about log compression and rotation not so long ago. Just install a good log rotator and the problem should be gone.

What I see more and more often, because it's so incredible fast, reliable, distributed ... is streaming log information to Apache Kafka. 300.000 messages (log entries) per second, would be no issue at all. Think about message queues as alternative to writing to a log file :) (Samples: https://www.devglan.com/apache-kafka/stream-log4j-logs-to-kafka , https://medium.com/oneclicklabs-io/streaming-spring-boot-application-logs-to-apache-kafka-elk-k-stack-part-2-f3ed18f64a31 , ...)

P.S./EDIT: The thread I was referencing is following: https://magicu-l.groups.io/g/main/message/188573

When I was a young and ambitioned Magic programnmer I also experimented with logging to Windows Event log and debug console, with good results. Why the file append actually gets that slow when the file grows, I cant tell, that should not be the case because append is just open+seek to end+write. Maybe Magic does some kind of processing. You can have a look with a file monitor (process monitor from sysinternals f.i.) to see what happens, ...

Andreas


Steven Blank
 

Peter,

Could it be that the log file is being written into a compressed folder, that the server itself is compressing the file "on the fly"?

Steve Blank


On 9/21/2018 2:54 AM, Peter Ashworth wrote:
Hi all,

We have various log files that we create for troubleshooting purposes. Its a fairly basic central program we wrote which does a Form output with the IO set to file append line, for a line up to 9999 in length.

In most of our client installations have server 2012 running as a virtual server.
They can see these logs files grow over time if not archived away up to 500mb sometimes. When writing 10 extra lines to the file, each with a separate call to the program that does the IO so we aren't holding the IO open, the timestamps we print on each line show from start to finish it happening within 1 second, or 2 seconds.

One of our customers recently upgraded to a server 2016 virtual server. When the log files are newly created everything runs as fast as it should, however even when the log file has hit 25mb the time taken to write these log lines is 5 or 6 seconds. and when it hit 50mb about 8 or 9 seconds. This is a problem for us because it increases the time it takes to respond to a waiting web request (not broker all magic is doing is writing an encrypted xml to disc which something else handles passing back to the web request) which can cause web applications to then timeout. If we disable the logs then the processing speeds right back up and the web requests stop timing out so we are certain it is the process of writing to a log file which is hanging everything up.

Is it possible that server 2016 somehow handles magic append line operation differently and its having to scan through the file first? Has anyone else had something like this? The customers IT says they haven't deployed anti virus yet which we thought might be a culprit. And they are newly created files by unipaas running on the new server, which eliminates a suspicion that the culprit was file owner permissions from the log files originally being copied over from the old server.

Any thoughts are appreciated as we are a bit flummoxed as to what might cause this

Thanks

Peter


Peter Ashworth
 

We found the culprit, windows defender was on and not ignoring our folder. We have got folder exclusions in place now and its working fine.

Thanks for both of your comments though.

Peter


Andreas Sedlmeier
 

Hmm, Antivirus is of course something we should have thought of first ^^. You should get familiar with the sysinternals suite. Just start the Filemonitor (now part of Processmonitor) and you see immediately who is dealing with your files and more.

I btw. do a small project at the moment which is about logs. Not a Magic project and not Magic logfiles but from other applications but there the plan is to collect the logs with Beats and ship them to Logstash / Elasticsearch. I never did this but the the first results look great and all the monitoring and visualization of events you then get for free. Way better than Windows Event Monitor and syslog ... which is what is used there currently (-> https://www.elastic.co/products/logstash) .When I find time I will do a small sample on Magic logs 

Andreas


Peter Ashworth
 

Hi Andreas,

Anti virus was the very first thing we thought of when the customer reported the issue. However the customers IT assured us there wasn't any antivirus on there at all, and apparently didn't think windows defender counted. So that was a bit annoying in that our first gut feel was actually correct all along (its been happening a couple of weeks now mitigated by archiving the logs more regularly).

Indeed Processmonitor with a path filter including the filename was how I discovered windows defender was to blame. On a 40mb file it was adding 0.7 of a second to each IO write. Which adds up quite quickly.

Peter