Edit

How to monitor execution time of instructions in bot step

Problem statment

Bot step is working slow and step code review does not give ideas where is weak place. In such case you can turn on additional logs to track each plugin time execution.

Steps

1. Setup ability to change level logs on runtime if it is not configured (see steps 1-2 from How to Change Logging Level)
2. open file %TOMCAT_HOME%/conf/wf-log-levels.properties and add row org.webharvest.runtime.Scraper = INFO
3. after logs configuration reloading (1 minutes by default) bot configs will log data into the logs/catalina.out file.

Example

Scraper [INFO] VarDefProcessor starts processing...
Scraper [INFO]     ConstantProcessor starts processing...
Scraper [INFO]     ConstantProcessor processor executed in 0ms.
Scraper [INFO] VarDefProcessor processor executed in 0ms.
Scraper [INFO] IncludeConfigPlugin starts processing...
Scraper [INFO]     ScriptProcessor starts processing...
Scraper [INFO]     ScriptProcessor processor executed in 2287ms.
Scraper [INFO] IncludeConfigPlugin processor executed in 2288ms.
Scraper [INFO] IncludeConfigPlugin starts processing...
Scraper [INFO]     IncludeConfigPlugin starts processing...
Scraper [INFO]         ScriptProcessor starts processing...
Scraper [INFO]         ScriptProcessor processor executed in 982ms.
Scraper [INFO]     IncludeConfigPlugin processor executed in 983ms.
Scraper [INFO]     IncludeConfigPlugin starts processing...
Scraper [INFO]         ScriptProcessor starts processing...
Scraper [INFO]         ScriptProcessor processor executed in 1008ms.
Scraper [INFO]     IncludeConfigPlugin processor executed in 1009ms.
Scraper [INFO]     ScriptProcessor starts processing...
Scraper [INFO]     ScriptProcessor processor executed in 649ms.
Scraper [INFO] IncludeConfigPlugin processor executed in 2642ms.
Scraper [INFO] ScriptProcessor starts processing...

Scraper output has tree structure so based on config code you can define what plugins works slow for future investigation.