2011-11-12 20:25:55,106+0000 DEBUG Loader arguments: [-config, cf, -tc.file, tc, -sites.file, sites.xml, catsn.swift, -n=2] 2011-11-12 20:25:55,107+0000 DEBUG Loader Max heap: 253624320 2011-11-12 20:25:55,108+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 20:25:55,108+0000 DEBUG textfiles END SWIFTSCRIPT: 2011-11-12 20:25:55,109+0000 DEBUG Loader kmlversion is >e5ab7b10-3052-4378-90ec-18e688aec71b< 2011-11-12 20:25:55,109+0000 DEBUG Loader build version is >e5ab7b10-3052-4378-90ec-18e688aec71b< 2011-11-12 20:25:55,109+0000 DEBUG Loader Recompilation suppressed. 2011-11-12 20:25:55,282+0000 DEBUG Loader setting: sites.file to: sites.xml 2011-11-12 20:25:55,282+0000 DEBUG Loader setting: tc.file to: tc 2011-11-12 20:25:55,282+0000 DEBUG textfiles using default sites file 2011-11-12 20:25:55,289+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 20:25:55,901+0000 INFO unknown Using sites file: sites.xml 2011-11-12 20:25:55,935+0000 INFO unknown Using tc.data: tc 2011-11-12 20:25:56,036+0000 INFO AbstractScheduler Setting resources to: {pbs=pbs} 2011-11-12 20:25:56,525+0000 INFO unknown Swift svn swift-r5205 cog-r3293 2011-11-12 20:25:56,526+0000 INFO unknown RUNID id=run:20111112-2025-g4qxj66a 2011-11-12 20:25:56,552+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000001 path=$ 2011-11-12 20:25:56,552+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000001 VALUE=?:string = 1 - Closed 2011-11-12 20:25:56,552+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000002 path=$ 2011-11-12 20:25:56,552+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000002 VALUE=?:string = n - Closed 2011-11-12 20:25:56,553+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000003 path=$ 2011-11-12 20:25:56,553+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000003 VALUE=?:string = f. - Closed 2011-11-12 20:25:56,553+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000004 path=$ 2011-11-12 20:25:56,553+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000004 VALUE=?:string = .out - Closed 2011-11-12 20:25:56,554+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000005 path=$ 2011-11-12 20:25:56,554+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000005 VALUE=?:string = outdir - Closed 2011-11-12 20:25:56,554+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000006 path=$ 2011-11-12 20:25:56,554+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000006 VALUE=?:int = 1.0 - Closed 2011-11-12 20:25:56,555+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=swift#mapper#17000 provenanceid=dataset:20111112-2025-7ckz2e67:720000000007 2011-11-12 20:25:56,556+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=swift#mapper#17002 provenanceid=dataset:20111112-2025-7ckz2e67:720000000008 2011-11-12 20:25:56,557+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=swift#mapper#17004 provenanceid=dataset:20111112-2025-7ckz2e67:720000000009 2011-11-12 20:25:56,557+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000010 path=$ 2011-11-12 20:25:56,557+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000010 VALUE=?:string = outdir - Closed 2011-11-12 20:25:56,558+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000011 path=$ 2011-11-12 20:25:56,558+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000011 VALUE=?:string = f. - Closed 2011-11-12 20:25:56,559+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000012 path=$ 2011-11-12 20:25:56,559+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000012 VALUE=?:string = .out - Closed 2011-11-12 20:25:56,571+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=out provenanceid=dataset:20111112-2025-7ckz2e67:720000000013 2011-11-12 20:25:56,574+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000014 path=$ 2011-11-12 20:25:56,574+0000 INFO AbstractDataNode FILENAME dataset=dataset:20111112-2025-7ckz2e67:720000000014 filename=file://localhost/data.txt 2011-11-12 20:25:56,574+0000 INFO RootDataNode Found data data:file - Closed.$ 2011-11-12 20:25:56,574+0000 INFO vdl:parameterlog PARAM thread=0 direction=intermediate variable=data provenanceid=dataset:20111112-2025-7ckz2e67:720000000014 2011-11-12 20:25:56,594+0000 INFO SetFieldValue Set: swift#mapper#17000=outdir 2011-11-12 20:25:56,594+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000007 path=$ 2011-11-12 20:25:56,594+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000007 VALUE=swift#mapper#17000:string = outdir - Closed 2011-11-12 20:25:56,594+0000 INFO SetFieldValue Set: swift#mapper#17002=f. 2011-11-12 20:25:56,594+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000008 path=$ 2011-11-12 20:25:56,595+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000008 VALUE=swift#mapper#17002:string = f. - Closed 2011-11-12 20:25:56,595+0000 INFO SetFieldValue Set: swift#mapper#17004=.out 2011-11-12 20:25:56,595+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000009 path=$ 2011-11-12 20:25:56,595+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000009 VALUE=swift#mapper#17004:string = .out - Closed 2011-11-12 20:25:56,597+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000015 path=$ 2011-11-12 20:25:56,597+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000015 VALUE=?:string = 2 - Closed 2011-11-12 20:25:56,597+0000 INFO VDLFunction FUNCTION: arg() 2011-11-12 20:25:56,598+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000016 path=$ 2011-11-12 20:25:56,598+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000016 VALUE=?:int = 2.0 - Closed 2011-11-12 20:25:56,598+0000 INFO VDLFunction FUNCTION: toint() 2011-11-12 20:25:56,599+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000017 path=$ 2011-11-12 20:25:56,600+0000 INFO vdl:mains ARRAYRANGE thread=0-3 array=dataset:20111112-2025-7ckz2e67:720000000017 from=dataset:20111112-2025-7ckz2e67:720000000006 to=dataset:20111112-2025-7ckz2e67:720000000016 step=none 2011-11-12 20:25:56,604+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000018 path=$ 2011-11-12 20:25:56,604+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000018 VALUE=?:int = 1.0 - Closed 2011-11-12 20:25:56,605+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000019 path=$ 2011-11-12 20:25:56,605+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000019 VALUE=?:int = 2.0 - Closed 2011-11-12 20:25:56,605+0000 DEBUG vdl:mains FOREACH_IT_START line=13 thread=0-3-0 2011-11-12 20:25:56,605+0000 DEBUG vdl:mains FOREACH_IT_START line=13 thread=0-3-1 2011-11-12 20:25:56,606+0000 DEBUG vdl:mains SCOPE thread=0-3-0 2011-11-12 20:25:56,606+0000 DEBUG vdl:mains SCOPE thread=0-3-1 2011-11-12 20:25:56,608+0000 INFO vdl:parameterlog PARAM thread=0-3-0-1 direction=input variable=i provenanceid=dataset:20111112-2025-7ckz2e67:720000000014 2011-11-12 20:25:56,608+0000 INFO vdl:parameterlog PARAM thread=0-3-1-1 direction=input variable=i provenanceid=dataset:20111112-2025-7ckz2e67:720000000014 2011-11-12 20:25:56,609+0000 INFO vdl:parameterlog PARAM thread=0-3-0-1 direction=output variable=o provenanceid=dataset:20111112-2025-7ckz2e67:720000000020 2011-11-12 20:25:56,609+0000 INFO vdl:parameterlog PARAM thread=0-3-1-1 direction=output variable=o provenanceid=dataset:20111112-2025-7ckz2e67:720000000021 2011-11-12 20:25:56,609+0000 DEBUG cat PROCEDURE line=3 thread=0-3-0-1 name=cat 2011-11-12 20:25:56,609+0000 DEBUG cat PROCEDURE line=3 thread=0-3-1-1 name=cat 2011-11-12 20:25:56,611+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000022 path=$ 2011-11-12 20:25:56,611+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000022 VALUE=?:string = data.txt - Closed 2011-11-12 20:25:56,611+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000023 path=$ 2011-11-12 20:25:56,611+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000023 VALUE=?:string = data.txt - Closed 2011-11-12 20:25:56,612+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000024 path=$ 2011-11-12 20:25:56,612+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000024 VALUE=?:string = outdir/f.0002.out - Closed 2011-11-12 20:25:56,612+0000 INFO AbstractDataNode ROOTPATH dataset=dataset:20111112-2025-7ckz2e67:720000000025 path=$ 2011-11-12 20:25:56,612+0000 INFO AbstractDataNode VALUE dataset=dataset:20111112-2025-7ckz2e67:720000000025 VALUE=?:string = outdir/f.0001.out - Closed 2011-11-12 20:25:56,615+0000 INFO vdl:execute START thread=0-3-1-1 tr=cat 2011-11-12 20:25:56,616+0000 INFO vdl:execute START thread=0-3-0-1 tr=cat 2011-11-12 20:25:56,627+0000 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-11-12 20:25:56,627+0000 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pbs, score=99.854 2011-11-12 20:25:56,629+0000 INFO GlobalSubmitQueue No global submit throttle set. Using default (1024) 2011-11-12 20:25:56,631+0000 INFO LateBindingScheduler JobQueue: 0 2011-11-12 20:25:56,632+0000 INFO LateBindingScheduler JobQueue: 0 2011-11-12 20:25:56,634+0000 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=cat-sfb7vnik thread=0-3-1-1-1 host=pbs replicationGroup=pfb7vnik 2011-11-12 20:25:56,634+0000 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=cat-rfb7vnik thread=0-3-0-1-1 host=pbs replicationGroup=qfb7vnik 2011-11-12 20:25:56,640+0000 DEBUG vdl:execute2 JOB_START jobid=cat-sfb7vnik tr=cat arguments=[data.txt] tmpdir=catsn-20111112-2025-g4qxj66a/jobs/s/cat-sfb7vnik host=pbs 2011-11-12 20:25:56,640+0000 DEBUG vdl:execute2 JOB_START jobid=cat-rfb7vnik tr=cat arguments=[data.txt] tmpdir=catsn-20111112-2025-g4qxj66a/jobs/r/cat-rfb7vnik host=pbs 2011-11-12 20:25:56,642+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 20:25:56,642+0000 DEBUG textfiles END TC: 2011-11-12 20:25:56,663+0000 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-3-1-1-1-1321129555916) 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 20:25:56,663+0000 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-3-0-1-1-1321129555917) 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 20:25:56,708+0000 INFO LocalService Started local service: 192.5.86.102:49371 2011-11-12 20:25:56,719+0000 INFO BootstrapService Socket bound. URL is http://login2.beagle.ci.uchicago.edu:50925 2011-11-12 20:25:56,757+0000 INFO Settings Local contacts: [http://192.5.86.102:43246, http://10.128.2.246:43246, http://127.0.0.2:43246] 2011-11-12 20:25:56,760+0000 INFO CoasterService Started local service: http://192.5.86.102:43246 2011-11-12 20:25:56,760+0000 INFO CoasterService Reserving channel for registration 2011-11-12 20:25:56,780+0000 INFO AbstractKarajanChannel MetaChannel: 1932951080[2123673391: {}] -> null: Disabling heartbeats (disabled in config) 2011-11-12 20:25:56,780+0000 INFO MetaChannel MetaChannel: 1932951080[2123673391: {}] -> null.bind -> null[2123673391: {}] 2011-11-12 20:25:56,780+0000 INFO AbstractKarajanChannel MetaChannel: 1400469397[1268384259: {}] -> null: Disabling heartbeats (disabled in config) 2011-11-12 20:25:56,780+0000 INFO MetaChannel MetaChannel: 1400469397[1268384259: {}] -> null.bind -> null[1268384259: {}] 2011-11-12 20:25:56,780+0000 INFO CoasterService Sending registration 2011-11-12 20:25:56,784+0000 INFO MetaChannel Trying to re-bind current channel 2011-11-12 20:25:56,786+0000 INFO CoasterService Registration complete 2011-11-12 20:25:56,786+0000 INFO CoasterService Started coaster service: http://192.5.86.102:59022 2011-11-12 20:25:56,847+0000 INFO BlockQueueProcessor Requeued 2 non-fitting jobs 2011-11-12 20:25:56,850+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.246 hookClass = null workerManager = block workerLoggingLevel = NONE workerLoggingDirectory = DEFAULT ppn = pbs.aprun;pbs.mpp;depth=24 ldLibraryPath = null workerCopies = null directory = null useHashBang = null providerAttributes = null parallelism = 0.01 } 2011-11-12 20:25:56,851+0000 INFO BlockQueueProcessor Required size: 2.1704418453972454 for 2 jobs 2011-11-12 20:25:56,851+0000 INFO BlockQueueProcessor h: 940, jj: 600, x-last: , r: 1, sumsz: 1 2011-11-12 20:25:56,851+0000 INFO BlockQueueProcessor h: 940, w: 24, size: 2.0, msz: 2, w*h: 22560 2011-11-12 20:25:56,854+0000 INFO BlockQueueProcessor Added: 0 - 1 2011-11-12 20:25:56,854+0000 INFO Block Starting block: workers=24, walltime=940.000s 2011-11-12 20:25:56,857+0000 INFO RemoteLogHandler BLOCK_REQUESTED id=1112-250856-000000, w=24, h=940 2011-11-12 20:25:56,861+0000 INFO BlockTaskSubmitter Queuing block Block 1112-250856-000000 (24x940.000s) for submission 2011-11-12 20:25:56,861+0000 INFO BlockQueueProcessor Added 2 jobs to new blocks 2011-11-12 20:25:56,861+0000 INFO BlockTaskSubmitter Submitting block Block 1112-250856-000000 (24x940.000s) 2011-11-12 20:25:56,861+0000 INFO ExecutionTaskHandler provider=pbs 2011-11-12 20:25:56,865+0000 INFO Block Block task status changed: Submitting 2011-11-12 20:25:56,884+0000 DEBUG AbstractExecutor Writing PBS script to /home/fangfang/.globus/scripts/PBS5685375261804852537.submit 2011-11-12 20:25:56,894+0000 DEBUG PBSExecutor PBS name: for: Block-1112-250856-000000 is: Block-1112-2508 2011-11-12 20:25:56,894+0000 INFO BlockTaskSubmitter Error submitting block task: Cannot submit job: Illegal value for ppn. Must be an integer. 2011-11-12 20:26:06,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:26:16,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:26:26,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:26:36,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:26:46,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:26:56,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:27:06,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:27:16,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:27:26,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:27:36,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:27:46,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:27:56,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:28:06,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:28:16,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:28:26,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:28:36,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:28:46,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:28:56,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:29:06,799+0000 INFO TaskNotifier Congestion queue size: 0 2011-11-12 20:29:16,799+0000 INFO TaskNotifier Congestion queue size: 0