Invoke-PSUScript from App taking a very long time to trigger #4238
Comments
bt-ndollimount
added
bug
|
I'll try to reproduce and get a fix in 5.2.1 if I can do so. Can you let me know a few things?
|
|
I'm not seeing it time out but am definitely seeing a delay. The script I'm running executes in under a second. Get-Service | Select-Object NameIn my app, I made 4 buttons with various configurations. New-UDApp -Content {
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Wait| Out-Null
}
Show-UDToast "Wait: $($Value.TotalMilliseconds)" -Persistent
} -Text "Wait"
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' | Out-Null
}
Show-UDToast "No Wait: $($Value.TotalMilliseconds)" -Persistent
} -Text "No Wait"
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Wait -Integrated| Out-Null
}
Show-UDToast "Wait - Integrated: $($Value.TotalMilliseconds)" -Persistent
} -Text "Wait - Integrated"
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Integrated| Out-Null
}
Show-UDToast "No Wait - Integrated: $($Value.TotalMilliseconds)" -Persistent
} -Text "No Wait - Integrated"
}It is pretty slow. It takes about 4 seconds if I'm waiting on the job.
That said, I introduced the -Silent flag, and it runs almost 4x as fast. New-UDApp -Content {
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Wait -Silent | Out-Null
}
Show-UDToast "Wait: $($Value.TotalMilliseconds)" -Persistent
} -Text "Wait"
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Silent | Out-Null
}
Show-UDToast "No Wait: $($Value.TotalMilliseconds)" -Persistent
} -Text "No Wait"
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Wait -Integrated -Silent | Out-Null
}
Show-UDToast "Wait - Integrated: $($Value.TotalMilliseconds)" -Persistent
} -Text "Wait - Integrated"
New-UDButton -ShowLoading -OnClick {
$Value = Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Integrated -Silent | Out-Null
}
Show-UDToast "No Wait - Integrated: $($Value.TotalMilliseconds)" -Persistent
} -Text "No Wait - Integrated"
}
I also setup a parent script to run the child script. Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Wait -Silent | Out-Null
} | Select TotalMilliseconds
Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' | Out-Null
} | Select TotalMilliseconds
Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Wait -Integrated -Silent | Out-Null
} | Select TotalMilliseconds
Measure-Command {
Invoke-PSUScript -Name 'script1.ps1' -Integrated | Out-Null
} | Select TotalMillisecondsIt's actually slower than running in the app. TotalMilliseconds
-----------------
2170.12
79.83
2131.13
24.89I suspect that this has to do with the app logging when not using -Silent. Here's the output from the app log. It streams the job output to the log if -Silent isn't on. It's unclear to me why this would be different in v5.1
|
Here's the code line I'm using; I didn't realize there was the -Wait and I'll give that a try. Piping it to Wait-PSUJob might be slowing it down? $userData = Invoke-PSUScript -ComputerGroup 'Job Nodes (Any)' -ComputerName localhost -AppToken $Secret:PSUToken -Script 'Dashboard Functionality/GetUserPostsRepliesStats.ps1' -UserId $selectedUserId | Wait-PSUJob I am returning data but once the job executes, it executes quickly and the data is returned quickly as well. It's the pause while it's waiting to actually execute the job. The app is authenticated with roles and right now this one is just my account as Administrator role. |
|
I see. I wonder if there is a heavy SQL query or something running that is causing the delay. How many jobs do you have in your Jobs table? |
|
Running jobs is only 2 and it's still really long. However, the public.job table has 4497 entries in it. The hangfire.job table has 257 entries. Following up to using -Wait -Silent; this doesn't appear to have made a difference. |
|
Strange. That's not a lot of data. It's also really weird it runs quickly from other jobs and it's only the app triggering that is slow. Do you have permissive security on? If so, have you tried -Integrated on Invoke-PSUScript? Mostly wondering because without it, the cmdlets effectively go out to the web server URL and communicate via that while integrated will use the backend gRPC port and I want to know if this a DB issue or something else. Logs from the app and server might be good. Feel free to email those. |
|
I don't think we have permissive set up. With our configuration, would that need to be set on all nodes? Also, our firewalls are extremely locked down so if that requires opening a new port, that could take some time... Internal External |
|
The gRPC port is dynamic and already being used to communicate between the jobs and server so no extra ports need to be opened on the firewall. Switching to integrated just changes the communication from cmdlet -> HTTP 443\80 to cmdlet -> Dynamic Port. We did add the ability to configure the cmdlet security behavior in 5.2 in the Settings \ General page. That said, I'm not totally convinced it's a communication issue and likely something else so it may not be going through the whole configuration of that. Just figured we could try it out if it was already setup. You can always try to include the -Integrated switch and it will just throw an error if it's not enabled. |
|
That makes sense. I just tested with -Integrated with the same results and no error. Also when testing from a script, I made sure that the source script is running on the web node and it invokes it quickly. I do have a long running job currently going, 16 hours and 40 minutes in, but right now that's just looping through a list, calculating and updating the list in-memory. The CPU usage on the database server is minimal, no more than 20% and on that particular job server, it's just the single core that's floating around 97%; I also don't have any other jobs going to that node as it's the "test" linux node. |
|
I don't think the long running job should affect this. It seems something related to the app. I'm going to review our changes to apps over the last month to see if I can see anything that will give us a hint about this. Unfortunately, I don't think this will make it into the 5.2.1 release as we have some pressing issues help address with a release tomorrow. That said, I realize this is impactful, so I won't hesitate to publish a 5.2.2 release sooner than expected to resolve it once we have it nailed down. |
|
Okay, I have a pretty significant update and seem to have isolated where things are breaking down. Recalling I said that running it from a script, it executes fine; in that script, the parameter value (userid) is hardcoded. In the app, we load all the users when the page loads and save them into a variable, $Page:communityUsers. I tested hardcoding the parameter value in there and it does execute. So I looked upward in the code. The setup of the app, we have a dropdown that is populated with the users list emails. The button click, it pipes the $Page:communityUsers to a Where-Object to match the email in the users list to the selected item value (email), then grabs the ID property of the resulting item. This ID is the value used for the parameter on the Invoke-PSUScript. Below is that line where we get that.
When I isolate that line, it hangs. Breaking it apart, the following work:
So it seems to be the part where the list is being piped to the Where-Object cmdlet that is causing it to hang. I tested using .Where instead and that has the same result. This is also isolated where the rest is commented out so it's only trying to do the loop to get the ID and then show a UDToast with the ID value. Furthermore, the browser log and app log (same by the looks of it?) gets filled with the following and looks like it probably repeats the amount of times matching the amount of objects in $Page:communityUsers. Then at the very end, you can see that it fails to show the toast message because the message is empty, of course 🥲. |
|
Another update: I got it working... So I made the following changes, breaking out the fetching of the selected user dropdown value into a variable and then used that variable in the Where filter. It seems the nesting of the that is what is breaking it. |
|
I wonder what changed in 5.2 to cause this. I don't see any changes for Get-UDElement. That said, the change you made is a big optimization because calling Get-UDElement in the loop was making a web socket call for each item. I could try to track down the problem but I figure that, since you have it working, this can probably be marked resolved unless you notice anything else. |
|
The only thing I'd be worried about is if there are other instances where having a nested check inside is valid and someone isn't aware of this bug, since theoretically it should work regardless of the performance of what I was using it for. Can you throw it into a "not super important but will get to it at some point" pile? 😁 |
|
Sounds good. I'll see if I can review the changes between the release and nail it down. |
|
I didn't fix the actual error, but I did narrow down that the slowness is actually related to the logging in the apps. I did some optimization and was able to get my 4 second test down to the same speed as the -Silent test. There was effectively 3 seconds of overhead from logging that is now a couple milliseconds. This should really improve app performance in 5.3. |
Description of Issue
After upgrading to 5.2.0, Invoke-PSUScript in an App takes a very long time to trigger. In the browser dev tools, it actually times out. I have a button that is showing progress spinner while it executes and because of the timeout, that never stops. The data is returned eventually but the button stays busy. Alternatively, using the exact same command to execute the same script from a normal job, this runs much quicker as expected.
Version
5.2.0
Severity
High
Hosting Method
Other
Operating System
Linux
Database
PostgreSQL
Licensed
Yes
Features
Git Sync
Additional Environment data
Windows Server 2022 Standard / Amazon Linux
PowerShell 7.4.6
PostgreSQL 16
Screenshots/Animations
No response
The text was updated successfully, but these errors were encountered: