JIT loads vs Full record load

Since the time when I came across this post by Waldo (or actually, he mentioned his test results in one online discussion) I was curious to try it myself and dig into its unexpected results. The question explored in that post was what is better... No, "better" not the right word here. Rather the question is which of the two offences against code performance has more serious consequences: loading the full record, completely omitting SetLoadFields, or referencing a field which was not included in the loaded set.

At first, it seems that the latter must be slower because as soon as BC runtime identifies a record field which was not included in SetLoadFields arguments and thus, not included in the record data, it triggers another SQL query to fetch the missing data (just in time or JIT load). And sure, two SQL queries must be slower than one. But unexpectedly, it turns out that JIT loads are still faster than reading the full record without SetLoadFields. Not as fast as a proper SetLoadFields with all the required fields in place, but still faster than no SetLoadFields at all. Not doubting the test results (but still having reproduced it myself) I am curious about the cause of this effect. Unfortunately, there is no magic in this world, and everything must have a logical explanation, even unexpectedly fast just in time data loads in Business Central.

What is the FAST N query option

Before delving into this JIT load behaviour, I need to take a step back and write about one query option which BC runtime appends to every query generated from AL code. I mean OPTION(FAST 50). I was going to do it for a while, but could never find a good context for some practical examples. And now it perfectly fits into the context, because this option is essential for understanding of the JIT effect.

Let's take the following code as an example:

StartTime := Time;

ItemLedgerEntry.FindSet();
repeat
    Quantity := ItemLedgerEntry.Quantity;
    break;
until ItemLedgerEntry.Next() = 0;

Message('Execution time: ' + Format(Time - StartTime) + ' ms');

My Item Ledger Entry table has over 1.5 million records, so it takes a while for SQL Server to scan it and return all rows back to BC. But I don't need all records, I only need the first one, and I am such a lazy programmer that I did not even think about using FindFirst to fetch only the first record, and simply discard all the rest of the dataset. What a waste!

But let's have a look at the message that shows the time it takes to run this code.

Wow! That was fast! But how can it be only 4 milliseconds? No way the whole table with 1 500 000 records could be read in this time.

If I run the same query in SQL Server Management Studio and look at the client statistics, it will show me this picture.

Indeed, the total execution time for the query is almost 6 seconds, but the "Wait time on server replies" is only 2 ms. This means that the client starts receiving data from the server already after 2 ms after it started, all thanks to the FAST 50 option. This option instructs the query optimizer to prioritize execution plans which can return the first 50 records as fast as possible, while the rest of the table data may be retrieved slower. This may result in a longer overall query execution time, but on the other hand, it allows Business Central to start processing the first batch of records earlier, while SQL Server continues reading the table at the same time.

So now we know how my foolish code can be executed so fast, despite all my efforts to slow it down. BC runtime is not passively waiting for the FindSet to come back with the full recordset, but enters the repeat..until loop as soon as the fist 50 records are received. And this takes just around 2-3 milliseconds.

But what about the SQL Server side? Does it continue running the long query, consuming the server resources on the job that is going to be thrown away? We can find it out looking at the query statistics in the query store.

select
	query_text.query_sql_text,
	query_stats.execution_type,
	query_stats.execution_type_desc,
	query_stats.last_duration,
	query_stats.last_cpu_time
from sys.query_store_query query
	join sys.query_store_query_text query_text on query.query_text_id = query_text.query_text_id
	join sys.query_store_plan query_plan on query_plan.query_id = query.query_id
	join sys.query_store_runtime_stats query_stats on query_stats.plan_id = query_plan.plan_id

And the query store tells us that the query did not run to the end, but was aborted by the client (execution_type = 3 is an abort request initiated by the client).

The time unit in query store stats is microsecond, so the last duration here is 2.4 ms. We see that not only Business Central server is not waiting for the query to complete before starting any processing, it also actively interrupts the query as soon as it becomes clear that its result is no loner required.

Does it mean that I am defeated and can't write code so dumb that it is impossible to optimize? No, of course I still can have it my way. I already mentioned the effect of blocking operators on the query execution, and this is where I can use this effect. All I need is to sort the recordset on a field that does not have an index to rely on. It can be Posting Date, for instance.

StartTime := Time;

ItemLedgerEntry.SetCurrentKey("Posting Date");
ItemLedgerEntry.FindSet();
repeat
    Quantity := ItemLedgerEntry.Quantity;
    break;
until ItemLedgerEntry.Next() = 0;

Message('Execution time: ' + Format(Time - StartTime) + ' ms');

And Boom!

Now SQL Server has to read the whole table and sort all rows before sending the data back, so the FAST 50 option does not work anymore.

Back to JIT loads

Now that we know that Business Central architecture prioritizes parallelization of work between BC and the database server, and can actively identify and interrupt a running query when its results become unusable, we can take a closer look at the JIT load scenario.

ItemLedgerEntry.SetLoadFields("Invoiced Quantity");
ItemLedgerEntry.FindSet();
repeat
    I += 1;
    Total += ItemLedgerEntry."Invoiced Quantity";
    Total += ItemLedgerEntry."Remaining Quantity";
until (ItemLedgerEntry.Next() = 0) or (I = 10000);

In this code, I want to count the total sum of Total Quantity and Remaining Quantity of the first 10000 item ledger entries. But of course, as a lazy developer, I included only one of the fields in the loaded set, and sure I don't use static code analyzers that could warn me about this mistake.

But as a curious explorer, I arm myself with the debugger and SQL Server profiler and start tracing the code.

First SQL query in this code is sent, unsurprisingly enough, when the runtime hits the FindSet function.

SELECT
    "32"."timestamp","32"."Entry No_","32"."Item No_",
    "32"."Invoiced Quantity",
    "32"."Source Type","32"."Job No_",
    "32"."Originally Ordered No_","32"."$systemId",
    "32"."$systemCreatedAt","32"."$systemCreatedBy",
    "32"."$systemModifiedAt","32"."$systemModifiedBy"
FROM "default".dbo."CRONUS Copy$Item Ledger Entry$437dbf0e-84ff-417a-965d-ed2bb9650972" "32"  WITH(READUNCOMMITTED)  
ORDER BY "Entry No_" ASC OPTION(FAST 50)

What is important to note is that the query selects a number of fields with Invoiced Quantity among them, but Remaining Quantity is not in the select list.

The loop on the records starts immediately once the first 50 records are returned from SQL Server - while the long query is still running, and the first two lines inside the loop are executed without any problems. But the attempt to access the value of the Remaining Quantity field is unsuccessful: this value is not available in the loaded dataset. And this statement triggers another SQL query:

SELECT
    <All table fields here>
FROM "default".dbo."CRONUS Copy$Item Ledger Entry$437dbf0e-84ff-417a-965d-ed2bb9650972" "32"  WITH(READUNCOMMITTED) 
WHERE ("32"."Entry No_"=@0)

This query retrieves all fields from the Item Ledger Entry table, but only for the current record that the AL statement references. Now we can complete the current iteration of the loop and hit the Next statement. Which now triggers yet another query.

SELECT TOP (@0)
    "32"."timestamp","32"."Entry No_","32"."Item No_",
    "32"."Remaining Quantity","32"."Invoiced Quantity",
    "32"."Source Type","32"."Job No_","32"."Originally Ordered No_",
    "32"."$systemId","32"."$systemCreatedAt",
    "32"."$systemCreatedBy","32"."$systemModifiedAt",
    "32"."$systemModifiedBy" 
FROM "default".dbo."CRONUS Copy$Item Ledger Entry$437dbf0e-84ff-417a-965d-ed2bb9650972" "32"  WITH(READUNCOMMITTED)  
WHERE ("32"."Entry No_">@1) 
ORDER BY "Entry No_" ASC OPTION(FAST 50)

And arguments sent to the procedure are @0=50,@1=1

At this step, the runtime, having identified all fields which were referenced in the loop, selects the next 50 records. This time limiting the selection list to the fields actually touched by the AL code.

And finally, when the loop is done iterating over these 50 records, the rest of the table content is requested. Of course, only with the fields that the client code actually references (plus anything the BC runtime deems necessary).

SELECT 
    "32"."timestamp","32"."Entry No_","32"."Item No_",
    "32"."Remaining Quantity","32"."Invoiced Quantity",
    "32"."Source Type","32"."Job No_","32"."Originally Ordered No_",
    "32"."$systemId","32"."$systemCreatedAt","32"."$systemCreatedBy",
    "32"."$systemModifiedAt","32"."$systemModifiedBy" 
FROM "default".dbo."CRONUS Copy$Item Ledger Entry$437dbf0e-84ff-417a-965d-ed2bb9650972" "32"  WITH(READUNCOMMITTED)  
WHERE ("32"."Entry No_">@0) 
ORDER BY "Entry No_" ASC OPTION(FAST 50)

Argument @0 is 51 here, so we get the rest of the table records which have not been received yet.

And what about the long query produced from my lazy code? Is it still running? Query store once again can help answer this question.

Query store tells us that the only two queries actually completed without interruption are those that selected one row and 50 rows, and their execution took 44 and 148 microseconds respectively. All the rest were aborted after running for 26 to 33 milliseconds. This is the moment when the loop completes 10000 iterations and exits. BC runtime identifies the query that is no longer needed and would be discarded anyway, and stops it.

In case of the full record load, the query also gets aborted, but after running for a little over 100 ms.

To sum up, TLDR.

When it comes to database reads, Business Central does not simply send a query to the DB server and steps aside as a passive bystander waiting for it to complete. Because of the FAST 50 option BC sends to SQL Server, it can receive the first response before the query is completed and the full result is retrieved. Besides, BC runtime can identify situations when the query result is no longer needed (due to a break or exit statement in AL code) or is invalid (due to fields referenced in AL, but missing in the recordset). In this cases the SQL query can be interrupted.

In the situation of a JIT load, BC sends not even two, but four SQL queries to select all the necessary columns, but the additional queries are fast, while the potentially long running query that selects the incorrect dataset, gets aborted.

Thanks to this clever optimisation technique implemented in the BC runtime, JIT data loads are so efficient and can be faster compared to loading the full record. Still, this optimisation is not a substitute for good coding practices. Run static code analyzers on your code and keep the CodeCop rule AA0242 enabled at all times, and the problem of "JIT loads vs no SetLoadFields at all" will remain only a curiosity for a lazy weekend debugging.