Friday, May 03, 2013

BizTalk ETW tracing and LogParser

 

On a recent project we’ve implemented ETW tracing following the best practices and it indeed gave a great feeling of being able to enable tracing whenever we needed to. My colleague Tomasso Groenendijk implemented an ESB Itinerary Service for ETW tracing and we used the Cat controller to create log files and perform analysis, i didn’t knew about a great tool (or how to use it) called LogParser which basically is the missing puzzle piece (thanks to my other colleague Glenn Fecunda).

LogParser is a great tool which is superfast at analyzing large amounts of data by building up some sort of internal database. It allows you to query the data, in a SQL like syntax.

Below is a small example, which shows a simple query, however, once you see how fast it is on large amounts of data, it sure is a tool worth looking at. The most practical use if when you have a log for which there are special providers (EventLog, IIS etc), but still, with the ‘general’ providers TEXTLINE you can get the idea of how it works, and from there, it’s easy to write some .cpp to create your own provider Knipogende emoticon.

TESTCODE

TraceManager.CustomComponent.TraceDetails("test, " + DateTime.Now.ToString(), null);

EventTrace (started a trace with the Cat Controller)

[0]2CB4.1710::04/29/2013-13:49:08.524 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]3590.2874::04/29/2013-13:49:56.360 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]364C.2604::04/29/2013-13:49:59.418 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]3788.254C::04/29/2013-13:50:32.604 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]1624.1DD4::04/29/2013-13:50:34.982 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]1B28.2700::04/29/2013-13:50:40.279 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]0454.1260::04/29/2013-13:50:43.305 [Event]:INFO: This is warm-up event written into ETW trace log - please ignore

[0]3360.0FD8::04/29/2013-13:53:07.038 [Event]:test, 29-4-2013 13:53:07

[0]3360.0FD8::04/29/2013-13:53:07.462 [Event]:test, 29-4-2013 13:53:07

[0]3360.0FD8::04/29/2013-13:53:16.939 [Event]:test, 29-4-2013 13:53:16

[0]3360.0FD8::04/29/2013-13:53:20.961 [Event]:test, 29-4-2013 13:53:20

[0]3360.0FD8::04/29/2013-13:53:21.201 [Event]:test, 29-4-2013 13:53:21

[0]3360.0FD8::04/29/2013-13:53:21.384 [Event]:test, 29-4-2013 13:53:21

[0]3360.0FD8::04/29/2013-13:53:21.889 [Event]:test, 29-4-2013 13:53:21

[0]3360.0FD8::04/29/2013-13:53:22.075 [Event]:test, 29-4-2013 13:53:22

[0]3360.0FD8::04/29/2013-13:53:22.235 [Event]:test, 29-4-2013 13:53:22

[0]3360.0FD8::04/29/2013-13:53:22.418 [Event]:test, 29-4-2013 13:53:22

[0]3360.0FD8::04/29/2013-13:53:22.584 [Event]:test, 29-4-2013 13:53:22

[0]3360.0FD8::04/29/2013-13:53:22.731 [Event]:test, 29-4-2013 13:53:22

Select using LogParser (-i:TEXTLINE…no other provider available)

LogParser "SELECT * FROM BizTalkTrace.txt WHERE Text LIKE '%22.731%'" -i:TEXTLINE

LogFilename   Index Text

20    [0]3360.0FD8::04/29/2013-13:53:22.731 [Event]:test, 29-4-2013 13:53:22

Exclude the INFO lines

LogParser "SELECT * FROM BizTalkTrace.txt WHERE TEXT NOT LIKE '%[Event]:INFO%'" -i:TEXTLINE

 

 

So, go on and develop your own providers….and keep me in the loop once they are done Knipogende emoticon.

 

Regards,

 

Sander

No comments: