[bind10-dev] it takes long time to IXFR (was: Re: b10-auth stops responding for several tens of seconds after receiving IXFR)

Fri Mar 22 06:05:52 UTC 2013

Hello,

(updated the subject)

I've configured severity: DEBUG, debuglevel: 40 (DBGLVL_TRACE_BASIC).
It shows it takes very long time between DATASRC_SQLITE_CONNOPEN and
DATASRC_SQLITE_DROPCONN, which seems to be doing actual database update.

I've also tried to strace the thread accessing SQLite3 database while
receiving IXFR. The screen is flooded with many many pairs of read(2)
and lseek(2), differed in the point to seek.

--- --- --- ---
lseek(12, 563727360, SEEK_SET)          = 563727360
read(12, contents..., 1024) = 1024
--- --- --- ---

(Some parts of the log are truncated)
--- --- --- ---
HH:01:26.653 DEBUG [b10-auth.auth/29278] AUTH_RECEIVED_NOTIFY received incoming NOTIFY for zone name jp., zone class IN
HH:01:26.654 DEBUG [b10-zonemgr.zonemgr/29274] ZONEMGR_RECEIVE_NOTIFY received NOTIFY command for zone jp. (class IN)
HH:01:26.654 DEBUG [b10-zonemgr.zonemgr/29274] ZONEMGR_REFRESH_ZONE refreshing zone jp. (class IN)
HH:01:26.656 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
HH:01:26.656 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/usr/local/var/bind10/zone.sqlite3'
HH:01:26.665 INFO  [b10-xfrin.xfrin/29270] XFRIN_XFR_TRANSFER_STARTED IXFR transfer of zone jp/IN started
HH:01:26.672 DEBUG [b10-xfrin.xfrin/29270] XFRIN_GOT_INCREMENTAL_RESP got incremental response for jp/IN
HH:01:26.672 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
HH:01:26.672 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/usr/local/var/bind10/zone.sqlite3'
HH:04:18.459 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
HH:04:18.459 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
HH:04:18.461 INFO  [b10-xfrin.xfrin/29270] XFRIN_IXFR_TRANSFER_SUCCESS incremental IXFR transfer of zone jp/IN succeeded (messages: 1, changesets: 1, ...
HH:04:18.461 DEBUG [b10-xfrin.xfrin/29270] XFRIN_AUTH_LOADZONE sending Auth loadzone for origin=jp., class=IN
HH:04:18.462 DEBUG [b10-auth.auth/29278] AUTH_RECEIVED_COMMAND command 'loadzone' received
HH:04:18.462 DEBUG [b10-auth.auth/29273] AUTH_RECEIVED_COMMAND command 'loadzone' received
HH:04:18.462 DEBUG [b10-auth.auth/29277] AUTH_RECEIVED_COMMAND command 'loadzone' received
HH:04:18.462 DEBUG [b10-auth.auth/29278] AUTH_DATASRC_CLIENTS_BUILDER_COMMAND data source builder received command: LOADZONE
HH:04:18.463 DEBUG [b10-auth.auth/29273] AUTH_DATASRC_CLIENTS_BUILDER_COMMAND data source builder received command: LOADZONE
HH:04:18.463 DEBUG [b10-auth.auth/29277] AUTH_DATASRC_CLIENTS_BUILDER_COMMAND data source builder received command: LOADZONE
HH:04:18.463 DEBUG [b10-auth.datasrc/29273] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
HH:04:18.464 DEBUG [b10-auth.datasrc/29277] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
HH:04:18.464 DEBUG [b10-auth.datasrc/29278] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
HH:04:18.464 DEBUG [b10-auth.datasrc/29278] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/usr/local/var/bind10/zone.sqlite3'
HH:04:18.464 DEBUG [b10-auth.auth/29279] AUTH_RECEIVED_COMMAND command 'loadzone' received
HH:04:18.464 DEBUG [b10-auth.auth/29279] AUTH_DATASRC_CLIENTS_BUILDER_COMMAND data source builder received command: LOADZONE
HH:04:18.464 DEBUG [b10-auth.datasrc/29279] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
HH:04:18.465 DEBUG [b10-auth.datasrc/29279] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/usr/local/var/bind10/zone.sqlite3'
HH:04:18.465 DEBUG [b10-auth.datasrc/29273] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/usr/local/var/bind10/zone.sqlite3'
HH:04:18.470 DEBUG [b10-auth.datasrc/29277] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/usr/local/var/bind10/zone.sqlite3'
HH:04:18.517 DEBUG [b10-zonemgr.zonemgr/29274] ZONEMGR_RECEIVE_XFRIN_SUCCESS received XFRIN SUCCESS command for zone jp. (class IN)
HH:04:18.529 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
HH:04:18.529 DEBUG [b10-xfrin.datasrc/29270] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
HH:06:06     (Auth modules start responding with updated zone data)
HH:06:07.122 DEBUG [b10-auth.datasrc/29277] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
HH:06:07.123 DEBUG [b10-auth.datasrc/29277] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
HH:06:07.784 DEBUG [b10-auth.datasrc/29273] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
HH:06:07.785 DEBUG [b10-auth.datasrc/29273] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
HH:06:07.924 DEBUG [b10-auth.datasrc/29279] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
HH:06:07.927 DEBUG [b10-auth.datasrc/29279] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
HH:06:08.582 DEBUG [b10-auth.datasrc/29278] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
HH:06:08.585 DEBUG [b10-auth.datasrc/29278] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
--- --- --- ---

Thanks,

On Tue, 19 Mar 2013 09:19:32 -0700
JINMEI Tatuya / 神明達哉 <jinmei at isc.org> wrote:

> At Tue, 19 Mar 2013 14:59:48 +0900,
> Yoshitaka Aharen <aharen at jprs.co.jp> wrote:
> 
> > We've been running BIND10 1.0.0 in our test environment which retrieves
> > periodic jp zone transfer into in-memory DB with SQLite3 backend.
> > Retrieving IXFR consists of 2 parts: SQLite3 update by Xfrin module and
> > (full) zone reload of Auth modules.
> > The time required to SQLite3 DB update depends on the number of updated
> > records and it takes about 2.5 minutes for 70 records of update in
> > average. It seems to be bit slower, but it should be because the test
> > environment is old; 2 AMD Opteron 275 processor and 8GB of memory,
> > 1.5Gbps SATA 250GB HDD.
> 
> Thanks for the experiments.  The update speed seems to be too slow
> (taking more than 2sec for 1 update).  I don't think it's due to the
> machine power.  There should be some significant bottleneck either in
> our own code or in a way we use SQLite3.
> 
> Do you have more detailed information about which part of the update
> processing takes time?  Maybe you can experimentally increase the log
> level before performing updates and examine the detailed logs.
> 
> Thanks,
> 
> ---
> JINMEI, Tatuya
> Internet Systems Consortium, Inc.

-- 
Yoshitaka Aharen <aharen at jprs.co.jp>
Japan Registry Services Co., Ltd.