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/rand954.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand954.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/install/rand954.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.90 0.94 0.91 2/59 23599
/proc/meminfo: memFree=347528/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=3152 CPUtime=0
/proc/23599/stat : 23599 (runsolver) R 23598 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115915471 3227648 32 18446744073709551615 134512640 134586868 4294781568 4294779616 4152005680 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 788 32 0 19 0 73 0

[startup+0.151835 s]
/proc/loadavg: 0.90 0.94 0.91 2/59 23599
/proc/meminfo: memFree=347528/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=0.03
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 700 2802 0 0 0 0 2 1 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200312 s]
/proc/loadavg: 0.90 0.94 0.91 2/59 23599
/proc/meminfo: memFree=347528/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=0.03
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 700 2802 0 0 0 0 2 1 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300317 s]
/proc/loadavg: 0.90 0.94 0.91 2/59 23599
/proc/meminfo: memFree=347528/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=0.03
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 700 2802 0 0 0 0 2 1 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700236 s]
/proc/loadavg: 0.90 0.94 0.91 2/59 23599
/proc/meminfo: memFree=347528/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=0.03
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 700 2802 0 0 0 0 2 1 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.90 0.94 0.91 2/61 23612
/proc/meminfo: memFree=312040/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=0.03
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 700 2802 0 0 0 0 2 1 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23612] ppid=23599 vsize=48096 CPUtime=1.4
/proc/23612/stat : 23612 (cudf2lp) R 23599 23599 1733 0 -1 4202496 10513 0 16 0 136 4 0 0 20 0 1 0 115915475 49250304 8795 18446744073709551615 4194304 5690517 140737031615024 140737031611224 4970533 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/23612/statm: 12024 8795 160 366 0 11655 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 57308

[startup+3.10033 s]
/proc/loadavg: 0.91 0.94 0.91 2/61 23612
/proc/meminfo: memFree=279428/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=0.03
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 700 2802 0 0 0 0 2 1 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23612] ppid=23599 vsize=93028 CPUtime=2.98
/proc/23612/stat : 23612 (cudf2lp) R 23599 23599 1733 0 -1 4202496 26520 0 16 0 288 10 0 0 20 0 1 0 115915475 95260672 19808 18446744073709551615 4194304 5690517 140737031615024 140737031612664 4357493 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/23612/statm: 23257 19808 160 366 0 22888 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 102240

[startup+6.30034 s]
/proc/loadavg: 0.91 0.94 0.91 2/61 23613
/proc/meminfo: memFree=287364/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=4.92
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 728 42108 0 16 1 0 468 23 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571759552 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23613] ppid=23599 vsize=38656 CPUtime=1.17
/proc/23613/stat : 23613 (gringo) R 23599 23599 1733 0 -1 4202496 10630 0 22 0 111 6 0 0 20 0 1 0 115915972 39583744 7518 18446744073709551615 4194304 6531320 140737291374176 140737291369992 5563104 0 0 16781316 16386 0 0 0 17 0 0 0 9 0 0
/proc/23613/statm: 9664 7518 259 571 0 9085 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 47868

[startup+12.7002 s]
/proc/loadavg: 0.92 0.94 0.91 2/61 23613
/proc/meminfo: memFree=10016/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 12.05
Current children cumulated vsize (KiB) 9212

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

[startup+12.8003 s]
/proc/loadavg: 0.92 0.94 0.91 2/61 23613
/proc/meminfo: memFree=10016/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 12.05
Current children cumulated vsize (KiB) 9212

[startup+16.0004 s]
/proc/loadavg: 0.92 0.94 0.91 2/62 23615
/proc/meminfo: memFree=241772/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23614] ppid=23599 vsize=124376 CPUtime=3.34
/proc/23614/stat : 23614 (unclasp) R 23599 23599 1733 0 -1 4202496 36401 0 17 0 319 15 0 0 20 0 1 0 115916717 127361024 30495 18446744073709551615 4194304 6012874 140737453810288 140737453809608 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 13 0 0
/proc/23614/statm: 31094 30495 226 444 0 30642 0
[pid=23615] ppid=23599 vsize=22040 CPUtime=0.02
/proc/23615/stat : 23615 (parse.py) S 23599 23599 1733 0 -1 4202496 1307 0 13 0 1 1 0 0 20 0 1 0 115916717 22568960 1129 18446744073709551615 4194304 6642060 140734119778976 140734119777304 139946082264864 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/23615/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 15.41
Current children cumulated vsize (KiB) 155628

[startup+17.6004 s]
/proc/loadavg: 0.93 0.94 0.91 2/62 23615
/proc/meminfo: memFree=241772/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23614] ppid=23599 vsize=124376 CPUtime=4.92
/proc/23614/stat : 23614 (unclasp) R 23599 23599 1733 0 -1 4202496 36402 0 17 0 477 15 0 0 20 0 1 0 115916717 127361024 30496 18446744073709551615 4194304 6012874 140737453810288 140737453809608 4506598 0 0 16781316 16386 0 0 0 17 0 0 0 13 0 0
/proc/23614/statm: 31094 30496 226 444 0 30642 0
[pid=23615] ppid=23599 vsize=22040 CPUtime=0.02
/proc/23615/stat : 23615 (parse.py) S 23599 23599 1733 0 -1 4202496 1307 0 13 0 1 1 0 0 20 0 1 0 115916717 22568960 1129 18446744073709551615 4194304 6642060 140734119778976 140734119777304 139946082264864 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/23615/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 16.99
Current children cumulated vsize (KiB) 155628

[startup+18.4004 s]
/proc/loadavg: 0.93 0.94 0.91 2/62 23615
/proc/meminfo: memFree=241772/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23614] ppid=23599 vsize=124376 CPUtime=5.71
/proc/23614/stat : 23614 (unclasp) R 23599 23599 1733 0 -1 4202496 36402 0 17 0 556 15 0 0 20 0 1 0 115916717 127361024 30496 18446744073709551615 4194304 6012874 140737453810288 140737453809608 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 13 0 0
/proc/23614/statm: 31094 30496 226 444 0 30642 0
[pid=23615] ppid=23599 vsize=22040 CPUtime=0.02
/proc/23615/stat : 23615 (parse.py) S 23599 23599 1733 0 -1 4202496 1307 0 13 0 1 1 0 0 20 0 1 0 115916717 22568960 1129 18446744073709551615 4194304 6642060 140734119778976 140734119777304 139946082264864 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/23615/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 17.78
Current children cumulated vsize (KiB) 155628

[startup+19.2004 s]
/proc/loadavg: 0.93 0.94 0.91 2/62 23615
/proc/meminfo: memFree=241772/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23614] ppid=23599 vsize=124376 CPUtime=6.51
/proc/23614/stat : 23614 (unclasp) R 23599 23599 1733 0 -1 4202496 36402 0 17 0 636 15 0 0 20 0 1 0 115916717 127361024 30496 18446744073709551615 4194304 6012874 140737453810288 140737453809608 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 13 0 0
/proc/23614/statm: 31094 30496 226 444 0 30642 0
[pid=23615] ppid=23599 vsize=22040 CPUtime=0.02
/proc/23615/stat : 23615 (parse.py) S 23599 23599 1733 0 -1 4202496 1307 0 13 0 1 1 0 0 20 0 1 0 115916717 22568960 1129 18446744073709551615 4194304 6642060 140734119778976 140734119777304 139946082264864 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/23615/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 18.58
Current children cumulated vsize (KiB) 155628

[startup+19.6004 s]
/proc/loadavg: 0.93 0.94 0.91 2/62 23615
/proc/meminfo: memFree=241772/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23614] ppid=23599 vsize=124376 CPUtime=6.9
/proc/23614/stat : 23614 (unclasp) R 23599 23599 1733 0 -1 4202496 36402 0 17 0 675 15 0 0 20 0 1 0 115916717 127361024 30496 18446744073709551615 4194304 6012874 140737453810288 140737453809608 4498658 0 0 16781316 16386 0 0 0 17 0 0 0 13 0 0
/proc/23614/statm: 31094 30496 226 444 0 30642 0
[pid=23615] ppid=23599 vsize=22040 CPUtime=0.02
/proc/23615/stat : 23615 (parse.py) S 23599 23599 1733 0 -1 4202496 1307 0 13 0 1 1 0 0 20 0 1 0 115916717 22568960 1129 18446744073709551615 4194304 6642060 140734119778976 140734119777304 139946082264864 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/23615/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 18.97
Current children cumulated vsize (KiB) 155628

[startup+19.7011 s]
/proc/loadavg: 0.93 0.94 0.91 2/62 23615
/proc/meminfo: memFree=241772/1022884 swapFree=0/0
[pid=23599] ppid=23598 vsize=9212 CPUtime=12.05
/proc/23599/stat : 23599 (aspuncud-basic) S 23598 23599 1733 0 -1 4202496 769 140990 0 39 1 0 1128 76 20 0 1 0 115915471 9433088 364 18446744073709551615 4194304 5129932 140735571760896 140735571758960 140681079190622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23599/statm: 2303 364 303 229 0 63 0
[pid=23614] ppid=23599 vsize=94628 CPUtime=7
/proc/23614/stat : 23614 (unclasp) R 23599 23599 1733 0 -1 4202496 36410 0 17 0 682 18 0 0 20 0 1 0 115916717 96899072 14988 18446744073709551615 4194304 6012874 140737453810288 140737453809688 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 13 0 0
/proc/23614/statm: 23657 14988 234 444 0 23205 0
[pid=23615] ppid=23599 vsize=22044 CPUtime=0.02
/proc/23615/stat : 23615 (parse.py) S 23599 23599 1733 0 -1 4202496 1309 0 13 0 1 1 0 0 20 0 1 0 115916717 22573056 1131 18446744073709551615 4194304 6642060 140734119778976 140734119777256 139946082264864 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/23615/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 19.07
Current children cumulated vsize (KiB) 125884

Child status: 0
Real time (s): 19.7595
CPU time (s): 19.1292
CPU user time (s): 18.1411
CPU system time (s): 0.988061
CPU usage (%): 96.8099
Max. virtual memory (cumulated for all children) (KiB): 420792

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.1411
system time used= 0.988061
maximum resident set size= 358484
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 179765
page faults= 70
swaps= 0
block input operations= 80080
block output operations= 47768
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 157
involuntary context switches= 2292

runsolver used 0.032002 second user time and 0.112007 second system time

The end