Skip to content
Search lessons, topics, tests…
Esc

    ↑ ↓ moveEnter openEsc close

    Guided course · Data Access in .NET

    EF Core Performance and Behavior: back to the course

    Module 1 · Foundations · Lesson 1 of 18

    How EF Core Runs a Query: Expression Trees, SQL, Logging and ToQueryString

    Learning outcome

    You can explain what happens between db.Products.Where(...) and rows arriving in your process. You can show the SQL for any query without running it (ToQueryString), log the SQL that does run (LogTo), tag a query so you can find it in production logs (TagWith), and say exactly which line causes a round trip. Every example in this course runs on .NET 10 with EF Core 10.0.12. Most use SQLite in memory; lessons that need SQL Server features (rowversion, retry strategies, idempotent migration scripts) run against SQL Server 2022 in Docker.

    Intuition

    A LINQ query over a DbSet is not code that runs. It is a description (an expression tree) that EF Core translates to SQL the moment you enumerate it. Until then nothing touches the database. Each execution (ToList, First, Count, Any, foreach) runs the query again, even when it reuses the same IQueryable variable. The simple single-query examples below use one command each; split queries can use several.

    flowchart LR
        A["LINQ over DbSet (IQueryable)"] --> B["Expression tree"]
        B --> C["Query cache lookup / compile"]
        C --> D["SQL + parameters"]
        D --> E["DbCommand to database"]
        E --> F["DbDataReader rows"]
        F --> G["Materialize entities, track (optional)"]

    Deep dive

    • Pipeline. EF Core parameterizes the expression (captured variables become parameters), looks it up in the compiled-query cache, translates it to SQL on a miss, executes a DbCommand, and materializes rows into objects. Tracking queries also register each entity in the change tracker (Lesson 2).
    • Deferred execution. Building IQueryable<T> does not execute the database query, but constructing its expression tree still costs CPU and allocations. ToQueryString() translates without executing. Every terminal call executes again. A query enumerated twice runs twice.
    • Seeing the SQL.
      • ToQueryString() for a single query during development or in a unit test.
      • optionsBuilder.LogTo(Console.WriteLine, ...) for simple logging. Filter it to RelationalEventId.CommandExecuted to see only executed SQL with its duration.
      • In ASP.NET Core, the Microsoft.EntityFrameworkCore.Database.Command log category at Information gives the same lines through ILogger.
      • EnableSensitiveDataLogging() adds parameter values to logs. Use it only in development, because it writes user data to logs.
    • TagWith("...") prepends a SQL comment. It shows up in logs, in Query Store and in Extended Events, so a DBA can trace a slow statement back to the endpoint.
    • Provider differences. The SQL is provider-specific: SQLite uses LIMIT/OFFSET and double quotes, SQL Server uses TOP/OFFSET FETCH and brackets. Always check the provider you deploy on.

    Code example: when does the SQL run?

    C#
    using Microsoft.EntityFrameworkCore;
    using Microsoft.EntityFrameworkCore.Diagnostics;
    
    using var db = new ShopDb();
    db.Database.OpenConnection();          // keep the in-memory SQLite database alive
    db.Database.EnsureCreated();
    db.Products.AddRange(Enumerable.Range(1, 5).Select(i => new Product { Name = $"P{i}", Price = i * 10 }));
    db.SaveChanges();
    ShopDb.Log = true;
    
    // 1. Building a query sends nothing to the database.
    IQueryable<Product> query = db.Products.Where(p => p.Price > 20).OrderBy(p => p.Name);
    Console.WriteLine("-- query built, nothing executed yet");
    
    // 2. ToQueryString shows the SQL without running it.
    Console.WriteLine("-- ToQueryString():");
    Console.WriteLine(query.ToQueryString());
    
    // 3. Enumeration executes. Each terminal operator is a new round trip.
    Console.WriteLine("-- ToList():");
    var list = query.ToList();
    Console.WriteLine($"rows = {list.Count}");
    Console.WriteLine("-- Count():");
    Console.WriteLine($"count = {query.Count()}");
    
    // 4. TagWith puts a comment in the SQL so you can find it in logs and Query Store.
    Console.WriteLine("-- TagWith:");
    var cheap = db.Products.TagWith("ProductList: cheap items").Where(p => p.Price < 20).ToList();
    
    public class Product { public int Id { get; set; } public string Name { get; set; } = ""; public int Price { get; set; } }
    
    public class ShopDb : DbContext
    {
        public static bool Log;
        public DbSet<Product> Products => Set<Product>();
        protected override void OnConfiguring(DbContextOptionsBuilder o) => o
            .UseSqlite("Data Source=:memory:")
            .LogTo(m => { if (Log) Console.WriteLine(m); }, new[] { RelationalEventId.CommandExecuted }, Microsoft.Extensions.Logging.LogLevel.Information,
                   DbContextLoggerOptions.None)
            .EnableSensitiveDataLogging();
    }

    Output (EF Core 10.0.12, SQLite in memory)

    Text
    -- query built, nothing executed yet
    -- ToQueryString():
    SELECT "p"."Id", "p"."Name", "p"."Price"
    FROM "Products" AS "p"
    WHERE "p"."Price" > 20
    ORDER BY "p"."Name"
    -- ToList():
    Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
    SELECT "p"."Id", "p"."Name", "p"."Price"
    FROM "Products" AS "p"
    WHERE "p"."Price" > 20
    ORDER BY "p"."Name"
    rows = 3
    -- Count():
    Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
    SELECT COUNT(*)
    FROM "Products" AS "p"
    WHERE "p"."Price" > 20
    count = 3
    -- TagWith:
    Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
    -- ProductList: cheap items
    
    SELECT "p"."Id", "p"."Name", "p"."Price"
    FROM "Products" AS "p"
    WHERE "p"."Price" < 20

    Code walkthrough

    • Building query printed nothing: no command was logged.
    • ToQueryString() printed SQL without an Executed DbCommand line. It translated but did not run.
    • ToList() and Count() each logged their own Executed DbCommand. Same IQueryable variable, two round trips.
    • Count() became SELECT COUNT(*) in SQL. EF did not fetch rows to count them in memory.
    • The TagWith text arrived as a -- ProductList: cheap items comment at the top of the SQL.
    • The literal 20 was inlined because it is a constant in the lambda. Captured variables become parameters (Lesson 7).

    Failure modes

    • Enumerating the same IQueryable several times (for example Any() and then ToList()), which doubles round trips.
    • Leaving EnableSensitiveDataLogging() on in production.
    • Logging at Debug level for everything, which floods logs. Filter by event or category instead.
    • Reading SQL from one provider (SQLite in tests) and assuming the same plan on another (SQL Server in production).

    Interview angle

    "How do you know what SQL EF generates?" Give three answers at three levels: ToQueryString() while writing the query, LogTo/ILogger with the Database.Command category during development, and in production TagWith plus the database's own tools (Query Store, Extended Events) or OpenTelemetry traces. Then say when it runs: at enumeration, once per terminal operator.

    Practice questions

    1. var q = db.Orders.Where(o => o.Total > 100); if (q.Any()) return q.ToList(); How many round trips?

    Answer: One if no rows match; two if they do. Any() runs an EXISTS query, and only a true result enters the branch that calls ToList(). If you need the rows anyway, call ToList() once and check Count.

    1. Does ToQueryString() hit the database?

    Answer: No. It runs translation only and returns the SQL with parameter declarations.

    1. Why is EnableSensitiveDataLogging dangerous in production?

    Answer: It writes parameter values (emails, tokens, personal data) into logs, and it also includes key values in exception messages.

    1. What does TagWith give you that logging does not?

    Answer: The tag travels inside the SQL text, so it is visible in database-side tools (Query Store, Extended Events, sys.dm_exec_query_stats text) where your application logs are not.

    Revision checklist

    • IQueryable = description; enumeration = execution.
    • One execution runs the query again; a split query can require several round trips.
    • ToQueryString() (no execution), LogTo filtered to CommandExecuted, TagWith for production tracing.
    • Sensitive data logging only in development.

    Analogy

    Everyday picture

    A shopping list vs a trip to the shop

    Writing Where(...).OrderBy(...) is writing a shopping list. Nothing is bought. ToList() is the trip to the shop. Calling Count() and then ToList() on the same list is driving to the shop twice: once to count the items on the shelf, once to buy them.

    Quick reference

    Seeing and controlling SQL

    • query.ToQueryString(): SQL without executing.
    • LogTo(Console.WriteLine, new[] { RelationalEventId.CommandExecuted }): executed SQL plus duration.
    • TagWith("Endpoint X"): comment inside the SQL for database-side tracing.
    • ToList/First/Count/Any/foreach: each executes; split queries can require multiple commands.
    • EnableSensitiveDataLogging(): development only.
    Sign in to mark lessons done and keep your place in the course.Sign in