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/rand30.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand30.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand30.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.92 0.98 1.00 2/59 3887
/proc/meminfo: memFree=439864/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=3152 CPUtime=0
/proc/3887/stat : 3887 (runsolver) R 3886 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120081981 3227648 32 18446744073709551615 134512640 134586868 4292760720 4292758768 4151624752 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.137915 s]
/proc/loadavg: 0.92 0.98 1.00 2/59 3887
/proc/meminfo: memFree=439864/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=0.05
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 734 3619 0 0 0 1 2 2 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200315 s]
/proc/loadavg: 0.92 0.98 1.00 2/59 3887
/proc/meminfo: memFree=439864/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=0.05
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 734 3619 0 0 0 1 2 2 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.30033 s]
/proc/loadavg: 0.92 0.98 1.00 2/59 3887
/proc/meminfo: memFree=439864/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=0.05
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 734 3619 0 0 0 1 2 2 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700223 s]
/proc/loadavg: 0.92 0.98 1.00 2/59 3887
/proc/meminfo: memFree=439864/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=0.05
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 734 3619 0 0 0 1 2 2 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.92 0.98 1.00 2/61 3903
/proc/meminfo: memFree=404996/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=0.05
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 734 3619 0 0 0 1 2 2 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3903] ppid=3887 vsize=57204 CPUtime=1.42
/proc/3903/stat : 3903 (cudf2lp) R 3887 3887 1733 0 -1 4202496 14065 0 0 0 135 7 0 0 20 0 1 0 120081985 58576896 12332 18446744073709551615 4194304 5690517 140733647380624 140733647376824 4363450 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/3903/statm: 14301 12332 160 366 0 13932 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 66416

[startup+3.10032 s]
/proc/loadavg: 0.92 0.98 1.00 2/61 3903
/proc/meminfo: memFree=372880/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=0.05
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 734 3619 0 0 0 1 2 2 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3903] ppid=3887 vsize=93028 CPUtime=3
/proc/3903/stat : 3903 (cudf2lp) R 3887 3887 1733 0 -1 4202496 26558 0 0 0 288 12 0 0 20 0 1 0 120081985 95260672 19831 18446744073709551615 4194304 5690517 140733647380624 140733647378264 4360769 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/3903/statm: 23257 19831 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.30033 s]
/proc/loadavg: 1.01 1.00 1.01 2/61 3904
/proc/meminfo: memFree=380692/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=4.92
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 760 42939 0 0 0 1 463 28 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3904] ppid=3887 vsize=39968 CPUtime=1.29
/proc/3904/stat : 3904 (gringo) R 3887 3887 1733 0 -1 4202496 11219 0 0 0 121 8 0 0 20 0 1 0 120082479 40927232 8086 18446744073709551615 4194304 6531320 140735057002480 140735056999096 5184870 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3904/statm: 9992 8086 259 571 0 9413 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 49180

[startup+12.7003 s]
/proc/loadavg: 1.01 1.00 1.00 2/61 3904
/proc/meminfo: memFree=10132/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=4.92
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 760 42939 0 0 0 1 463 28 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048688 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3904] ppid=3887 vsize=472048 CPUtime=7.5
/proc/3904/stat : 3904 (gringo) R 3887 3887 1733 0 -1 4202496 112240 0 0 0 706 44 0 0 20 0 1 0 120082479 483377152 102310 18446744073709551615 4194304 6531320 140735057002480 140735057000152 5502135 0 0 16781316 16386 0 0 0 17 0 0 0 5 0 0
/proc/3904/statm: 118012 102310 284 571 0 117433 0
Current children cumulated CPU time (s) 12.42
Current children cumulated vsize (KiB) 481260

[startup+25.5004 s]
/proc/loadavg: 1.01 1.00 1.00 2/62 3906
/proc/meminfo: memFree=276772/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=143872 CPUtime=12.34
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 41655 0 1 0 1221 13 0 0 20 0 1 0 120083282 147324928 35466 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4332897 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 35968 35466 263 500 0 35465 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.07
Current children cumulated vsize (KiB) 175124

[startup+51.1004 s]
/proc/loadavg: 1.08 1.01 1.01 2/62 3906
/proc/meminfo: memFree=276648/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=143872 CPUtime=37.68
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 41655 0 1 0 3755 13 0 0 20 0 1 0 120083282 147324928 35466 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 35968 35466 263 500 0 35465 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.41
Current children cumulated vsize (KiB) 175124

[startup+102.3 s]
/proc/loadavg: 1.03 1.01 1.00 2/62 3906
/proc/meminfo: memFree=276152/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=143872 CPUtime=88.39
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 41746 0 1 0 8826 13 0 0 20 0 1 0 120083282 147324928 35557 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4409923 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 35968 35557 263 500 0 35465 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.12
Current children cumulated vsize (KiB) 175124

[startup+162.3 s]
/proc/loadavg: 1.01 1.00 1.00 2/62 3914
/proc/meminfo: memFree=232132/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=187364 CPUtime=147.9
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 52679 0 1 0 14770 20 0 0 20 0 1 0 120083282 191860736 46490 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 46841 46490 263 500 0 46338 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.63
Current children cumulated vsize (KiB) 218616

[startup+222.303 s]
/proc/loadavg: 1.00 1.00 1.00 2/62 3914
/proc/meminfo: memFree=188732/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=235664 CPUtime=207.47
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 63547 0 1 0 20721 26 0 0 20 0 1 0 120083282 241319936 57358 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 58916 57358 263 500 0 58413 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.2
Current children cumulated vsize (KiB) 266916

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 1.00 2/62 3914
/proc/meminfo: memFree=82464/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=341988 CPUtime=267.02
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 90071 0 1 0 26663 39 0 0 20 0 1 0 120083282 350195712 83882 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4407221 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 85497 83882 263 500 0 84994 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.75
Current children cumulated vsize (KiB) 373240



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.7 s]
/proc/loadavg: 1.00 1.00 1.00 2/62 3914
/proc/meminfo: memFree=82464/1022884 swapFree=0/0
[pid=3887] ppid=3886 vsize=9212 CPUtime=12.72
/proc/3887/stat : 3887 (aspcud-full) S 3886 3887 1733 0 -1 4202496 800 155183 0 0 0 1 1185 86 20 0 1 0 120081981 9433088 364 18446744073709551615 4194304 5129932 140734982050032 140734982048096 139781960012894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3887/statm: 2303 364 303 229 0 63 0
[pid=3905] ppid=3887 vsize=341988 CPUtime=287.28
/proc/3905/stat : 3905 (clasp) R 3887 3887 1733 0 -1 4202496 90071 0 1 0 28688 40 0 0 20 0 1 0 120083282 350195712 83882 18446744073709551615 4194304 6238623 140734448943888 140734448940912 4409884 0 0 16781316 18946 0 0 0 17 0 0 0 1 0 0
/proc/3905/statm: 85497 83882 263 500 0 84994 0
[pid=3906] ppid=3887 vsize=22040 CPUtime=0.01
/proc/3906/stat : 3906 (parse.py) S 3887 3887 1733 0 -1 4202496 1317 0 0 0 0 1 0 0 20 0 1 0 120083282 22568960 1127 18446744073709551615 4194304 6642060 140736131741184 140736131739544 140549710329632 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3906/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.01
Current children cumulated vsize (KiB) 373240

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.748
CPU time (s): 300.087
CPU user time (s): 298.767
CPU system time (s): 1.32008
CPU usage (%): 99.1211
Max. virtual memory (cumulated for all children) (KiB): 485360

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.767
system time used= 1.32008
maximum resident set size= 411844
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 247683
page faults= 1
swaps= 0
block input operations= 68552
block output operations= 51664
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 87
involuntary context switches= 34347

runsolver used 0.540033 second user time and 1.28808 second system time

The end