BPMs seeming slower at 2023.2.10

Kinetic ERP
1

I am working with a customer who’s been having performance issues since their update (and hardware changes etc). We’ve got some good improvements from the usual hardware optimisation, working through challenges with AV and the client, and we’re now at a point where we are ready to look at BPMs. And I have now observed nothing I’ve seen before: The BPM time reported at the Customisation Level is significantly higher than the individual times for each directive. This can be seen in the highlighted extract from a server log:

<BpmCustomization Source="BO" BpMethodCode="Erp.BO.JobEntry.Update" Type="BO Customization" Duration="54">
  <BpmDirective Type="1" ID="6960212e-20a3-49ff-b1e8-74c5c9f5b816" Name="CopyInspectionInfo" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="1" ID="2a75df57-562c-4537-bef4-74fde989bd02" Name="RelatedOperationNotZero" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="1" ID="082d8deb-1cbb-4883-9ab1-a6d65a746d1f" Name="ValidateFields" VisibilityScope="1" Duration="1" />
  <BpmDirective Type="1" ID="13b3ed3d-d9f4-426e-8ccf-f6cc4346c054" Name="VU-VendorChanged" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="1" ID="db34e3f5-0c73-4e23-89a0-e33189ef92c2" Name="CheckJobMtlPartClassFilled" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="1" ID="276df636-bfe7-42f0-9a9c-e83476a7a996" Name="WarnSubcontractVendorChange" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="1" ID="c37f2d7f-0c37-472c-ac4a-0d427208c54c" Name="CopyPlannerToPartSug" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="1" ID="2c8e02bc-110d-46eb-b728-9b72831890fd" Name="SchedLocked" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="3" ID="6fff6409-5fe2-43d0-a331-54b871fb76f1" Name="VU-VendorChanged" VisibilityScope="1" Duration="0" />
  <BpmDirective Type="3" ID="e91a9cec-d673-4084-bf2b-9a03fd9d2a6a" Name="CopyPlannerToPartSug" VisibilityScope="1" Duration="0" />
</BpmCustomization>

Now it doesn’t take a rocked scientist to work out that 0 + 0 + 0 + 1 != 54. So what is happening? Well obviously there is some penalty to initialising these BPMs but having adapted my tooling to highlight “Bad BPMs” in a day’s logs to total this discrepancy, the Total at the customisation level is 1,486s vs 590s reported at the individual directive level.

Well, maybe it has always been like this? No. Using data from the same customer from 2020, the Customisation Level BPM time is 1,279s vs 1,277s if you total up all the individual BPMDirectives.

So we’re paying a huge penalty at the moment.

We’re going to run with AV off on the server tomorrow - just to get a day’s data to compare - but I would be grateful for any ideas anyone else might have.

2

I did a quick test on my current test 21.2.10 and a 23.2.8 I made a couple of weeks ago with get details in job entry for the same assembly and quantity and it is similar 9 and 17 versus 1 and 7

2023.2.8

image
image1047×190 143 KB

2021.2.10

image
image1161×305 218 KB

3

Interesting Greg. Would you mind sharing a log file from each version which I could run through my version of the PDT? As a thanks I can let you know any BPMs which may benefit from a little optimisation!

4

What has your database growth been between now and then? Have you attempted any database profiling, and index tuning, schema changes (ud fields) added… I have seen lags where you start joining ud columns to real columns.

That’s my 2c

5

Did you lose any custom indexes during the upgrade? Sometimes they get blown away in the upgrade process.

6

Those systems don’t have much logging since I am the only user and if I needed any PDT analysis on my work I can run them.

7

OK - no worries Greg. Thanks for your investigation though.

8

DB has grown significantly and I have used DB and my version of the PDT profiling to get the 50% improvement we’ve already achieved.

But I don’t think this is SQL related, more something happening on the application server.
One example I have found for JobEntryUpdate, shows:
Total time 104ms
SQL Time 42ms
BPMCustomisation Time 68ms
BPMDirective Time 4ms
If SQL was a factor, I would expect SQL time to be higher (or at least the same) than the 64ms difference between the two BPM times (other SQL processing is required also).

And while the times may seem trivial in this instance - I am seeing individual calls where the difference is over 1s - but there are many more BPM iterations in these instances, so less friendly to post!

1 Like
9

Could you do some trials in a test environment? What result do you get if all those BPM’s are disabled? How about one at a time?

10

We could - but not sure what that would prove. The delays are apparent across all BPM types (Method and DataDirectives) for all method calls traced. And if we switch them all off then the top level time will obviously be zero.

And Greg’s testing shows totally similar results on completely different BPMs.

11

So AV doesn’t seem to make a difference - still the same difference with AV off on the application server.