[reSIProcate] DNS performance tuning
Byron Campen
bcampen at estacado.net
Mon Jan 22 15:42:59 CST 2007
This isn't really a poll; this relies on select, which will suspend
execution until something occurs on one of the sockets in fdset. The
integer argument to selectMilliSeconds is a maximum wait-time, after
which execution will resume, regardless of whether anything worth
noting happened in fdset (this is to keep non-socket-related
processing from starving). The 10 ms delay is probably network-
related; the point of waiting on the FdSet is to allow network stuff
to get ready. So, when you call dns->lookup(), no network traffic
happens, we just queue up some work to be done, and wait until we get
the go-ahead from the kernel (by calling select). Once we are ready
to send, we do so, and select again to wait for the reply. Once you
have lots of queries in flight, you end up handling lots of them per
iteration, but early on you haven't gotten stuff pipelined yet.
Best regards,
Byron Campen
> I think I'm getting close, I'm pretty sure the problem comes from
> the way my
> DnsInterface::thread works. Mine is nearly identical to the one in
> testDns.cxx. I tightened the delay down to 1 ms but that doesn't
> fix the
> problem. Here's what I've got:
>
> class ResipDnsInterface : public DnsInterface, public ThreadIf
> {
> public:
> void thread()
> {
> while (!waitForShutdown(1))
> {
> DebugLog (<< "+++ResipDnsInterface::thread - top of
> loop");
> FdSet fdset;
> buildFdSet(fdset);
> mStub.buildFdSet(fdset);
> fdset.selectMilliSeconds(1);
> process(fdset);
> DebugLog (<< "+++ResipDnsInterface::thread - before
> mStub.process");
> mStub.process(fdset);
> DebugLog (<< "+++ResipDnsInterface::thread - after
> mStub.process");
> }
> }
> }
>
> I find it can take as much as 10 ms between dns->lookup and when
> "top of
> loop" happens. From there, it always takes 10 ms until "before
> mStub.process" appears. The actual query is fast, the "after
> mStub.process"
> log appears within 1 ms.
>
> Instead of a delay loop with polling, can you suggest a way to use a
> condition signal to trigger the thread to execute? Do I really
> need all the
> fdset stuff each time through the loop, or could I just do it once?
>
> Dave
>
> -----Original Message-----
> From: Dave Mason
> Sent: Monday, January 22, 2007 1:51 PM
> To: 'Byron Campen'
> Cc: resiprocate-devel at list.resiprocate.org
> Subject: RE: [reSIProcate] DNS performance tuning
>
> As part of another thing I was checking, I added a line to the
> constructor
> of my singleton wrapper class to set the time to live:
> RRCache::instance()->setTTL(5). This should instantiate the cache
> before
> the first lookup is ever done. However, the same delay happens on
> that
> first lookup and on every lookup that follows. I checked the cache
> times
> again, and I see that the SRV cache works fine too like the A
> record. The
> delay only happens at the very beginning before the query is
> attempted,
> sometime between dns->lookup(res, query.uri) and stub.query(...).
>
> Thanks for the help,
> Dave
>
>
> -----Original Message-----
> From: Byron Campen [mailto:bcampen at estacado.net]
> Sent: Monday, January 22, 2007 1:08 PM
> To: Dave Mason
> Cc: resiprocate-devel at list.resiprocate.org
> Subject: Re: [reSIProcate] DNS performance tuning
>
> I imagine you could be running into lazy-initialization delay. I
> know that at least the RRCache isn't initialized until the first
> access is
> attempted. I can look through the code when I get a free moment
> (unless
> someone else knows off the top of their head).
>
> Best regards,
> Byron Campen
>
>> Answering my own question a bit, I put new logs at the beginning of
>> DnsStub::query and the DnsStub::Query::Query constructor. As you
>> would expect the constructor runs near instantaneously, but the delay
>> occurs before DnsStub::query is called, 29 ms in this case.
>>
>> DEBUG | 20070122-122348.333 | dcmlaptop | SmSipMgr | RESIP:APP |
>> 2961 |
>> 182419 | app.cpp:250 | ResipDns::lookup - waiting for results
>> +++DnsStub::query: enter 1169490228.362918
>> STACK | 20070122-122348.362 | dcmlaptop | SmSipMgr | RESIP:DNS |
>> 2961 |
>> 158850 | dns/DnsStub.cxx:363 | Query ctor enter STACK |
>> 20070122-122348.363 | dcmlaptop | SmSipMgr | RESIP:DNS |
>> 2961 |
>> 158850 | dns/DnsStub.cxx:376 | DnsStub::Query::go:
>> _sip._udp.flammajobby.com
>> type(enum): 33 proto: 1
>>
>>
>> -----Original Message-----
>> From: Dave Mason
>> Sent: Monday, January 22, 2007 11:33 AM
>> To: 'Byron Campen'
>> Cc: resiprocate-devel at list.resiprocate.org
>> Subject: RE: [reSIProcate] DNS performance tuning
>>
>> Oops, meant to point out in my last mail that the log in
>> DnsStub::Query::go is at the beginning of the method, so the delay
>> has
>> already happened before that method starts. My guess is there's some
>> kind of overhead involved, which hopefully I can move or deal with.
>>
>> Regards,
>> Dave
>>
>> -----Original Message-----
>> From: Byron Campen [mailto:bcampen at estacado.net]
>> Sent: Monday, January 22, 2007 11:11 AM
>> To: Dave Mason
>> Cc: resiprocate-devel at list.resiprocate.org
>> Subject: Re: [reSIProcate] DNS performance tuning
>>
>> Well, it looks like you don't have any SRV records in your DNS,
> which
>> is what the resolver tries looking for first. When that fails, it
>> attempts an A query. So, you're having to wait for two DNS queries to
>> finish in sequence, which would explain some amount of delay. How
>> much
>> delay are you seeing?
>>
>> Best regards,
>> Byron Campen
>>
>>> Hi,
>>> I picked up a development build from svn last week and the RRCache
>>> code works great, thanks for the help on that one. However, I'm
>>> still seeing a big delay when DnsStub::Query::go: is first called.
>>> Is this because I'm specifying "transport=udp"? Is there anything I
>>> can do to reduce or eliminate this? I keep a DnsInterface thread
>>> running continuously for all my lookups so I don't need to
>>> restart it
>>> each time. I cant think of any problems with my mutex/condition
>>> that
>>> would prevent Query::go from starting.
>>>
>>> Regards,
>>> Dave
>>>
>>> Application code
>>> ----------------
>>> Constructor for singleton wrapper class:
>>> dns = new ResipDnsInterface(*stub);
>>> dns->run();
>>>
>>> Lookup code:
>>> Lock lock(lookupCompleteMutex);
>>> Condition dnsCond;
>>> DebugLog (<< "ResipDns::lookup - Looking up");
>>> dns->lookup(res, query.uri);
>>> DebugLog (<< "ResipDns::lookup - waiting for results");
>>> dnsCond.wait(lookupCompleteMutex); // signal sent from end of
>>> DnsHandler::handle
>>> InfoLog (<< "ResipDns::lookup - DNS results for " << query.uri);
>>>
>>> Stack trace
>>> -----------
>>> DEBUG | 20070119-163503.126 | dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 190616 | app.cpp:227 | ResipDns::lookup - Creating Uri:
>>> sip:flammajobby.com;transport=udp
>>> DEBUG | 20070119-163503.126 | dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 190616 | app.cpp:233 | ResipDns::lookup - Creating DnsResult DEBUG |
>>> 20070119-163503.126 | dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 190616 | app.cpp:236 | ResipDns::lookup - Looking up DEBUG |
>>> 20070119-163503.126 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 190616 | DnsResult.cxx:198 | DnsResult::lookup
>>> sip:flammajobby.com;transport=udp STACK | 20070119-163503.126 |
>>> dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 190616 | DnsResult.cxx:321 | Doing SRV lookup of
>>> _sip._udp.flammajobby.com DEBUG | 20070119-163503.126 | dcmlaptop |
>>> SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 190616 | app.cpp:250 | ResipDns::lookup - waiting for results
>>> STACK |
>>> 20070119-163503.154 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | dns/DnsStub.cxx:375 | DnsStub::Query::go:
>>> _sip._udp.flammajobby.com
>>> type(enum): 33 proto: 1
>>> STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:912 | Received SRV result for:
>>> flammajobby.com
>>> STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:915 | DnsResult::onDnsResult() 0 status=4
>>> STACK
>>> | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:978 | SRV lookup failed:
>>> _sip._udp.flammajobby.com 4
>>> STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:1024 | No SRV records for flammajobby.com.
>>> Trying A
>>> records
>>> STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | dns/DnsStub.cxx:375 | DnsStub::Query::go: flammajobby.com
>>> type(enum): 1 proto: 1
>>> STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:749 | Received dns result for:
>>> flammajobby.com
>>> STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:750 | DnsResult::onDnsResult() 0 STACK |
>>> 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:771 | Adding [ V4 10.4.5.249:5060 UDP target
>>> domain=flammajobby.com connectionId=0 ] to result set DEBUG |
>>> 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 162926 | app.cpp:66 | ResipDnsHandler::handle - received
>>> flammajobby.com STACK | 20070119-163503.155 | dcmlaptop | SmSipMgr |
>>> RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:178 | Returning next dns entry: [ V4
>>> 10.4.5.249:5060 UDP target domain=flammajobby.com connectionId=0 ]
>>> DEBUG | 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 162926 | app.cpp:74 | flammajobby.com -> [ V4 10.4.5.249:5060 UDP
>>> target domain=flammajobby.com connectionId=0 ] STACK |
>>> 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:DNS |
>>> 17423 |
>>> 162926 | DnsResult.cxx:485 | Priming [] DEBUG |
>>> 20070119-163503.155 |
>>> dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 162926 | app.cpp:78 | ResipDnsHandler::handle - complete INFO |
>>> 20070119-163503.155 | dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 190616 | app.cpp:253 | ResipDns::lookup - DNS results for
>>> sip:flammajobby.com;transport=udp INFO | 20070119-163503.156 |
>>> dcmlaptop | SmSipMgr | RESIP:APP |
>>> 17423 |
>>> 190616 | app.cpp:260 | [ V4 10.4.5.249:5060 UDP target
>>> domain=flammajobby.com connectionId=0 ]
>>>
>>> _______________________________________________
>>> resiprocate-devel mailing list
>>> resiprocate-devel at list.resiprocate.org
>>> https://list.resiprocate.org/mailman/listinfo/resiprocate-devel
>>
>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 2423 bytes
Desc: not available
URL: <http://list.resiprocate.org/pipermail/resiprocate-devel/attachments/20070122/4aa1ee1c/attachment.bin>
More information about the resiprocate-devel
mailing list