nsd users - Jan 2019 - Interpreting log messages during inbound XFR

Hi!

I just analyzed why an IXFR takes longer on one server than on another:

Server 1
14:21:03 vie1 nsd[25852]: notify for xxx. from 11.22.33.44 serial 2019011730
14:21:04 vie1 nsd[669]: xfrd: zone xxx committed "received update to
serial 2019011730 at 2019-01-17T14:21:04 from 11.22.33.44 TSIG verified
with key rcode0-distribution"
14:21:10 vie1 nsd[672]: zone xxx. received update to serial 2019011730
at 2019-01-17T14:21:04 from 11.22.33.44 TSIG verified with key
rcode0-distribution of 12522393 bytes in 0.448595 seconds
14:21:13 vie1 nsd[669]: zone xxx serial 2019011729 is updated to 2019011730.

Server 2
14:21:02 fra1 nsd[20402]: notify for xxx. from 11.22.33.44 serial 2019011730
14:21:03 fra1 nsd[22465]: xfrd: zone xxx committed "received update to
serial 2019011730 at 2019-01-17T14:21:03 from 11.22.33.44 TSIG verified
with key rcode0-distribution"
14:21:40 fra1 nsd[22466]: zone xxx. received update to serial 2019011730
at 2019-01-17T14:21:03 from 11.22.33.44 TSIG verified with key
rcode0-distribution of 12522393 bytes in 0.439546 seconds
14:21:44 fra1 nsd[22465]: zone xxx serial 2019011729 is updated to
2019011730.


What exactly took longer on server 2? The IXFR itself? Forking the
process which loads the new zone? Loading/hashing the new zone?

Thanks
Klaus

Hi Klaus,

On 17/01/2019 16:40, Klaus Darilion wrote:
> Hi!
>
> I just analyzed why an IXFR takes longer on one server than on another:
>
> Server 1
> 14:21:03 vie1 nsd[25852]: notify for xxx. from 11.22.33.44 serial
2019011730
> 14:21:04 vie1 nsd[669]: xfrd: zone xxx committed "received update to
> serial 2019011730 at 2019-01-17T14:21:04 from 11.22.33.44 TSIG verified
> with key rcode0-distribution"
> 14:21:10 vie1 nsd[672]: zone xxx. received update to serial 2019011730
> at 2019-01-17T14:21:04 from 11.22.33.44 TSIG verified with key
> rcode0-distribution of 12522393 bytes in 0.448595 seconds
> 14:21:13 vie1 nsd[669]: zone xxx serial 2019011729 is updated to
2019011730.
>
> Server 2
> 14:21:02 fra1 nsd[20402]: notify for xxx. from 11.22.33.44 serial
2019011730
> 14:21:03 fra1 nsd[22465]: xfrd: zone xxx committed "received update to
> serial 2019011730 at 2019-01-17T14:21:03 from 11.22.33.44 TSIG verified
> with key rcode0-distribution"
> 14:21:40 fra1 nsd[22466]: zone xxx. received update to serial 2019011730
> at 2019-01-17T14:21:03 from 11.22.33.44 TSIG verified with key
> rcode0-distribution of 12522393 bytes in 0.439546 seconds
> 14:21:44 fra1 nsd[22465]: zone xxx serial 2019011729 is updated to
> 2019011730.
>
>
> What exactly took longer on server 2? The IXFR itself? Forking the
> process which loads the new zone? Loading/hashing the new zone?
On server 2, the transfer itself took 0.43.. seconds which is slightly
faster than on server one, where it was 0.44.. seconds. That was the
data transfer itself.? The timestamps on the left of the log messages
tell that after the transfer was received.? So server2 took 37 seconds
bewteen the commit and the update processed.? And server1 only 6
seconds.? The processing itself takes about equally long, server 2 takes
4 seconds and server 1 takes 3 seconds.

So the commit writes the data into a tmp place, and then it waits for
the reload task to have a spot to work on it and apply the update. That
wait is 37 seconds, and it is other update tasks. Like a big zone or a
lot of other updates queued in front of it, and it is waiting for reload
to finish on those other zones.

Best regards, Wouter

>
> Thanks
> Klaus
> _______________________________________________
> nsd-users mailing list
> nsd-users at NLnetLabs.nl
> https://open.nlnetlabs.nl/mailman/listinfo/nsd-users