bzr fast-import performance slows over time

Sat Apr 11 19:17:44 BST 2009

The commit performance is definitely on a downwards trend :-(  Log  
below.

On 9-Apr-2009, at 8:30 PM, Brian de Alwis wrote:
> Hi Ian.  With the new brisbane-core formats landed and your fast- 
> import improvements, I thought I'd give importing the NetBSD  
> repository another whirl.  I seem some interesting behaviour though  
> -- it starts off very fast (417 commits a minute!) and then slows  
> down over time.  I've appended the log from the last 5 hours.  This  
> repository has about 14 years of development, I believe this  
> repository has many many heads, which may partially account for this.
>
> This is still far speedier that the previous fast-import performance.
>
> Brian.

15:30:11 progress 10000 objects
15:30:31 progress 20000 objects
15:32:10 1000 commits processed at 417/minute (:24354)
15:35:38 2000 commits processed at 341/minute (:29396)
15:37:57 progress 30000 objects
15:41:24 3000 commits processed at 258/minute (:37985)
15:43:07 progress 40000 objects
15:43:52 4000 commits processed at 284/minute (:41857)
15:45:44 5000 commits processed at 313/minute (:45272)
15:48:32 6000 commits processed at 320/minute (:48682)
15:49:38 progress 50000 objects
15:51:37 7000 commits processed at 320/minute (:52284)
15:54:41 8000 commits processed at 321/minute (:55780)
15:58:01 9000 commits processed at 319/minute (:59044)
15:58:43 progress 60000 objects
16:01:20 10000 commits processed at 317/minute (:62926)
16:01:20 10000 commits - automatic checkpoint triggered
16:08:55 11000 commits processed at 281/minute (:67838)
16:10:58 progress 70000 objects
16:12:04 12000 commits processed at 284/minute (:71105)
16:16:18 13000 commits processed at 279/minute (:76416)
16:20:28 progress 80000 objects
16:21:15 14000 commits processed at 272/minute (:80569)
16:25:32 15000 commits processed at 269/minute (:84878)
16:30:01 progress 90000 objects
16:30:05 16000 commits processed at 265/minute (:90039)
16:33:58 17000 commits processed at 265/minute (:93597)
16:38:32 18000 commits processed at 262/minute (:96941)
16:42:55 progress 100000 objects
16:45:10 19000 commits processed at 252/minute (:100659)
16:50:19 20000 commits processed at 248/minute (:104163)
16:50:19 20000 commits - automatic checkpoint triggered
16:58:13 21000 commits processed at 237/minute (:108086)
17:01:18 progress 110000 objects
17:05:30 22000 commits processed at 230/minute (:111997)
17:13:17 23000 commits processed at 222/minute (:115316)
17:23:57 24000 commits processed at 210/minute (:118248)
17:29:06 progress 120000 objects
17:31:53 25000 commits processed at 205/minute (:120877)
17:40:56 26000 commits processed at 198/minute (:125073)
17:52:27 27000 commits processed at 189/minute (:129490)
17:53:54 progress 130000 objects
18:05:45 28000 commits processed at 180/minute (:132884)
18:18:26 29000 commits processed at 172/minute (:136751)
18:30:20 30000 commits processed at 166/minute (:139399)
18:30:20 30000 commits - automatic checkpoint triggered
18:32:14 progress 140000 objects
18:39:35 31000 commits processed at 163/minute (:142809)
18:51:18 32000 commits processed at 159/minute (:146069)
19:03:41 33000 commits processed at 154/minute (:148961)
19:06:08 progress 150000 objects
19:15:03 34000 commits processed at 151/minute (:151892)
19:28:39 35000 commits processed at 147/minute (:155357)
19:39:01 36000 commits processed at 144/minute (:159499)
19:40:48 progress 160000 objects
19:52:00 37000 commits processed at 141/minute (:166438)
20:03:38 progress 170000 objects
20:07:08 38000 commits processed at 137/minute (:171634)
20:24:54 39000 commits processed at 132/minute (:175730)
20:40:14 40000 commits processed at 129/minute (:178849)
20:40:14 40000 commits - automatic checkpoint triggered
20:40:31 Packing repository ...
21:06:47 Removing obsolete packs ...
21:14:41 progress 180000 objects
21:26:17 41000 commits processed at 115/minute (:182173)
21:41:28 42000 commits processed at 113/minute (:184814)
22:01:53 43000 commits processed at 110/minute (:189598)
22:03:09 progress 190000 objects
22:24:44 44000 commits processed at 106/minute (:194476)
22:46:00 progress 200000 objects
22:47:06 45000 commits processed at 103/minute (:200263)
23:07:27 46000 commits processed at 101/minute (:203350)
23:28:53 47000 commits processed at 98/minute (:206648)
23:48:26 progress 210000 objects
23:54:38 48000 commits processed at 95/minute (:210808)
00:19:02 49000 commits processed at 93/minute (:214365)
00:46:52 50000 commits processed at 90/minute (:219676)
00:46:52 50000 commits - automatic checkpoint triggered
00:49:15 progress 220000 objects
01:13:05 51000 commits processed at 87/minute (:223321)
01:43:17 52000 commits processed at 85/minute (:226764)
02:07:38 progress 230000 objects
02:08:18 53000 commits processed at 83/minute (:230087)
02:43:38 54000 commits processed at 80/minute (:233381)
03:16:15 55000 commits processed at 78/minute (:236709)
03:37:39 progress 240000 objects
03:41:26 56000 commits processed at 77/minute (:240459)
04:10:48 57000 commits processed at 75/minute (:245173)
04:39:45 58000 commits processed at 73/minute (:249207)
04:45:28 progress 250000 objects
05:11:24 59000 commits processed at 72/minute (:252841)
05:40:31 60000 commits processed at 71/minute (:256077)
05:40:31 60000 commits - automatic checkpoint triggered
06:07:50 61000 commits processed at 69/minute (:258884)
06:17:19 progress 260000 objects
06:40:05 62000 commits processed at 68/minute (:263273)
07:13:44 63000 commits processed at 67/minute (:267473)
07:37:24 progress 270000 objects
07:45:59 64000 commits processed at 66/minute (:271469)
08:16:35 65000 commits processed at 65/minute (:274795)
08:57:01 66000 commits processed at 63/minute (:278891)
09:08:13 progress 280000 objects
09:34:18 67000 commits processed at 62/minute (:282126)
10:14:09 68000 commits processed at 60/minute (:286666)
10:45:20 progress 290000 objects
10:55:36 69000 commits processed at 59/minute (:290777)
11:38:11 70000 commits processed at 58/minute (:297083)
11:38:11 70000 commits - automatic checkpoint triggered
12:14:38 progress 300000 objects
12:20:14 71000 commits processed at 57/minute (:300447)
13:02:09 72000 commits processed at 56/minute (:303529)
13:44:12 73000 commits processed at 55/minute (:307038)
14:18:49 progress 310000 objects
14:34:39 74000 commits processed at 53/minute (:311581)
15:20:04 75000 commits processed at 52/minute (:314945)
16:04:13 progress 320000 objects
16:05:49 76000 commits processed at 51/minute (:320107)
17:05:17 77000 commits processed at 50/minute (:323914)
18:08:07 78000 commits processed at 49/minute (:327658)
18:12:47 progress 330000 objects
19:09:52 79000 commits processed at 48/minute (:334382)
20:10:14 80000 commits processed at 46/minute (:338033)
20:10:14 80000 commits - automatic checkpoint triggered
20:10:42 Packing repository ...
21:30:50 Removing obsolete packs ...
21:49:08 progress 340000 objects
22:50:56 81000 commits processed at 43/minute (:347064)
00:02:01 progress 350000 objects
00:06:25 82000 commits processed at 42/minute (:350183)
01:21:37 83000 commits processed at 41/minute (:353278)
02:37:33 84000 commits processed at 40/minute (:356960)
03:46:55 progress 360000 objects
03:52:18 85000 commits processed at 39/minute (:360249)
05:06:27 86000 commits processed at 38/minute (:363268)
05:53:25 progress 370000 objects
06:30:53 87000 commits processed at 37/minute (:371930)
07:59:28 88000 commits processed at 36/minute (:376272)
09:26:35 progress 380000 objects
09:43:07 89000 commits processed at 35/minute (:381646)
11:38:41 90000 commits processed at 34/minute (:386176)
11:38:41 90000 commits - automatic checkpoint triggered

-- 
"Amusement to an observing mind is study." - Benjamin Disraeli