Print

---

[log in to unmask]" type="cite"> 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:

[log in to unmask]" type="cite"> 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:

[log in to unmask]" type="cite">

On 11/19/2015 12:14 AM, Gates, John H wrote:

[log in to unmask]" type="cite">

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

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