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/aspcud-full-1.7/trendy-size/install/rand220.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand220.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand220.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-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.00 1.04 1.05 2/59 32472
/proc/meminfo: memFree=750136/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=3152 CPUtime=0
/proc/32472/stat : 32472 (runsolver) D 32471 32472 1733 0 -1 4202560 75 0 0 0 0 0 0 0 20 0 1 0 118800130 3227648 96 18446744073709551615 134512640 134586868 4294235104 4294233152 4152153136 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/32472/statm: 788 96 64 19 0 73 0

[startup+0.196093 s]
/proc/loadavg: 1.00 1.04 1.05 2/59 32472
/proc/meminfo: memFree=750136/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=0.05
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 732 3619 2 6 0 1 2 2 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200449 s]
/proc/loadavg: 1.00 1.04 1.05 2/59 32472
/proc/meminfo: memFree=750136/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=0.05
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 732 3619 2 6 0 1 2 2 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300345 s]
/proc/loadavg: 1.00 1.04 1.05 2/59 32472
/proc/meminfo: memFree=750136/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=0.05
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 732 3619 2 6 0 1 2 2 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700257 s]
/proc/loadavg: 1.00 1.04 1.05 2/59 32472
/proc/meminfo: memFree=750136/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=0.05
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 732 3619 2 6 0 1 2 2 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50039 s]
/proc/loadavg: 1.00 1.04 1.05 2/61 32488
/proc/meminfo: memFree=716136/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=0.05
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 732 3619 2 6 0 1 2 2 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32488] ppid=32472 vsize=29616 CPUtime=1.26
/proc/32488/stat : 32488 (cudf2lp) D 32472 32472 1733 0 -1 4202496 8699 0 16 0 121 5 0 0 20 0 1 0 118800140 30326784 6982 18446744073709551615 4194304 5690517 140736618010048 140736618007720 5058400 0 0 16781316 0 0 0 0 17 0 0 0 10 0 0
/proc/32488/statm: 7404 6982 159 366 0 7035 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 38828

[startup+3.10033 s]
/proc/loadavg: 1.00 1.04 1.05 2/61 32488
/proc/meminfo: memFree=684640/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=0.05
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 732 3619 2 6 0 1 2 2 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32488] ppid=32472 vsize=97368 CPUtime=2.83
/proc/32488/stat : 32488 (cudf2lp) R 32472 32472 1733 0 -1 4202496 22897 0 16 0 267 16 0 0 20 0 1 0 118800140 99704832 19515 18446744073709551615 4194304 5690517 140736618010048 140736618006216 4363496 0 0 16781316 0 0 0 0 17 0 0 0 14 0 0
/proc/32488/statm: 24342 19515 160 366 0 23973 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 106580

[startup+6.30024 s]
/proc/loadavg: 1.00 1.04 1.05 2/61 32488
/proc/meminfo: memFree=657236/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=5.29
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 758 42923 2 22 0 1 493 35 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 5.29
Current children cumulated vsize (KiB) 9212

[startup+12.7003 s]
/proc/loadavg: 1.00 1.04 1.05 2/61 32489
/proc/meminfo: memFree=426968/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=5.29
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 758 42923 2 22 0 1 493 35 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468872368 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32489] ppid=32472 vsize=382564 CPUtime=6.93
/proc/32489/stat : 32489 (gringo) R 32472 32472 1733 0 -1 4202496 92185 0 23 0 656 37 0 0 20 0 1 0 118800684 391745536 75733 18446744073709551615 4194304 6531320 140734011553648 140734011550072 5554416 0 0 16781316 16386 0 0 0 17 0 0 0 14 0 0
/proc/32489/statm: 95641 75733 282 571 0 95062 0
Current children cumulated CPU time (s) 12.22
Current children cumulated vsize (KiB) 391776

[startup+25.5005 s]
/proc/loadavg: 1.00 1.04 1.05 2/62 32491
/proc/meminfo: memFree=432912/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=237988 CPUtime=6.44
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 71346 0 22 0 616 28 0 0 20 0 1 0 118802020 243699712 58238 18446744073709551615 4194304 6238623 140736549705424 140736549702448 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 59497 58238 263 500 0 58994 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.81
Current children cumulated vsize (KiB) 269240

[startup+51.1004 s]
/proc/loadavg: 1.00 1.03 1.05 2/62 32491
/proc/meminfo: memFree=429936/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=237988 CPUtime=31.76
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 72192 0 22 0 3147 29 0 0 20 0 1 0 118802020 243699712 59084 18446744073709551615 4194304 6238623 140736549705424 140736549702448 4421756 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 59497 59084 264 500 0 58994 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.13
Current children cumulated vsize (KiB) 269240

[startup+102.3 s]
/proc/loadavg: 1.00 1.02 1.04 2/62 32491
/proc/meminfo: memFree=387032/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=280444 CPUtime=82.45
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 82861 0 22 0 8209 36 0 0 20 0 1 0 118802020 287174656 69753 18446744073709551615 4194304 6238623 140736549705424 140736549701976 4635062 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 70111 69753 264 500 0 69608 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.82
Current children cumulated vsize (KiB) 311696

[startup+162.3 s]
/proc/loadavg: 1.00 1.02 1.04 2/62 32491
/proc/meminfo: memFree=342268/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=325216 CPUtime=141.84
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 94002 0 22 0 14139 45 0 0 20 0 1 0 118802020 333021184 80894 18446744073709551615 4194304 6238623 140736549705424 140736549701976 4331904 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 81304 80894 264 500 0 80801 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.21
Current children cumulated vsize (KiB) 356468

[startup+222.31 s]
/proc/loadavg: 1.06 1.03 1.04 2/62 32491
/proc/meminfo: memFree=333836/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=334160 CPUtime=201.29
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 96113 0 22 0 20082 47 0 0 20 0 1 0 118802020 342179840 83005 18446744073709551615 4194304 6238623 140736549705424 140736549702072 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 83540 83005 264 500 0 83037 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 219.66
Current children cumulated vsize (KiB) 365412

[startup+282.3 s]
/proc/loadavg: 1.02 1.02 1.03 2/62 32491
/proc/meminfo: memFree=329868/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=338300 CPUtime=260.81
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 97151 0 22 0 26034 47 0 0 20 0 1 0 118802020 346419200 84043 18446744073709551615 4194304 6238623 140736549705424 140736549701976 4669534 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 84575 84043 264 500 0 84072 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.18
Current children cumulated vsize (KiB) 369552



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.3 s]
/proc/loadavg: 1.01 1.02 1.03 2/62 32491
/proc/meminfo: memFree=326520/1022884 swapFree=0/0
[pid=32472] ppid=32471 vsize=9212 CPUtime=18.36
/proc/32472/stat : 32472 (aspcud-full) S 32471 32472 1733 0 -1 4202496 798 222503 2 45 0 1 1696 139 20 0 1 0 118800130 9433088 364 18446744073709551615 4194304 5129932 140734468873712 140734468871776 139944951108702 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/32472/statm: 2303 364 303 229 0 63 0
[pid=32490] ppid=32472 vsize=341380 CPUtime=281.65
/proc/32490/stat : 32490 (clasp) R 32472 32472 1733 0 -1 4202496 97969 0 22 0 28117 48 0 0 20 0 1 0 118802020 349573120 84861 18446744073709551615 4194304 6238623 140736549705424 140736549701976 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/32490/statm: 85345 84861 264 500 0 84842 0
[pid=32491] ppid=32472 vsize=22040 CPUtime=0.01
/proc/32491/stat : 32491 (parse.py) S 32472 32472 1733 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 118802020 22568960 1128 18446744073709551615 4194304 6642060 140735556767504 140735556765864 140220013516576 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/32491/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 372632

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 303.419
CPU time (s): 300.159
CPU user time (s): 298.211
CPU system time (s): 1.94812
CPU usage (%): 98.9255
Max. virtual memory (cumulated for all children) (KiB): 785472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.211
system time used= 1.94812
maximum resident set size= 652496
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 322902
page faults= 71
swaps= 0
block input operations= 79952
block output operations= 82232
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 177
involuntary context switches= 34336

runsolver used 0.836052 second user time and 1.27608 second system time

The end