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/paranoid-size/real/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/real/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

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: 1.08 1.02 0.92 2/60 21813
/proc/meminfo: memFree=316004/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=1212 CPUtime=0
/proc/21813/stat : 21813 (aspuncud-basic) R 21812 21813 1733 0 -1 4194304 77 0 0 0 0 0 0 0 20 0 1 0 115391449 1241088 2 18446744073709551615 4194304 5129932 140734283285296 140734283285296 139897681386224 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 303 2 0 229 0 30 0

[startup+0.172627 s]
/proc/loadavg: 1.08 1.02 0.92 2/60 21813
/proc/meminfo: memFree=316004/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=0.02
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 701 2805 0 0 0 0 1 1 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283952 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200271 s]
/proc/loadavg: 1.08 1.02 0.92 2/60 21813
/proc/meminfo: memFree=316004/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=0.02
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 701 2805 0 0 0 0 1 1 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283952 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300252 s]
/proc/loadavg: 1.08 1.02 0.92 2/60 21813
/proc/meminfo: memFree=316004/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=0.02
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 701 2805 0 0 0 0 1 1 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283952 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.7002 s]
/proc/loadavg: 1.08 1.02 0.92 2/60 21813
/proc/meminfo: memFree=316004/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=0.02
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 701 2805 0 0 0 0 1 1 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283952 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 1.08 1.02 0.92 2/62 21826
/proc/meminfo: memFree=271216/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=0.02
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 701 2805 0 0 0 0 1 1 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283952 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21826] ppid=21813 vsize=78584 CPUtime=1.46
/proc/21826/stat : 21826 (cudf2lp) R 21813 21813 1733 0 -1 4202496 21943 0 0 0 141 5 0 0 20 0 1 0 115391451 80470016 18544 18446744073709551615 4194304 5690517 140733609056480 140733609053544 4963881 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/21826/statm: 19646 18544 168 366 0 19277 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 87796

[startup+3.10026 s]
/proc/loadavg: 1.08 1.02 0.92 2/62 21827
/proc/meminfo: memFree=294404/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=1.87
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 729 26219 0 0 0 0 177 10 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283952 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21827] ppid=21813 vsize=90224 CPUtime=1.2
/proc/21827/stat : 21827 (gringo) R 21813 21813 1733 0 -1 4202496 23218 0 0 0 114 6 0 0 20 0 1 0 115391638 92389376 18550 18446744073709551615 4194304 6531320 140734405991104 140734405987032 5511396 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21827/statm: 22556 18550 281 571 0 21977 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 99436

[startup+6.30021 s]
/proc/loadavg: 1.07 1.02 0.92 2/62 21827
/proc/meminfo: memFree=10032/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 5.64
Current children cumulated vsize (KiB) 9212

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

[startup+6.40027 s]
/proc/loadavg: 1.07 1.02 0.92 2/62 21827
/proc/meminfo: memFree=10032/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 5.64
Current children cumulated vsize (KiB) 9212

[startup+8.00031 s]
/proc/loadavg: 1.07 1.02 0.92 2/63 21829
/proc/meminfo: memFree=212400/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21828] ppid=21813 vsize=103088 CPUtime=2.24
/proc/21828/stat : 21828 (unclasp) R 21813 21813 1733 0 -1 4202496 31095 0 0 0 218 6 0 0 20 0 1 0 115392020 105562112 25440 18446744073709551615 4194304 6012874 140734469466880 140734469466200 4300059 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21828/statm: 25772 25440 226 444 0 25320 0
[pid=21829] ppid=21813 vsize=22188 CPUtime=0
/proc/21829/stat : 21829 (parse.py) S 21813 21813 1733 0 -1 4202496 1336 0 0 0 0 0 0 0 20 0 1 0 115392020 22720512 1147 18446744073709551615 4194304 6642060 140737243341296 140737243339224 140612715181856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21829/statm: 5547 1147 508 598 0 633 0
Current children cumulated CPU time (s) 7.88
Current children cumulated vsize (KiB) 134488

[startup+8.80041 s]
/proc/loadavg: 1.07 1.02 0.92 2/63 21829
/proc/meminfo: memFree=212400/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21828] ppid=21813 vsize=103088 CPUtime=3.04
/proc/21828/stat : 21828 (unclasp) R 21813 21813 1733 0 -1 4202496 31097 0 0 0 297 7 0 0 20 0 1 0 115392020 105562112 25442 18446744073709551615 4194304 6012874 140734469466880 140734469466200 4536038 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21828/statm: 25772 25442 226 444 0 25320 0
[pid=21829] ppid=21813 vsize=22320 CPUtime=0
/proc/21829/stat : 21829 (parse.py) S 21813 21813 1733 0 -1 4202496 1380 0 0 0 0 0 0 0 20 0 1 0 115392020 22855680 1191 18446744073709551615 4194304 6642060 140737243341296 140737243339256 140612715181856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21829/statm: 5580 1191 508 598 0 666 0
Current children cumulated CPU time (s) 8.68
Current children cumulated vsize (KiB) 134620

[startup+9.60033 s]
/proc/loadavg: 1.07 1.02 0.92 2/63 21829
/proc/meminfo: memFree=212400/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21828] ppid=21813 vsize=103088 CPUtime=3.83
/proc/21828/stat : 21828 (unclasp) R 21813 21813 1733 0 -1 4202496 31097 0 0 0 376 7 0 0 20 0 1 0 115392020 105562112 25442 18446744073709551615 4194304 6012874 140734469466880 140734469466200 4300161 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21828/statm: 25772 25442 226 444 0 25320 0
[pid=21829] ppid=21813 vsize=22320 CPUtime=0
/proc/21829/stat : 21829 (parse.py) S 21813 21813 1733 0 -1 4202496 1380 0 0 0 0 0 0 0 20 0 1 0 115392020 22855680 1191 18446744073709551615 4194304 6642060 140737243341296 140737243339256 140612715181856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21829/statm: 5580 1191 508 598 0 666 0
Current children cumulated CPU time (s) 9.47
Current children cumulated vsize (KiB) 134620

[startup+10.009 s]
/proc/loadavg: 1.07 1.02 0.92 2/63 21829
/proc/meminfo: memFree=212400/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21828] ppid=21813 vsize=103088 CPUtime=4.23
/proc/21828/stat : 21828 (unclasp) R 21813 21813 1733 0 -1 4202496 31097 0 0 0 416 7 0 0 20 0 1 0 115392020 105562112 25442 18446744073709551615 4194304 6012874 140734469466880 140734469466200 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21828/statm: 25772 25442 226 444 0 25320 0
[pid=21829] ppid=21813 vsize=22320 CPUtime=0
/proc/21829/stat : 21829 (parse.py) S 21813 21813 1733 0 -1 4202496 1380 0 0 0 0 0 0 0 20 0 1 0 115392020 22855680 1191 18446744073709551615 4194304 6642060 140737243341296 140737243339256 140612715181856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21829/statm: 5580 1191 508 598 0 666 0
Current children cumulated CPU time (s) 9.87
Current children cumulated vsize (KiB) 134620

[startup+10.1003 s]
/proc/loadavg: 1.07 1.02 0.92 2/63 21829
/proc/meminfo: memFree=212400/1022884 swapFree=0/0
[pid=21813] ppid=21812 vsize=9212 CPUtime=5.64
/proc/21813/stat : 21813 (aspuncud-basic) S 21812 21813 1733 0 -1 4202496 769 111526 0 0 0 0 520 44 20 0 1 0 115391449 9433088 364 18446744073709551615 4194304 5129932 140734283285296 140734283283360 139897673999454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21813/statm: 2303 364 303 229 0 63 0
[pid=21828] ppid=21813 vsize=0 CPUtime=4.32
/proc/21828/stat : 21828 (unclasp) R 21813 21813 1733 0 -1 4202500 31107 0 0 0 422 10 0 0 20 0 1 0 115392020 0 0 18446744073709551615 0 0 0 0 0 0 0 16781316 16386 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21828/statm: 0 0 0 0 0 0 0
[pid=21829] ppid=21813 vsize=22504 CPUtime=0.01
/proc/21829/stat : 21829 (parse.py) R 21813 21813 1733 0 -1 4202496 1414 0 0 0 1 0 0 0 20 0 1 0 115392020 23044096 1225 18446744073709551615 4194304 6642060 140737243341296 140737243339416 4596530 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21829/statm: 5626 1225 518 598 0 712 0
Current children cumulated CPU time (s) 9.97
Current children cumulated vsize (KiB) 31716

Child status: 0
Real time (s): 10.1133
CPU time (s): 10.0206
CPU user time (s): 9.45259
CPU system time (s): 0.568035
CPU usage (%): 99.0832
Max. virtual memory (cumulated for all children) (KiB): 377424

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.45259
system time used= 0.568035
maximum resident set size= 306152
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 145092
page faults= 0
swaps= 0
block input operations= 0
block output operations= 36624
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 151
involuntary context switches= 1295

runsolver used 0.024001 second user time and 0.036002 second system time

The end