[From nobody Tue Feb 20 16:47:49 2007 Received: from mr1.dcs.gla.ac.uk ([130.209.249.184]) by ex1.ad.dcs.gla.ac.uk over TLS secured channel with Microsoft SMTPSVC(6.0.3790.1830); Mon, 5 Feb 2007 23:48:32 +0000 Received: from mail by mr1.dcs.gla.ac.uk with spam-scanned (Exim 4.42) id 1HEDZX-0002L5-8U for craigm@dcs.gla.ac.uk; Mon, 05 Feb 2007 23:48:32 +0000 Received: from clusterresources.com ([208.187.181.131]:44522 helo=kahu.supercluster.org) by mr1.dcs.gla.ac.uk with esmtp (Exim 4.42) id 1HEDZW-0002L2-Eh for craigm@dcs.gla.ac.uk; Mon, 05 Feb 2007 23:48:31 +0000 Received: from clusterresources.com (localhost.localdomain [127.0.0.1]) by kahu.supercluster.org (Postfix) with ESMTP id 5686A1BA407B; Mon, 5 Feb 2007 16:48:14 -0700 (MST) X-Original-To: mauiusers@supercluster.org Delivered-To: mauiusers@supercluster.org Received: from mr1.dcs.gla.ac.uk (mr1.dcs.gla.ac.uk [130.209.249.184]) by kahu.supercluster.org (Postfix) with ESMTP id A49E21BA4069 for <mauiusers@supercluster.org>; Mon, 5 Feb 2007 16:48:05 -0700 (MST) Received: from ex1.ad.dcs.gla.ac.uk ([130.209.249.157]:14611) by mr1.dcs.gla.ac.uk with esmtp (Exim 4.42) id 1HEDZ6-0001pZ-Tj for mauiusers@supercluster.org; Mon, 05 Feb 2007 23:48:04 +0000 X-MimeOLE: Produced By Microsoft Exchange V6.5 Content-class: urn:content-classes:message MIME-Version: 1.0 Date: Mon, 5 Feb 2007 23:46:04 -0000 Message-ID: <58577CAC1C0FB34DAA24FA9DC76613F1016C576F@ex1.ad.dcs.gla.ac.uk> X-MS-Has-Attach: X-MS-TNEF-Correlator: Thread-Topic: maui pausing on Torque multiple qsubs Thread-Index: AcdJf8yap2t89sAQTJSdy9DK2aQk3A== References: <45BA4A30.1050908@dcs.gla.ac.uk> From: "Craig Macdonald" <craigm@dcs.gla.ac.uk> To: <mauiusers@supercluster.org> Subject: [Mauiusers] FW: maui pausing on Torque multiple qsubs X-BeenThere: mauiusers@supercluster.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Maui Users Mailing List <mauiusers.supercluster.org> List-Unsubscribe: <http://www.supercluster.org/mailman/listinfo/mauiusers>, <mailto:mauiusers-request@supercluster.org?subject=unsubscribe> List-Archive: <http://www.supercluster.org/pipermail/mauiusers> List-Post: <mailto:mauiusers@supercluster.org> List-Help: <mailto:mauiusers-request@supercluster.org?subject=help> List-Subscribe: <http://www.supercluster.org/mailman/listinfo/mauiusers>, <mailto:mauiusers-request@supercluster.org?subject=subscribe> Content-Type: multipart/mixed; boundary="===============1035603559==" Sender: mauiusers-bounces@supercluster.org Errors-To: mauiusers-bounces@supercluster.org X-Spam-Checker-Version: SpamAssassin 2.63 (2004-01-11) on mr1.dcs.gla.ac.uk X-Spam-Level: X-Spam-Status: No, hits=0.1 required=6.5 tests=AWL, HTML_MESSAGE autolearn=no version=2.63 Return-Path: mauiusers-bounces@supercluster.org X-OriginalArrivalTime: 05 Feb 2007 23:48:32.0741 (UTC) FILETIME=[24EB9950:01C74980] This is a multi-part message in MIME format. --===============1035603559== Content-class: urn:content-classes:message Content-Type: multipart/alternative; boundary="----_=_NextPart_001_01C74980.14022736" This is a multi-part message in MIME format. ------_=_NextPart_001_01C74980.14022736 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Hi all, Didnt get any replies last time - does anyone know why Maui pauses for = 15 mins after: ERROR: cannot get node info: Premature end of message or just as good, does anyone know where this timeout can be configured? Craig -----Original Message----- From: Craig Macdonald Sent: Fri 1/26/2007 6:36 PM To: mauiusers@supercluster.org; torqueusers@supercluster.org Subject: maui pausing on Torque multiple qsubs =20 Hi there, I have a problem extremely similar to http://www.clusterresources.com/pipermail/torqueusers/2006-April/003576.h= tml When doing multiple qsubs, Maui starts scheduling, then times out=20 getting node info. However, it doesn't start scheduling again for a significant amount of=20 time. (15+mins) The most recent time, this happened to me while qdel-ing 3 jobs: [craigm@bohol terrier]$qdel 545 546 547 No Permission. qdel: cannot connect to server trmaster (errno=3D15007) [craigm@bohol terrier]$qstat Job id Name User Time Use S Queue ------------------- ---------------- --------------- -------- - ----- 547.trmaster index_wt2g_2 craigm 0 H verylong [craigm@bohol terrier]$qdel 547 At this point, maui will do it's pause. This happens with torque-2.1.6 and maui 3.2.6p17 My issue is that Maui seems to recieve a timeout from the libpbs, but=20 doesnt seem to know what to do with it for a significant amount of time (till something else times out?). Is=20 there any timeouts we can configure in Maui to reduce this. The alternative route is to trace why the timeout occur in pbs_server. Configurations and logs below. Logs are from a previous occurrence of=20 this event. Many thanks Craig I have Torque config set server node_check_rate =3D 150 set server tcp_timeout =3D 6 set server poll_jobs =3D True set server scheduler_iteration =3D 600 and relevant bit for Maui: RMPOLLINTERVAL 00:00:30 Maui Log =3D=3D=3D=3D=3D=3D=3D 01/23 22:58:05 MResUpdateStats() 01/23 22:58:05 INFO: current util[2097]: 7/8 (87.50%) PH: 28.43% =20 active jobs: 2 of 2 (completed: 413) 01/23 22:58:05 MQueueCheckStatus() 01/23 22:58:05 MNodeCheckStatus() 01/23 22:58:05 ALERT: node 'trnode03' sync from expected state 'Idle' = to state 'Running' at Tue Jan 23 22:58:05 01/23 22:58:05 ALERT: node 'trnode04' sync from expected state 'Idle' = to state 'Running' at Tue Jan 23 22:58:05 01/23 22:58:05 ALERT: node 'trnode05' sync from expected state 'Idle' = to state 'Running' at Tue Jan 23 22:58:05 01/23 22:58:05 ALERT: node 'trnode06' sync from expected state 'Idle' = to state 'Running' at Tue Jan 23 22:58:05 01/23 22:58:05 ALERT: node 'trnode08' sync from expected state 'Idle' = to state 'Running' at Tue Jan 23 22:58:05 01/23 22:58:05 MUClearChild(PID) 01/23 22:58:05 INFO: scheduling complete. sleeping 30 seconds 01/23 22:58:14 INFO: connect request from 130.209.249.20 01/23 22:58:14 INFO: received service request from host 'trmaster' 01/23 22:58:14 MSURecvPacket(9,BufP,4,NULL,100000,SC) 01/23 22:58:14 INFO: connect request from 130.209.249.20 01/23 22:58:14 INFO: received service request from host 'trmaster' 01/23 22:58:14 MSURecvPacket(9,BufP,4,NULL,100000,SC) 01/23 22:58:14 ServerProcessRequests() 01/23 22:58:14 INFO: not rolling logs (8941183 < 10000000) 01/23 22:58:14 MResAdjust(NULL,0,0) 01/23 22:58:14 MStatInitializeActiveSysUsage() 01/23 22:58:14 MStatClearUsage([NONE],Active) 01/23 22:58:14 ServerUpdate() 01/23 22:58:14 MSysUpdateTime() 01/23 22:58:14 INFO: starting iteration 2098 01/23 22:58:14 MRMGetInfo() 01/23 22:58:14 MClusterClearUsage() 01/23 22:58:14 MRMClusterQuery() 01/23 22:58:14 MPBSClusterQuery(base,RCount,SC) 01/23 22:58:23 ERROR: cannot get node info: Premature end of message <PAUSE HERE> 01/23 23:13:44 ALERT: cannot load cluster resources on RM (RM 'base'=20 failed in function 'clusterquery') 01/23 23:13:44 WARNING: no resources detected 01/23 23:13:44 MRMWorkloadQuery() 01/23 23:13:44 MPBSWorkloadQuery(base,JCount,SC) 01/23 23:13:44 MPBSInitialize(base,SC) 01/23 23:13:45 MSUListen(S) 01/23 23:13:45 INFO: opened service socket on port 15004 01/23 23:13:45 __MPBSSystemQuery(base,RCount,SC) 01/23 23:13:45 INFO: connected to PBS server :0 on sd 1 01/23 23:13:45 MPBSJobUpdate(422,422.trmaster,TaskList,0) 01/23 23:13:45 MStatUpdateActiveJobUsage(422) Torque pbs_server log =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D 01/23/2007 22:58:14;0040;PBS_Server;Svr;trmaster;Scheduler sent command = new 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type AuthenticateUser request=20 received from craigm@trangan, sock=3D13 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type QueueJob request received=20 from craigm@trangan, sock=3D11 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type JobScript request received = from craigm@trangan, sock=3D11 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type ReadyToCommit request=20 received from craigm@trangan, sock=3D11 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type Commit request received=20 from craigm@trangan, sock=3D11 01/23/2007 22:58:14;0100;PBS_Server;Job;490.trmaster;enqueuing into=20 feed, state 1 hop 1 01/23/2007 22:58:14;0100;PBS_Server;Job;490.trmaster;dequeuing from=20 feed, state QUEUED 01/23/2007 22:58:14;0100;PBS_Server;Job;490.trmaster;enqueuing into=20 verylong, state 1 hop 1 01/23/2007 22:58:14;0008;PBS_Server;Job;490.trmaster;Job Queued at=20 request of craigm@trangan, owner =3D craigm@trangan, job name =3D=20 tagDisk454, queue =3D verylong 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type AuthenticateUser request=20 received from craigm@trangan, sock=3D12 01/23/2007 22:58:39;0100;PBS_Server;Req;;Type QueueJob request received=20 from craigm@trangan, sock=3D11 01/23/2007 22:58:39;0040;PBS_Server;Svr;trmaster;Scheduler sent command = time 01/23/2007 22:58:39;0100;PBS_Server;Req;;Type StatusNode request=20 received from craigm@trmaster, sock=3D9 ------_=_NextPart_001_01C74980.14022736 Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2//EN"> <HTML> <HEAD> <META HTTP-EQUIV=3D"Content-Type" CONTENT=3D"text/html; = charset=3Diso-8859-1"> <META NAME=3D"Generator" CONTENT=3D"MS Exchange Server version = 6.5.7650.28"> <TITLE>FW: maui pausing on Torque multiple qsubs</TITLE> </HEAD> <BODY> <!-- Converted from text/plain format --> <P><FONT SIZE=3D2>Hi all,<BR> <BR> Didnt get any replies last time - does anyone know why Maui pauses for = 15 mins after:<BR> ERROR:&nbsp;&nbsp;&nbsp; cannot get node info: Premature end of = message<BR> or just as good, does anyone know where this timeout can be = configured?<BR> <BR> Craig<BR> <BR> -----Original Message-----<BR> From: Craig Macdonald<BR> Sent: Fri 1/26/2007 6:36 PM<BR> To: mauiusers@supercluster.org; torqueusers@supercluster.org<BR> Subject: maui pausing on Torque multiple qsubs<BR> <BR> Hi there,<BR> <BR> I have a problem extremely similar to<BR> <A = HREF=3D"http://www.clusterresources.com/pipermail/torqueusers/2006-April/= 003576.html">http://www.clusterresources.com/pipermail/torqueusers/2006-A= pril/003576.html</A><BR> <BR> When doing multiple qsubs, Maui starts scheduling, then times out<BR> getting node info.<BR> However, it doesn't start scheduling again for a significant amount = of<BR> time. (15+mins)<BR> The most recent time, this happened to me while qdel-ing 3 jobs:<BR> <BR> [craigm@bohol terrier]$qdel 545 546 547<BR> No Permission.<BR> qdel: cannot connect to server trmaster (errno=3D15007)<BR> [craigm@bohol terrier]$qstat<BR> Job = id&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp= ;&nbsp; = Name&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb= sp; = User&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; = Time Use S Queue<BR> ------------------- ---------------- --------------- -------- - = -----<BR> 547.trmaster&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; = index_wt2g_2&nbsp;&nbsp;&nbsp;&nbsp; = craigm&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&= nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 0 H verylong<BR> [craigm@bohol terrier]$qdel 547<BR> <BR> <BR> At this point, maui will do it's pause.<BR> <BR> This happens with torque-2.1.6 and maui 3.2.6p17<BR> <BR> My issue is that Maui seems to recieve a timeout from the libpbs, = but<BR> doesnt seem to know what to do with it<BR> for a significant amount of time (till something else times out?). = Is<BR> there any timeouts we can configure in Maui to reduce this.<BR> <BR> The alternative route is to trace why the timeout occur in = pbs_server.<BR> <BR> Configurations and logs below. Logs are from a previous occurrence = of<BR> this event.<BR> <BR> Many thanks<BR> <BR> Craig<BR> <BR> I have Torque config<BR> set server node_check_rate =3D 150<BR> set server tcp_timeout =3D 6<BR> set server poll_jobs =3D True<BR> set server scheduler_iteration =3D 600<BR> <BR> and relevant bit for Maui:<BR> RMPOLLINTERVAL&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 00:00:30<BR> <BR> Maui Log<BR> =3D=3D=3D=3D=3D=3D=3D<BR> 01/23 22:58:05 MResUpdateStats()<BR> 01/23 22:58:05 INFO:&nbsp;&nbsp;&nbsp;&nbsp; current util[2097]:&nbsp; = 7/8 (87.50%)&nbsp; PH: 28.43%&nbsp;<BR> active jobs: 2 of 2 (completed: 413)<BR> 01/23 22:58:05 MQueueCheckStatus()<BR> 01/23 22:58:05 MNodeCheckStatus()<BR> 01/23 22:58:05 ALERT:&nbsp;&nbsp;&nbsp; node 'trnode03' sync from = expected state 'Idle'<BR> to state 'Running' at Tue Jan 23 22:58:05<BR> 01/23 22:58:05 ALERT:&nbsp;&nbsp;&nbsp; node 'trnode04' sync from = expected state 'Idle'<BR> to state 'Running' at Tue Jan 23 22:58:05<BR> 01/23 22:58:05 ALERT:&nbsp;&nbsp;&nbsp; node 'trnode05' sync from = expected state 'Idle'<BR> to state 'Running' at Tue Jan 23 22:58:05<BR> 01/23 22:58:05 ALERT:&nbsp;&nbsp;&nbsp; node 'trnode06' sync from = expected state 'Idle'<BR> to state 'Running' at Tue Jan 23 22:58:05<BR> 01/23 22:58:05 ALERT:&nbsp;&nbsp;&nbsp; node 'trnode08' sync from = expected state 'Idle'<BR> to state 'Running' at Tue Jan 23 22:58:05<BR> 01/23 22:58:05 MUClearChild(PID)<BR> 01/23 22:58:05 INFO:&nbsp;&nbsp;&nbsp;&nbsp; scheduling complete.&nbsp; = sleeping 30 seconds<BR> 01/23 22:58:14 INFO:&nbsp;&nbsp;&nbsp;&nbsp; connect request from = 130.209.249.20<BR> 01/23 22:58:14 INFO:&nbsp;&nbsp;&nbsp;&nbsp; received service request = from host 'trmaster'<BR> 01/23 22:58:14 MSURecvPacket(9,BufP,4,NULL,100000,SC)<BR> 01/23 22:58:14 INFO:&nbsp;&nbsp;&nbsp;&nbsp; connect request from = 130.209.249.20<BR> 01/23 22:58:14 INFO:&nbsp;&nbsp;&nbsp;&nbsp; received service request = from host 'trmaster'<BR> 01/23 22:58:14 MSURecvPacket(9,BufP,4,NULL,100000,SC)<BR> 01/23 22:58:14 ServerProcessRequests()<BR> 01/23 22:58:14 INFO:&nbsp;&nbsp;&nbsp;&nbsp; not rolling logs (8941183 = &lt; 10000000)<BR> 01/23 22:58:14 MResAdjust(NULL,0,0)<BR> 01/23 22:58:14 MStatInitializeActiveSysUsage()<BR> 01/23 22:58:14 MStatClearUsage([NONE],Active)<BR> 01/23 22:58:14 ServerUpdate()<BR> 01/23 22:58:14 MSysUpdateTime()<BR> 01/23 22:58:14 INFO:&nbsp;&nbsp;&nbsp;&nbsp; starting iteration 2098<BR> 01/23 22:58:14 MRMGetInfo()<BR> 01/23 22:58:14 MClusterClearUsage()<BR> 01/23 22:58:14 MRMClusterQuery()<BR> 01/23 22:58:14 MPBSClusterQuery(base,RCount,SC)<BR> 01/23 22:58:23 ERROR:&nbsp;&nbsp;&nbsp; cannot get node info: Premature = end of message<BR> &lt;PAUSE HERE&gt;<BR> 01/23 23:13:44 ALERT:&nbsp;&nbsp;&nbsp; cannot load cluster resources on = RM (RM 'base'<BR> failed in function 'clusterquery')<BR> 01/23 23:13:44 WARNING:&nbsp; no resources detected<BR> 01/23 23:13:44 MRMWorkloadQuery()<BR> 01/23 23:13:44 MPBSWorkloadQuery(base,JCount,SC)<BR> 01/23 23:13:44 MPBSInitialize(base,SC)<BR> 01/23 23:13:45 MSUListen(S)<BR> 01/23 23:13:45 INFO:&nbsp;&nbsp;&nbsp;&nbsp; opened service socket on = port 15004<BR> 01/23 23:13:45 __MPBSSystemQuery(base,RCount,SC)<BR> 01/23 23:13:45 INFO:&nbsp;&nbsp;&nbsp;&nbsp; connected to PBS server :0 = on sd 1<BR> 01/23 23:13:45 MPBSJobUpdate(422,422.trmaster,TaskList,0)<BR> 01/23 23:13:45 MStatUpdateActiveJobUsage(422)<BR> <BR> Torque pbs_server log<BR> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D<BR> 01/23/2007 22:58:14;0040;PBS_Server;Svr;trmaster;Scheduler sent command = new<BR> 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type AuthenticateUser = request<BR> received from craigm@trangan, sock=3D13<BR> 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type QueueJob request = received<BR> from craigm@trangan, sock=3D11<BR> 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type JobScript request = received<BR> from craigm@trangan, sock=3D11<BR> 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type ReadyToCommit request<BR> received from craigm@trangan, sock=3D11<BR> 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type Commit request = received<BR> from craigm@trangan, sock=3D11<BR> 01/23/2007 22:58:14;0100;PBS_Server;Job;490.trmaster;enqueuing into<BR> feed, state 1 hop 1<BR> 01/23/2007 22:58:14;0100;PBS_Server;Job;490.trmaster;dequeuing from<BR> feed, state QUEUED<BR> 01/23/2007 22:58:14;0100;PBS_Server;Job;490.trmaster;enqueuing into<BR> verylong, state 1 hop 1<BR> 01/23/2007 22:58:14;0008;PBS_Server;Job;490.trmaster;Job Queued at<BR> request of craigm@trangan, owner =3D craigm@trangan, job name =3D<BR> tagDisk454, queue =3D verylong<BR> 01/23/2007 22:58:14;0100;PBS_Server;Req;;Type AuthenticateUser = request<BR> received from craigm@trangan, sock=3D12<BR> 01/23/2007 22:58:39;0100;PBS_Server;Req;;Type QueueJob request = received<BR> from craigm@trangan, sock=3D11<BR> 01/23/2007 22:58:39;0040;PBS_Server;Svr;trmaster;Scheduler sent command = time<BR> 01/23/2007 22:58:39;0100;PBS_Server;Req;;Type StatusNode request<BR> received from craigm@trmaster, sock=3D9<BR> <BR> <BR> <BR> </FONT> </P> </BODY> </HTML> ------_=_NextPart_001_01C74980.14022736-- --===============1035603559== Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Content-Disposition: inline _______________________________________________ mauiusers mailing list mauiusers@supercluster.org http://www.supercluster.org/mailman/listinfo/mauiusers --===============1035603559==-- ]