[Buildbot-commits] [Buildbot] #2256: sqlite is fantastically slow on blelbach-4

[Buildbot]

#2256: sqlite is fantastically slow on blelbach-4
-------------------+-------------------------
Reporter:  dustin  |      Owner:
    Type:  defect  |     Status:  new
Priority:  minor   |  Milestone:  0.8.7
 Version:  0.8.6   |   Keywords:  performance
-------------------+-------------------------
 Look at these times:
 {{{
 2012-03-22 21:42:22-0600 [-] Log opened.
 2012-03-22 21:42:22-0600 [-] -->
 buildbot.test.integration.test_upgrade.TestWeirdChanges.testUpgradeChangeNoRevision
 <--
 2012-03-22 21:42:22-0600 [-] cleaning database sqlite://
 2012-03-22 21:42:22-0600 [-] Setting up database with URL
 'sqlite:///state.sqlite'
 2012-03-22 21:42:22-0600 [-] setting database journal mode to 'wal'
 2012-03-22 21:42:22-0600 [-] using SQLAlchemy-Migrate version 0.7.1
 2012-03-22 21:42:24-0600 [-] migrating schema version 0 -> 1
 2012-03-22 21:42:25-0600 [-] migrating schema version 1 -> 2
 2012-03-22 21:42:27-0600 [-] migrating schema version 2 -> 3
 2012-03-22 21:42:28-0600 [-] migrating schema version 3 -> 4
 2012-03-22 21:42:29-0600 [-] migrating schema version 4 -> 5
 2012-03-22 21:42:33-0600 [-] migrating schema version 5 -> 6
 2012-03-22 21:42:33-0600 [-] migrating schema version 6 -> 7
 2012-03-22 21:42:34-0600 [-] migrating schema version 7 -> 8
 2012-03-22 21:42:34-0600 [-] migrating schema version 8 -> 9
 2012-03-22 21:42:34-0600 [-] migrating schema version 9 -> 10
 2012-03-22 21:42:35-0600 [-] migrating schema version 10 -> 11
 2012-03-22 21:42:36-0600 [-] migrating schema version 11 -> 12
 2012-03-22 21:42:37-0600 [-] migrating schema version 12 -> 13
 2012-03-22 21:42:37-0600 [-] migrating schema version 13 -> 14
 2012-03-22 21:42:38-0600 [-] migrating schema version 14 -> 15
 2012-03-22 21:42:38-0600 [-] migrating schema version 15 -> 16
 2012-03-22 21:42:38-0600 [-] migrating schema version 16 -> 17
 2012-03-22 21:42:40-0600 [-] migrating schema version 17 -> 18
 2012-03-22 21:42:41-0600 [-] migrating schema version 18 -> 19
 2012-03-22 21:42:42-0600 [-] migrating schema version 19 -> 20
 2012-03-22 21:42:42-0600 [-] migrating schema version 20 -> 21
 2012-03-22 21:42:42-0600 [-] migrating schema version 21 -> 22
 2012-03-22 21:42:43-0600 [-] Main loop terminated.
 }}}

 I took a brief look at dtruss output, but its timing information doesn't
 make sense to me - it claims to be in usec, but seems to actually be in
 units 1/65536 of a second.  And I'm not sure if the decoration of each
 syscall is when the syscall *started* or when it *completed*.

 It *looks* like the fsync operations at WAL check points take 100's of
 msec, which would certainly explain this behavior.

 The drive in this system is a Hitachi HTS545050B9SA02.  My r5 Mac Mini
 (Lion) shows the same behavior.  This runs fine on my Macbook (Snow
 Leopard).

 This runs a lot faster (although not blindingly fast) if I turn off WAL
 mode.

 I'm running sqlite3 3.7.8.  The buildslave has 3.7.7.

-- 
Ticket URL: <http://trac.buildbot.net/ticket/2256>
Buildbot <http://buildbot.net/>
Buildbot: build/test automation