< Previous by Date Date Index Next by Date >
< Previous in Thread Thread Index Next in Thread >

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
>