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/upgrade/install/rand179.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand179.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/upgrade/install/rand179.cudf.result -count(down),-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

[startup+0 s]
/proc/loadavg: 0.91 0.93 0.56 2/60 9712
/proc/meminfo: memFree=475956/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=3152 CPUtime=0
/proc/9712/stat : 9712 (runsolver) R 9711 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117117591 3227648 32 18446744073709551615 134512640 134586868 4294398784 4294396832 4151673904 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/9712/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.175374 s]
/proc/loadavg: 0.91 0.93 0.56 2/60 9712
/proc/meminfo: memFree=475956/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9204 CPUtime=0.02
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 594 1948 2 4 0 0 2 0 20 0 1 0 117117591 9424896 360 18446744073709551615 4194304 5129932 140733771227504 140733771224968 139951079937824 0 0 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2301 360 300 229 0 61 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9204

[startup+0.200387 s]
/proc/loadavg: 0.91 0.93 0.56 2/60 9712
/proc/meminfo: memFree=475956/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=0.03
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 695 2799 2 7 0 0 3 0 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300392 s]
/proc/loadavg: 0.91 0.93 0.56 2/60 9712
/proc/meminfo: memFree=475956/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=0.03
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 695 2799 2 7 0 0 3 0 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700221 s]
/proc/loadavg: 0.91 0.93 0.56 2/60 9712
/proc/meminfo: memFree=475956/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=0.03
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 695 2799 2 7 0 0 3 0 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.92 0.93 0.56 2/62 9725
/proc/meminfo: memFree=449900/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=0.03
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 695 2799 2 7 0 0 3 0 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
[pid=9725] ppid=9712 vsize=29272 CPUtime=1.07
/proc/9725/stat : 9725 (cudf2lp) R 9712 9712 1750 0 -1 4202496 8367 0 16 0 102 5 0 0 20 0 1 0 117117610 29974528 6650 18446744073709551615 4194304 5690517 140737276113456 140737276111112 4811168 0 0 16781316 0 0 0 0 17 0 0 0 22 0 0
/proc/9725/statm: 7318 6650 159 366 0 6949 0
Current children cumulated CPU time (s) 1.1
Current children cumulated vsize (KiB) 38484

[startup+3.10032 s]
/proc/loadavg: 0.92 0.93 0.56 2/62 9725
/proc/meminfo: memFree=410716/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=0.03
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 695 2799 2 7 0 0 3 0 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
[pid=9725] ppid=9712 vsize=56532 CPUtime=2.65
/proc/9725/stat : 9725 (cudf2lp) R 9712 9712 1750 0 -1 4202496 17060 0 16 0 256 9 0 0 20 0 1 0 117117610 57888768 13678 18446744073709551615 4194304 5690517 140737276113456 140737276111096 4328288 0 0 16781316 0 0 0 0 17 0 0 0 23 0 0
/proc/9725/statm: 14133 13678 160 366 0 13764 0
Current children cumulated CPU time (s) 2.68
Current children cumulated vsize (KiB) 65744

[startup+6.30023 s]
/proc/loadavg: 0.93 0.93 0.56 2/62 9725
/proc/meminfo: memFree=303208/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=5.19
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 723 44061 2 23 0 0 486 33 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 5.19
Current children cumulated vsize (KiB) 9212

[startup+12.7002 s]
/proc/loadavg: 0.93 0.93 0.56 2/62 9726
/proc/meminfo: memFree=9900/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=5.19
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 723 44061 2 23 0 0 486 33 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
[pid=9726] ppid=9712 vsize=576156 CPUtime=6.76
/proc/9726/stat : 9726 (gringo) R 9712 9712 1750 0 -1 4202496 135069 0 23 0 623 53 0 0 20 0 1 0 117118154 589983744 116595 18446744073709551615 4194304 6531320 140734171218144 140734171214552 4596736 0 0 16781316 16386 0 0 0 17 0 0 0 15 0 0
/proc/9726/statm: 144039 116595 282 571 0 143460 0
Current children cumulated CPU time (s) 11.95
Current children cumulated vsize (KiB) 585368

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

[startup+12.8003 s]
/proc/loadavg: 0.93 0.93 0.56 2/62 9726
/proc/meminfo: memFree=9900/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=5.19
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 723 44061 2 23 0 0 486 33 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771226160 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
[pid=9726] ppid=9712 vsize=578480 CPUtime=6.85
/proc/9726/stat : 9726 (gringo) R 9712 9712 1750 0 -1 4202496 135644 0 23 0 632 53 0 0 20 0 1 0 117118154 592363520 117170 18446744073709551615 4194304 6531320 140734171218144 140734171214952 5502135 0 0 16781316 16386 0 0 0 17 0 0 0 15 0 0
/proc/9726/statm: 144620 117170 283 571 0 144041 0
Current children cumulated CPU time (s) 12.04
Current children cumulated vsize (KiB) 587692

[startup+13.6002 s]
/proc/loadavg: 0.93 0.93 0.56 2/62 9726
/proc/meminfo: memFree=48636/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=12.62
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 764 179709 2 46 0 0 1164 98 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771225568 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 9212

[startup+14.4033 s]
/proc/loadavg: 0.93 0.93 0.56 2/63 9728
/proc/meminfo: memFree=310764/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=12.62
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 764 179709 2 46 0 0 1164 98 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771225568 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
[pid=9727] ppid=9712 vsize=170288 CPUtime=0.96
/proc/9727/stat : 9727 (unclasp) R 9712 9712 1750 0 -1 4202496 47104 0 18 0 84 12 0 0 20 0 1 0 117118929 174374912 40888 18446744073709551615 4194304 6012874 140735346533712 140735346533032 4535488 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/9727/statm: 42572 40888 220 444 0 42120 0
[pid=9728] ppid=9712 vsize=22040 CPUtime=0.01
/proc/9728/stat : 9728 (parse.py) S 9712 9712 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 117118929 22568960 1128 18446744073709551615 4194304 6642060 140735454970768 140735454969128 139954071525152 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9728/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 13.59
Current children cumulated vsize (KiB) 201540

[startup+14.8003 s]
/proc/loadavg: 0.93 0.93 0.56 2/63 9728
/proc/meminfo: memFree=310764/1022884 swapFree=0/0
[pid=9712] ppid=9711 vsize=9212 CPUtime=12.62
/proc/9712/stat : 9712 (aspuncud-full) S 9711 9712 1750 0 -1 4202496 764 179709 2 46 0 0 1164 98 20 0 1 0 117117591 9433088 365 18446744073709551615 4194304 5129932 140733771227504 140733771225568 139951079793758 0 65536 16781316 1115778811 0 0 0 17 0 0 0 7 0 0
/proc/9712/statm: 2303 365 303 229 0 63 0
[pid=9727] ppid=9712 vsize=157984 CPUtime=1.35
/proc/9727/stat : 9727 (unclasp) R 9712 9712 1750 0 -1 4202496 47123 0 18 0 123 12 0 0 20 0 1 0 117118929 161775616 38640 18446744073709551615 4194304 6012874 140735346533712 140735346532776 4514671 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/9727/statm: 39496 38640 226 444 0 39044 0
[pid=9728] ppid=9712 vsize=22340 CPUtime=0.01
/proc/9728/stat : 9728 (parse.py) S 9712 9712 1750 0 -1 4202496 1390 0 0 0 0 1 0 0 20 0 1 0 117118929 22876160 1199 18446744073709551615 4194304 6642060 140735454970768 140735454969048 139954071525152 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9728/statm: 5585 1199 508 598 0 671 0
Current children cumulated CPU time (s) 13.98
Current children cumulated vsize (KiB) 189536

Child status: 0
Real time (s): 14.8768
CPU time (s): 14.1009
CPU user time (s): 12.9168
CPU system time (s): 1.18407
CPU usage (%): 94.7846
Max. virtual memory (cumulated for all children) (KiB): 587692

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.9168
system time used= 1.18407
maximum resident set size= 468680
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 229280
page faults= 66
swaps= 0
block input operations= 78928
block output operations= 65408
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 223
involuntary context switches= 1760

runsolver used 0.032002 second user time and 0.060003 second system time

The end