2011-11-12 19:21:04,775+0000 DEBUG Loader arguments: [-config, cf, -tc.file, tc, -sites.file, sites.xml, catsn.swift, -n=2] 2011-11-12 19:21:04,776+0000 DEBUG Loader Max heap: 253624320 2011-11-12 19:21:04,777+0000 DEBUG textfiles BEGIN SWIFTSCRIPT: type file; app (file o) cat (file i) { cat @i stdout=@o; } file out[]; file data<"data.txt">; foreach j in [1:@toint(@arg("n","1"))] { out[j] = cat(data); } 2011-11-12 19:21:04,777+0000 DEBUG textfiles END SWIFTSCRIPT: 2011-11-12 19:21:04,778+0000 DEBUG Loader kmlversion is >e5ab7b10-3052-4378-90ec-18e688aec71b< 2011-11-12 19:21:04,778+0000 DEBUG Loader build version is >e5ab7b10-3052-4378-90ec-18e688aec71b< 2011-11-12 19:21:04,778+0000 DEBUG Loader Recompilation suppressed. 2011-11-12 19:21:04,948+0000 DEBUG Loader setting: sites.file to: sites.xml 2011-11-12 19:21:04,948+0000 DEBUG Loader setting: tc.file to: tc 2011-11-12 19:21:04,948+0000 DEBUG textfiles using default sites file 2011-11-12 19:21:04,955+0000 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 = /soft/swift/swift-0.93RC3/bin/.. 2011-11-12 19:21:05,562+0000 INFO unknown Using sites file: sites.xml 2011-11-12 19:21:05,596+0000 INFO unknown Using tc.data: tc 2011-11-12 19:21:05,696+0000 INFO AbstractScheduler Setting resources to: {pbs=pbs} 2011-11-12 19:21:06,161+0000 INFO unknown Swift svn swift-r5205 cog-r3293 2011-11-12 19:21:06,162+0000 INFO unknown RUNID id=run:20111112-1921-u149j6i5 2011-11-12 19:21:06,188+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000001 path=$ 2011-11-12 19:21:06,188+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000001 VALUE=?:string = 1 - Closed 2011-11-12 19:21:06,189+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000002 path=$ 2011-11-12 19:21:06,189+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000002 VALUE=?:string = n - Closed 2011-11-12 19:21:06,189+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000003 path=$ 2011-11-12 19:21:06,189+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000003 VALUE=?:string = f. - Closed 2011-11-12 19:21:06,189+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000004 path=$ 2011-11-12 19:21:06,189+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000004 VALUE=?:string = .out - Closed 2011-11-12 19:21:06,190+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000005 path=$ 2011-11-12 19:21:06,190+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000005 VALUE=?:string = outdir - Closed 2011-11-12 19:21:06,190+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000006 path=$ 2011-11-12 19:21:06,190+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000006 VALUE=?:int = 1.0 - Closed 2011-11-12 19:21:06,191+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=swift#mapper#17000 provenanceid=dataset:20111112-1921-3fqud1s8:720000000007 2011-11-12 19:21:06,192+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=swift#mapper#17002 provenanceid=dataset:20111112-1921-3fqud1s8:720000000008 2011-11-12 19:21:06,193+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=swift#mapper#17004 provenanceid=dataset:20111112-1921-3fqud1s8:720000000009 2011-11-12 19:21:06,193+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000010 path=$ 2011-11-12 19:21:06,193+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000010 VALUE=?:string = outdir - Closed 2011-11-12 19:21:06,194+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000011 path=$ 2011-11-12 19:21:06,194+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000011 VALUE=?:string = f. - Closed 2011-11-12 19:21:06,194+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000012 path=$ 2011-11-12 19:21:06,195+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000012 VALUE=?:string = .out - Closed 2011-11-12 19:21:06,207+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=out provenanceid=dataset:20111112-1921-3fqud1s8:720000000013 2011-11-12 19:21:06,210+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000014 path=$ 2011-11-12 19:21:06,210+0000 INFO AbstractDataNode FILENAME dataset=dataset:20111112-1921-3fqud1s8:720000000014 filename=file://localhost/data.txt 2011-11-12 19:21:06,210+0000 INFO RootDataNode Found data data:file - Closed.$ 2011-11-12 19:21:06,211+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=data provenanceid=dataset:20111112-1921-3fqud1s8:720000000014 2011-11-12 19:21:06,230+0000 INFO SetFieldValue Set: swift#mapper#17000=outdir 2011-11-12 19:21:06,230+0000 INFO SetFieldValue Set: swift#mapper#17002=f. 2011-11-12 19:21:06,230+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000007 path=$ 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000008 path=$ 2011-11-12 19:21:06,231+0000 INFO SetFieldValue Set: swift#mapper#17004=.out 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000007 VALUE=swift#mapper#17000:string = outdir - Closed 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000009 path=$ 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000008 VALUE=swift#mapper#17002:string = f. - Closed 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000009 VALUE=swift#mapper#17004:string = .out - Closed 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000015 path=$ 2011-11-12 19:21:06,231+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000015 VALUE=?:string = 2 - Closed 2011-11-12 19:21:06,232+0000 INFO VDLFunction FUNCTION: arg() 2011-11-12 19:21:06,232+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000016 path=$ 2011-11-12 19:21:06,232+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000016 VALUE=?:int = 2.0 - Closed 2011-11-12 19:21:06,232+0000 INFO VDLFunction FUNCTION: toint() 2011-11-12 19:21:06,233+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000017 path=$ 2011-11-12 19:21:06,234+0000 INFO vdl:mains ARRAYRANGE thread=0-3 array=dataset:20111112-1921-3fqud1s8:720000000017 from=dataset:20111112-1921-3fqud1s8:720000000006 to=dataset:20111112-1921-3fqud1s8:720000000016 step=none 2011-11-12 19:21:06,238+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000018 path=$ 2011-11-12 19:21:06,238+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000018 VALUE=?:int = 1.0 - Closed 2011-11-12 19:21:06,239+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000019 path=$ 2011-11-12 19:21:06,239+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000019 VALUE=?:int = 2.0 - Closed 2011-11-12 19:21:06,239+0000 DEBUG vdl:mains FOREACH_IT_START line=13 thread=0-3-0 2011-11-12 19:21:06,239+0000 DEBUG vdl:mains FOREACH_IT_START line=13 thread=0-3-1 2011-11-12 19:21:06,240+0000 DEBUG vdl:mains SCOPE thread=0-3-1 2011-11-12 19:21:06,240+0000 DEBUG vdl:mains SCOPE thread=0-3-0 2011-11-12 19:21:06,242+0000 INFO vdl:parameterlog PARAM thread=0-3-1-1 direction=input variable=i provenanceid=dataset:20111112-1921-3fqud1s8:720000000014 2011-11-12 19:21:06,242+0000 INFO vdl:parameterlog PARAM thread=0-3-0-1 direction=input variable=i provenanceid=dataset:20111112-1921-3fqud1s8:720000000014 2011-11-12 19:21:06,243+0000 INFO vdl:parameterlog PARAM thread=0-3-1-1 direction=output variable=o provenanceid=dataset:20111112-1921-3fqud1s8:720000000020 2011-11-12 19:21:06,243+0000 INFO vdl:parameterlog PARAM thread=0-3-0-1 direction=output variable=o provenanceid=dataset:20111112-1921-3fqud1s8:720000000021 2011-11-12 19:21:06,243+0000 DEBUG cat PROCEDURE line=3 thread=0-3-1-1 name=cat 2011-11-12 19:21:06,244+0000 DEBUG cat PROCEDURE line=3 thread=0-3-0-1 name=cat 2011-11-12 19:21:06,245+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000022 path=$ 2011-11-12 19:21:06,245+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000022 VALUE=?:string = data.txt - Closed 2011-11-12 19:21:06,245+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000023 path=$ 2011-11-12 19:21:06,245+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000023 VALUE=?:string = data.txt - Closed 2011-11-12 19:21:06,246+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000024 path=$ 2011-11-12 19:21:06,246+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000024 VALUE=?:string = outdir/f.0002.out - Closed 2011-11-12 19:21:06,246+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-1921-3fqud1s8:720000000025 path=$ 2011-11-12 19:21:06,246+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-1921-3fqud1s8:720000000025 VALUE=?:string = outdir/f.0001.out - Closed 2011-11-12 19:21:06,250+0000 INFO vdl:execute START thread=0-3-1-1 tr=cat 2011-11-12 19:21:06,250+0000 INFO vdl:execute START thread=0-3-0-1 tr=cat 2011-11-12 19:21:06,261+0000 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-11-12 19:21:06,262+0000 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-11-12 19:21:06,263+0000 INFO GlobalSubmitQueue No global submit throttle set. Using default (1024) 2011-11-12 19:21:06,265+0000 INFO LateBindingScheduler JobQueue: 0 2011-11-12 19:21:06,266+0000 INFO LateBindingScheduler JobQueue: 0 2011-11-12 19:21:06,268+0000 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=cat-anklsnik thread=0-3-1-1-1 host=pbs replicationGroup=8nklsnik 2011-11-12 19:21:06,269+0000 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=cat-bnklsnik thread=0-3-0-1-1 host=pbs replicationGroup=9nklsnik 2011-11-12 19:21:06,274+0000 DEBUG vdl:execute2 JOB_START jobid=cat-anklsnik tr=cat arguments=[data.txt] tmpdir=catsn-20111112-1921-u149j6i5/jobs/a/cat-anklsnik host=pbs 2011-11-12 19:21:06,274+0000 DEBUG vdl:execute2 JOB_START jobid=cat-bnklsnik tr=cat arguments=[data.txt] tmpdir=catsn-20111112-1921-u149j6i5/jobs/b/cat-bnklsnik host=pbs 2011-11-12 19:21:06,276+0000 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 2011-11-12 19:21:06,276+0000 DEBUG textfiles END TC: 2011-11-12 19:21:06,294+0000 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-3-1-1-1-1321125665579) is /bin/bash _swiftwrap.staging -e /bin/cat -out outdir/f.0002.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0002.out -k -cdmfile -status provider -a data.txt 2011-11-12 19:21:06,294+0000 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-3-0-1-1-1321125665578) is /bin/bash _swiftwrap.staging -e /bin/cat -out outdir/f.0001.out -err stderr.txt -i -d outdir -if data.txt -of outdir/f.0001.out -k -cdmfile -status provider -a data.txt 2011-11-12 19:21:06,340+0000 INFO LocalService Started local service: 192.5.86.101:44784 2011-11-12 19:21:06,350+0000 INFO BootstrapService Socket bound. URL is http://login1.beagle.ci.uchicago.edu:45766 2011-11-12 19:21:06,388+0000 INFO Settings Local contacts: [http://192.5.86.101:46607, http://10.128.2.245:46607, http://127.0.0.2:46607] 2011-11-12 19:21:06,390+0000 INFO CoasterService Started local service: http://192.5.86.101:46607 2011-11-12 19:21:06,391+0000 INFO CoasterService Reserving channel for registration 2011-11-12 19:21:06,410+0000 INFO AbstractKarajanChannel MetaChannel: 138319567[1159656515: {}] -> null: Disabling heartbeats (disabled in config) 2011-11-12 19:21:06,410+0000 INFO MetaChannel MetaChannel: 138319567[1159656515: {}] -> null.bind -> null[1159656515: {}] 2011-11-12 19:21:06,410+0000 INFO AbstractKarajanChannel MetaChannel: 1932951080[2123673391: {}] -> null: Disabling heartbeats (disabled in config) 2011-11-12 19:21:06,411+0000 INFO MetaChannel MetaChannel: 1932951080[2123673391: {}] -> null.bind -> null[2123673391: {}] 2011-11-12 19:21:06,411+0000 INFO CoasterService Sending registration 2011-11-12 19:21:06,415+0000 INFO MetaChannel Trying to re-bind current channel 2011-11-12 19:21:06,417+0000 INFO CoasterService Registration complete 2011-11-12 19:21:06,417+0000 INFO CoasterService Started coaster service: http://192.5.86.101:45917 2011-11-12 19:21:06,474+0000 INFO BlockQueueProcessor Requeued 2 non-fitting jobs 2011-11-12 19:21:06,477+0000 INFO BlockQueueProcessor Settings { slots = 1 jobsPerNode = 24 workersPerNode = 24 nodeGranularity = 1 allocationStepSize = 0.1 maxNodes = 1 lowOverallocation = 10.0 highOverallocation = 1.0 overallocationDecayFactor = 0.0010 spread = 0.9 reserve = 60.000s maxtime = 1000 project = CI-DEB000002 queue = null remoteMonitorEnabled = false kernelprofile = null alcfbgpnat = false internalHostname = 10.128.2.245 hookClass = null workerManager = block workerLoggingLevel = NONE workerLoggingDirectory = DEFAULT ppn = 24:cray:pack ldLibraryPath = null workerCopies = null directory = null useHashBang = null providerAttributes = null parallelism = 0.01 } 2011-11-12 19:21:06,477+0000 INFO BlockQueueProcessor Required size: 2.1704418453972454 for 2 jobs 2011-11-12 19:21:06,477+0000 INFO BlockQueueProcessor h: 940, jj: 600, x-last: , r: 1, sumsz: 1 2011-11-12 19:21:06,478+0000 INFO BlockQueueProcessor h: 940, w: 24, size: 2.0, msz: 2, w*h: 22560 2011-11-12 19:21:06,481+0000 INFO BlockQueueProcessor Added: 0 - 1 2011-11-12 19:21:06,481+0000 INFO Block Starting block: workers=24, walltime=940.000s 2011-11-12 19:21:06,483+0000 INFO RemoteLogHandler BLOCK_REQUESTED id=1112-210706-000000, w=24, h=940 2011-11-12 19:21:06,487+0000 INFO BlockTaskSubmitter Queuing block Block 1112-210706-000000 (24x940.000s) for submission 2011-11-12 19:21:06,487+0000 INFO BlockQueueProcessor Added 2 jobs to new blocks 2011-11-12 19:21:06,487+0000 INFO BlockTaskSubmitter Submitting block Block 1112-210706-000000 (24x940.000s) 2011-11-12 19:21:06,487+0000 INFO ExecutionTaskHandler provider=pbs 2011-11-12 19:21:06,492+0000 INFO Block Block task status changed: Submitting 2011-11-12 19:21:06,510+0000 DEBUG AbstractExecutor Writing PBS script to /home/fangfang/.globus/scripts/PBS6954924010553344333.submit 2011-11-12 19:21:06,521+0000 DEBUG PBSExecutor PBS name: for: Block-1112-210706-000000 is: Block-1112-2107 2011-11-12 19:21:06,521+0000 INFO BlockTaskSubmitter Error submitting block task: Cannot submit job: Illegal value for ppn. Must be an integer. 2011-11-12 19:21:16,429+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:21:26,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:21:36,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:21:46,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:21:56,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:22:06,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:22:16,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:22:26,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:22:36,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:22:46,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:22:56,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:23:06,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:23:16,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:23:26,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:23:36,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:23:46,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:23:56,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:24:06,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:24:16,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:24:26,428+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 19:24:36,428+0000 INFO TaskNotifier Congestion queue size: 0