ios - SQLite 页面缓存不断增长——性能下降

Question

我们有一个 iOS 应用存在性能问题——交易时间长。涉及的一些事务很大——数百个更新，但是当问题发生时，给定事务的持续时间增加了 20 倍左右(因此它可以从 3 秒增加到 60 秒)。并且，观察交易时间(短的和长的)，可以看到给定类型的交易的时间缓慢而稳定地增长，直到突然上升的某个点。这一切似乎都与数据库大小或曾经在其中使用过的事务数有关。 (应用重启后问题依然存在。)

通过对 sqlite3_status 进行定时调用，我发现“PAGECACHE_OVERFLOW”数字似乎随着性能恶化而增长，直到“飞跃”，此时它似乎被“固定”在周围2,351,392，可能在该数字上下变化 10,000。

(在这里包含任何代码没有多大意义，因为我不知道应该包含 50,000 行中的哪一行，但如果有人愿意，我可以包含更多数据。)

这里是基本的时间数据，用来说明问题:

Line 6003: 2013-01-17 17:05:57.296 [640f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7bd7490> (operation count 50) for TestCase 31 was 0.007225
Line 6006: 2013-01-17 17:05:57.699 [640f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7bdcc50> (operation count 100) for TestCase 31 was 0.012519
Line 6008: 2013-01-17 17:05:58.130 [640f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7be3ce0> (operation count 150) for TestCase 31 was 0.012854
Line 6011: 2013-01-17 17:05:58.614 [640f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7bead70> (operation count 200) for TestCase 31 was 0.012298
Line 6013: 2013-01-17 17:05:59.117 [640f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7bf1dd0> (operation count 250) for TestCase 31 was 0.008589
Line 10158: 2013-01-17 17:10:59.635 [6e6b] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b6a370> (operation count 50) for TestCase 20 was 0.019303
Line 10161: 2013-01-17 17:11:00.526 [6e6b] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b704a0> (operation count 100) for TestCase 20 was 0.090055
Line 10164: 2013-01-17 17:11:01.354 [6e6b] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7ea94b0> (operation count 150) for TestCase 20 was 0.014182
Line 13712: 2013-01-17 17:11:08.467 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e77090> (operation count 50) for TestCase 21 was 0.014494
Line 13714: 2013-01-17 17:11:09.368 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e7dae0> (operation count 100) for TestCase 21 was 0.016176
Line 16852: 2013-01-17 17:11:15.417 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e5da90> (operation count 50) for TestCase 22 was 0.016824
Line 16854: 2013-01-17 17:11:16.469 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e81e50> (operation count 100) for TestCase 22 was 0.018769
Line 18: 2013-01-17 17:11:24.845 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b14fa0> (operation count 50) for TestCase 13 was 0.025399
Line 21: 2013-01-17 17:11:26.447 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7bd4cb0> (operation count 100) for TestCase 13 was 0.025167
Line 23: 2013-01-17 17:11:27.886 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e3acf0> (operation count 150) for TestCase 13 was 0.026859
Line 27: 2013-01-17 17:11:29.353 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7ee8920> (operation count 200) for TestCase 13 was 0.019391
Line 29: 2013-01-17 17:11:30.601 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7eef680> (operation count 250) for TestCase 13 was 0.019822
Line 5742: 2013-01-17 17:11:41.681 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x5730970> (operation count 50) for TestCase 23 was 0.081646
Line 5745: 2013-01-17 17:11:43.421 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b263f0> (operation count 100) for TestCase 23 was 0.021661
Line 5747: 2013-01-17 17:11:44.821 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7f86ff0> (operation count 150) for TestCase 23 was 0.028541
Line 5750: 2013-01-17 17:11:46.233 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b7fda0> (operation count 200) for TestCase 23 was 0.023087
Line 5752: 2013-01-17 17:11:47.696 [1b97] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e64400> (operation count 250) for TestCase 23 was 0.030041
Line 10685: 2013-01-17 17:12:04.873 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x84a0ec0> (operation count 50) for TestCase 24 was 0.030812
Line 10687: 2013-01-17 17:12:06.479 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x5728a80> (operation count 100) for TestCase 24 was 0.026640
Line 10690: 2013-01-17 17:12:08.147 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e5f130> (operation count 150) for TestCase 24 was 0.029734
Line 10692: 2013-01-17 17:12:09.807 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b0d280> (operation count 200) for TestCase 24 was 0.039982
Line 15692: 2013-01-17 17:12:20.456 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x83edb60> (operation count 50) for TestCase 25 was 0.044163
Line 15695: 2013-01-17 17:12:22.265 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b8d1c0> (operation count 100) for TestCase 25 was 0.036278
Line 15697: 2013-01-17 17:12:24.092 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e4fa90> (operation count 150) for TestCase 25 was 0.039441
Line 15700: 2013-01-17 17:12:25.957 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7f63ef0> (operation count 200) for TestCase 25 was 0.044993
Line 15702: 2013-01-17 17:12:27.844 [6473] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x84e9d00> (operation count 250) for TestCase 25 was 0.039544
Line 20761: 2013-01-17 17:12:36.498 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e7f600> (operation count 50) for TestCase 26 was 0.036249
Line 20763: 2013-01-17 17:12:39.247 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b30960> (operation count 100) for TestCase 26 was 0.058809
Line 20767: 2013-01-17 17:12:41.772 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7ea9a70> (operation count 150) for TestCase 26 was 0.048724
Line 20769: 2013-01-17 17:12:43.768 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b287b0> (operation count 200) for TestCase 26 was 0.040958
Line 20772: 2013-01-17 17:12:45.788 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7b64eb0> (operation count 250) for TestCase 26 was 0.040524
Line 17: 2013-01-17 17:12:58.002 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7f78130> (operation count 50) for TestCase 27 was 0.049245
Line 20: 2013-01-17 17:13:00.157 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7eacf20> (operation count 100) for TestCase 27 was 0.042884
Line 22: 2013-01-17 17:13:02.323 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x83e0de0> (operation count 150) for TestCase 27 was 0.043717
Line 25: 2013-01-17 17:13:04.483 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e2f690> (operation count 200) for TestCase 27 was 0.044739
Line 27: 2013-01-17 17:13:06.686 [9327] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7f6c7f0> (operation count 250) for TestCase 27 was 0.044045
Line 5109: 2013-01-17 17:13:33.149 [9613] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x8444de0> (operation count 50) for TestCase 28 was 0.054260
Line 5112: 2013-01-17 17:13:35.969 [9613] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7f6fd50> (operation count 100) for TestCase 28 was 0.065153
Line 5114: 2013-01-17 17:13:38.885 [9613] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7ee9b10> (operation count 150) for TestCase 28 was 0.046428
Line 5117: 2013-01-17 17:13:41.801 [9613] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7bc66a0> (operation count 200) for TestCase 28 was 0.057400
Line 5119: 2013-01-17 17:13:44.749 [9613] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7efadb0> (operation count 250) for TestCase 28 was 0.050737
Line 6553: 2013-01-17 17:13:52.572 [9613] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x85b71d0> (operation count 50) for TestCase 29 was 0.068941
Line 12883: 2013-01-17 17:51:57.413 [ff5f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x7e5d260> (operation count 50) for TestCase 6 was 0.217507
Line 12886: 2013-01-17 17:52:08.760 [ff5f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x84a4c60> (operation count 100) for TestCase 6 was 0.224743
Line 12888: 2013-01-17 17:52:20.051 [ff5f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x84f7110> (operation count 150) for TestCase 6 was 0.220262
Line 12891: 2013-01-17 17:52:31.397 [ff5f] [TestCase insertDependentRows:](1224) <PHI> Time to insert/update MyAppMarker <MyAppMarker: 0x8540ec0> (operation count 200) for TestCase 6 was 0.222045

所以我想问题是:有谁知道造成这种情况的可能原因，或者进一步诊断的方法吗？

更新:使用探查器的分配选项进行了一些测试。似乎很多数据库插入/更新都在 B 树(位于 PAGECACHE 中)中分配(堆)空间并且从不释放它。我想这是有道理的，但存储量似乎很大。

Answer 1

终于明白了。这是索引缺失的案例。当我运行测试足够长的时间并每隔一定时间转储数据库文件大小时，很明显操作时间几乎与数据库大小呈线性增长。

通过数据库挖掘(我没有设置它)并在没有相应索引的大表上发现了几个频繁的 WHERE 子句。添加了大约 6 个索引，性能现在接近 O(1)。

我还没有时间弄清楚 PAGECACHE 统计数据可能发生了多大程度的变化，也没有时间弄清楚明显的 SQLite 堆泄漏是否已经消失。在称其为“好”之前，我会先看一下这些头发。

已添加:一个小小的警示故事——事实证明，我添加的其中一个索引已经应该已经存在了。只有它被编码为

CREATE INDEX IF NOT EXISTS FileIdIndex ON FileMetaData (FileId)

当有一个更早的时候(在单独的模块中，用于“模块化”)

CREATE INDEX IF NOT EXISTS FileIdIndex ON Master (FileId)

因此在创建索引名称时，最好将表名作为索引名称的一部分，如“FileIdToFileMetaDataIndex”，以避免名称冲突。