- VMware Technology Network
- :
- Cloud & SDDC
- :
- Automation
- :
- VMware PowerCLI Discussions
- :
- What does PowerCLI continue to do *after* the last...
- Subscribe to RSS Feed
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Bookmark
- Subscribe
- Mute
- Printer Friendly Page
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
What does PowerCLI continue to do *after* the last command has completed?
I'm a PowerCLI newbie, trying out commands on Ubuntu to get a feeling for performance. Here's an example:
PS /home/simon> 1..20 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds}
1.4876538
1.3092909
1.2353557
1.3190417
2.0242428
1.5912262
1.3021472
2.501124
1.7418662
2.1958787
1.6472901
1.7337026
1.9211327
1.6142597
1.4281164
2.0955256
1.4610803
1.8353361
1.5623451
1.5523348So this command takes about 33 seconds to complete? Or is it not yet completed and am I misunderstanding how PowerCLI works?
The reason I think it's not completed is because if I have Wireshark running, then Wireshark shows 147 seconds of higher network activity, and not just 33 seconds as expected:
$ cat get-vm-ubuntu-capture.pcapng.txt | perl -lane 'if(m~^\s*\d+\s+(\d+).+?(TCP|TLS|SSL|H1)[^\s]*\s+(\d+)~){ ($sec,$type,$size) = ($1,$2,$3); $s->[$sec]{$type} += $size; }else{ die qq[ERROR: cannot parse: $_\n]; } sub END{ foreach $sec(0..$#{$s}){ printf qq[- %3u=sec], $sec; foreach $type(qw(TCP TLS SSL H1)){ printf qq[ %9u=%s %-15s], $s->[$sec]{$type}, $type, q[-] x ($s->[$sec]{$type} / 1_000_000); } printf qq[\n]; } }'
- 0=sec 557660=TCP 50730=TLS 0=SSL 0=H1
- 1=sec 138054=TCP 14294=TLS 0=SSL 0=H1
- 2=sec 3645466=TCP --- 341723=TLS 0=SSL 0=H1
- 3=sec 1079962=TCP - 95943=TLS 0=SSL 0=H1
- 4=sec 1787942=TCP - 1077110=TLS - 0=SSL 0=H1
- 5=sec 3655420=TCP --- 1630784=TLS - 0=SSL 0=H1
- 6=sec 6701523=TCP ------ 7256583=TLS ------- 0=SSL 0=H1
- 7=sec 5011694=TCP ----- 6299927=TLS ------ 0=SSL 0=H1
- 8=sec 6150914=TCP ------ 7321875=TLS ------- 0=SSL 0=H1
- 9=sec 4834084=TCP ---- 4292699=TLS ---- 0=SSL 0=H1
- 10=sec 6537963=TCP ------ 5516348=TLS ----- 0=SSL 0=H1
- 11=sec 7400690=TCP ------- 7238038=TLS ------- 0=SSL 0=H1
- 12=sec 12293091=TCP ------------ 8625985=TLS -------- 0=SSL 0=H1
- 13=sec 15633444=TCP --------------- 6592047=TLS ------ 0=SSL 0=H1
- 14=sec 10877783=TCP ---------- 10910371=TLS ---------- 0=SSL 0=H1
- 15=sec 10545872=TCP ---------- 10402240=TLS ---------- 0=SSL 0=H1
- 16=sec 7133344=TCP ------- 7827850=TLS ------- 0=SSL 0=H1
- 17=sec 9653564=TCP --------- 10987209=TLS ---------- 0=SSL 0=H1
- 18=sec 12511628=TCP ------------ 12730279=TLS ------------ 1404=SSL 0=H1
- 19=sec 10026942=TCP ---------- 14739462=TLS -------------- 0=SSL 0=H1
- 20=sec 7240682=TCP ------- 8906599=TLS -------- 0=SSL 0=H1
- 21=sec 12567690=TCP ------------ 10337406=TLS ---------- 0=SSL 0=H1
- 22=sec 8131874=TCP -------- 9972289=TLS --------- 0=SSL 0=H1
- 23=sec 10530618=TCP ---------- 14532455=TLS -------------- 0=SSL 0=H1
- 24=sec 11434585=TCP ----------- 15071877=TLS --------------- 0=SSL 0=H1
- 25=sec 7949554=TCP ------- 13302310=TLS ------------- 1404=SSL 0=H1
- 26=sec 12674027=TCP ------------ 14584307=TLS -------------- 0=SSL 0=H1
- 27=sec 10769485=TCP ---------- 14804650=TLS -------------- 0=SSL 0=H1
- 28=sec 9565160=TCP --------- 9068683=TLS --------- 0=SSL 0=H1
- 29=sec 9691960=TCP --------- 8902336=TLS -------- 0=SSL 0=H1
- 30=sec 7341036=TCP ------- 11148878=TLS ----------- 0=SSL 0=H1
- 31=sec 7642724=TCP ------- 9859215=TLS --------- 0=SSL 0=H1
- 32=sec 10024764=TCP ---------- 12032376=TLS ------------ 0=SSL 0=H1
- 33=sec 10977489=TCP ---------- 14329251=TLS -------------- 0=SSL 0=H1 <-- Ubuntu command finishes!
- 34=sec 8744603=TCP -------- 12820702=TLS ------------ 0=SSL 0=H1
- 35=sec 11729951=TCP ----------- 15355723=TLS --------------- 0=SSL 0=H1
- 36=sec 14005525=TCP -------------- 12581244=TLS ------------ 0=SSL 0=H1
- 37=sec 12902575=TCP ------------ 15682680=TLS --------------- 0=SSL 0=H1
- 38=sec 13041476=TCP ------------- 13099320=TLS ------------- 0=SSL 0=H1
- 39=sec 11576756=TCP ----------- 14549652=TLS -------------- 0=SSL 0=H1
- 40=sec 9819210=TCP --------- 11773944=TLS ----------- 0=SSL 0=H1
- 41=sec 8480366=TCP -------- 11466468=TLS ----------- 0=SSL 0=H1
- 42=sec 8366692=TCP -------- 12885912=TLS ------------ 0=SSL 0=H1
- 43=sec 8750200=TCP -------- 12299040=TLS ------------ 1404=SSL 0=H1
- 44=sec 8392140=TCP -------- 10670400=TLS ---------- 0=SSL 0=H1
- 45=sec 9538844=TCP --------- 12133368=TLS ------------ 0=SSL 0=H1
- 46=sec 8986250=TCP -------- 13170924=TLS ------------- 1404=SSL 0=H1
- 47=sec 12640298=TCP ------------ 15324660=TLS --------------- 0=SSL 0=H1
- 48=sec 12287890=TCP ------------ 14479452=TLS -------------- 0=SSL 0=H1
- 49=sec 11976812=TCP ----------- 14973660=TLS -------------- 0=SSL 0=H1
- 50=sec 12011328=TCP ------------ 15467868=TLS --------------- 0=SSL 0=H1
- 51=sec 13677596=TCP ------------- 12516660=TLS ------------ 1404=SSL 0=H1
- 52=sec 10740108=TCP ---------- 12235860=TLS ------------ 0=SSL 0=H1
- 53=sec 9425238=TCP --------- 14563777=TLS -------------- 0=SSL 0=H1
- 54=sec 10582866=TCP ---------- 16616340=TLS ---------------- 0=SSL 0=H1
- 55=sec 12310000=TCP ------------ 16782012=TLS ---------------- 1404=SSL 0=H1
- 56=sec 10142028=TCP ---------- 13822380=TLS ------------- 0=SSL 0=H1
- 57=sec 9088710=TCP --------- 12616344=TLS ------------ 0=SSL 0=H1
- 58=sec 8322444=TCP -------- 10806588=TLS ---------- 0=SSL 0=H1
- 59=sec 9419340=TCP --------- 13054392=TLS ------------- 0=SSL 0=H1
- 60=sec 11913050=TCP ----------- 14795352=TLS -------------- 1404=SSL 0=H1
- 61=sec 11061092=TCP ----------- 16939260=TLS ---------------- 0=SSL 0=H1
- 62=sec 11224744=TCP ----------- 14541228=TLS -------------- 0=SSL 0=H1
- 63=sec 12779028=TCP ------------ 12870198=TLS ------------ 0=SSL 0=H1
- 64=sec 9133796=TCP --------- 10603758=TLS ---------- 0=SSL 0=H1
- 65=sec 5268616=TCP ----- 8614340=TLS -------- 0=SSL 0=H1
- 66=sec 6156594=TCP ------ 8282626=TLS -------- 0=SSL 0=H1
- 67=sec 5610256=TCP ----- 6851786=TLS ------ 0=SSL 0=H1
- 68=sec 6357128=TCP ------ 9339640=TLS --------- 0=SSL 0=H1
- 69=sec 7626312=TCP ------- 9181600=TLS --------- 0=SSL 0=H1
- 70=sec 7153900=TCP ------- 6411762=TLS ------ 0=SSL 0=H1
- 71=sec 5168386=TCP ----- 5824874=TLS ----- 0=SSL 0=H1
- 72=sec 6302724=TCP ------ 4158140=TLS ---- 0=SSL 0=H1
- 73=sec 7178980=TCP ------- 7439232=TLS ------- 0=SSL 0=H1
- 74=sec 4839816=TCP ---- 4334056=TLS ---- 0=SSL 0=H1
- 75=sec 5585678=TCP ----- 4670470=TLS ---- 0=SSL 0=H1
- 76=sec 7013596=TCP ------- 4565356=TLS ---- 0=SSL 0=H1
- 77=sec 7945786=TCP ------- 6806826=TLS ------ 0=SSL 0=H1
- 78=sec 5408476=TCP ----- 3813880=TLS --- 0=SSL 0=H1
- 79=sec 6430726=TCP ------ 5090644=TLS ----- 0=SSL 0=H1
- 80=sec 6853286=TCP ------ 5085982=TLS ----- 0=SSL 0=H1
- 81=sec 7106898=TCP ------- 6265330=TLS ------ 0=SSL 0=H1
- 82=sec 6119440=TCP ------ 3132888=TLS --- 0=SSL 0=H1
- 83=sec 7218278=TCP ------- 4635854=TLS ---- 0=SSL 0=H1
- 84=sec 7830482=TCP ------- 6342106=TLS ------ 0=SSL 0=H1
- 85=sec 6612556=TCP ------ 4857528=TLS ---- 0=SSL 0=H1
- 86=sec 6055736=TCP ------ 3796194=TLS --- 0=SSL 0=H1
- 87=sec 8324764=TCP -------- 7527312=TLS ------- 0=SSL 0=H1
- 88=sec 5945578=TCP ----- 8780205=TLS -------- 0=SSL 0=H1
- 89=sec 8592660=TCP -------- 15504372=TLS --------------- 1404=SSL 0=H1
- 90=sec 9776428=TCP --------- 15897524=TLS --------------- 1404=SSL 0=H1
- 91=sec 8178058=TCP -------- 10832284=TLS ---------- 0=SSL 0=H1
- 92=sec 7230376=TCP ------- 11083173=TLS ----------- 2808=SSL 0=H1
- 93=sec 4913112=TCP ---- 7413852=TLS ------- 0=SSL 0=H1
- 94=sec 5789534=TCP ----- 8715966=TLS -------- 0=SSL 0=H1
- 95=sec 9454462=TCP --------- 13061730=TLS ------------- 0=SSL 0=H1
- 96=sec 10415798=TCP ---------- 14544036=TLS -------------- 1404=SSL 0=H1
- 97=sec 9660348=TCP --------- 14713920=TLS -------------- 0=SSL 0=H1
- 98=sec 10945606=TCP ---------- 14848704=TLS -------------- 0=SSL 0=H1
- 99=sec 9923556=TCP --------- 15858180=TLS --------------- 0=SSL 0=H1
- 100=sec 10299294=TCP ---------- 14607216=TLS -------------- 0=SSL 0=H1
- 101=sec 9995842=TCP --------- 12143196=TLS ------------ 0=SSL 0=H1
- 102=sec 11166844=TCP ----------- 13484016=TLS ------------- 0=SSL 0=H1
- 103=sec 8539044=TCP -------- 10848708=TLS ---------- 0=SSL 0=H1
- 104=sec 3950286=TCP --- 5513508=TLS ----- 1404=SSL 0=H1
- 105=sec 5345214=TCP ----- 8804484=TLS -------- 0=SSL 0=H1
- 106=sec 5199364=TCP ----- 8292024=TLS -------- 0=SSL 0=H1
- 107=sec 7570738=TCP ------- 11918556=TLS ----------- 0=SSL 0=H1
- 108=sec 7890375=TCP ------- 12133368=TLS ------------ 1404=SSL 0=H1
- 109=sec 6290946=TCP ------ 7797816=TLS ------- 0=SSL 0=H1
- 110=sec 6798404=TCP ------ 11286640=TLS ----------- 0=SSL 0=H1
- 111=sec 6018624=TCP ------ 9360468=TLS --------- 1404=SSL 0=H1
- 112=sec 7157220=TCP ------- 11214847=TLS ----------- 0=SSL 0=H1
- 113=sec 9733762=TCP --------- 13151353=TLS ------------- 0=SSL 0=H1
- 114=sec 8997462=TCP -------- 11392056=TLS ----------- 0=SSL 0=H1
- 115=sec 8013208=TCP -------- 13571064=TLS ------------- 0=SSL 0=H1
- 116=sec 8104428=TCP -------- 12737088=TLS ------------ 0=SSL 0=H1
- 117=sec 9690012=TCP --------- 15992964=TLS --------------- 0=SSL 0=H1
- 118=sec 8633372=TCP -------- 11348532=TLS ----------- 0=SSL 0=H1
- 119=sec 8285364=TCP -------- 11875032=TLS ----------- 0=SSL 0=H1
- 120=sec 9719504=TCP --------- 13901142=TLS ------------- 0=SSL 0=H1
- 121=sec 9001832=TCP --------- 12513852=TLS ------------ 0=SSL 0=H1
- 122=sec 8119594=TCP -------- 14469624=TLS -------------- 0=SSL 0=H1
- 123=sec 9958230=TCP --------- 14975635=TLS -------------- 0=SSL 0=H1
- 124=sec 6581972=TCP ------ 10552464=TLS ---------- 0=SSL 0=H1
- 125=sec 8404966=TCP -------- 13738140=TLS ------------- 0=SSL 0=H1
- 126=sec 9426908=TCP --------- 11728000=TLS ----------- 0=SSL 0=H1
- 127=sec 11132314=TCP ----------- 15215148=TLS --------------- 0=SSL 0=H1
- 128=sec 7192096=TCP ------- 10722348=TLS ---------- 0=SSL 0=H1
- 129=sec 6275224=TCP ------ 10997532=TLS ---------- 0=SSL 0=H1
- 130=sec 5933830=TCP ----- 8511048=TLS -------- 1404=SSL 0=H1
- 131=sec 6786582=TCP ------ 9350640=TLS --------- 0=SSL 0=H1
- 132=sec 9101274=TCP --------- 12961728=TLS ------------ 0=SSL 0=H1
- 133=sec 8050732=TCP -------- 11069274=TLS ----------- 0=SSL 0=H1
- 134=sec 7771302=TCP ------- 10187581=TLS ---------- 1404=SSL 0=H1
- 135=sec 8710244=TCP -------- 9818172=TLS --------- 0=SSL 0=H1
- 136=sec 8061942=TCP -------- 8129160=TLS -------- 0=SSL 0=H1
- 137=sec 10305660=TCP ---------- 9385740=TLS --------- 0=SSL 0=H1
- 138=sec 7735012=TCP ------- 8571420=TLS -------- 0=SSL 0=H1
- 139=sec 5126001=TCP ----- 6838884=TLS ------ 0=SSL 0=H1
- 140=sec 5880252=TCP ----- 8211996=TLS -------- 0=SSL 0=H1
- 141=sec 4297740=TCP ---- 6425564=TLS ------ 0=SSL 0=H1
- 142=sec 3891543=TCP --- 4783346=TLS ---- 0=SSL 0=H1
- 143=sec 4466040=TCP ---- 4419747=TLS ---- 0=SSL 0=H1
- 144=sec 2393550=TCP -- 3670056=TLS --- 0=SSL 0=H1
- 145=sec 4319838=TCP ---- 3017196=TLS --- 0=SSL 0=H1
- 146=sec 972486=TCP 743351=TLS 0=SSL 0=H1
- 147=sec 0=TCP 0=TLS 0=SSL 0=H1 <-- keepalive packets from now on?
- 148=sec 54=TCP 1420=TLS 0=SSL 0=H1
- 149=sec 0=TCP 0=TLS 0=SSL 0=H1
- 150=sec 162=TCP 85=TLS 0=SSL 0=H1
- 151=sec 0=TCP 0=TLS 0=SSL 0=H1
- 152=sec 0=TCP 0=TLS 0=SSL 0=H1
- 153=sec 0=TCP 0=TLS 0=SSL 0=H1
- 154=sec 0=TCP 0=TLS 0=SSL 0=H1
- 155=sec 0=TCP 0=TLS 0=SSL 0=H1
- 156=sec 0=TCP 0=TLS 0=SSL 0=H1
- 157=sec 0=TCP 0=TLS 0=SSL 0=H1
- 158=sec 0=TCP 0=TLS 0=SSL 0=H1
- 159=sec 0=TCP 0=TLS 0=SSL 0=H1
- 160=sec 0=TCP 0=TLS 0=SSL 0=H1
- 161=sec 0=TCP 0=TLS 0=SSL 0=H1
- 162=sec 0=TCP 0=TLS 0=SSL 0=H1
- 163=sec 0=TCP 0=TLS 0=SSL 0=H1
- 164=sec 0=TCP 0=TLS 0=SSL 0=H1
- 165=sec 162=TCP 85=TLS 0=SSL 0=H1
- 166=sec 0=TCP 0=TLS 0=SSL 0=H1
- 167=sec 0=TCP 0=TLS 0=SSL 0=H1
- 168=sec 0=TCP 0=TLS 0=SSL 0=H1
- 169=sec 0=TCP 0=TLS 0=SSL 0=H1
- 170=sec 0=TCP 0=TLS 0=SSL 0=H1
- 171=sec 0=TCP 0=TLS 0=SSL 0=H1
- 172=sec 0=TCP 0=TLS 0=SSL 0=H1
- 173=sec 108=TCP 1488=TLS 0=SSL 0=H1
- 174=sec 0=TCP 0=TLS 0=SSL 0=H1
- 175=sec 0=TCP 0=TLS 0=SSL 0=H1
- 176=sec 0=TCP 0=TLS 0=SSL 0=H1
- 177=sec 0=TCP 0=TLS 0=SSL 0=H1
- 178=sec 0=TCP 0=TLS 0=SSL 0=H1
- 179=sec 0=TCP 0=TLS 0=SSL 0=H1
- 180=sec 571=TCP 170=TLS 0=SSL 0=H1
- 181=sec 0=TCP 0=TLS 0=SSL 0=H1
And it's a similar story for CPU usage too.
So is the command taking 33 or 146 seconds to execute?
If 146 seconds, then how to determine when the command has finished without using Wireshark?
Thanks in advance! 🙂
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
Not sure which packages you are including, but I don't see that behavior.
The open VCSA connection is doing a keep-alive communication at regular intervals, but not to the likes of what you measuring.
I'm wondering if all that traffic is actually between the Ubuntu station and the VCSA.
If you close your VCSA connection immediately after your snippet, you shouldn't see any more communication to the VCSA from your Ubuntu station.
At least that is what I am seeing.
1..20 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds}; Disconnect-VIServer -Server * -Confirm:$false
Blog: lucd.info Twitter: @LucD22 Co-author PowerCLI Reference
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
Thanks for the quick reply @LucD !
> I'm wondering if all that traffic is actually between the Ubuntu station and the VCSA.
Yes, it should be, because I told Wireshark to only record packets where the source or destination IP is that of the VCSA.
> If you close your VCSA connection immediately after your snippet, you shouldn't see any more communication to the VCSA from your Ubuntu station.
Thanks for the suggestion! I tried timing closing the connection immediately after and got unexpected results. The disconnect appears to take an unexpectedly very long time; 246 seconds. The connection finally closes when the unexpected network activity with the VCSA stops.
PS /home/simon> 1..20 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
1.5618847
1.8132676
...
245.9708355
Any ideas how I might diagnose / debug why my setup is behaving like this? In theory I have a clean setup which hasn't been meddled with 🙂 I installed "pwsh" and "PowerCLI". That's about it.
PS /home/simon> pwsh --version PowerShell 7.4.1
PS /home/simon> Get-PowerCLIVersion
WARNING: The cmdlet "Get-PowerCLIVersion" is deprecated. Please use the 'Get-Module' cmdlet instead.
PowerCLI Version
----------------
VMware.PowerCLI 13.2.1 build 22851661
---------------
Component Versions
---------------
VMware Common PowerCLI Component 13.2 build 22643733
VMware Cis Core PowerCLI Component PowerCLI Component 13.2 build 22643734
VMware VimAutomation VICore Commands PowerCLI Component PowerCLI Component 13.2 build 22643732
PS /home/simon> Get-Module
ModuleType Version PreRelease Name ExportedCommands
---------- ------- ---------- ---- ----------------
Manifest 7.0.0.0 Microsoft.PowerShell.Management {Add-Content, Clear-Content, Clear-Item, Clear-ItemProperty…}
Manifest 7.0.0.0 Microsoft.PowerShell.Utility {Add-Member, Add-Type, Clear-Variable, Compare-Object…}
Script 2.3.4 PSReadLine {Get-PSReadLineKeyHandler, Get-PSReadLineOption, Remove-PSReadLineKeyHandler, Set-PSReadLineKeyHandler…}
Script 8.2.0.226… VMware.Vim
Script 13.2.0.22… VMware.VimAutomation.Cis.Core {Connect-CisServer, Disconnect-CisServer, Get-CisService}
Script 13.2.0.22… VMware.VimAutomation.Common {Get-PowerCLIContext, Get-Task, New-OAuthSecurityContext, Stop-Task…}
Script 13.2.0.22… VMware.VimAutomation.Core {Add-PassthroughDevice, Add-VirtualSwitchPhysicalNetworkAdapter, Add-VMHost, Add-VMHostNtpServer…}
Script 13.2.0.22… VMware.VimAutomation.Sdk {Get-ErrorReport, EnableParameterCompleters, Get-InstallPath, Get-PSVersion}
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
Thanks for the quick reply!
> I'm wondering if all that traffic is actually between the Ubuntu station and the VCSA.
Yes, it should be, because I told Wireshark to only record packets where the source or destination IP is that of the VCSA.
> If you close your VCSA connection immediately after your snippet, you shouldn't see any more communication to the VCSA from your Ubuntu station.
Thanks for the suggestion! I tried timing closing the connection immediately after and got unexpected results. The disconnect appears to take an unexpectedly very long time; 246 seconds. The connection finally closes when the unexpected network activity with the VCSA stops.
PS /home/simon> 1..20 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
1.5618847
1.8132676
...
245.9708355
Any ideas how I might diagnose / debug why my setup is behaving like this? In theory I have a clean setup which hasn't been meddled with 🙂 I installed "pwsh" and "PowerCLI". That's about it.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
That long time to do the Disconnect-VIServer is not normal.
When I test that it happens nearly instantaneously.
Can you see in WireShark what is happening during those 246 seconds?
Are there retransmissions of packets, or timeouts?
If you are using an AD account to connect, you could check KB79317 and KB79323
Blog: lucd.info Twitter: @LucD22 Co-author PowerCLI Reference
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
Thanks for the reply, LucD!
> Can you see in WireShark what is happening during those 246 seconds?
It looks like regular packets / traffic.
One thing I should also say is that "get-vm" is returning some 1,000s of VMs...
I tried using a different tool called "ssldump" to analyze a capture made with "tcpdump":
This is how I captured the packets:
$ sudo tcpdump -vvv -s 0 -nni $MY_INTERFACE -w ./ssl-client-disconnect-early.cap host $MY_IP and port 443
^C
957328 packets captured
957328 packets received by filter
0 packets dropped by kernelThis is the command to connect, sleep 10s, do 20x get-vm, no sleep, disconnect:
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 10 ; 1..20 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
1.359173
1.3307955
1.3874726
1.4249941
1.6020137
1.8653579
2.0515704
1.2944206
1.2112047
1.1386629
1.6471517
1.630373
1.3010904
1.5786187
1.1242513
2.4786786
1.621102
1.1031861
2.1626463
1.7960649
86.843966Note: Today the time to disconnect is "only" 86 seconds.
Next I analyze the "ssldump" output using a Perl one-liner:
$ ssldump -nr ./ssl-client-disconnect-early.cap 2>&1 | perl -lane 'if(m~^(\d+)\s+.*?\s+(\d+\.\d+)\s+.*?[C>S]+\s+(.*)~){ ($conn, $sec, $type) = ($1, $2, $3, $4); next if($type eq q[ChangeCipherSpec]); if(not exists $c->{$conn}{type}{$type}){ $c->{$conn}{type}{$type} ++; $c->{$conn}{sec}{$sec} = $_; } if(($_ =~ m~application_data~) && (1 == $c->{$conn}{type}{$type})){ $c->{$conn}{app_last} = $_; if(0){ printf qq[#$conn#$sec#$type# %s\n], $_; } } } sub END{ printf qq[\n]; foreach $conn(sort {$a <=> $b} keys %{$c}){ foreach $sec(sort {$a <=> $b} keys %{$c->{$conn}{sec}}){ printf qq[%s], $c->{$conn}{sec}{$sec}; if(($c->{$conn}{sec}{$sec} =~ m~application_data~) && (exists $c->{$conn}{app_last})){ printf qq[ ... %s], $c->{$conn}{app_last}; } printf qq[\n]; } printf qq[\n]; } }'
1 1 0.0300 (0.0300) C>S Handshake
1 7 0.0657 (0.0009) C>S application_data ... 1 10304 120.7639 (0.0000) S>C application_data
2 1 0.0303 (0.0303) C>S Handshake
2 0.0618 (0.0017) C>S TCP FIN
2 7 0.0894 (0.0275) S>C Alert
3 1 0.0299 (0.0299) C>S Handshake
3 12 0.0941 (0.0011) C>S application_data ... 3 15 0.1795 (0.0486) S>C application_data
3 16 75.0992 (0.1024) S>C Alert
4 1 0.0309 (0.0309) C>S Handshake
4 7 0.0663 (0.0020) C>S application_data ... 4 10 0.1866 (0.0016) S>C application_data
4 74.9878 (74.8012) C>S TCP FIN
4 11 75.1490 (0.1612) S>C Alert
5 1 0.0294 (0.0294) C>S Handshake
5 7 0.1651 (0.0010) C>S application_data ... 5 10035 94.7697 (0.0000) S>C application_data
6 1 0.0313 (0.0313) C>S Handshake
6 7 0.1801 (0.1143) C>S application_data ... 6 9459 85.2392 (0.0000) S>C application_data
7 1 0.0280 (0.0280) C>S Handshake
7 7 0.0565 (0.0006) C>S application_data ... 7 9394 97.9209 (0.0000) S>C application_data
8 1 0.0313 (0.0313) C>S Handshake
8 7 0.0891 (0.0245) C>S application_data ... 8 9419 77.4832 (0.0027) S>C application_data
9 1 0.0520 (0.0520) C>S Handshake
9 7 0.0827 (0.0007) C>S application_data ... 9 9713 101.7412 (0.0000) S>C application_data
10 1 0.0655 (0.0655) C>S Handshake
10 7 0.1006 (0.0026) C>S application_data ... 10 9757 95.6419 (0.0049) S>C application_data
11 1 0.0297 (0.0297) C>S Handshake
11 7 0.0608 (0.0009) C>S application_data ... 11 9708 102.2692 (0.0001) S>C application_data
12 1 0.0344 (0.0344) C>S Handshake
12 7 0.0663 (0.0006) C>S application_data ... 12 10001 102.5595 (0.0000) S>C application_data
13 1 0.0346 (0.0346) C>S Handshake
13 7 0.0717 (0.0014) C>S application_data ... 13 9718 92.6556 (0.0000) S>C application_data
14 1 0.0295 (0.0295) C>S Handshake
14 7 0.0973 (0.0374) C>S application_data ... 14 9449 82.5953 (0.0001) S>C application_data
15 1 0.0334 (0.0334) C>S Handshake
15 7 0.0657 (0.0005) C>S application_data ... 15 9765 100.9660 (0.0124) S>C application_data
16 1 0.0329 (0.0329) C>S Handshake
16 7 0.0733 (0.0017) C>S application_data ... 16 9714 96.1787 (0.0000) S>C application_data
17 1 0.0722 (0.0722) C>S Handshake
17 7 0.1232 (0.0006) C>S application_data ... 17 9771 95.9160 (0.0033) S>C application_data
18 1 0.1291 (0.1291) C>S Handshake
18 7 0.2243 (0.0037) C>S application_data ... 18 5373 75.3090 (0.0052) S>C application_data
19 1 0.0797 (0.0797) C>S Handshake
19 7 0.1458 (0.0032) C>S application_data ... 19 1560 18.4055 (0.0065) S>C application_data
19 86.0363 (67.6307) C>S TCP FIN
19 1561 86.0759 (0.0396) S>C Alert
20 1 0.0657 (0.0657) C>S Handshake
20 7 0.4083 (0.2514) C>S application_data ... 20 9443 91.9355 (0.0000) S>C application_data
21 1 0.0484 (0.0484) C>S Handshake
21 7 0.1092 (0.0013) C>S application_data ... 21 9445 86.8842 (0.0022) S>C application_data
22 1 0.0928 (0.0928) C>S Handshake
22 7 0.1373 (0.0060) C>S application_data ... 22 9392 89.1947 (0.0000) S>C application_data
23 1 0.0577 (0.0577) C>S Handshake
23 7 0.1138 (0.0018) C>S application_data ... 23 70 1.7827 (0.0512) S>C application_data
23 64.6518 (62.8691) C>S TCP FIN
23 71 64.6815 (0.0296) S>C AlertThis shows there are 23 different SSL connections to vCenter, and I group connections together to it's easer to see what's going on. I show the first "Handshake" packet, the first "application_data" packet, the last "application_data" packet, and the first "TCP FIN" and "Alert" packets.
All of the 23 SSL connections hand shake and connect immediately after the "Connect-VIServer" PowerCLI command.
While a few SSL connections terminate earlier on, none of them are around the 30 to 40 second mark like you would expect. Most of the SSL connections are still sending "application_data" 77 to 102 seconds into the packet capture.
Any ideas?
> AD account to connect
A colleague of mine is going to look at those KB articles. Thanks! But the initial connection(s) occur(s) very fast, and there is not lots of "application_data" happening after the initial connect. It's only after the "get-vm" command has finished that the .NET threads keep using CPU and lots of network bandwidth.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
Unfortunately, I don't have those numbers of VMs in my lab to test and eventually replicate what you are seeing.
To see what is happening one would need to look inside the transmitted packets, but those are encrypted, so no deal I'm afraid.
It could be that some information from the VMs is transmitted directly, and this is what is shown in the regular output.
That is to say the properties that are defined in the .ps1xml files for the VirtualMachine object.
The other info that is transmitted afterwards could be other VM properties.
I do know that PowerCLI optimised the functioning of the Get-VM cmdlet for large environments some releases ago.
But I'm not sure if that is actually what is happening.
You could do some testing with the Get-View cmdlet, which is what I would always use in larger environments.
For example
Get-View -ViewType VirtualMachineCheck if that shows the same behavior.
Then you limit which properties are returned by using the Property parameter.
Get-View -ViewType VirtualMaachine -Property Config,GuestHowever, the behavior of the Get-VM cmdlet is unexplored territory since the source code for PowerCLI is not open-sourced.
Blog: lucd.info Twitter: @LucD22 Co-author PowerCLI Reference
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
Thanks for the tip regarding "get-view" which I will definitely have a look at 🙂
In the meantime, I did this further test which gives a clue as to what might be happening:
Below, we connect, run n "get-vm" commands, and the disconnect, and inc n for the next test, doing 10 runs:
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..1 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
1.2779272
0.8708699
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..2 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
0.9233572
0.9715198
0.7468619
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..3 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
1.2251007
1.3051243
1.1103782
7.1154114
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..4 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
0.922873
1.048508
1.1326211
0.9024899
17.3058807
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..5 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
0.8461962
1.0914008
0.828443
1.0824637
0.9489878
20.6333869
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..6 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
0.9136968
1.1865681
0.9858537
0.8305779
1.2379933
1.6523577
31.4192167
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..7 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
0.9458537
1.1976562
1.0030188
1.4112965
2.1380231
1.8915091
1.1912775
32.2236988
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..8 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
0.925041
1.8963528
3.0684709
1.3279066
1.9312983
1.9533709
2.007666
1.3640866
37.3110531
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..9 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
1.3205683
1.4561693
1.2504701
1.501217
1.9889244
1.8832007
4.0105103
1.2910477
1.376814
36.4589061
PS> Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; sleep 1 ; 1..10 | %{(Measure-Command{ $vm = get-vm }).TotalSeconds} ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds
...
1.1456539
1.4146568
1.20826
1.0229657
1.4225492
1.1401147
1.1073229
2.047932
1.9635946
2.0813102
60.1613763Interestingly, for 1 or 2 "get-vm" commands, between connect and disconnect, then the disconnect occurs in less than 1 second.
However, starting with 3 or more commands then the disconnect time increases depending upon the number of commands ran.
So the problem seems limited to the number of commands run during a single authenticated connection.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
And as a further experiment, I tried doing 10 "get-vm" commands in a row, but this time connecting and disconnecting between every command:
PS> 1..10 | %{ Connect-VIServer -server $env:MY_DATA_CENTER -user $env:MY_SERVER_DOT_USER -pass $env:MY_SERVER_DOT_PASSWORD ; (Measure-Command{ $vm = get-vm }).TotalSeconds ; (Measure-Command{ Disconnect-VIServer -Server * -Confirm:$false }).TotalSeconds }
...
0.8704571
1.1028503
...
0.9659054
0.708065
...
0.9119757
0.711403
...
0.8559371
0.7070745
...
0.8861469
0.9853003
...
0.9868887
0.6688438
...
1.0937617
0.6603562
...
1.0791848
0.965693
...
0.8778906
0.5957551
...
0.9607003
0.968272As you can see, the disconnect times do not go, suggesting there is a performance advantage in regularly connecting and disconnecting around "get-vm" commands, or there is a performance bug with multiple "get-vm" commands in the same authenticated session.
LucD, I don't know if you have the ability to escalate such a bug to the PowerCLI developers, but if you could, that would be great.
In the meantime, I can use the workaround of more frequently connecting and disconnecting 🙂
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
I never heard of any impact from the number of commands one runs in 1 single VCSA session.
Since PowerCLI is using the same API as the Web Gui, you should see the same effect in the Web GUI, provided there would be such an impact.
I'm afraid that since the recent events at VMware, my contacts with PowerCLI developers are at an all-time low.
Read: I'm not sure there are many PowerCLI developers left 🤔
But you can open an SR yourself.If GSS claims that PowerCLI is not supported or that you need a Developer Support contract, point them to the PowerCLI support policy: https://developer.vmware.com/docs/15315/GUID-0F835722-E667-4177-A8EF-51AB15FA837E.html.
Blog: lucd.info Twitter: @LucD22 Co-author PowerCLI Reference