Re: [reSIProcate] DNS performance tuning
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@xxxxxxxxxxxxxxxxxxxx
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@xxxxxxxxxxxx]
Sent: Monday, January 22, 2007 1:08 PM
To: Dave Mason
Cc: resiprocate-devel@xxxxxxxxxxxxxxxxxxxx
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@xxxxxxxxxxxxxxxxxxxx
> 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@xxxxxxxxxxxx]
> Sent: Monday, January 22, 2007 11:11 AM
> To: Dave Mason
> Cc: resiprocate-devel@xxxxxxxxxxxxxxxxxxxx
> 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@xxxxxxxxxxxxxxxxxxxx
>> https://list.resiprocate.org/mailman/listinfo/resiprocate-devel
>