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/slowlink/upgrade/easy/rand393.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand393.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand393.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

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.85 0.95 0.98 2/59 4637
/proc/meminfo: memFree=285772/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=3152 CPUtime=0
/proc/4637/stat : 4637 (runsolver) R 4636 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120322909 3227648 32 18446744073709551615 134512640 134586868 4293942624 4293940672 4151542832 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 788 32 0 19 0 73 0

[startup+0.197967 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 4637
/proc/meminfo: memFree=285772/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=0.04
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 733 3625 0 0 0 0 3 1 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200311 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 4637
/proc/meminfo: memFree=285772/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=0.04
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 733 3625 0 0 0 0 3 1 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300234 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 4637
/proc/meminfo: memFree=285772/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=0.04
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 733 3625 0 0 0 0 3 1 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700237 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 4637
/proc/meminfo: memFree=285772/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=0.04
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 733 3625 0 0 0 0 3 1 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.85 0.95 0.98 2/61 4653
/proc/meminfo: memFree=251648/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=0.04
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 733 3625 0 0 0 0 3 1 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4653] ppid=4637 vsize=48864 CPUtime=1.43
/proc/4653/stat : 4653 (cudf2lp) R 4637 4637 1733 0 -1 4202496 13686 0 0 0 133 10 0 0 20 0 1 0 120322912 50036736 10288 18446744073709551615 4194304 5690517 140734919165968 140734919163608 4961194 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/4653/statm: 12216 10288 159 366 0 11847 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 58076

[startup+3.10042 s]
/proc/loadavg: 0.85 0.95 0.98 1/61 4653
/proc/meminfo: memFree=220772/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=2.96
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 759 27449 0 0 0 0 277 19 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 9212

[startup+6.30032 s]
/proc/loadavg: 0.87 0.95 0.98 2/61 4654
/proc/meminfo: memFree=140768/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=2.96
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 759 27449 0 0 0 0 277 19 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113962464 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4654] ppid=4637 vsize=211324 CPUtime=3.25
/proc/4654/stat : 4654 (gringo) R 4637 4637 1733 0 -1 4202496 51069 0 0 0 304 21 0 0 20 0 1 0 120323209 216395776 46433 18446744073709551615 4194304 6531320 140735517857664 140735517854280 4358962 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/4654/statm: 52831 46433 283 571 0 52252 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 220536

[startup+12.7004 s]
/proc/loadavg: 0.88 0.95 0.98 2/62 4656
/proc/meminfo: memFree=179688/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=4.86
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25703 0 0 0 474 12 0 0 20 0 1 0 120323685 90697728 21659 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4684850 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21659 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 119824

[startup+25.5004 s]
/proc/loadavg: 0.90 0.95 0.98 2/62 4656
/proc/meminfo: memFree=179688/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=17.53
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25768 0 0 0 1741 12 0 0 20 0 1 0 120323685 90697728 21724 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4421810 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21724 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 119824

[startup+51.1004 s]
/proc/loadavg: 0.93 0.96 0.98 2/62 4656
/proc/meminfo: memFree=179564/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=42.88
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25768 0 0 0 4275 13 0 0 20 0 1 0 120323685 90697728 21724 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4407221 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21724 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.54
Current children cumulated vsize (KiB) 119824

[startup+102.3 s]
/proc/loadavg: 0.97 0.96 0.98 2/62 4656
/proc/meminfo: memFree=179440/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=93.59
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25768 0 0 0 9342 17 0 0 20 0 1 0 120323685 90697728 21724 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4407211 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21724 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.25
Current children cumulated vsize (KiB) 119824

[startup+162.3 s]
/proc/loadavg: 1.02 0.98 0.99 2/62 4656
/proc/meminfo: memFree=179440/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=153.03
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25768 0 0 0 15285 18 0 0 20 0 1 0 120323685 90697728 21724 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21724 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.69
Current children cumulated vsize (KiB) 119824

[startup+222.314 s]
/proc/loadavg: 1.01 0.98 0.99 3/64 4739
/proc/meminfo: memFree=175208/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=211.31
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25768 0 0 0 21111 20 0 0 20 0 1 0 120323685 90697728 21724 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4586167 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21724 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 218.97
Current children cumulated vsize (KiB) 119824

[startup+282.3 s]
/proc/loadavg: 1.10 1.02 1.00 2/62 4907
/proc/meminfo: memFree=172620/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=88572 CPUtime=263.65
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 25881 0 0 0 26342 23 0 0 20 0 1 0 120323685 90697728 21837 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4407293 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 22143 21837 264 500 0 21640 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 271.31
Current children cumulated vsize (KiB) 119824



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+311.3 s]
/proc/loadavg: 1.06 1.02 1.00 2/62 4907
/proc/meminfo: memFree=167040/1022884 swapFree=0/0
[pid=4637] ppid=4636 vsize=9212 CPUtime=7.64
/proc/4637/stat : 4637 (aspcud-full) S 4636 4637 1733 0 -1 4202496 799 100973 0 0 0 0 701 63 20 0 1 0 120322909 9433088 364 18446744073709551615 4194304 5129932 140737113963808 140737113961872 140307711042654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4637/statm: 2303 364 303 229 0 63 0
[pid=4655] ppid=4637 vsize=94248 CPUtime=292.41
/proc/4655/stat : 4655 (clasp) R 4637 4637 1733 0 -1 4202496 27306 0 0 0 29217 24 0 0 20 0 1 0 120323685 96509952 23262 18446744073709551615 4194304 6238623 140735124603664 140735124600688 4407293 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4655/statm: 23562 23262 264 500 0 23059 0
[pid=4656] ppid=4637 vsize=22040 CPUtime=0.02
/proc/4656/stat : 4656 (parse.py) S 4637 4637 1733 0 -1 4202496 1311 0 7 0 1 1 0 0 20 0 1 0 120323685 22568960 1128 18446744073709551615 4194304 6642060 140736603094304 140736603092664 140399678650144 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/4656/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 125500

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): 311.331
CPU time (s): 300.119
CPU user time (s): 299.207
CPU system time (s): 0.912057
CPU usage (%): 96.3987
Max. virtual memory (cumulated for all children) (KiB): 321784

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.207
system time used= 0.912057
maximum resident set size= 259148
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 130702
page faults= 7
swaps= 0
block input operations= 42984
block output operations= 31384
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 81
involuntary context switches= 36181

runsolver used 0.736046 second user time and 1.45209 second system time

The end