The czar doesn't get anything back from the worker but it looks like the
worker is sending it.
The last thing that happens on the czar is that xrootd calls
QueryRequest::GetRequest and then it goes silent. I don't know if it
passed an invalid payload to xrootd or if something else happened. It
looks like xrootd is never calling QueryRequest::ProcessResponse.
I'm hoping Andy Hanushevsky can help me determine if this is the case.
-John
Worker xrootd.log specifically for chunk 5299 on ccqserv148, it looks fine:
[2015-11-24T15:07:42.989Z] [0x7ffbc8244700] INFO root
(core/modules/xrdsvc/SsiSession.cc:61) - ProcessRequest,
service=/chk/LSST/5299
[0x7ffbc8244700] DEBUG root
(core/modules/wsched/BlendScheduler.cc:75) - BlendScheduler::queCmd tSeq=109
[0x7ffbc8244700] DEBUG BlendSched
(core/modules/wsched/BlendScheduler.cc:93) - Blend chose group
[0x7ffbc8244700] DEBUG BlendSched
(core/modules/wsched/BlendScheduler.cc:100) - Blend queCmd tSeq=109
[0x7ffbc8244700] INFO root (core/modules/xrdsvc/SsiSession.cc:125) -
Enqueued TaskMsg for Resource(/chk/LSST/5299) in 0.000465 seconds
...
[0x7ffbc3fff700] DEBUG Foreman (core/modules/wdb/QueryRunner.cc:120)
- QueryRunner::runQuery() tSeq=109
[0x7ffbc3fff700] DEBUG Foreman (core/modules/wdb/QueryRunner.cc:137)
- Exec in flight for Db = q_3c48232a8ba6adfe0b316b74245d8dca
[0x7ffbc3fff700] WARN Foreman (core/modules/wdb/QueryRunner.cc:115)
- QueryRunner overriding dbName with LSST
[0x7ffbc3fff700] DEBUG root (core/modules/wdb/QueryRunner.cc:242) -
_transmit last=1 tSeq=109
[0x7ffbc3fff700] DEBUG root (core/modules/wdb/QueryRunner.cc:259) -
_transmitHeader
[0x7ffbc3fff700] INFO root
(core/modules/proto/ProtoHeaderWrap.cc:52) - msgBuf size=256 -> [[0]=40,
[1]=13, [2]=2, [3]=0, [4]=0, ..., [251]=48, [252]=48, [253]=48,
[254]=48, [255]=48]
[0x7ffbc3fff700] INFO root
(core/modules/xrdsvc/SsiSession_ReplyChannel.cc:85) - sendStream,
checking stream 0 len=256 last=0
[0x7ffbc3fff700] INFO root (core/modules/xrdsvc/ChannelStream.cc:91)
- last=0 [[0]=40, [1]=13, [2]=2, [3]=0, [4]=0, [5]=0, [6]=21, [7]=47,
[8]=0, [9]=0, ..., [246]=48, [247]=48, [248]=48, [249]=48, [250]=48,
[251]=48, [252]=48, [253]=48, [254]=48, [255]=48]
[0x7ffbc3fff700] INFO root (core/modules/xrdsvc/ChannelStream.cc:94)
- trying to append message (flowing)
[0x7ffbc3fff700] INFO root (core/modules/wdb/QueryRunner.cc:253) -
_transmit last=1 tSeq=109 resultString=[[0]=8, [1]=0, [2]=16, [3]=4,
[4]=26, ..., [42]=51, [43]=51, [44]=56, [45]=16, [46]=0]
[0x7ffbc3fff700] INFO root
(core/modules/xrdsvc/SsiSession_ReplyChannel.cc:85) - sendStream,
checking stream 0x7ffb78008e70 len=47 last=1
[0x7ffbc3fff700] INFO root (core/modules/xrdsvc/ChannelStream.cc:91)
- last=1 [[0]=8, [1]=0, [2]=16, [3]=4, [4]=26, [5]=29, [6]=10, [7]=27,
[8]=10, [9]=9, ..., [37]=10, [38]=6, [39]=50, [40]=53, [41]=56, [42]=51,
[43]=51, [44]=56, [45]=16, [46]=0]
[0x7ffbc3fff700] INFO root (core/modules/xrdsvc/ChannelStream.cc:94)
- trying to append message (flowing)
[0x7ffbc3fff700] DEBUG BlendSched
(core/modules/wsched/BlendScheduler.cc:132) -
BlendScheduler::commandFinish tSeq=109
--- Transmitted message with last=1, that should be fine
On the czar for chunk 5299 and jobId=2639:
2015-11-24T15:07:42.974Z [0x7f06b37fe700] DEBUG root
(core/modules/qproc/TaskMsgFactory2.cc:153) - SELECT count(*) AS
QS1_COUNT FROM LSST.Object_5299 AS QST_1_
[0x7f06b37fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:226) - setError: code: 0, message:
[0x7f06b37fe700] DEBUG qdisp.Executive
(core/modules/qdisp/Executive.cc:106) - Executive::add(job(id=2639
payload.len=123 ru=/chk/LSST/5299))
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/JobQuery.h:104) -
JobQuery JQ_jobId=2639 desc=job(id=2639 payload.len=123 ru=/chk/LSST/5299)
[0x7f06b37fe700] INFO qdisp.Executive
(core/modules/qdisp/Executive.cc:129) - Executive: Add job with
path=/chk/LSST/5299
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/MessageStore.cc:53) -
Add msg: 5299 1200 Executive: Add job with path=/chk/LSST/5299
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/JobQuery.cc:55) -
runJob {job(id=2639 payload.len=123 ru=/chk/LSST/5299) :
2015-11-24T15:07:42+0000, Unknown, 0, }
[0x7f06b37fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:226) - setError: code: 0, message:
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/QueryResource.cc:51)
- QueryResource JQ_jobId=2639
[0x7f06b37fe700] INFO qproc.QuerySession
(core/modules/qproc/QuerySession.cc:383) - Non-subchunkedn
[0x7f06b37fe700] DEBUG root
(core/modules/qproc/TaskMsgFactory2.cc:151) - no nextFragment
...
[0x7f05dbfff700] INFO root (core/modules/qdisp/QueryRequest.cc:57) -
New QueryRequest with payload(123)
[0x7f05dbfff700] DEBUG root (core/modules/qdisp/QueryRequest.cc:58) -
QueryRequest JQ_jobId=2639
[0x7f05dbfff700] DEBUG root (core/modules/qdisp/QueryRequest.cc:75) -
Requesting, payload size: [123]
[0x7f05dbfff700] DEBUG root (core/modules/qdisp/QueryResource.cc:55)
- ~QueryResource() JQ_jobId=2639
??????? [0x7f05dbfff700] INFO root
(core/modules/qdisp/QueryRequest.cc:57) - New QueryRequest with payload(123)
**** And that's it for jobId=2639. It looks like
QueryRequest::ProcessResponse is never called by xrootd for this query.
For job 2638 on the czar (which completes):
2015-11-24T15:07:42.973Z [0x7f06b37fe700] DEBUG root
(core/modules/qproc/TaskMsgFactory2.cc:153) - SELECT count(*) AS
QS1_COUNT FROM LSST.Object_5298 AS QST_1_
[0x7f06b37fe700] INFO qdisp.Executive
(core/modules/qdisp/Executive.cc:129) - Executive: Add job with
path=/chk/LSST/5298
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/MessageStore.cc:53) -
Add msg: 5298 1200 Executive: Add job with path=/chk/LSST/5298
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/JobQuery.cc:55) -
runJob {job(id=2638 payload.len=123 ru=/chk/LSST/5298) :
2015-11-24T15:07:42+0000, Unknown, 0, }
[0x7f06b37fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:226) - setError: code: 0, message:
[0x7f06b37fe700] DEBUG root (core/modules/qdisp/QueryResource.cc:51)
- QueryResource JQ_jobId=2638
[0x7f06b37fe700] INFO qproc.QuerySession
(core/modules/qproc/QuerySession.cc:383) - Non-subchunked
[0x7f06b37fe700] DEBUG root
(core/modules/qproc/TaskMsgFactory2.cc:151) - no nextFragment
...
[0x7f067a7fc700] DEBUG root (core/modules/qdisp/QueryRequest.cc:58) -
QueryRequest JQ_jobId=2638
[0x7f067a7fc700] DEBUG root (core/modules/qdisp/QueryRequest.cc:75) -
Requesting, payload size: [123]
[0x7f067a7fc700] DEBUG root (core/modules/qdisp/QueryResource.cc:55)
- ~QueryResource() JQ_jobId=2638
*** [0x7f067a7fc700] DEBUG root
(core/modules/qdisp/QueryRequest.cc:127) - QueryRequest::_importStream
buffer.size=256
[0x7f067a7fc700] DEBUG root (core/modules/qdisp/QueryRequest.cc:130)
- _importStream->GetResponseData size=256 0x7f06b46e91c0 [[0]=0, [1]=0,
[2]=0, [3]=0, [4]=0, ..., [251]=0, [252]=0, [253]=0, [254]=0, [255]=0]
[0x7f067a7fc700] DEBUG root (core/modules/qdisp/QueryRequest.cc:132)
- Initiated request ok
[0x7f067a7fc700] INFO root (core/modules/qdisp/QueryRequest.cc:57) -
New QueryRequest with payload(123)
...
[0x7f05db7fe700] INFO root (core/modules/qdisp/QueryRequest.cc:155)
- ProcessResponseData with buflen=47 (more)
[0x7f05db7fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:85) - From:ccqserv147 flush
state=RESULT_WAIT blen=47 last=0
[0x7f05db7fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:113) - From:ccqserv147 _buffer
[[0]=8, [1]=0, [2]=16, [3]=4, [4]=26, ..., [42]=52, [43]=48, [44]=53,
[45]=16, [46]=0]
[0x7f05db7fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:123) - Messages ends, setting
last=true
[0x7f05db7fe700] INFO root
(core/modules/ccontrol/MergingHandler.cc:127) - Flushed msgContinues=0
last=1 for tableName=r_41ff8f47beaf890993226b08c275692c4_5298_0
[0x7f05db7fe700] DEBUG rproc.InfileMerger
(core/modules/rproc/InfileMerger.cc:279) - Executing
InfileMerger::merge(sizes=40, 47, rowcount=1, errCode=0, hasErrorMsg=0)
[0x7f05db7fe700] INFO root (core/modules/qdisp/QueryRequest.cc:266)
- Finished() ok.
[0x7f05db7fe700] INFO qdisp.Executive
(core/modules/qdisp/Executive.cc:175) - Executive::markCompleted(2638,1)
On 11/24/15 10:25, John Gates wrote:
> It looks like all the tasks on ccqserv148 have completed, and it is
> expected that all the threads in the pool will block on getCmd() as
> there are no Tasks in the scheduler to run. For this query, there were
> 321 tasks which all seem to have run to completion. The last line in
> the worker log is
>
> INFO root (core/modules/xrdsvc/SsiSession.cc:153) -
> RequestFinished type=isStream
>
> That seems pretty reasonable. I've logged into a couple of other
> workers (147 and 140) and their log files look very similar. The thing
> that bothers me about all three logs is that the SsiSession is not
> being destroyed (I think it might be waiting on something from the
> czar but I need to look into it).
>
> For a quick check, I did
>
> /opt/shmux/bin/shmux -c "sudo -u qserv docker exec -t qserv tail
> /qserv/run/var/log/worker/xrootd.log" ccqserv{126..146} > ~/junk
>
> and the ends of all the log files look very similar (despite being
> mashed together by shmux) They all end with at least one
> RequestFinished and none of them appear to be deleteing SsiSession.
>
> On 11/24/15 08:23, Fabrice Jammes wrote:
>> On 11/19/2015 12:14 AM, Gates, John H wrote:
>>>
>>> Hi Fabrice,
>>>
>>>
>>> I'd like to test things out on the cluster but I want to make sure
>>> that I'm not going to step on your toes. I also want to make sure
>>> that it's working before I get into.
>>>
>>>
>>> -John
>>>
>> Hi John
>>
>> A recent Qserv version seems to run on ccqserv125...ccqserv149.
>> It works fine for small query but stall for large queries, on the
>> worker side it seems...
>>
>> I tried to diagnose it in this ticket description:
>> https://jira.lsstcorp.org/browse/DM-4407
>>
>> Feel free to ask if you need information about connecting to docker
>> machine.
>>
>>
>> I use:
>>
>> ssh ccqservXXX
>> sudo -u qserv bash
>> docker exec -it qserv bash
>> # then I'm log in the container
>> ls /qserv/run/var/log
>> ps x
>> ls /qserv/data
>> ...
>
>
> ------------------------------------------------------------------------
>
> 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
