Besides the official announcement in Tales from the Edge site about the full supportability of ISA Server in a virtual environment, we now also have an interview with Jim Harrison that explains more about ISA/TMG in a virtual environment and why now is supported.
Check it out the interview here:
http://edge.technet.com/Media/Virtualize-your-ISA-or-Forefront-TMG-servers/
It was winter 2006 when Roberto Farah and I started to develop this project out of MS work hours called Network Monitor Wizard. I was very excited with the robustness of nmcap but also a little concern about how many parameters we have to manually input. Then I brought this simple idea to him to create a wizard for nmcap and we called Network Monitor Wizard. This tool can actually assist you in scenarios like the following ones (for example):
· I would like to capture all packets coming from one specific host and stop the capture when this host sent a packet using the TCP port 85.
· I need to capture all packets DNS and HTTP packet and stop the capture only tomorrow.
· …and more…
I know that you can manually do this using nmcap, but you also know that it will be a long command line. This tool actually build the command line in the screen for you. You can either start the capture using the tool or just copy and paste the command line in an email and send to your friend that is asking for that. If you choose to run the command line from the tool a VBS script is created and you can use it again later if you want.
The beta version that we are making available is completely AS IS with no warranties, but we do want to hear your feedback. If you have any comments, please contact myself or Roberto Farah. In the subject type [Network Monitor Wizard Feedback] and type your question in the message field.
In order to run this tool, you need:
· Microsoft Windows XP, 2003 or Vista;
· Microsoft Network Monitor 3.x;
· Microsoft .Net Framework 2 (or higher);
Feel free to download and test it.
Today two new and very important articles were published in Tales from the Edge Page. The first one is the official statement about virtualization on ISA (TMG) Server that you can access from the link below:
Security Considerations with Forefront Edge Virtual Deployments
The second one is the new supportability statement about installing ISA Server in a Domain Controller, which you can access from the link below:
ISA Server Branch Office Policies Best Practices: ISA Server co-location with a domain controller
These are really good and excited news in Microsoft Firewall world and definitely you should take some time to read it.
Stay tune that we are always looking for new Tales from the Edge J
1. Introduction
Well, I was not planning to have a round two on this subject, but it is just amazing how ISA is blamed by sys admin even before the deep troubleshoot being done. I hear every other week someone saying: my ISA is slow to answer, takes forever to open a page when we are in a rush hour, etc.
We need to demystify that, any affirmation that ISA is causing slow down in the Internet access should be carefully analyzed before this statement being said. This post is about one more complain about Internet being slow and of course ISA was the one that the admin was blaming.
2. Start from the Basics – Yeah, I know
Review the start from the basics session explained in the last post.
3. As usual, everything looks fine when we first look
When everything seems to be okay, the challenge is to concentrate in the details. This particular case all the items were covered fine, including the logging (which was done locally in the TXT file). The footprint of something that could cause the issue was discovered while the issue was happening.
4. Reviewing the Data
Here the first set of data that was capture during the time that the issue was happening:
· Perfmon and Netmon from ISA and DC/DNS
· ISA Data Packager
After look to the netmon trace we could clearly see that during the time that the issue was happening the DNS Server was not answering the queries sent by ISA. You might think: but you should review DNS in the basic review, right? Correct, but when we reviewed during that time it was answering in timely manner. This leads to a conclusion that the DNS Server works and then stops to work for some reason.
Another interesting point was that the DNS.exe process was having a leaking behavior, very similar to the behavior explained in KB830381. The problem was: customer’s DNS.exe process was much newer than that one since he was using Windows Server 2003 SP2.
At least at that point we knew that the issue was not caused by ISA, it was the DNS that was not answering for some reason.
5. Looking closer to the DNS Server
All right, since ISA was kind of out of the game we start to concentrate more in the DNS Server itself and we found out that the server had the following event:
Event ID : 7502
Category : None
Source : DNS
Type : Error
Generated : 8/13/2008 8:52:34 PM
Machine : SRVDNS
Message : The DNS server was unable to service a client request due a shortage of available memory. Close any applications not in use or reboot the computer
to free memory.
Clearly we have an issue here; looking to the perfmon data we found the following suspicious counters (data for the DNS.exe process):
Private Bytes
Minimum: 25MB
Maximum: 2,564MB
Average: 996MB
Virtual Bytes
Minimum: 95MB
Maximum: 3,049MB
Average: 1,586MB
Processor Time
Minimum: 0%
Maximum: 180%
Average: 93%
The user mode dump from the DNS.exe process also showed us the remaining data that helped us to categorize this as a memory leak. Here the relevant data extracted from the DebugDiag Report:
Top 1 functions by allocation count
dns!allocMemory+8f
58 638 allocation(s)
Function details
Function dns!allocMemory+8f
Allocation type Heap allocation(s)
Heap handle 0x007c0000
Allocation Count 58638 allocation(s)
Allocation Size 106,91 MBytes
Leak Probability 100%
6. Resolution
The problem was really caused by the DNS.exe process that was leaking and the issue was fixed applying the post SP2 update for DNS described in KB946565. If your DNS Server is running Windows Server 2003 SP2, make sure to update your DNS.exe process and remember: don’t blame ISA before you are 100% sure that it is ISA that is causing the issue J.
This post is about a support call where customer was complaining that the ISA Server was stop answering requests every five days in average. Of course this is too broad statement and we have to narrow it down with more and more questions. The interrogatory started:
· When you say stop answering requests you are talking about Web Proxy requests?
o Answer: Internet doesn’t work.
· Can you access the server using Remote Desktop?
o Answer: no.
· Can you logon locally in the server?
o Answer: yes.
· Is it slow or doesn’t answer at all?
o Answer: it is extremely slow.
· What you do as workaround?
o Answer: I have to restart the machine.
· Do you gracefully shutdown/restart?
o Answer: no, it is so slow that I can’t click in Start/Shutdown.
That being said, let’s start gathering data.
2. Gathering Data
Since the issue was affecting the server itself and we were entering in hang mode it was necessary to get a full memory dump. To prepare the machine to get a full memory dump we follow KB244139 and also reviewed the main points of KB130536.
3. Analyzing
With the full memory dump in hands we can start to look at the possible root cause for this issue. First thing in this case is to check what locks are held on resources by threads. To do that we need to run the!locks command:
0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks....
Resource @ nt!CmpRegistryLock (0x808ad480) Shared 2 owning threads
Contention Count = 14
Threads: 89a30ca8-01<*> 899ef708-01<*>
Resource @ Ntfs!NtfsData (0xf7053590) Shared 2 owning threads
Contention Count = 1
Threads: 8a398020-01<*> 8a398b40-01<*>
KD: Scanning for held locks.
* ----- hiding other resources since it were hundreds of them ----- *
Resource @ 0x8a045534 Shared 2 owning threads
Contention Count = 1893
NumberOfSharedWaiters = 54
NumberOfExclusiveWaiters = 1
Threads: 89a30ca8-01<*> 8a127020-01<*> 89883ba8-01 89f5eb50-01
8985f020-01 897e3600-01 89ac0ba8-01 89fb9940-01
89834db0-01 8978c380-01 897ed020-01 897559d8-01
88b40bd0-01 898a7590-01 89a3b700-01 8a398b40-01
897c59a8-01 89ffbd48-01 898d4658-01 8983b4c0-01
897c8020-01 89a84168-01 8986d020-01 8a179ba8-01
899fe7a0-01 8a109db0-01 89a19be0-01 89a26c80-01
897c9020-01 88b3e740-01 88b1adb0-01 8a0ca428-01
89727b18-01 8a1d55a0-01 8a0d7db0-01 897ff7c8-01
8a0c0ba0-01 8a0c3b28-01 88aec960-01 88b17020-01
8971f020-01 88b14db0-01 88ae3890-01 88ae0aa0-01
88b0b430-01 88ada840-01 88b052d0-01 88b034d8-01
88ace738-01 88ac9020-01 8a106a20-01 88ac4b60-01
88abb350-01 88ab4db0-01 88aaeca8-01 8a14eb18-01
Threads Waiting On Exclusive Access:
898a2db0
The resource in red is the one that has more contention count (1893). Reviewing the threads 89a30ca8 and 8a127020 we have:
0: kd> !thread 8a127020
THREAD 8a127020 Cid 12d4.172c Teb: 00000000 Win32Thread: 00000000 WAIT: (WrResource) KernelMode Non-Alertable
8a25d110 SynchronizationEvent
8a127098 NotificationTimer
IRP List:
8a1279f0: (0006,01fc) Flags: 00000884 Mdl: 00000000
Not impersonating
DeviceMap e1433fd0
Owning Process 8972f2e0 Image: wepmcoll.exe
Wait Start TickCount 2658502 Ticks: 84 (0:00:00:01.312)
Context Switch Count 2096 LargeStack
UserTime 00:00:00.0015
KernelTime 00:00:00.0015
Win32 Start Address 0x00401846
Start Address 0x77e6b5ff
Stack Init b85ed000 Current b85ec054 Base b85ed000 Limit b85e9000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6
ChildEBP RetAddr Args to Child
b85ec06c 8083e6a2 8a127098 8a127020 8a1270c8 nt!KiSwapContext+0x26
b85ec098 8083f164 8a127020 899bf900 00000000 nt!KiSwapThread+0x284
b85ec0e0 80818613 8a25d110 0000001b 00000000 nt!KeWaitForSingleObject+0x346
b85ec11c 80841266 00000000 e16d8008 88b2dc20 nt!ExpWaitForResource+0xd5
b85ec13c f7038438 899bf900 88b2dc01 b85ec170 nt!ExAcquireResourceExclusiveLite+0x8d
b85ec14c f706a3dc 88b2dc20 e16d8008 88b2dc01 Ntfs!NtfsAcquireResourceExclusive+0x20
b85ec170 f706c59b 88b2dc01 e16d8008 00000000 Ntfs!NtfsAcquireExclusiveFcb+0x42
b85ec19c f70553d9 88b2dc20 e16d8008 00000000 Ntfs!NtfsAcquireFcbWithPaging+0x7f
b85ec1d0 f706b903 88b2dc20 8a045260 e145f948 Ntfs!NtfsFindPrefixHashEntry+0x35c
b85ec320 f706c1e5 88b2dc20 8a1279f0 b85ec360 Ntfs!NtfsCommonCreate+0xaff
b85ec424 8083f9d0 8a045020 8a1279f0 8a1279f0 Ntfs!NtfsFsdCreate+0x17d
b85ec438 f71ef51e b85ec4dc 8a127ba4 8a2bef38 nt!IofCallDriver+0x45
b85ec468 8083f9d0 8a3ab530 8a1279f0 8a127bc8 fltmgr!FltpCreate+0x1aa
b85ec47c ba5f76f1 8a127ba4 8a127bc8 b85ec4dc nt!IofCallDriver+0x45
WARNING: Stack unwind information not available. Following frames may be wrong.
b85ec4a4 ba5fe740 8a3ab530 00000000 b85ec4dc SYMEVENT+0x76f1
b85ec4c0 ba5f7769 b85ec4dc 8082b0b9 ba5f782a SYMEVENT+0xe740
b85ec4fc 8083f9d0 8a1146d0 8a1279f0 8a1279f0 SYMEVENT+0x7769
b85ec510 f71e1b43 00000000 8a1279f0 8a127bc8 nt!IofCallDriver+0x45
b85ec534 f71ef5af b85ec554 89d43620 00000000 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x20b
b85ec570 8083f9d0 89d43620 8a1279f0 8a1279f0 fltmgr!FltpCreate+0x23b
b85ec584 8092e269 b85ec72c 8a34e910 00000000 nt!IofCallDriver+0x45
b85ec66c 80936caa 8a34e928 00000000 88b23cb0 nt!IopParseDevice+0xa35
b85ec6ec 80936aa5 00000000 b85ec72c 00000240 nt!ObpLookupObjectName+0x5a9
b85ec740 80936f27 00000000 00000000 83da0600 nt!ObOpenObjectByName+0xea
b85ec7bc 80936ff8 b85ec8ec 00100080 b85ec89c nt!IopCreateFile+0x447
b85ec818 ba2dec67 b85ec8ec 00100080 b85ec89c nt!IoCreateFile+0xa3
b85ec8bc ba2def24 b85ecdf0 b85e9000 00000007 SPBBCDrv+0x2c67
b85ec8f0 ba2df451 b85ec914 b85ec924 b85ec91c SPBBCDrv+0x2f24
b85ec93c ba2eb6d6 e14e5378 e305bb40 00000000 SPBBCDrv+0x3451
b85ec978 ba2fa603 b85ecaec 00000005 0000000b SPBBCDrv+0xf6d6
b85ec9a8 ba2fa2e8 b85eca74 e352f678 00000000 SPBBCDrv+0x1e603
b85ec9e4 ba2eb335 00000001 b85eca74 e365b6c0 SPBBCDrv+0x1e2e8
b85eca44 ba2ec67e b85ecbb8 005ecb8c 00000001 SPBBCDrv+0xf335
b85ecb08 8083f893 0000005f b85ecb3c e1920e14 SPBBCDrv+0x1067e
ba32df50 ba2f9fe4 ba2e7852 ba2e7870 ba2e7852 nt!ExReleaseResourceLite+0x8c
ba32df54 ba2e7852 ba2e7870 ba2e7852 ba2fa006 SPBBCDrv+0x1dfe4
ba32df58 ba2e7870 ba2e7852 ba2fa006 ba2e7852 SPBBCDrv+0xb852
ba32df5c ba2e7852 ba2fa006 ba2e7852 ba2f9f72 SPBBCDrv+0xb870
ba32df60 ba2fa006 ba2e7852 ba2f9f72 ba2fa05e SPBBCDrv+0xb852
ba32df64 ba2e7852 ba2f9f72 ba2fa05e ba2e787e SPBBCDrv+0x1e006
This thread has an I/O request packet (IRP), let’s see what we have in this IRP using the !irp command:
0: kd> !irp 8a1279f0
Irp is active with 11 stacks 9 is current (= 0x8a127b80)
No Mdl: No System Buffer: Thread 8a127020: Irp stack trace.
cmd flg cl Device File Completion-Context
[ 0, 0] 0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
>[ 0, 0] 1 e0 8a045020 897c27a0 ba5f7640-b85ec490 Success Error Cancel Pending
\FileSystem\Ntfs SYMEVENT
Args: b85ec5b0 01000021 00070000 00000000
[ 0, 0] 1 e0 8a1146d0 897c27a0 f71e0fac-88af0480 Success Error Cancel
\Driver\SymEvent fltmgr!FltpGeneralCompletion
[ 0, 0] 1 0 89d43620 897c27a0 00000000-00000000
\FileSystem\FltMgr
The IRP is pending during a file access (FileSystem\NTFS) for the filter driver SYMEVENT. Let’s see which NTFS object this drive was accessing during the time that the issue was happening:
0: kd> !object 897c27a0
Object: 897c27a0 Type: (8a3be560) File
ObjectHeader: 897c2788
HandleCount: 0 PointerCount: 1
Directory Object: 00000000 Name: \urlcache\dir1.cdat
Great, looks like the Antivirus is scanning the ISA Server cache file. Let’s see the version of the 3rd party drivers that were in the stack:
0: kd> lmvm SYMEVENT
start end module name
ba5f0000 ba612000 SYMEVENT (no symbols)
Loaded symbol image file: SYMEVENT.SYS
Image path: \??\C:\Program Files\Symantec\SYMEVENT.SYS
Image name: SYMEVENT.SYS
Timestamp: Mon Jan 16 14:53:50 2006 (43CC07DE)
CheckSum: 0001A8D7
ImageSize: 00022000
Translations: 0000.04b0 0000.04e0 0409.04b0 0409.04e0
0: kd> lmvm SPBBCDrv
ba2dc000 ba33e000 SPBBCDrv (no symbols)
Loaded symbol image file: SPBBCDrv.sys
Image path: \??\C:\Program Files\Common Files\Symantec Shared\SPBBC\SPBBCDrv.sys
Image name: SPBBCDrv.sys
Timestamp: Mon Feb 06 14:34:12 2006 (43E7B2C4)
CheckSum: 0006C4AB
ImageSize: 00062000
4. Conclusion
This was one of many examples that I see in daily basis when I’m working with customers that have Antivirus installed on ISA Server. Fortunately we published in the Tales from the Edge site the official statement about having Antivirus installed in ISA Server. So, if you really need to have an Antivirus on ISA Server, follow the guidelines of the article Considerations when using antivirus software on ISA Server. This particular issue was fixed after update the Antivirus filter driver and excludes the ISA Server folders from the real time scan.
While many Microsoft Application Servers such as Exchange take full advantage of /3GB switch in boot.ini, ISA Server can be seriously affected if you use this switch on it. Before we discuss what this switch does and how can affect ISA Server I strongly recommend you to read this great post from Windows Performance Team. After read that, we can be in the same page to talk about the side effects on ISA Server.
2. Why this is bad for ISA?
When you add /3GB on boot.ini what you are telling to the Operating System is to use 1GB for Kernel and 3GB for User Mode space. The problem is that the main ISA Server service runs in Kernel Mode (fweng) and limiting this driver to use only 1GB can be very dangerous. Besides when you add this switch you also reduce the memory available for:
• Nonpaged Pool
• Paged Pool
• System Page Table Entries (PTEs)
Considering that ISA Server is the default gateway for many of your networks, during a period of high network activity, the usage of non-paged pool memory may cause the server to stop responding because there will be no more memory available. The reason why is because when you use /3GB the maximum size of the nonpaged pool reduces from 256 MB to 128 MB.
3. ISABPA is your friend
Many people still not aware of how powerful ISA BPA can be when the subject is: identify what is wrong and tell you about it. When you run a Health Check on your ISA Server using ISABPA and this machine has /3GB the following alert will show up in the report:
Figure 1 – ISABPA alerts about /3GB.
Don’t know how to download ISABPA, easy: now can just type www.isabpa.com and you will be redirected to the download page for ISABPA.
Many myths are behind /3GB switch and many system admin still think that this could be beneficial for all servers’ regardless; untrue statement. Each server/application has its own needs and you need to carefully analyze and understand these needs before add such switch in your boot.ini.
Back in May I wrote the first part of this blog where I explained how to use DebugDiag to capture a crash on ISA Server Service. Now is time to see how it looks like.
2. Got ya !!!
An administrator’s feeling when it catches a crash while the debugger is attached to the process that he was hunting for awhile is just super. Now with the crash (dump) files in hands it is time to decide what to and here it comes the experience and the knowledge that will drive to the answer. Sometimes, even when the administrator has strong debugging skills he could be limited due the fact that in some situations only the private symbols will really give you the full explanation about what happened during that time.
3. Reviewing the Crash
Assuming that you have the Debugging Tools installed and the public symbols configured, it is time to open your crash dump. When you open the crash dump, the first command that you probably will use (since this is a crash) is the !analyze-v. The result will vary, but you will have an output structured in the following parts:
0:019> !analyze -v
*************************************************************************
* *
* Exception Analysis *
Debugger WatsonDb Connection::Open failed 80004005
FAULTING_IP:
isamon2+1a7a
1e301a7a f3a5 rep movs dword ptr es:[edi],dword ptr [esi]
EXCEPTION_RECORD: ffffffff -- (.exr ffffffffffffffff)
//Address where the exception happened
ExceptionAddress: 1e301a7a (isamon2+0x00001a7a)
//Type of Exception, in this case access violation
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 20686000
Attempt to read from address 20686000
DEFAULT_BUCKET_ID: APPLICATION_FAULT
//Process (ISA Server Firewall Service Process)
PROCESS_NAME: wspsrv.exe
ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at "0x%08lx" referenced memory
at "0x%08lx". The memory could not be "%s".
READ_ADDRESS: 20686000
BUGCHECK_STR: ACCESS_VIOLATION
LAST_CONTROL_TRANSFER: from 1e307a44 to 1e301a7a
STACK_TEXT:
01639674 1e307a44 20685fdf 1e31ecc4 00000029 isamon2+0x1a7a
01639698 1e30e96d 1e301b0b 1e3b3ff8 2734e7b8 isamon2!GetFilterVersion+0x16d4
0163969c 1e301b0b 1e3b3ff8 2734e7b8 0163fd38 isamon2!DllUnregisterServer+0x90d
016396b8 1e308292 20685b68 1e31e81c 00000004 isamon2+0x1b0b
016396ec 6472eb58 0163d96c 0000000b f4e03f1f isamon2!GetFilterVersion+0x1f22
01639710 01639750 1f486d50 1f486d38 1e3e8ec7 W3Filter!HTTP_FILTER::GetInfo+0x4d
01639740 1e30aa2a 1e3e8ebc 1e320d5c 1f495a6c 0x1639750
0163fc40 71c02679 0163fc64 63703493 275362c0 isamon2!GetFilterVersion+0x46ba
71b2199f 90909090 ffffff90 b356acff b356b571 ws2_32!WSARecv+0x77
71b219bf b3586cff b3587571 00000271 b3584500 0x90909090
71b219c3 b3587571 00000271 b3584500 b3584e71 0xb3586cff
71b219c7 00000000 b3584500 b3584e71 90909071 0xb3587571
// In the stack above, the function at the top of the stack is GetFilterVersion in the module isamon2.dll, the denotation is “file_name!function_name”. The “+0x16d4” next to the function name indicates how far into the code of that function the thread is. Notice that W3Filter.dll call uses the function HTTP_Filter right before the ISAMon2 takes over.
FAULTING_THREAD: 00000a7c
FOLLOWUP_IP:
SYMBOL_STACK_INDEX: 0
FOLLOWUP_NAME: wintriag
MODULE_NAME: isamon2
IMAGE_NAME: isamon2.dll
DEBUG_FLR_IMAGE_TIMESTAMP: 40b1fcdf
SYMBOL_NAME: isamon2+1a7a
STACK_COMMAND: ~19s; .ecxr ; kb
FAILURE_BUCKET_ID: ACCESS_VIOLATION_isamon2+1a7a
BUCKET_ID: ACCESS_VIOLATION_isamon2+1a7a
Followup: MachineOwner
In this case you can see the ISAMon2 version by running the command lmvm isamon2 the result will be the following:
0:019> lmvm isamon2
1e300000 1e3ab000 isamon2 C (export symbols) isamon2.dll
Loaded symbol image file: isamon2.dll
Image path: C:\Program Files\Microsoft ISA Server\isamon2.dll
Image name: isamon2.dll
Timestamp: Mon May 24 08:47:11 2004 (40B1FCDF)
CheckSum: 00000000
ImageSize: 000AB000
File version: 2.0.0.2
Product version: 2.0.0.2
File flags: 0 (Mask 3F)
File OS: 40004 NT Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0409.04b0
CompanyName: GFI Software Ltd.
ProductName: GFI Web Monitor
InternalName: GFIWEBMON
OriginalFilename: IsaMon2.dll
ProductVersion: 2, 0, 0, 2
FileVersion: 2, 0, 0, 2
FileDescription: GFI Web Monitor
LegalCopyright: Copyright © 2003
This was a case where this filter was causing an access violation and crashing the Firewall Service. An access violation occur when an application attempts to use memory located in another process address space. By referring the customer to the third party vendor for solution they were able to fix it by updating the version.
By examining and understanding a call stack like this when a server or application crashes makes you more comfortable to tells with authority what components were involved in the crash and what types of actions they were performing. Remember that this is not always the case, however this much information can often lead to root cause of a problem without any further debugging.
Today we are launching in the Forefront Edge Community page a new session called: Tales from the Edge. Jim Harrison and I will host articles about Forefront Edge Suite bringing real world scenarios and documenting things that were not documented yet. In this new wave we are going to release four brand new articles with very precious information about Edge products. Visit the new Forefront Community Page at:
http://technet.microsoft.com/en-us/forefront/edgesecurity/bb687298.aspx
One of the most challenges for the ISA Admin is to determine the culprit for an intermittent issue. This gets worse when the issue is related with performance. While there are many elements that can impact ISA Server’s performance, this post will describe an interesting case where the client was having problems to browse Internet through ISA Server. The web sites were coming up really slow and regardless of the browser (IE6 or IE7) the issue was happening.
2. Start from the Basics
Do not over estimate the basics, missing a basic check can cost you hours of deep troubleshooting while the monkey is right there looking for you. Here it is a checklist of things that should be reviewed:
· DNS Configuration: This can dramatically impact the performance if it is not correctly configured. Tom Shinder wrote a good post about an issue that he got because of the DNS that was not answering in time manner. Besides that, remember to review Microsoft recommendation on DNS configuration for ISA Server.
· RSS, Chimney and TCPCA: if you have Windows Server 2003 SP2 installed make sure to use KB936594 to address the issues that those keys can cause.
· Network Configuration: on ISA Server, make sure that the Network range is correctly defined. Review the article Troubleshooting Network Configuration in ISA Server.
· NIC Drivers: are the NIC drivers updated for the latest version?
· Speed and Duplex: autosense configuration between the Server and the Switch can also cause network intermittence behavior. Better force the speed (100 Mbps or 1Gbps) and duplex (full) in the switch port and in the NIC driver.
These are things that you can start looking in first hand. If all those elements look good than is time to move on and get more data.
3. The Output
After reviewing the netmon trace that was get it while the issue was happening the result was clear: did not have delay in the name resolution as well as the initial TCP handshake. The network communication was clear and there were not big gaps in between frames. The only thing that we notice was that it was taking too much time to transfer data to build the page. Something in the application level was not really going as good as it should.
The output from perfmon (using the counters from the article Monitoring and Troubleshooting Performance also did not show any suspicious activity. There was no leak in the server itself; processor utilization was good as well as memory and disk.
3. User Mode Dump
The next troubleshooting level was really to get a dump from wspsrv.exe and understand what that guy was doing during the page request. To do that we used the command below while repro the issue:
Cscript adplus.vbs -quiet -hang -pn wspsrv.exe
Note: for more information on how to use ADPLUS use the KB286350.
General Considerations:
· Install WinDbg that is part of the debugging tools.
· Configure the Symbol path using KB311503.
After load the dump in WinDBG we ran the command runaway to show the time that each thread is consuming:
0:000> !runaway
User Mode Time
Thread Time
21:f80 0 days 0:00:20.437
8:eb4 0 days 0:00:11.375
19:f78 0 days 0:00:02.953
25:fb8 0 days 0:00:02.656
42:10e8 0 days 0:00:01.859
45:152c 0 days 0:00:01.796
43:1318 0 days 0:00:01.718
35:1664 0 days 0:00:01.703
44:1534 0 days 0:00:01.562
…
The thread 21 is the one that seems to be using more resources. To see what this thread is doing run ~21kb, for this case the result was:
0:000> ~21kv
0220f3a8 7c827d0b 7c83d236 000079e8 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
0220f3ac 7c83d236 000079e8 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])
0220f3e8 7c83d281 000079e8 00000004 646f30a0 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [Non-Fpo])
*** ERROR: Symbol file could not be found. Defaulted to export symbols for W3Filter.dll -
0220f408 64709542 1adf1eec 1adf1eec 6470bead ntdll!RtlEnterCriticalSection+0xa8 (FPO: [Non-Fpo])
*** ERROR: Symbol file could not be found. Defaulted to export symbols for msfpc.dll -
0220f44c 615e7407 00000000 00000000 0220f470 W3Filter!CNetAddr::operator=+0x15e
0220f47c 615eb41d 202f3c28 0020f4a8 646f3080 msfpc!HmacMD5CreateKey+0x3944
0220f4ac 6470a167 1ad91218 202f3c28 0220f4d0 msfpc!TsLogInformationA+0x1b7
0220f4d4 6471bd0b 202f3c28 202f3558 202f3508 W3Filter!CNetAddr::operator=+0xd83
0220f508 647670c4 04e74008 00000000 00002faa W3Filter!DllUnregisterServer+0x1b4e
0220f520 6472676c 00002faa 64702748 00000002 W3Filter!DllUnregisterServer+0x4cf07
0220fdb0 647773ad 00000000 00000000 0000000a W3Filter!DllUnregisterServer+0xc5af
*** ERROR: Symbol file could not be found. Defaulted to export symbols for wspsrv.exe
0220fdf4 004c37d4 18b21558 00000001 00000000 W3Filter!DllUnregisterServer+0x5d1f0
0220fe3c 0046982d 00000001 00000001 00000000 wspsrv!IsNameInRwsConfigsLdt+0xb2af
0220fe7c 0046a570 00000001 00000000 20320c78 wspsrv+0x6982d
0220fee0 0046a8e0 00000109 00000000 00000001 wspsrv+0x6a570
0220ff04 0046a9e7 1d6ac2a8 0046a856 0220ff30 wspsrv+0x6a8e0
0220ff14 0046ab8b 00000109 00000000 00000001 wspsrv+0x6a9e7
0220ff30 00469939 00000109 00000000 00000001 wspsrv+0x6ab8b
0220ff50 00452a27 1d6ac34c 00000109 00000000 wspsrv+0x69939
0220ff7c 004536a4 1d6ac34c 00000109 00000000 wspsrv+0x52a27
Note: I’m using the public symbol server (SRV*c:\symbols*http://msdl.microsoft.com/download/symbols) which doesn’t have too much info about ISA Server symbols. For this reason I’m receiving the error showed above.
Let’s look at the critical section information:
0:000> !cs -s -l -o
-----------------------------------------
DebugInfo = 0x000cc228
Critical section = 0x000d0e74 (+0xD0E74)
LOCKED
LockCount = 0x6
WaiterWoken = No
OwningThread = 0x00000f74
RecursionCount = 0x1
LockSemaphore = 0x7398
SpinCount = 0x00000000
OwningThread DbgId = ~18s
OwningThread Stack =
0214fd94 7c827d0b 77e61d1e 00000d38 00000000 ntdll!KiFastSystemCallRet
0214fd98 77e61d1e 00000d38 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0214fe08 77e61c8d 00000d38 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
0214fe1c 0043b9fd 00000d38 ffffffff 000d0e08 kernel32!WaitForSingleObject+0x12
0214fe6c 615e7407 00000000 00000000 0214fe90 wspsrv+0x3b9fd
0214fe9c 615eb41d 1dbea130 0014fec8 0041e4f8 msfpc!HmacMD5CreateKey+0x3944
0214fecc 004d3686 000abb98 1dbea130 0214fef4 msfpc!TsLogInformationA+0x1b7
0214ff04 0042beec 1dbea130 1dbea130 1dbea108 wspsrv!GetNetworkVIPAddress+0x66e5
0214ff20 00435549 00000000 00000001 1dbeaa94 wspsrv+0x2beec
0214ff50 0042b850 1dbeab3c 0214ff74 00430f1c wspsrv+0x35549
0214ff5c 00430f1c 00000000 6370a830 1dbeaa94 wspsrv+0x2b850
0214ff74 63705056 00000000 00000000 00409960 wspsrv+0x30f1c
0214ff94 00453616 00000001 00000000 00000000 ratlib!RatPollTimer+0x1a9
0214ffb8 77e64829 00000001 00000000 00000000 wspsrv+0x53616
0214ffec 00000000 00453576 00000001 00000000 kernel32!BaseThreadStart+0x34
DebugInfo = 0x000a8890
Critical section = 0x000d0e38 (+0xD0E38)
LockCount = 0x0
OwningThread = 0x000006dc
LockSemaphore = 0x0
OwningThread DbgId = ~37s
2294f96c 7c827d0b 71b21af5 0000890c 00000001 ntdll!KiFastSystemCallRet
2294f970 71b21af5 0000890c 00000001 2294f998 ntdll!NtWaitForSingleObject+0xc
2294f9ac 71b2c517 0000890c 00008fc4 00000000 mswsock!SockWaitForSingleObject+0x19d
2294fa24 71c094e5 00008fc4 2294fa84 00000001 mswsock!WSPRecv+0x203 (FPO: [Non-Fpo])
2294fa60 71bb1151 00008fc4 2294fa84 00000001 ws2_32!WSARecv+0x77 (FPO: [Non-Fpo])
2294fa8c 6d561686 00008fc4 00000000 00001000 wsock32!recv+0x31 (FPO: [Non-Fpo])
2294fadc 4e2597ce 00007530 012bdd40 012bdd40 dbnetlib!ConnectionRead+0x3b6 (FPO: [Non-Fpo])
2294fb10 4e25982d 012b0450 012bdd40 00000009 sqloledb!CDataSource::ConnectionRead+0x35
2294fb5c 4e252358 01710cc6 00000001 00000000 sqloledb!CDBConnection::GetBytes+0x269
2294fba8 4e2555c4 01158560 00000088 0000001e sqloledb!CDBConnection::ProcessTDSStream+0x157
2294fc64 4e255691 01155e78 00000049 01157688 sqloledb!CStmt::ExecDirect+0x786
2294fc7c 4e254d32 01155e78 00000049 00000000 sqloledb!CStmt::SQLExecDirect+0x28
2294fcac 4e25517d 00000000 4e25321c 00000049 sqloledb!CCommand::ExecuteHelper+0x157
2294fd30 4e254c4b 01157688 00000000 615d30b0 sqloledb!CCommand::Execute+0x76b
2294fd68 6160de22 0114dd78 00000000 615d30b0 sqloledb!CImpICommandText::Execute+0xdd
2294fd98 6160e2a1 00000000 00000000 2294fdfc msfpc!CFastSession::Insert+0xe2
2294fdb4 6160e776 201f8bf0 2294fe14 2294fdfc msfpc!SessionInfo::~SessionInfo+0x4f
2294fee0 6160e9f5 201f8bf0 0115a278 615d1a14 msfpc!OpenFastLoadRowset+0x4cb
2294ff08 6160eaa4 00000000 000d0010 6160ecd1 msfpc!CFastSession::Commit+0x29
2294ff20 0050a069 00000001 004d78e6 000d0010 msfpc!CFastSession::~CFastSession+0x18
The red line in the second stack shows that the machine is submitting a SQL statement using the SQLExecDirect function. Now let’s see what SQL command is being executed:
0:035> du 01155e78
01155e78 "EXEC sp_batch_insert [##Firewall"
01155eb8 "Log000000391SDCTSI00FW02], [Fir"
01155ef8 "ewallLog]"
Ok, now things start to make sense. The problem was happening during that time and the ISA Server Firewall Service was writing to the log file (Firewall Log) which was located in a SQL Server database.
4. Logging was the Problem
The browsing performance issue for this case was caused by a performance problem in the SQL Server. The SQL Server that ISA Server was using for logging had disk I/O problems and therefore it was very slow to answer to network requests. The workaround for that while customer fixed his SQL issue was to change the logging type for TXT in the local machine.
The browsing experience improved tremendous and this is actually expected. You can review the ISA Server Logging Best Practices and you will see that TXT log format has the best performance in comparison with the other log types.
5. Additional Reading - Learning More about Debugging
Here are good references for learning more about debugging:
Books
· Advanced Windows Debugging by Hewardt and Pravat
o This book has two great authors from Microsoft and it also foreword by Mark Russinovich, so you know that it is really worth to have it.
· Memory Dump Analysis Anthology, Volume 1 by Dmitry Vostokov
o This book is very good to startup on debugging. It really starts from the basics and it keeps going more in depth. Easy to read and very didactic.
· Windows Internals by Mark Russinovich (Author), David A. Solomon (Author)
o This should be a book that every IT professional should have on his desk if he really wants to know how Windows Architecture works. Just amazing.
Online Resources
· One of the best sites that I found about dump analyses: http://www.dumpanalysis.org/blog/ maintained by Dmitry Vostokov
· There are two really good blogs from two personal friends from Microsoft:
o http://blogs.msdn.com/debuggingtoolbox/ from Roberto Farah (Sharepoint PFE).
o http://blogs.technet.com/marcelofartura/ from Marcelo Fartura (IIS PFE).
· Very good in depth online resource: http://blogs.msdn.com/tess
· Microsoft Advanced Windows Debugging and Troubleshooting: http://blogs.msdn.com/ntdebugging
Once again, ISA Server was only a victim of an environmental issue J !!
The article that Tom Shinder and I wrote couple of months ago about TS Gateway publishing through ISA Server 2006 is now available online at TechNet Magazine web site. Check it out here:
Enhance TS Gateway Security with ISA Server 2006
Dr. Thomas W. Shinder and Yuri Diogenes
http://technet.microsoft.com/en-us/magazine/cc742827.aspx