search

certinia / debug-log-analyzer

Salesforce Apex debug log analyzer for Visual Studio Code - Visualize code execution via a Flame chart and identify performance and SOQL/DML problems via Method and Database analysis
https://marketplace.visualstudio.com/items?itemName=financialforce.lana
BSD 3-Clause "New" or "Revised" License
84 stars 18 forks source link

bug: workflows ending not being captured #529

Closed TachyonicSpace closed 2 months ago

TachyonicSpace commented 4 months ago

Summary

we have some flows and processes we are looking into a cpu timeout issue, and noticed some of the before insert flows are being treaded as running the entire DML operation, even though the FLOW_INTERVIEW_FINISHED_LIMIT_USAGE log lines are right below that line, but the timeline shows it doesnt end until the DML operation ended

Steps To Reproduce

download a log with pre-insert record triggered flows, and enable finer workflow debug logs show log analysis

Expected result

while parsing the log, and it sees that a flow interview started, and it sees that we encountered a FLOW_INTERVIEW_FINISHED_LIMIT_USAGE line, it should end that active flow interview and update its runtime appropriatly

Actual result

it doesnt seem to detect any of those tags, and kust waits for the operation or dml to finish, showing the 5 flows took over 5 seconds to do fast record updates

Additional information

image

VS Code Version:1.91

Log Analyzer Extension Version:1.14.1

OS and version:windows 11: 23H2

TachyonicSpace commented 4 months ago

Update: it appears the issue might be an incorrectly named ending point, if i renamed the first 'FLOW_INTERVIEW_FINISHED_LIMIT_USAGE' token to 'FLOW_START_INTERVIEWS_END' (which is not present in my debug logs at all), the log looks normal, so that node might need to be renamed, or accept the first 'FLOW_START_INTERVIEWS_END' it encounters as the end, then skip the lines that also have 'FLOW_START_INTERVIEWS_END' until they find something different, then continue parsing like normal, as this is what the log looks like with that change, which is correct.

image

lcottercertinia commented 4 months ago

It is like you say a FLOW_START_INTERVIEWS_BEGIN event should have a corresponding FLOW_START_INTERVIEWS_END event in order to determine the end time and duration. If this is not present then the parser thinks all following events should be nested under this one until an exit is found (which it never will). This is why you get the stair case effect in the 1st image. You should however have seen an issue in the issue list tell you about a missing end. I will have a think to see if we can handle cases where the exit event is missing due to a malformed log a bit better.

It sounds like the log way have been generated incorrectly if the FLOW_START_INTERVIEWS_END are missing, have you raised a case?

It would also be really useful to be able to get a copy of the log. I understand parts may need to be removed before sharing for privacy reasons.

lcottercertinia commented 3 months ago

@TachyonicSpace did you have a chance to read my response? If this is a bug with the parser I would love to get it resolved.

TachyonicSpace commented 2 months ago

sorry, yes i did, although i noticed some other logs i generated seem to work fine, not sure what happened with that one. it seems to be working for now, thanks

lcottercertinia commented 2 months ago

@TachyonicSpace I am glad it was resolved. If you spot anything similar in future which does seem to be a parser gap let us know and we'll get it fixed.