Core Data SQLDebug Log Levels

The first step in any performance tuning exercise is to identify the amount of execution work that is being incurred and to evaluate how performant each element is. Within the context of Core Data backed by the SQLite persistent store those elements are usually SQL statements.

While Core Data attempts to hide the SQLite backing store through abstraction. It can be beneficial for performance monitoring to understand what's going on behind the curtain.

One of the useful tools Core Data gives is the SQLDebug argument that will cause Core Data to log various events to the console. This is enabled by specifying -com.apple.CoreData.SQLDebug followed by an integer on the launch arguments within the scheme for the project.

Edit Scheme dialog pane with SQL Debug specified on launch arguments.

Logging Levels for SQLDebug

I did not find a detailed explanation of what the different log levels will give, so I decided to experiment and publish my findings here. To do that I created a project with a simple Core Data model, with a Person entity, added one million rows of test data then captured the log output for the a simple query for person row where the age is greater than 18.

let request = NSFetchRequest<NSManagedObject>(entityName: "Person")

request.predicate = NSPredicate(format: "age > %@", 18 as NSNumber)

_ = try! container.viewContext.fetch(request)

The following shows log output from query at different log levels: -

1 and above	CoreData: sql: SELECT 0, t0.Z_PK, t0.Z_OPT, t0.ZAGE, t0.ZFIRSTNAME, t0.ZLASTNAME, t0.ZPERSONID FROM ZPERSON t0 WHERE t0.ZAGE > ?
2 and above	CoreData: details: SQLite bind[0] = 18
1 and above	CoreData: annotation: sql connection fetch time: 0.4789s.
2 Only	CoreData: annotation: fetch using NSSQLiteStatement <0x60800008bf40> on entity 'Person' with sql text 'SELECT 0, t0.Z_PK, t0.Z_OPT, t0.ZAGE, t0.ZFIRSTNAME, t0.ZLASTNAME, t0.ZPERSONID FROM ZPERSON t0 WHERE t0.ZAGE > ? ' returned 688187 rows
3 and above	CoreData: annotation: fetch using NSSQLiteStatement <0x60c00009b620> on entity 'Person' with sql text 'SELECT 0, t0.Z_PK, t0.Z_OPT, t0.ZAGE, t0.ZFIRSTNAME, t0.ZLASTNAME, t0.ZPERSONID FROM ZPERSON t0 WHERE t0.ZAGE > ? ' returned 688187 rows with values: ( "<Person: 0x604000098470> (entity: Person; id: 0xd0000000000c0000 <x-coredata://804E31B9-8EB9-4A42-B73D-F3B53FB47D27/Person/p3> ; data: <fault>)", "<Person: 0x600009283700> (entity: Person; id: 0xd000002632dc0000 <x-coredata://804E31B9-8EB9-4A42-B73D-F3B53FB47D27/Person/p625847> ; data: <fault>)", ... "<Person: 0x60c008c939c0> (entity: Person; id: 0xd000003d08fc0000 <x-coredata://804E31B9-8EB9-4A42-B73D-F3B53FB47D27/Person/p999999> ; data: <fault>)", "<Person: 0x60c008c93a10> (entity: Person; id: 0xd000003d09000000 <x-coredata://804E31B9-8EB9-4A42-B73D-F3B53FB47D27/Person/p1000000> ; data: <fault>)" )
1 and above	CoreData: annotation: total fetch execution time: 0.6390s for 688187 rows.
4 and above	CoreData: details: SQLite: EXPLAIN QUERY PLAN SELECT 0, t0.Z_PK, t0.Z_OPT, t0.ZAGE, t0.ZFIRSTNAME, t0.ZLASTNAME, t0.ZPERSONID FROM ZPERSON t0 WHERE t0.ZAGE > ?      0 0 0 SCAN TABLE ZPERSON AS t0

After looking at the output, we can say each value will stack (in general with one exception). So specifying a log level of 3 will give all the logging events that levels 1 and 2 gave as well. To summarise the output the following table has the elements that get added at each log level.

Value	Description
1	SQL Statements, Row count and Execution time
2	Bind values and the truncated version of NSSQLiteStatement that does not list the full list of Managed objects.
3	List of Managed Objects returned for the query. These objects have not been faulted into memory and therefore only the Managed Object ID is outputted.
4	SQLite Explain Query Plan

1.