EV 10.0.2 Indexing processing 500 items an hour

[Jose_Luis_Per1]

Hi,

I installed EV10.0.2 for Lotus Domino recently and everything seemed to work OK until we tried to search some items: Indexing engine has archived 120,000 items when EV has archived 800,000+ items so far.

I checked the behaviour and noticed that every 2 - 10 minutes EV indexes 100 +- 10 items and then it stops for 2 - 10 minutes again.  The final result is that EV is indexing 12,000 items a day (instead of the expected 25,00 / hr). The search results bring the message: "Vault Store is being updated" (and it will remain that way untill I find out what´s going on.

I can discard antivirus issues since we unininstalled SEP to test. Any ideas?

Thank you!

[AndrewB]

you'll probably want to start with a dtrace of the indexing processes. let it run for an hour and then look through it to identify what's happening to cause it to stop and start like you describe

[Jose_Luis_Per1]

Thanks Andrew,

I dtraced indexServer, indexBroker and StorageCrawler for an hour and only got the following lines in the log file:

62 17:20:42.714 [5164] (EVIndexAdminService) <7892> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

69 17:21:02.836 [5164] (EVIndexAdminService) <7892> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

79 17:21:22.959 [5164] (EVIndexAdminService) <7892> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

91 17:21:43.081 [5164] (EVIndexAdminService) <7892> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

116 17:22:03.219 [5164] (EVIndexAdminService) <7892> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

117 17:22:04.093 [5164] (EVIndexAdminService) <6800> EV~I |Event ID: 41302 The Indexing Service has completed its initialization. The service is now functioning fully.

140 17:22:05.231 [5164] (EVIndexAdminService) <7892> EV~I |Event ID: 41297 The Indexing Service has started (10.0.2.1112).

Not much, I know...

Don´t know for sure if it´s stopping and starting really but the thing is that it is processing 100 items at once every 2 to 10 minutes.

[AndrewB]

well, you dont have anything in the dtrace really other than the index service starting.

[Jose_Luis_Per1]

Andrew,

I was able to get finally an event and in the dtrace only after launching a reindexing task: "Indexing Engine Unreachable". It surprises me that items are being added to the index (really slowly) without logging any activity on dtrace logs. Here´s the dtrace output:

907 11:17:51.262 [7724] EV: CProcessState::SetStopping

920 11:18:09.920 [8264] (EVIndexAdminService) <7716> EV~I |Event ID: 41298 The Indexing Service has stopped (10.0.2.1112).

927 11:18:10.419 [2920] EV: CProcessState::SetStopping

1146 11:18:49.076 [8308] (MonitoringConfigUtility) <804> EV~I |Event ID: 41120 Monitoring Configuration Utility started with command '/update DBGROUPSQL2.NETPOLAR.COM\PSQL2 NOSITE H:\Program Files (x86)\Enterprise Vault\reports\evomdb_updates.log '

1159 11:18:49.123 [8308] (MonitoringConfigUtility) <804> EV~I |Event ID: 41396 Monitoring Configuration Utility information: 'Upgrade/Migration of Monitoring database started.'

1166 11:18:49.154 [8308] (MonitoringConfigUtility) <804> EV~I |Event ID: 41121 Monitoring Configuration Utility completed successfully. Exit code NoUpgradeDone(19). Additional info: No upgrade required

1190 11:18:56.704 [1900] (EVIndexAdminService) <7436> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

1208 11:19:16.829 [1900] (EVIndexAdminService) <7436> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

1215 11:19:36.953 [1900] (EVIndexAdminService) <7436> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

1224 11:19:57.077 [1900] (EVIndexAdminService) <7436> EV~I |Event ID: 41299 The Indexing Service is pending initialization.|Requesting additional time for initialization routines....

1249 11:20:05.501 [1900] (EVIndexAdminService) <5704> EV~I |Event ID: 41302 The Indexing Service has completed its initialization. The service is now functioning fully.

1272 11:20:07.139 [1900] (EVIndexAdminService) <7436> EV~I |Event ID: 41297 The Indexing Service has started (10.0.2.1112).

1714 11:28:51.021 [9164] (EVIndexVolumesProcessor) <Agent List thread:5412> EV~E |Event ID: 41352 The processing of the Rebuild Sub task has stopped following errors.|Rebuild Sub task ID: 1AB30F8A2A937E648BCEA79D86339BA561110000vault01_10|Reason: Undefined|Error Type: NonCritical|Description: Indexing engine unreachable.

1838 11:31:49.268 [9164] (EVIndexVolumesProcessor) <Agent List thread:5412> EV~E |Event ID: 41352 The processing of the Rebuild Sub task has stopped following errors.|Rebuild Sub task ID: 1DA737348C15C594AB6CA851AA4A0F3251110000vault01_9|Reason: Undefined|Error Type: NonCritical|Description: |Error 1: Indexing engine unreachable.|Error 2: Indexing engine unreachable.

1844 11:32:06.163 [9164] (EVIndexVolumesProcessor) <Agent List thread:5412> EV~E |Event ID: 41352 The processing of the Rebuild Sub task has stopped following errors.|Rebuild Sub task ID: 155ADF9A96FB0C848B74650B8E238463C1110000vault01_12|Reason: Undefined|Error Type: NonCritical|Description: Indexing engine unreachable.

1852 11:32:10.360 [9164] (EVIndexVolumesProcessor) <Agent List thread:5412> EV~E |Event ID: 41352 The processing of the Rebuild Sub task has stopped following errors.|Rebuild Sub task ID: 1DA737348C15C594AB6CA851AA4A0F3251110000vault01_13|Reason: Undefined|Error Type: NonCritical|Description: |Error 1: Indexing engine unreachable.|Error 2: Indexing engine unreachable.

Thanks!

[AndrewB]

we observed a similar issue with the new indexing engine with one of our customers. i believe we increased the maximum concurent indexing capacity to help overcome the issue but we also made some changes to timeouts and other things along with regular reboots of the server until it got over the issue. if the first suggestion and a reboot doesnt help then i'd suggest opening a case so that symantec can start keeping track of this issue too.

[Jose_Luis_Per1]

Increasing  Maximum Concurrent Indexing Capacity and rebooting did not make any difference. I´ll update this thread with the solution as soon as we get there with tech support. Thanx!

[Jeff_Shotton]

Hi,

What is the memory specification of the EV server?

The indexing engine is operating as a web based service and is contactable on the port specified on the advanced properties page of the Enterprise Vault server. 7215 is the default. This is going to be contacted even by the 'local' resources.

I would check to see if you have something killing the connection off...problems with IIS, NIC teaming, firewalls, dodgy NIC etc etc.

try using TCPview. You should see query-service.exe looking at remote port 7215...it should not be flashing red and green (port closed/port created)

http://technet.microsoft.com/en-gb/sysinternals/bb897437.aspx

Regards,

Jeff

[Jose_Luis_Per1]

Thanks Feff, I´ll check: NIC teaming is enabled.

On the other hand, I was dtracing indexserver and indexbroker and the right processes to check against in 64 bit indexing are in thios case EVIndexAdminService, EVINdexVolumesProcessor and StorageCrawler. I dtraced them and this time I got a lot of activity. I found the following exception constantly:

7545  14:51:15.973           [8488]          (EVIndexVolumesProcessor)         <5808>         EV-H   {IndexingWCFProxy`1} Exception: Error in deserializing body of reply message for operation 'CollectionBrokerEnqueueXml'. Info: Diag: Type:System.ServiceModel.CommunicationException ST:|Server stack trace: |   at System.ServiceModel.Dispatcher.XmlSerializerOperationFormatter.DeserializeBody(XmlDictionaryReader reader, MessageVersion version, XmlSerializer serializer, MessagePartDescription returnPart, MessagePartDescriptionCollection bodyParts, Object[] parameters, Boolean isRequest)|   at System.ServiceModel.Dispatcher.XmlSerializerOperationFormatter.DeserializeBody(XmlDictionaryReader reader, MessageVersion version, String action, MessageDescription messageDescription, Object[] parameters, Boolean isRequest)|   at System.ServiceModel.Dispatcher.OperationFormatter.DeserializeBodyContents(Message message, Object[] parameters, Boolean isRequest)|   at System.ServiceModel.Dispatcher.OperationFormatter.DeserializeReply(Message message, Object[] parameters)|   at System.ServiceModel.Dispatcher.ProxyOperationRuntime.AfterReply(ProxyRpc& rpc)|   at System.ServiceModel.Channels.ServiceChannel.HandleReply(ProxyOperationRuntime operation, ProxyRpc& rpc)|   at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)|   at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)|   at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)|Exception rethrown at [0]: |   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)|   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)|   at Symantec.EnterpriseVault.Indexing.IndexingEngineService.VelocitySrvRef.VelocityPort.CollectionBrokerEnqueueXml(CollectionBrokerEnqueueXmlRequest request)|   at lambda_method(ExecutionScope , VelocityPort )|   at KVS.EnterpriseVault.Runtime.WCF.WCFProxy`1.Invoke[TResult](Expression`1 method)|   at Symantec.EnterpriseVault.Indexing.Common.IndexingWCFProxy`1.Invoke[TResult](Expression`1 method) Inner:System.InvalidOperationException: There is an error in XML document (1, 99215). ---> System.FormatException: The string '2012-12-12T14:51:14-04:-30' is not a valid AllXsd value.|   at System.Xml.Schema.XsdDateTime..ctor(String text, XsdDateTimeFlags kinds)|   at System.Xml.XmlConvert.ToDateTime(String s, XmlDateTimeSerializationMode dateTimeOption)|   at System.Xml.Serialization.XmlSerializationReader.ToDateTime(String value)|   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderVelocityPort.Read87_logmessage(Boolean isNullable, Boolean checkType)|   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderVelocityPort.Read88_log(Boolean isNullable, Boolean checkType)|   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderVelocityPort.Read303_Item(Boolean isNullable, Boolean checkType)|   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderVelocityPort.Read304_Item(Boolean isNullable, Boolean checkType)|   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderVelocityPort.Read481_Item()|   at Microsoft.Xml.Serialization.GeneratedAssembly.ArrayOfObjectSerializer44.Deserialize(XmlSerializationReader reader)|   at System.Xml.Serialization.XmlSerializer.Deserialize(XmlReader xmlReader, String encodingStyle, XmlDeserializationEvents events)|   --- End of inner exception stack trace ---|   at System.Xml.Serialization.XmlSerializer.Deserialize(XmlReader xmlReader, String encodingStyle, XmlDeserializationEvents events)|   at System.Xml.Serialization.XmlSerializer.Deserialize(XmlReader xmlReader, String encodingStyle)|   at System.ServiceModel.Dispatcher.XmlSerializerOperationFormatter.DeserializeBody(XmlDictionaryReader reader, MessageVersion version, XmlSerializer serializer, MessagePartDescription returnPart, MessagePartDescriptionColl

[Jose_Luis_Per1]

Hi,

tech support found some problems with the current archive and asked me to create a new one. After that indexed items are still increasing at a very slow rate in index volumes but dtracing against EVIndexAdmin, EVINdexVolumeProcessor and StorageCrawler brings constantly duplicate index information and it seems to me indexing is busy "reprocessing" previously indexed items endless (20,000 items in half an hour which would be great if that represented items added). Here´s the log output:

 (EVIndexVolumesProcessor)        <Status Checker Thread for 10BE902F94A1AD6458E47632CCD7791E31110000vault01_21:11676>        EV-H        {StatusList} WARNING, item found in status list but already acknowledgment. Seems to be a duplicate. StatusList copy:[Item SN:'13732' - Action SN:'13732' - Status:'Success' - DataReader:''] Incoming copy:[Item SN:'0' - Action SN:'13732' - Status:'Success']|Called from: DoAcknowledgeAction|AcknowledgeActions|ProcessBatchOfAcknowledgements|DoWork|DoWorkThread|runTryCode|ExecuteCodeWithGuaranteedCleanup|Run|ThreadStart|
56498        10:48:32.566         [3372]

Is anyone experiencing this with EV10.0.2? This is a Lotus Domino environment but  I don´t think that fact is relevant at all.

Thanks!

[Jose_Luis_Per1]

Another idea:

From this lines in the dtrace file:

nner:System.ServiceModel.CommunicationException: Error in deserializing body of reply message for operation 'CollectionBrokerEnqueueXml'. ---> System.InvalidOperationException: There is an error in XML document (1, 3054). ---> System.FormatException: The string '2013-01-03T10:44:40-04:-30' is not a valid AllXsd value

This environment is installed in Caracas where for example time zone was changed 1/2 hr. ahead of EST in the past years. I´m wondering if regional settings may be affecting somehow.

[GertjanA]

Hi Jose,

These kind f things can drive you crazy!

What OS is the EV-server specifically (W2008R2 standard or enterprise) and how much RAM is in the machine?

For the timezone / regional setting, that should have been catched by deploymentscanner.

In addition, check this:

https://www-secure.symantec.com/connect/forums/event-id-41293-index-service-admin-descriptioncompila...

Might help/might not

[Jose_Luis_Per1]

Thanks Gertjan,

After changing the time zone setting from Caracas to EST in the indexing server 48,000 items are added to index volumes in 10 minutes (much better than 500 / hr!!!!).

I´ll check if it keeps processing the same way tonight and determine if this is just an issue with EV10.0.2 and the Caracas time zone specifically. I´ll keep my fingers crossed.

[GertjanA]

Hello Jose,

If this resetting time zone is indeed the resolution, it might be worth opening a support case for this. It might be an issue with EV, or it might be something that needs to be investigated by Symantec, to be able to warn EV Admins about this.

Good find by the way, and hopefully it resolves the issue

[Jose_Luis_Per1 · Accepted solution]

OK, confirmed: If Caracas time zone is set at in the indexin server (at least in 64 bits). I told support about this through case number 03152441 and hope this is addressed soon.