Showing posts with label coredata. Show all posts
Showing posts with label coredata. Show all posts

Saturday, 13 January 2018

Using sqlite3_analyzer to identify space usage with Core Data

When using SQLite as the backing store for your Core Data persistence store it's easy to take a hands off approach. However lifting the lid on that abstraction can provide useful insights on its effectivness. If you are wondering why the database file seems to have grown beyond your expectations or just have a general interest in digging deeper then this post is for you.

Analysing the database

One of the tools the SQLite project develops is sqlite3_analyzer to measure the efficiency of space used by individual tables and indexes within an SQLite database file. There are precompiled binary versions of the sqlite-tools available for the mac on their download page.

Update - The precompiled binary available from the SQLite web site works on macOS Sierra, but fails on High Sierra with the following error:-
dyld: Library not loaded: /System/Library/Frameworks/Tcl.framework/Versions/8.4/Tcl
  Referenced from: /Users/raymond/Downloads/sqlite-tools-osx-x86-3210000/./sqlite3_analyzer
  Reason: image not found
Abort trap: 6
This is because High Sierra ships with version 8.5 of the Tcl framework. Of course you could compile your own version of the tool from source to resolve this, but for simplicity we can update the executables rpath with the following command:-
install_name_tool -change "/System/Library/Frameworks/Tcl.framework/Versions/8.4/Tcl" "/System/Library/Frameworks/Tcl.framework/Versions/8.5/Tcl" sqlite3_analyzer


I'd previously written about finding the underlying sqlite database file here.

So what does sqlite3_analyzer give us, let's use an example by creating a database via Core Data, with a entity Person and add 1 million entries into the database. sqlite3_analyzer gives a lot of information, so i've included only an extract of the overall output here.


The report starts with statistics for the overall database file and then breaks down in to sections for each table and index. For this discussion let us constrain ourselves to the top level information of the overall database. The report contains a handy definitions section at the bottom in case you require a more verbose description of each term in the report.

The section "Page counts for all tables with their indices" is very useful to see which tables are using most of the space within the file. In this example we can see the ZPERSON table is consuming 99.84% of the overall file. The other tables prefixed with Z_ are used by Core Data to store metadata. Therefore things are looking pretty healthy in this database.

Vacuuming the clutter

One of the aspects of SQLite when deleting data is that the file size of the database does not reduce. Instead the released space is marked as been available for reuse. This makes sense as the general case of application use will cause the growth to plateau, as the inserts and deletes reach a state of equilibrium. However under special use cases where large fluctuations in the quantity of data occur, the database can be left consuming significantly more space than required. To resolve this problem SQLite has the VACUUM command. This will cause the database to be repacked to used the smallest possible space required. It is worth noting that during the process of vacuuming SQLite will temporarily copy the database, therefore as much as twice the size of the original database file is required in free space in storage.

Let's demonstrate this by deleting 30% of the data from Person in our demo database. Notice "Size of the file in bytes" remains unchanged, however "Pages on the freelist" has jumped to 29.7%.


So far we've talk purely at the SQLite level, inevitably the next question becomes how can we use the vacuum command via Core Data within our applications. Fortunately Apple has us cover in the form of the persistent store option NSSQLiteManualVacuumOption. When specified as part of the options on the NSPersistentStoreDescription will cause a full database vacuum operation to be perform when opening the persistent store.




Finally we run the sqlite3_analyzer report again after the vacuum operation. We can see the file size is now 29155328, a reduction of 36% from the original size. Additionally the values for "Pages on the freelist" are now back to zero indicting all the space within the file is in use.

Thursday, 28 December 2017

Exploring Core Data database with sqlite3 on command line

Core Data abstracts a lot of the low level details of storage away for programmers, and that’s a good thing however sometimes it’s useful to lift the lid and see what’s happening beneath. For this post I’ll be specifically looking at the SQLite persistent store, I’ll assume you already have an app using Core Data and want to glean more insight into the inner workings. Fortunately the mac comes with a command utility to open and explore sqlite databases (sqlite3), but before we can delve into the database file, we must first find the file.

Finding the database file for an iOS App
The easiest way to look inside the database file is by running your app within the iOS Simulator for Xcode. The simulator stores all of its file structure within a directory on your mac. The trick is finding it. By default the simulator will store its files in Home Directory ▷ Library ▷ Developer ▷ CoreSimulator ▷ Devices. Normally the Library folder is hidden to prevent users mucking things up, however you can access Library from the Go menu in Finder by holding the option key down while displaying the menu.



However since we’re starting to perform some advanced techniques it may be easier to perform these actions on the command line, therefore open Terminal and type the following to perform a search of all the simulator devices for a file with a given name (you can substitute the file name for your own):
find ~/Library/Developer/CoreSimulator/Devices -name CoreDataDemo.sqlite

This will print a list of all the files found with the given name. However if you have been running your app on multiple simulators then multiple files will be displayed. It may not be obvious which file is for which simulator as the folders are named after the device identifier rather than a human readable name, additionally the files are not sorted therefore the first file may not be the most recent one.


To find out the Identifier for the simulated device, we can get it in Xcode by going to the Windows menu and selecting Devices and Simulators. This will open a new window, switch tabs to Simulators and select the simulator that your interested in. The Identifier will be displayed along with the summary information.


Since this can be rather painstaking, I've written as script that will search for a given database file and display the top 5 most recently modified files and the ability to directly open them. As well as listing a human understandable version of the simulator. The findcoredata.py script can be found on GitHub.


You’ll notice that the sqlite database file may not be alone. You may also have a file with ‘wal’ suffix, this is the Write-ahead log and a file with ‘shm’ for the Shared-Memory file. If you intend to copy the database then it is important that you copy these files also.

Look, but don’t touch
It is important to remember that you should avoid making modifications to the sqlite data file as Core Data will manage that. The sqlite3 command line tool can be used to execute commands against the database.


Perhaps I'll blog more on the internal structure of the database, but for now since you know how to find and open the database happy exploration.

Saturday, 16 December 2017

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
2Bind values and the truncated version of NSSQLiteStatement that does not list the full list of Managed objects.
3List of Managed Objects returned for the query. These objects have not been faulted into memory and therefore only the Managed Object ID is outputted.
4SQLite Explain Query Plan