Thread dump analysis

Dump retrieval

You can retrieve the thread dump related to Bot Task execution in a Business Process (BP) via the following REST API endpoint: api/v1/monitoring/bots/thread-dumps.

Tools

Viewing through a textual dump.
Using UI tools like http://fastthread.io.

Download files using an FTP client and upload them to the web tool. It provides general stats, such as total thread count grouped by status.

BLOCKED threads can indicate performance issues. In the dump-example.txt, HIT review threads are blocked by using the same worker:

Although there are a lot of RUNNABLE threads, they are almost all JIT and GC threads (this can indicate memory issues). Application threads are mainly bot-results-run-*-hit-* and write bot results to the database (DB). This can also be caused by large Bot Task outputs.
FlameGraph visualization

If there are multiple thread dumps, they can be visualized using modified scripts.

Modifications:
- BLOCKED threads are not excluded.
- Threads with the socketAccept in method names are not excluded because of DB/REST calls.
Usage:
1. Copy the thread dumps with the TXT extension to an analysis folder.
2. Copy create-gpaph.sh, stackcollapse-jstack.pl, flamegraph.pl to the same folder.
3. Execute the script:
```
./create-gpaph.sh
```
  The script scans all TXT files in the current folder recursively and generates flame.svg after execution.
  
  See the sample flame.svg.

Analysis

Common hints

A common line in multiple dumps of the same thread can indicate a performance issue in that line. For example, a thread stuck in a JDBC call is the clue to check DB stats and query logs.
Usually, you need to start the investigation from application classes in the stack trace, for example, having a com.workfusion.* or com.crowdcontrol.* package.
A deeper analysis usually requires access to a particular Control Tower version source. You can find the version in the bottom right corner).

Bot Task execution

Bot Task processing dumps can be identified by the machine-run-* prefix in a thread name:

Thread.sleep in Bot Config

"machine-run-603-hit-35416-step-1820" #920 prio=5 os_prio=0 tid=0x00000000318a3000 nid=0x26d0 waiting on condition [0x000000006e87d000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at bsh.Reflect.invokeMethod(Reflect.java:134)
at bsh.Reflect.invokeStaticMethod(Reflect.java:98)
at bsh.Name.invokeMethod(Name.java:874)
at bsh.BSHMethodInvocation.eval(BSHMethodInvocation.java:75)
at bsh.BSHPrimaryExpression.eval(BSHPrimaryExpression.java:102)
at bsh.BSHPrimaryExpression.eval(BSHPrimaryExpression.java:47)
at bsh.Interpreter.eval(Interpreter.java:660)
at bsh.Interpreter.eval(Interpreter.java:754)
at bsh.Interpreter.eval(Interpreter.java:743)
at org.webharvest.runtime.scripting.BeanShellScriptEngine.eval(BeanShellScriptEngine.java:134)
at org.webharvest.runtime.processors.ScriptProcessor.execute(ScriptProcessor.java:74)
at org.webharvest.runtime.processors.BaseProcessor.run(BaseProcessor.java:127)
at org.webharvest.runtime.Scraper.execute(Scraper.java:169)
at org.webharvest.runtime.Scraper.execute(Scraper.java:182)
at com.freedomoss.crowdcontrol.webharvest.executor.LocalWebharvestTaskExecutor.executeWebHarvestTask(LocalWebharvestTaskExecutor.java:187)
at com.freedomoss.crowdcontrol.webharvest.executor.LocalWebharvestTaskExecutor.executeWebHarvestTask(LocalWebharvestTaskExecutor.java:97)
at com.workfusion.service.machine.BotRecordExecutionService.process(BotRecordExecutionService.java:171)
at com.workfusion.service.machine.BotRecordExecutionService.process(BotRecordExecutionService.java:142)
at com.workfusion.service.machine.BotRecordExecutionService.lambda$3(BotRecordExecutionService.java:113)
at com.workfusion.service.machine.BotRecordExecutionService$$Lambda$428/544535371.run(Unknown Source)
at com.workfusion.utils.thread.ThreadMonitoringUtils.executeWithAllocatedMemoryCallback(ThreadMonitoringUtils.java:17)
at com.workfusion.service.machine.BotRecordExecutionService.processSubmissionWithAllocationLogger(BotRecordExecutionService.java:113)
at com.workfusion.service.machine.BotRecordExecutionService.lambda$0(BotRecordExecutionService.java:97)
at com.workfusion.service.machine.BotRecordExecutionService$$Lambda$426/1429204113.run(Unknown Source)
at com.workfusion.utils.thread.NamedThreadTemplate.executeWithNamedThread(NamedThreadTemplate.java:10)
at com.workfusion.service.machine.BotRecordExecutionService.processRecord(BotRecordExecutionService.java:97)
at com.workfusion.service.machine.thread.RecordProcessThread.run(RecordProcessThread.java:28)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

From the stacktrace lines at org.webharvest.runtime.processors.ScriptProcessor.execute(ScriptProcessor.java:74) and at org.webharvest.runtime.processors.BaseProcessor.run(BaseProcessor.java:127), it's clear that a <script> tag inside <config> is being executed.

Threads waiting for Data Stores

The following thread is stuck in the slow query caused by the usage of pg_sleep(300) function inside the datastore plugin.

Slow Data Store query in Bot Config

A stack trace shows that the datastore plugin is being executed:

at com.freedomoss.crowdcontrol.webharvest.plugin.datastore.DataStorePlugin.executePlugin(DataStorePlugin.java:63)
at org.webharvest.runtime.processors.WebHarvestPlugin.execute(WebHarvestPlugin.java:125
at org.webharvest.runtime.processors.BaseProcessor.run(BaseProcessor.java:127)

Also, it is stuck in java.net.SocketInputStream.socketRead, so it shows that the activity is on the DB side.

UI and REST calls

UI and REST requests can be identified via the http-nio-* prefix in a thread name.

Stuck BP list page

"http-nio-8080-exec-10" #346 daemon prio=5 os_prio=0 tid=0x000000001c58c000 nid=0x2f74 runnable [0x0000000049b08000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
- locked <0x00000000aba53030> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1281)
- locked <0x00000000b6cd62b8> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:782)
- locked <0x00000000b6cd62b8> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
- locked <0x00000000b6cd62b8> (a com.mysql.jdbc.JDBC4Connection)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2168)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1931)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1893)
at org.hibernate.loader.Loader.doQuery(Loader.java:938)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341)
at org.hibernate.loader.Loader.doList(Loader.java:2692)
at org.hibernate.loader.Loader.doList(Loader.java:2675)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2507)
at org.hibernate.loader.Loader.list(Loader.java:2502)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:109)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1898)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:370)
at org.hibernate.internal.CriteriaImpl.uniqueResult(CriteriaImpl.java:392)
at com.freedomoss.workfusion.repository.run.impl.RunRepository.isHasProcessingIssuesInChild(RunRepository.java:1014)
at com.freedomoss.requester.service.run.impl.RunService.isHasProcessingIssuesInChild(RunService.java:644)
at com.freedomoss.requester.service.run.impl.RunService$$FastClassBySpringCGLIB$$2699e362.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at com.freedomoss.requester.service.run.impl.RunService$$EnhancerBySpringCGLIB$$8890d0d.isHasProcessingIssuesInChild(<generated>)
at com.freedomoss.crowdcontrol.controller.task.TaskListController.isReprocessRun(TaskListController.java:458)
at sun.reflect.GeneratedMethodAccessor1112.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.el.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:329)
at org.jboss.el.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:274)
at org.jboss.el.parser.AstMethodSuffix.getValue(AstMethodSuffix.java:59)
at org.jboss.el.parser.AstValue.getValue(AstValue.java:67)
at org.jboss.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:186)
at com.sun.faces.facelets.el.TagValueExpression.getValue(TagValueExpression.java:109)
at javax.faces.component.ComponentStateHelper.eval(ComponentStateHelper.java:193)
at javax.faces.component.UIComponentBase.isRendered(UIComponentBase.java:421)
at javax.faces.component.UIComponentBase.processDecodes(UIComponentBase.java:1037)

JSF classes in a stack trace (javax.faces.component.UIComponentBase) indicate that it is a UI request. The thread is stuck in java.net.SocketInputStream.socketRead, so the cause of the slowness can be found on the MySQL side.

Background system threads

review-hit-<hit_id>: processing of human worker answers
bot-results-run-<run_id>-hit-<hit_id>: processing of bot worker answers
get-reviewable-hits-prod/get-reviewable-hits-sandbox: retrieval of human worker answers from a Crowd
get-reviewable-hits-paused-prod/get-reviewable-hits-paused-sandbox: retrieval of human worker answers from a Crowd for paused runs
process-refreshable-hits-sandbox/process-refreshable-hits-prod redistribution-production/redistribution-sandbox: redistribution of Manual Tasks in multi-crowd setups
bp-[<instance_uuid>]: BP lifecycle tasks
createHumanTasks-<stream_id>: submission of Manual Tasks to crowds
completeMachineRun-<run_id>: completion or transition of Bot Step records
startMachineHits-<run_id>: start of a Bot Step record execution
runStatsUpdate-<run_id>: periodic update of BP step stats
processRunStreamEvent-<run_uuid>: completion or transition of manual step records

Most of scheduled activities are executed inside threads WorkFusion_Worker-*. So, the executed task should be guessed based on the stack trace.

Identify BP by thread name

In a thread dump, bot execution threads can be identified via the machine-run-<run_id> prefix. The BP that started bot execution can be identified via the following query:

note

Before execution, replace the @run_id parameter with an appropriate value from the thread name.

set @run_id = 4;
 
select c.title as bp_title, r.title as step_title, r.rootRunUUID as bp_instance_uuid
from Run r
join CampaignMap cm on r.campaignMap_id = cm.id
join Campaign c on c.id = cm.parent
where r.id = @run_id;

bp_title column contains the BP name.
step_title column contains the BP step name.
The bp_instance_uuid column contains the UUID of the BP instance. You can insert it in the browser URL line in the format: business-process/edit/<UUID>.

Get thread dump process

Find the process pid

The standard ps utility can be used for that.

For example, to find the Tomcat process, you can use the following command:

ps aux | grep java | grep tomcat

It prints the process id (pid), owner, and other process details.

Make sure current user is process owner

For the jstack operation to be successful, execute under the user who owns the process being checked.

To check the user who is logged in currently, run the command below:

whoami

Make sure JAVA_HOME is defined

To print the current JAVA_HOME value, use the following command:

echo $JAVA_HOME

To set the environment variable, use the command below. The actual path to the Java installation folder can differ based on the WorkFusion version or what folder WorkFusion was installed to. The most common case is as shown below:

JAVA_HOME=/opt/workfusion/lib/jdk1.8.0_101/

Take jstack snapshots

As jstack takes a snapshot of the immediate state, it's a good idea to take a few snapshots to see the things in motion. The general recommendation is to take three snapshots at a 15-second interval.

To replace process_pid, specify the process pid collected in the first step.

$JAVA_HOME/bin/jstack ${process_pid} > jstack-`date -u +"%Y-%m-%dT%H-%M-%SZ"`.txt

This command can be put into the loop to create multiple dumps, for example:

Take multiple dumps (take-dumps.sh)

#!/bin/sh
for ((n=0;n<$2;n++))
do
  echo "Taking dump `date '+%Y-%m-%d %H:%M:%SZ'`"
  $JAVA_HOME/bin/jstack $1 > jstack-`date -u +'%Y-%m-%dT%H-%M-%SZ'`.txt
  sleep 1
done
Take multiple dumps example
bash-4.2$ ./take-dumps.sh <jvm_pid> 5
Taking dump 2018-05-28 19:03:17Z
Taking dump 2018-05-28 19:03:18Z
Taking dump 2018-05-28 19:03:19Z
Taking dump 2018-05-28 19:03:20Z
Taking dump 2018-05-28 19:03:22Z

WorkFusion Documentation

9.4

RPA performance

Business Process performance analysis

Database

AutoML

RPA

S3 File Storage

Database

Installation

Security

WorkSpace

Dump retrieval

Tools

Analysis

Common hints

Bot Task execution

Threads waiting for Data Stores

Slow Data Store query in Bot Config

UI and REST calls

Background system threads

Identify BP by thread name

note

Get thread dump process

Find the process pid

Make sure current user is process owner

Make sure JAVA_HOME is defined

Take jstack snapshots