Enabling log timing information for crawl processing steps

You can enable a logging setting in ias-service-log4j.properties that instructs IAS to write log timing information for each processing step of a crawl. This additional logging information is especially useful for troubleshooting performance issues.

  1. In a text editor, open <install path>\IAS\workspace\conf\ias-service-log4j.properties.
  2. Un-comment the following line in the file: 
    log4j.logger.com.endeca.eidi.executor.ProcessorTaskTiming=DEBUG
  3. Save and close the file.
  4. Restart the Endeca IAS Service.
The next time you run a crawl you will get additional logging information similar to the following: 
Processor Task Timing

IncrementalDataSourceProcessor-414611937: (Hits=1, Value=8542.280 ms, Time=15:11:37,489)
MdexOutputSink-1898864883(processRecord): (Total=7413.427 ms, Avg=0.835 ms, Hits=8877, StdDev=9.526 ms, Min=0.001 ms, Max=659.003 ms, FirstTimed=15:11:36,802, LastTimed=15:11:40,078)
SplittingFilterProcessor-1235020019(processRecord): (Total=3250.518 ms, Avg=0.366 ms, Hits=8877, StdDev=0.711 ms, Min=0.010 ms, Max=26.920 ms, FirstTimed=15:11:29,626, LastTimed=15:11:37,457)
ArchiveExpandProcessor-1134860470(processRecord): (Total=2104.446 ms, Avg=0.237 ms, Hits=8877, StdDev=0.843 ms, Min=0.004 ms, Max=44.004 ms, FirstTimed=15:11:29,595, LastTimed=15:11:37,457)
PropertyRemover-92265517(processRecord): (Total=1849.963 ms, Avg=0.208 ms, Hits=8877, StdDev=0.716 ms, Min=0.003 ms, Max=27.465 ms, FirstTimed=15:11:29,595, LastTimed=15:11:37,457)
MdexOutputSink-1898864883(notifyInputClosed): (Total=598.802 ms, Avg=299.401 ms, Hits=2, StdDev=391.645 ms, Min=22.466 ms, Max=576.336 ms, FirstTimed=15:11:38,206, LastTimed=15:11:40,094)
PropertyRemover-92265517(notifyInputClosed): (Hits=1, Value=0.544 ms, Time=15:11:37,489)
ArchiveExpandProcessor-1134860470(notifyInputClosed): (Total=0.330 ms, Avg=0.165 ms, Hits=2, StdDev=0.141 ms, Min=0.065 ms, Max=0.265 ms, FirstTimed=15:11:37,489, LastTimed=15:11:37,489)
SplittingFilterProcessor-1235020019(notifyInputClosed): (Hits=1, Value=0.012 ms, Time=15:11:37,489)