Yup, I think this is def on our side of the fence -- we are chasing it
downstream right now -- will keep you posted!
--FritzM.
On 05/07/2015 03:18 PM, Andrew Hanushevsky wrote:
> Hi John,
>
> The defined action is that you need to delete this object after you
> have called the request object's Finished() method. No one but the
> object creator can delete that object.
>
> Andy
>
> On Thu, 7 May 2015, John Gates wrote:
>
>> I took a very close look at what's going on with the leaks. The
>> smoking gun appears to be qdisp::QueryResource.cc:line 83 bool
>> requestSent = _session->ProcessRequest(_request);
>>
>> The _request object is never delete during normal operation. It holds
>> 2 shared pointers to MergingRequester. One directly as _requester and
>> one its _retryFunc (aka DispatchAction).
>>
>> Some action needs to be taken to delete _request, which has been
>> given to xrootd. When ProcessRequest() is done, it calls
>> Executive::markCompleted() via the NotifyExecutive class.
>> Is there something we need to do with xrootd or are we supposed to
>> delete this object in the call to markCompleted()?
>>
>> -John
>>
>>
>>
>> DispatchAction - destructor not called - holds a ResponseRequestor
>> shared pointer in _spec
>> -Passed to xrootd as _retryFunc
>>
>> MergingRequester - destructor not called - because DispatchAction
>> still holds shared pointer and ?????? holds shared pointer
>>
>> QueryResource - destructor not called -
>>
>> Mgr - destructor not called because ?????
>>
>> InfileMerger - destructor not called because ????
>>
>>
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/css/Facade.cc:463) - *** qservTest_case01_qserv.Filter is NOT
>> subChunked.
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/css/Facade.cc:244) - getChunkLevel returns 0
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/qana/PostPlugin.cc:158) - Query is non-chunked
>> 0507 11:36:44.479 [0x7f28cb63f700] DEBUG qproc.QuerySession
>> (build/qproc/QuerySession.cc:118) - Query Plugins applied:
>> QuerySession::_showFinal() : parallel: SELECT * FROM
>> qservTest_case01_qserv.Filter AS QST_1_
>> QuerySession::_showFinal() : merge: SELECT *
>>
>> ****************
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/ccontrol/UserQuery.cc:269) - UserQuery uqCount=1
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/qdisp/Executive.cc:158) - Executive exCount=1
>> ***************
>>
>>
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/css/KvInterfaceImplMem.cc:128) - ***
>> KvInterfaceImplMem::exists(/DBS/qservTest_case01_qserv): YES
>> 0507 11:36:44.479 [0x7f28cb63f700] INFO root
>> (build/css/Facade.cc:105) - *** containsDb(qservTest_case01_qserv): 1
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root (app.py:343) -
>> reporting -1 100 Dispatch Query.
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/MessageStore.cc:49) - Msg: -1 100 Dispatch Query.
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root
>> (build/ccontrol/userQueryProxy.cc:105) - EXECUTING UserQuery_submit(1)
>> 0507 11:36:44.489 [0x7f28bde8a700] INFO root
>> (build/qana/ScanTablePlugin.cc:130) - Squash scan tables: <2 chunks.
>> 0507 11:36:44.489 [0x7f28bde8a700] INFO root
>> (build/ccontrol/UserQuery.cc:277) - UserQuery::_setupMerger()
>>
>> 0507 11:36:44.489 [0x7f28bde8a700] INFO root
>> (build/rproc/InfileMerger.cc:218) - Mgr mgrCount=1
>> *******************************************
>>
>> 0507 11:36:44.489 [0x7f28bde8a700] INFO root
>> (build/mysql/MySqlConnection.cc:181) - MySqlConnection::_connectHelper
>> 0507 11:36:44.489 [0x7f28bde8a700] INFO root
>> (build/ccontrol/UserQuery.cc:179) - UserQuery beginning submission
>> 0507 11:36:44.489 [0x7f28bde8a700] INFO root
>> (build/qproc/QuerySession.cc:399) - Non-subchunked
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root
>> (build/qproc/QuerySession.cc:419) - returning queries:
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root
>> (build/qproc/QuerySession.cc:421) - SELECT * FROM
>> qservTest_case01_qserv.Filter AS QST_1_
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root
>> (build/qproc/TaskMsgFactory2.cc:152) - no nextFragment
>> 0507 11:36:44.489 [0x7f28bde8a700] DEBUG root
>> (build/qproc/TaskMsgFactory2.cc:154) - SELECT * FROM
>> qservTest_case01_qserv.Filter AS QST_1_
>>
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/ccontrol/MergingRequester.cc:68) - MergingRequester mrCount=1
>> ********************************
>> ******MergingRequesterPTR ++1 local on stack mr
>> ****** ++1 local on stack s.requester
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/ccontrol/MergingRequester.cc:236) - setError
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/ccontrol/MergingRequester.cc:237) - setError 0
>>
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:203) - add TRACK s.requester.use_count()=2
>> *********************************
>> 0507 11:36:44.490 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/Executive.cc:493) - Executive (0x1a8ef30) TRACKING id=1
>> r.use_count=2 ******************
>> ******MergingRequesterPTR ++1 _requesters[1]
>> 0507 11:36:44.490 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/Executive.cc:501) - Executive TRACKING id=1
>> r.use_count=3 *****************************
>> 0507 11:36:44.490 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/Executive.cc:211) - Flag set to false 0
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:215) - Exec add
>> pth=/chk/qservTest_case01_qserv/1234567890
>> 0507 11:36:44.490 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/MessageStore.cc:49) - Msg: 1234567890 1200 Exec add
>> pth=/chk/qservTest_case01_qserv/1234567890
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:392) - _dispatchQuery TRACK start
>> use_count=3 ******************************
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:176) - DispatchAction daCount=1
>> *********************************************
>> ******MergingRequesterPTR ++1 retryFunc->DispatchAction._spec.requester
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:399) - _dispatchQuery TRACK a use_count=4
>> *********************************
>> ******MergingRequesterPTR ++1 r-> QueryResource._requester
>> ****** QueryResource has sharedptr to
>> retryFunc->DispatchAction
>> ****** r->QueryResource passed to xrootd _service->Provision(r)
>> 0507 11:36:44.490 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:407) - _dispatchQuery TRACK b use_count=5
>> **********************************
>> Opening xroot://127.0.0.1:1094//chk/qservTest_case01_qserv/1234567890
>> 0507 11:36:44.491 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:410) - _dispatchQuery TRACK c use_count=5
>> **********************************
>> 0507 11:36:44.491 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/Executive.cc:422) - Provision was ok
>> 0507 11:36:44.491 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:426) - _dispatchQuery TRACK end use_count=5
>> *********************************
>> 0507 11:36:44.491 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:221) - Executive::add end TRACK use_count=5
>> *********************************
>> 0507 11:36:44.491 [0x7f28bde8a700] INFO root
>> (build/ccontrol/UserQuery.cc:210) - UserQuery::submit end TRACK
>> requester.use_count=5 ****************
>> ******MergingRequesterPTR --1 local on stack mr
>> ****** --1 local on stack s.requester
>> 0507 11:36:44.491 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryResource.cc:56) - Provision done
>> 0507 11:36:44.491 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryResource.cc:75) - QueryResource::ProvisionDone a
>> TRACK use_count()=3 ****************
>> 0507 11:36:44.491 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryRequest.cc:92) - New QueryRequest with payload(143)
>> **************************************************************
>> ******MergingRequesterPTR ++1 QueryResource._requester
>> ****** QueryResource._requester also has shared_ptr to
>> retryFunc->DispatchAction
>> ****** is then passed to xrootd
>> _session->ProcessRequest(_request);
>> 0507 11:36:44.492 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryResource.cc:79) - QueryResource::ProvisionDone b
>> TRACK use_count()=4 ****************
>> 0507 11:36:44.492 [0x7f28a6bfd700] DEBUG root
>> (build/qdisp/QueryRequest.cc:103) - Requesting, payload size: [143]
>> Task=0x7f2898000f00 processing id=0
>> ******MergingRequesterPTR ++1 local pointer p created for logging
>> 0507 11:36:44.492 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryResource.cc:101) - QueryResource::ProvisionDone c
>> TRACK use_count()=5 *************
>> ******MergingRequesterPTR --1 QueryResource self deletes taking its
>> _requester with it
>> 0507 11:36:44.492 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryResource.cc:103) - QueryResource::ProvisionDone end
>> TRACK use_count()=4 ***********
>> ******MergingRequesterPTR --1 local pointer p drops out
>> ****** leaving use_count=3
>> 0507 11:36:44.492 [0x7f28bde8a700] INFO root (app.py:404) - Query
>> dispatch (1) took 0.006904 seconds
>> 0507 11:36:44.492 [0x7f28bde8a700] INFO root
>> (build/ccontrol/UserQuery.cc:217) - UserQuery::join TRACK
>> 0507 11:36:44.492 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:586) - Still 1 in flight.
>> Task 0x7f2898000f00 sess=ok Status = 1 isWrite
>> Task Handler calling RelBuff.
>> 0507 11:36:44.531 [0x7f28a61fc700] DEBUG root
>> (build/qdisp/QueryRequest.cc:109) - Early release of request buffer
>> Task Handler calling trunc.
>> Task 0x7f2898000f00 sess=ok Status = 1 isSync
>> Task Handler responding with stream.
>> 0507 11:36:44.533 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryRequest.cc:156) - GetResponseData with buffer of
>> 1701016181
>> Task 0x7f2898000f00 SetBuff Async Status=isReady
>> 0507 11:36:44.533 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryRequest.cc:158) - Initiated request ok
>> Task 0x7f2898000f00 sess=ok Status = 1 isReady
>> Task Handler calling ProcessResponseData.
>> 0507 11:36:44.533 [0x7f28a61fc700] INFO root
>> (build/qdisp/QueryRequest.cc:184) - ProcessResponse[data] with
>> buflen=256 (more)
>> 0507 11:36:44.533 [0x7f28a61fc700] INFO root
>> (build/ccontrol/MergingRequester.cc:92) - flush
>> state=HEADER_SIZE_WAIT blen=256 last=0
>> 0507 11:36:44.533 [0x7f28a61fc700] INFO root
>> (build/proto/ProtoHeaderWrap.cc:64) - buffer size=256 -> [[0]=28,
>> [1]=13, [2]=2, [3]=0, [4]=0, ..., [251]=48, [252]=48, [253]=48,
>> [254]=48, [255]=48]
>> 0507 11:36:44.533 [0x7f28a61fc700] DEBUG root
>> (build/ccontrol/MergingRequester.cc:107) - HEADER_SIZE_WAIT: Resizing
>> buffer to 307
>> 0507 11:36:44.533 [0x7f28a61fc700] INFO root
>> (build/qdisp/QueryRequest.cc:208) - ProcessResponse waiting for more
>> data
>> Task 0x7f2898000f00 SetBuff Async Status=isReady
>> Task 0x7f2898000f00 sess=ok Status = 1 isReady
>> Task Handler calling ProcessResponseData.
>> 0507 11:36:44.533 [0x7f28a57fb700] INFO root
>> (build/qdisp/QueryRequest.cc:184) - ProcessResponse[data] with
>> buflen=307 (more)
>> 0507 11:36:44.533 [0x7f28a57fb700] INFO root
>> (build/ccontrol/MergingRequester.cc:92) - flush state=RESULT_WAIT
>> blen=307 last=0
>> 0507 11:36:44.533 [0x7f28a57fb700] INFO root
>> (build/ccontrol/MergingRequester.cc:115) - _buffer [[0]=8, [1]=0,
>> [2]=16, [3]=1, [4]=26, ..., [302]=0, [303]=16, [304]=0, [305]=16,
>> [306]=0]
>> 0507 11:36:44.533 [0x7f28a57fb700] INFO root
>> (build/ccontrol/MergingRequester.cc:126) - Flushed msgContinues=0
>> last=0 for tableName=r_1ebceab7f925bae5a000996b370390668_1234567890_0
>> 0507 11:36:44.534 [0x7f28a57fb700] DEBUG root
>> (build/rproc/InfileMerger.cc:287) - EXECUTING
>> InfileMerger::merge(sizes=28, 307, rowcount=9)
>> 0507 11:36:44.534 [0x7f28a57fb700] DEBUG root
>> (build/rproc/InfileMerger.cc:446) - InfileMerger query prepared:
>> CREATE TABLE qservResult.result_11903762039 (`filterId` TINYINT(4),
>> `filterName` CHAR(3),
>> `photClam` FLOAT,
>> `photBW` FLOAT)
>> 0507 11:36:44.534 [0x7f28a57fb700] INFO root
>> (build/mysql/MySqlConnection.cc:181) - MySqlConnection::_connectHelper
>> 0507 11:36:44.534 [0x7f28a57fb700] INFO root
>> (build/rproc/InfileMerger.cc:358) - InfileMerger 0x7f28a8003040
>> connected to db.
>> 0507 11:36:44.617 [0x7f28a57fb700] DEBUG root
>> (build/rproc/InfileMerger.cc:369) - InfileMerger query success:
>> CREATE TABLE qservResult.result_11903762039 (`filterId` TINYINT(4),
>> `filterName` CHAR(3),
>> `photClam` FLOAT,
>> `photBW` FLOAT)
>> 0507 11:36:44.617 [0x7f28a57fb700] DEBUG root
>> (build/rproc/InfileMerger.cc:459) - InfileMerger table
>> qservResult.result_11903762039 ready
>> 0507 11:36:44.617 [0x7f28a57fb700] INFO root
>> (build/qdisp/QueryRequest.cc:208) - ProcessResponse waiting for more
>> data
>> Task 0x7f2898000f00 SetBuff Async Status=isReady
>> Task 0x7f2898000f00 sess=ok Status = 1 isReady
>> Task Handler calling ProcessResponseData.
>> 0507 11:36:44.618 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryRequest.cc:184) - ProcessResponse[data] with
>> buflen=0 (more)
>> 0507 11:36:44.618 [0x7f28a6bfd700] INFO root
>> (build/ccontrol/MergingRequester.cc:92) - flush state=RESULT_RECV
>> blen=0 last=0
>> 0507 11:36:44.618 [0x7f28a6bfd700] DEBUG root
>> (build/ccontrol/MergingRequester.cc:146) - RESULT_RECV last = 0
>> 0507 11:36:44.618 [0x7f28a6bfd700] INFO root
>> (build/qdisp/QueryRequest.cc:208) - ProcessResponse waiting for more
>> data
>> Task 0x7f2898000f00 SetBuff Async Status=isReady
>> Task 0x7f2898000f00 sess=ok Status = 1 isReady
>> Task Handler calling ProcessResponseData.
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/QueryRequest.cc:184) - ProcessResponse[data] with
>> buflen=0 (last)
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/ccontrol/MergingRequester.cc:92) - flush state=BUFFER_DRAIN
>> blen=0 last=1
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/ccontrol/MergingRequester.cc:156) - BUFFER_DRAIN last=1 bLen=0
>> buffer=[0]
>> 0507 11:36:44.618 [0x7f28a61fc700] WARN root
>> (build/qdisp/QueryRequest.cc:203) - Connection closed when more
>> information expected sz=1
>> Session Complete: cancel=0 task=ok
>> Task 0x7f2898000f00 Kill status = isDone mhpend=0
>> RelTask dodel=0 id=0
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/QueryRequest.cc:288) - Finished() ok.
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/Executive.cc:256) - Executive::markCompleted(1,1)
>> ******MergingRequesterPTR ++1 local pointer i created for logging
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/Executive.cc:283) - markCompleted TRACK ref=1
>> use_count=4 *******************************
>> ******MergingRequesterPTR ++1 local pointer p created for logging
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/Executive.cc:512) - &&& UNTRACK
>> p.use_count()=5 ***************************
>> ******MergingRequesterPTR --1 Executive._requesters erased it
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/Executive.cc:514) - &&& UNTRACK erased
>> p.use_count()=4 *************************
>> ******MergingRequesterPTR ++1 local pointer p removed
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/Executive.cc:520) - Executive (0x1a8ef30) UNTRACKING
>> id=1 ***************************
>> 0507 11:36:44.618 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:592) - Executive::_waitAllUntilEmpty()
>> TRACK ************************
>> 0507 11:36:44.618 [0x7f28a61fc700] INFO root
>> (build/qdisp/Executive.cc:286) - markCompleted end TRACK ref=1
>> use_count=3 ***********************
>> ******MergingRequesterPTR --1 local pointer i removed, use_count=2
>> 0507 11:36:44.618 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:232) - entry state:0x7f28a800d480
>> Resource(/chk/qservTest_case01_qserv/1234567890): 20150507-11:36:44,
>> Complete (success), 0, )
>> 0507 11:36:44.618 [0x7f28bde8a700] INFO root
>> (build/qdisp/Executive.cc:243) - Query exec finish. 1 dispatched.
>> 0507 11:36:44.618 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/MessageStore.cc:49) - Msg: 1234567890 2000 Complete
>> (success) 0 1431023804
>> 0507 11:36:44.618 [0x7f28bde8a700] DEBUG root
>> (build/qdisp/Executive.cc:250) - Flag set to _empty=1 sCount=1
>> requestCount=1
>> 0507 11:36:44.618 [0x7f28bde8a700] INFO root
>> (build/rproc/InfileMerger.cc:332) - Merged
>> qservResult.result_11903762039 into qservResult.result_11903762039
>> 0507 11:36:44.618 [0x7f28bde8a700] INFO root
>> (build/ccontrol/UserQuery.cc:222) - Joined everything (success)
>> 0507 11:36:44.619 [0x7f28bde8a700] INFO root (app.py:408) - Query
>> exec (1) took 0.126505 seconds
>> 0507 11:36:44.620 [0x7f28bde8a700] INFO root (app.py:413) - Final
>> state of all queries success
>> 0507 11:36:44.621 [0x7f28bd489700] INFO root
>> (build/ccontrol/UserQuery.cc:134) - ~UserQuery uqCount=0
>> *************************
>> 0507 11:36:44.621 [0x7f28bd489700] INFO root
>> (build/qdisp/Executive.cc:163) - ~Executive exCount=0
>> *************************
>>
>> ########################################################################
>> Use REPLY-ALL to reply to list
>>
>> To unsubscribe from the QSERV-L list, click the following link:
>> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=QSERV-L&A=1
>>
>
> ########################################################################
> Use REPLY-ALL to reply to list
>
> To unsubscribe from the QSERV-L list, click the following link:
> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=QSERV-L&A=1
########################################################################
Use REPLY-ALL to reply to list
To unsubscribe from the QSERV-L list, click the following link:
https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=QSERV-L&A=1
|
