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/install/rand717.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand717.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand717.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.88 1.00 1.11 2/59 19839
/proc/meminfo: memFree=323240/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=3152 CPUtime=0
/proc/19839/stat : 19839 (runsolver) R 19838 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120014127 3227648 32 18446744073709551615 134512640 134586868 4288859664 4288857712 4151710768 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.195318 s]
/proc/loadavg: 0.88 1.00 1.11 2/59 19839
/proc/meminfo: memFree=323240/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=0.03
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 733 3622 0 0 0 0 2 1 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.20031 s]
/proc/loadavg: 0.88 1.00 1.11 2/59 19839
/proc/meminfo: memFree=323240/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=0.03
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 733 3622 0 0 0 0 2 1 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.30028 s]
/proc/loadavg: 0.88 1.00 1.11 2/59 19839
/proc/meminfo: memFree=323240/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=0.03
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 733 3622 0 0 0 0 2 1 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700209 s]
/proc/loadavg: 0.88 1.00 1.11 2/59 19839
/proc/meminfo: memFree=323240/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=0.03
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 733 3622 0 0 0 0 2 1 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 0.88 1.00 1.11 2/61 19855
/proc/meminfo: memFree=265928/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=0.03
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 733 3622 0 0 0 0 2 1 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19855] ppid=19839 vsize=50676 CPUtime=1.44
/proc/19855/stat : 19855 (cudf2lp) R 19839 19839 1750 0 -1 4202496 15011 0 0 0 138 6 0 0 20 0 1 0 120014130 51892224 11613 18446744073709551615 4194304 5690517 140736231185184 140736231182824 4378195 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/19855/statm: 12669 11613 160 366 0 12300 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 59888

[startup+3.10027 s]
/proc/loadavg: 0.88 1.00 1.11 2/61 19855
/proc/meminfo: memFree=213972/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=0.03
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 733 3622 0 0 0 0 2 1 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19855] ppid=19839 vsize=114764 CPUtime=3
/proc/19855/stat : 19855 (cudf2lp) R 19839 19839 1750 0 -1 4202496 39319 0 0 0 286 14 0 0 20 0 1 0 120014130 117518336 28363 18446744073709551615 4194304 5690517 140736231185184 140736231182184 4934595 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/19855/statm: 28691 28363 174 366 0 28322 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 123976

[startup+6.30025 s]
/proc/loadavg: 0.89 1.00 1.11 2/61 19856
/proc/meminfo: memFree=129844/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=3.31
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 759 42943 0 0 0 0 312 19 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334316224 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19856] ppid=19839 vsize=267804 CPUtime=2.9
/proc/19856/stat : 19856 (gringo) R 19839 19839 1750 0 -1 4202496 65124 0 0 0 269 21 0 0 20 0 1 0 120014464 274231296 55845 18446744073709551615 4194304 6531320 140734725545872 140734725542216 5511412 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19856/statm: 66951 55845 283 571 0 66372 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 277016

[startup+12.7003 s]
/proc/loadavg: 0.90 1.00 1.10 2/62 19858
/proc/meminfo: memFree=282456/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=148436 CPUtime=3.98
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 44956 0 0 0 388 10 0 0 20 0 1 0 120014994 151998464 36651 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4662388 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 37109 36651 263 500 0 36606 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.43
Current children cumulated vsize (KiB) 179688

[startup+25.5003 s]
/proc/loadavg: 0.92 1.00 1.10 2/62 19858
/proc/meminfo: memFree=282332/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=148436 CPUtime=16.68
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 44956 0 0 0 1658 10 0 0 20 0 1 0 120014994 151998464 36651 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4669541 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 37109 36651 263 500 0 36606 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.13
Current children cumulated vsize (KiB) 179688

[startup+51.1003 s]
/proc/loadavg: 0.95 1.00 1.10 2/62 19858
/proc/meminfo: memFree=282332/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=148436 CPUtime=42.09
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 44956 0 0 0 4199 10 0 0 20 0 1 0 120014994 151998464 36651 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4422093 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 37109 36651 263 500 0 36606 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.54
Current children cumulated vsize (KiB) 179688

[startup+102.3 s]
/proc/loadavg: 0.98 1.00 1.09 2/62 19858
/proc/meminfo: memFree=164036/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=266672 CPUtime=92.92
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 74507 0 0 0 9270 22 0 0 20 0 1 0 120014994 273072128 66202 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4332525 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 66668 66202 263 500 0 66165 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.37
Current children cumulated vsize (KiB) 297924

[startup+162.3 s]
/proc/loadavg: 0.99 1.00 1.08 2/62 19858
/proc/meminfo: memFree=121752/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=308848 CPUtime=152.48
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 85045 0 0 0 15218 30 0 0 20 0 1 0 120014994 316260352 76740 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 77212 76740 263 500 0 76709 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.93
Current children cumulated vsize (KiB) 340100

[startup+222.303 s]
/proc/loadavg: 0.99 1.00 1.08 2/62 19858
/proc/meminfo: memFree=79964/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=350544 CPUtime=212.03
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 95456 0 0 0 21170 33 0 0 20 0 1 0 120014994 358957056 87151 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 87636 87151 263 500 0 87133 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.48
Current children cumulated vsize (KiB) 381796

[startup+282.3 s]
/proc/loadavg: 0.99 1.00 1.07 2/62 19858
/proc/meminfo: memFree=73640/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=357056 CPUtime=271.58
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 97072 0 0 0 27124 34 0 0 20 0 1 0 120014994 365625344 88767 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4425984 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 89264 88767 263 500 0 88761 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 280.03
Current children cumulated vsize (KiB) 388308



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.5 s]
/proc/loadavg: 0.99 1.00 1.07 2/62 19858
/proc/meminfo: memFree=73516/1022884 swapFree=0/0
[pid=19839] ppid=19838 vsize=9212 CPUtime=8.44
/proc/19839/stat : 19839 (aspcud-full) S 19838 19839 1750 0 -1 4202496 799 157845 0 0 0 0 779 65 20 0 1 0 120014127 9433088 364 18446744073709551615 4194304 5129932 140735334317568 140735334315632 140083544638558 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19839/statm: 2303 364 303 229 0 63 0
[pid=19857] ppid=19839 vsize=357056 CPUtime=291.64
/proc/19857/stat : 19857 (clasp) R 19839 19839 1750 0 -1 4202496 97073 0 0 0 29130 34 0 0 20 0 1 0 120014994 365625344 88768 18446744073709551615 4194304 6238623 140736150785216 140736150782240 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19857/statm: 89264 88768 263 500 0 88761 0
[pid=19858] ppid=19839 vsize=22040 CPUtime=0.01
/proc/19858/stat : 19858 (parse.py) S 19839 19839 1750 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120014994 22568960 1127 18446744073709551615 4194304 6642060 140733385811056 140733385809416 139988251981600 0 0 16777220 20994 0 0 0 17 0 0 0 17 0 0
/proc/19858/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 388308

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.587
CPU time (s): 300.159
CPU user time (s): 299.127
CPU system time (s): 1.03206
CPU usage (%): 99.1975
Max. virtual memory (cumulated for all children) (KiB): 492432

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.127
system time used= 1.03206
maximum resident set size= 422476
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 257336
page faults= 14
swaps= 0
block input operations= 69864
block output operations= 53016
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 34423

runsolver used 0.528033 second user time and 1.07607 second system time

The end