Tuesday, September 2, 2008

Sysinternals AD Insight and DSQUERY

Just out of curiosity, I ran the ADInsight utility from Microsoft Sysinternals to see what goes on when you run DSQUERY to fetch information from an LDAP call to Active Directory. If you're not familiar with ADInsight, and you have an Active Directory environment to play with, go download the Sysinternals toolkit and check it out. Basically, it watches communications using LDAP and shows each event as it transpires. As with Process Explorer, Process Monitor, RegMon and the others, you can pause the realtime captures and analyze them more closely.

The command I executed was "DSQUERY COMPUTER" which dumps the LDAP distinguishedName values for every computer in my Active Directory domain. Here's the actual command query and results I got back.

C:\>dsquery computer
"CN=dc1,OU=Domain Controllers,DC=steinfamily,DC=home"
"CN=comp1,OU=Desktops,DC=steinfamily,DC=home"
"CN=comp2,OU=Desktops,DC=steinfamily,DC=home"
"CN=laptop,OU=Desktops,DC=steinfamily,DC=home"
"CN=comp3,CN=Computers,DC=steinfamily,DC=home"

There was a noticable time lag after I hit ENTER before it actually returned the results. But I wanted to know where the lag was occurring. Was it during the connection request, the bind request, the query submission or the results return? It was during the initial LDAP connection request, which is line 9 in the capture results (see below) which paused for 366 milliseconds...

# Timestamp Process:PID Request Type Session Event ID Domain Controller User Input Output Result Duration
1 62.591s dsquery.exe:4508 initialize Sync Session 1 Event 1 OURHOME.home:389 301.186ms
2 62.892s dsquery.exe:4508 get option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_GETDSNAME_FLAGS 71.517us
3 62.892s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_GETDSNAME_FLAGS 34.292us
4 62.892s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_PROMPT_CREDENTIALS 31.638us
5 62.892s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_SIGN 30.870us
6 62.892s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_ENCRYPT 30.870us
7 62.892s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_PROTOCOL_VERSION 33.803us
8 62.892s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home LDAP_OPT_HOST_NAME 36.667us
9 62.893s dsquery.exe:4508 connect Sync Session 1 Event 1 OURHOME.home Anonymous User Timeout INFINITE 366.592ms
10 63.259s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home Anonymous User LDAP_OPT_REFERRAL_CALLBACK 28.076us
11 63.259s dsquery.exe:4508 set option Sync Session 1 Event 1 OURHOME.home Anonymous User LDAP_OPT_REFERRALS 20.743us
12 63.259s dsquery.exe:4508 bind Sync Session 1 Event 1 OURHOME.home OURHOME\user100 OURHOME\user100 126.909ms
13 63.386s dsquery.exe:4508 search Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:LDAP_SCOPE_BASE:(objectClass=*) 160.709ms
15 63.547s dsquery.exe:4508 first entry Sync Session 1 Event 2 OURHOME.home OURHOME\user100 0x003badf0 0x003badf0 21.790us
16 63.547s dsquery.exe:4508 first attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 currentTime 25.771us
17 63.547s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:currentTime 09/02/2008 13:58:26 + 0Z 28.495us
19 63.547s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 subschemaSubentry 25.283us
20 63.548s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:subschemaSubentry CN=Aggregate,CN=Schema,CN=Configuration,DC=OURHOME,DC=home 27.029us
22 63.548s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 dsServiceName 27.797us
23 63.548s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:dsServiceName CN=NTDS Settings,CN=DC1,CN=Servers,CN=Default-First-Site-Name,CN=Sites,CN=Configuration,DC=OURHOME,DC=home 28.006us
25 63.548s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 namingContexts 26.330us 26 63.548s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:namingContexts DC=OURHOME,DC=home 42.603us
28 63.548s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 defaultNamingContext 25.981us
29 63.548s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:defaultNamingContext DC=OURHOME,DC=home 26.260us
31 63.548s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 schemaNamingContext 24.235us
32 63.548s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:schemaNamingContext CN=Schema,CN=Configuration,DC=OURHOME,DC=home 30.660us
34 63.548s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 configurationNamingContext 28.356us 35 63.548s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:configurationNamingContext CN=Configuration,DC=OURHOME,DC=home 25.283us
37 63.549s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 rootDomainNamingContext 24.794us
38 63.549s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE: rootDomainNamingContext DC=OURHOME,DC=home 25.632us
40 63.549s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 supportedControl 24.375us
41 63.549s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:supportedControl 1.2.840.113556.1.4.319 63.556us
43 63.549s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 supportedLDAPVersion 24.305us
44 63.549s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:supportedLDAPVersion 3 25.981us
46 63.549s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 supportedLDAPPolicies 24.724us 47 63.549s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:supportedLDAPPolicies MaxPoolThreads 35.829us
49 63.549s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 highestCommittedUSN 29.263us
50 63.549s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:highestCommittedUSN 74539 35.549us
52 63.549s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 supportedSASLMechanisms 29.263us
53 63.549s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:supportedSASLMechanisms GSSAPI 32.197us
55 63.550s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 dnsHostName 28.914us
56 63.550s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:dnsHostName dc1.OURHOME.home 29.962us
58 63.550s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 ldapServiceName 28.565us
59 63.550s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:ldapServiceName OURHOME.home:DC1$@OURHOME.HOME 36.178us
61 63.550s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 serverName 27.937us
62 63.550s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:serverName CN=DC1,CN=Servers,CN=Default-First-Site-Name,CN=Sites,CN=Configuration,DC=OURHOME,DC=home 29.613us
64 63.550s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 supportedCapabilities 28.076us 65 63.550s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:supportedCapabilities 1.2.840.113556.1.4.800 31.917us
67 63.550s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 isSynchronized 26.610us
68 63.550s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:isSynchronized TRUE 33.733us 70 63.551s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 isGlobalCatalogReady 26.749us
71 63.551s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:isGlobalCatalogReady TRUE 27.657us
73 63.551s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 domainFunctionality 26.959us
74 63.551s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:domainFunctionality 3 34.292us
76 63.551s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 forestFunctionality 25.422us
77 63.551s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:forestFunctionality 3 31.429us
79 63.551s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 domainControllerFunctionality 25.702us
80 63.551s dsquery.exe:4508 get values Sync Session 1 Event 2 OURHOME.home OURHOME\user100 RootDSE:domainControllerFunctionality 3 26.679us
82 63.551s dsquery.exe:4508 next attribute Sync Session 1 Event 2 OURHOME.home OURHOME\user100 No more attributes 24.095us
83 63.552s dsquery.exe:4508 search Sync Session 1 Event 3 OURHOME.home OURHOME\user100 OURHOME.home\Configuration:LDAP_SCOPE_BASE:(objectClass=*) 1.107ms
84 63.553s dsquery.exe:4508 first entry Sync Session 1 Event 3 OURHOME.home OURHOME\user100 0x003bae70 0x003bae70 35.898us
85 63.553s dsquery.exe:4508 get values Sync Session 1 Event 3 OURHOME.home OURHOME\user100 OURHOME.home\Configuration:objectClass top 42.952us
87 63.558s dsquery.exe:4508 search Sync Session 1 Event 4 OURHOME.home OURHOME\user100 OURHOME.home\Configuration:LDAP_SCOPE_BASE:(objectClass=*) 1.669ms
88 63.560s dsquery.exe:4508 first entry Sync Session 1 Event 4 OURHOME.home OURHOME\user100 0x003badf0 0x003badf0 27.517us
89 63.560s dsquery.exe:4508 get option Sync Session 1 Event 1 OURHOME.home OURHOME\user100 LDAP_OPT_HOST_NAME 23.187us
90 73.560s dsquery.exe:4508 initialize Sync Session 2 Event 5 dc1.OURHOME.home:389 198.698us
91 73.561s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_GETDSNAME_FLAGS 133.117us
92 73.561s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_GETDSNAME_FLAGS 21.022us
93 73.561s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_PROMPT_CREDENTIALS 20.254us
94 73.561s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_SIGN 25.003us
95 73.561s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_ENCRYPT 29.403us
96 73.561s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_PROTOCOL_VERSION 21.232us
97 73.561s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home LDAP_OPT_AREC_EXCLUSIVE 21.581us
98 73.561s dsquery.exe:4508 connect Sync Session 2 Event 5 dc1.OURHOME.home Anonymous User Timeout INFINITE 2.476ms 99 73.564s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home Anonymous User LDAP_OPT_REFERRAL_CALLBACK 39.321us 100 73.564s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home Anonymous User LDAP_OPT_REFERRALS 31.010us 101 73.564s dsquery.exe:4508 bind Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 OURHOME\user100 3.825ms 102 73.568s dsquery.exe:4508 search Sync Session 2 Event 6 dc1.OURHOME.home OURHOME\user100 OURHOME.home:LDAP_SCOPE_BASE:(objectClass=*) 5.063ms
103 73.573s dsquery.exe:4508 first entry Sync Session 2 Event 6 dc1.OURHOME.home OURHOME\user100 0x003bb630 0x003bb630 42.044us 104 73.573s dsquery.exe:4508 get values Sync Session 2 Event 6 dc1.OURHOME.home OURHOME\user100 OURHOME.home:objectClass top 49.168us 1
06 73.574s dsquery.exe:4508 search Sync Session 2 Event 7 dc1.OURHOME.home OURHOME\user100 RootDSE:LDAP_SCOPE_BASE:(objectClass=*) 2.757ms 107 73.577s dsquery.exe:4508 first entry Sync Session 2 Event 7 dc1.OURHOME.home OURHOME\user100 0x003bb630 0x003bb630 43.022us
108 73.577s dsquery.exe:4508 get values Sync Session 2 Event 7 dc1.OURHOME.home OURHOME\user100 RootDSE:subschemaSubentry CN=Aggregate,CN=Schema,CN=Configuration,DC=OURHOME,DC=home 50.914us
110 73.577s dsquery.exe:4508 get values Sync Session 2 Event 7 dc1.OURHOME.home OURHOME\user100 RootDSE:supportedControl 1.2.840.113556.1.4.319 70.749us
112 73.577s dsquery.exe:4508 get values Sync Session 2 Event 7 dc1.OURHOME.home OURHOME\user100 RootDSE:supportedCapabilities 1.2.840.113556.1.4.800 54.057us
114 73.587s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 33.175us
115 73.587s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 29.054us
116 73.587s dsquery.exe:4508 init search page Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 OURHOME.home:LDAP_SCOPE_SUBTREE:(&(objectCategory=Computer)) 46.375us
117 73.587s dsquery.exe:4508 get next page Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 Timeout: INFINITE; Limit to 50 entries/page Est. result set count = 0 85.781ms
118 73.673s dsquery.exe:4508 first entry Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003bab70 0x003bab70 36.806us
119 73.673s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 27.168us
120 73.673s dsquery.exe:4508 search Sync Session 2 Event 9 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Configuration\Schema\Aggregate:LDAP_SCOPE_BASE:objectClass=* 3.141ms
121 73.676s dsquery.exe:4508 first entry Sync Session 2 Event 9 dc1.OURHOME.home OURHOME\user100 0x003baa70 0x003baa70 49.657us
122 73.676s dsquery.exe:4508 get values Sync Session 2 Event 9 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Configuration\Schema\Aggregate:modifyTimeStamp 08/16/2008 14:52:40 + 0Z 41.206us
124 73.850s dsquery.exe:4508 get values Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Domain Controllers\DC1:distinguishedName CN=DC1,OU=Domain Controllers,DC=OURHOME,DC=home 133.467us
126 73.854s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 92.121us 127 73.854s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 33.105us 128 73.854s dsquery.exe:4508 next entry Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003bab70 0x003baa30 33.524us
129 73.854s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 23.816us 130 73.855s dsquery.exe:4508 get values Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Desktops\comp1:distinguishedName CN=comp1,OU=Desktops,DC=OURHOME,DC=home 40.927us 132 73.856s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 87.022us
133 73.856s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 76.127us 134 73.857s dsquery.exe:4508 next entry Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003baa30 0x003ba9f0 25.352us
135 73.857s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 21.371us 136 73.857s dsquery.exe:4508 get values Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Desktops\comp2:distinguishedName CN=comp2,OU=Desktops,DC=OURHOME,DC=home 35.619us 138 73.858s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 75.010us
139 73.859s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 22.908us
140 73.859s dsquery.exe:4508 next entry Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003ba9f0 0x003ba9b0 22.070us
141 73.859s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 21.651us
142 73.859s dsquery.exe:4508 get values Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Desktops\laptop:distinguishedName CN=laptop,OU=Desktops,DC=OURHOME,DC=home 36.737us
144 73.860s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 88.629us
145 73.860s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 42.184us
146 73.860s dsquery.exe:4508 next entry Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003ba9b0 0x003ba830 44.698us
147 73.861s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 30.870us
148 73.861s dsquery.exe:4508 get values Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 OURHOME.home\Computers\comp3:distinguishedName CN=comp3,CN=Computers,DC=OURHOME,DC=home 39.670us 150 73.863s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 97.708us
151 73.863s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 30.870us
152 73.863s dsquery.exe:4508 next entry Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003ba830 No more entries 35.200us
153 73.863s dsquery.exe:4508 get next page Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 Timeout: INFINITE; Limit to 50 entries/page NO_RESULTS_RETURNED NO_RESULTS_RETURNED 32.895us
154 73.863s dsquery.exe:4508 get option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_SERVER_ERROR 33.175us
155 73.863s dsquery.exe:4508 set option Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 LDAP_OPT_REFERRALS 33.803us
156 73.863s dsquery.exe:4508 abandon search page Sync Session 2 Event 8 dc1.OURHOME.home OURHOME\user100 0x003b7ec8 41.346us
157 73.863s dsquery.exe:4508 unbind Sync Session 2 Event 5 dc1.OURHOME.home OURHOME\user100 Session 0x003ce424 549.791us
158 73.864s dsquery.exe:4508 unbind Sync Session 1 Event 1 OURHOME.home OURHOME\user100 Session 0x003b3494 2.556ms

As you can see, for such a seemingly simple request there's a lot going on under the hood. This is very common in any operating system environment actually. If you perform a network capture, or a file access transaction, you will see very similar behaviors. In case you're wondering, I didn't strip out any line items. It actually reports the line numbering in the exact way shown above. Some numbers are skipped and I'm still not 100% as to why, but I suspect it's reporting a subset of events out of a larger collective.

If you went to college for a CE, CS or IS degree, this stuff will bring back painful memories of inspecting things. Much like doing proofs in a Calculus course. Ugh. Makes me want to drink more just thinking about it.

No comments: