0

我们有一个遇到性能问题的 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 中）中分配（堆）空间，并且从不释放它。我想这是有道理的，但存储量似乎很大。

4

1 回答 1

2

终于想通了。这是缺少索引的情况。当我运行测试足够长的时间并每隔一段时间转储 DB 文件大小时，很明显操作时间几乎与 DB 大小呈线性增长。

翻遍数据库（我没有设置），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”，以避免名称冲突。

于 2013-01-23T00:38:33.840 回答