very slow first click, calls to mp_BannedIPAddresses

very slow first click, calls to mp_BannedIPAddresses_Exists , possible circular calls?

Post here for help with installing or upgrading mojoPortal pre-compiled release packages. When posting in this forum, please provide all relevant details. You may also want to review the installation or upgrading documentation.

If you have questions about using the source code or working with mojoPortal in Visual Studio, please post in the Developer forum.

Post here for help with installation of mojoPortal pre-compiled release packages

When posting in this forum, please try to provide as many relevant details as possible. Particularly the following:

What operating system were you running when the bug appeared?
What database platform is your site using?
What version of mojoPortal are you running?
What version of .NET do you use?
What steps are necessary to reproduce the issue? Compare expected results vs actual results.

You may also want to review the installation or upgrading documentation.

If you have questions about using the source code or working with mojoPortal in Visual Studio, please post in the Developer forum.

This thread is closed to new posts. You must sign in to post in the forums.

5/3/2015 7:33:14 PM

shev72

Total Posts 17

View Posts

very slow first click, calls to mp_BannedIPAddresses_Exists , possible circular calls?

Hello,

I have been using Mojoportal for years with no issues. I have recently started a new site, fist with version 2.4.0.8 and now I updated to 2.4.0.9. We are regularly seeing (but randomly) that the first click on the site can take up to 30 secs! This is not related to the appdomain loading since I am using uptime robot. I think there is some kind of circular reference,but I am having trouble picking off the issue.

I set the log4net level to DEBUG, and I am seeing what appears to be repeated calls for a given first click (on session start). Once session is started everything runs very fast. The site is in fact very small and simple, we are just starting up.

Here is the log, below.

thanks in advance for any insights you can provide.

additional details:

.NET 4.5

DB=MSSQL

hosting provide : UsanacarHosting, with Plesk

Regards,

shelby

2015-05-03 17:13:54,962 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-03 17:13:54,962 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-03 17:13:54,978 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectOneByUrl
2015-05-03 17:13:54,978 DEBUG 74.86.158.106 - fr-FR - /de - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_BannedIPAddresses_Exists
2015-05-03 17:13:54,978 DEBUG 74.86.158.106 - fr-FR - /de - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-03 17:13:54,978 DEBUG 74.86.158.106 - fr-FR - /de - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-03 17:13:54,993 DEBUG 74.86.158.106 - fr-FR - /de - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectOneByUrl
2015-05-03 17:13:55,118 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_BannedIPAddresses_Exists
2015-05-03 17:13:55,134 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-03 17:13:55,134 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-03 17:13:55,196 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_BannedIPAddresses_Exists
2015-05-03 17:13:55,196 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-03 17:13:55,212 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-03 17:13:55,212 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_BannedIPAddresses_Exists
2015-05-03 17:13:55,212 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-03 17:13:55,212 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-03 17:13:55,228 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-03 17:13:55,228 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectBySiteUrl
2015-05-03 17:13:55,228 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Web.UrlRewriter - Rewriting URL to
2015-05-03 17:13:55,228 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_BannedIPAddresses_Exists
2015-05-03 17:13:55,228 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-03 17:13:55,243 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-03 17:13:55,243 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Web.Global - Global.asax.cs Session_Start
2015-05-03 17:13:55,243 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Web.Global - IncrementUserCount key was midibible.org_onlineCount
2015-05-03 17:13:55,243 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadCurrentPage
2015-05-03 17:13:55,243 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadPage
2015-05-03 17:13:55,259 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Pages_SelectOne
2015-05-03 17:13:55,259 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Modules_SelectByPage
2015-05-03 17:13:55,259 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_ModuleSettings_Select
2015-05-03 17:13:55,275 DEBUG 74.86.158.106 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_HtmlContent_Select
2015-05-03 17:14:13,806 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_BannedIPAddresses_Exists

5/4/2015 9:20:28 AM

Joe Audette

Total Posts 18439

View Posts

Re: very slow first click, calls to mp_BannedIPAddresses_Exists , possible circular calls?

Nothing has changed in the banned ip module for a very long time.

There is nothing circular, but in in Integrated Pipeline mode modules would run for each request including requests for static files like css or js.

You can easily disable the BannedIpBlockingHttpModule if you don't want to use it and especially if you have not banned any ip addresses, you might as well disable it.

To disable it, just comment it out in the <httpModules> and in <modules> sections of Web.config

5/4/2015 12:47:13 PM

shev72

Total Posts 17

View Posts

Re: very slow first click, calls to mp_BannedIPAddresses_Exists , possible circular calls?

Hello Joe,

May thanks for your quick help! Commenting out the banned IP module fixed the speed problem. The website flies now !

I think I have never encountered this on other sites because they are probably not running in integrated pipeline mode (I am not tehcnically savvy enough to set this type of parameter though).

thanks again,

shelby

5/11/2015 1:36:31 PM

shev72

Total Posts 17

View Posts

Very Slow First click

Joe, a couple of weeks ago, you helped me with a slow first click issue (in this forum). I am in fact getting a slow 1st click 30s+ in other situations, much more rarely. I set the log level to Debug and get the following , slow part in bold.

NOTE: this is not an app start since I started the website and all subdomains and then went to my Iphone for further testing, I also use UptimeRobot as you recommend to keep the site alive. You help me recently by suggesting I comment out a module, but it is not so clear what I can do you.

I am running on .NET 4.5.2, Plesk Parallels hosting , current version of Mojo 2.4.0.9

Thanks for any suggestions,

Regards,

shelby

2015-05-11 11:26:30,574 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Web.Global - Global.asax.cs Session_Start
2015-05-11 11:26:30,574 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Web.Global - IncrementUserCount key was midibible.org_onlineCount
2015-05-11 11:26:30,589 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadCurrentPage
2015-05-11 11:26:30,589 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadPage
2015-05-11 11:26:30,589 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Pages_SelectOne
2015-05-11 11:26:30,605 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Modules_SelectByPage
2015-05-11 11:26:30,605 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_ModuleSettings_Select
2015-05-11 11:26:30,620 DEBUG 178.193.185.123 - fr-FR - / - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_HtmlContent_Select
2015-05-11 11:26:31,152 DEBUG 178.193.185.123 - en-US - /csshandler.ashx?skin=art42-lightblueplaid&s=1&v=2.4.0.9&sv=00000000-0000-0000-0000-000000000000 - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-11 11:26:34,933 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-11 11:26:34,980 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-11 11:26:34,980 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-11 11:26:34,995 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectBySiteUrl
2015-05-11 11:26:34,995 DEBUG (null) - (null) - (null) - mojoPortal.Web.UrlRewriter - Rewriting URL to
2015-05-11 11:26:35,089 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-11 11:26:35,089 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-11 11:26:35,121 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-11 11:26:35,136 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectBySiteUrl
2015-05-11 11:26:35,183 DEBUG 100.43.81.153 - en-US - /en/Secure/Login.aspx?skin=printerfriendly&returnurl=%2Fen%2Fediting - mojoPortal.Web.Global - Global.asax.cs Session_Start
2015-05-11 11:26:35,183 DEBUG 100.43.81.153 - en-US - /en/Secure/Login.aspx?skin=printerfriendly&returnurl=%2Fen%2Fediting - mojoPortal.Web.Global - IncrementUserCount key was midibible.org_onlineCount
2015-05-11 11:26:35,183 DEBUG 100.43.81.153 - en-US - /en/Secure/Login.aspx?skin=printerfriendly&returnurl=%2Fen%2Fediting - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadCurrentPage
2015-05-11 11:26:35,199 DEBUG 100.43.81.153 - en-US - /en/Secure/Login.aspx?skin=printerfriendly&returnurl=%2Fen%2Fediting - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadPage
2015-05-11 11:26:35,199 DEBUG 100.43.81.153 - en-US - /en/Secure/Login.aspx?skin=printerfriendly&returnurl=%2Fen%2Fediting - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Pages_SelectOne
2015-05-11 11:26:35,199 DEBUG 100.43.81.153 - en-US - /en/Secure/Login.aspx?skin=printerfriendly&returnurl=%2Fen%2Fediting - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Modules_SelectByPage
2015-05-11 11:26:44,324 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-11 11:26:44,324 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-11 11:26:44,339 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-11 11:26:44,339 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectOneByUrl
2015-05-11 11:26:44,355 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadCurrentPage
2015-05-11 11:26:44,355 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadPage
2015-05-11 11:26:44,355 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Pages_SelectOne
2015-05-11 11:26:44,371 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Modules_SelectByPage
2015-05-11 11:26:44,371 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Users_SelectByLoginName
2015-05-11 11:26:44,464 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteNonQuery mp_Users_UpdateLastActivityTime
2015-05-11 11:26:44,464 DEBUG (null) - (null) - (null) - mojoPortal.Web.SiteUtils - Tracked user activity for request /Admin/ServerLog.aspx
2015-05-11 11:27:12,621 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-11 11:27:12,637 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-11 11:27:12,637 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
2015-05-11 11:27:12,637 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_FriendlyUrls_SelectOneByUrl
2015-05-11 11:27:12,653 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadCurrentPage
2015-05-11 11:27:12,653 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Business.WebHelpers.CacheHelper - CacheHelper.cs LoadPage
2015-05-11 11:27:12,653 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Pages_SelectOne
2015-05-11 11:27:12,653 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Modules_SelectByPage
2015-05-11 11:27:12,668 DEBUG 178.193.185.123 - fr-FR - /Admin/ServerLog.aspx - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_Users_SelectByLoginName

5/12/2015 5:52:20 AM

shev72

Total Posts 17

View Posts

Re: very slow first click, calls to mp_BannedIPAddresses_Exists , possible circular calls?

I just wanted to make a small clarification on my previous post. I think this may again be linked to Integrated Pipeline mode. However with my current provider (UsanaCar Hosting with Plesk Parallels which is quite powerful), I do not have the option to switch to classic mode. Also there are no logs written for almost 30 secs between the following 2 lines. I am just wondering if another hhtlpmodule/Handler is running which I can safely turn off in pipeline mode.

2015-05-11 11:26:44,464 DEBUG (null) - (null) - (null) - mojoPortal.Web.SiteUtils - Tracked user activity for request /Admin/ServerLog.aspx
2015-05-11 11:27:12,621 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists

5/12/2015 3:26:31 PM

shev72

Total Posts 17

View Posts

Re: very slow first click

Hello, sorry to have so many posts on this topic, but I also found another place on the first click which causes issue. I see this just a short time after the session_Start. The css_Handler took 54s (or possibly something else which is not being logged).

Has anyone experienced similar issues in integrated pipeline mode, is there a suggestion for a quick fix? hopefully just a config somewhere?

Regards,

shelby

2015-05-12 13:16:07,230 DEBUG 178.193.185.123 - de-DE - /de/ - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_HtmlContent_Select
2015-05-12 13:16:07,636 DEBUG 178.193.185.123 - en-US - /de/csshandler.ashx?skin=art42-lightblueplaid&s=3&v=2.4.0.9&sv=00000000-0000-0000-0000-000000000000 - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolder_Exists
2015-05-12 13:16:07,636 DEBUG 178.193.185.123 - en-US - /de/csshandler.ashx?skin=art42-lightblueplaid&s=3&v=2.4.0.9&sv=00000000-0000-0000-0000-000000000000 - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-12 13:17:01,168 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteScalar mp_SiteFolders_SelectSiteIdByFolder
2015-05-12 13:17:01,168 DEBUG (null) - (null) - (null) - mojoPortal.Data.SqlParameterHelper - ExecuteReader mp_RedirectList_SelectBySiteAndUrl
20

5/12/2015 4:56:42 PM

shev72

Total Posts 17

View Posts

Re: very slow first click

Hello,

in fact further investigation in the forums pointed me to this:

https://www.mojoportal.com/Forums/Thread.aspx?pageid=5&t=11857~-1

following the instructions that Joe provided there to identify the minimified css, copy it into a separate file and updatestyle.config worked beautifully. Load time is down to 3 secs for 1st click (notincluding application start, but I use uptime robot for this)..

5/23/2015 12:09:59 PM

shev72

Total Posts 17

View Posts

Slow First click: my setup for integrated pipeline mode

As a follow-up to this thread, I actually found several difficulties with my hosting in integrated pipeline mode. Unfortunately I cannot change this with my provider. However I was able to fix the speed issues using the following tricks. ALL provided significant gains so I wanted to share with the community (Joe perhaps it is worthwhile to add to the documentation a link covering Integrated Pipeline mode speed issues, I am not sure if this is general enough though?)

1. the Banned_IP address module was running slow in Integrated Pipeline mode (current mode of our server). This was easy to disable by commenting out the line at the top part of the web.config section.

2. It looks like the module trying to cache the css is also slow. I followed the instructions in the forum: https://www.mojoportal.com/Forums/Thread.aspx?pageid=5&t=11857~-1

3. In addition a standard issue in ASP.NET sites (all sites, all CMS, and independent hosting), is the issue with the very first click on the site by anyone, which causes a domrant site to awaken. There is in easy solution to this.. It is to use UptimeRobot, which just regularly pings the website. We are currently using this once every 10 minutes on our site.

4. In the App_GlobalResources directory. I deleted all languages that we do not use (this reduces the file count substantially from almost 700 to about 80 (to cover French, English , German in my case).

5. web.config : we should set <modules runAllManagedModulesForAllRequests="false"> (there is a comment for this in the web.config saying that we "might need to set this to true". However on my setup it works with it set to false on IIS 7.0 and setting to true led to a significant performance hit.

You must sign in to post in the forums. This thread is closed to new posts.