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/aspuncud-basic-1.7/embedded/install/rand547.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand547.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/install/rand547.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: 0.94 0.94 0.91 2/59 23621
/proc/meminfo: memFree=389612/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=3152 CPUtime=0
/proc/23621/stat : 23621 (runsolver) R 23620 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115918519 3227648 33 18446744073709551615 134512640 134586868 4293922800 4293920848 4151305264 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23621/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.133512 s]
/proc/loadavg: 0.94 0.94 0.91 2/59 23621
/proc/meminfo: memFree=389612/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=0.04
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 693 2796 2 7 1 0 3 0 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200326 s]
/proc/loadavg: 0.94 0.94 0.91 2/59 23621
/proc/meminfo: memFree=389612/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=0.04
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 693 2796 2 7 1 0 3 0 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300304 s]
/proc/loadavg: 0.94 0.94 0.91 2/59 23621
/proc/meminfo: memFree=389612/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=0.04
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 693 2796 2 7 1 0 3 0 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700218 s]
/proc/loadavg: 0.94 0.94 0.91 2/59 23621
/proc/meminfo: memFree=389612/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=0.04
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 693 2796 2 7 1 0 3 0 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.94 0.94 0.91 2/61 23634
/proc/meminfo: memFree=364912/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=0.04
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 693 2796 2 7 1 0 3 0 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23634] ppid=23621 vsize=33064 CPUtime=1.38
/proc/23634/stat : 23634 (cudf2lp) R 23621 23621 1733 0 -1 4202496 9701 0 0 0 134 4 0 0 20 0 1 0 115918529 33857536 7968 18446744073709551615 4194304 5690517 140734070078560 140734070076200 4970613 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/23634/statm: 8266 7968 160 366 0 7897 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 42276

[startup+3.10029 s]
/proc/loadavg: 0.94 0.94 0.91 2/61 23634
/proc/meminfo: memFree=343088/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=0.04
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 693 2796 2 7 1 0 3 0 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23634] ppid=23621 vsize=93028 CPUtime=2.97
/proc/23634/stat : 23634 (cudf2lp) R 23621 23621 1733 0 -1 4202496 26674 0 0 0 287 10 0 0 20 0 1 0 115918529 95260672 19947 18446744073709551615 4194304 5690517 140734070078560 140734070076200 4340480 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/23634/statm: 23257 19947 160 366 0 22888 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.94 0.94 0.91 2/61 23635
/proc/meminfo: memFree=361068/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=4.79
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 721 42117 2 7 1 0 454 24 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226642032 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23635] ppid=23621 vsize=42940 CPUtime=1.39
/proc/23635/stat : 23635 (gringo) R 23621 23621 1733 0 -1 4202496 11816 0 0 0 132 7 0 0 20 0 1 0 115919008 43970560 8683 18446744073709551615 4194304 6531320 140734720041760 140734720037576 4219922 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23635/statm: 10735 8683 259 571 0 10156 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 52152

[startup+12.7003 s]
/proc/loadavg: 0.95 0.95 0.91 2/62 23637
/proc/meminfo: memFree=240524/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=1.3
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 36902 0 0 0 123 7 0 0 20 0 1 0 115919655 129515520 30957 18446744073709551615 4194304 6012874 140733913474848 140733913474168 4855843 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 30957 219 444 0 31168 0
[pid=23637] ppid=23621 vsize=22040 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115919655 22568960 1128 18446744073709551615 4194304 6642060 140737338040240 140737338038600 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 157732

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

[startup+12.8004 s]
/proc/loadavg: 0.95 0.95 0.91 2/62 23637
/proc/meminfo: memFree=240524/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=1.4
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 36909 0 0 0 133 7 0 0 20 0 1 0 115919655 129515520 30964 18446744073709551615 4194304 6012874 140733913474848 140733913474168 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 30964 226 444 0 31168 0
[pid=23637] ppid=23621 vsize=22040 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 115919655 22568960 1129 18446744073709551615 4194304 6642060 140737338040240 140737338038568 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 157732

[startup+19.2003 s]
/proc/loadavg: 0.95 0.95 0.91 2/62 23637
/proc/meminfo: memFree=247096/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=7.75
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 36909 0 0 0 767 8 0 0 20 0 1 0 115919655 129515520 30964 18446744073709551615 4194304 6012874 140733913474848 140733913474168 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 30964 226 444 0 31168 0
[pid=23637] ppid=23621 vsize=22040 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 115919655 22568960 1129 18446744073709551615 4194304 6642060 140737338040240 140737338038568 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 18.93
Current children cumulated vsize (KiB) 157732

[startup+20.8003 s]
/proc/loadavg: 0.95 0.95 0.91 2/62 23637
/proc/meminfo: memFree=247096/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=9.34
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 36911 0 0 0 926 8 0 0 20 0 1 0 115919655 129515520 30966 18446744073709551615 4194304 6012874 140733913474848 140733913474168 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 30966 226 444 0 31168 0
[pid=23637] ppid=23621 vsize=22040 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 115919655 22568960 1129 18446744073709551615 4194304 6642060 140737338040240 140737338038568 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 20.52
Current children cumulated vsize (KiB) 157732

[startup+21.6003 s]
/proc/loadavg: 0.95 0.95 0.91 2/62 23637
/proc/meminfo: memFree=247096/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=10.13
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 36993 0 0 0 1005 8 0 0 20 0 1 0 115919655 129515520 31048 18446744073709551615 4194304 6012874 140733913474848 140733913474168 4546227 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 31048 227 444 0 31168 0
[pid=23637] ppid=23621 vsize=22040 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 115919655 22568960 1129 18446744073709551615 4194304 6642060 140737338040240 140737338038568 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 21.31
Current children cumulated vsize (KiB) 157732

[startup+22.0003 s]
/proc/loadavg: 0.96 0.95 0.91 2/62 23637
/proc/meminfo: memFree=247096/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=10.53
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 37022 0 0 0 1045 8 0 0 20 0 1 0 115919655 129515520 31077 18446744073709551615 4194304 6012874 140733913474848 140733913474168 4498884 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 31077 227 444 0 31168 0
[pid=23637] ppid=23621 vsize=22040 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 115919655 22568960 1129 18446744073709551615 4194304 6642060 140737338040240 140737338038568 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 21.71
Current children cumulated vsize (KiB) 157732

[startup+22.2004 s]
/proc/loadavg: 0.96 0.95 0.91 2/62 23637
/proc/meminfo: memFree=247096/1022884 swapFree=0/0
[pid=23621] ppid=23620 vsize=9212 CPUtime=11.18
/proc/23621/stat : 23621 (aspuncud-basic) S 23620 23621 1733 0 -1 4202496 761 142471 2 7 1 0 1048 69 20 0 1 0 115918519 9433088 365 18446744073709551615 4194304 5129932 140733226643376 140733226641440 140211254269022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23621/statm: 2303 365 303 229 0 63 0
[pid=23636] ppid=23621 vsize=126480 CPUtime=10.73
/proc/23636/stat : 23636 (unclasp) R 23621 23621 1733 0 -1 4202496 37029 0 0 0 1064 9 0 0 20 0 1 0 115919655 129515520 30060 18446744073709551615 4194304 6012874 140733913474848 140733913474264 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23636/statm: 31620 30060 234 444 0 31168 0
[pid=23637] ppid=23621 vsize=22044 CPUtime=0
/proc/23637/stat : 23637 (parse.py) S 23621 23621 1733 0 -1 4202496 1321 0 0 0 0 0 0 0 20 0 1 0 115919655 22573056 1131 18446744073709551615 4194304 6642060 140737338040240 140737338038488 140294430455584 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23637/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 21.91
Current children cumulated vsize (KiB) 157736

Child status: 0
Real time (s): 22.2431
CPU time (s): 21.9934
CPU user time (s): 21.1573
CPU system time (s): 0.836052
CPU usage (%): 98.8771
Max. virtual memory (cumulated for all children) (KiB): 430220

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 21.1573
system time used= 0.836052
maximum resident set size= 364284
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 181870
page faults= 9
swaps= 0
block input operations= 536
block output operations= 48280
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 69
involuntary context switches= 2553

runsolver used 0.060003 second user time and 0.076004 second system time

The end