Problem in profiling WebService! Exception thrownby Profiler

Sachin

Hi,

I have run profiler on Windows application, console app and web sites. Everytime it gave good results but I really got frustrated and tired to run profiler on WebService. It's giving following exception
"Unable to start profiler - exception details RedGate.Profiler.Engine.IIS.PortTimeoutException: Timed out waiting for port 9120 on 127.0.0.1 to become available"

I have checked all help provided by red-gate as well by the user groups but could not make it run.

Could I request somebody to help me out...

I am running red-gate profiler on Windows 2003 with ASP.NET 2.0. I am a admin on my PC and the value in HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\IISAdmin\ImagePath
is "C:\WINDOWS\system32\inetsrv\inetinfo.exe"

I tried running it with "Webdev.WebServer.exe" too but of no avail :-(

What else...

The exception in eventlog says

"Unable to start profiler - exception details RedGate.Profiler.Engine.IIS.PortTimeoutException: Timed out waiting for port 9120 on 127.0.0.1 to become available

Server stack trace:
at RedGate.Profiler.Engine.IISUtilities.WaitForPort(IPAddress address, Int32 port, Int32 timeout)
at RedGate.Profiler.Engine.IISUtilities.WaitForPort(String hostname, Int32 port, Int32 timeout)
at RedGate.Profiler.Engine.ProfileIISController.StartProfilingIIS(String currentUserName, String& url, WebApplicationDefinition appDef)
at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext)

Exception rethrown at [0]:
at RedGate.Profiler.Engine.ProfilingSession.StartProfiler()
at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.AsyncProcessMessage(IMessage msg, IMessageSink replySink)

Exception rethrown at [1]:
at System.Runtime.Remoting.Proxies.RealProxy.EndInvokeHelper(Message reqMsg, Boolean bProxyCase)
at System.Runtime.Remoting.Proxies.RemotingProxy.Invoke(Object NotUsed, MessageData& msgData)
at System.Windows.Forms.MethodInvoker.EndInvoke(IAsyncResult result)
at _5._4(IAsyncResult )

For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.
"


What should i do...

Best Regards,
Sachin Bansal.

Robert C

Hi Sachin,

Firstly, let's look at the IIS side of things. After you try to start profiling (but before the timeout happens), could you check in task manager to see whether another w3wp.exe process gets started? (You might need to discount any previously running as part of IIS)

Could you also check the event log for any other errors from W3WP, ASP.NET, IIS or similar that occur at around the same time as you start profiling?

Secondly, when you try and use WebDev, what error do you get there? They're probably unrelated, but might not be...

Rob

Sachin

Hi Rob,

Answers Inline:

Firstly, let's look at the IIS side of things. After you try to start profiling (but before the timeout happens), could you check in task manager to see whether another w3wp.exe process gets started? (You might need to discount any previously running as part of IIS)

SB: No i dont see a single w3wp.exe in task manager under process section.

Could you also check the event log for any other errors from W3WP, ASP.NET, IIS or similar that occur at around the same time as you start profiling?

SB: No there are none.

Secondly, when you try and use WebDev, what error do you get there? They're probably unrelated, but might not be...
SB: I ran it, and it is working fine now, y'day I was not taking snap shots... now I took and got the results.

But we are really interested in doing it by IIS.

Hope it help you to investigate...

Regards

Robert C

Hi,

Thanks for the reply.

One question first: are you running IIS in IIS 5 Isolation Mode? If so, you'll need to select "IIS 5" in the ANTS Profiler Wizard rather than IIS 6.

If not, if you could open up a command prompt on your machine, and try the following from the C:\WINDOWS\system32\inetsrv directory:

w3wp -debug -d http://*:9120/ -s 1 -ap "RGTestAppPool"

See whether that starts up (at which point you should be able to surf to your site at http://localhost:9120/), or whether it throws an error. This is not profiling it at this stage - it's just trying to get a better idea of what's causing the problem.

Rob

Sachin

I am using IIS6.0

I entered the command in command prompt. it did nothing just came out to the next line.

Then I tried accessing my Web service, i could access it well.

Robert C

Hi,

Do you mean it terminated instantly and returned you to the command prompt, or remained running but with no output? (The latter is what I'd expect.)

Also, can you confirm what port the web service was originally running on? The logs posted on the other thread suggest it was originally on port 80, and that you're trying to profile on 8013. However, the logs below suggest a timeout on 9120.

One other thing... are you running at least Windows 2003 SP1? SP2 is also fine, but pre-SP1 had some issues. That said, I'd expect a different problem if that was the case.

Sachin

Hi Rob,

I am now getting confused... I think I am making some small mistake somewhere...

Let me explain you what I am doing...

I did this
w3wp -debug -d http://localhost:9120/ -s 1 -ap "DefaultAppPool"
and control came out immediately. I dont know whether I should mention it as a crash/terminate. But it gave me cmd prompt immediately. There was no error msg.

I am using WindowsNT SP1

I am running my web service on 80 port. but we need to mention a different port for profiler so i mentioned 8013(it can be anything, i believe).

I dont have any idea regarding: "the logs below suggest a timeout on 9120."
I think my log files which i posted at
"http://www.red-gate.com/messageboard/viewtopic.php?t=4551"
says:
3/27/2007 1:51:38 PM ENGINE - Caught Exception in ProfilingSession: Timed out waiting for port 8013 on 127.0.0.1 to become available

Regards,

Robert C

Hi,

OK, that's not what should be happening then. For me, this happens if the port is already in use. You'd think it'd give an error message, but apparently not .

I'd got the port 9120 from the event log entry below: "Unable to start profiler - exception details RedGate.Profiler.Engine.IIS.PortTimeoutException: Timed out waiting for port 9120 on 127.0.0.1 to become available"

Could you try running the w3wp command again with port 8013 instead of 9120? (If it stays running, you'll need to terminate it with Control-C before trying to profile.)

It might also be worth trying to profile on a completely different port to anything you've used anywhere else - e.g. 12345 (must be less than 65535).

Sachin

I dont know which log are you refering to. I am sending you the latest log when i ran the app with port 8013. My webservice is running on 80.

Log file 1: ANTSProfilerLog16340.txt

3/27/2007 4:24:24 PM ANTSProfilerLog initialized
3/27/2007 4:24:24 PM PID = 16340
3/27/2007 4:24:24 PM Log file name = ANTSProfilerLog16340.txt
3/27/2007 4:24:24 PM OS version = Microsoft Windows NT 5.2.3790 Service Pack 1
3/27/2007 4:24:24 PM Machine name = TCS031751
3/27/2007 4:24:24 PM User name = administrator
3/27/2007 4:24:24 PM PARAMHOST - Listening on port 8084
3/27/2007 4:24:24 PM PARAMHOST - Listening on port 8084, channel registered
3/27/2007 4:24:26 PM EditProjectClosingWizard start
3/27/2007 4:24:26 PM EditProjectClosingWizard start
3/27/2007 4:24:27 PM About to show wizard
3/27/2007 4:24:30 PM Using IIS Version 6
3/27/2007 4:26:04 PM Wizard dialog returned
3/27/2007 4:26:05 PM UI Start profiling
3/27/2007 4:26:05 PM ENGINE - Core2.dll found in regisry
3/27/2007 4:26:05 PM ENGINE Start profiling performance of ASP.NET web application http://localhost/CheckProfiler/Service.asmx
3/27/2007 4:26:05 PM ENGINE The profiler is enabled
3/27/2007 4:26:06 PM TRANSFER - Waiting for pipe connection from core
3/27/2007 4:26:06 PM WaitForPort on address 127.0.0.1, port 8086
3/27/2007 4:26:07 PM ENGINE - Managed to hook into status updates from IIS Profile Host
3/27/2007 4:26:42 PM ENGINE - Closing IISProfileHost
3/27/2007 4:26:44 PM ENGINE - Caught Exception in ProfilingSession: Timed out waiting for port 8013 on 127.0.0.1 to become available


Log File 2: IISProfileHostLog17340.txt

3/27/2007 4:26:06 PM IISProfileHostLog initialized
3/27/2007 4:26:06 PM PID = 17340
3/27/2007 4:26:06 PM Log file name = IISProfileHostLog17340.txt
3/27/2007 4:26:06 PM OS version = Microsoft Windows NT 5.2.3790 Service Pack 1
3/27/2007 4:26:06 PM Machine name = TCS031751
3/27/2007 4:26:06 PM User name = administrator
3/27/2007 4:26:06 PM ANTS Profiler IISProfileHost Start up
3/27/2007 4:26:06 PM Listening on port 8086
3/27/2007 4:26:07 PM StartProfilingIIS currentUserName SOLOMON\administrator, url http://localhost/CheckProfiler/Service.asmx, .NET 2.0 Two, IIS6
3/27/2007 4:26:07 PM Parse IIS metabase
3/27/2007 4:26:08 PM InitServiceList
3/27/2007 4:26:08 PM StartIIS
3/27/2007 4:26:08 PM StartWebService for IIS 6
3/27/2007 4:26:08 PM WaitForPort on address 127.0.0.1, port 8013
3/27/2007 4:26:11 PM About to get site for URL
3/27/2007 4:26:11 PM About to get IIS6 sites
3/27/2007 4:26:11 PM Got site 'Default Web Site' with identifier 1
3/27/2007 4:26:11 PM About to get IIS6 x64 status
3/27/2007 4:26:11 PM WaitForPort start, url = http://localhost:8013/CheckProfiler/Service.asmx
3/27/2007 4:26:11 PM WaitForPort on address 127.0.0.1, port 8013
3/27/2007 4:26:42 PM StartProfilingIIS - threw exception
3/27/2007 4:26:42 PM ENGINE - Received request to close IISProfileHost
3/27/2007 4:26:43 PM IISPROFILEHOST - Exiting due to closing: True and UI Exit: False
3/27/2007 4:26:43 PM Main() exiting


I dont see any mentioning of 9120 in this. Now please tell me what should I do!

Regards,

Sachin

Hi Rob,

The event vrw log you were saw was very old. Actually i was trying plenty of things, so might have given 9120 port.

The latest error msg in EventVwr for port 8013 is:

Unable to start profiler - exception details RedGate.Profiler.Engine.IIS.PortTimeoutException: Timed out waiting for port 8013 on 127.0.0.1 to become available

Server stack trace:
at RedGate.Profiler.Engine.IISUtilities.WaitForPort(IPAddress address, Int32 port, Int32 timeout)
at RedGate.Profiler.Engine.IISUtilities.WaitForPort(String hostname, Int32 port, Int32 timeout)
at RedGate.Profiler.Engine.ProfileIISController.StartProfilingIIS(String currentUserName, String& url, WebApplicationDefinition appDef)
at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext)

Exception rethrown at [0]:
at RedGate.Profiler.Engine.ProfilingSession.StartProfiler()
at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
at System.Runtime.Remoting.Messaging.StackBuilderSink.AsyncProcessMessage(IMessage msg, IMessageSink replySink)

Exception rethrown at [1]:
at System.Runtime.Remoting.Proxies.RealProxy.EndInvokeHelper(Message reqMsg, Boolean bProxyCase)
at System.Runtime.Remoting.Proxies.RemotingProxy.Invoke(Object NotUsed, MessageData& msgData)
at System.Windows.Forms.MethodInvoker.EndInvoke(IAsyncResult result)
at _5._4(IAsyncResult )


I hope it will help...
Thanks,
Sachin Bansal

Robert C

Hi,

Thanks - that clears up the port number confusion.

If you could run in a terminal (in C:\windows\system32\inetsrv):

w3wp -debug -d http://localhost:8013/ -s 1 -ap "RGTestAppPool"

(note RGTestAppPool rather than DefaultAppPool is deliberate, and also port 8013)

That should not terminate immediately - if it does, check your event viewer "Application" log for entries coming from W3SVC-WP.

Rob

Sachin

Nothing happened. I just pasted the command as-is given by you in cmd prompt (both at cmd as well on VS cmd) and pressed enter. It came out immediately, doing or showing nothing!

What next
Sachin Bansal

Sachin

Sorry, forgot to mention that there are no error in eventvwr!

Robert C

In that case, I'm at a bit of a loss. It sounds like an issue with IIS, since that should definitely work.

More things to try:

1) Reboot your machine (the old classic )
2) Run "netstat -a" in a command prompt. Look for any lines that mention port 8013.
3) Try connecting to port 8013 using telnet - in a command prompt, "telnet localhost 8013". If it connects, it will blank the terminal, if not, it should give some error like "could not open connection". I'd hope you'd get a "could not open connection", since that port shouldn't be in use.

I'm afraid I'm running out of ideas beyond those - if you have another machine running IIS 6, you might like to give it a go on that, or even a virtual machine (though I don't guarantee the accuracy of profiling results taken inside a VM).

Rob

Sachin

1) Reboot your machine (the old classic )
SB: I tried on 3 different machine but of no avail.

2) Run "netstat -a" in a command prompt. Look for any lines that mention port 8013.
SB: no where mentioning of 8013

3) Try connecting to port 8013 using telnet - in a command prompt, "telnet localhost 8013". If it connects, it will blank the terminal, if not, it should give some error like "could not open connection". I'd hope you'd get a "could not open connection", since that port shouldn't be in use.
SB:- you are right i got a msg "Could not open connection".


Apart from this tell me one thing:
If our webservice is running on port 80, what number should we enter in Dialog box "Profile an ASPnet application in IIS" screen 3rd, while running profiler. I think it should be any port which is free. right!

Secondly, I read some where that you should give previlage to some IISMetadata, is that the case

Robert C

2) Good, that's what I'd hope
3) Also good

Port number: yes, that's entirely correct. 8013 is the one we choose as a default, but any free port should be fine.

One of the things we need to do is to read the IIS Metabase which obviously needs appropriate permissions to do so, but this is happening fine in your case - it's extracting the site ID appropriately.

Are the computers in question members of a domain? Do you know of any security policy restricions in place beyond what comes as standard?

Brian Donahue

Hi,

It might be helpful to see if the application pool had been started, but for some reason isn't answering requests.

If you go through the wizard and choose the ASP .NET web application as the type of application to profile, enter the URL to the webservice in the path (it should appear in the dropdown list), verify the .NET Framework and IIS versions are correct, and that you can run web applications on the selected port, go through the next screen and click finish, you should see the w3wp process running for your web application.

The way to check to see if the application pool is running is to open a command prompt, change working directory to %systemroot%\System32, and run

cscript iisapp.vbs

One of the application pools listed should be RGTestAppPool, like Robert had said. If not, then Profiler is not starting the application pool for some reason, maybe because of a user rights issue.