2011-08-23 15:27:41,056-0500 DEBUG Loader arguments: [-config, cf, -tc.file, tc, -sites.file, pads-coaster-93.xml, catsnsleep.swift, -s=60, -n=20] 2011-08-23 15:27:41,056-0500 DEBUG Loader Max heap: 257294336 2011-08-23 15:27:41,057-0500 DEBUG textfiles BEGIN SWIFTSCRIPT: type file; app (file o) catnap (string delay, file i) { catnap delay @i stdout=@o; } string some_delay=@arg("s","1"); file out[]; foreach j in [1:@toint(@arg("n","1"))] { file data<"data.txt">; out[j] = catnap(some_delay, data); } 2011-08-23 15:27:41,057-0500 DEBUG textfiles END SWIFTSCRIPT: 2011-08-23 15:27:41,063-0500 DEBUG Loader kmlversion is >db117a35-cc00-4f44-a922-50bd4b54b37e< 2011-08-23 15:27:41,063-0500 DEBUG Loader build version is >db117a35-cc00-4f44-a922-50bd4b54b37e< 2011-08-23 15:27:41,063-0500 DEBUG Loader Recompilation suppressed. 2011-08-23 15:27:41,204-0500 DEBUG Loader setting: sites.file to: pads-coaster-93.xml 2011-08-23 15:27:41,204-0500 DEBUG Loader setting: tc.file to: tc 2011-08-23 15:27:41,204-0500 DEBUG textfiles using default sites file 2011-08-23 15:27:41,209-0500 INFO VDL2ExecutionContext Stack dump: Level 1 [iA = 0, iB = 0, bA = false, bB = false] vdl:instanceconfigfile = cf vdl:instanceconfig = Swift configuration [cf] vdl:operation = run PATH_SEPARATOR = / swift.home = /home/ketan/swift-install/0.93/cog/modules/swift/dist/swift-svn 2011-08-23 15:27:41,733-0500 INFO unknown Using sites file: pads-coaster-93.xml 2011-08-23 15:27:41,760-0500 INFO unknown Using tc.data: tc 2011-08-23 15:27:41,844-0500 INFO AbstractScheduler Setting resources to: {pbs=pbs} 2011-08-23 15:27:42,279-0500 INFO unknown Swift svn swift-r4989 (swift modified locally) cog-r3232 2011-08-23 15:27:42,283-0500 INFO unknown RUNID id=run:20110823-1527-b6kpd8h9 2011-08-23 15:27:42,353-0500 INFO SetFieldValue Set: swift#mapper#17002=outdir 2011-08-23 15:27:42,353-0500 INFO SetFieldValue Set: swift#mapper#17006=.out 2011-08-23 15:27:42,353-0500 INFO SetFieldValue Set: swift#mapper#17004=f. 2011-08-23 15:27:42,353-0500 INFO VDLFunction FUNCTION: arg() 2011-08-23 15:27:42,353-0500 INFO VDLFunction FUNCTION: arg() 2011-08-23 15:27:42,353-0500 INFO SetFieldValue Set: some_delay=60 2011-08-23 15:27:42,353-0500 INFO VDLFunction FUNCTION: toint() 2011-08-23 15:27:42,358-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-0 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-2 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-4 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-5 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-6 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-8 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-9 2011-08-23 15:27:42,358-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-1 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains SCOPE thread=0-4-2 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-11 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-13 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains SCOPE thread=0-4-4 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-6 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-19 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-11 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-13 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-19 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-10 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains SCOPE thread=0-4-0 2011-08-23 15:27:42,361-0500 DEBUG vdl:mains SCOPE thread=0-4-10 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-7 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-8 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-3 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-1 2011-08-23 15:27:42,362-0500 DEBUG vdl:mains SCOPE thread=0-4-7 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-18 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains SCOPE thread=0-4-9 2011-08-23 15:27:42,360-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-17 2011-08-23 15:27:42,362-0500 DEBUG vdl:mains SCOPE thread=0-4-17 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-16 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-15 2011-08-23 15:27:42,363-0500 DEBUG vdl:mains SCOPE thread=0-4-16 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains SCOPE thread=0-4-5 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,364-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-14 2011-08-23 15:27:42,364-0500 DEBUG vdl:mains SCOPE thread=0-4-14 2011-08-23 15:27:42,364-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,359-0500 DEBUG vdl:mains FOREACH_IT_START line=11 thread=0-4-12 2011-08-23 15:27:42,364-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,365-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,366-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,367-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-8-1 name=catnap 2011-08-23 15:27:42,367-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-16-1 name=catnap 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,368-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-17-1 name=catnap 2011-08-23 15:27:42,368-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-5-1 name=catnap 2011-08-23 15:27:42,369-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-10-1 name=catnap 2011-08-23 15:27:42,369-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-14-1 name=catnap 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,371-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-7-1 name=catnap 2011-08-23 15:27:42,372-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-1-1 name=catnap 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,373-0500 INFO vdl:execute START thread=0-4-5-1 tr=catnap 2011-08-23 15:27:42,373-0500 INFO vdl:execute START thread=0-4-14-1 tr=catnap 2011-08-23 15:27:42,363-0500 DEBUG vdl:mains SCOPE thread=0-4-15 2011-08-23 15:27:42,373-0500 INFO vdl:execute START thread=0-4-10-1 tr=catnap 2011-08-23 15:27:42,373-0500 INFO vdl:execute START thread=0-4-8-1 tr=catnap 2011-08-23 15:27:42,374-0500 INFO vdl:execute START thread=0-4-7-1 tr=catnap 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,363-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,375-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,362-0500 DEBUG vdl:mains SCOPE thread=0-4-18 2011-08-23 15:27:42,362-0500 DEBUG vdl:mains SCOPE thread=0-4-3 2011-08-23 15:27:42,373-0500 INFO vdl:execute START thread=0-4-17-1 tr=catnap 2011-08-23 15:27:42,376-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-4-1 name=catnap 2011-08-23 15:27:42,377-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-11-1 name=catnap 2011-08-23 15:27:42,377-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,377-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-2-1 name=catnap 2011-08-23 15:27:42,378-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-15-1 name=catnap 2011-08-23 15:27:42,379-0500 INFO vdl:execute START thread=0-4-4-1 tr=catnap 2011-08-23 15:27:42,373-0500 INFO vdl:execute START thread=0-4-16-1 tr=catnap 2011-08-23 15:27:42,373-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-13-1 name=catnap 2011-08-23 15:27:42,367-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-19-1 name=catnap 2011-08-23 15:27:42,367-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-6-1 name=catnap 2011-08-23 15:27:42,380-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-3-1 name=catnap 2011-08-23 15:27:42,380-0500 INFO vdl:execute START thread=0-4-11-1 tr=catnap 2011-08-23 15:27:42,367-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-9-1 name=catnap 2011-08-23 15:27:42,367-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-0-1 name=catnap 2011-08-23 15:27:42,380-0500 INFO vdl:execute START thread=0-4-15-1 tr=catnap 2011-08-23 15:27:42,365-0500 DEBUG vdl:mains SCOPE thread=0-4-12 2011-08-23 15:27:42,381-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,380-0500 INFO vdl:execute START thread=0-4-2-1 tr=catnap 2011-08-23 15:27:42,382-0500 INFO vdl:execute START thread=0-4-13-1 tr=catnap 2011-08-23 15:27:42,382-0500 INFO vdl:execute START thread=0-4-19-1 tr=catnap 2011-08-23 15:27:42,377-0500 INFO RootDataNode Found data data:file - Closed.$ 2011-08-23 15:27:42,382-0500 INFO vdl:execute START thread=0-4-6-1 tr=catnap 2011-08-23 15:27:42,382-0500 INFO vdl:execute START thread=0-4-0-1 tr=catnap 2011-08-23 15:27:42,382-0500 INFO vdl:execute START thread=0-4-9-1 tr=catnap 2011-08-23 15:27:42,376-0500 INFO vdl:execute START thread=0-4-1-1 tr=catnap 2011-08-23 15:27:42,384-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-12-1 name=catnap 2011-08-23 15:27:42,384-0500 DEBUG catnap PROCEDURE line=3 thread=0-4-18-1 name=catnap 2011-08-23 15:27:42,382-0500 INFO vdl:execute START thread=0-4-3-1 tr=catnap 2011-08-23 15:27:42,386-0500 INFO vdl:execute START thread=0-4-12-1 tr=catnap 2011-08-23 15:27:42,386-0500 INFO vdl:execute START thread=0-4-18-1 tr=catnap 2011-08-23 15:27:42,387-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:27:42,387-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:27:42,389-0500 INFO GlobalSubmitQueue No global submit throttle set. Using default (1024) 2011-08-23 15:27:42,390-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,392-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,393-0500 INFO vdl:initshareddir START host=pbs - Initializing shared directory 2011-08-23 15:27:42,396-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,414-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,425-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,426-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,429-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,430-0500 INFO vdl:initshareddir END host=pbs - Done initializing shared directory 2011-08-23 15:27:42,431-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-9bslmuek thread=0-4-7-1-1 host=pbs replicationGroup=raslmuek 2011-08-23 15:27:42,431-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-8bslmuek thread=0-4-19-1-1 host=pbs replicationGroup=0bslmuek 2011-08-23 15:27:42,436-0500 INFO vdl:createdirset START jobid=catnap-9bslmuek host=pbs - Initializing directory structure 2011-08-23 15:27:42,436-0500 INFO vdl:createdirset START jobid=catnap-8bslmuek host=pbs - Initializing directory structure 2011-08-23 15:27:42,437-0500 INFO vdl:createdirs START path=outdir dir=catsnsleep-20110823-1527-b6kpd8h9/shared - Creating directory structure 2011-08-23 15:27:42,438-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,439-0500 INFO vdl:createdirset END jobid=catnap-8bslmuek - Done initializing directory structure 2011-08-23 15:27:42,439-0500 INFO vdl:createdirset END jobid=catnap-9bslmuek - Done initializing directory structure 2011-08-23 15:27:42,439-0500 INFO vdl:dostagein START jobid=catnap-8bslmuek - Staging in files 2011-08-23 15:27:42,439-0500 INFO vdl:dostagein START jobid=catnap-9bslmuek - Staging in files 2011-08-23 15:27:42,445-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,445-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,448-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:27:42,448-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:27:42,451-0500 DEBUG vdl:dostageinfile FILE_STAGE_IN_START file=data.txt srchost=localhost srcdir= srcname=data.txt desthost=pbs destdir=catsnsleep-20110823-1527-b6kpd8h9/shared/ provider=file policy=DEFAULT 2011-08-23 15:27:42,453-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:27:42,454-0500 DEBUG vdl:dostageinfile FILE_STAGE_IN_END file=data.txt srchost=localhost srcdir= srcname=data.txt desthost=pbs destdir=catsnsleep-20110823-1527-b6kpd8h9/shared/ provider=file 2011-08-23 15:27:42,454-0500 INFO vdl:dostagein END jobid=catnap-8bslmuek - Staging in finished 2011-08-23 15:27:42,454-0500 INFO vdl:dostagein END jobid=catnap-9bslmuek - Staging in finished 2011-08-23 15:27:42,455-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-8bslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/8/catnap-8bslmuek host=pbs 2011-08-23 15:27:42,455-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-9bslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/9/catnap-9bslmuek host=pbs 2011-08-23 15:27:42,458-0500 DEBUG textfiles BEGIN TC: localhost sh /bin/sh null null null localhost cat /bin/cat null null null pbs cat /bin/cat null null null pbs catnap /gpfs/pads/swift/ketan/catsn-pads/catnap.sh null null null 2011-08-23 15:27:42,458-0500 DEBUG textfiles END TC: 2011-08-23 15:27:42,465-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-19-1-1-1314131261790) is /bin/bash shared/_swiftwrap catnap-8bslmuek -jobdir 8 -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0020.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0020.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:27:42,465-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-7-1-1-1314131261789) is /bin/bash shared/_swiftwrap catnap-9bslmuek -jobdir 9 -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0008.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0008.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:27:42,495-0500 INFO LocalService Started local service: 192.5.86.5:50000 2011-08-23 15:27:42,503-0500 INFO BootstrapService Socket bound. URL is http://login1.pads.ci.uchicago.edu:50001 2011-08-23 15:27:42,541-0500 INFO Settings Local contacts: [http://192.5.86.5:50003, http://169.254.95.119:50003, http://172.5.86.5:50003] 2011-08-23 15:27:42,543-0500 INFO CoasterService Started local service: http://192.5.86.5:50003 2011-08-23 15:27:42,543-0500 INFO CoasterService Reserving channel for registration 2011-08-23 15:27:42,566-0500 INFO AbstractKarajanChannel MetaChannel: 1770446243[356593269: {}] -> null: Disabling heartbeats (disabled in config) 2011-08-23 15:27:42,567-0500 INFO MetaChannel MetaChannel: 1770446243[356593269: {}] -> null.bind -> null[356593269: {}] 2011-08-23 15:27:42,567-0500 INFO AbstractKarajanChannel MetaChannel: 1783696953[1870460598: {}] -> null: Disabling heartbeats (disabled in config) 2011-08-23 15:27:42,567-0500 INFO MetaChannel MetaChannel: 1783696953[1870460598: {}] -> null.bind -> null[1870460598: {}] 2011-08-23 15:27:42,567-0500 INFO CoasterService Sending registration 2011-08-23 15:27:42,570-0500 INFO MetaChannel Trying to re-bind current channel 2011-08-23 15:27:42,572-0500 INFO CoasterService Registration complete 2011-08-23 15:27:42,572-0500 INFO CoasterService Started coaster service: http://192.5.86.5:50002 2011-08-23 15:27:42,627-0500 INFO BlockQueueProcessor Requeued 2 non-fitting jobs 2011-08-23 15:27:42,629-0500 INFO BlockQueueProcessor Settings { slots = 1 jobsPerNode = 8 workersPerNode = 8 nodeGranularity = 1 allocationStepSize = 0.1 maxNodes = 1 lowOverallocation = 10.0 highOverallocation = 1.0 overallocationDecayFactor = 0.0010 spread = 0.9 reserve = 60.000s maxtime = 2600 project = CI-SES000031 queue = fast remoteMonitorEnabled = false kernelprofile = null alcfbgpnat = false internalHostname = 169.254.95.119 hookClass = null workerManager = block workerLoggingLevel = NONE workerLoggingDirectory = DEFAULT ppn = null ldLibraryPath = null workerCopies = null directory = null useHashBang = null providerAttributes = null parallelism = 0.01 } 2011-08-23 15:27:42,629-0500 INFO BlockQueueProcessor Required size: 2.144628893377326 for 2 jobs 2011-08-23 15:27:42,630-0500 INFO BlockQueueProcessor h: 1080, jj: 120, x-last: , r: 1, sumsz: 1 2011-08-23 15:27:42,630-0500 INFO BlockQueueProcessor h: 1200, w: 8, size: 2.0, msz: 2, w*h: 9600 2011-08-23 15:27:42,632-0500 INFO BlockQueueProcessor Added: 0 - 1 2011-08-23 15:27:42,632-0500 INFO Block Starting block: workers=8, walltime=1200.000s 2011-08-23 15:27:42,634-0500 INFO RemoteLogHandler BLOCK_REQUESTED id=0823-270342-000000, w=8, h=1200 2011-08-23 15:27:42,635-0500 INFO BlockTaskSubmitter Queuing block Block 0823-270342-000000 (8x1200.000s) for submission 2011-08-23 15:27:42,635-0500 INFO BlockQueueProcessor Added 2 jobs to new blocks 2011-08-23 15:27:42,635-0500 INFO BlockTaskSubmitter Submitting block Block 0823-270342-000000 (8x1200.000s) 2011-08-23 15:27:42,635-0500 INFO ExecutionTaskHandler provider=pbs 2011-08-23 15:27:42,638-0500 INFO Block Block task status changed: Submitting 2011-08-23 15:27:42,651-0500 DEBUG AbstractExecutor Writing PBS script to /home/ketan/.globus/scripts/PBS6506669395345563156.submit 2011-08-23 15:27:42,672-0500 DEBUG PBSExecutor PBS name: for: Block-0823-270342-000000 is: Block-0823-2703 2011-08-23 15:27:42,673-0500 DEBUG PBSExecutor Job type: null 2011-08-23 15:27:42,679-0500 DEBUG AbstractExecutor Wrote PBS script to /home/ketan/.globus/scripts/PBS6506669395345563156.submit 2011-08-23 15:27:42,679-0500 DEBUG AbstractExecutor Command line: qsub /home/ketan/.globus/scripts/PBS6506669395345563156.submit 2011-08-23 15:27:42,910-0500 DEBUG AbstractExecutor qsub done (exit code 0) 2011-08-23 15:27:42,910-0500 DEBUG AbstractExecutor Waiting for output from qsub 2011-08-23 15:27:42,911-0500 DEBUG AbstractExecutor Output from qsub is: "1691873.svc.pads.ci.uchicago.edu" 2011-08-23 15:27:42,911-0500 DEBUG AbstractExecutor Submitted job with id '1691873.svc.pads.ci.uchicago.edu' 2011-08-23 15:27:42,913-0500 INFO Block Block task status changed: Submitted 2011-08-23 15:27:43,164-0500 INFO AbstractQueuePoller Actively monitored: 0, New: 1, Done: 0 2011-08-23 15:27:48,205-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:27:50,370-0500 INFO AbstractStreamKarajanChannel$Multiplexer Multiplexer 0 started 2011-08-23 15:27:50,370-0500 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-08-23 15:27:50,371-0500 INFO AbstractStreamKarajanChannel nullChannel started 2011-08-23 15:27:50,371-0500 INFO AbstractStreamKarajanChannel$Multiplexer Multiplexer 1 started 2011-08-23 15:27:50,393-0500 INFO LocalTCPService Received registration: blockid = 0823-270342-000000, url = c23.pads.ci.uchicago.edu 2011-08-23 15:27:50,393-0500 INFO AbstractKarajanChannel MetaChannel: 1473790157[914784201: {}] -> null: Disabling heartbeats (config is null) 2011-08-23 15:27:50,393-0500 INFO MetaChannel MetaChannel: 1473790157[914784201: {}] -> null.bind -> SC-null 2011-08-23 15:27:50,396-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:0 2011-08-23 15:27:50,396-0500 DEBUG Cpu 0823-270342-000000:0 pullLater 2011-08-23 15:27:50,397-0500 INFO Block Started CPU 0:1314131270s 2011-08-23 15:27:50,397-0500 INFO Cpu 0823-270342-000000:0 pull 2011-08-23 15:27:50,397-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:1 2011-08-23 15:27:50,397-0500 DEBUG Cpu 0823-270342-000000:1 pullLater 2011-08-23 15:27:50,397-0500 INFO Block Started CPU 1:1314131270s 2011-08-23 15:27:50,397-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:2 2011-08-23 15:27:50,397-0500 DEBUG Cpu 0823-270342-000000:2 pullLater 2011-08-23 15:27:50,397-0500 INFO Block Started CPU 2:1314131270s 2011-08-23 15:27:50,397-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:3 2011-08-23 15:27:50,397-0500 DEBUG Cpu 0823-270342-000000:3 pullLater 2011-08-23 15:27:50,397-0500 INFO Block Started CPU 3:1314131270s 2011-08-23 15:27:50,398-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:4 2011-08-23 15:27:50,398-0500 DEBUG Cpu 0823-270342-000000:4 pullLater 2011-08-23 15:27:50,398-0500 INFO Block Started CPU 4:1314131270s 2011-08-23 15:27:50,398-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:5 2011-08-23 15:27:50,398-0500 DEBUG Cpu 0823-270342-000000:5 pullLater 2011-08-23 15:27:50,398-0500 INFO Block Started CPU 5:1314131270s 2011-08-23 15:27:50,398-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:6 2011-08-23 15:27:50,398-0500 DEBUG Cpu 0823-270342-000000:6 pullLater 2011-08-23 15:27:50,398-0500 INFO Block Started CPU 6:1314131270s 2011-08-23 15:27:50,398-0500 DEBUG Cpu workerStarted: 0823-270342-000000:c23.pads.ci.uchicago.edu:7 2011-08-23 15:27:50,398-0500 DEBUG Cpu 0823-270342-000000:7 pullLater 2011-08-23 15:27:50,398-0500 INFO Block Started CPU 7:1314131270s 2011-08-23 15:27:50,398-0500 INFO Block Started worker 0823-270342-000000:000000 2011-08-23 15:27:50,398-0500 INFO Cpu 0823-270342-000000:0 submitting urn:1314131261790-1314131261793-1314131261794: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-8bslmuek -jobdir 8 -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0020.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0020.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:27:50,399-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261790-1314131261793-1314131261794) Submitting 2011-08-23 15:27:50,400-0500 INFO Cpu 0823-270342-000000:1 pull 2011-08-23 15:27:50,400-0500 INFO Cpu 0823-270342-000000:1 submitting urn:1314131261789-1314131261796-1314131261797: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-9bslmuek -jobdir 9 -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0008.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0008.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:27:50,400-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261789-1314131261796-1314131261797) Submitting 2011-08-23 15:27:50,400-0500 INFO Cpu 0823-270342-000000:2 pull 2011-08-23 15:27:50,400-0500 INFO Cpu 0823-270342-000000:3 pull 2011-08-23 15:27:50,400-0500 INFO Cpu 0823-270342-000000:4 pull 2011-08-23 15:27:50,401-0500 INFO Cpu 0823-270342-000000:5 pull 2011-08-23 15:27:50,401-0500 INFO Cpu 0823-270342-000000:6 pull 2011-08-23 15:27:50,401-0500 INFO Cpu 0823-270342-000000:7 pull 2011-08-23 15:27:50,422-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261790-1314131261793-1314131261794) Submitted 2011-08-23 15:27:50,467-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261790-1314131261793-1314131261794) Active workerid=000000 2011-08-23 15:27:50,468-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261789-1314131261796-1314131261797) Submitted 2011-08-23 15:27:50,468-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261789-1314131261796-1314131261797) Active workerid=000000 2011-08-23 15:27:52,583-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:27:53,247-0500 INFO Block Block task status changed: Active 2011-08-23 15:27:53,247-0500 INFO RemoteLogHandler BLOCK_ACTIVE id=0823-270342-000000 2011-08-23 15:27:53,248-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:27:58,289-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:00,391-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:28:00,438-0500 INFO PullThread runTime: 4, sleepTime: 10037 2011-08-23 15:28:02,586-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:28:03,359-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:08,402-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:10,401-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:28:10,474-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:28:12,589-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:28:13,444-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:18,486-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:20,411-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:28:20,510-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:28:22,592-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:28:23,528-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:28,570-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:29,087-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:28:30,421-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:28:30,546-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:28:32,595-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:28:33,613-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:38,659-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:40,433-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:28:40,582-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:28:42,598-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:28:43,784-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:48,827-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:50,443-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:28:50,618-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:28:50,707-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261790-1314131261793-1314131261794) Completed 2011-08-23 15:28:50,707-0500 INFO Cpu 0823-270342-000000:0 jobTerminated 2011-08-23 15:28:50,708-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,708-0500 DEBUG Cpu 0823-270342-000000:0 pullLater 2011-08-23 15:28:50,708-0500 INFO Cpu 0823-270342-000000:0 pull 2011-08-23 15:28:50,708-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261789-1314131261796-1314131261797) Completed 2011-08-23 15:28:50,708-0500 INFO Cpu 0823-270342-000000:1 jobTerminated 2011-08-23 15:28:50,708-0500 DEBUG Cpu 0823-270342-000000:1 pullLater 2011-08-23 15:28:50,708-0500 INFO Cpu 0823-270342-000000:1 pull 2011-08-23 15:28:50,709-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:28:50,708-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,713-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-8bslmuek 2011-08-23 15:28:50,713-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-9bslmuek 2011-08-23 15:28:50,715-0500 INFO vdl:dostageout START jobid=catnap-8bslmuek - Staging out files 2011-08-23 15:28:50,715-0500 INFO vdl:dostageout START jobid=catnap-9bslmuek - Staging out files 2011-08-23 15:28:50,715-0500 DEBUG vdl:dostageout stageouts: [[$, out[20]:file - Open]] 2011-08-23 15:28:50,716-0500 DEBUG vdl:dostageout stageouts: [[$, out[8]:file - Open]] 2011-08-23 15:28:50,729-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0008.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:28:50,729-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0020.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:28:50,731-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,731-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,757-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,758-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0020.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:28:50,759-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,761-0500 INFO vdl:dostageout END jobid=catnap-8bslmuek - Staging out finished 2011-08-23 15:28:50,764-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,765-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0008.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:28:50,765-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,767-0500 INFO vdl:dostageout END jobid=catnap-9bslmuek - Staging out finished 2011-08-23 15:28:50,776-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,777-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-8bslmuek 2011-08-23 15:28:50,777-0500 INFO vdl:execute END_SUCCESS thread=0-4-19-1 tr=catnap 2011-08-23 15:28:50,778-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:28:50,778-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-19 2011-08-23 15:28:50,779-0500 INFO LateBindingScheduler JobQueue: 18 2011-08-23 15:28:50,779-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:28:50,781-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-abslmuek thread=0-4-6-1-1 host=pbs replicationGroup=1bslmuek 2011-08-23 15:28:50,781-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-9bslmuek 2011-08-23 15:28:50,782-0500 INFO vdl:execute END_SUCCESS thread=0-4-7-1 tr=catnap 2011-08-23 15:28:50,782-0500 INFO vdl:createdirset START jobid=catnap-abslmuek host=pbs - Initializing directory structure 2011-08-23 15:28:50,782-0500 INFO vdl:createdirset END jobid=catnap-abslmuek - Done initializing directory structure 2011-08-23 15:28:50,782-0500 INFO vdl:dostagein START jobid=catnap-abslmuek - Staging in files 2011-08-23 15:28:50,783-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:28:50,783-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:28:50,783-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-7 2011-08-23 15:28:50,784-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:28:50,784-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-bbslmuek thread=0-4-0-1-1 host=pbs replicationGroup=2bslmuek 2011-08-23 15:28:50,784-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:28:50,785-0500 INFO vdl:dostagein END jobid=catnap-abslmuek - Staging in finished 2011-08-23 15:28:50,786-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-abslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/a/catnap-abslmuek host=pbs 2011-08-23 15:28:50,786-0500 INFO vdl:createdirset START jobid=catnap-bbslmuek host=pbs - Initializing directory structure 2011-08-23 15:28:50,786-0500 INFO vdl:createdirset END jobid=catnap-bbslmuek - Done initializing directory structure 2011-08-23 15:28:50,786-0500 INFO vdl:dostagein START jobid=catnap-bbslmuek - Staging in files 2011-08-23 15:28:50,788-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:28:50,788-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-6-1-1-1314131261824) is /bin/bash shared/_swiftwrap catnap-abslmuek -jobdir a -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0007.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0007.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:28:50,789-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:28:50,789-0500 INFO vdl:dostagein END jobid=catnap-bbslmuek - Staging in finished 2011-08-23 15:28:50,790-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-bbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/b/catnap-bbslmuek host=pbs 2011-08-23 15:28:50,792-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-0-1-1-1314131261826) is /bin/bash shared/_swiftwrap catnap-bbslmuek -jobdir b -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0001.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0001.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:28:50,812-0500 INFO Cpu 0823-270342-000000:2 pull 2011-08-23 15:28:50,813-0500 INFO Cpu 0823-270342-000000:2 submitting urn:1314131261824-1314131261828-1314131261829: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-abslmuek -jobdir a -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0007.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0007.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:28:50,813-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261824-1314131261828-1314131261829) Submitting 2011-08-23 15:28:50,813-0500 INFO Cpu 0823-270342-000000:3 pull 2011-08-23 15:28:50,813-0500 INFO Cpu 0823-270342-000000:3 submitting urn:1314131261826-1314131261831-1314131261832: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-bbslmuek -jobdir b -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0001.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0001.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:28:50,813-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261826-1314131261831-1314131261832) Submitting 2011-08-23 15:28:50,814-0500 INFO Cpu 0823-270342-000000:4 pull 2011-08-23 15:28:50,814-0500 INFO Cpu 0823-270342-000000:5 pull 2011-08-23 15:28:50,814-0500 INFO Cpu 0823-270342-000000:6 pull 2011-08-23 15:28:50,814-0500 INFO Cpu 0823-270342-000000:7 pull 2011-08-23 15:28:50,814-0500 INFO Cpu 0823-270342-000000:0 pull 2011-08-23 15:28:50,814-0500 INFO Cpu 0823-270342-000000:1 pull 2011-08-23 15:28:50,818-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261824-1314131261828-1314131261829) Submitted 2011-08-23 15:28:50,862-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261824-1314131261828-1314131261829) Active workerid=000000 2011-08-23 15:28:50,863-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261826-1314131261831-1314131261832) Submitted 2011-08-23 15:28:50,864-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261826-1314131261831-1314131261832) Active workerid=000000 2011-08-23 15:28:52,601-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:28:53,870-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:28:58,911-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:00,455-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:29:00,642-0500 INFO PullThread runTime: 3, sleepTime: 10021 2011-08-23 15:29:02,604-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:29:04,010-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:09,054-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:10,465-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:29:10,678-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:29:12,607-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:29:14,095-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:19,137-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:20,475-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:29:20,714-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:29:22,610-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:29:24,179-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:29,219-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:29,359-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:29:30,485-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:29:30,750-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:29:32,613-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:29:34,260-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:39,301-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:40,495-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:29:40,787-0500 INFO PullThread runTime: 1, sleepTime: 10035 2011-08-23 15:29:42,616-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:29:44,426-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:49,469-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:50,505-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:29:50,823-0500 INFO PullThread runTime: 11, sleepTime: 10026 2011-08-23 15:29:51,276-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261824-1314131261828-1314131261829) Completed 2011-08-23 15:29:51,276-0500 INFO Cpu 0823-270342-000000:2 jobTerminated 2011-08-23 15:29:51,276-0500 DEBUG Cpu 0823-270342-000000:2 pullLater 2011-08-23 15:29:51,276-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,276-0500 INFO Cpu 0823-270342-000000:2 pull 2011-08-23 15:29:51,276-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261826-1314131261831-1314131261832) Completed 2011-08-23 15:29:51,277-0500 INFO Cpu 0823-270342-000000:3 jobTerminated 2011-08-23 15:29:51,277-0500 DEBUG Cpu 0823-270342-000000:3 pullLater 2011-08-23 15:29:51,277-0500 INFO Cpu 0823-270342-000000:3 pull 2011-08-23 15:29:51,277-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:29:51,277-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-abslmuek 2011-08-23 15:29:51,278-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,278-0500 INFO vdl:dostageout START jobid=catnap-abslmuek - Staging out files 2011-08-23 15:29:51,278-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-bbslmuek 2011-08-23 15:29:51,278-0500 INFO vdl:dostageout START jobid=catnap-bbslmuek - Staging out files 2011-08-23 15:29:51,278-0500 DEBUG vdl:dostageout stageouts: [[$, out[1]:file - Open]] 2011-08-23 15:29:51,279-0500 DEBUG vdl:dostageout stageouts: [[$, out[7]:file - Open]] 2011-08-23 15:29:51,280-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0007.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:29:51,280-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0001.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:29:51,281-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,281-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,301-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,301-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0007.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:29:51,302-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,303-0500 INFO vdl:dostageout END jobid=catnap-abslmuek - Staging out finished 2011-08-23 15:29:51,305-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,305-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0001.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:29:51,306-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,307-0500 INFO vdl:dostageout END jobid=catnap-bbslmuek - Staging out finished 2011-08-23 15:29:51,316-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,316-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-abslmuek 2011-08-23 15:29:51,316-0500 INFO vdl:execute END_SUCCESS thread=0-4-6-1 tr=catnap 2011-08-23 15:29:51,316-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:29:51,317-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-6 2011-08-23 15:29:51,317-0500 INFO LateBindingScheduler JobQueue: 16 2011-08-23 15:29:51,319-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:29:51,319-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-bbslmuek 2011-08-23 15:29:51,319-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:29:51,319-0500 INFO vdl:execute END_SUCCESS thread=0-4-0-1 tr=catnap 2011-08-23 15:29:51,320-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:29:51,320-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-0 2011-08-23 15:29:51,321-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-cbslmuek thread=0-4-1-1-1 host=pbs replicationGroup=4bslmuek 2011-08-23 15:29:51,321-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-dbslmuek thread=0-4-9-1-1 host=pbs replicationGroup=3bslmuek 2011-08-23 15:29:51,322-0500 INFO vdl:createdirset START jobid=catnap-cbslmuek host=pbs - Initializing directory structure 2011-08-23 15:29:51,322-0500 INFO vdl:createdirset END jobid=catnap-cbslmuek - Done initializing directory structure 2011-08-23 15:29:51,322-0500 INFO vdl:dostagein START jobid=catnap-cbslmuek - Staging in files 2011-08-23 15:29:51,323-0500 INFO vdl:createdirset START jobid=catnap-dbslmuek host=pbs - Initializing directory structure 2011-08-23 15:29:51,323-0500 INFO vdl:createdirset END jobid=catnap-dbslmuek - Done initializing directory structure 2011-08-23 15:29:51,323-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:29:51,323-0500 INFO vdl:dostagein START jobid=catnap-dbslmuek - Staging in files 2011-08-23 15:29:51,324-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:29:51,324-0500 INFO vdl:dostagein END jobid=catnap-cbslmuek - Staging in finished 2011-08-23 15:29:51,325-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-cbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/c/catnap-cbslmuek host=pbs 2011-08-23 15:29:51,325-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:29:51,325-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:29:51,326-0500 INFO vdl:dostagein END jobid=catnap-dbslmuek - Staging in finished 2011-08-23 15:29:51,326-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-dbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/d/catnap-dbslmuek host=pbs 2011-08-23 15:29:51,327-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-1-1-1-1314131261858) is /bin/bash shared/_swiftwrap catnap-cbslmuek -jobdir c -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0002.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0002.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:29:51,327-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-9-1-1-1314131261860) is /bin/bash shared/_swiftwrap catnap-dbslmuek -jobdir d -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0010.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0010.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:29:51,381-0500 INFO Cpu 0823-270342-000000:4 pull 2011-08-23 15:29:51,381-0500 INFO Cpu 0823-270342-000000:4 submitting urn:1314131261858-1314131261862-1314131261863: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-cbslmuek -jobdir c -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0002.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0002.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:29:51,381-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261858-1314131261862-1314131261863) Submitting 2011-08-23 15:29:51,381-0500 INFO Cpu 0823-270342-000000:5 pull 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:5 submitting urn:1314131261860-1314131261865-1314131261866: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-dbslmuek -jobdir d -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0010.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0010.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:29:51,382-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261860-1314131261865-1314131261866) Submitting 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:6 pull 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:7 pull 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:0 pull 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:1 pull 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:2 pull 2011-08-23 15:29:51,382-0500 INFO Cpu 0823-270342-000000:3 pull 2011-08-23 15:29:51,387-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261858-1314131261862-1314131261863) Submitted 2011-08-23 15:29:51,387-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261858-1314131261862-1314131261863) Active workerid=000000 2011-08-23 15:29:51,409-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261860-1314131261865-1314131261866) Submitted 2011-08-23 15:29:51,409-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261860-1314131261865-1314131261866) Active workerid=000000 2011-08-23 15:29:52,619-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:29:54,509-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:29:59,551-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:00,517-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:30:00,847-0500 INFO PullThread runTime: 1, sleepTime: 10023 2011-08-23 15:30:02,622-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:30:04,652-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:09,697-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:10,527-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:30:10,884-0500 INFO PullThread runTime: 0, sleepTime: 10037 2011-08-23 15:30:12,625-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:30:14,740-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:19,781-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:20,537-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:30:20,920-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:30:22,628-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:30:24,830-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:29,684-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:30:29,872-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:30,548-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:30:30,956-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:30:32,631-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:30:34,914-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:39,956-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:40,558-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:30:40,992-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:30:42,634-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:30:45,079-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:50,121-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:30:50,568-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:30:51,028-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:30:51,668-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261860-1314131261865-1314131261866) Completed 2011-08-23 15:30:51,668-0500 INFO Cpu 0823-270342-000000:5 jobTerminated 2011-08-23 15:30:51,668-0500 DEBUG Cpu 0823-270342-000000:5 pullLater 2011-08-23 15:30:51,668-0500 INFO Cpu 0823-270342-000000:5 pull 2011-08-23 15:30:51,669-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,669-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261858-1314131261862-1314131261863) Completed 2011-08-23 15:30:51,669-0500 INFO Cpu 0823-270342-000000:4 jobTerminated 2011-08-23 15:30:51,669-0500 DEBUG Cpu 0823-270342-000000:4 pullLater 2011-08-23 15:30:51,669-0500 INFO Cpu 0823-270342-000000:4 pull 2011-08-23 15:30:51,670-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,670-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:30:51,670-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-dbslmuek 2011-08-23 15:30:51,670-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-cbslmuek 2011-08-23 15:30:51,670-0500 INFO vdl:dostageout START jobid=catnap-dbslmuek - Staging out files 2011-08-23 15:30:51,670-0500 INFO vdl:dostageout START jobid=catnap-cbslmuek - Staging out files 2011-08-23 15:30:51,670-0500 DEBUG vdl:dostageout stageouts: [[$, out[10]:file - Open]] 2011-08-23 15:30:51,671-0500 DEBUG vdl:dostageout stageouts: [[$, out[2]:file - Open]] 2011-08-23 15:30:51,671-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0010.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:30:51,671-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0002.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:30:51,672-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,672-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,692-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,692-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0010.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:30:51,693-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,694-0500 INFO vdl:dostageout END jobid=catnap-dbslmuek - Staging out finished 2011-08-23 15:30:51,695-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,696-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0002.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:30:51,696-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,697-0500 INFO vdl:dostageout END jobid=catnap-cbslmuek - Staging out finished 2011-08-23 15:30:51,708-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,709-0500 INFO LateBindingScheduler JobQueue: 14 2011-08-23 15:30:51,710-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-cbslmuek 2011-08-23 15:30:51,710-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-dbslmuek 2011-08-23 15:30:51,710-0500 INFO vdl:execute END_SUCCESS thread=0-4-1-1 tr=catnap 2011-08-23 15:30:51,710-0500 INFO vdl:execute END_SUCCESS thread=0-4-9-1 tr=catnap 2011-08-23 15:30:51,711-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:30:51,711-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:30:51,711-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-1 2011-08-23 15:30:51,711-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-9 2011-08-23 15:30:51,762-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:51,762-0500 INFO Block Shutting down block Block 0823-270342-000000 (8x1200.000s) 2011-08-23 15:30:51,763-0500 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0823-270342-000000 2011-08-23 15:30:51,823-0500 INFO Node Node [c23.pads.ci.uchicago.edu] 0 shut down successfully 2011-08-23 15:30:52,211-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:30:52,211-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:30:52,212-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-ebslmuek thread=0-4-10-1-1 host=pbs replicationGroup=oaslmuek 2011-08-23 15:30:52,213-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-fbslmuek thread=0-4-5-1-1 host=pbs replicationGroup=qaslmuek 2011-08-23 15:30:52,213-0500 INFO vdl:createdirset START jobid=catnap-ebslmuek host=pbs - Initializing directory structure 2011-08-23 15:30:52,214-0500 INFO vdl:createdirset END jobid=catnap-ebslmuek - Done initializing directory structure 2011-08-23 15:30:52,214-0500 INFO vdl:dostagein START jobid=catnap-ebslmuek - Staging in files 2011-08-23 15:30:52,214-0500 INFO vdl:createdirset START jobid=catnap-fbslmuek host=pbs - Initializing directory structure 2011-08-23 15:30:52,214-0500 INFO vdl:createdirset END jobid=catnap-fbslmuek - Done initializing directory structure 2011-08-23 15:30:52,214-0500 INFO vdl:dostagein START jobid=catnap-fbslmuek - Staging in files 2011-08-23 15:30:52,215-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:30:52,215-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:30:52,216-0500 INFO vdl:dostagein END jobid=catnap-ebslmuek - Staging in finished 2011-08-23 15:30:52,216-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:30:52,216-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-ebslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/e/catnap-ebslmuek host=pbs 2011-08-23 15:30:52,217-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:30:52,217-0500 INFO vdl:dostagein END jobid=catnap-fbslmuek - Staging in finished 2011-08-23 15:30:52,217-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-fbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/f/catnap-fbslmuek host=pbs 2011-08-23 15:30:52,218-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-10-1-1-1314131261892) is /bin/bash shared/_swiftwrap catnap-ebslmuek -jobdir e -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0011.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0011.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:30:52,219-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-5-1-1-1314131261894) is /bin/bash shared/_swiftwrap catnap-fbslmuek -jobdir f -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0006.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0006.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,241-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,242-0500 INFO Block Block 0823-270342-000000 (8x1200.000s): all cpus are clear 2011-08-23 15:30:52,637-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:30:55,187-0500 INFO Block Block task status changed: Completed 2011-08-23 15:30:55,187-0500 INFO BlockQueueProcessor Removing block Block 0823-270342-000000 (8x1200.000s) 2011-08-23 15:30:55,187-0500 INFO Block 0823-270342-000000 stdout: ---------------------------------------- Begin PBS Prologue Tue Aug 23 15:27:49 CDT 2011 Job ID: 1691873.svc.pads.ci.uchicago.edu Username: ketan Group: ci-users Nodes: c23.pads.ci.uchicago.edu End PBS Prologue Tue Aug 23 15:27:49 CDT 2011 ---------------------------------------- ---------------------------------------- Begin PBS Epilogue Tue Aug 23 15:30:52 CDT 2011 Job ID: 1691873.svc.pads.ci.uchicago.edu Username: ketan Group: ci-users Job Name: Block-0823-2703 Session: 12746 Limits: ncpus=1,neednodes=1:ppn=1,nodes=1:ppn=1,size=1,walltime=00:20:00 Resources: cput=00:00:00,mem=18284kb,vmem=606836kb,walltime=00:03:03 Nodes: c23.pads.ci.uchicago.edu End PBS Epilogue Tue Aug 23 15:30:52 CDT 2011 ---------------------------------------- 2011-08-23 15:30:55,187-0500 INFO Block 0823-270342-000000 stderr: 2011-08-23 15:30:55,187-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 1 2011-08-23 15:30:57,821-0500 INFO BlockQueueProcessor Requeued 2 non-fitting jobs 2011-08-23 15:30:57,822-0500 INFO BlockQueueProcessor Required size: 2.144628893377326 for 2 jobs 2011-08-23 15:30:57,822-0500 INFO BlockQueueProcessor h: 1080, jj: 120, x-last: , r: 1, sumsz: 1 2011-08-23 15:30:57,822-0500 INFO BlockQueueProcessor h: 1200, w: 8, size: 2.0, msz: 2, w*h: 9600 2011-08-23 15:30:57,822-0500 INFO BlockQueueProcessor Added: 0 - 1 2011-08-23 15:30:57,822-0500 INFO Block Starting block: workers=8, walltime=1200.000s 2011-08-23 15:30:57,822-0500 INFO BlockTaskSubmitter Queuing block Block 0823-270342-000001 (8x1200.000s) for submission 2011-08-23 15:30:57,822-0500 INFO BlockQueueProcessor Added 2 jobs to new blocks 2011-08-23 15:30:57,822-0500 INFO RemoteLogHandler BLOCK_REQUESTED id=0823-270342-000001, w=8, h=1200 2011-08-23 15:30:57,823-0500 INFO BlockTaskSubmitter Submitting block Block 0823-270342-000001 (8x1200.000s) 2011-08-23 15:30:57,823-0500 INFO ExecutionTaskHandler provider=pbs 2011-08-23 15:30:57,824-0500 INFO Block Block task status changed: Submitting 2011-08-23 15:30:57,830-0500 DEBUG AbstractExecutor Writing PBS script to /home/ketan/.globus/scripts/PBS4031033146726912965.submit 2011-08-23 15:30:57,839-0500 DEBUG PBSExecutor PBS name: for: Block-0823-270342-000001 is: Block-0823-2703 2011-08-23 15:30:57,839-0500 DEBUG PBSExecutor Job type: null 2011-08-23 15:30:57,845-0500 DEBUG AbstractExecutor Wrote PBS script to /home/ketan/.globus/scripts/PBS4031033146726912965.submit 2011-08-23 15:30:57,846-0500 DEBUG AbstractExecutor Command line: qsub /home/ketan/.globus/scripts/PBS4031033146726912965.submit 2011-08-23 15:30:58,276-0500 DEBUG AbstractExecutor qsub done (exit code 0) 2011-08-23 15:30:58,276-0500 DEBUG AbstractExecutor Waiting for output from qsub 2011-08-23 15:30:58,277-0500 DEBUG AbstractExecutor Output from qsub is: "1691874.svc.pads.ci.uchicago.edu" 2011-08-23 15:30:58,277-0500 DEBUG AbstractExecutor Submitted job with id '1691874.svc.pads.ci.uchicago.edu' 2011-08-23 15:30:58,277-0500 INFO Block Block task status changed: Submitted 2011-08-23 15:31:00,189-0500 INFO AbstractQueuePoller Actively monitored: 0, New: 1, Done: 0 2011-08-23 15:31:00,579-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:31:01,029-0500 INFO PullThread runTime: 2, sleepTime: 9999 2011-08-23 15:31:02,640-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:31:05,512-0500 INFO Block Block task status changed: Active 2011-08-23 15:31:05,512-0500 INFO RemoteLogHandler BLOCK_ACTIVE id=0823-270342-000001 2011-08-23 15:31:05,514-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:05,678-0500 INFO TCPBufferManager Adjusting buffer size to 786432 2011-08-23 15:31:05,678-0500 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-08-23 15:31:05,678-0500 INFO AbstractStreamKarajanChannel nullChannel started 2011-08-23 15:31:05,706-0500 INFO LocalTCPService Received registration: blockid = 0823-270342-000001, url = c23.pads.ci.uchicago.edu 2011-08-23 15:31:05,706-0500 INFO AbstractKarajanChannel MetaChannel: 873128399[913242042: {}] -> null: Disabling heartbeats (config is null) 2011-08-23 15:31:05,706-0500 INFO MetaChannel MetaChannel: 873128399[913242042: {}] -> null.bind -> SC-null 2011-08-23 15:31:05,706-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:0 2011-08-23 15:31:05,706-0500 DEBUG Cpu 0823-270342-000001:0 pullLater 2011-08-23 15:31:05,706-0500 INFO Block Started CPU 0:1314131465s 2011-08-23 15:31:05,706-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:1 2011-08-23 15:31:05,706-0500 DEBUG Cpu 0823-270342-000001:1 pullLater 2011-08-23 15:31:05,706-0500 INFO Block Started CPU 1:1314131465s 2011-08-23 15:31:05,706-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:31:05,706-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:2 2011-08-23 15:31:05,706-0500 DEBUG Cpu 0823-270342-000001:2 pullLater 2011-08-23 15:31:05,707-0500 INFO Block Started CPU 2:1314131465s 2011-08-23 15:31:05,707-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:3 2011-08-23 15:31:05,707-0500 DEBUG Cpu 0823-270342-000001:3 pullLater 2011-08-23 15:31:05,707-0500 INFO Block Started CPU 3:1314131465s 2011-08-23 15:31:05,707-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:4 2011-08-23 15:31:05,707-0500 DEBUG Cpu 0823-270342-000001:4 pullLater 2011-08-23 15:31:05,707-0500 INFO Block Started CPU 4:1314131465s 2011-08-23 15:31:05,707-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:5 2011-08-23 15:31:05,707-0500 DEBUG Cpu 0823-270342-000001:5 pullLater 2011-08-23 15:31:05,707-0500 INFO Block Started CPU 5:1314131465s 2011-08-23 15:31:05,707-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:6 2011-08-23 15:31:05,707-0500 DEBUG Cpu 0823-270342-000001:6 pullLater 2011-08-23 15:31:05,707-0500 INFO Block Started CPU 6:1314131465s 2011-08-23 15:31:05,707-0500 DEBUG Cpu workerStarted: 0823-270342-000001:c23.pads.ci.uchicago.edu:7 2011-08-23 15:31:05,707-0500 DEBUG Cpu 0823-270342-000001:7 pullLater 2011-08-23 15:31:05,707-0500 INFO Block Started CPU 7:1314131465s 2011-08-23 15:31:05,707-0500 INFO Block Started worker 0823-270342-000001:000000 2011-08-23 15:31:05,708-0500 INFO Cpu 0823-270342-000001:0 submitting urn:1314131261892-1314131261896-1314131261897: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-ebslmuek -jobdir e -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0011.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0011.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:31:05,708-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261892-1314131261896-1314131261897) Submitting 2011-08-23 15:31:05,709-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:31:05,709-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:31:05,709-0500 INFO Cpu 0823-270342-000001:1 submitting urn:1314131261894-1314131261899-1314131261900: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-fbslmuek -jobdir f -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0006.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0006.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:31:05,709-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261894-1314131261899-1314131261900) Submitting 2011-08-23 15:31:05,709-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:31:05,710-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:31:05,710-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:31:05,710-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:31:05,710-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:31:05,710-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:31:05,730-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261892-1314131261896-1314131261897) Submitted 2011-08-23 15:31:05,751-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261892-1314131261896-1314131261897) Active workerid=000000 2011-08-23 15:31:05,752-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261894-1314131261899-1314131261900) Submitted 2011-08-23 15:31:05,753-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261894-1314131261899-1314131261900) Active workerid=000000 2011-08-23 15:31:10,558-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:10,594-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:31:11,066-0500 INFO PullThread runTime: 4, sleepTime: 10033 2011-08-23 15:31:12,643-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:31:15,602-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:20,604-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:31:20,647-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:21,102-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:31:22,646-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:31:25,689-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:30,014-0500 INFO AbstractStreamKarajanChannel Channel IOException java.net.SocketException: Broken pipe at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:124) at org.globus.cog.karajan.workflow.service.channels.AbstractStreamKarajanChannel$Sender.send(AbstractStreamKarajanChannel.java:305) at org.globus.cog.karajan.workflow.service.channels.AbstractStreamKarajanChannel$Sender.run(AbstractStreamKarajanChannel.java:251) 2011-08-23 15:31:30,016-0500 INFO AbstractStreamKarajanChannel Channel config: null 2011-08-23 15:31:30,016-0500 INFO ChannelManager Handling channel exception java.net.SocketException: Broken pipe at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:124) at org.globus.cog.karajan.workflow.service.channels.AbstractStreamKarajanChannel$Sender.send(AbstractStreamKarajanChannel.java:305) at org.globus.cog.karajan.workflow.service.channels.AbstractStreamKarajanChannel$Sender.run(AbstractStreamKarajanChannel.java:251) 2011-08-23 15:31:30,017-0500 INFO TCPBufferManager Adjusting buffer size to 1572864 2011-08-23 15:31:30,017-0500 INFO AbstractStreamKarajanChannel 0823-270342-000000-000000: Channel shut down 2011-08-23 15:31:30,017-0500 INFO MetaChannel MetaChannel: 1473790157[914784201: {}] -> SC-0823-270342-000000-000000.bind -> NullChannel 2011-08-23 15:31:30,017-0500 INFO AbstractStreamKarajanChannel$Multiplexer Unregistering channel SC-0823-270342-000000-000000 2011-08-23 15:31:30,017-0500 INFO Node Node [c23.pads.ci.uchicago.edu] 0 lost connection to worker; removing node from block. java.net.SocketException: Broken pipe at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:124) at org.globus.cog.karajan.workflow.service.channels.AbstractStreamKarajanChannel$Sender.send(AbstractStreamKarajanChannel.java:305) at org.globus.cog.karajan.workflow.service.channels.AbstractStreamKarajanChannel$Sender.run(AbstractStreamKarajanChannel.java:251) 2011-08-23 15:31:30,018-0500 INFO MetaChannel MetaChannel: 1473790157[914784201: {}] -> NullChannel.bind -> NullChannel 2011-08-23 15:31:30,018-0500 INFO ChannelManager Channel exception handled 2011-08-23 15:31:30,018-0500 INFO AbstractStreamKarajanChannel 0823-270342-000000-000000: Channel shut down 2011-08-23 15:31:30,021-0500 INFO AbstractStreamKarajanChannel$Multiplexer Channel is closed. Removing. 2011-08-23 15:31:30,615-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:31:30,732-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:31,138-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:31:32,649-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:31:35,698-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:31:35,775-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:40,625-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:31:40,817-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:41,174-0500 INFO PullThread runTime: 1, sleepTime: 10035 2011-08-23 15:31:42,652-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:31:45,939-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:50,635-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:31:50,980-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:31:51,211-0500 INFO PullThread runTime: 6, sleepTime: 10031 2011-08-23 15:31:52,655-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:31:56,022-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:00,646-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:32:01,066-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:01,247-0500 INFO PullThread runTime: 7, sleepTime: 10029 2011-08-23 15:32:02,658-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:32:05,970-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261892-1314131261896-1314131261897) Completed 2011-08-23 15:32:05,970-0500 INFO Cpu 0823-270342-000001:0 jobTerminated 2011-08-23 15:32:05,970-0500 DEBUG Cpu 0823-270342-000001:0 pullLater 2011-08-23 15:32:05,970-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:32:05,970-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261894-1314131261899-1314131261900) Completed 2011-08-23 15:32:05,970-0500 INFO Cpu 0823-270342-000001:1 jobTerminated 2011-08-23 15:32:05,970-0500 DEBUG Cpu 0823-270342-000001:1 pullLater 2011-08-23 15:32:05,971-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:32:05,971-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,971-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:32:05,971-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-ebslmuek 2011-08-23 15:32:05,971-0500 INFO vdl:dostageout START jobid=catnap-ebslmuek - Staging out files 2011-08-23 15:32:05,971-0500 DEBUG vdl:dostageout stageouts: [[$, out[11]:file - Open]] 2011-08-23 15:32:05,972-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,972-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0011.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:32:05,973-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-fbslmuek 2011-08-23 15:32:05,974-0500 INFO vdl:dostageout START jobid=catnap-fbslmuek - Staging out files 2011-08-23 15:32:05,974-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,974-0500 DEBUG vdl:dostageout stageouts: [[$, out[6]:file - Open]] 2011-08-23 15:32:05,976-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0006.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:32:05,977-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,993-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,994-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0011.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:32:05,995-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,996-0500 INFO vdl:dostageout END jobid=catnap-ebslmuek - Staging out finished 2011-08-23 15:32:05,997-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,998-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0006.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:32:05,999-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:05,999-0500 INFO vdl:dostageout END jobid=catnap-fbslmuek - Staging out finished 2011-08-23 15:32:06,010-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:06,010-0500 INFO LateBindingScheduler JobQueue: 12 2011-08-23 15:32:06,010-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-fbslmuek 2011-08-23 15:32:06,011-0500 INFO vdl:execute END_SUCCESS thread=0-4-5-1 tr=catnap 2011-08-23 15:32:06,011-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-ebslmuek 2011-08-23 15:32:06,011-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:32:06,011-0500 INFO vdl:execute END_SUCCESS thread=0-4-10-1 tr=catnap 2011-08-23 15:32:06,011-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-5 2011-08-23 15:32:06,011-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:32:06,011-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-10 2011-08-23 15:32:06,165-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:06,513-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:32:06,513-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:32:06,514-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-hbslmuek thread=0-4-15-1-1 host=pbs replicationGroup=xaslmuek 2011-08-23 15:32:06,514-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-gbslmuek thread=0-4-17-1-1 host=pbs replicationGroup=saslmuek 2011-08-23 15:32:06,515-0500 INFO vdl:createdirset START jobid=catnap-gbslmuek host=pbs - Initializing directory structure 2011-08-23 15:32:06,515-0500 INFO vdl:createdirset START jobid=catnap-hbslmuek host=pbs - Initializing directory structure 2011-08-23 15:32:06,515-0500 INFO vdl:createdirset END jobid=catnap-gbslmuek - Done initializing directory structure 2011-08-23 15:32:06,515-0500 INFO vdl:createdirset END jobid=catnap-hbslmuek - Done initializing directory structure 2011-08-23 15:32:06,515-0500 INFO vdl:dostagein START jobid=catnap-gbslmuek - Staging in files 2011-08-23 15:32:06,515-0500 INFO vdl:dostagein START jobid=catnap-hbslmuek - Staging in files 2011-08-23 15:32:06,517-0500 INFO LateBindingScheduler JobQueue: 11 2011-08-23 15:32:06,518-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:32:06,518-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:32:06,518-0500 INFO vdl:dostagein END jobid=catnap-gbslmuek - Staging in finished 2011-08-23 15:32:06,519-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:32:06,519-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-gbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/g/catnap-gbslmuek host=pbs 2011-08-23 15:32:06,520-0500 INFO vdl:dostagein END jobid=catnap-hbslmuek - Staging in finished 2011-08-23 15:32:06,520-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-hbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/h/catnap-hbslmuek host=pbs 2011-08-23 15:32:06,523-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-17-1-1-1314131261927) is /bin/bash shared/_swiftwrap catnap-gbslmuek -jobdir g -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0018.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0018.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:32:06,523-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-15-1-1-1314131261929) is /bin/bash shared/_swiftwrap catnap-hbslmuek -jobdir h -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0016.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0016.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:32:06,543-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:32:06,543-0500 INFO Cpu 0823-270342-000001:2 submitting urn:1314131261927-1314131261931-1314131261932: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-gbslmuek -jobdir g -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0018.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0018.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:32:06,543-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261927-1314131261931-1314131261932) Submitting 2011-08-23 15:32:06,544-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:32:06,544-0500 INFO Cpu 0823-270342-000001:3 submitting urn:1314131261929-1314131261934-1314131261935: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-hbslmuek -jobdir h -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0016.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0016.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:32:06,544-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261929-1314131261934-1314131261935) Submitting 2011-08-23 15:32:06,545-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:32:06,545-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:32:06,545-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:32:06,545-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:32:06,545-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:32:06,545-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:32:06,565-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261927-1314131261931-1314131261932) Submitted 2011-08-23 15:32:06,587-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261927-1314131261931-1314131261932) Active workerid=000000 2011-08-23 15:32:06,587-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261929-1314131261934-1314131261935) Submitted 2011-08-23 15:32:06,588-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261929-1314131261934-1314131261935) Active workerid=000000 2011-08-23 15:32:10,658-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:32:11,210-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:11,277-0500 INFO PullThread runTime: 2, sleepTime: 10028 2011-08-23 15:32:12,661-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:32:16,251-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:17,187-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:32:20,668-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:32:21,294-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:21,313-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:32:22,664-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:32:26,337-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:30,678-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:32:31,349-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:32:31,378-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:32,667-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:32:36,421-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:40,688-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:32:41,385-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:32:41,463-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:42,670-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:32:46,588-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:50,698-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:32:51,421-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:32:51,631-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:52,672-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:32:56,548-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:32:56,673-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:32:59,860-0500 WARN Command Command(13, HEARTBEAT): handling reply timeout; sendReqTime=110823-153059.847, sendTime=110823-153059.847, now=110823-153259.860 2011-08-23 15:32:59,860-0500 INFO Command Command(13, HEARTBEAT): re-sending 2011-08-23 15:32:59,861-0500 WARN Command Command(13, HEARTBEAT)fault was: Reply timeout org.globus.cog.karajan.workflow.service.ReplyTimeoutException at org.globus.cog.karajan.workflow.service.commands.Command.handleReplyTimeout(Command.java:288) at org.globus.cog.karajan.workflow.service.commands.Command$Timeout.run(Command.java:293) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) 2011-08-23 15:32:59,861-0500 INFO Command Command(13, HEARTBEAT): re-sending 2011-08-23 15:32:59,861-0500 WARN Command Command(13, HEARTBEAT)fault was: Invalid channel: 914784201: {} org.globus.cog.karajan.workflow.service.ReplyTimeoutException at org.globus.cog.karajan.workflow.service.commands.Command.handleReplyTimeout(Command.java:288) at org.globus.cog.karajan.workflow.service.commands.Command$Timeout.run(Command.java:293) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) 2011-08-23 15:32:59,861-0500 INFO Command Command(13, HEARTBEAT): failed too many times org.globus.cog.karajan.workflow.service.ReplyTimeoutException at org.globus.cog.karajan.workflow.service.commands.Command.handleReplyTimeout(Command.java:288) at org.globus.cog.karajan.workflow.service.commands.Command$Timeout.run(Command.java:293) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) 2011-08-23 15:32:59,861-0500 WARN HeartBeatTask Heartbeat failed: Invalid channel: 914784201: {} org.globus.cog.karajan.workflow.service.ReplyTimeoutException at org.globus.cog.karajan.workflow.service.commands.Command.handleReplyTimeout(Command.java:288) at org.globus.cog.karajan.workflow.service.commands.Command$Timeout.run(Command.java:293) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) 2011-08-23 15:33:00,708-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:33:01,457-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:33:01,715-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:02,675-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:33:06,815-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:06,824-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261927-1314131261931-1314131261932) Completed 2011-08-23 15:33:06,824-0500 INFO Cpu 0823-270342-000001:2 jobTerminated 2011-08-23 15:33:06,824-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,824-0500 DEBUG Cpu 0823-270342-000001:2 pullLater 2011-08-23 15:33:06,825-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:33:06,825-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261929-1314131261934-1314131261935) Completed 2011-08-23 15:33:06,826-0500 INFO Cpu 0823-270342-000001:3 jobTerminated 2011-08-23 15:33:06,826-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-gbslmuek 2011-08-23 15:33:06,826-0500 DEBUG Cpu 0823-270342-000001:3 pullLater 2011-08-23 15:33:06,826-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,826-0500 INFO vdl:dostageout START jobid=catnap-gbslmuek - Staging out files 2011-08-23 15:33:06,826-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:33:06,826-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:33:06,827-0500 DEBUG vdl:dostageout stageouts: [[$, out[18]:file - Open]] 2011-08-23 15:33:06,827-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-hbslmuek 2011-08-23 15:33:06,827-0500 INFO vdl:dostageout START jobid=catnap-hbslmuek - Staging out files 2011-08-23 15:33:06,827-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0018.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:33:06,828-0500 DEBUG vdl:dostageout stageouts: [[$, out[16]:file - Open]] 2011-08-23 15:33:06,828-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,829-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0016.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:33:06,830-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,849-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,849-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0018.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:33:06,850-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,851-0500 INFO vdl:dostageout END jobid=catnap-gbslmuek - Staging out finished 2011-08-23 15:33:06,853-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,853-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0016.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:33:06,854-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,855-0500 INFO vdl:dostageout END jobid=catnap-hbslmuek - Staging out finished 2011-08-23 15:33:06,862-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,863-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-gbslmuek 2011-08-23 15:33:06,864-0500 INFO vdl:execute END_SUCCESS thread=0-4-17-1 tr=catnap 2011-08-23 15:33:06,864-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:33:06,864-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-17 2011-08-23 15:33:06,865-0500 INFO LateBindingScheduler JobQueue: 10 2011-08-23 15:33:06,865-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:33:06,866-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-hbslmuek 2011-08-23 15:33:06,866-0500 INFO vdl:execute END_SUCCESS thread=0-4-15-1 tr=catnap 2011-08-23 15:33:06,867-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:33:06,867-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-15 2011-08-23 15:33:06,867-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-ibslmuek thread=0-4-16-1-1 host=pbs replicationGroup=uaslmuek 2011-08-23 15:33:06,867-0500 INFO vdl:createdirset START jobid=catnap-ibslmuek host=pbs - Initializing directory structure 2011-08-23 15:33:06,868-0500 INFO vdl:createdirset END jobid=catnap-ibslmuek - Done initializing directory structure 2011-08-23 15:33:06,868-0500 INFO vdl:dostagein START jobid=catnap-ibslmuek - Staging in files 2011-08-23 15:33:06,868-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:33:06,869-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:33:06,869-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-jbslmuek thread=0-4-2-1-1 host=pbs replicationGroup=yaslmuek 2011-08-23 15:33:06,869-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:33:06,870-0500 INFO vdl:dostagein END jobid=catnap-ibslmuek - Staging in finished 2011-08-23 15:33:06,871-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-ibslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/i/catnap-ibslmuek host=pbs 2011-08-23 15:33:06,871-0500 INFO vdl:createdirset START jobid=catnap-jbslmuek host=pbs - Initializing directory structure 2011-08-23 15:33:06,871-0500 INFO vdl:createdirset END jobid=catnap-jbslmuek - Done initializing directory structure 2011-08-23 15:33:06,872-0500 INFO vdl:dostagein START jobid=catnap-jbslmuek - Staging in files 2011-08-23 15:33:06,873-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-16-1-1-1314131261961) is /bin/bash shared/_swiftwrap catnap-ibslmuek -jobdir i -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0017.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0017.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:33:06,873-0500 INFO LateBindingScheduler JobQueue: 9 2011-08-23 15:33:06,874-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:33:06,874-0500 INFO vdl:dostagein END jobid=catnap-jbslmuek - Staging in finished 2011-08-23 15:33:06,874-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-jbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/j/catnap-jbslmuek host=pbs 2011-08-23 15:33:06,875-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-2-1-1-1314131261963) is /bin/bash shared/_swiftwrap catnap-jbslmuek -jobdir j -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0003.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0003.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:33:06,878-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:33:06,878-0500 INFO Cpu 0823-270342-000001:4 submitting urn:1314131261961-1314131261965-1314131261966: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-ibslmuek -jobdir i -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0017.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0017.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:33:06,878-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261961-1314131261965-1314131261966) Submitting 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:5 submitting urn:1314131261963-1314131261968-1314131261969: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-jbslmuek -jobdir j -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0003.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0003.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:33:06,879-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261963-1314131261968-1314131261969) Submitting 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:33:06,879-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:33:06,880-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:33:06,892-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261961-1314131261965-1314131261966) Submitted 2011-08-23 15:33:06,893-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261961-1314131261965-1314131261966) Active workerid=000000 2011-08-23 15:33:06,915-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261963-1314131261968-1314131261969) Submitted 2011-08-23 15:33:06,915-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261963-1314131261968-1314131261969) Active workerid=000000 2011-08-23 15:33:10,721-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:33:11,507-0500 INFO PullThread runTime: 2, sleepTime: 10048 2011-08-23 15:33:11,861-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:12,678-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:33:16,903-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:20,731-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:33:21,543-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:33:21,948-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:22,681-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:33:26,995-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:30,741-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:33:31,579-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:33:32,039-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:32,684-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:33:35,909-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:33:37,082-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:40,752-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:33:41,615-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:33:42,125-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:42,687-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:33:47,252-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:50,762-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:33:51,651-0500 INFO PullThread runTime: 1, sleepTime: 10035 2011-08-23 15:33:52,296-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:33:52,690-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:33:57,340-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:00,772-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:34:01,688-0500 INFO PullThread runTime: 5, sleepTime: 10031 2011-08-23 15:34:02,385-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:02,693-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:34:07,197-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261961-1314131261965-1314131261966) Completed 2011-08-23 15:34:07,197-0500 INFO Cpu 0823-270342-000001:4 jobTerminated 2011-08-23 15:34:07,197-0500 DEBUG Cpu 0823-270342-000001:4 pullLater 2011-08-23 15:34:07,197-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:34:07,197-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:34:07,197-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,197-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261963-1314131261968-1314131261969) Completed 2011-08-23 15:34:07,198-0500 INFO Cpu 0823-270342-000001:5 jobTerminated 2011-08-23 15:34:07,198-0500 DEBUG Cpu 0823-270342-000001:5 pullLater 2011-08-23 15:34:07,198-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:34:07,198-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-ibslmuek 2011-08-23 15:34:07,198-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,199-0500 INFO vdl:dostageout START jobid=catnap-ibslmuek - Staging out files 2011-08-23 15:34:07,199-0500 DEBUG vdl:dostageout stageouts: [[$, out[17]:file - Open]] 2011-08-23 15:34:07,199-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-jbslmuek 2011-08-23 15:34:07,199-0500 INFO vdl:dostageout START jobid=catnap-jbslmuek - Staging out files 2011-08-23 15:34:07,200-0500 DEBUG vdl:dostageout stageouts: [[$, out[3]:file - Open]] 2011-08-23 15:34:07,200-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0017.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:34:07,200-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0003.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:34:07,200-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,201-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,218-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,218-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0017.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:34:07,219-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,219-0500 INFO vdl:dostageout END jobid=catnap-ibslmuek - Staging out finished 2011-08-23 15:34:07,221-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,221-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0003.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:34:07,222-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,223-0500 INFO vdl:dostageout END jobid=catnap-jbslmuek - Staging out finished 2011-08-23 15:34:07,231-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,232-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-ibslmuek 2011-08-23 15:34:07,232-0500 INFO vdl:execute END_SUCCESS thread=0-4-16-1 tr=catnap 2011-08-23 15:34:07,232-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:34:07,232-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-16 2011-08-23 15:34:07,234-0500 INFO LateBindingScheduler JobQueue: 8 2011-08-23 15:34:07,235-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:34:07,235-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-jbslmuek 2011-08-23 15:34:07,235-0500 INFO vdl:execute END_SUCCESS thread=0-4-2-1 tr=catnap 2011-08-23 15:34:07,235-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:34:07,236-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-2 2011-08-23 15:34:07,236-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:34:07,236-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-kbslmuek thread=0-4-11-1-1 host=pbs replicationGroup=vaslmuek 2011-08-23 15:34:07,236-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-lbslmuek thread=0-4-14-1-1 host=pbs replicationGroup=paslmuek 2011-08-23 15:34:07,237-0500 INFO vdl:createdirset START jobid=catnap-kbslmuek host=pbs - Initializing directory structure 2011-08-23 15:34:07,237-0500 INFO vdl:createdirset START jobid=catnap-lbslmuek host=pbs - Initializing directory structure 2011-08-23 15:34:07,237-0500 INFO vdl:createdirset END jobid=catnap-kbslmuek - Done initializing directory structure 2011-08-23 15:34:07,237-0500 INFO vdl:createdirset END jobid=catnap-lbslmuek - Done initializing directory structure 2011-08-23 15:34:07,237-0500 INFO vdl:dostagein START jobid=catnap-kbslmuek - Staging in files 2011-08-23 15:34:07,237-0500 INFO vdl:dostagein START jobid=catnap-lbslmuek - Staging in files 2011-08-23 15:34:07,239-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:34:07,240-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:34:07,240-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:34:07,240-0500 INFO vdl:dostagein END jobid=catnap-kbslmuek - Staging in finished 2011-08-23 15:34:07,240-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:34:07,240-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-kbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/k/catnap-kbslmuek host=pbs 2011-08-23 15:34:07,240-0500 INFO vdl:dostagein END jobid=catnap-lbslmuek - Staging in finished 2011-08-23 15:34:07,241-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-lbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/l/catnap-lbslmuek host=pbs 2011-08-23 15:34:07,241-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-11-1-1-1314131261995) is /bin/bash shared/_swiftwrap catnap-kbslmuek -jobdir k -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0012.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0012.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:34:07,241-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-14-1-1-1314131261997) is /bin/bash shared/_swiftwrap catnap-lbslmuek -jobdir l -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0015.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0015.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:34:07,251-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:34:07,251-0500 INFO Cpu 0823-270342-000001:6 submitting urn:1314131261995-1314131261999-1314131262000: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-kbslmuek -jobdir k -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0012.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0012.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:34:07,251-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261995-1314131261999-1314131262000) Submitting 2011-08-23 15:34:07,251-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:7 submitting urn:1314131261997-1314131262002-1314131262003: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-lbslmuek -jobdir l -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0015.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0015.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:34:07,252-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261997-1314131262002-1314131262003) Submitting 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:34:07,252-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:34:07,264-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261995-1314131261999-1314131262000) Submitted 2011-08-23 15:34:07,308-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261995-1314131261999-1314131262000) Active workerid=000000 2011-08-23 15:34:07,308-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261997-1314131262002-1314131262003) Submitted 2011-08-23 15:34:07,308-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261997-1314131262002-1314131262003) Active workerid=000000 2011-08-23 15:34:07,487-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:10,785-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:34:11,724-0500 INFO PullThread runTime: 3, sleepTime: 10034 2011-08-23 15:34:12,534-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:12,696-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:34:17,579-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:20,795-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:34:21,760-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:34:22,630-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:22,699-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:34:27,675-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:30,805-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:34:31,796-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:34:32,702-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:34:32,719-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:37,765-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:40,815-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:34:41,832-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:34:42,705-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:34:42,809-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:47,938-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:50,825-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:34:51,868-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:34:52,708-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:34:52,984-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:34:54,632-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:34:58,029-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:00,835-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:35:01,904-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:35:02,711-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:35:03,074-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:07,545-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261995-1314131261999-1314131262000) Completed 2011-08-23 15:35:07,545-0500 INFO Cpu 0823-270342-000001:6 jobTerminated 2011-08-23 15:35:07,545-0500 DEBUG Cpu 0823-270342-000001:6 pullLater 2011-08-23 15:35:07,546-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:35:07,546-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131261997-1314131262002-1314131262003) Completed 2011-08-23 15:35:07,546-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,546-0500 INFO Cpu 0823-270342-000001:7 jobTerminated 2011-08-23 15:35:07,546-0500 DEBUG Cpu 0823-270342-000001:7 pullLater 2011-08-23 15:35:07,546-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:35:07,547-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:35:07,547-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,547-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-kbslmuek 2011-08-23 15:35:07,547-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-lbslmuek 2011-08-23 15:35:07,547-0500 INFO vdl:dostageout START jobid=catnap-kbslmuek - Staging out files 2011-08-23 15:35:07,548-0500 INFO vdl:dostageout START jobid=catnap-lbslmuek - Staging out files 2011-08-23 15:35:07,548-0500 DEBUG vdl:dostageout stageouts: [[$, out[12]:file - Open]] 2011-08-23 15:35:07,548-0500 DEBUG vdl:dostageout stageouts: [[$, out[15]:file - Open]] 2011-08-23 15:35:07,548-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0012.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:35:07,549-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0015.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:35:07,550-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,550-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,567-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,568-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0015.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:35:07,568-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,569-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0012.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:35:07,569-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,569-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,569-0500 INFO vdl:dostageout END jobid=catnap-lbslmuek - Staging out finished 2011-08-23 15:35:07,570-0500 INFO vdl:dostageout END jobid=catnap-kbslmuek - Staging out finished 2011-08-23 15:35:07,581-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,582-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-lbslmuek 2011-08-23 15:35:07,582-0500 INFO vdl:execute END_SUCCESS thread=0-4-14-1 tr=catnap 2011-08-23 15:35:07,582-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:35:07,582-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-14 2011-08-23 15:35:07,583-0500 INFO LateBindingScheduler JobQueue: 6 2011-08-23 15:35:07,583-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:35:07,584-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-kbslmuek 2011-08-23 15:35:07,584-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-mbslmuek thread=0-4-4-1-1 host=pbs replicationGroup=taslmuek 2011-08-23 15:35:07,585-0500 INFO vdl:execute END_SUCCESS thread=0-4-11-1 tr=catnap 2011-08-23 15:35:07,585-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:35:07,585-0500 INFO vdl:createdirset START jobid=catnap-mbslmuek host=pbs - Initializing directory structure 2011-08-23 15:35:07,585-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-11 2011-08-23 15:35:07,586-0500 INFO vdl:createdirset END jobid=catnap-mbslmuek - Done initializing directory structure 2011-08-23 15:35:07,586-0500 INFO vdl:dostagein START jobid=catnap-mbslmuek - Staging in files 2011-08-23 15:35:07,587-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:35:07,588-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:35:07,588-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:35:07,588-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-nbslmuek thread=0-4-8-1-1 host=pbs replicationGroup=naslmuek 2011-08-23 15:35:07,588-0500 INFO vdl:dostagein END jobid=catnap-mbslmuek - Staging in finished 2011-08-23 15:35:07,589-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-mbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/m/catnap-mbslmuek host=pbs 2011-08-23 15:35:07,589-0500 INFO vdl:createdirset START jobid=catnap-nbslmuek host=pbs - Initializing directory structure 2011-08-23 15:35:07,590-0500 INFO vdl:createdirset END jobid=catnap-nbslmuek - Done initializing directory structure 2011-08-23 15:35:07,590-0500 INFO vdl:dostagein START jobid=catnap-nbslmuek - Staging in files 2011-08-23 15:35:07,591-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:35:07,591-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-4-1-1-1314131262030) is /bin/bash shared/_swiftwrap catnap-mbslmuek -jobdir m -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0005.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0005.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:35:07,592-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:35:07,593-0500 INFO vdl:dostagein END jobid=catnap-nbslmuek - Staging in finished 2011-08-23 15:35:07,593-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-nbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/n/catnap-nbslmuek host=pbs 2011-08-23 15:35:07,594-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-8-1-1-1314131262035) is /bin/bash shared/_swiftwrap catnap-nbslmuek -jobdir n -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0009.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0009.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:35:07,598-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:35:07,598-0500 INFO Cpu 0823-270342-000001:0 submitting urn:1314131262030-1314131262032-1314131262033: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-mbslmuek -jobdir m -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0005.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0005.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:35:07,598-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262030-1314131262032-1314131262033) Submitting 2011-08-23 15:35:07,598-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:1 submitting urn:1314131262035-1314131262037-1314131262038: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-nbslmuek -jobdir n -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0009.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0009.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:35:07,599-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262035-1314131262037-1314131262038) Submitting 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:35:07,599-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:35:07,612-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262030-1314131262032-1314131262033) Submitted 2011-08-23 15:35:07,656-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262030-1314131262032-1314131262033) Active workerid=000000 2011-08-23 15:35:07,657-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262035-1314131262037-1314131262038) Submitted 2011-08-23 15:35:07,657-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262035-1314131262037-1314131262038) Active workerid=000000 2011-08-23 15:35:08,174-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:10,847-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:35:11,915-0500 INFO PullThread runTime: 3, sleepTime: 10008 2011-08-23 15:35:12,714-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:35:13,222-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:18,267-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:20,857-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:35:21,951-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:35:22,717-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:35:23,311-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:28,355-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:30,867-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:35:31,987-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:35:32,720-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:35:33,399-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:33,993-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:35:38,443-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:40,877-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:35:42,023-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:35:42,723-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:35:43,488-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:48,615-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:50,887-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:35:52,059-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:35:52,726-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:35:53,657-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:35:58,700-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:00,897-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:36:02,095-0500 INFO PullThread runTime: 1, sleepTime: 10035 2011-08-23 15:36:02,730-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:36:03,756-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:08,091-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262035-1314131262037-1314131262038) Completed 2011-08-23 15:36:08,091-0500 INFO Cpu 0823-270342-000001:1 jobTerminated 2011-08-23 15:36:08,091-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,091-0500 DEBUG Cpu 0823-270342-000001:1 pullLater 2011-08-23 15:36:08,092-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:36:08,092-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:36:08,092-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-nbslmuek 2011-08-23 15:36:08,092-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262030-1314131262032-1314131262033) Completed 2011-08-23 15:36:08,092-0500 INFO Cpu 0823-270342-000001:0 jobTerminated 2011-08-23 15:36:08,092-0500 INFO vdl:dostageout START jobid=catnap-nbslmuek - Staging out files 2011-08-23 15:36:08,093-0500 DEBUG vdl:dostageout stageouts: [[$, out[9]:file - Open]] 2011-08-23 15:36:08,093-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0009.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:36:08,093-0500 DEBUG Cpu 0823-270342-000001:0 pullLater 2011-08-23 15:36:08,094-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:36:08,094-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,094-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,095-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-mbslmuek 2011-08-23 15:36:08,095-0500 INFO vdl:dostageout START jobid=catnap-mbslmuek - Staging out files 2011-08-23 15:36:08,095-0500 DEBUG vdl:dostageout stageouts: [[$, out[5]:file - Open]] 2011-08-23 15:36:08,096-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0005.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:36:08,096-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,120-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,121-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0009.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:36:08,122-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,122-0500 INFO vdl:dostageout END jobid=catnap-nbslmuek - Staging out finished 2011-08-23 15:36:08,125-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,125-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0005.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:36:08,126-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,127-0500 INFO vdl:dostageout END jobid=catnap-mbslmuek - Staging out finished 2011-08-23 15:36:08,136-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,137-0500 INFO LateBindingScheduler JobQueue: 4 2011-08-23 15:36:08,137-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-nbslmuek 2011-08-23 15:36:08,138-0500 INFO vdl:execute END_SUCCESS thread=0-4-8-1 tr=catnap 2011-08-23 15:36:08,138-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:36:08,138-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-8 2011-08-23 15:36:08,138-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-mbslmuek 2011-08-23 15:36:08,138-0500 INFO vdl:execute END_SUCCESS thread=0-4-4-1 tr=catnap 2011-08-23 15:36:08,138-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:36:08,138-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-4 2011-08-23 15:36:08,639-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:36:08,639-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:36:08,640-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-obslmuek thread=0-4-3-1-1 host=pbs replicationGroup=5bslmuek 2011-08-23 15:36:08,640-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-pbslmuek thread=0-4-12-1-1 host=pbs replicationGroup=6bslmuek 2011-08-23 15:36:08,641-0500 INFO vdl:createdirset START jobid=catnap-obslmuek host=pbs - Initializing directory structure 2011-08-23 15:36:08,641-0500 INFO vdl:createdirset START jobid=catnap-pbslmuek host=pbs - Initializing directory structure 2011-08-23 15:36:08,641-0500 INFO vdl:createdirset END jobid=catnap-obslmuek - Done initializing directory structure 2011-08-23 15:36:08,641-0500 INFO vdl:createdirset END jobid=catnap-pbslmuek - Done initializing directory structure 2011-08-23 15:36:08,641-0500 INFO vdl:dostagein START jobid=catnap-obslmuek - Staging in files 2011-08-23 15:36:08,641-0500 INFO vdl:dostagein START jobid=catnap-pbslmuek - Staging in files 2011-08-23 15:36:08,642-0500 INFO LateBindingScheduler JobQueue: 3 2011-08-23 15:36:08,642-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:36:08,643-0500 INFO vdl:dostagein END jobid=catnap-obslmuek - Staging in finished 2011-08-23 15:36:08,643-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-obslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/o/catnap-obslmuek host=pbs 2011-08-23 15:36:08,644-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:36:08,644-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-3-1-1-1314131262064) is /bin/bash shared/_swiftwrap catnap-obslmuek -jobdir o -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0004.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0004.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:36:08,645-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:36:08,645-0500 INFO vdl:dostagein END jobid=catnap-pbslmuek - Staging in finished 2011-08-23 15:36:08,646-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-pbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/p/catnap-pbslmuek host=pbs 2011-08-23 15:36:08,647-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-12-1-1-1314131262069) is /bin/bash shared/_swiftwrap catnap-pbslmuek -jobdir p -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0013.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0013.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:36:08,666-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:36:08,666-0500 INFO Cpu 0823-270342-000001:2 submitting urn:1314131262064-1314131262066-1314131262067: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-obslmuek -jobdir o -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0004.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0004.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:36:08,666-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262064-1314131262066-1314131262067) Submitting 2011-08-23 15:36:08,666-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:3 submitting urn:1314131262069-1314131262071-1314131262072: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-pbslmuek -jobdir p -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0013.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0013.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:36:08,667-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262069-1314131262071-1314131262072) Submitting 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:36:08,667-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:36:08,689-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262064-1314131262066-1314131262067) Submitted 2011-08-23 15:36:08,711-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262064-1314131262066-1314131262067) Active workerid=000000 2011-08-23 15:36:08,711-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262069-1314131262071-1314131262072) Submitted 2011-08-23 15:36:08,712-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262069-1314131262071-1314131262072) Active workerid=000000 2011-08-23 15:36:08,856-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:10,911-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:36:12,100-0500 INFO PullThread runTime: 15, sleepTime: 9990 2011-08-23 15:36:12,732-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:36:13,905-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:18,950-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:20,922-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:36:22,136-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:36:22,735-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:36:23,995-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:29,039-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:30,932-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:36:32,172-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:36:32,738-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:36:34,085-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:39,129-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:40,942-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:36:42,208-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:36:42,741-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:36:44,173-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:49,299-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:50,952-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:36:52,244-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:36:52,716-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:36:52,744-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:36:54,342-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:36:59,385-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:00,962-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:37:02,280-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:37:02,747-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:37:04,430-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:08,926-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262064-1314131262066-1314131262067) Completed 2011-08-23 15:37:08,926-0500 INFO Cpu 0823-270342-000001:2 jobTerminated 2011-08-23 15:37:08,926-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,926-0500 DEBUG Cpu 0823-270342-000001:2 pullLater 2011-08-23 15:37:08,927-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:37:08,928-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-obslmuek 2011-08-23 15:37:08,928-0500 INFO vdl:dostageout START jobid=catnap-obslmuek - Staging out files 2011-08-23 15:37:08,928-0500 DEBUG vdl:dostageout stageouts: [[$, out[4]:file - Open]] 2011-08-23 15:37:08,928-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0004.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:37:08,929-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262069-1314131262071-1314131262072) Completed 2011-08-23 15:37:08,929-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,929-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,929-0500 INFO Cpu 0823-270342-000001:3 jobTerminated 2011-08-23 15:37:08,929-0500 DEBUG Cpu 0823-270342-000001:3 pullLater 2011-08-23 15:37:08,929-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:37:08,929-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:37:08,930-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-pbslmuek 2011-08-23 15:37:08,930-0500 INFO vdl:dostageout START jobid=catnap-pbslmuek - Staging out files 2011-08-23 15:37:08,930-0500 DEBUG vdl:dostageout stageouts: [[$, out[13]:file - Open]] 2011-08-23 15:37:08,931-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0013.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:37:08,932-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,945-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,945-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0004.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:37:08,946-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,947-0500 INFO vdl:dostageout END jobid=catnap-obslmuek - Staging out finished 2011-08-23 15:37:08,948-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,949-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0013.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:37:08,949-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,950-0500 INFO vdl:dostageout END jobid=catnap-pbslmuek - Staging out finished 2011-08-23 15:37:08,958-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,958-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-obslmuek 2011-08-23 15:37:08,958-0500 INFO vdl:execute END_SUCCESS thread=0-4-3-1 tr=catnap 2011-08-23 15:37:08,959-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:37:08,959-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-3 2011-08-23 15:37:08,959-0500 INFO LateBindingScheduler JobQueue: 2 2011-08-23 15:37:08,959-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:37:08,960-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-pbslmuek 2011-08-23 15:37:08,960-0500 INFO vdl:execute END_SUCCESS thread=0-4-12-1 tr=catnap 2011-08-23 15:37:08,960-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:37:08,960-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-12 2011-08-23 15:37:08,961-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-qbslmuek thread=0-4-13-1-1 host=pbs replicationGroup=zaslmuek 2011-08-23 15:37:08,962-0500 INFO vdl:createdirset START jobid=catnap-qbslmuek host=pbs - Initializing directory structure 2011-08-23 15:37:08,962-0500 INFO vdl:createdirset END jobid=catnap-qbslmuek - Done initializing directory structure 2011-08-23 15:37:08,962-0500 INFO vdl:dostagein START jobid=catnap-qbslmuek - Staging in files 2011-08-23 15:37:08,962-0500 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-08-23 15:37:08,963-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:37:08,964-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=catnap-rbslmuek thread=0-4-18-1-1 host=pbs replicationGroup=7bslmuek 2011-08-23 15:37:08,964-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:37:08,964-0500 INFO vdl:dostagein END jobid=catnap-qbslmuek - Staging in finished 2011-08-23 15:37:08,965-0500 INFO vdl:createdirset START jobid=catnap-rbslmuek host=pbs - Initializing directory structure 2011-08-23 15:37:08,966-0500 INFO vdl:createdirset END jobid=catnap-rbslmuek - Done initializing directory structure 2011-08-23 15:37:08,966-0500 INFO vdl:dostagein START jobid=catnap-rbslmuek - Staging in files 2011-08-23 15:37:08,966-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-qbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/q/catnap-qbslmuek host=pbs 2011-08-23 15:37:08,967-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:37:08,968-0500 DEBUG vdl:dostagein CDM: file://localhost/data.txt : DEFAULT 2011-08-23 15:37:08,968-0500 INFO vdl:dostagein END jobid=catnap-rbslmuek - Staging in finished 2011-08-23 15:37:08,969-0500 DEBUG vdl:execute2 JOB_START jobid=catnap-rbslmuek tr=catnap arguments=[60, data.txt] tmpdir=catsnsleep-20110823-1527-b6kpd8h9/jobs/r/catnap-rbslmuek host=pbs 2011-08-23 15:37:08,969-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-13-1-1-1314131262098) is /bin/bash shared/_swiftwrap catnap-qbslmuek -jobdir q -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0014.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0014.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:37:08,970-0500 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-18-1-1-1314131262100) is /bin/bash shared/_swiftwrap catnap-rbslmuek -jobdir r -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0019.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0019.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:37:08,981-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:37:08,981-0500 INFO Cpu 0823-270342-000001:4 submitting urn:1314131262098-1314131262102-1314131262103: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-qbslmuek -jobdir q -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0014.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0014.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:37:08,981-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262098-1314131262102-1314131262103) Submitting 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:5 submitting urn:1314131262100-1314131262105-1314131262106: /bin/bash /gpfs/pads/swift/ketan//catsnsleep-20110823-1527-b6kpd8h9/shared/_swiftwrap catnap-rbslmuek -jobdir r -scratch -e /gpfs/pads/swift/ketan/catsn-pads/catnap.sh -out outdir/f.0019.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0019.out -k -cdmfile -status provider -a 60 data.txt 2011-08-23 15:37:08,982-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262100-1314131262105-1314131262106) Submitting 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:6 pull 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:7 pull 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:1 pull 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:0 pull 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:2 pull 2011-08-23 15:37:08,982-0500 INFO Cpu 0823-270342-000001:3 pull 2011-08-23 15:37:08,995-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262098-1314131262102-1314131262103) Submitted 2011-08-23 15:37:08,996-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262098-1314131262102-1314131262103) Active workerid=000000 2011-08-23 15:37:09,017-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262100-1314131262105-1314131262106) Submitted 2011-08-23 15:37:09,018-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262100-1314131262105-1314131262106) Active workerid=000000 2011-08-23 15:37:09,530-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:10,975-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:37:12,310-0500 INFO PullThread runTime: 3, sleepTime: 10027 2011-08-23 15:37:12,750-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:37:14,576-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:19,619-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:20,985-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:37:22,346-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:37:22,753-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:37:24,663-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:29,707-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:30,995-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:37:32,077-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 1 2011-08-23 15:37:32,382-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:37:32,756-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:37:34,750-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:39,793-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:41,005-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:37:42,418-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:37:42,759-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:37:44,837-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:49,963-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:37:51,016-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:37:52,454-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:37:52,762-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:37:55,006-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:38:00,049-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:38:01,026-0500 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-08-23 15:38:02,490-0500 INFO PullThread runTime: 0, sleepTime: 10036 2011-08-23 15:38:02,765-0500 INFO TaskNotifier Congestion queue size: 0 2011-08-23 15:38:05,094-0500 INFO AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0 2011-08-23 15:38:09,299-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262100-1314131262105-1314131262106) Completed 2011-08-23 15:38:09,299-0500 INFO Cpu 0823-270342-000001:5 jobTerminated 2011-08-23 15:38:09,299-0500 DEBUG Cpu 0823-270342-000001:5 pullLater 2011-08-23 15:38:09,299-0500 INFO Cpu 0823-270342-000001:5 pull 2011-08-23 15:38:09,299-0500 INFO AbstractStreamKarajanChannel Sender 2041998086 queue size: 0 2011-08-23 15:38:09,299-0500 DEBUG Cpu StatusEvent: Task(type=JOB_SUBMISSION, identity=urn:1314131262098-1314131262102-1314131262103) Completed 2011-08-23 15:38:09,299-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,299-0500 INFO Cpu 0823-270342-000001:4 jobTerminated 2011-08-23 15:38:09,300-0500 DEBUG Cpu 0823-270342-000001:4 pullLater 2011-08-23 15:38:09,300-0500 INFO Cpu 0823-270342-000001:4 pull 2011-08-23 15:38:09,300-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,300-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-rbslmuek 2011-08-23 15:38:09,301-0500 INFO vdl:dostageout START jobid=catnap-rbslmuek - Staging out files 2011-08-23 15:38:09,301-0500 DEBUG vdl:execute2 STAGING_OUT jobid=catnap-qbslmuek 2011-08-23 15:38:09,301-0500 DEBUG vdl:dostageout stageouts: [[$, out[19]:file - Open]] 2011-08-23 15:38:09,301-0500 INFO vdl:dostageout START jobid=catnap-qbslmuek - Staging out files 2011-08-23 15:38:09,301-0500 DEBUG vdl:dostageout stageouts: [[$, out[14]:file - Open]] 2011-08-23 15:38:09,302-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0019.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:38:09,302-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_START srcname=f.0014.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:38:09,304-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,304-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,323-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,323-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0019.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:38:09,324-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,324-0500 INFO vdl:dostageout END jobid=catnap-rbslmuek - Staging out finished 2011-08-23 15:38:09,329-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,329-0500 DEBUG vdl:dostageout FILE_STAGE_OUT_END srcname=f.0014.out srcdir=catsnsleep-20110823-1527-b6kpd8h9/shared/outdir srchost=pbs destdir=outdir desthost=localhost provider=file 2011-08-23 15:38:09,330-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,330-0500 INFO vdl:dostageout END jobid=catnap-qbslmuek - Staging out finished 2011-08-23 15:38:09,337-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,337-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-rbslmuek 2011-08-23 15:38:09,338-0500 INFO vdl:execute END_SUCCESS thread=0-4-18-1 tr=catnap 2011-08-23 15:38:09,338-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:38:09,338-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-18 2011-08-23 15:38:09,341-0500 INFO LateBindingScheduler JobQueue: 0 2011-08-23 15:38:09,342-0500 DEBUG vdl:execute2 JOB_END jobid=catnap-qbslmuek 2011-08-23 15:38:09,342-0500 INFO vdl:execute END_SUCCESS thread=0-4-13-1 tr=catnap 2011-08-23 15:38:09,342-0500 DEBUG catnap PROCEDURE_END line=3 2011-08-23 15:38:09,342-0500 DEBUG vdl:mains FOREACH_IT_END line=11 thread=0-4-13 2011-08-23 15:38:09,413-0500 DEBUG vdl:mains Starting cleanups 2011-08-23 15:38:09,414-0500 INFO vdl:cleanups START cleanups=[[catsnsleep-20110823-1527-b6kpd8h9, pbs]] 2011-08-23 15:38:09,415-0500 INFO vdl:cleanup START dir=catsnsleep-20110823-1527-b6kpd8h9 host=pbs 2011-08-23 15:38:09,415-0500 DEBUG vdl:cleanup cdmfile 2011-08-23 15:38:09,416-0500 INFO vdl:cleanup END dir=catsnsleep-20110823-1527-b6kpd8h9 host=pbs 2011-08-23 15:38:09,416-0500 INFO vdl:cleanups END cleanups=[[catsnsleep-20110823-1527-b6kpd8h9, pbs]] 2011-08-23 15:38:09,416-0500 DEBUG vdl:mains Ending cleanups 2011-08-23 15:38:09,418-0500 INFO Loader Swift finished with no errors 2011-08-23 15:38:09,419-0500 INFO ServiceManager Cleaning up... 2011-08-23 15:38:09,419-0500 INFO ServiceManager Shutting down service at https://192.5.86.5:50002 2011-08-23 15:38:09,529-0500 INFO BlockQueueProcessor Shutting down blocks 2011-08-23 15:38:09,529-0500 INFO Block Shutting down block Block 0823-270342-000001 (8x1200.000s) 2011-08-23 15:38:09,529-0500 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0823-270342-000001 2011-08-23 15:38:09,530-0500 INFO Block Average utilization: 24.93% 2011-08-23 15:38:09,530-0500 INFO CoasterService Shutdown sequence completed 2011-08-23 15:38:09,530-0500 INFO RemoteLogHandler BLOCK_UTILIZATION id=0823-270342-000001, u=24.93 2011-08-23 15:38:09,542-0500 INFO Node Node [c23.pads.ci.uchicago.edu] 0 shut down successfully