cancel
Showing results for 
Search instead for 
Did you mean: 

Insights

 

Introduction

In the previous article we covered some of the DTRACE basics such as how to run it, and an overview of common things to look for in each and every DTRACE that you produce.  In this article we will cover some of the more advanced topics, such as Filtering and Triggers.  Both of these are good features to know about, and can be used to help narrow down the amount of data that gets captured for an issue you are investigating.  They require some practice and this article will walk through an example of each so that it’s possible for you to get a feel for how and when they might be used.

Filtering

Let’s cover filtering first of all.  It was touched upon in the previous article, but here I’ll go into it in more detail.  Filtering, as the name implies, allows you to alter which lines make it into the trace file.  You can exclude everything, and include just specific matching lines, or you can include everything and exclude just specific matching lines.

In the following example, we will cover including just specific, relevant lines. 

The issue we’re investigating is why some items are archived, and others are not.  When processing a mailbox with many thousands of items in it, the trace file normally produced can be quite large.  For example in this particular test I had 329 calendar items, to compare the sizes of the resultant DTRACE :

No filter               17.8 Mb

Filtered                   .5 Mb

A big difference as you can see, and as well as the size being much, much smaller, it’s actually more helpful, at least for this issue, in having the smaller file with the relevant information in it.

 

The way to obtain the right things to filter on (for either inclusion or exclusion) is somewhat based on trial and error, and somewhat based on experience.  To help it is often easier to get a normal trace file first, and review it in detail.  During that review you would make a note of relevant strings that you would want to include (or exclude)

I did this for the example provided here, and came up with the following includes:

  1. :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
  2. {GetCalculatedModifiedDate:#1285} Calculated date (dd/mm/yyyy): [09/02/2011 20:35.34] [PR_MESSAGE_DELIVERY_TIME]
  3. :CArchivingAgent::IsEligibleForArchive(/o=EV Training/ou=First Administrative Group/cn=Recipients/cn=mrg) |The message titled: GambleGobble has the retention category of its parent folder its value  is 1064EA2220AA1774199F44FAEAB0D81291b10000evsite   |
  4. :CArchivingAgent::IsEligibleForArchive(/o=EV Training/ou=First Administrative Group/cn=Recipients/cn=mrg) |The message titled: GambleGobble is eligible for archive  |
  5. :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
  6. CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]

I didn’t find any particular excludes, and as I’ve got more includes than excludes this is how I decided to proceed :

Most of the lines identified above have the common element “IsEligibleForArchive”, a function within the Archiving Agent.  So we can use that.  This covers lines 1, 3, 4, and 5.  It is also good because it’s obviously a main decision point it is determining whether an item is eligible for archive – exactly what we’re after if we’re trying to see why some items aren’t being archived.

Another relevant line contains the element “GetCalculatedModifiedDate”.  This also sounds important to our investigation so we should include that.  This covers line 2.

The final line identified doesn’t have that common string. ..  in effect all it’s doing is telling us which strategy it falls under, age or quota.  We can include it, it might be relevant.  This covers line 6.

Essentially that’s the process I suggest adopting in order to get an initial filter .. Go through each of the lines you identified (in this case just a small number) and work out anything which is common, and then identify whether you really need it or not. 

This is often an iterative process!

In the first trace, where I just captured everything I ended up with a trace file of nearly 18 Mb, the header looks like this :

 

And now it looks like this :

 

And the output :

8567     08:04:42.139     <1376>            EV:M    :CArchivingAgent::IsEligibleForArchive() |Entering routine  |

8572     08:04:42.139     <1376>            EV:L     {GetCalculatedModifiedDate:#1285} Calculated date (dd/mm/yyyy): [20/04/2009 16:38.25] [PR_MESSAGE_DELIVERY_TIME]

8573     08:04:42.139     <1376>            EV:L     :CArchivingAgent::IsEligibleForArchive(/o=EV Training/ou=First Administrative Group/cn=Recipients/cn=mrg) |The message titled: Hector has the retention category of its parent folder its value  is 1064EA2220AA1774199F44FAEAB0D81291b10000evsite   |

8574     08:04:42.139     <1376>            EV:L     :CArchivingAgent::IsEligibleForArchive(/o=EV Training/ou=First Administrative Group/cn=Recipients/cn=mrg) |The message titled: Hector is eligible for archive  |

8575     08:04:42.139     <1376>            EV:H    :CArchivingAgent::IsEligibleForArchive() |Exiting routine |

8576     08:04:42.139     <1376>            EV:L     CArchivingAgent::QueueEligibleItem - Eligible Item Strategy [Age]

 

That’s per item and of course it’s much better than the previous run when these sort of things were buried deep inside the trace, with a lot of other activity.

Here is an example (from a separate run) of what the new output looks like when an item isn’t eligible:

148974  08:18:07.842     <4252>EV:M    :CArchivingAgent::IsEligibleForArchive() |Entering routine  |

148979  08:18:07.842     <4252>EV:L     {GetCalculatedModifiedDate:#1285} Calculated date (dd/mm/yyyy): [21/06/2011 13:17.52] [PR_MESSAGE_DELIVERY_TIME]

148980  08:18:07.842     <4252>EV:L     :CArchivingAgent::IsEligibleForArchive(/o=EV Training/ou=First Administrative Group/cn=Recipients/cn=mrg) |The message titled: shonky will not be archived as its inactivity period has not expired  |

148981  08:18:07.842     <4252>EV:H    :CArchivingAgent::IsEligibleForArchive() |Exiting routine |

In order to set up DTRACE to capture like this, I did the following :

  1. Start DTRACE
  2. Set archivetask v
  3. Filter
  4. Clear both
  5. + IsEligibleForArchive
  6. + GetCalculatedModifiedDate
  7. + ::QueueEligibleItem
  8. Exit
  9. Log testlogfile.log

All that is left to do is to run the archiving task, and then review the trace.

 

Triggers

Triggers are another great tool for assisting in troubleshooting an issue.  They are used to start/capture DTRACE output when a specific “something” is logged.  For example, say the archiving task is processing thousands of items, and “sometimes” an error is thrown, but you can’t guarantee which item it will be on.  When the error is thrown, you want all the tracing possible.  This is the sort of situation which triggers excel in.  Hopefully you will see that filters are not useful here.  In this example I set a filter to operate on IndexServer when it encounters "parsed", as follows :-

  1. Open Dtrace
  2. Set indexserver v
  3. trigger + parsed

'parsed' - added to filter include strings

Current Filter Settings:

  Include strings:

    parsed

  No Include Strings

 

  1. watch 2 c:\dt1.log 10 yes

Watch Trace Output

Watching is enabled to 'c:\outputlogfile.log'     (Use 'watch' to disable)

 

When you now do a search from an end user workstation you will see the following logged :

 

And if you do two searches, trigger will then be completed (because that is what we specified above)

 

If you then look at the DTRACE file which is generated you will see two big "chunks" of data along similar lines to each other, along with the regular file versions, and registry information.

 

Note it says that there are 10 lines after the trigger line, and we see that here :

 

A little further explanation on the lines within DTRACE in the above example should help you follow what is happening.

First of all the syntax of what you trigger on is very similar to the way you do the filter.  So “Trigger + parsed” means to add an inclusion for the word/phrase parsed.  You can add multiple, just like with filtering.

Second of all the line which shows :

watch 2 c:\dt1.log 10 yes

What this means is that you want to record up to 2 occurences of the error, in to the file c:\dt1.log, you want 10 lines of output, and you want to use the filtering/triggering you’ve defined.

You can adapt those as you wish.

In addition, you can just type “Watch”, and you will be prompted for each of the values, with some default responses provided for you – good for a first attempt at gathering triggered DTRACE.

Manipulation using TextPad

DTRACE files are often quite large, and therefore pretty much impossible to handle with the regular Microsoft Windows Notepad application.  There are many alternatives to pick from, for example :

  • Notepad++
  • TextPad

Many people in Symantec Support use TextPad.  I actually use both.  Normally I use Notepad++, but TextPad has one current killer feature which really helps in troubleshooting, and helps greatly in producing the list of things that you might want to include in a triggered DTRACE.  You can add a flag to particular lines when you’re doing a search, and you can select+copy those lines, and paste them in to a new file.  Here is how to perform those steps, using the large trace file that I generated for the example on filtering.

  1. Open TextPad
  2. Drag and drop in the DTRACE that was generated using no filter
  3. Click Search -> Find, or press F5
  4. Enter IsEligibleForArchive and click on Mark All in this dialog :

You will see lots of little blue angles at the left of the trace now in TextPad like this:

 

  1. From the TextPad menu go to Edit -> Copy Other -> Bookmarked Lines.  This will add all those lines to a buffer.
  2. Go to File -> New
  3. Now do Edit -> Paste

All the lines that will be pasted in to the new document will be the bookmarked lines from the main trace.

A View into the Future

Listen out for the phrase BackTrace when you see Enterprise Vault 10.  This is the next generation of DTRACE whereby data is gathered automatically when issues occur.

Conclusion

DTRACE, as you can imagine, is a huge topic.  Even with the two articles produced so far they only cover some of the more elementary aspects of what DTRACE can show you and Symantec Support.  Some of the aspects of DTRACE are as much experience/art as science, and it’s practice that gets you to grips with it. 

Working for cloudficient.com
Comments

Nice addition to the first article

Good work :)

Maybe now would be a good time for an article on Backtrace?

It is in the works :)