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. 🙂

A lot of times when people run into issues with LDAP based apps, one of the troubleshooting steps I recommend is to do a network trace and look at the LDAP traffic and then I hear… Hey, I try to but it looks like gibberish and WireShark says it can’t be decoded or something… By this I think they mean it looks something like

Lightweight-Directory-Access-Protocol
    BER Error: Sequence expected but Class:0(UNIVERSAL) PC:0 Tag:0 was unexpected

0000  00 50 8d 91 0b d2 00 0c 29 f4 7b 5e 08 00 45 00   .P……).{^..E.
0010  05 dc 07 ab 40 00 80 06 6b 2e c0 a8 00 78 c0 a8   ….@…k….x..
0020  00 7a 01 85 04 6c e4 78 1a 2e 35 8f ea 5b 50 10   .z…l.x..5..[P.
0030  f7 5d 83 2f 00 00 00 00 0a 9d 01 00 00 00 f5 18   .]./…………
0040  cf 41 7a b3 3f da 01 00 00 00 11 de f4 b8 eb 4c   .Az.?……….L
0050  28 e8 b2 c3 e0 69 20 28 f6 b0 90 1b ec b8 05 4f   (….i (…….O
0060  80 bb 82 75 af a7 26 68 e6 d5 35 2b 56 04 ba 11   …u..&h..5+V…
0070  30 16 00 fe 8d 16 85 e7 da 62 97 d5 86 f9 bb 59   0……..b…..Y
0080  00 d7 59 60 12 36 fe b6 b5 82 bb 2b ec cf 3b 6a   ..Y`.6…..+..;j
0090  42 6b 6b dd d3 a3 e4 63 42 8a 0b ae d1 bc 5a 40   Bkk….cB…..Z@
00a0  46 de 1e 78 01 bc c1 ad ec 36 80 db cc eb c2 f9   F..x…..6……
00b0  ba 85 83 a8 f5 22 bf cc 7b 97 29 9e e0 18 b2 fc   …..”..{.)…..
00c0  c2 bd 01 2a a6 83 33 55 a3 57 e1 21 65 4d f9 08   …*..3U.W.!eM..
00d0  8d ff dc 25 0e 3d 93 cc 4c 34 4c 1f f1 17 39 be   …%.=..L4L…9.
00e0  78 39 42 90 0c 23 65 3d 3b 29 5f 95 c0 d7 cf 2c   x9B..#e=;)_….,
00f0  ae a5 0c 12 94 bc 41 bb 2e f1 33 05 2c 95 20 94   ……A…3.,. .
0100  3c 1f d6 32 9f 73 8b df 4c dc fe 5b cd 2a ac 3a   <..2.s..L..[.*.:

instead of something like

Lightweight-Directory-Access-Protocol
    LDAPMessage searchRequest(7) “DC=test,DC=loc” baseObject
        messageID: 7
        protocolOp: searchRequest (3)
            searchRequest
                baseObject: DC=test,DC=loc
                scope: baseObject (0)
                derefAliases: neverDerefAliases (0)
                sizeLimit: 0
                timeLimit: 120
                typesOnly: False
                Filter: (objectclass=*)
                    present: objectclass
                attributes: 1 item
                    Item: ntsecuritydescriptor
        [Response In: 72]
        controls: 2 items
            Item LDAP_SERVER_SD_FLAGS_OID
                controlType: 1.2.840.113556.1.4.801 (LDAP_SERVER_SD_FLAGS_OID)
                criticality: True
                controlValue: 308400000003020107
            Item LDAP_PAGED_RESULT_OID_STRING
                controlType: 1.2.840.113556.1.4.319 (LDAP_PAGED_RESULT_OID_STRING)
                criticality: True
                controlValue: 308400000006020203E80400

0000  00 a0 c9 ce b2 7b 00 50 8d 91 0b d2 08 00 45 00   …..{.P……E.
0010  00 e0 7a a7 40 00 80 06 fd 9b c0 a8 00 7a c0 a8   ..z.@……..z..
0020  00 0a 0b 74 01 85 f2 eb 1b 1d c0 25 e9 57 50 18   …t…….%.WP.
0030  f6 2e 82 a7 00 00 30 84 00 00 00 b2 02 01 07 63   ……0……..c
0040  84 00 00 00 48 04 0e 44 43 3d 74 65 73 74 2c 44   ….H..DC=test,D
0050  43 3d 6c 6f 63 0a 01 00 0a 01 00 02 01 00 02 01   C=loc………..
0060  78 01 01 00 87 0b 6f 62 6a 65 63 74 63 6c 61 73   x…..objectclas
0070  73 30 84 00 00 00 16 04 14 6e 74 73 65 63 75 72   s0…….ntsecur
0080  69 74 79 64 65 73 63 72 69 70 74 6f 72 a0 84 00   itydescriptor…
0090  00 00 5b 30 84 00 00 00 26 04 16 31 2e 32 2e 38   ..[0….&..1.2.8
00a0  34 30 2e 31 31 33 35 35 36 2e 31 2e 34 2e 38 30   40.113556.1.4.80
00b0  31 01 01 ff 04 09 30 84 00 00 00 03 02 01 07 30   1…..0……..0
00c0  84 00 00 00 29 04 16 31 2e 32 2e 38 34 30 2e 31   ….)..1.2.840.1
00d0  31 33 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff   13556.1.4.319…
00e0  04 0c 30 84 00 00 00 06 02 02 03 e8 04 00         ..0………..

The second snippet clearly shows an LDAP query of

• Base DN: DC=test,DC=loc
• Scope: Base
• Filter: objectclass=*
• Return the attribute nTSecurityDescriptor…

The second is very clear and easy to understand. The first… Well not so easy.

This first capture looks the way it does due to a thing called LDAP Client Signing or LDAP Integrity. It “sort of” secures the data passing across LDAP. I say sort of because there are a few ways to get around it.

The first way around is to use the sysinternals tool called Insight for Active Directory. You can get that here… http://technet.microsoft.com/en-us/sysinternals/bb897539.aspx 

This is a pretty cool tool, can be very handy. You used to have to pay for it. But now you don’t. 🙂

 

The second way around is to disable the Client Signing. The current Client Signing setting is maintained in the registry (of course) in the key

hklm\system\currentcontrolset\services\ldap under the value ldapclientintegrity. There are three possible values

0	No signing/sealing
1	Negotiate signing/sealing
2	Require signing/sealing

You will likely see it set to 1 if it is set to anything. If it isn’t set, the default internally is 1 anyway… So if you switch this to 0, you will *generally* start seeing the LDAP traffic in the clear. If not, the issue could very well be that the application is forcing the information to be “encrypted” anyway like the AdFind -kerbenc switch does. At that point you have no choice but to use Insight for AD which hooks the LDAP calls prior to being encoded.

This can also be set through Group Policy so you may find that you set it to 0 and then later it goes back to 1 or even possibly 2. If that happens a GPO was configured to define a value for Computer Configuration | Windows Settings | Security Settings | Local Policies | Security Options | Network Security: LDAP client signing requirements.

     joe

So I uninstalled Microsoft Expressions Web 1 and installed Microsoft Expressions Web 2 on my main workstation (SFMFXP32) this weekend. Then a familiar problem popped up which kind of ticks me off as I bugged this with Microsoft quite some time before and I know people have been complaining about it since at least 2006. The Outlook 2003[1] Junkmail Filter stopped working.

Thankfully the same fix I found before worked again…

Go into control panel, add/remove programs, tick Show Updates, go down to Microsoft Office Professional Edition 2003, click on Update for Outlook 2003: Junk E-Mail Filter (KBxxxxxx):OUTFLTR, Click on Remove.

Then go to Microsoft Update and click Custom and install the Outlook Junk Mail Filter Update. After the installation is done, restart Outlook. Junk Mail filter should be working again.

  joe

 

[1] Yes yes I haven’t upgraded to O2K7 on this machine yet. I planned on doing it when I upgrade it to Vista which also hasn’t happened as it will be a good amount of work. I do run Vista and O2K7 on my main laptop though.