Filter initiated I/O problem

Boaz_Raufman · September 19, 2007, 4:00pm

Hello,

I’m working on a minifilter that suppose to write a log message to a log file for every IRP_MJ_WRITE and IRP_MJ_SET_INFORMATION. My code is based on the minispy sample.
I’m using FltCreateFile to create the log file, and FltWriteFile to write to log records into it.
The requirement is that every IRP_MJ_WRITE & IRP_MJ_SET_INFORMATION request are logged into a file, even in case of unexpected system crash or power down – thus the log info must be update immediately into the log file.
My code is running fine for a while but when a large number of threads are trying to update file the system freeze! I tried adding the FILE_WRITE_THROUGH flag on create - it holds the system running for a bit longer but eventually the problem repeats. Need help – what should I do to make this work?
I’m also wondering if the IRQL requirement for driver initiated I/O (must be PASSIVE_LEVEL) can result in having inaccurate log (in which cases the filter my get IRP with a higher IRQL)?

Thank you.

Here are the relevant parts of the code:

// Create file routine – called from the instance setup callback

NTSTATUS
OpenTraceFile (
__in PCFLT_RELATED_OBJECTS pFltObjects
)

OBJECT_ATTRIBUTES objAttr;
HANDLE handle;
NTSTATUS ntstatus;
IO_STATUS_BLOCK ioStatusBlock;
UNICODE_STRING logFileName;

if(KeGetCurrentIrql() != PASSIVE_LEVEL)
return STATUS_INVALID_DEVICE_STATE;

if (!MiniSpyData.LoggingEnabled) {

RtlInitUnicodeString(&logFileName, L"\??\C:\temp\logdata.log");

InitializeObjectAttributes(
&objAttr,
&logFileName,
OBJ_CASE_INSENSITIVE|OBJ_KERNEL_HANDLE,
NULL,
NULL);

ntstatus = FltCreateFile(
MiniSpyData.Filter,
pFltObjects->Instance,
&handle,
GENERIC_WRITE,
&objAttr,
&ioStatusBlock,
0,
FILE_ATTRIBUTE_NORMAL,
FILE_SHARE_READ,
FILE_OPEN_IF,
FILE_SYNCHRONOUS_IO_NONALERT | FILE_WRITE_THROUGH,
NULL,
0,
0);

if (!NT_SUCCESS(ntstatus)) {
return(ntstatus);
}

// Get file object from the handle
ntstatus = ObReferenceObjectByHandle(
handle, //Handle
0, //DesiredAccess
NULL, //ObjectType
KernelMode, //AccessMode
&MiniSpyData.LogFileHandle, //File Handle
NULL);

if (!NT_SUCCESS(ntstatus)) {
return(ntstatus);
}

MiniSpyData.LoggingEnabled = TRUE;
}

return STATUS_SUCCESS;

}

// This rountine insert the log info into the log file
// It is called from the pre operation callback if
// MajorFunction == IRP_MJ_WRITE or IRP_MJ_SET_INFORMATION

NTSTATUS
InsertToLogFile (
__in PCFLT_RELATED_OBJECTS pFltObjects
)

{
NTSTATUS ntstatus;
ULONG BytesWritten;

if (MiniSpyData.LoggingEnabled) {

if(KeGetCurrentIrql() != PASSIVE_LEVEL) {
return STATUS_INVALID_DEVICE_STATE;
}

ntstatus = FltWriteFile(pFltObjects->Instance,
MiniSpyData.LogFileHandle,
NULL,
strlen(“log info…\r\n”),
“log info…\r\n”,
0,
&BytesWritten,
NULL,
NULL);

if (!NT_SUCCESS(ntstatus)) {
return(ntstatus);
}
}

return STATUS_SUCCESS;

}

OSR_Community_User · September 19, 2007, 4:52pm

it’s silly to log each IRP_MJ_WRITE/IRP_MJ_SET_INFORMATION operation !
tell me the reason why you need to log it - there’re many write operations
and the system will slowdown due to logging.

I see from your source code you don’t log all IRPs (not at higher irql >
PASSIVE_LEVEL) and you’re also unable to log paged IRP_MJ_WRITE operations

wrote in message news:xxxxx@ntfsd…
Hello,

I’m working on a minifilter that suppose to write a log message to a log
file for every IRP_MJ_WRITE and IRP_MJ_SET_INFORMATION. My code is based on
the minispy sample.
I’m using FltCreateFile to create the log file, and FltWriteFile to write to
log records into it.
The requirement is that every IRP_MJ_WRITE & IRP_MJ_SET_INFORMATION request
are logged into a file, even in case of unexpected system crash or power
down - thus the log info must be update immediately into the log file.
My code is running fine for a while but when a large number of threads are
trying to update file the system freeze! I tried adding the
FILE_WRITE_THROUGH flag on create - it holds the system running for a bit
longer but eventually the problem repeats. Need help - what should I do to
make this work?
I’m also wondering if the IRQL requirement for driver initiated I/O (must be
PASSIVE_LEVEL) can result in having inaccurate log (in which cases the
filter my get IRP with a higher IRQL)?

Thank you.

Here are the relevant parts of the code:

// Create file routine - called from the instance setup callback

NTSTATUS
OpenTraceFile (
__in PCFLT_RELATED_OBJECTS pFltObjects
)

OBJECT_ATTRIBUTES objAttr;
HANDLE handle;
NTSTATUS ntstatus;
IO_STATUS_BLOCK ioStatusBlock;
UNICODE_STRING logFileName;

if(KeGetCurrentIrql() != PASSIVE_LEVEL)
return STATUS_INVALID_DEVICE_STATE;

if (!MiniSpyData.LoggingEnabled) {

RtlInitUnicodeString(&logFileName, L"\??\C:\temp\logdata.log");

InitializeObjectAttributes(
&objAttr,
&logFileName,
OBJ_CASE_INSENSITIVE|OBJ_KERNEL_HANDLE,
NULL,
NULL);

ntstatus = FltCreateFile(
MiniSpyData.Filter,
pFltObjects->Instance,
&handle,
GENERIC_WRITE,
&objAttr,
&ioStatusBlock,
0,
FILE_ATTRIBUTE_NORMAL,
FILE_SHARE_READ,
FILE_OPEN_IF,
FILE_SYNCHRONOUS_IO_NONALERT | FILE_WRITE_THROUGH,
NULL,
0,
0);

if (!NT_SUCCESS(ntstatus)) {
return(ntstatus);
}

// Get file object from the handle
ntstatus = ObReferenceObjectByHandle(
handle, //Handle
0, //DesiredAccess
NULL, //ObjectType
KernelMode, //AccessMode
&MiniSpyData.LogFileHandle, //File Handle
NULL);

if (!NT_SUCCESS(ntstatus)) {
return(ntstatus);
}

MiniSpyData.LoggingEnabled = TRUE;
}

return STATUS_SUCCESS;

}

// This rountine insert the log info into the log file
// It is called from the pre operation callback if
// MajorFunction == IRP_MJ_WRITE or IRP_MJ_SET_INFORMATION

NTSTATUS
InsertToLogFile (
__in PCFLT_RELATED_OBJECTS pFltObjects
)

{
NTSTATUS ntstatus;
ULONG BytesWritten;

if (MiniSpyData.LoggingEnabled) {

if(KeGetCurrentIrql() != PASSIVE_LEVEL) {
return STATUS_INVALID_DEVICE_STATE;
}

ntstatus = FltWriteFile(pFltObjects->Instance,
MiniSpyData.LogFileHandle,
NULL,
strlen(“log info.\r\n”),
“log info.\r\n”,
0,
&BytesWritten,
NULL,
NULL);

if (!NT_SUCCESS(ntstatus)) {
return(ntstatus);
}
}

return STATUS_SUCCESS;

}

Boaz_Raufman · September 19, 2007, 8:43pm

Petr,

Can you think of any other way to do it?

The log will be analyzed later by the application people. This is what they need.

I know that there is some cost in performances - I’m trying know to determine how much (the log record should be very small and the logging mode will be operational only when requested) but I can’t check if it’s not working…

Can you explain why paged operations are not logged (drivers and filters and new region for me)?
IRQL must be PASSVIE_LEVEL according to documentation. In which cases I’ll get WRITE/SET to disk with higher IRQL?

Thanks,
Boaz

rod_widdowson · September 20, 2007, 3:36am

Didn’t we have this last month? It’ just like deja vu all over again…

As I remember the bottom line was that if you want to write logging
information in the paging write path you cannot use a standard filesystem -
you write one yourself or you grab the mapping pointer and write direct to
the device.

OSR_Community_User · September 20, 2007, 5:12am

First of all, do you need to do it exclusively in the filter? What about using an assist User mode application that can poll the driver and extract a buffer of records (much like in the example MS has in the code). You can blast it with records and it will move along quite nicely, and you can also have the driver notify the user mode application that its buffer is getting too large to come and get the records if you have a crazy amount of records per second (since you do not want to tie up a lot of memory in kernel space). I used this model in part of my development efforts which required that I flood the driver with a high amount of small byte offset requests and log each one (create, read, write, acquire sync, release).

If you have to do it from the driver itself, you should use a buffering method so that when you hit records that you cannot write out due to the higher IRQL, you can at least store them and then push it into a worker thread that can do the work when it is safe to do it.

If you absolutely have to write each entry as it comes then I would follow rod’s suggestion with the FSCTL_GET_RETRIEVAL_POINTERS, however writing directly to the device is not a light hearted task unless it is in a controlled environment since you may run into the fun of partially allocated compression units, or unallocated regions of a sparse file. Look in the WDDK for that control code above.

OSR_Community_User · September 21, 2007, 2:00am

Make sure that you are not trying to do this in the paging i/o path. If you are, take a look at other threads about what you can and cannot do in the paging i/o path (esp. write path). (Hint: You’d have to very carefully roll your own irps.) Otherwise, you can deadlock.

Danilo

Boaz_Raufman · September 21, 2007, 2:12am

The user mode solution was my first choice but the problem is how I can be sure the every action is logged in case of an unexpected problem such as power failure. If there is some way to be sure that nothing is missed I’ll choose that solution immediately.
In fact can I really know that the log reflect the disk operations even if I manage to write it from the driver?

Following the above leads I located a long discussions under the title “Why does blocking the Paging I/O request lead to deadlock?”. It seems to discuses similar problems. Reading this I filtered out paging I/O operations from my log filter:
if !(Data->Iopb->IrpFlags & (IRP_PAGING_IO | IRP_SYNCHRONOUS_PAGING_IO) …

Now the filter/logger is not freezing anymore (of course – disk performance still suffer).

This leaves me with some open questions:

What will happen if the system crash - for example right after the FltWriteFile call – can I avoid inconsistency between the log and the disk in that case?
Do I have to wait on the file handle after the write to confirm the write to the log?
Which I/O operations am I missing because of the IRQL PASSIVE_LEVEL limit (except the paging IO)?

Boaz

OSR_Community_User · September 21, 2007, 4:23am

If you are doing a create, write, close at every transaction, you can expect pretty dismal performance. Especially if you have a pretty active application. In my world, any given game that weighs in over a gig has some pretty wicked loading patterns, and I can go through hundreds or thousands of requests in no time flat. My customers would go off the wall if they lost even a few frames per second in their favorite game because i wrote sloppy performing kernel code.

You could set the flags and force a flush each time, but your performance will be horrid. Unless you are trying to write a crashlogger that is critical and cannot afford to buffer anything, you are going to have a performance issue.

Writing extra code to do some sort of confirmation will only add more complexity to an otherwise simple IO operation and again cause performance issues.

If the system crashes after FltWritefile, most likely it isnt going to be written, and it depends on what crashed it, was your thread running, is there more than 1 proc, when did it crash, did it get buffered (more likely)… etc… There are a lot of reasons of why it would or would not write the record, and trying to determine it would be like tracking grains of sand in a dust storm. You would have to trace where everything was in time to see if it made it.

If it REALLY had to be that critical, you may be better off looking at a user module that sends the log entry to a remote monitoring piece somewhere else via TCP socket because the other option of running locally with unbuffered single entry critical writes is going to be bad news in the performance category.