One HttpRequest is not guaranteed to be serviced by the same

jimjxr · **Joined:** Sun Sep 18, 2005 4:11 am **Posts:** 11

thread!?

I just read this in the FAQ, how is this possible? I couldn't find any definite support evidence for this claim. An interesting article in MSDN http://msdn.microsoft.com/msdnmag/issues/05/10/WickedCode/default.aspx says "When ASP.NET receives a request for a page, it grabs a thread from a thread pool and assigns that request to the thread. A normal, or synchronous, page holds onto the thread for the duration of the request, preventing the thread from being used to process other requests.", this is how I imagine things would work inside ASP.NET runtime (and this is how Java servlet engines work).

So I think the above claim in FAQ is not correct, as long as the page is synchronous, one HttpRequest is guaranteed to be serviced by the same thread. If you use asynchronous pages, one request could go through multiple threads, but your custom request processing can still be guaranteed to be done on one thread (unless you try to spawn more than one thread to service the request in your code, that is).

And I believe ThreadStatic session can definitely be used in ASP.NET, as long as you initialize/cleanup it inside the same request/thread.

Any objections?[/url]

xor · **Posted:** Wed Sep 21, 2005 8:37 am

Both sources of information are correct. You just have to realize that ASP.NET not always serves pages synchronously. I even not sure that it ever serves them this way.
It can be easily checked with an experiment. Create code, that depends on thread static members and put the site under havy load. When you will discover strange bugs then you will know that NH FAQ is right. :)

jimjxr · **Joined:** Sun Sep 18, 2005 4:11 am **Posts:** 11

Ok, please check if this test case does the trick:

First, the thread local

Code:

using System;
using System.Web;
using log4net;

namespace ClassLibraryTest
{
   /// <summary>
   /// Summary description for ThreadLocalTest.
   /// </summary>
   public class ThreadLocalTest
   {
      private static readonly ILog Log = LogManager.GetLogger(typeof(ThreadLocalTest));
      [ThreadStaticAttribute()]
      private static string _threadLocalString;
      public static readonly string ContextKey = "ThreadLocalTestKey";

      public static string CurrentThreadLocal
      {
         get 
         { 
            Log.Debug("Get current thread local '" + _threadLocalString
               + "' for current thread " + AppDomain.GetCurrentThreadId());
            return _threadLocalString; 
         }
         set
         {
            Log.Debug("Set current thread local to '" + value 
               + "' for current thread " + AppDomain.GetCurrentThreadId());
            _threadLocalString = value;
         }
      }

      public static void StartTest()
      {
         Random rand = new Random();
         string str = AppDomain.GetCurrentThreadId() + "_" + rand.Next();
         HttpContext.Current.Items[ThreadLocalTest.ContextKey] = str;
         _threadLocalString = str;
         Log.Info("Start test on thread " + AppDomain.GetCurrentThreadId()
            + " with string '" + str + "'");
      }

      public static void EndTest()
      {
         _threadLocalString = null;
         Log.Info("End test on thread " + AppDomain.GetCurrentThreadId());
      }

      public static void CheckThreadLocal(string name)
      {
         string contextString = HttpContext.Current.Items[ContextKey] as string;
         string localString = _threadLocalString;
         if(!Object.Equals(contextString, localString))
         {
            Log.Error("Check " + name + " failed: String in http context '" 
               + contextString + "' != string in thread local '" + localString 
               + "', current thread is " + AppDomain.GetCurrentThreadId());
         }
      }
   }
}

Then, the webpage

Code:

using System;
using System.Collections;
using System.ComponentModel;
using System.Data;
using System.Drawing;
using System.Web;
using System.Web.SessionState;
using System.Web.UI;
using System.Web.UI.WebControls;
using System.Web.UI.HtmlControls;
using ClassLibraryTest;
using System.Threading;

namespace ASPNETTest
{
   /// <summary>
   /// Summary description for WebForm1.
   /// </summary>
   public class WebForm1 : System.Web.UI.Page
   {
      protected System.Web.UI.WebControls.Label Label2;
      protected System.Web.UI.WebControls.Label Label1;
   

      private void Page_Load(object sender, System.EventArgs e)
      {
         DoTest("Load", 5);
         Label1.Text = ThreadLocalTest.CurrentThreadLocal;
         Label2.Text = HttpContext.Current.Items[ThreadLocalTest.ContextKey] as string;
      }

      private void Page_PreRender(object sender, System.EventArgs e)
      {
         DoTest("PreRender", 5);
         Label1.Text = ThreadLocalTest.CurrentThreadLocal;
         Label2.Text = HttpContext.Current.Items[ThreadLocalTest.ContextKey] as string;
      }

      private void DoTest(string name, int count)
      {
         ThreadLocalTest.CheckThreadLocal(name + "0");
         for(int i=0; i<count; i++)
         {
            Thread.Sleep(1000);
            ThreadLocalTest.CheckThreadLocal(name + i);
         }
      }

      protected override void OnUnload(EventArgs e)
      {
         base.OnUnload (e);
         ThreadLocalTest.EndTest();
      }


      #region Web Form Designer generated code
      override protected void OnInit(EventArgs e)
      {
         //
         // CODEGEN: This call is required by the ASP.NET Web Form Designer.
         //
         InitializeComponent();
         base.OnInit(e);
         ThreadLocalTest.StartTest();
      }
      
      /// <summary>
      /// Required method for Designer support - do not modify
      /// the contents of this method with the code editor.
      /// </summary>
      private void InitializeComponent()
      {    
         this.Load += new System.EventHandler(this.Page_Load);
         this.PreRender += new System.EventHandler(this.Page_PreRender);
      }
      #endregion
   }
}

And Global.asax

Code:

using System;
using System.Collections;
using System.ComponentModel;
using System.Web;
using System.Web.SessionState;
using ClassLibraryTest;

namespace ASPNETTest 
{
   /// <summary>
   /// Summary description for Global.
   /// </summary>
   public class Global : System.Web.HttpApplication
   {
      /// <summary>
      /// Required designer variable.
      /// </summary>
      private System.ComponentModel.IContainer components = null;

      public Global()
      {
         InitializeComponent();
      }   
      
      protected void Application_Start(Object sender, EventArgs e)
      {
         log4net.Config.XmlConfigurator.Configure();
      }
 
      protected void Session_Start(Object sender, EventArgs e)
      {
      }

      protected void Application_BeginRequest(Object sender, EventArgs e)
      {
         //ThreadLocalTest.StartTest();
      }

      protected void Application_EndRequest(Object sender, EventArgs e)
      {
         //ThreadLocalTest.EndTest();
      }

      protected void Application_AuthenticateRequest(Object sender, EventArgs e)
      {

      }

      protected void Application_Error(Object sender, EventArgs e)
      {

      }

      protected void Session_End(Object sender, EventArgs e)
      {

      }

      protected void Application_End(Object sender, EventArgs e)
      {

      }
         
      #region Web Form Designer generated code
      /// <summary>
      /// Required method for Designer support - do not modify
      /// the contents of this method with the code editor.
      /// </summary>
      private void InitializeComponent()
      {    
         this.components = new System.ComponentModel.Container();
      }
      #endregion
   }
}

I did my best to load test this on my PC, here's the test result:
1. If running the test as it is (i.e. start the test on page init, end it on page unload), then there's no error. Thread local and Context local agrees with each other.
2. If we comment out the start/end at page level, and uncomment the start/end at Global.asax, errors would show up.

So if the test case and test run is correct, it seems that some asynchronous processing is indeed happening in ASP.NET, but the page processing is still done on the same thread.

xor · **Posted:** Thu Sep 22, 2005 4:00 am

You are completely right. IHttpHandler.ProcessRequest is always processed by one thread, but full request processing includes several steps that could be served by different threads. So it's wrong to bind a session to the thread at the BeginRequest event. This is what NH FAQ is talking about.

jimjxr · **Joined:** Sun Sep 18, 2005 4:11 am **Posts:** 11

Ok, that certainly cleared up a lot of doubts, thanks.

It might also be a good idea to update the faq to clarify this, since not everyone trying to use thread locals will start the session at BeginRequest, I think the most useful case for thread local is to start/end session/transaction around service method invocations via AOP.

xor · **Posted:** Thu Sep 22, 2005 11:17 am

I just want to warn, that if session would be opened before the beginning of the method and closed upon its end, and you use serveral such methods to serve one request, then you're slowing down the performance. Opening and closing session cost time.
Today i was profiling our application and i found that mere ISession.Disconnect ate around 10% of all execution time. It was definitely a bug that it was called several thousands times in a loop and it was easy to fix. But what if your "aspected" method will be called repeatedly? I expect the same problem.

Ayende Rahien · **Posted:** Thu Sep 22, 2005 2:14 pm

I was under the impression that Sessions were cheap, isn't it so?

sergey · **Posted:** Thu Sep 22, 2005 2:27 pm

They are, but not when opened "several thousands times in a loop" :)

jimjxr · **Joined:** Sun Sep 18, 2005 4:11 am **Posts:** 11

Good advice, I'll keep that in mind. I was thinking about the performance impact of this setup the other day, but I feel it won't be much as long as the # of service method is small (say less than 5).

I'm guessing the slowdown mainly comes from open/close connections, right? If we use a connection pool (Does ADO.NET automatically give you this?), then the performance hit would be minimal, no?

xor · **Posted:** Mon Sep 26, 2005 4:08 am

No, it wasn't because of connection opening and closing. Actually all the data was already in cache, so it wasn't even trying to connect. In a loop I was calling Session.Reconnect, then getting an object by id and calling Session.Disconnect. Reconnect was very cheap, while Disconnect was 1000 times slower. Most of the time - 99.93% - was eaten by AfterTransactionCompletion method. Most expensive of its callees are:

32.87% - SequenceHashMap.OrderedEnumerator.MoveNext;
28.22% - ...OrderedEnumerator.get_Current;
5.96% - EntityEntry.set_LockMode;

Each of those methods are not expensive by itself, but they were called around 8000 times per one call to Disconnect.

Here is the detailed trace:

Code:

100,00%   Disconnect  -  99074 ms  -  4330 calls  -  NHibernate.Impl.SessionImpl.Disconnect()
  99,93%   AfterTransactionCompletion  -  99009 ms  -  4330 calls  -  NHibernate.Impl.SessionImpl.AfterTransactionCompletion(bool)
    32,87%   MoveNext  -  32562 ms  -  33667076 calls  -  NHibernate.Util.SequencedHashMap.OrderedEnumerator.MoveNext()
      10,29%   get_Next  -  10195 ms  -  67329822 calls  -  NHibernate.Util.SequencedHashMap.Entry.get_Next()
    28,22%   get_Current  -  27962 ms  -  33662746 calls  -  NHibernate.Util.SequencedHashMap.OrderedEnumerator.get_Current()
      5,64%   get_Value  -  5591 ms  -  33662746 calls  -  NHibernate.Util.SequencedHashMap.Entry.get_Value()
    5,96%   set_LockMode  -  5901 ms  -  33662746 calls  -  NHibernate.Impl.EntityEntry.set_LockMode(LockMode)
    0,03%   Debug  -  30 ms  -  4330 calls  -  log4net.Core.LogImpl.Debug(Object)
      0,01%   Log  -  9 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Logger.Log(Type, Level,  Object, Exception)
        0,01%   IsEnabledFor  -  7 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Logger.IsEnabledFor(Level)
          0,00%   IsDisabled  -  3 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Hierarchy.IsDisabled(Level)
            0,00%   get_Configured  -  1 ms  -  4330 calls  -  log4net.Repository.LoggerRepositorySkeleton.get_Configured()
            0,00%   get_Threshold  -  0 ms  -  4330 calls  -  log4net.Repository.LoggerRepositorySkeleton.get_Threshold()
          0,00%   get_EffectiveLevel  -  1 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Logger.get_EffectiveLevel()
      0,00%   get_Logger  -  2 ms  -  4330 calls  -  log4net.Core.LoggerWrapperImpl.get_Logger()
    0,02%   get_Values  -  15 ms  -  4330 calls  -  NHibernate.Util.IdentityMap.get_Values()
      0,01%   get_Values  -  11 ms  -  4330 calls  -  NHibernate.Util.SequencedHashMap.get_Values()
        0,01%   ctor  -  6 ms  -  4330 calls  -  NHibernate.Util.SequencedHashMap.ValuesCollection.ctor(SequencedHashMap)
          0,00%   ctor  -  1 ms  -  4330 calls  -  System.Object.ctor()
    0,01%   Clear  -  13 ms  -  4330 calls  -  System.Collections.ArrayList.Clear()
    0,01%   GetEnumerator  -  12 ms  -  4330 calls  -  NHibernate.Util.SequencedHashMap.ValuesCollection.GetEnumerator()
      0,01%   ctor  -  6 ms  -  4330 calls  -  NHibernate.Util.SequencedHashMap.OrderedEnumerator.ctor(SequencedHashMap,  ReturnType)
        0,00%   ctor  -  1 ms  -  4330 calls  -  System.Object.ctor()
    0,01%   MoveNext  -  6 ms  -  4330 calls  -  System.Collections.ArrayList.ArrayListEnumeratorSimple.MoveNext()
    0,01%   GetEnumerator  -  6 ms  -  4330 calls  -  System.Collections.ArrayList.GetEnumerator()
  0,03%   CloseConnection  -  30 ms  -  38 calls  -  NHibernate.Impl.SessionFactoryImpl.CloseConnection(IDbConnection)
    0,03%   CloseConnection  -  30 ms  -  38 calls  -  sdf.Persist.Hibernate.SdfConnectionProvider.CloseConnection(IDbConnection)
      0,03%   Close  -  27 ms  -  38 calls  -  System.Data.SqlClient.SqlConnection.Close()
    0,00%   get_ConnectionProvider  -  0 ms  -  38 calls  -  NHibernate.Impl.SessionFactoryImpl.get_ConnectionProvider()
      0,00%   get_ConnectionProvider  -  0 ms  -  38 calls  -  NHibernate.Cfg.Settings.get_ConnectionProvider()
  0,02%   Debug  -  15 ms  -  4330 calls  -  log4net.Core.LogImpl.Debug(Object)
    0,01%   Log  -  9 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Logger.Log(Type, Level,  Object, Exception)
      0,01%   IsEnabledFor  -  8 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Logger.IsEnabledFor(Level)
        0,00%   IsDisabled  -  3 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Hierarchy.IsDisabled(Level)
          0,00%   get_Threshold  -  1 ms  -  4330 calls  -  log4net.Repository.LoggerRepositorySkeleton.get_Threshold()
          0,00%   get_Configured  -  1 ms  -  4330 calls  -  log4net.Repository.LoggerRepositorySkeleton.get_Configured()
        0,00%   get_EffectiveLevel  -  1 ms  -  4330 calls  -  log4net.Repository.Hierarchy.Logger.get_EffectiveLevel()
    0,00%   get_Logger  -  0 ms  -  4330 calls  -  log4net.Core.LoggerWrapperImpl.get_Logger()
  0,00%   CloseCommands  -  1 ms  -  38 calls  -  NHibernate.Impl.BatcherImpl.CloseCommands()
    0,00%   GetEnumerator  -  0 ms  -  76 calls  -  Iesi.Collections.DictionarySet.GetEnumerator()
      0,00%   GetEnumerator  -  0 ms  -  76 calls  -  System.Collections.Hashtable.KeyCollection.GetEnumerator()
      0,00%   get_Keys  -  0 ms  -  76 calls  -  System.Collections.Hashtable.get_Keys()
    0,00%   Clear  -  0 ms  -  76 calls  -  Iesi.Collections.DictionarySet.Clear()
      0,00%   Clear  -  0 ms  -  76 calls  -  System.Collections.Hashtable.Clear()
    0,00%   MoveNext  -  0 ms  -  76 calls  -  System.Collections.Hashtable.HashtableEnumerator.MoveNext()

jimjxr · **Joined:** Sun Sep 18, 2005 4:11 am **Posts:** 11

That's something interesting to know... The time spent is proportional to # of objects in the cache, right? So, more objects in cache, slower the close/disconnect of a session...

TJ · **Posted:** Wed Dec 21, 2005 4:57 pm

So what does that mean exactly? Right now I have this:

protected void Application_BeginRequest(Object sender, EventArgs e)
{
NHibernate.Cfg.Configuration cfg = new NHibernate.Cfg.Configuration();
cfg.AddAssembly("nHibernateTestData");
NHibernate.ISessionFactory _sessionFactory = cfg.BuildSessionFactory();
NHibernate.ISession session = _sessionFactory.OpenSession();

HttpContext.Current.Items["NHibernateSession"] = session;
}

protected void Application_EndRequest(Object sender, EventArgs e)
{
NHibernate.ISession session = (NHibernate.ISession) HttpContext.Current.Items["NHibernateSession"];
session.Close();
}

I'm not going to write a million lines of code to fix this - I need a simple answer on what is an acceptable solution. Please be specific.

dblock · **Joined:** Wed Dec 14, 2005 3:29 pm **Posts:** 16

[code]
100,00% Disconnect - 99074 ms - 4330 calls - NHibernate.Impl.SessionImpl.Disconnect()
99,93% AfterTransactionCompletion - 99009 ms - 4330 calls - NHibernate.Impl.SessionImpl.AfterTransactionCompletion(bool)
32,87% MoveNext - 32562 ms - 33667076 calls -
[/quote]

Hey, what do you use to generate this trace?

Thx
dB.

Pilotbob · **Joined:** Mon May 16, 2005 2:15 pm **Posts:** 59

TJ wrote:

So what does that mean exactly? Right now I have this:

protected void Application_BeginRequest(Object sender, EventArgs e)
{
NHibernate.Cfg.Configuration cfg = new NHibernate.Cfg.Configuration();
cfg.AddAssembly("nHibernateTestData");
NHibernate.ISessionFactory _sessionFactory = cfg.BuildSessionFactory();
NHibernate.ISession session = _sessionFactory.OpenSession();

HttpContext.Current.Items["NHibernateSession"] = session;
}

protected void Application_EndRequest(Object sender, EventArgs e)
{
NHibernate.ISession session = (NHibernate.ISession) HttpContext.Current.Items["NHibernateSession"];
session.Close();
}

I'm not going to write a million lines of code to fix this - I need a simple answer on what is an acceptable solution. Please be specific.

You shouldn't do this. You are creating the session factory on every request. You should move that code to the Application_OnStart and only create the new session in the BeginRequest.

BOb

xor · **Posted:** Fri Jan 27, 2006 11:07 am

dblock wrote:

Hey, what do you use to generate this trace?

JetBrain's DotTrace. Highly recommend to try. :)