How to follow the basic processes for index ingestion using the Dtrace logs?

Description

Here is a filtered extract from the DTrace showing the processing of an item by the EVIndexVolumesProcessor process.

1)    The index volume is added to the ‘work item’ queue:
12:59:34.246     [6048]    (EVIndexVolumesProcessor)    <2404>    EV-L    {IVPWEBSERVICEPROCESSING.EN_US} Request to synchronise Index volumes received: XML:
<IndexVolumes><IndexVolume ContentSourceID="1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow" IndexVolumeIdentity="69702" Type="9" /></IndexVolumes>
12:59:34.293     [6048]    (EVIndexVolumesProcessor)    <2404>    EV-M    {INDEXVOLUMESMANAGER.EN_US} Weight ==> The synchronisation requested for '1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702' of type 9 will be enqueued with a weight of Normal
12:59:34.309     [6048]    (EVIndexVolumesProcessor)    <2404>    EV-L    {IVPWEBSERVICEPROCESSING.EN_US} Request to synchronise Index volumes done  return XML:
<IndexVolumes><IndexVolume ContentSourceID="1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow" IndexVolumeIdentity="69702" Message="Done" Type="9" /></IndexVolumes>

The ‘ContentSourceID’ detailed above refers to the ArchiveID.

2)    The index volume is taken from the queue for processing and checked to ensure the index volume is able to be updated:
12:59:40.871     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-M    {INDEXVOLUMEOPERATIONS.EN_US} PrepareIndexVolumeForProcessing: CheckForRollOver: True, Ignore Failed Flag: False for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702.
12:59:40.949     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-L    {LOG.EN_US} The Archive type DV_DS_VT_MB_ARCHIVE (9) will be using Small collection template
12:59:40.981     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-L    {EVCONTENTSOURCEACCESSOR.EN_US} Index volume [1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702] is valid for processing. Failed False, Offline False, BeingDeleted False, ReadOnly False, BackupMode False, IndexItemsMode 0
12:59:40.981     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-L    {INDEXVOLUMEOPERATIONS.EN_US} Check the internal state for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702
12:59:45.012     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-L    {VELOCITYPROXY.EN_US} Collection [1AEF95A72294C8847B21C5E7AEDAFA048_69702] exists.
12:59:45.418     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-M    {VELOCITYINDEXINGENGINE.EN_US} Index volume [1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702] is ready for processing

3)    The ‘HighestIndexSeqNo’ is obtained for the index volume which details the last archived item that has been indexed:
12:59:45.762     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-L    {TRACEDBCOMMAND.EN_US} Executed usps_HighestIndexSeqNo in 6 ms after 0 retries. @ArchivePointID=1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow
12:59:45.762     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-M    {STATEINITIALVERIFICATION.EN_US} Sequence Number stored stored in the Content Source: 51 - in the state XML: 25
12:59:45.778     [6048]    (EVIndexVolumesProcessor)    <Agent Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5248>    EV-L    {CONTENTSOURCEINITIALISER.EN_US}  Resetting pending work for [125 cc]:
 Any Addition work higher than 26 will be reset
 Any Deletion work higher than 51 will be reset
 Any Updates work higher than 1 will be reset

4)    The unindexed items are then requested (from Storage) by the ‘Fetcher’ thread:
12:59:46.356     [6048]    (EVIndexVolumesProcessor)    <Updater Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5216>    EV-L    {FETCHER.EN_US} Fetcher Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702 Starting Worker thread ...
12:59:46.371     [6048]    (EVIndexVolumesProcessor)    <Fetcher Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5056>    EV-H    {ITEMADDITIONSALLOCATOR.EN_US} Will start from action addition 25 to action addition 18446744073709551615

5)    Storage Crawler then retrieves the archived item(s), extracts the indexable data and passes the information back to indexing:
12:59:46.996     [2548]    (StorageCrawler)    <6088>    EV:L    CItemFetcher::RequestItem New fetch request NextISN:26 ItemISN:51 SSID:201107080126366~201107080842350000~Z~7165BE9BCACD6C7962E21E23BE44F941 (hr=Success  (0))
…
12:59:47.653     [2548]    (StorageCrawler)    <6088>    EV:L    CItemFetcher::WaitForItem NextISN:26 Timeout:30 (secs) SSID:201107080126366~201107080842350000~Z~7165BE9BCACD6C7962E21E23BE44F941 ItemISN:51 (hr=Success  (0))

6)    The index ‘fetcher’ thread keeps requesting and receiving items from Storage (Crawler) until there are no more items to fetch (or errors encountered)
12:59:47.621     [6048]    (EVIndexVolumesProcessor)    <Fetcher Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5056>    EV-L    {CLASSICEVINDEXABLEITEMTRAVERSER.EN_US} Loaded classic indexable item.  Size = 259510 bytes
12:59:47.637     [6048]    (EVIndexVolumesProcessor)    <Fetcher Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5056>    EV-M    {ITEMADDITIONSALLOCATOR.EN_US} There are some additions to do...
12:59:47.700     [6048]    (EVIndexVolumesProcessor)    <Fetcher Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:5056>    EV-H    {FETCHER.EN_US} NO MORE ITEMS TO FETCH - Processed 1 items in all. WILL STOP NOW.

7)    ‘Indexer’ thread then packages the data and sends it to the indexing engine:
12:59:47.715     [6048]    (EVIndexVolumesProcessor)    <Indexer (1) Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:6744>    EV-L    {EVADDITIONDATAREADER.EN_US} Traversing EV item. SavesetID=[201107080126366~201107080842350000~Z~7165BE9BCACD6C7962E21E23BE44F941], ItemSequenceNum=[51]
12:59:48.434     [6048]    (EVIndexVolumesProcessor)    <6116>    EV-M    {VELOCITYINDEX.EN_US} DoFlush is called by Indexer (1) Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702
12:59:48.450     [6048]    (EVIndexVolumesProcessor)    <6116>    EV-L    {VELOCITYINDEX.EN_US} Enqueuing a batch of 1 actions to Velocity. IndexVolumeID=[1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702]
12:59:51.903     [6048]    (EVIndexVolumesProcessor)    <6116>    EV-L    {VELOCITYINDEX.EN_US} Batch has been enqueued successfully to offline collection......

8)    The indexing engine is then checked for confirmation of indexed items (on this index volume) and the item status is updated:
12:59:57.934     [6048]    (EVIndexVolumesProcessor)    <6116>    EV-L    {VELOCITYPROXY.EN_US} Enumerating Log Entries for 1AEF95A72294C8847B21C5E7AEDAFA048_69702 - Veritas.EnterpriseVault.Indexing.IndexingEngineService.VelocitySrvRef.SearchCollectionAuditLogRetrieve
12:59:58.028     [6048]    (EVIndexVolumesProcessor)    <6116>    EV-L    {VELOCITYINDEX.EN_US} [99ms] DoEnumerateAcknowledgements  - IndexVolumeID=1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702
12:59:58.028     [6048]    (EVIndexVolumesProcessor)    <6116>    EV-M    {VELOCITYINDEX.EN_US} Process Acknowledgment Enumeration Response. Number of Entries:[1] Token:[0::0]
12:59:58.028     [6048]    (EVIndexVolumesProcessor)    <Status Checker Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:3060>    EV-L    {VELOCITYINDEX.EN_US} Received 1 acknowledgements from velocity
12:59:58.044     [6048]    (EVIndexVolumesProcessor)    <Status Checker Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:3060>    EV-L    {STATUSLIST.EN_US} All 1 item actions have been acknowledged
12:59:58.044     [6048]    (EVIndexVolumesProcessor)    <Status Checker Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:3060>    EV-L    {STATUSCHECKER.EN_US} Received [1] acknowledgments - Processed 1
12:59:58.044     [6048]    (EVIndexVolumesProcessor)    <Status Checker Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:3060>    EV-L    {STATUSCHECKER.EN_US} Purging acknowledgments...

9)    Finally the ‘HighestIndexSeqNo’ for the index volume is increased accordingly:
12:59:59.372     [6048]    (EVIndexVolumesProcessor)    <Auditor Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:6204>    EV-M    {STATUSLIST.EN_US} Returning ALL item actions: 1 items with Item SN:'51' - Action SN:'51' - Status:'Success' - DataReader:'' as the last Acknowledged Before First Pending
12:59:59.403     [6048]    (EVIndexVolumesProcessor)    <Auditor Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:6204>    EV-H    {AUDITOR.EN_US} Auditing [1] actions in content source - HighestActionSequenceNumberToCommit [51]
12:59:59.544     [6048]    (EVIndexVolumesProcessor)    <Auditor Thread for 1AEF95A72294C8847B21C5E7AEDAFA0481110000evshadow_69702:6204>    EV-M    {ADDITIONSMETADATAUPDATER.EN_US} Updating metadata values: HISN[25 -> 51] IndexedItems[0 -> 1] FailedItems[0 -> 0]