Linq performance issue with non cacheable linq query plan

[gokhanabatay]

Hi,
We have a performance issue with below linq query is not added to query plan cache. Because x.F2.Mask(6, 4, '*', MaskOption.Default) of this function call makes query uncacheable. This function is masks card number middle digits other than first 6 and last 4 digits. This api called concurrent 100 request at the same time.

First of all why this function call leads to query plan uncacheable, is this desired behaviour?
When we look at Dynatrace pure path below image added there is a suspension at QueryTranslatorImpl.Compile that I cannot understand and takes to much time to compile the query?

To report all uncacheable queries could you change QueryPlanCache.GetHqlQueryPlan log.Debug("Query plan not cacheable") to log.Warn("Query plan not cacheable {0}", queryExpression.Key) Adding elapsed time could be better for performance issues, we cannot find this issue without Dynatrace.

Environment
NHibernate 5.3.9
.net 5.0
linux container

            var transactions = Query<TxnAcquirerOnl>().WithOptions(opt => opt.SetReadOnly(true))
                                                   .Where(predicateTxnAcquirerOnl)
                                                   .OrderByDescending(order => order.Guid)
                                                   .Select(x => new GetTransactionsResponse
                                                   {
                                                       TxnGuid = x.Guid,
                                                       CardNo = x.F2.Mask(6, 4, '*', MaskOption.Default),
                                                       CardDci = x.CardDci,
                                                       CardSource = x.CardSource,
                                                       TerminalType = x.TerminalType,
                                                       TransactionName = x.TxnDef.Description.GetText(CurrentLanguage),
                                                       TxnEffect = x.TxnDef.TxnEffect,
                                                       TxnEntry = x.TxnEntry,
                                                       TransactionStatus = x.TxnStt,
                                                       TransactionDate = x.F13,
                                                       TransactionTime = x.F12,
                                                       TxnRegion = x.TxnRegion,
                                                       BinProductType = x.BinProductType,
                                                       MerchantCode = x.F42,
                                                       MerchantName = x.F43Name,
                                                       MerchantLocation = x.F43,
                                                       MerchantCity = x.F43City,
                                                       MerchantCountry = x.F43Country,
                                                       TerminalCode = x.F41,
                                                       TerminalStan = x.F11Trm,
                                                       BatchNo = x.BatchNo,
                                                       InstallCount = x.TxnAcquirerInstall.InstallCnt,
                                                       AuthCode = x.F38,
                                                       Rrn = x.F37,
                                                       ResponseCode = x.F39,
                                                       ResponseDescription = x.TxnResponseCodeDef.Description.GetText(CurrentLanguage),
                                                       Irc = x.Irc,
                                                       IrcDescription = x.TxnIrcDef.Description.GetText(CurrentLanguage),
                                                       Mcc = x.F18,
                                                       RequestDate = x.RequestDate,
                                                       RequestTime = x.RequestTime,
                                                       TransactionAmount = x.F4,
                                                       TransactionCurrency = x.F49,
                                                       BillingAmount = x.F6,
                                                       BillingCurrency = x.F51,
                                                   }).ToList()

SQL:

select
	txnacquire0_.guid as col_0_0_,
	txnacquire0_.f2 as col_1_0_,
	txnacquire0_.card_dci as col_2_0_,
	txnacquire0_.card_source as col_3_0_,
	txnacquire0_.terminal_type as col_4_0_,
	OCN_CFG.FN_GET_LANGUAGE_TEXT(txndef1_.description,
	:p0) as col_5_0_,
	txndef1_.txn_effect as col_6_0_,
	txnacquire0_.txn_entry as col_7_0_,
	txnacquire0_.txn_stt as col_8_0_,
	txnacquire0_.f13 as col_9_0_,
	txnacquire0_.f12 as col_10_0_,
	txnacquire0_.txn_region as col_11_0_,
	txnacquire0_.bin_product_type as col_12_0_,
	txnacquire0_.f42 as col_13_0_,
	txnacquire0_.f43_name as col_14_0_,
	txnacquire0_.f43 as col_15_0_,
	txnacquire0_.f43_city as col_16_0_,
	txnacquire0_.f43_country as col_17_0_,
	txnacquire0_.f41 as col_18_0_,
	txnacquire0_.f11_trm as col_19_0_,
	txnacquire0_.batch_no as col_20_0_,
	txnacquire2_.install_cnt as col_21_0_,
	txnacquire0_.f38 as col_22_0_,
	txnacquire0_.f37 as col_23_0_,
	txnacquire0_.f39 as col_24_0_,
	OCN_CFG.FN_GET_LANGUAGE_TEXT(txnrespons3_.description,
	:p1) as col_25_0_,
	txnacquire0_.irc as col_26_0_,
	OCN_CFG.FN_GET_LANGUAGE_TEXT(txnircdef4_.description,
	:p2) as col_27_0_,
	txnacquire0_.f18 as col_28_0_,
	txnacquire0_.request_date as col_29_0_,
	txnacquire0_.request_time as col_30_0_,
	txnacquire0_.f4 as col_31_0_,
	txnacquire0_.f49 as col_32_0_,
	txnacquire0_.f6 as col_33_0_,
	txnacquire0_.f51 as col_34_0_
from
	OCN_ACQ.TXN_ACQUIRER_ONL txnacquire0_
left outer join OCN_CFG.TXN_DEF txndef1_ on
	txnacquire0_.txn_def_guid = txndef1_.guid
left outer join OCN_ACQ.TXN_ACQUIRER_INSTALL txnacquire2_ on
	txnacquire0_.guid = txnacquire2_.txn_guid
left outer join OCN_CFG.TXN_RESPONSE_CODE_DEF txnrespons3_ on
	txnacquire0_.f39 = txnrespons3_.code
left outer join OCN_CFG.TXN_IRC_DEF txnircdef4_ on
	txnacquire0_.irc = txnircdef4_.code
where
	txnacquire0_.STATUS = :p3
	and txnacquire0_.MBR_ID = :p4
	and txnacquire0_.f42 =:p5
	and cast(cast(txnacquire0_.f13 as text)|| LPAD(cast(txnacquire0_.f12 as text), '*****', '*****') as numeric('*****'))<=:p6
	and cast(cast(txnacquire0_.f13 as text)|| LPAD(cast(txnacquire0_.f12 as text), '*****', '*****') as numeric('*****'))>=:p7
order by
	txnacquire0_.guid desc

Suspension: total 51.5 ms is too much

Another pure path without Suspension but 1.72 ms too much for this kind of query for every request

[razzmatazz]

@gokhanabatay unrelated, but what is the tool you are using for profiling (in screenshots)?

[bahusoid]

First of all why this function call leads to query plan uncacheable, is this desired behaviour?

Well some parametrized lambda is executed in code rather than SQL. And those constant parameters are not part of query plan - such caching is not supported (see #2375 which might fix it)

If you have any methods which are not translated to SQL directly - try to move them out of query. So my suspect is CardNo = x.F2.Mask(6, 4, '*', MaskOption.Default). Currently it would be more effective to do it in separate cycle after query execution.

[gokhanabatay]

@gokhanabatay unrelated, but what is the tool you are using for profiling (in screenshots)?

We are using Dynatrace

[gokhanabatay]

First of all why this function call leads to query plan uncacheable, is this desired behaviour?

Well some parametrized lambda is executed in code rather than SQL. And those constant parameters are not part of query plan - such caching is not supported (see #2375 which might fix it)

If you have any methods which are not translated to SQL directly - try to move them out of query. So my suspect is CardNo = x.F2.Mask(6, 4, '*', MaskOption.Default). Currently it would be more effective to do it in separate cycle after query execution.

When we remove CardNo = x.F2.Mask(6, 4, '*', MaskOption.Default)query plan is cached but suspencion is the main problem for queries that is not cacheable(first screenshot), I could not find out reason of suspencion? Dou you have any idea? Query compile is too much expensive 51.5 ms #2375 when will you deploy this change.

To report all uncacheable queries could you change QueryPlanCache.GetHqlQueryPlan log.Debug("Query plan not cacheable") to log.Warn("Query plan not cacheable {0}", queryExpression.Key) Adding elapsed time could be better for performance issues, we cannot find this issue without Dynatrace.

Also what dou you think about logging suggestion?

[bahusoid]

but suspencion is the main problem for queries that is not cacheable

No idea about suspension. Again the only suggestion I have: just make problematic queries cacheable again by executing in code methods after query execution.

#2375 when will you deploy

When it's ready and properly reviewed (not me).

Also what do you think about logging suggestion

No objections

[gokhanabatay]

@bahusoid
When i go deep down I see an issue with all queries except Query 5 at DefaultQueryProvider.ExecuteList self time is too much.
Query 5 difference is there is no Mask method call with LinqExtensionMethodAttribute.

Query 1:

Query 2:

Query 3:

Query 4:

Query 5:

With 'Query 5' there is 893 micro seconds self time at DefaultQueryProvider.ExecuteList its acceptable so I think there is a perfromance issue with LinqExtensionMethodAttribute

Our mask method calls database function in sql and registered through session factory setup.

[LinqExtensionMethod]
 public static string Mask(this string value, int firstCharacters, int lastCharacters, char mask, MaskOption maskOption = MaskOption.Default)
{
     throw new System.NotSupportedException();
}

public enum MaskOption
{
        /// <summary>
        /// if (first + last characters).length = input.length
        /// Returns input value
        /// </summary>
        Default,
        /// <summary>
        /// if (first + last characters).length = input.length
        /// Prefer first characters to be open
        /// </summary>
        PreferFirstCharacterToBeOpen,
        /// <summary>
        /// if (first + last characters).length = input.length
        /// Prefer last characters to be open
        /// </summary>
        PreferLastCharacterToBeOpen
}

So I think the issue is in NhPartialEvaluatingExpressionVisitor but I cannot figure out which one, how to find out reason can you help?

public static PreTransformationResult PreTransform(Expression expression, PreTransformationParameters parameters)
{
		parameters.EvaluatableExpressionFilter = new NhEvaluatableExpressionFilter(parameters.SessionFactory);
		parameters.QueryVariables = new Dictionary<ConstantExpression, QueryVariable>();

		var partiallyEvaluatedExpression = NhPartialEvaluatingExpressionVisitor
				.EvaluateIndependentSubtrees(expression, parameters);

		return new PreTransformationResult(
				parameters.PreTransformer.Invoke(partiallyEvaluatedExpression),
				parameters.SessionFactory,
				parameters.QueryVariables);
}

Maybe the reason is NhPartialEvaluatingExpressionVisitor Compile call if its related with LinqExtensionMethodAttribute

private Expression EvaluateSubtree(Expression subtree)
{
	if (subtree.NodeType == ExpressionType.Constant)
	{
		var constantExpression = (ConstantExpression) subtree;
		var valueAsIQueryable = constantExpression.Value as IQueryable;
		if (valueAsIQueryable != null && valueAsIQueryable.Expression != constantExpression)
			return valueAsIQueryable.Expression;

		return constantExpression;
	}
	else
	{
		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);
	}
}

[gokhanabatay]

We changed nuget to NHibernate 5.4.0-dev.3582 and I guess find the issue @bahusoid @razzmatazz, that is similar you resolved with #2948

ExpressionProcessor compile call can we change it, its is really effects the performance very bad you can look below dynatrace outputs.

public static object FindValue(Expression expression)
{
	if (expression.NodeType == ExpressionType.Constant)
		return ((ConstantExpression) expression).Value;

	if (expression.NodeType == ExpressionType.MemberAccess)
	{
		var memberAccess = (MemberExpression) expression;
		if (memberAccess.Expression == null || memberAccess.Expression.NodeType == ExpressionType.Constant)
		{
			var constantValue = ((ConstantExpression) memberAccess.Expression)?.Value;
			var member = memberAccess.Member;
			switch (member.MemberType)
			{
				case MemberTypes.Field:
					return ((FieldInfo) member).GetValue(constantValue);
				case MemberTypes.Property:
					return ((PropertyInfo) member).GetValue(constantValue);
			}
		}
	}

	var valueExpression = Expression.Lambda(expression).Compile();
	object value = valueExpression.DynamicInvoke();
	return value;
}

[bahusoid]

I guess find the issue

Are you saying the perf is worse than in 5.3 or what? All your images are not helpful.

Compilation is not an issue. Though it can be avoided. Find what expressions are compiled and move them out of query in to parameter variables. Example:

int GetValue(int p1) => p1 *1000;
query.Where(e => e.Id == GetValue(1)); <-- GetValue(1) call will be compiled

With #2948 you can avoid compilation by moving GetValue method call out of query:

int v = GetValue(1);
query.Where(e => e.Id == v); <-- No compilation

And as I already explained in #2947 if e.Id from example above is nullable (int?) or long it will still compile. v and e.Id must be exactly of the same types to avoid compilation.