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 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.result -notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.01 1.04 1.05 2/64 13099
/proc/meminfo: memFree=402788/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9204 CPUtime=0
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 118016833 9424896 331 18446744073709551615 4194304 5129932 140733767925504 140733767922968 140613714990880 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2301 331 272 229 0 61 0

[startup+0.137471 s]
/proc/loadavg: 1.01 1.04 1.05 2/64 13099
/proc/meminfo: memFree=402788/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=0.02
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 693 2807 0 0 0 0 2 0 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200315 s]
/proc/loadavg: 1.01 1.04 1.05 2/64 13099
/proc/meminfo: memFree=402788/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=0.02
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 693 2807 0 0 0 0 2 0 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300296 s]
/proc/loadavg: 1.01 1.04 1.05 2/64 13099
/proc/meminfo: memFree=402788/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=0.02
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 693 2807 0 0 0 0 2 0 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700234 s]
/proc/loadavg: 1.01 1.04 1.05 2/64 13099
/proc/meminfo: memFree=402788/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=0.02
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 693 2807 0 0 0 0 2 0 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.01 1.04 1.05 2/66 13112
/proc/meminfo: memFree=365936/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=0.02
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 693 2807 0 0 0 0 2 0 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
[pid=13112] ppid=13099 vsize=54360 CPUtime=1.43
/proc/13112/stat : 13112 (cudf2lp) R 13099 13099 1745 0 -1 4202496 15078 0 0 0 135 8 0 0 20 0 1 0 118016835 55664640 11680 18446744073709551615 4194304 5690517 140733370338832 140733370336472 4951991 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/13112/statm: 13590 11680 160 366 0 13221 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 63572

[startup+3.1006 s]
/proc/loadavg: 1.01 1.04 1.05 2/66 13112
/proc/meminfo: memFree=331836/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=0.02
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 693 2807 0 0 0 0 2 0 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
[pid=13112] ppid=13099 vsize=1816 CPUtime=3.01
/proc/13112/stat : 13112 (cudf2lp) R 13099 13099 1745 0 -1 4202496 26201 0 0 0 286 15 0 0 20 0 1 0 118016835 1859584 227 18446744073709551615 4194304 5690517 140733370338832 140733370336632 5219018 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/13112/statm: 454 227 174 366 0 85 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 11028

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

[startup+3.2004 s]
/proc/loadavg: 1.01 1.04 1.05 2/66 13112
/proc/meminfo: memFree=331836/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=3.05
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 720 29010 0 0 0 0 289 16 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 9212

[startup+4.80029 s]
/proc/loadavg: 1.01 1.04 1.05 2/66 13113
/proc/meminfo: memFree=331836/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=3.05
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 720 29010 0 0 0 0 289 16 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
[pid=13113] ppid=13099 vsize=105016 CPUtime=1.67
/proc/13113/stat : 13113 (gringo) R 13099 13099 1745 0 -1 4202496 24365 0 0 0 156 11 0 0 20 0 1 0 118017143 107536384 21265 18446744073709551615 4194304 6531320 140733904053408 140733904049832 4598007 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13113/statm: 26254 21265 282 571 0 25675 0
Current children cumulated CPU time (s) 4.72
Current children cumulated vsize (KiB) 114228

[startup+5.20046 s]
/proc/loadavg: 1.01 1.04 1.05 2/66 13113
/proc/meminfo: memFree=331836/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=3.05
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 720 29010 0 0 0 0 289 16 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767924160 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
[pid=13113] ppid=13099 vsize=115908 CPUtime=2.07
/proc/13113/stat : 13113 (gringo) R 13099 13099 1745 0 -1 4202496 29492 0 0 0 194 13 0 0 20 0 1 0 118017143 118689792 24218 18446744073709551615 4194304 6531320 140733904053408 140733904051096 4318262 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13113/statm: 28977 24218 283 571 0 28398 0
Current children cumulated CPU time (s) 5.12
Current children cumulated vsize (KiB) 125120

[startup+5.40022 s]
/proc/loadavg: 1.01 1.04 1.05 2/66 13113
/proc/meminfo: memFree=331836/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=5.19
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 759 58506 0 0 0 0 486 33 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767923568 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 5.19
Current children cumulated vsize (KiB) 9212

[startup+5.50111 s]
/proc/loadavg: 1.08 1.05 1.06 2/67 13115
/proc/meminfo: memFree=351916/1022884 swapFree=0/0
[pid=13099] ppid=13098 vsize=9212 CPUtime=5.19
/proc/13099/stat : 13099 (aspuncud-full) S 13098 13099 1745 0 -1 4202496 759 58506 0 0 0 0 486 33 20 0 1 0 118016833 9433088 364 18446744073709551615 4194304 5129932 140733767925504 140733767923568 140613714846814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13099/statm: 2303 364 303 229 0 63 0
[pid=13114] ppid=13099 vsize=30788 CPUtime=0.2
/proc/13114/stat : 13114 (unclasp) R 13099 13099 1745 0 -1 4202496 9093 0 0 0 17 3 0 0 20 0 1 0 118017360 31526912 4275 18446744073709551615 4194304 6012874 140737446358480 140737446357880 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13114/statm: 7697 4275 234 444 0 7245 0
[pid=13115] ppid=13099 vsize=22180 CPUtime=0.02
/proc/13115/stat : 13115 (parse.py) S 13099 13099 1745 0 -1 4202496 1324 0 0 0 1 1 0 0 20 0 1 0 118017360 22712320 1134 18446744073709551615 4194304 6642060 140737446706144 140737446704392 140671949510432 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13115/statm: 5545 1134 508 598 0 631 0
Current children cumulated CPU time (s) 5.41
Current children cumulated vsize (KiB) 62180

Child status: 0
Real time (s): 5.51613
CPU time (s): 5.45234
CPU user time (s): 5.06432
CPU system time (s): 0.388024
CPU usage (%): 98.8435
Max. virtual memory (cumulated for all children) (KiB): 137416

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.06432
system time used= 0.388024
maximum resident set size= 105568
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 69967
page faults= 0
swaps= 0
block input operations= 43032
block output operations= 19400
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 70
involuntary context switches= 674

runsolver used 0.012 second user time and 0.032002 second system time

The end