joeware - never stop exploring... :)

So Brandon stepped up and did something I didn’t think anyone would step up and do… Start profiling and comparing the performance of PowerShell and .NET DS Protocols against a native App using the wldap32 LDAP library[1]. Brandon’s first blog entry on the topic is here – http://bsonposh.com/archives/325

While I am going to question Brandon’s testing a little here, especially his results, I commend him for taking the time and energy to step up and actually do this[3].

I guess I should state my underlying thoughts on this whole topic since some people know, some people don’t know, and a whole lot of people *think they know* what I think about it… I would be happy to see PoS+.NET compete with or even beat out a native app+wldap32, I don’t expect it, but I would be happy to see it[6]. I definitely don’t expect to see the numbers Brandon is showing on his blog which is why I am taking the time to look at this with the detail that I am going to provide.

Anyway… Historically, there is almost always a tradeoff in terms of speed and ease of use. For instance, C++ is easier to use than Assembler but if you have a great C++ programmer and a great ASM programmer, the ASM programmer will write more code but it should almost certainly be faster, smaller compiled footprint, and more efficient overall. However some things are so painful to do or take so long or require so much code that we have moved from using ASM to using C and then C++ and other higher level compiled languages[7]. This is one of the big reasons why you use .NET. It isn’t about performance of the running code, it is about how fast you can get to having running code. It is, IMO, sort of a RAD tool, not something you want to put into heavy use, but something to prototype out what you want to do or if you just need to do something quick.

 

So after running through the tests, my results are so radically different from Brandon’s I wonder what is going on. If someone sees a mistake in the testing I followed, please let me know. I expected the results to not be as good as what Brandon came up with but I didn’t expect them to be as bad as they were.

 

1. Testing Methodology.

I don’t really like how Brandon ran his tests from a couple of angles.

The first thing I don’t like is that he uses PoS to measure the speed of PoS and AdFind. I have no clue what overhead is in there which is why I don’t like it. Brandon is obviously comfortable with it however. Whether that is blind faith or he has done comprehensive tests to prove out that it is trustworthy, I don’t know… I do know that I can’t and won’t assume the latter. His trust in it does not transition to me. I am quite untrusting.

The second thing I don’t like is how the commands are all mixed up together. When I am measuring speed on commands, especially something for AD,  I tend to run the same command over and over again so that caching is taken out of the picture as well as anything else. What I am looking for out of the numbers is consistency in times to run the specific command. If you don’t see consistency, it tends to mean something else is playing into the tests. I would prefer to see 5, 10, or 100 runs of the same command in a row and then ditto for the next command and the next, etc. I don’t see consistency in Brandon’s reported numbers. Way too much skew.

 

Solutions

My solutions for these issues are

A. Instead of using a PoS script to launch AdFind and the Counting PoS script, I changed the prompt in PoS to include the current time with the following command

function prompt {Write-Host $(get-date).Tostring(“yyyy-MM-dd HH:mm:ss”)}

That gives me a prompt that looks like

2008-06-08 17:16:25
PS>

Then I just paste in my commands I want to run with a blank line at the beginning and end of the command sequence. This is something I do in the normal command prompt as well (though my prompt in that case is instead prompt=[$D $T] $M$+ $_$P$G). That makes it so the shell stamps the time to the console right there on the spot like so…

Command Sequence

• [ENTER]
• [ENTER]
• dir
• [ENTER]
• [ENTER]

Which generates output like

2008-06-08 18:13:12
PS>
2008-06-08 18:13:23
PS>
2008-06-08 18:13:23
PS>dir

    Directory: Microsoft.PowerShell.Core\FileSystem::G:\PSTest

Mode                LastWriteTime     Length Name
—-                ————-     —— —-
-a—         6/24/2007  10:06 PM    2013184 AdFind.exe
-a—          6/8/2008  10:37 AM       1559 PSSpeed.ps1
-a—          6/8/2008  10:33 AM       2338 Test-DSProtocalsSP.ps1

2008-06-08 18:13:23
PS>
2008-06-08 18:13:23
PS>

I think anyone who looks at it should be comfortable with this method. If not, please let me know what you aren’t comfortable about.

 

 

B. So my solution for the second issue is probably pretty obvious after seeing the solution to the first… Have a notepad document with some commands all ready to cut and paste into the PoS window in one fell swoop. That looks something like

• [ENTER]
• [ENTER]
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• [ENTER]
• [ENTER]
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• [ENTER]
• [ENTER]

 

and a “10 count run”

• [ENTER]
• [ENTER]
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• adfind -default -f objectclass=* -c
• [ENTER]
• [ENTER]
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• .\Test-DSProtocalsSP.ps1
• [ENTER]
• [ENTER]

 

2. Testing environment

I think testing against a 700k user environment is a bit extreme as there aren’t but a handful of AD Implementations out there that come anywhere near that but maybe it is good in that it will help stabilize any time variance issues resulting from spin up time for the app/script. I.E. If you have a second of overhead for starting an app, the more objects you have to pull, the smaller the percentage that overhead will be of the total execution time. I kind of think this tends to help PoS more than a native app because a native app has very little spin up overhead relative to PoS script or .NET but I will go with it. If anything, launching AdFind from within PoS likely has more overhead for launch than launching a PoS script from PoS. If someone wants to test on different sized environments, knock yourself out. I am already spending too much time on this.

I used AdMod to create 700k test users on my test domain with the following command:

admod -sc adau:70000;MyPassword1!;cn=PoSTest,ou=PoSTest,dc=test,dc=loc

I am running all of my tests against a virtual DC loaded with Windows Server 2003 SP2; it is one of 3 virtuals currently running on an Intel Quad Core Server box I build specifically for running virtuals using VMWARE Server. The RAM allocated (256MB) is not even close enough to cache the entire DIT (~2.75GB) even if I enabled /3GB (which I didn’t, no point…). The actual code is running on a real physical machine that has x86 XP SP2 on it and is a AMD Athlon 64 X2 4200+ Dual Core proc. Underlying network is 100Mbs with most network traffic quiesced for the testing period.

I am using the publicly available version of AdFind – V01.37.00 compiled on June 24, 2007.

PS>filever adfind.exe
–a– W32i   APP ENU     1.37.0.1604 shp  2,013,184 06-24-2007 adfind.exe

I am using the PoS Script that Brandon posted on his blog…Here it is again for completeness. Brandon, note a good modification to the script would be to output what DC it is connecting to to do the work so you know if it is consistently connecting to the same place and that AdFind and the script are connecting to the same place. I validated that it appeared to be using the same DC as AdFind by doing some network tracing. That shouldn’t be needed and honestly there should be a way to specify the domain/DC to use to make sure the same source is used consistently.

Test-DSProtocalsSP.ps1

[System.Reflection.assembly]::LoadWithPartialName(“system.directoryservices.protocols”) | Out-Null
$domain = ([ADSI]””).distinguishedName -replace  “,”,”.” -replace “dc=”,””
$DomainDN = “DC=” + $Domain -replace “\.”,”,DC=”
[int]$pageCount = 0
[int]$pageSize = 1000
[int]$count = 0
$connection = New-Object System.DirectoryServices.Protocols.LdapConnection($domain) 
$subtree = [System.DirectoryServices.Protocols.SearchScope]”Subtree”
$filter = “(objectclass=user)”
$searchRequest = New-Object System.DirectoryServices.Protocols.SearchRequest($DomainDN,$filter,$subtree,@(“1.1”)) 
$pagedRequest = New-Object System.DirectoryServices.Protocols.PageResultRequestControl($pageSize)
$searchRequest.Controls.add($pagedRequest) | out-null
$searchOptions = new-object System.DirectoryServices.Protocols.SearchOptionsControl([System.DirectoryServices.Protocols.SearchOption]::DomainScope)
$searchRequest.Controls.Add($searchOptions) | out-null
while ($true)
{
    ## increment the pageCount by 1
    $pageCount++
    ## cast the directory response into a
    ## SearchResponse object
    $searchResponse = $connection.SendRequest($searchRequest)
    ## verify support for this advanced search operation
    if (($searchResponse.Controls.Length -lt 1) -or
        !($searchResponse.Controls[0] -is [System.DirectoryServices.Protocols.PageResultResponseControl]))
    {
        Write-Host “The server cannot page the result set”
        return;
    }
    ## cast the diretory control into
    ## a PageResultResponseControl object.
    $pageResponse = $searchResponse.Controls[0]
    ## display the retrieved page number and the number of
    ## directory entries in the retrieved page                   
    #”Page:{0} Contains {1} response entries” -f $pageCount,$searchResponse.entries.count
    $count += $searchResponse.entries.count
    ## display the entries within this page
    ## foreach($entry in $searchResponse.entries){$entry.DistinguishedName}
    ## if this is true, there
    ## are no more pages to request
    if ($pageResponse.Cookie.Length -eq 0){write-Host $count;break}
    ## set the cookie of the pageRequest equal to the cookie
    ## of the pageResponse to request the next page of data
    ## in the send request
    $pagedRequest.Cookie = $pageResponse.Cookie
}

 

3. Considerable performance hit on the machine running the tools…. Based on .FAT[11] isn’t it???

This one is actually pretty humourous, doesn’t take much to see what is happening… It shows quite quickly and easily one of my issues with using something other than native code; especially .NET/PoS. This is what you get as you abstract and bloat… This is a part of the reason why it is slow overall, it beats the machine up.

 

Figure 1 shows my machine at “idle”. When I watched it I saw CPU usage bumps between 0% and 5% with spikes up to about 15%.

                                                     [Figure 1]

 

Figure 2 shows AdFind running the command “adfind -default -f objectclass=* -c” which counts the objects in the domain NC. When I watched it I saw CPU usage bumps between about 4% and 11% with spikes up to about 18%.

                                                     [Figure 2]

 

 

Figure 3 shows Brandon’s PoS script counting the objects in the domain NC. When I watched it I saw CPU usage bumps between 20% and 45% with spikes up to around 50%.

                                                     [Figure 3]

 

If you don’t like pretty pictures and prefer hard text data instead, here is output from typeperf… 35 one second samples from each state…

 

This is when idling

“(PDH-CSV 4.0)”,”\\SFMXP32\processor(_total)\% processor time”

“06/08/2008 17:00:04.789″,”0.000000”
“06/08/2008 17:00:05.789″,”0.000000”
“06/08/2008 17:00:06.789″,”0.000000”
“06/08/2008 17:00:07.789″,”0.000000”
“06/08/2008 17:00:08.789″,”0.774265”
“06/08/2008 17:00:09.789″,”0.000000”
“06/08/2008 17:00:10.789″,”0.000000”
“06/08/2008 17:00:11.789″,”0.000000”
“06/08/2008 17:00:12.789″,”0.000000”
“06/08/2008 17:00:13.789″,”0.000000”
“06/08/2008 17:00:14.789″,”0.774265”
“06/08/2008 17:00:15.789″,”0.774265”
“06/08/2008 17:00:16.789″,”0.000000”
“06/08/2008 17:00:17.789″,”0.774265”
“06/08/2008 17:00:18.789″,”0.000000”
“06/08/2008 17:00:19.788″,”0.000000”
“06/08/2008 17:00:20.788″,”2.336875”
“06/08/2008 17:00:21.788″,”0.774265”
“06/08/2008 17:00:22.788″,”2.336875”
“06/08/2008 17:00:23.788″,”0.000000”
“06/08/2008 17:00:24.788″,”0.000000”
“06/08/2008 17:00:25.788″,”0.000000”
“06/08/2008 17:00:26.788″,”0.000000”
“06/08/2008 17:00:27.788″,”0.000000”
“06/08/2008 17:00:28.788″,”0.000000”
“06/08/2008 17:00:29.788″,”0.774265”
“06/08/2008 17:00:30.788″,”0.000000”
“06/08/2008 17:00:31.788″,”1.555570”
“06/08/2008 17:00:32.788″,”0.000000”
“06/08/2008 17:00:33.787″,”0.774265”
“06/08/2008 17:00:34.787″,”0.000000”
“06/08/2008 17:00:35.787″,”0.000000”
“06/08/2008 17:00:36.787″,”0.000000”
“06/08/2008 17:00:37.787″,”0.000000”
“06/08/2008 17:00:38.787″,”0.000000”
“06/08/2008 17:00:39.787″,”0.000000”
“06/08/2008 17:00:40.787″,”0.000000”
“06/08/2008 17:00:41.787″,”0.000000”
“06/08/2008 17:00:42.787″,”0.000000”
“06/08/2008 17:00:43.787″,”0.000000”
“06/08/2008 17:00:44.787″,”0.774265”

 

This is when AdFind was running

“(PDH-CSV 4.0)”,”\\SFMXP32\processor(_total)\% processor time”

“06/08/2008 17:01:06.785″,”1.555570”
“06/08/2008 17:01:07.785″,”6.243400”
“06/08/2008 17:01:08.785″,”3.899485”
“06/08/2008 17:01:09.785″,”8.587315”
“06/08/2008 17:01:10.785″,”10.931230”
“06/08/2008 17:01:11.800″,”7.685809”
“06/08/2008 17:01:12.800″,”10.931230”
“06/08/2008 17:01:13.800″,”14.056450”
“06/08/2008 17:01:14.800″,”9.368620”
“06/08/2008 17:01:15.800″,”15.619060”
“06/08/2008 17:01:16.800″,”5.462095”
“06/08/2008 17:01:17.800″,”9.368620”
“06/08/2008 17:01:18.800″,”13.275145”
“06/08/2008 17:01:19.800″,”9.368620”
“06/08/2008 17:01:20.800″,”11.712535”
“06/08/2008 17:01:21.800″,”5.462095”
“06/08/2008 17:01:22.800″,”10.149925”
“06/08/2008 17:01:23.800″,”6.243400”
“06/08/2008 17:01:24.799″,”6.243400”
“06/08/2008 17:01:25.799″,”9.368620”
“06/08/2008 17:01:26.799″,”8.587315”
“06/08/2008 17:01:27.799″,”9.368620”
“06/08/2008 17:01:28.799″,”10.149925”
“06/08/2008 17:01:29.799″,”11.712535”
“06/08/2008 17:01:30.799″,”14.837755”
“06/08/2008 17:01:31.799″,”5.462095”
“06/08/2008 17:01:32.799″,”9.368620”
“06/08/2008 17:01:33.799″,”6.243400”
“06/08/2008 17:01:34.799″,”2.336875”
“06/08/2008 17:01:35.799″,”0.774265”
“06/08/2008 17:01:36.799″,”3.118180”
“06/08/2008 17:01:37.799″,”1.555570”
“06/08/2008 17:01:38.799″,”2.336875”
“06/08/2008 17:01:39.798″,”4.680790”
“06/08/2008 17:01:40.798″,”5.462095”
“06/08/2008 17:01:41.798″,”9.368620”
“06/08/2008 17:01:42.798″,”3.118180”

 

This is when the PoS Script was running

“(PDH-CSV 4.0)”,”\\SFMXP32\processor(_total)\% processor time”

“06/08/2008 17:09:17.344″,”36.918636”
“06/08/2008 17:09:18.407″,”41.786947”
“06/08/2008 17:09:19.422″,”43.072915”
“06/08/2008 17:09:20.469″,”44.772231”
“06/08/2008 17:09:21.516″,”35.816377”
“06/08/2008 17:09:22.563″,”33.083524”
“06/08/2008 17:09:23.594″,”36.918636”
“06/08/2008 17:09:24.594″,”29.682550”
“06/08/2008 17:09:25.594″,”33.589075”
“06/08/2008 17:09:26.609″,”29.540494”
“06/08/2008 17:09:27.656″,”29.540494”
“06/08/2008 17:09:28.734″,”41.300215”
“06/08/2008 17:09:29.734″,”36.359156”
“06/08/2008 17:09:30.797″,”34.086269”
“06/08/2008 17:09:31.812″,”31.533642”
“06/08/2008 17:09:32.812″,”28.901245”
“06/08/2008 17:09:33.828″,”33.072211”
“06/08/2008 17:09:34.859″,”33.328640”
“06/08/2008 17:09:35.859″,”34.610781”
“06/08/2008 17:09:36.905″,”34.086269”
“06/08/2008 17:09:37.952″,”35.816377”
“06/08/2008 17:09:38.952″,”35.151685”
“06/08/2008 17:09:40.015″,”32.348178”
“06/08/2008 17:09:41.046″,”39.547983”
“06/08/2008 17:09:42.093″,”38.230946”
“06/08/2008 17:09:43.139″,”40.904931”
“06/08/2008 17:09:44.186″,”38.230946”
“06/08/2008 17:09:45.217″,”39.839515”
“06/08/2008 17:09:46.233″,”36.918636”
“06/08/2008 17:09:47.233″,”46.089955”
“06/08/2008 17:09:48.280″,”41.786947”
“06/08/2008 17:09:49.280″,”27.338635”
“06/08/2008 17:09:50.280″,”38.276905”
“06/08/2008 17:09:51.279″,”39.839515”
“06/08/2008 17:09:52.279″,”32.807770”
“06/08/2008 17:09:53.295″,”31.533642”
“06/08/2008 17:09:54.295″,”41.402125”
“06/08/2008 17:09:55.342″,”49.250159”
“06/08/2008 17:09:56.342″,”34.610781”
“06/08/2008 17:09:57.388″,”39.389672”
“06/08/2008 17:09:58.388″,”32.807770”
“06/08/2008 17:09:59.420″,”41.662560”
“06/08/2008 17:10:00.435″,”42.533268”
“06/08/2008 17:10:01.497″,”39.389672”
“06/08/2008 17:10:02.513″,”31.533642”
“06/08/2008 17:10:03.513″,”32.571011”
“06/08/2008 17:10:04.575″,”40.904931”
“06/08/2008 17:10:05.575″,”32.807770”
“06/08/2008 17:10:06.575″,”32.026465”
“06/08/2008 17:10:07.575″,”9.368620”
“06/08/2008 17:10:08.575″,”27.338635”
“06/08/2008 17:10:09.591″,”37.687921”
“06/08/2008 17:10:10.637″,”41.786947”
“06/08/2008 17:10:11.653″,”39.995776”
“06/08/2008 17:10:12.684″,”46.965963”
“06/08/2008 17:10:13.731″,”58.820630”
“06/08/2008 17:10:14.762″,”39.995776”
“06/08/2008 17:10:15.778″,”39.547983”
“06/08/2008 17:10:16.840″,”40.147302”
“06/08/2008 17:10:17.871″,”37.495600”

Plugged into Excel, these are the stats for those 35 data points

Idle

• Min: 0
• Max: 2.336875
• Avg: 0.332834
• Median: 0
• Skew: 2.156378
• Variance: 0.401792

AdFind

• Min: 0.774265
• Max: 15.61906
• Avg: 7.75793
• Median: 8.587315
• Skew: 0.05928
• Variance: 15.36671

PoS

• Min: 27.33864
• Max: 46.08996
• Avg: 36.14655
• Median: 35.81638
• Skew: 0.157006
• Variance: 21.74553

 

4. Network Utilization

After running a couple of tests and going out and working in the yard for a bit I thought… hmmm With the results I saw, I bet the network utilization numbers are off too between AdFind and the script… Sure enough.

 

Figure 4 is idle use

                                                     [Figure 4]

 

Figure 5 is AdFind use

                                                     [Figure 5]

 

Figure 6 is the PoS Script.

                                                     [Figure 6]

 

Note the percentage range on the graphs… The AdFind graph has a range of 0-25% and the PoS graph has a range of 0-5%…

 

Again with some typeperf stats… 35 data points for each state again….

 

This is when idling…

“(PDH-CSV 4.0)”,”\\SFMXP32\network interface(Realtek RTL8168_8111 PCI-E Gigabit Ethernet NIC – Packet Scheduler Miniport)\Bytes Total/sec”

06/08/2008 20:21:15.101,”0.000000″
06/08/2008 20:21:16.101,”0.000000″
06/08/2008 20:21:17.101,”0.000000″
06/08/2008 20:21:18.101,”0.000000″
06/08/2008 20:21:19.101,”0.000000″
06/08/2008 20:21:20.116,”0.000000″
06/08/2008 20:21:21.116,”0.000000″
06/08/2008 20:21:22.116,”0.000000″
06/08/2008 20:21:23.116,”0.000000″
06/08/2008 20:21:24.116,”0.000000″
06/08/2008 20:21:25.116,”0.000000″
06/08/2008 20:21:26.132,”0.000000″
06/08/2008 20:21:27.132,”0.000000″
06/08/2008 20:21:28.132,”0.000000″
06/08/2008 20:21:29.132,”0.000000″
06/08/2008 20:21:30.132,”0.000000″
06/08/2008 20:21:31.132,”0.000000″
06/08/2008 20:21:32.132,”0.000000″
06/08/2008 20:21:33.132,”0.000000″
06/08/2008 20:21:34.147,”0.000000″
06/08/2008 20:21:35.147,”0.000000″
06/08/2008 20:21:36.147,”0.000000″
06/08/2008 20:21:37.147,”0.000000″
06/08/2008 20:21:38.147,”409.193170″
06/08/2008 20:21:39.147,”0.000000″
06/08/2008 20:21:40.147,”0.000000″
06/08/2008 20:21:41.147,”0.000000″
06/08/2008 20:21:42.163,”0.000000″
06/08/2008 20:21:43.163,”0.000000″
06/08/2008 20:21:44.163,”0.000000″
06/08/2008 20:21:45.163,”0.000000″
06/08/2008 20:21:46.163,”0.000000″
06/08/2008 20:21:47.163,”0.000000″
06/08/2008 20:21:48.163,”0.000000″
06/08/2008 20:21:49.163,”0.000000″

 

AdFind query…

“(PDH-CSV 4.0)”,”\\SFMXP32\network interface(Realtek RTL8168_8111 PCI-E Gigabit Ethernet NIC – Packet Scheduler Miniport)\Bytes Total/sec”

06/08/2008 20:22:48.303,”432.148631″
06/08/2008 20:22:49.303,”7812.669507″
06/08/2008 20:22:50.319,”215500.866875″
06/08/2008 20:22:51.319,”675597.824476″
06/08/2008 20:22:52.319,”210349.356274″
06/08/2008 20:22:53.319,”1266930.446812″
06/08/2008 20:22:54.319,”1416464.689079″
06/08/2008 20:22:55.319,”1558286.015944″
06/08/2008 20:22:56.319,”425118.163681″
06/08/2008 20:22:57.334,”1344444.782983″
06/08/2008 20:22:58.334,”1137181.434605″
06/08/2008 20:22:59.334,”1597069.087841″
06/08/2008 20:23:00.334,”1312058.658551″
06/08/2008 20:23:01.334,”1530619.724371″
06/08/2008 20:23:02.334,”1676687.003461″
06/08/2008 20:23:03.334,”1603403.974700″
06/08/2008 20:23:04.334,”1676201.171529″
06/08/2008 20:23:05.350,”1755335.554489″
06/08/2008 20:23:06.350,”1815894.653956″
06/08/2008 20:23:07.350,”1748979.095744″
06/08/2008 20:23:08.350,”1457658.560362″
06/08/2008 20:23:09.350,”1749027.180590″
06/08/2008 20:23:10.350,”1748969.577365″
06/08/2008 20:23:11.350,”1602738.860017″
06/08/2008 20:23:12.350,”1880224.306196″
06/08/2008 20:23:13.366,”1543784.545800″
06/08/2008 20:23:14.366,”1528733.402130″
06/08/2008 20:23:15.366,”1748985.669767″
06/08/2008 20:23:16.365,”1675179.234176″
06/08/2008 20:23:17.365,”1750306.711728″
06/08/2008 20:23:18.365,”1374845.844406″
06/08/2008 20:23:19.365,”1975074.793721″
06/08/2008 20:23:20.381,”1457283.676124″
06/08/2008 20:23:21.381,”1603445.281594″
06/08/2008 20:23:22.381,”1674138.066714″

 

And PoS script

“(PDH-CSV 4.0)”,”\\SFMXP32\network interface(Realtek RTL8168_8111 PCI-E Gigabit Ethernet NIC – Packet Scheduler Miniport)\Bytes Total/sec”

06/08/2008 20:24:23.537,”95271.394985″
06/08/2008 20:24:24.537,”152096.806819″
06/08/2008 20:24:25.537,”304867.276069″
06/08/2008 20:24:26.537,”229631.839613″
06/08/2008 20:24:27.537,”76356.320892″
06/08/2008 20:24:28.553,”282718.881348″
06/08/2008 20:24:29.553,”212996.840599″
06/08/2008 20:24:30.553,”428616.679015″
06/08/2008 20:24:31.553,”288234.300414″
06/08/2008 20:24:32.553,”288276.315703″
06/08/2008 20:24:33.553,”287835.901916″
06/08/2008 20:24:34.568,”144267.514096″
06/08/2008 20:24:35.568,”288038.282918″
06/08/2008 20:24:36.568,”287903.691420″
06/08/2008 20:24:37.568,”215894.243299″
06/08/2008 20:24:38.568,”288022.088767″
06/08/2008 20:24:39.584,”287852.416168″
06/08/2008 20:24:40.584,”287907.460559″
06/08/2008 20:24:41.584,”287867.971897″
06/08/2008 20:24:42.584,”216662.763604″
06/08/2008 20:24:43.584,”359322.953951″
06/08/2008 20:24:44.584,”216204.281269″
06/08/2008 20:24:45.599,”287921.254846″
06/08/2008 20:24:46.599,”216670.797928″
06/08/2008 20:24:47.599,”431409.468785″
06/08/2008 20:24:48.599,”216048.609884″
06/08/2008 20:24:49.599,”360909.160668″
06/08/2008 20:24:50.599,”359313.537159″
06/08/2008 20:24:51.599,”216058.961104″
06/08/2008 20:24:52.615,”287855.543216″
06/08/2008 20:24:53.615,”362659.902837″
06/08/2008 20:24:54.615,”292073.121217″
06/08/2008 20:24:55.615,”292124.653467″
06/08/2008 20:24:56.615,”219204.028101″
06/08/2008 20:24:57.615,”219607.804823″

 

Plugged into Excel, these are the stats for those 35 data points

Idle

• Min: 0
• Max: 409.19317
• Avg: 11.691233
• Median: 0
• Skew: 5.9160798
• Variance: 4783.9729

AdFind

• Min: 432.15
• Max: 1,975,074.79  (1.88 MB/s)
• Avg: 1,364,136.09 (1.30 MB/s)
• Median: 1,558,286.02 (1.49 MB/s)
• Skew: -1.55
• Variance: 301,963,579,984.33

PoS

• Min: 76,356.32
• Max: 431,409.47 (.41 MB/s)
• Avg: 265,391.52 (.25 MB/s)
• Median: 287,855.54 (.27 MB/s)
• Skew: -0.21
• Variance: 6,301,469,856.37

 

Average of 1.3 MB per second versus .25  MB per second… AdFind is pulling the data 5 times faster… This absolutely does not support what Brandon saw in his tests which makes me question what is different or is the PoS timing script he is using that bad? Both tools have to pull the same amount of data to get object counts, there are no shortcuts… If AdFind pulls the data 5 times faster, it has the potential to be at least 5 times faster at execution.

 

5. Umm there is a problem in the PoS Script… It doesn’t seen to know how to count correctly.

Here is what AdFind says the count is… 711387

Here is what the script says the count is… 711145

Looking at the script I am pretty sure I know what is wrong but will let Brandon sort it out.  Good learning exercise… 😉

 

6. The PoS doesn’t seem so fast in relation to AdFind…  (at least to me)

So here are the results of the actual tests…

First the two count run…

 

2008-06-08 20:52:45
PS>
2008-06-08 20:52:46
PS>
2008-06-08 20:52:46
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 20:53:19
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 20:54:01
PS>
2008-06-08 20:54:01
PS>
2008-06-08 20:54:01
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 20:57:22
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:00:48
PS>
2008-06-08 21:00:48
PS>
2008-06-08 21:00:48
PS>

Here are the numbers

AdFind

1. 20:52:46 – 20:53:19  = 33 seconds
2. 20:53:19 – 20:54:01 = 42 seconds

 

PoS

1. 20:54:01 – 20:57:22 = 201 seconds (3 minutes 21 seconds)
2. 20:57:22 – 21:00:48 = 206 seconds (3 minutes 26 seconds)

 

This is showing AdFind is roughly 4.5-6.25 times faster than the PoS script which is what the network traffic implied.

 

So let’s look at the 10 count test and see if we have consistency…

 

2008-06-08 21:01:27
PS>
2008-06-08 21:02:08
PS>
2008-06-08 21:02:08
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:02:49
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:03:36
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:04:22
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:05:06
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:05:52
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:06:38
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:07:25
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:08:13
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:09:02
PS>adfind -default -f objectclass=* -c

AdFind V01.37.00cpp Joe Richards (joe@joeware.net) June 2007

Using server: TEST-DC1.test.loc:389
Directory: Windows Server 2003
Base DN: DC=test,DC=loc

711387 Objects returned
2008-06-08 21:09:47
PS>
2008-06-08 21:09:47
PS>
2008-06-08 21:09:47
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:13:17
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:16:47
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:20:14
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:23:49
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:27:18
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:30:45
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:34:14
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:37:50
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:41:22
PS>.\Test-DSProtocalsSP.ps1
711145
2008-06-08 21:45:22
PS>
2008-06-08 21:45:22
PS>
2008-06-08 21:45:22
PS>

 

Here are the numbers

 

AdFind

1. 21:02:08 – 21:02:49 = 41 seconds
2. 21:02:49 – 21:03:36 = 47 seconds
3. 21:03:36 – 21:04:22 = 46 seconds
4. 21:04:22 – 21:05:06 = 44 seconds
5. 21:05:06 – 21:05:52 = 46 seconds
6. 21:05:52 – 21:06:38 = 46 seconds
7. 21:06:38 – 21:07:25 = 47 seconds
8. 21:07:25 – 21:08:13 = 48 seconds
9. 21:08:13 – 21:09:02 = 49 seconds
10. 21:09:02 – 21:09:47 = 45 seconds

 

PoS

1. 21:09:47 – 21:13:17 = 210 seconds (3 minutes 30 seconds)
2. 21:13:17 – 21:16:47 = 210 seconds (3 minutes 30 seconds)
3. 21:16:47 – 21:20:14 = 207 seconds (3 minutes 27 seconds)
4. 21:20:14 – 21:23:49 = 215 seconds (3 minutes 35 seconds)
5. 21:23:49 – 21:27:18 = 209 seconds (3 minutes 29 seconds)
6. 21:27:18 – 21:30:45 = 207 seconds (3 minutes 27 seconds)
7. 21:30:45 – 21:34:14 = 209 seconds (3 minutes 29 seconds)
8. 21:34:14 – 21:37:50 = 216 seconds (3 minutes 36 seconds)
9. 21:37:50 – 21:41:22 = 212 seconds (3 minutes 32 seconds)
10. 21:41:22 – 21:45:22 = 240 seconds (4 minutes 0 seconds)

 

After seeing those numbers I thought wow and then tried it all again but flipped it around and had PoS run first and then AdFind. In summary the PoS stuff started at 22:51:49 and finished at 23:30:22, that is 37 minutes and 33 seconds or 2253 seconds or an average of 225.3 seconds for 10 runs (compared to 21:09:47 to 21:45:22 which is 35 minutes and 35 seconds or 2135 seconds or an average of 213.5 seconds for 10 runs). The AdFind stuff started at 23:30:22 and finished at 23:37:59, that is 7 minutes 37 seconds or 457 seconds or an average of 45.7 seconds for 10 runs (compared to 21:02:08 to 21:09:47 which is 7 minutes 39 seconds or 459 seconds or an average of 45.9 seconds for 10 runs). So we are seeing that AdFind is between 4.22 and 5.85 times faster than PoS.

 

I consider those numbers to be very consistent as well as very telling. I can’t for the life of me explain why Brandon and my numbers are so dramatically different other than maybe trying to use a PoS script to measure the perf of AdFind and the other PoS Script may not be the optimal test framework and is maybe introducing some other errors? Alternately maybe he has some special tuning for .NET stuff? That shouldn’t be needed, but I know I don’t have any special tunings, my machine has whatever the .NET stuff loads as is and PowerShell loaded on top. I guess possibly he changed the script and didn’t post the latest version to his blog… I don’t know. I just know where he was seeing seconds of difference, I see no way of that occurring.

 

Thoughts?

 

    joe

 

 

[1] I think it sort of went like this… He maybe got tired of hearing about PowerShell being fat and slow (ditto .NET) so set out to prove that it could be as performant or maybe close to as performant as native code. I am just guessing based on my knowledge of Brandon and what he has written on this testing. I know Brandon sometimes likes to fight for the sake of fighting[2]… not a problem, I am fine with that. I debated with him in person for several days at the last MVP summit.

[2] Yes you really do Brandon.

[3] FWIW, I think most folks are just going to up and assume .NET and PoS are going to be slower and accept it for what it is; people don’t use those technologies because they want raw run performance, they want ease of getting to what they want to get to[4].

[4] I am, despite what some may think, ok with that. In fact, I often tell people who are starting out now in DS programming to look at the .NET stuff instead of the native stuff[5] because quite honestly with the exception of true professional programmers I think the raw LDAP and native code stuff might be a bit much for many of the computer people of today… However, this doesn’t mean I am looking at using it. I am already spun up on the native and raw LDAP stuff.

[5] Using the .NET Framework will be easier to spin up and go for most of the folks in the field today who aren’t already seasoned programmers (with real language backgrounds… this IMO excludes VB from discussion); especially admins.  However, I don’t want them writing any serious app that is doing a ton of work that I will be dependent on using heavily. Using it to get some basic stuff going or stuff that I never have to use I have no problem with.

[6] That is because it means the “next generation” programming mechanisms aren’t going to make us all upgrade our hardware yet again… How does it go… Something like…  Intel Giveth us Speed, Microsoft takes it away… In all honesty, I don’t expect to see .NET being truly performant to any well written native code standards until it is embedded in the core and absolutely HAS to be performant. Note the key use of “well written”. Just because someone writes in native code, doesn’t mean they write well and for those people that don’t write well, they likely will do better writing in .NET. So anyway, I want to see .NET and PoS work well and efficiently because it will likely be heavily used and I would rather people not be running a bunch of slow crap out there as I may end up dealing with it one way or another.

[7] We are slowly moving out from the intricacies of the hardware abstracting more and more. It is a curve where on the far left we have the binary machine language which is all 0’s and 1’s and as you move towards the right you get to more and more complexity and robustness and hopefully ease of use. But also as you move to the right while you gain the ease of use abstraction, you pay more and more penalty in performance for that abstraction. First step after machine language… Assembler, then Macro Assembler, and then say C and then C++ and FORTRAN and COBOL, etc etc etc… We have moved further and further right in the curve[8] as we “evolve” in our use of computers and as the right becomes more acceptable either by becoming more performant from learning and making things more efficient or we just are more accepting of the trade offs because computers get faster and what ran slow yesterday runs faster today or we just can’t be bothered to worry about the speed period.

[8] The .NET framework is on the far right side of this curve right now and may or may not be what we go to next as the de facto for things that native C++, IMO, is now. I don’t think it has been proven conclusively one way or the other yet. Java has been claiming it is the de facto now for at least 10 years. I still haven’t written a line of Java though back in the late 90’s all my “cool” friends said I would, it was just a matter of time…. “You just wait joe… No one will be writing anything in C++ in 10 years… it will all be Java[9] and CORBA[10]…”

[9] The .NET stuff, at least to me, is Microsoft’s “Java”. Might as well called it MSava (sic) in my mind. 🙂 Anyway now all my .NET friends say the same things to me my Java friends said. Granted, they are more likely to be correct, but not guaranteed to be…

[10] Interestingly, at least to me, is that now right around 10 years later most people in the computer world know of and have heard of Java but say “What the frack is CORBA???”

[11] I can’t take the credit for .FAT, but I like it just the same. 🙂