In an ISAPI filter, what is a good approach for a common logfile for multiple processes?

Question

I have an ISAPI filter that runs on IIS6 or 7. When there are multiple worker processes ("Web garden"), the filter will be loaded and run in each w3wp.exe.

How can I efficiently allow the filter to log its activities in a single consolidated logfile?

• log messages from the different (concurrent) processes must not interfere with each other. In other words, a single log message emitted from any of the w3wp.exe must be realized as a single contiguous line in the log file.

• there should be minimal contention for the logfile. The websites may serve 100's of requests per second.

• strict time ordering is preferred. In other words if w3wp.exe process #1 emits a message at t1, then process #2 emits a message at t2, then process #1 emits a message at t3, the messages should appear in proper time order in the log file.

The current approach I have is that each process owns a separate logfile. This has obvious drawbacks.

Some ideas:

• nominate one of the w3wp.exe to be "logfile owner" and send all log messages through that special process. This has problems in case of worker process recycling.

• use an OS mutex to protect access to the logfile. Is this high-perf enough? In this case each w3wp.exe would have a FILE on the same filesystem file. Must I fflush the logfile after each write? Will this work?

any suggestions?

Answer 1

Would logging to a database make sense here?

Answer 2

I've used a UDP-based logging system in the past and I was happy with this kind of solution.

The logs are sent via UDP to a log-collector process which his in charge of saving it to a file on a regular basis.

I don't know if it can work in your high-perf context but I was satisfied with that solution in a less under-stress application.

I hope it helps.

Answer 3

Rather than an OS Mutex to control access to the file, you could just use Win32 file locking mechanisms with LockFile() and UnlockFile().

Answer 4

At first I was going to say that I like your current approach best, because each process shares nothing, and then I realized, that, well, they are probably all sharing the same hard drive underneath. So, there's still a bottleneck where contention occurs. Or maybe the OS and hard drive controllers are really smart about handling that?

I think what you want to do is have the writing of the log not slow down the threads that are doing the real work.

So, run another process on the same machine (lower priority?) which actually writes the log messages to disk. Communicate to the other process using not UDP as suggested, but rather memory that the processes share. Also known, confusingly, as a memory mapped file. More about memory mapped files. At my company, we have found memory mapped files to be much faster than loopback TCP/IP for communication on the same box, so I'm assuming it would be faster than UDP too.

What you actually have in your shared memory could be, for starters, an std::queue where the pushs and pops are protected using a mutex. Your ISAPI threads would grab the mutex to put things into the queue. The logging process would grab the mutex to pull things off of the queue, release the mutex, and then write the entries to disk. The mutex is only protected the updating of shared memory, not the updating of the file, so it seems in theory that the mutex would be held for a briefer time, creating less of a bottleneck.

The logging process could even re-arrange the order of what it's writing to get the timestamps in order.

Here's another variation: Contine to have a separate log for each process, but have a logger thread within each process so that the main time-critical thread doesn't have to wait for the logging to occur in order to proceed with its work.

The problem with everything I've written here is that the whole system - hardware, os, the way multicore CPU L1/L2 cache works, your software - is too complex to be easily predictable by a just thinking it thru. Code up some simple proof-of-concept apps, instrument them with some timings, and try them out on the real hardware.

Answer 5

My suggestion is send messages asynchronously (UDP) to a process that will take charge of recording the log.
The process will :
- one thread receiver puts the messages in a queue;
- one thread is responsible for removing the messages from the queue putting in a time ordered list;
- one thread monitor messages in the list and only messages with time length greater than the minimum should be saved in file (to prevent a delayed message to be written out of order).

Answer 6

You could continue logging to separate files and find/write a tool to merge them later (perhaps automated, or you could just run it at the point you want to use the files.)

Answer 7

Event Tracing for Windows, included in Windows Vista and later, provides a nice capability for this.

Excerpt:

Event Tracing for Windows (ETW) is an efficient kernel-level tracing facility that lets you log kernel or application-defined events to a log file. You can consume the events in real time or from a log file and use them to debug an application or to determine where performance issues are occurring in the application.