runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: runsolver -s SIGUSR1 -M 1124 -C 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/d5026b8e-3477-11e0-986e-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/d5026b8e-3477-11e0-986e-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/d5026b8e-3477-11e0-986e-00163e3d3b7c.cudf.result -sum(solution,installedsize),-count(removed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB

[startup+0 s]
/proc/loadavg: 1.09 1.00 0.93 2/59 23319
/proc/meminfo: memFree=259680/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=3152 CPUtime=0
/proc/23319/stat : 23319 (runsolver) R 23318 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115827591 3227648 32 18446744073709551615 134512640 134586868 4287961584 4287959632 4151608368 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.151242 s]
/proc/loadavg: 1.09 1.00 0.93 2/59 23319
/proc/meminfo: memFree=259680/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=0.05
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 737 3609 0 1 0 1 4 0 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200332 s]
/proc/loadavg: 1.09 1.00 0.93 2/59 23319
/proc/meminfo: memFree=259680/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=0.05
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 737 3609 0 1 0 1 4 0 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300307 s]
/proc/loadavg: 1.09 1.00 0.93 2/59 23319
/proc/meminfo: memFree=259680/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=0.05
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 737 3609 0 1 0 1 4 0 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700221 s]
/proc/loadavg: 1.09 1.00 0.93 2/59 23319
/proc/meminfo: memFree=259680/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=0.05
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 737 3609 0 1 0 1 4 0 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.08 1.00 0.93 2/61 23335
/proc/meminfo: memFree=223820/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=0.05
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 737 3609 0 1 0 1 4 0 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
[pid=23335] ppid=23319 vsize=50504 CPUtime=1.4
/proc/23335/stat : 23335 (cudf2lp) R 23319 23319 1733 0 -1 4202496 14143 0 0 0 134 6 0 0 20 0 1 0 115827595 51716096 10744 18446744073709551615 4194304 5690517 140737008760784 140737008758424 4293334 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/23335/statm: 12626 10744 160 366 0 12257 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 59716

[startup+3.1003 s]
/proc/loadavg: 1.08 1.00 0.93 2/61 23336
/proc/meminfo: memFree=235228/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=2.01
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 763 22450 0 1 0 1 188 12 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
[pid=23336] ppid=23319 vsize=52008 CPUtime=1.03
/proc/23336/stat : 23336 (gringo) R 23319 23319 1733 0 -1 4202496 13050 0 0 0 97 6 0 0 20 0 1 0 115827796 53256192 10431 18446744073709551615 4194304 6531320 140736944001984 140736943998600 5059328 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23336/statm: 13002 10431 280 571 0 12423 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 61220

Solver just ended. Dumping a history of the last processes samples

[startup+3.20039 s]
/proc/loadavg: 1.08 1.00 0.93 2/61 23336
/proc/meminfo: memFree=235228/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=2.01
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 763 22450 0 1 0 1 188 12 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
[pid=23336] ppid=23319 vsize=54992 CPUtime=1.13
/proc/23336/stat : 23336 (gringo) R 23319 23319 1733 0 -1 4202496 13762 0 0 0 107 6 0 0 20 0 1 0 115827796 56311808 11143 18446744073709551615 4194304 6531320 140736944001984 140736943998600 5554608 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23336/statm: 13748 11143 280 571 0 13169 0
Current children cumulated CPU time (s) 3.14
Current children cumulated vsize (KiB) 64204

[startup+4.00032 s]
/proc/loadavg: 1.08 1.00 0.93 2/61 23336
/proc/meminfo: memFree=188356/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=2.01
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 763 22450 0 1 0 1 188 12 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592952480 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
[pid=23336] ppid=23319 vsize=131636 CPUtime=1.92
/proc/23336/stat : 23336 (gringo) R 23319 23319 1733 0 -1 4202496 30803 0 0 0 180 12 0 0 20 0 1 0 115827796 134795264 28184 18446744073709551615 4194304 6531320 140736944001984 140736943999112 5502304 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23336/statm: 32909 28184 284 571 0 32330 0
Current children cumulated CPU time (s) 3.93
Current children cumulated vsize (KiB) 140848

[startup+4.40022 s]
/proc/loadavg: 1.08 1.00 0.93 2/62 23338
/proc/meminfo: memFree=195168/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=4.09
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 801 53257 0 1 0 1 380 28 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592951888 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
[pid=23337] ppid=23319 vsize=40868 CPUtime=0.21
/proc/23337/stat : 23337 (clasp) R 23319 23319 1733 0 -1 4202496 10993 0 0 0 19 2 0 0 20 0 1 0 115828006 41848832 9697 18446744073709551615 4194304 6238623 140735105504144 140735105501704 4496080 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/23337/statm: 10217 9697 209 500 0 9714 0
[pid=23338] ppid=23319 vsize=22040 CPUtime=0.02
/proc/23338/stat : 23338 (parse.py) S 23319 23319 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115828006 22568960 1128 18446744073709551615 4194304 6642060 140733413336640 140733413335000 140214142138144 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23338/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 4.32
Current children cumulated vsize (KiB) 72120

[startup+4.80041 s]
/proc/loadavg: 1.08 1.00 0.93 2/62 23338
/proc/meminfo: memFree=195168/1022884 swapFree=0/0
[pid=23319] ppid=23318 vsize=9212 CPUtime=4.09
/proc/23319/stat : 23319 (aspcud-basic) S 23318 23319 1733 0 -1 4202496 801 53257 0 1 0 1 380 28 20 0 1 0 115827591 9433088 364 18446744073709551615 4194304 5129932 140733592953824 140733592951888 140386365473886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23319/statm: 2303 364 303 229 0 63 0
[pid=23337] ppid=23319 vsize=39692 CPUtime=0.6
/proc/23337/stat : 23337 (clasp) R 23319 23319 1733 0 -1 4202496 11362 0 0 0 58 2 0 0 20 0 1 0 115828006 40644608 9525 18446744073709551615 4194304 6238623 140735105504144 140735105501168 4683059 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/23337/statm: 9923 9525 264 500 0 9420 0
[pid=23338] ppid=23319 vsize=22040 CPUtime=0.02
/proc/23338/stat : 23338 (parse.py) S 23319 23319 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115828006 22568960 1128 18446744073709551615 4194304 6642060 140733413336640 140733413335000 140214142138144 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23338/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 4.71
Current children cumulated vsize (KiB) 70944

Child status: 0
Real time (s): 4.88683
CPU time (s): 4.8243
CPU user time (s): 4.46428
CPU system time (s): 0.360022
CPU usage (%): 98.7205
Max. virtual memory (cumulated for all children) (KiB): 140848

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.46428
system time used= 0.360022
maximum resident set size= 112736
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67075
page faults= 1
swaps= 0
block input operations= 29520
block output operations= 17072
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 79
involuntary context switches= 588

runsolver used 0 second user time and 0.040002 second system time

The end