LINQ queries triggers JIT a bit too much

[razzmatazz]

I was profiling our CPU-heavy application and apparently there are a lot of traces where jit is invoked to compile some lambdas when issuing a LINQ ISession.Query<TRecord>

This is noticable especially when using dotnet counters monitor -p1, example:

[System.Runtime]
    % Time in GC since last GC (%)                                 8    
    Allocation Rate (B / 1 sec)                               3.2411e+08   
    CPU Usage (%)                                                 69    
    Exception Count (Count / 1 sec)                                9    
    GC Committed Bytes (MB)                                    3,389    
    GC Fragmentation (%)                                          27.191
    GC Heap Size (MB)                                          2,344    
    Gen 0 GC Count (Count / 1 sec)                                 0    
    Gen 0 Size (B)                                               192    
    Gen 1 GC Count (Count / 1 sec)                                 0    
    Gen 1 Size (B)                                            1.1532e+08   
    Gen 2 GC Count (Count / 1 sec)                                 0    
    Gen 2 Size (B)                                            8.8658e+08   
    IL Bytes Jitted (B)                                       2.3988e+08   
    LOH Size (B)                                              4.3898e+08   
    Monitor Lock Contention Count (Count / 1 sec)                116    
    Number of Active Timers                                      312    
    Number of Assemblies Loaded                                  305    
    Number of Methods Jitted                               8,407,800    
    POH (Pinned Object Heap) Size (B)                        898,696    
    ThreadPool Completed Work Item Count (Count / 1 sec)       7,637    
    ThreadPool Queue Length                                        0    
    ThreadPool Thread Count                                       20    
    Time spent in JIT (ms / 1 sec)                               639.439
    Working Set (MB)                                           3,943    

Note Number of Methods Jitted and Time spent in JIT (ms / 1 sec)

The traces point to NhPartialEvaluatingExpressionVisitor.EvaluateSubtree as the culprit. See:

• nhibernate-core/src/NHibernate/Linq/Visitors/NhPartialEvaluatingExpressionVisitor.cs

  Lines 147 to 153 in 47992e7

  	{
  	Expression<Func<object>> lambdaWithoutParameters = Expression.Lambda<Func<object>>(Expression.Convert(subtree, typeof(object)));
  	var compiledLambda = lambdaWithoutParameters.Compile();
  	object value = compiledLambda();
  	return Expression.Constant(value, subtree.Type);
  	}

Stack trace example where application code looks like:

                var record = await db.Query<TRecord>().SingleOrDefaultAsync(
                    s => s.ColumnA == entityA
                    && s.ColumnB == entityB);

Thread (0x71E):
  [Native Frames]
  System.Private.CoreLib!System.Reflection.Emit.DynamicMethod.CreateDelegate(class System.Type,class System.Object)
  System.Linq.Expressions!System.Linq.Expressions.Compiler.LambdaCompiler.Compile(class System.Linq.Expressions.LambdaExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.EvaluateSubtree(class System.Linq.Expressions.Expression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitBinary(class System.Linq.Expressions.BinaryExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitBinary(class System.Linq.Expressions.BinaryExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitLambda(class System.Linq.Expressions.Expression`1<!!0>)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitUnary(class System.Linq.Expressions.UnaryExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Dynamic.Utils.ExpressionVisitorUtils.VisitArguments(class System.Linq.Expressions.ExpressionVisitor,class System.Linq.Expressions.IArgumentProvider)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitMethodCall(class System.Linq.Expressions.MethodCallExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  NHibernate!NHibernate.Linq.NhRelinqQueryParser.PreTransform(class System.Linq.Expressions.Expression,class NHibernate.Linq.Visitors.PreTransformationParameters)
  NHibernate!NHibernate.Linq.NhLinqExpression..ctor(value class NHibernate.Linq.QueryMode,class System.Linq.Expressions.Expression,class NHibernate.Engine.ISessionFactoryImplementor)
  NHibernate!NHibernate.Linq.DefaultQueryProvider.PrepareQuery(class System.Linq.Expressions.Expression,class NHibernate.IQuery&)
  NHibernate!NHibernate.Linq.DefaultQueryProvider.ExecuteAsync(class System.Linq.Expressions.Expression,value class System.Threading.CancellationToken)
  NHibernate!NHibernate.Linq.DefaultQueryProvider+<ExecuteAsync>d__25`1[System.__Canon].MoveNext()
  System.Private.CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
  NHibernate!NHibernate.Linq.DefaultQueryProvider.ExecuteAsync(class System.Linq.Expressions.Expression,value class System.Threading.CancellationToken)
  NHibernate!NHibernate.Linq.LinqExtensionMethods.SingleOrDefaultAsync(class System.Linq.IQueryable`1<!!0>,class System.Linq.Expressions.Expression`1<class System.Func`2<!!0,bool>>,value class System.Threading.CancellationToken)

(( private application code/scrubbed ))

  System.Private.CoreLib!System.Threading.Tasks.TaskSchedulerAwaitTaskContinuation+<>c.<Run>b__2_0(class System.Object)
  System.Private.CoreLib!System.Threading.Tasks.Task.ExecuteWithThreadLocal(class System.Threading.Tasks.Task&,class System.Threading.Thread)
  System.Private.CoreLib!System.Threading.Tasks.TaskScheduler.TryExecuteTask(class System.Threading.Tasks.Task)
  Akka!Akka.Actor.ActorCell.HandleActorTaskSchedulerMessage(class Akka.Dispatch.SysMsg.ActorTaskSchedulerMessage)
  Akka!Akka.Actor.ActorCell.SysMsgInvokeAll(value class Akka.Dispatch.SysMsg.EarliestFirstSystemMessageList,int32)
  Akka!Akka.Dispatch.Mailbox.ProcessAllSystemMessages()
  Akka!Akka.Dispatch.Mailbox.<Run>b__36_0()
  Akka!Akka.Actor.ActorCell.UseThreadContext(class System.Action)
  Akka!Akka.Dispatch.Mailbox.Run()
  System.Private.CoreLib!System.Threading.QueueUserWorkItemCallback.Execute()
  System.Private.CoreLib!System.Threading.ThreadPoolWorkQueue.Dispatch()
  System.Private.CoreLib!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()

Is this performance/jit profile intended, maybe people have workarounds?

[razzmatazz]

OK, this patch from #2948 has helped a bit (we're applying in on top of 5.3.x), but there are still some hot traces left, deeper the down the rabbit hole... not that many though!

the queries are in the form (not sure which one of the two, atm -- please ask if you need more profiling context):

db.Query<DBRecordX>().Where(c => c == entityA).ToList()

db.Query<DBRecordY>().Where(d => idList.Contains(d.Id)).ToList()

e.g.:

Thread (0x1D9):
  CPU_TIME
  System.Private.CoreLib!System.Reflection.Emit.DynamicMethod.CreateDelegate(class System.Type,class System.Object)
  System.Linq.Expressions!System.Linq.Expressions.Compiler.LambdaCompiler.Compile(class System.Linq.Expressions.LambdaExpression)
  NHibernate!NHibernate.Impl.ExpressionProcessor.FindValue(class System.Linq.Expressions.Expression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.EvaluateSubtree(class System.Linq.Expressions.Expression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitBinary(class System.Linq.Expressions.BinaryExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitLambda(class System.Linq.Expressions.Expression`1<!!0>)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitUnary(class System.Linq.Expressions.UnaryExpression)
  NHibernate!NHibernate.Linq.Visitors.NhPartialEvaluatingExpressionVisitor.Visit(class System.Linq.Expressions.Expression)
  System.Linq.Expressions!System.Dynamic.Utils.ExpressionVisitorUtils.VisitArguments(class System.Linq.Expressions.ExpressionVisitor,class System.Linq.Expressions.IArgumentProvider)
  System.Linq.Expressions!System.Linq.Expressions.ExpressionVisitor.VisitMethodCall(class System.Linq.Expressions.MethodCallExpression)

[bahusoid]

Not sure if it's the case here but If any type conversions are involved (implicit or explicit) it will still compile. For instance

int param = 1;
query.Where(e => e.NullablePropInt == param); //<-- param is implicitly converted to int?. Will be compiled

To fix it - avoid type conversions inside expressions (so in this case use int? for param):

int? param = 1; 
query.Where(e => e.NullablePropInt == param); //<-- No type conversions - no compilations

Basically just make sure that on both sides of expressions are exactly the same types.

[bahusoid]

this patch from #2948 has helped a bit (we're applying in on top of 5.3.x)

Did you apply #2448 too? It contains required optimizations

[razzmatazz]

this patch from #2948 has helped a bit (we're applying in on top of 5.3.x)

Did you apply #2448 too? It contains required optimizations

oh.. missed that, will do and report. thanks!

[razzmatazz]

ok, @bahusoid this looks much better now with both patches applied on top of 5.3.x thank you!

although i do see it to be still be hitting JIT on code like this (apparently):

int[] ids = new [] { 1, 2, 3 }
db.Query<TRecord>().Where(r => ids.Contains(r.Id))

also probably (not 100% sure based on callstacks) these:

decimal max;
db.Query<TRecord>().Where(r => r.Value < max)

I did note your note about conversions from/to nullable.s

[bahusoid]

I did note your note about conversions from/to nullable

nullable is just one example. There is plenty others cases with implicit conversions (like int -> long or int -> decimal or AnyType -> object and so on). Just make sure that on both sides of expressions are exactly the same types.

[hazzik]

Something like this could help with convert if we feel like:

if (expression.NodeType == ExpressionType.Convert)
{
    var convert = (UnaryExpression)expression;
    if (convert.IsLiftedToNull)
    {
        var v = FindValue(convert.Operand);
        if (v != null)
        {
            var type = Nullable.GetUnderlyingType(convert.Type) ?? convert.Type;
            if (type != convert.Operand.Type)
            {
                return convert.Method != null
                    ? convert.Method.Invoke(null, new[] { v })
                    : Convert.ChangeType(v, type);
            }
        }

        return v;
    }
}

[bahusoid]

Yeah sure it can be handled with some effort. Right now I can think of the following common scenarios that should be considered:

• nullable types (int -> int?);
• primitive types (int -> decimal);
• double cast (when both cases above involved int -> decimal?);