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/difficult/rand869.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand869.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand869.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.89 0.98 0.97 2/56 27277
/proc/meminfo: memFree=362316/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=3152 CPUtime=0
/proc/27277/stat : 27277 (runsolver) R 27276 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 42318769 3227648 32 18446744073709551615 134512640 134586868 4291922608 4291920656 4152079408 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.126424 s]
/proc/loadavg: 0.89 0.98 0.97 2/56 27277
/proc/meminfo: memFree=362316/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=0.06
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 739 3621 0 0 0 1 3 2 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200318 s]
/proc/loadavg: 0.89 0.98 0.97 2/56 27277
/proc/meminfo: memFree=362316/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=0.06
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 739 3621 0 0 0 1 3 2 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300307 s]
/proc/loadavg: 0.89 0.98 0.97 2/56 27277
/proc/meminfo: memFree=362316/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=0.06
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 739 3621 0 0 0 1 3 2 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700224 s]
/proc/loadavg: 0.89 0.98 0.97 2/56 27277
/proc/meminfo: memFree=362316/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=0.06
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 739 3621 0 0 0 1 3 2 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.89 0.98 0.97 2/58 27293
/proc/meminfo: memFree=327820/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=0.06
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 739 3621 0 0 0 1 3 2 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27293] ppid=27277 vsize=52584 CPUtime=1.42
/proc/27293/stat : 27293 (cudf2lp) R 27277 27277 32685 0 -1 4202496 12303 0 0 0 137 5 0 0 20 0 1 0 42318772 53846016 10569 18446744073709551615 4194304 5690517 140736228078576 140736228074744 4960576 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/27293/statm: 13146 10569 160 366 0 12777 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 61796

[startup+3.10032 s]
/proc/loadavg: 0.89 0.98 0.97 2/58 27293
/proc/meminfo: memFree=295828/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=0.06
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 739 3621 0 0 0 1 3 2 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27293] ppid=27277 vsize=93028 CPUtime=3.01
/proc/27293/stat : 27293 (cudf2lp) R 27277 27277 32685 0 -1 4202496 26532 0 0 0 291 10 0 0 20 0 1 0 42318772 95260672 19804 18446744073709551615 4194304 5690517 140736228078576 140736228076216 4960629 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/27293/statm: 23257 19804 160 366 0 22888 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 102240

[startup+6.30026 s]
/proc/loadavg: 0.89 0.98 0.97 2/58 27294
/proc/meminfo: memFree=274996/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=4.46
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 763 42943 0 0 0 1 423 22 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381845520 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27294] ppid=27277 vsize=135920 CPUtime=1.79
/proc/27294/stat : 27294 (gringo) R 27277 27277 32685 0 -1 4202496 34912 0 0 0 171 8 0 0 20 0 1 0 42319218 139182080 29729 18446744073709551615 4194304 6531320 140733755934480 140733755930488 4598430 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/27294/statm: 33980 29729 282 571 0 33401 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 145132

[startup+12.7003 s]
/proc/loadavg: 0.91 0.98 0.97 2/59 27296
/proc/meminfo: memFree=270208/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=3.14
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41188 0 0 0 300 14 0 0 20 0 1 0 42319720 145465344 35024 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35024 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 173308

[startup+25.5003 s]
/proc/loadavg: 0.92 0.98 0.97 2/59 27296
/proc/meminfo: memFree=270208/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=15.87
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41188 0 0 0 1573 14 0 0 20 0 1 0 42319720 145465344 35024 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4407084 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35024 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.2
Current children cumulated vsize (KiB) 173308

[startup+51.1003 s]
/proc/loadavg: 0.95 0.98 0.97 2/59 27296
/proc/meminfo: memFree=269712/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=41.34
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41291 0 0 0 4119 15 0 0 20 0 1 0 42319720 145465344 35127 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35127 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.67
Current children cumulated vsize (KiB) 173308

[startup+102.3 s]
/proc/loadavg: 0.98 0.98 0.97 2/59 27296
/proc/meminfo: memFree=269340/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=92.24
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41372 0 0 0 9208 16 0 0 20 0 1 0 42319720 145465344 35208 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4407098 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35208 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.57
Current children cumulated vsize (KiB) 173308

[startup+162.3 s]
/proc/loadavg: 0.99 0.98 0.97 2/59 27296
/proc/meminfo: memFree=269216/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=151.81
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41372 0 0 0 15162 19 0 0 20 0 1 0 42319720 145465344 35208 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4407221 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35208 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 161.14
Current children cumulated vsize (KiB) 173308

[startup+222.305 s]
/proc/loadavg: 0.99 0.98 0.97 2/63 27311
/proc/meminfo: memFree=267820/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=211.35
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41372 0 0 0 21116 19 0 0 20 0 1 0 42319720 145465344 35208 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4635761 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35208 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.68
Current children cumulated vsize (KiB) 173308

[startup+282.3 s]
/proc/loadavg: 0.99 0.98 0.97 2/63 27311
/proc/meminfo: memFree=267820/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=270.91
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41372 0 0 0 27071 20 0 0 20 0 1 0 42319720 145465344 35208 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35208 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 280.24
Current children cumulated vsize (KiB) 173308



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.3 s]
/proc/loadavg: 0.99 0.98 0.97 2/63 27311
/proc/meminfo: memFree=267820/1022884 swapFree=0/0
[pid=27277] ppid=27276 vsize=9212 CPUtime=9.33
/proc/27277/stat : 27277 (aspcud-full) S 27276 27277 32685 0 -1 4202496 801 153042 0 0 0 1 871 61 20 0 1 0 42318769 9433088 364 18446744073709551615 4194304 5129932 140733381846864 140733381844928 140368392574046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27277/statm: 2303 364 303 229 0 63 0
[pid=27295] ppid=27277 vsize=142056 CPUtime=290.76
/proc/27295/stat : 27295 (clasp) R 27277 27277 32685 0 -1 4202496 41372 0 0 0 29056 20 0 0 20 0 1 0 42319720 145465344 35208 18446744073709551615 4194304 6238623 140734299717232 140734299714256 4662355 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/27295/statm: 35514 35208 263 500 0 35011 0
[pid=27296] ppid=27277 vsize=22040 CPUtime=0
/proc/27296/stat : 27296 (parse.py) S 27277 27277 32685 0 -1 4202496 1309 0 10 0 0 0 0 0 20 0 1 0 42319720 22568960 1128 18446744073709551615 4194304 6642060 140734156075888 140734156074248 139744156895008 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/27296/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 173308

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): 302.365
CPU time (s): 300.171
CPU user time (s): 299.295
CPU system time (s): 0.876054
CPU usage (%): 99.2742
Max. virtual memory (cumulated for all children) (KiB): 474360

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.295
system time used= 0.876054
maximum resident set size= 403260
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 196838
page faults= 11
swaps= 0
block input operations= 69576
block output operations= 51024
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 90
involuntary context switches= 4583

runsolver used 0.636039 second user time and 1.37609 second system time

The end