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
|
