March 5, 2010

Simple audit logging with DO4: code + some analysis of DO4 brains :)

I'm slowly progressing with adding more samples to Manual project, and today I added a really nice (as I think) example of DO4 usage. It's an IModule adding audit logging to the Domain.

Features involved:
  • Automatic IModule registration and typical usage pattern
  • Automatic registration of instances of open generics (there are AuditRecord<T> and SyncInfo<T>, the second one is used just to dump its actually registered instances)
  • Binding to Session events to get notified on Entity changes and transaction-related events
  • Using IHasExtensions interface - likely, you don't know it is implemented on Domain, Session and Transaction. This sample shows when it is really helpful.
  • Gathering change info and creating audit records on transaction commit.
  • Some conditions that might be interesting to such services are tested there, e.g. if there is a nested transaction (Transaction.IsNested), or if DisconnectedState is attached to Session (Session.IsDisconnected).
  • Prefetch API usage. Look for "Prefetch" there. Btw, I use it with .Batch() in TransactionCommitting(...) handler - to split the original sequence to relatively small parts (1000 items) and then prefetch & process each of them. If Session uses weak cache (now it can use strong as well), this helps to avoid possible cache misses after prefetch by significantly reducing the probability of GC there.
  • New way of making DO4 to use a dedicated KeyGenerator instance for TransactionInfo.Id property - by default, DO4 uses one KeyGenerator for each key type, so they are shared. Earlier almost identical case was discussed here, and it was really ugly. Now it's much less ugly, but actually, I still dislike the idea of declaring a special type for this (alternative is to make the same by adding IoC configuration in App.config, but I finally preferred to define named service in code using an attribute).
The test was inspired by idea to show how open generics registration work in DO4 and this post. The audit logging  used here is pretty simple, but I think it's good enough for sample; if you're interested in more complex one, try to use OperationCapturer - it is used by DisconnectedState and designed for exactly this purpose.

What I like in this sample:
  • To get all this stuff working in any Domain, you should just ensure the SimpleAuditModule and AuditRecord<T> types are registered there - that's it (so if they're in a single assembly, you must simply register it). Convention over configuration!
  • We implemented a general purpose logic (audit) and attached it to Domain it knows nothing about. Unification and decoupling.
  • Doing the same with SQL would involve much more complex code - just imagined the hell with triggers  on all the tables :) Some stuff, like AuditRecord.EntityKey and AuditRecord.EntityAsString properties, are simply unimaginable there. So we use OOP features to make it simpler.
AFAIK, this is the first sample showing this kind of logic. I shown SyncInfo<T> there to indicate sync can be implemented this way. The same is about security - just add new assembly, and you've got it. Imagine this with any other  ORM tool :)

Brief overview of file structure:
Sample output:
Automatically registered generic instances:

Audit log:

Transaction #1 (04.03.2010 22:23:47, 203ms)
  Created Cat Tom, Id: #1, Owner: none
          Current state: Cat Tom, Id: #1, Owner: Alex
  Created Dog Sharik, Id: #2, Owner: none
          Current state: Dog Sharik, Id: #2, Owner: none

Transaction #2 (04.03.2010 22:23:47, 15ms)
  Created Cat , Id: #3, Owner: none
          Current state: removed Cat, (3)

Transaction #3 (04.03.2010 22:23:47, 93ms)
  Changed Cat Musya, Id: #3, Owner: none
          Current state: removed Cat, (3)

Transaction #4 (04.03.2010 22:23:47, 31ms)
  Removed Cat, (3)
          Current state: removed Cat, (3)

Transaction #5 (04.03.2010 22:23:47, 78ms)
  Created Person Alex, Id: #4, Pets: 
          Current state: Person Alex, Id: #4, Pets: Tom

Transaction #6 (04.03.2010 22:23:47, 31ms)
  Changed Cat Tom, Id: #1, Owner: Alex
          Current state: Cat Tom, Id: #1, Owner: Alex
  Changed Person Alex, Id: #4, Pets: Tom
          Current state: Person Alex, Id: #4, Pets: Tom

Note: transaction durations are significantly exaggerated because of JITting here (test isn't repeating). To be sure, I tried to repeat a part of it in a loop - 90% of transactions were showing 0ms duration.

A bit of analysis

Here is SQL Profiler screenshot showing the batch executed during the last updating transaction:

Can you find out why this batch was "flushed"?

Batch "flush" happens when someone (query) needs a result right now. If you take a look at red SQL there, you'll find the last statement there (SELECT) looks like EntitySet loading. Acutally, the batch was executed because Person.ToString() method invoked during building one of AuditRecords started to enumerate Person.Pets (EntitySet), which was not yet loaded...

"Wait, this is impossible - just before this moment we added an item to this collection (by setting paired association), so it must already be loaded!" - that's what come to my mind first :)

But after thinking a bit more I discovered this behavior is correct: we have one more optimization allowing EntitySet to do not load its state (actually, its isn't simply state loading anyway), if it is precisely known an item that we adding it can be added to it without any check (the simplest case: a item is is newly created entity). In this case it was precisely known, because Person and Animal state was already fetched (two preceding SELECT queries in log did this).

So adding an item didn't lead to EntitySet loading; this happened only on subsequent Person.ToString() call executed by audit logger.

Isn't DO4 a smart guy? ;)

You should note as well that .Prefetch() doesn't lead to any queries, if everything it needs is already loaded. So in this case all my stuff with .Batch() / .Prefetch() did nothing (actually, it did - it performed all the checks). But if transaction would be long, may be it could help ;) (actually, very rare case, so it's better to remove it from TransactionCommitting(...) or use it only if its duration is relatively big ;) ).

Ok, I'm going to get some sleep now - hopefully, the article was helpful. Questions, etc. are welcome, but I'll be able to reply only in 6-8 hours :)

Have a good night / day!