Using .ToString() on a string value can break the query translation

[fschlaef]

This is a weird one.
I noticed recently that some of my "simple" queries were sometimes performing horribly bad, especially when handling large result sets. I was surprised, because I use .Skip() and .Take() to avoid those.

When I looked at the debug logs, the SQL queries seemed good, but the actual execution of my function was still taking much, much more time that what I was getting when I pasted the SQL request into SSMS. A ~100ms query in SQL Server could take upwards of 9s in EF, despite the query being a copy&pase of what EF gave me in the first place.

I used IQueryableExtensions.ToSQL() from here : https://github.com/guillaumesp/EfCore-IQueryableExtensions-ToSql to see what was going on. All of a sudden, I started seeing warnings like this :

Microsoft.EntityFrameworkCore.Query:Warning: The LINQ expression 'where (True OrElse [so].Code.ToString().ToLower().Equals(PartialEvalException (NullReferenceException ("Object reference not set to an instance of an object."), null.ToLower())))' could not be translated and will be evaluated locally.
Microsoft.EntityFrameworkCore.Query:Warning: The LINQ expression 'Skip(0)' could not be translated and will be evaluated locally.
Microsoft.EntityFrameworkCore.Query:Warning: The LINQ expression 'Take(20)' could not be translated and will be evaluated locally.

It looked like the .Skip() and .Take() were not being actually sent to SQL Server, despite EF debug logs saying the contrary which explained the poor performance. These warnings are directly related to IQueryableExtensions being used and would not appear otherwise.

I tinkered more and more until I found the problem : using .ToString() on a string value in a .Where() condition. In my case, I had used it in two occasions. I removed both and performance was back to normal.

Admittedly, it is useless and it was an oversight on our part (thanks, copy&paste), but still, it just returns the string with no conversion, why does it break EF entirely ?

Steps to reproduce

See full repro below, the interesting line is : (Code is a string value)

.Where(so => string.IsNullOrEmpty(filter.Code) || so.Code.ToString().ToLower().Equals(filter.Code.ToLower()))

using Microsoft.EntityFrameworkCore;
using Microsoft.EntityFrameworkCore.Internal;
using Microsoft.EntityFrameworkCore.Query;
using Microsoft.EntityFrameworkCore.Query.Internal;
using Microsoft.EntityFrameworkCore.Storage;
using Microsoft.Extensions.Logging;
using Remotion.Linq.Parsing.Structure;
using System;
using System.Diagnostics;
using System.Linq;
using System.Reflection;

namespace _12824Repro
{
    public partial class Order
    {
        public int Id { get; set; }
        public string Code { get; set; }
    }

    public partial class MyContext : DbContext
    {
        public virtual DbSet<Order> Order { get; set; }

        protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        {
            string connectionString = "Server=.;Database=Repro12824;Trusted_Connection=True;MultipleActiveResultSets=true";

            optionsBuilder.UseSqlServer(connectionString)
                .EnableSensitiveDataLogging()
                .UseLoggerFactory(new LoggerFactory().AddDebug(LogLevel.Debug));
        }

        protected override void OnModelCreating(ModelBuilder modelBuilder)
        {
            modelBuilder.Entity<Order>(entity =>
            {
                entity.Property(e => e.Id).HasColumnName("id");

                entity.Property(e => e.Code)
                    .IsRequired()
                    .HasColumnName("code")
                    .HasMaxLength(50);
            });
        }
    }

    public class OrderFilter
    {
        public string Code { get; set; }
        public int Skip { get; set; } = 0;
        public int Take { get; set; } = 20;
    }

    class Program
    {
        static void Main(string[] args)
        {
            using (var context = new MyContext())
            {
                context.Database.EnsureDeleted();
                context.Database.EnsureCreated();

                var filter = new OrderFilter();
                var orders = context.Order
                    .Where(so => string.IsNullOrEmpty(filter.Code) || so.Code.ToString().ToLower().Equals(filter.Code.ToLower())) // Order.Code is a string value, by calling ToString() on it we break the SQL translation
                    //.Where(so => string.IsNullOrEmpty(filter.Code) || so.Code.ToLower().Equals(filter.Code.ToLower())) // This works perfectly fine
                    .Select(o => new
                    {
                        o.Id,
                        o.Code
                    });

                int total = orders.Count();
                var data = orders.Skip(filter.Skip).Take(filter.Take);

                Debug.WriteLine("REQUEST : " + IQueryableExtensions.ToSql(data));

                var result = data.ToList();
            }
        }
    }

    public static class IQueryableExtensions
    {
        private static readonly TypeInfo QueryCompilerTypeInfo = typeof(QueryCompiler).GetTypeInfo();
        private static readonly FieldInfo QueryCompilerField = typeof(EntityQueryProvider).GetTypeInfo().DeclaredFields.First(x => x.Name == "_queryCompiler");
        private static readonly FieldInfo QueryModelGeneratorField = QueryCompilerTypeInfo.DeclaredFields.Single(x => x.Name == "_queryModelGenerator");//NodeTypeProvider
        private static readonly FieldInfo NodeTypeProviderField = typeof(QueryModelGenerator).GetField("_nodeTypeProvider", BindingFlags.NonPublic | BindingFlags.Instance);
        private static readonly MethodInfo CreateQueryParserMethod = typeof(QueryModelGenerator).GetMethod("CreateQueryParser", BindingFlags.NonPublic | BindingFlags.Instance);
        private static readonly FieldInfo DataBaseField = QueryCompilerTypeInfo.DeclaredFields.Single(x => x.Name == "_database");
        private static readonly PropertyInfo DatabaseDependenciesField = typeof(Database).GetTypeInfo().DeclaredProperties.Single(x => x.Name == "Dependencies");

        public static string ToSql<TEntity>(this IQueryable<TEntity> query) where TEntity : class
        {
            if (!(query is EntityQueryable<TEntity>) && !(query is InternalDbSet<TEntity>))
            {
                throw new ArgumentException("Invalid query");
            }

            var queryCompiler = (QueryCompiler)QueryCompilerField.GetValue(query.Provider);
            var queryModelGenerator = (QueryModelGenerator)QueryModelGeneratorField.GetValue(queryCompiler);
            var nodeTypeProvider = (INodeTypeProvider)NodeTypeProviderField.GetValue(queryModelGenerator);
            var parser = (IQueryParser)CreateQueryParserMethod.Invoke(queryModelGenerator, new object[] { nodeTypeProvider });
            var queryModel = parser.GetParsedQuery(query.Expression);
            var database = DataBaseField.GetValue(queryCompiler);
            var databaseDependencies = (DatabaseDependencies)DatabaseDependenciesField.GetValue(database);
            var queryCompilationContext = databaseDependencies.QueryCompilationContextFactory.Create(false);
            var modelVisitor = (RelationalQueryModelVisitor)queryCompilationContext.CreateQueryModelVisitor();
            modelVisitor.CreateQueryExecutor<TEntity>(queryModel);
            var sql = modelVisitor.Queries.First().ToString();

            return sql;
        }

    }
}

So, the issues :

• Using string.ToString() breaks SQL translation
• Queries generated by EF in debug are not necessarily being the one actually executed
• Important warnings that do not appear without special tools

Further technical details

EF Core version: 2.1.1 (also reproduces on 2.1.0)
Database Provider: Microsoft.EntityFrameworkCore.SqlServer
Operating system: Windows 7
IDE: Visual Studio 2017 15.7.5

[ajcvickers]

@fschlaef Can you post the output from the debug logs that indicate the Where clause was being translated?

[fschlaef]

I am no longer able to reproduce the bug, but I still managed to get some logs. They are virtually identical, indicating I am probably wrong in my diagnostic.

Here are both logs for reference, both from the original software, not the repro above.

query_without_tostring_on_string.txt
query_with_tostring_on_string.txt

One thing I did though was shrink my database log file, which was capped at 10GB. I will investigate more in that direction.

[fschlaef]

I am completely unable to reproduce this bug. Please close this issue as the problem is almost certainly not what I originally thought anyway. Sorry !