Debugging PowerShell Execution from Connector Log Examples (KBA8395)
KBA
KBA# 8395Applicable Delphix Versions
- Click here to view the versions of the Delphix engine to which this article applies
-
Major Release All Sub Releases 6.0 6.0.0.0, 6.0.1.0, 6.0.1.1, 6.0.2.0, 6.0.2.1, 6.0.3.0, 6.0.3.1, 6.0.4.0, 6.0.4.1, 6.0.4.2, 6.0.5.0, 6.0.6.0, 6.0.6.1, 6.0.7.0, 6.0.8.0, 6.0.8.1, 6.0.9.0, 6.0.10.0, 6.0.10.1
5.3
5.3.0.0, 5.3.0.1, 5.3.0.2, 5.3.0.3, 5.3.1.0, 5.3.1.1, 5.3.1.2, 5.3.2.0, 5.3.3.0, 5.3.3.1, 5.3.4.0, 5.3.5.0, 5.3.6.0, 5.3.7.0, 5.3.7.1, 5.3.8.0, 5.3.8.1, 5.3.9.0 5.2
5.2.2.0, 5.2.2.1, 5.2.3.0, 5.2.4.0, 5.2.5.0, 5.2.5.1, 5.2.6.0, 5.2.6.1
5.1
5.1.0.0, 5.1.1.0, 5.1.2.0, 5.1.3.0, 5.1.4.0, 5.1.5.0, 5.1.5.1, 5.1.6.0, 5.1.7.0, 5.1.8.0, 5.1.8.1, 5.1.9.0, 5.1.10.0
5.0
5.0.1.0, 5.0.1.1, 5.0.2.0, 5.0.2.1, 5.0.2.2, 5.0.2.3, 5.0.3.0, 5.0.3.1, 5.0.4.0, 5.0.4.1, 5.0.5.0, 5.0.5.1, 5.0.5.2, 5.0.5.3, 5.0.5.4
Introduction
In the process of debugging job performance, PowerShell command execution may be delayed. An increase in timing for PowerShell command execution can ultimately cause Dataset job times to dramatically increase for a given Environment host.
In order to 'illustrate' the problem or reproduce outside of Delphix dataset operations it may be helpful to execute these scripts ad-hoc, in the same manner as the Delphix Connector executes.
As it is currently unknown what additional delays may be obfuscated by executing a new PowerShell from an existing instance (shared memory, libraries may be already loaded), this process is detailed for execution from a CMD window rather than PowerShell directly.
Consider the example execution logged for ListDirectory.ps1, which takes ~15 seconds to complete; in normal operation, we would expect this to be an operation that falls in the range of milliseconds to 2 seconds to complete, depending on the environment characteristics. In each command execution logged, a unique identifier is included to allow tracing per-transaction. This will also be highlighted in bold below.
[2021-11-03 15:28:43,343][INFO][com.delphix.appliance.server.connector.Connector][pool-2-thread-13][ConnectorLogger.info] /10.161.148.9:0/77412204-2d29-4c06-9e81-075b9f99eb00: [executing] "D:\Delphix\DelphixConnector\Delphix_COMMON_abcd1234abcd_host\client\bootstrap\dlpxrunas.exe" powershell -NonInteractive -NoProfile -InputFormat none -ExecutionPolicy RemoteSigned -Command & 'D:\Delphix\DelphixConnector\43211234-abab-dcdc-12ab-ab1256780ab3-vdb-1649\SCRIPT\ListDirectory.ps1' [2021-11-03 15:28:58,524][DEBUG][com.delphix.appliance.server.connector.Connector][pool-2-thread-13][ConnectorLogger.debug] /10.161.148.9:0/77412204-2d29-4c06-9e81-075b9f99eb00: [execute complete: 0] [2021-11-03 15:28:58,524][INFO][com.delphix.appliance.server.connector.Connector][pool-2-thread-13][ConnectorLogger.info] /10.161.148.9:0/77412204-2d29-4c06-9e81-075b9f99eb00: [execute complete]
In the process of diagnosis, it is important to review the pathology of command execution. This example is used as it is not an operation known to suffer from variability in timing (such as iSCSI volume mounts), and it is not SQL Server dependent. Those PowerShell executions appearing to be delayed that are SQL Server dependent (DisableBroker, DoesDatabaseExist, GetVersion) can be executed from SSMS or another SQL client to determine if the delay occurs as a result of SQL Server operation or Environmental concerns.
As Delphix cannot offer extensive expertise in Windows internals, this procedure is offered as a best-effort for on-demand reproduction of Environment issues for further debugging with Windows Administrators or Windows Support vendors, if needed.
Executing Script Ad-hoc
From the Delphix Connector logs on the target host, an example command execution can be extracted for troubleshooting. For the purposes of illustration and reproduction, the comparable command execution will be extracted from a lab system, so paths will differ from those in the introductory example used. The unique identifier used for the command execution and timing are highlighted.
[2021-11-04 08:25:41,908][INFO][com.delphix.appliance.server.connector.Connector][pool-2-thread-51][ConnectorLogger.info] /10.43.37.201:0/a87ac371-fec2-4209-85db-91cd9c8a8003: [executing] "C:\Program Files\Delphix\DelphixConnector\Delphix_COMMON_d5001ed560c5_host\client\bootstrap\dlpxrunas.exe" powershell -NonInteractive -NoProfile -InputFormat none -ExecutionPolicy RemoteSigned -Command & 'C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\SCRIPT\ListDirectory.ps1'
[2021-11-04 08:25:42,486][DEBUG][com.delphix.appliance.server.connector.Connector][pool-2-thread-51][ConnectorLogger.debug] /10.43.37.201:0/a87ac371-fec2-4209-85db-91cd9c8a8003: [execute complete: 0]
stdout
{
C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\DATA\db\McLaren.mdf
C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\DATA\db\McLaren_log.ldf
}
stderr
{
}
[2021-11-04 08:25:42,486][INFO][com.delphix.appliance.server.connector.Connector][pool-2-thread-51][ConnectorLogger.info] /10.43.37.201:0/a87ac371-fec2-4209-85db-91cd9c8a8003: [execute complete]
In order to execute this, including dlpxrunas.exe, a few Environment Variables must be set first, to configure the Delphix OS username and password for dlpxrunas:
DELPHIX_USERNAME DELPHIX_PASSWORD
These can be set via CMD using setx:
setx DELPHIX_USERNAME "<your username>" setx DELPHIX_PASSWORD "<your user password>"
Once completed, a new window must be opened to ensure the new variables are present. This can be confirmed via the set command.
C:\WINDOWS\system32>set ALLUSERSPROFILE=C:\ProgramData APPDATA=C:\Users\delphix\AppData\Roaming CommonProgramFiles=C:\Program Files\Common Files CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files CommonProgramW6432=C:\Program Files\Common Files COMPUTERNAME=kbademo ComSpec=C:\WINDOWS\system32\cmd.exe delphix_bootstrap=C:\Program Files\Delphix\DelphixConnector\Delphix_COMMON_d5001ed560c5_host\client\bootstrap delphix_password=password delphix_username=delphix DriverData=C:\Windows\System32\Drivers\DriverData HOMEDRIVE=C: HOMEPATH=\Users\delphix
With these prerequisites configured, we can now take the logged command execution and adjust formatting for manual execution. Again, from the logged example above, only slight modification is required for command formatting, adding quotations to enclose the PS1 (PowerShell) script execution. The original logged command:
"C:\Program Files\Delphix\DelphixConnector\Delphix_COMMON_d5001ed560c5_host\client\bootstrap\dlpxrunas.exe" powershell -NonInteractive -NoProfile -InputFormat none -ExecutionPolicy RemoteSigned -Command & 'C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\SCRIPT\ListDirectory.ps1'
And the modification, with added quotes highlighted in bold to encapsulate the PS1 script:
"C:\Program Files\Delphix\DelphixConnector\Delphix_COMMON_d5001ed560c5_host\client\bootstrap\dlpxrunas.exe" powershell -NonInteractive -NoProfile -InputFormat none -ExecutionPolicy RemoteSigned -Command " & 'C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\SCRIPT\ListDirectory.ps1'"
When launching the new CMD window, be sure to run as Administrator by right-clicking on the CMD program first. When you right-click Command Prompt select Run as administrator.
Successful execution should result in a PowerShell window appearing briefly, then closing, and the PS1 script output in the CMD window.
C:\WINDOWS\system32>"C:\Program Files\Delphix\DelphixConnector\Delphix_COMMON_d5001ed560c5_host\client\bootstrap\dlpxrunas.exe" powershell -NonInteractive -NoProfile -InputFormat none -ExecutionPolicy RemoteSigned -Command " & 'C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\SCRIPT\ListDirectory.ps1'" C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\DATA\db\McLaren.mdf C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\DATA\db\McLaren_log.ldf
Adding a Timer
Without the benefit of PowerShell cmdlets, some additional logic must be added to capture precise timing of the command execution, if this is desired. Borrowing from a community solution from Stack Overflow, a .bat file can be created to capture more precise timing for the execution. Create timecmd.bat with the following content (or any desired name):
@echo off
@setlocal
set start=%time%
:: Runs your command
cmd /c %*
set end=%time%
set options="tokens=1-4 delims=:.,"
for /f %options% %%a in ("%start%") do set start_h=%%a&set /a start_m=100%%b %% 100&set /a start_s=100%%c %% 100&set /a start_ms=100%%d %% 100
for /f %options% %%a in ("%end%") do set end_h=%%a&set /a end_m=100%%b %% 100&set /a end_s=100%%c %% 100&set /a end_ms=100%%d %% 100
set /a hours=%end_h%-%start_h%
set /a mins=%end_m%-%start_m%
set /a secs=%end_s%-%start_s%
set /a ms=%end_ms%-%start_ms%
if %ms% lss 0 set /a secs = %secs% - 1 & set /a ms = 100%ms%
if %secs% lss 0 set /a mins = %mins% - 1 & set /a secs = 60%secs%
if %mins% lss 0 set /a hours = %hours% - 1 & set /a mins = 60%mins%
if %hours% lss 0 set /a hours = 24%hours%
if 1%ms% lss 100 set ms=0%ms%
:: Mission accomplished
set /a totalsecs = %hours%*3600 + %mins%*60 + %secs%
echo command took %hours%:%mins%:%secs%.%ms% (%totalsecs%.%ms%s total)
Then, the batch script may be prepended to the previous command execution. This also requires execution of the command string with call included (<batch script name> call <command string>). The execution time will be logged below the script output.
C:\Users\delphix>timecmd call "C:\Program Files\Delphix\DelphixConnector\Delphix_COMMON_d5001ed560c5_host\client\bootstrap\dlpxrunas.exe" powershell -NonInteractive -NoProfile -InputFormat none -ExecutionPolicy RemoteSigned -Command "& 'C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\SCRIPT\ListDirectory.ps1'" C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\DATA\db\McLaren.mdf C:\Program Files\Delphix\DelphixConnector\564d3265-57a7-b2ec-5832-d5001ed560c5-vdb-7\DATA\db\McLaren_log.ldf command took 0:0:1.37 (1.37s total)
Removing Environment Variables
In order to prevent unintended exposure of the Delphix OS user credentials, the variables initially configured should be unconfigured when this process is completed. This can be done again with setx to set these parameters to null value:
setx DELPHIX_USERNAME "" setx DELPHIX_PASSWORD ""
Following this, it is recommended to log out of the current desktop session, or at least ensure all CMD and PS windows are terminated.
Related Articles
The following articles may provide more information or related information to this article: