Re: GURUS HELP - Web Page delays every 2 Mins?!?

quantass0 — Tue, 13 Jun 2006 18:51:39 GMT

Hi Ryan. Thanks for the tip. The problem is no one is there which has led me here. I've posted over 15 message without a single response. I figure the community has moved on. Besides the question seems very much like a .NET issue than a Rainbow one.

Anyway, an update:

I discovered an Advanced mode of Filemon and it revleaed:
2:40:26.234 PM aspnet_wp.exe:2488 FSCTL_IS_VOLUME_MOUNTED C:\WINNT\system32 SUCCESS
This line is repeated several times before and after the .DLL and is consuming the majority of the time. On refresh of the page, it does not exist whatsoever. Any ideas on what it is and how to resolve it?

Re: GURUS HELP - Web Page delays every 2 Mins?!?

StrongTypes — Tue, 13 Jun 2006 18:48:00 GMT

Since most of the Rainbow community has moved to the Rainbow Community site, I suggest you post there.

Ryan

GURUS HELP - Web Page delays every 2 Mins?!?

quantass0 — Tue, 13 Jun 2006 18:10:13 GMT

We're using Rainbow Portal .NET v1.5 as our CMS to compose many of our sites. We develop several .ASCX controls and Rainbow easily plops them onto a dynamically created page. I've been asked to look into why a paritcular area of our site is running slowly as compared to other areas. I discovered several blotttlenecks and have resolved them to the best I could but one remains.

When i hit the page there is normally a 5 sec delay before the IE browser displays the site. On subsequent refreshes it takes about 1 sec. Clearly ASP.NET has cached what it needs. I then wait for about 2 mins and do a refresh again within the IE browser. Now the page takes about 5 secs or so to display. I dont get it. I thought .NET already had the page cached?

I then launched FILEMON to investigate all the IO file access by ASPNET_WP.exe and INETINFO.exe. Several Rainbow files (theme, layouts, dlls) are accessed but these consume less than 1 sec. The majority of the time was spent here:

1:35:11 PM    sqlservr.exe:688    WRITE     C:\Program Files\Microsoft SQL Server\MSSQL\Data\Rainbow_log.ldf    SUCCESS    Offset: 7912448 Length: 512
1:35:13 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:35:13 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes:
1:35:13 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:35:13 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:35:13 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:35:13 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:35:13 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:35:13 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:35:13 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:35:13 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:35:13 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:35:13 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:35:13 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:35:13 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:35:13 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:35:15 PM    inetinfo.exe:1140    OPEN    C:\PROJECTS\RAINBOW\DESIGN\THEMES\NEWCOUNTYSITE\DEFAULT.CSS    SUCCESS    Options: Open Access: All

You can see from blue to blue a time of 4 secs was consumed. The solpartwebcontrols.dll appears to be the major cause of the slow down. On subsquent refresh (within 1 min), there is no more delay with the page displaying in about 1 sec. Filemon reveals the .dll file being accessed like before but the 4 sec delay does not exist.:

1:42:58 PM    sqlservr.exe:688    WRITE     C:\Program Files\Microsoft SQL Server\MSSQL\Data\Rainbow_log.ldf    SUCCESS    Offset: 7921152 Length: 512
1:42:58 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:42:58 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes:
1:42:58 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:42:58 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:42:58 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:42:58 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:42:58 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:42:58 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:42:58 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:42:58 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:42:58 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:42:58 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:42:58 PM    aspnet_wp.exe:2488    OPEN    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Options: Open Access: All
1:42:58 PM    aspnet_wp.exe:2488    QUERY INFORMATION    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS    Attributes: A
1:42:58 PM    aspnet_wp.exe:2488    CLOSE    C:\winnt\microsoft.net\framework\v1.1.4322\temporary asp.net files\root\061162b5\7a6ac1c\assembly\dl2\c9b3b93f\b2d1d96e_8893c501\solpartwebcontrols.dll    SUCCESS
1:42:58 PM    inetinfo.exe:1140    OPEN    C:\PROJECTS\RAINBOW\DESIGN\THEMES\NEWCOUNTYSITE\DEFAULT.CSS    SUCCESS    Options: Open Access: All

Regarding the .DLL it is an acutal .DLL file (no accompanying src) within the Rainbow \Bin folder. Apparently .NET felt the need to copy just this .DLL file into its temportary asp.net files folder rather than leave it (like the rest of the 100s of control .DLL files) within the \Bin folder. Now i decided to investigate the temporary folder's .DLL file to see if it is being modified or accessed during the delay. According to FILEMON, the file is being accessed but from Explorer's Properties, Last Accessed Time is several minutes old rather than current. Hmmm. This goes for the delay and no delay.

I would figure the delay was caused by .NET having to copy the original .DLL file back into the temp folder or copy it back into memory to refresh its cache, for some reason. But I'd also expect the last access time (on either the temp or original dll) to change, which it does not.

Can someone help me determine why this file is consuming the majority of my page load's time? Why isnt ASP.NET keeping it cached when nothing has changed within it? Why does this mysterious page load delay occur after 2 mins of not refreshing?

Thanks for any leads!