danielgerlag / danielgerlag/workflow-core

Workflow slow when the count of the execution point more and more

Open
#1,028 5 comments 4 reactions 1 assignee Claimed by @danielgerlag View on GitHub
Dominant language
C#
Stars
5.9k
Forks
1.3k
Avg merge
1d 1h
Merged PRs (30d)
5

Description

Hi,

I use workflow-core to control the manufacturing process. One product might spend 1-2 months so that the number of execution points goes to almost 3000. In this case, executing one step will take a lot of time (1-2 seconds). I use sample.10 to reproduce this issue.

```cs
public class WhileWorkflow : IWorkflow
{
public string Id => "While";
public int Version => 1;

public void Build(IWorkflowBuilder builder)
{
builder
.StartWith()
.While(data => data.Counter < 3000) // increase to 3000 times
.Do(x => x
.StartWith()
.Then()
.Input(step => step.Value1, data => data.Counter)
.Output(data => data.Counter, step => step.Value2))
.Then();
}
}
```

add debug message

EntityFrameworkPersistenceProvider
```cs
public async Task PersistWorkflow(WorkflowInstance workflow, CancellationToken cancellationToken = default)
{
long t1 = 0, t2 = 0, t3 = 0, t4 = 0;
var watch = Stopwatch.StartNew();

using (var db = ConstructDbContext())
{
t1 = watch.ElapsedMilliseconds;
watch.Restart();

var uid = new Guid(workflow.Id);
var existingEntity = await db.Set()
.Where(x => x.InstanceId == uid)
.Include(wf => wf.ExecutionPointers)
.ThenInclude(ep => ep.ExtensionAttributes)
.Include(wf => wf.ExecutionPointers)
.AsTracking()
.FirstAsync(cancellationToken);
t2 = watch.ElapsedMilliseconds;
watch.Restart();

var persistable = workflow.ToPersistable(existingEntity);
t3 = watch.ElapsedMilliseconds;
watch.Restart();

await db.SaveChangesAsync(cancellationToken);
t4 = watch.ElapsedMilliseconds;
watch.Restart();
}

Console.WriteLine($"\n\n PersistWorkflow >>> p1={t1}, p2={t2}, p3={t3}, p4={t4}\n\n");
}
```

WorkflowConsumer
```cs
protected override async Task ProcessItem(string itemId, CancellationToken cancellationToken)
{
if (!await _lockProvider.AcquireLock(itemId, cancellationToken))
{
Logger.LogInformation("Workflow locked {0}", itemId);
return;
}

WorkflowInstance workflow = null;
WorkflowExecutorResult result = null;

long t1, t2, t3, t4, t5;
t1 = t2 = t3 = t4 = t5 = 0;
var watch = Stopwatch.StartNew();

Logger.LogDebug("ProcessItem >>> step.1");
try
{
cancellationToken.ThrowIfCancellationRequested();
workflow = await _persistenceStore.GetWorkflowInstance(itemId, cancellationToken);
t1 = watch.ElapsedMilliseconds;
watch.Restart();
if (workflow.Status == WorkflowStatus.Runnable)
{
try
{
result = await _executor.Execute(workflow, cancellationToken);
t2 = watch.ElapsedMilliseconds;
watch.Restart();
}
finally
{
await _persistenceStore.PersistWorkflow(workflow, cancellationToken);
t3 = watch.ElapsedMilliseconds;
watch.Restart();
await QueueProvider.QueueWork(itemId, QueueType.Index);
t4 = watch.ElapsedMilliseconds;
watch.Restart();
_greylist.Remove($"wf:{itemId}");
}
}
}
finally
{
await _lockProvider.ReleaseLock(itemId);
if ((workflow != null) && (result != null))
{
foreach (var sub in result.Subscriptions)
{
await SubscribeEvent(sub, _persistenceStore, cancellationToken);
}

await _persistenceStore.PersistErrors(result.Errors, cancellationToken);

if ((workflow.Status == WorkflowStatus.Runnable) && workflow.NextExecution.HasValue)
{
var readAheadTicks = _datetimeProvider.UtcNow.Add(Options.PollInterval).Ticks;
if (workflow.NextExecution.Value < readAheadTicks)
{
new Task(() => FutureQueue(workflow, cancellationToken)).Start();
}
else
{
if (_persistenceStore.SupportsScheduledCommands)
{
await _persistenceStore.ScheduleCommand(new ScheduledCommand()
{
CommandName = ScheduledCommand.ProcessWorkflow,
Data = workflow.Id,
ExecuteTime = workflow.NextExecution.Value
});
}
}
}
}
t5 = watch.ElapsedMilliseconds;
watch.Restart();
}

Logger.LogDebug($"ProcessItem >>> t1={t1}, t2={t2}, t3={t3}, t4={t4}, t5={t5}");
}
```

```txt
[11:02:34.106] info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 5.0.1 initialized 'SqlServerContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: NoTracking
dbug: WorkflowCore.Services.BackgroundTasks.WorkflowConsumer[0]
ProcessItem >>> step.1
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 5.0.1 initialized 'SqlServerContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: NoTracking
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (14ms) [Parameters=[@__uid_0='?' (DbType = Guid)], CommandType='Text', CommandTimeout='30']
SELECT [t].[PersistenceId], [t].[CompleteTime], [t].[CreateTime], [t].[Data], [t].[Description], [t].[InstanceId], [t].[NextExecution], [t].[Reference], [t].[Status], [t].[Version], [t].[WorkflowDefinitionId], [t0].[PersistenceId], [t0].[Active], [t0].[Children], [t0].[ContextItem], [t0].[EndTime], [t0].[EventData], [t0].[EventKey], [t0].[EventName], [t0].[EventPublished], [t0].[Id], [t0].[Outcome], [t0].[PersistenceData], [t0].[PredecessorId], [t0].[RetryCount], [t0].[Scope], [t0].[SleepUntil], [t0].[StartTime], [t0].[Status], [t0].[StepId], [t0].[StepName], [t0].[WorkflowId], [t0].[PersistenceId0], [t0].[AttributeKey], [t0].[AttributeValue], [t0].[ExecutionPointerId]
FROM (
SELECT TOP(1) [w].[PersistenceId], [w].[CompleteTime], [w].[CreateTime], [w].[Data], [w].[Description], [w].[InstanceId], [w].[NextExecution], [w].[Reference], [w].[Status], [w].[Version], [w].[WorkflowDefinitionId]
FROM [wfc].[Workflow] AS [w]
WHERE [w].[InstanceId] = @__uid_0
) AS [t]
LEFT JOIN (
SELECT [e].[PersistenceId], [e].[Active], [e].[Children], [e].[ContextItem], [e].[EndTime], [e].[EventData], [e].[EventKey], [e].[EventName], [e].[EventPublished], [e].[Id], [e].[Outcome], [e].[PersistenceData], [e].[PredecessorId], [e].[RetryCount], [e].[Scope], [e].[SleepUntil], [e].[StartTime], [e].[Status], [e].[StepId], [e].[StepName], [e].[WorkflowId], [e0].[PersistenceId] AS [PersistenceId0], [e0].[AttributeKey], [e0].[AttributeValue], [e0].[ExecutionPointerId]
FROM [wfc].[ExecutionPointer] AS [e]
LEFT JOIN [wfc].[ExtensionAttribute] AS [e0] ON [e].[PersistenceId] = [e0].[ExecutionPointerId]
) AS [t0] ON [t].[PersistenceId] = [t0].[WorkflowId]
ORDER BY [t].[PersistenceId], [t0].[PersistenceId], [t0].[PersistenceId0]
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (15ms) [Parameters=[@__uid_0='?' (DbType = Guid)], CommandType='Text', CommandTimeout='30']
SELECT [t].[PersistenceId], [t].[CompleteTime], [t].[CreateTime], [t].[Data], [t].[Description], [t].[InstanceId], [t].[NextExecution], [t].[Reference], [t].[Status], [t].[Version], [t].[WorkflowDefinitionId], [t0].[PersistenceId], [t0].[Active], [t0].[Children], [t0].[ContextItem], [t0].[EndTime], [t0].[EventData], [t0].[EventKey], [t0].[EventName], [t0].[EventPublished], [t0].[Id], [t0].[Outcome], [t0].[PersistenceData], [t0].[PredecessorId], [t0].[RetryCount], [t0].[Scope], [t0].[SleepUntil], [t0].[StartTime], [t0].[Status], [t0].[StepId], [t0].[StepName], [t0].[WorkflowId], [t0].[PersistenceId0], [t0].[AttributeKey], [t0].[AttributeValue], [t0].[ExecutionPointerId]
FROM (
SELECT TOP(1) [w].[PersistenceId], [w].[CompleteTime], [w].[CreateTime], [w].[Data], [w].[Description], [w].[InstanceId], [w].[NextExecution], [w].[Reference], [w].[Status], [w].[Version], [w].[WorkflowDefinitionId]
FROM [wfc].[Workflow] AS [w]
WHERE [w].[InstanceId] = @__uid_0
) AS [t]
LEFT JOIN (
SELECT [e].[PersistenceId], [e].[Active], [e].[Children], [e].[ContextItem], [e].[EndTime], [e].[EventData], [e].[EventKey], [e].[EventName], [e].[EventPublished], [e].[Id], [e].[Outcome], [e].[PersistenceData], [e].[PredecessorId], [e].[RetryCount], [e].[Scope], [e].[SleepUntil], [e].[StartTime], [e].[Status], [e].[StepId], [e].[StepName], [e].[WorkflowId], [e0].[PersistenceId] AS [PersistenceId0], [e0].[AttributeKey], [e0].[AttributeValue], [e0].[ExecutionPointerId]
FROM [wfc].[ExecutionPointer] AS [e]
LEFT JOIN [wfc].[ExtensionAttribute] AS [e0] ON [e].[PersistenceId] = [e0].[ExecutionPointerId]
) AS [t0] ON [t].[PersistenceId] = [t0].[WorkflowId]
ORDER BY [t].[PersistenceId], [t0].[PersistenceId], [t0].[PersistenceId0]
[11:02:34.310] dbug: WorkflowCore.Services.WorkflowExecutor[0]
Starting step (null) on workflow c3ec1e32-c549-490b-81d2-94f2250781bf
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 5.0.1 initialized 'SqlServerContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: NoTracking
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (12ms) [Parameters=[@__uid_0='?' (DbType = Guid)], CommandType='Text', CommandTimeout='30']
SELECT [t].[PersistenceId], [t].[CompleteTime], [t].[CreateTime], [t].[Data], [t].[Description], [t].[InstanceId], [t].[NextExecution], [t].[Reference], [t].[Status], [t].[Version], [t].[WorkflowDefinitionId], [t0].[PersistenceId], [t0].[Active], [t0].[Children], [t0].[ContextItem], [t0].[EndTime], [t0].[EventData], [t0].[EventKey], [t0].[EventName], [t0].[EventPublished], [t0].[Id], [t0].[Outcome], [t0].[PersistenceData], [t0].[PredecessorId], [t0].[RetryCount], [t0].[Scope], [t0].[SleepUntil], [t0].[StartTime], [t0].[Status], [t0].[StepId], [t0].[StepName], [t0].[WorkflowId], [t0].[PersistenceId0], [t0].[AttributeKey], [t0].[AttributeValue], [t0].[ExecutionPointerId]
FROM (
SELECT TOP(1) [w].[PersistenceId], [w].[CompleteTime], [w].[CreateTime], [w].[Data], [w].[Description], [w].[InstanceId], [w].[NextExecution], [w].[Reference], [w].[Status], [w].[Version], [w].[WorkflowDefinitionId]
FROM [wfc].[Workflow] AS [w]
WHERE [w].[InstanceId] = @__uid_0
) AS [t]
LEFT JOIN (
SELECT [e].[PersistenceId], [e].[Active], [e].[Children], [e].[ContextItem], [e].[EndTime], [e].[EventData], [e].[EventKey], [e].[EventName], [e].[EventPublished], [e].[Id], [e].[Outcome], [e].[PersistenceData], [e].[PredecessorId], [e].[RetryCount], [e].[Scope], [e].[SleepUntil], [e].[StartTime], [e].[Status], [e].[StepId], [e].[StepName], [e].[WorkflowId], [e0].[PersistenceId] AS [PersistenceId0], [e0].[AttributeKey], [e0].[AttributeValue], [e0].[ExecutionPointerId]
FROM [wfc].[ExecutionPointer] AS [e]
LEFT JOIN [wfc].[ExtensionAttribute] AS [e0] ON [e].[PersistenceId] = [e0].[ExecutionPointerId]
) AS [t0] ON [t].[PersistenceId] = [t0].[WorkflowId]
ORDER BY [t].[PersistenceId], [t0].[PersistenceId], [t0].[PersistenceId0]
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (10ms) [Parameters=[@p2='?' (DbType = Int64), @p0='?' (Size = -1), @p1='?' (Size = 4000)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
UPDATE [wfc].[ExecutionPointer] SET [Children] = @p0, [PersistenceData] = @p1
WHERE [PersistenceId] = @p2;
SELECT @@ROWCOUNT;
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (5ms) [Parameters=[@p0='?' (DbType = Boolean), @p1='?' (Size = 4000), @p2='?' (Size = 4000), @p3='?' (DbType = DateTime2), @p4='?' (Size = 4000), @p5='?' (Size = 100), @p6='?' (Size = 100), @p7='?' (DbType = Boolean), @p8='?' (Size = 50), @p9='?' (Size = 4000), @p10='?' (Size = 4000), @p11='?' (Size = 100), @p12='?' (DbType = Int32), @p13='?' (Size = 4000), @p14='?' (DbType = DateTime2), @p15='?' (DbType = DateTime2), @p16='?' (DbType = Int32), @p17='?' (DbType = Int32), @p18='?' (Size = 100), @p19='?' (DbType = Int64)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [wfc].[ExecutionPointer] ([Active], [Children], [ContextItem], [EndTime], [EventData], [EventKey], [EventName], [EventPublished], [Id], [Outcome], [PersistenceData], [PredecessorId], [RetryCount], [Scope], [SleepUntil], [StartTime], [Status], [StepId], [StepName], [WorkflowId])
VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10, @p11, @p12, @p13, @p14, @p15, @p16, @p17, @p18, @p19);
SELECT [PersistenceId]
FROM [wfc].[ExecutionPointer]
WHERE @@ROWCOUNT = 1 AND [PersistenceId] = scope_identity();

PersistWorkflow >>> p1=0, p2=123, p3=21, p4=41

dbug: WorkflowCore.Services.BackgroundTasks.WorkflowConsumer[0]
ProcessItem >>> t1=219, t2=1, t3=186, t4=0, t5=0
```

ProcessItem t1 is time to get the workflow instance from the database. It spend a lot of time because there are so many execution points.

ProcessItem t3 is time to persist the workflow. The detailed time span is shown in the `PersistWorkflow p1~p4`. p2 is time to query workflow from the database, p3 is ToPersistable(), p4 is SaveChangesAsync()

There are 1595 execution points in the database, and the number of children is large (string length is 29489).

![image](https://user-images.githubusercontent.com/997727/162356915-72e3ffc8-f72e-4805-b008-b01746a43ba6.png)

Maybe we can optimize

- Reduce the number of execution points when querying from the database. (Only return active execution point?)
- To prevent `Children` growth. (I'm not sure about the `Children` purpose, but it looks like can use `Scope` instead of it?)

Thanks!

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.