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/rand242.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand242.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand242.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: 1.04 1.05 1.02 2/60 25037
/proc/meminfo: memFree=623116/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=3152 CPUtime=0
/proc/25037/stat : 25037 (runsolver) R 25036 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41737311 3227648 33 18446744073709551615 134512640 134586868 4287766944 4287764992 4152112176 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/25037/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.111338 s]
/proc/loadavg: 1.04 1.05 1.02 2/60 25037
/proc/meminfo: memFree=623116/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9204 CPUtime=0.01
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 557 1145 3 2 0 0 0 1 20 0 1 0 41737311 9424896 350 18446744073709551615 4194304 5129932 140735431400896 140735431398416 140405343880286 0 65536 16781316 65538 0 0 0 17 0 0 0 3 0 0
/proc/25037/statm: 2301 350 291 229 0 61 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 9204

[startup+0.200361 s]
/proc/loadavg: 1.04 1.05 1.02 2/60 25037
/proc/meminfo: memFree=623116/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=0.05
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 729 3615 4 9 0 0 3 2 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300307 s]
/proc/loadavg: 1.04 1.05 1.02 2/60 25037
/proc/meminfo: memFree=623116/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=0.05
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 729 3615 4 9 0 0 3 2 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700239 s]
/proc/loadavg: 1.04 1.05 1.02 2/60 25037
/proc/meminfo: memFree=623116/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=0.05
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 729 3615 4 9 0 0 3 2 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/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: 1.04 1.05 1.02 2/62 25053
/proc/meminfo: memFree=589116/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=0.05
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 729 3615 4 9 0 0 3 2 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25053] ppid=25037 vsize=28956 CPUtime=1.18
/proc/25053/stat : 25053 (cudf2lp) R 25037 25037 32685 0 -1 4202496 8475 0 16 0 116 2 0 0 20 0 1 0 41737330 29650944 6758 18446744073709551615 4194304 5690517 140735186102208 140735186099864 4349296 0 0 16781316 0 0 0 0 17 0 0 0 11 0 0
/proc/25053/statm: 7239 6758 159 366 0 6870 0
Current children cumulated CPU time (s) 1.23
Current children cumulated vsize (KiB) 38168

[startup+3.10031 s]
/proc/loadavg: 1.04 1.05 1.02 2/62 25053
/proc/meminfo: memFree=558364/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=0.05
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 729 3615 4 9 0 0 3 2 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25053] ppid=25037 vsize=99216 CPUtime=2.75
/proc/25053/stat : 25053 (cudf2lp) R 25037 25037 32685 0 -1 4202496 23635 0 16 0 264 11 0 0 20 0 1 0 41737330 101597184 20253 18446744073709551615 4194304 5690517 140735186102208 140735186098408 4962292 0 0 16781316 0 0 0 0 17 0 0 0 13 0 0
/proc/25053/statm: 24804 20253 160 366 0 24435 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 108428

[startup+6.30033 s]
/proc/loadavg: 1.04 1.05 1.02 2/62 25054
/proc/meminfo: memFree=565184/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=4.84
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 755 42919 4 25 0 0 459 25 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25054] ppid=25037 vsize=31740 CPUtime=1.08
/proc/25054/stat : 25054 (gringo) R 25037 25037 32685 0 -1 4202496 8965 0 22 0 99 9 0 0 20 0 1 0 41737826 32501760 6879 18446744073709551615 4194304 6531320 140734332455680 140734332451496 4636336 0 0 16781316 16386 0 0 0 17 0 0 0 5 0 0
/proc/25054/statm: 7935 6879 259 571 0 7356 0
Current children cumulated CPU time (s) 5.92
Current children cumulated vsize (KiB) 40952

[startup+12.7003 s]
/proc/loadavg: 1.03 1.05 1.02 2/62 25054
/proc/meminfo: memFree=177808/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=4.84
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 755 42919 4 25 0 0 459 25 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431399552 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25054] ppid=25037 vsize=477536 CPUtime=7.43
/proc/25054/stat : 25054 (gringo) R 25037 25037 32685 0 -1 4202496 112852 0 23 0 687 56 0 0 20 0 1 0 41737826 488996864 103596 18446744073709551615 4194304 6531320 140734332455680 140734332452488 4344279 0 0 16781316 16386 0 0 0 17 0 0 0 5 0 0
/proc/25054/statm: 119384 103596 284 571 0 118805 0
Current children cumulated CPU time (s) 12.27
Current children cumulated vsize (KiB) 486748

[startup+25.5004 s]
/proc/loadavg: 1.02 1.05 1.02 2/63 25056
/proc/meminfo: memFree=411292/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=144860 CPUtime=12.14
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 41913 0 22 0 1202 12 0 0 20 0 1 0 41738627 148336640 35728 18446744073709551615 4194304 6238623 140736321436128 140736321433152 4355569 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 36215 35728 263 500 0 35712 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.9
Current children cumulated vsize (KiB) 176112

[startup+51.1004 s]
/proc/loadavg: 1.02 1.04 1.02 2/63 25056
/proc/meminfo: memFree=411168/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=144860 CPUtime=37.54
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 41913 0 22 0 3741 13 0 0 20 0 1 0 41738627 148336640 35728 18446744073709551615 4194304 6238623 140736321436128 140736321433152 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 36215 35728 263 500 0 35712 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.3
Current children cumulated vsize (KiB) 176112

[startup+102.3 s]
/proc/loadavg: 1.00 1.03 1.01 2/63 25056
/proc/meminfo: memFree=410796/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=144860 CPUtime=88.37
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 41996 0 22 0 8823 14 0 0 20 0 1 0 41738627 148336640 35811 18446744073709551615 4194304 6238623 140736321436128 140736321433152 4406960 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 36215 35811 263 500 0 35712 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.13
Current children cumulated vsize (KiB) 176112

[startup+162.3 s]
/proc/loadavg: 1.00 1.02 1.01 2/63 25056
/proc/meminfo: memFree=399016/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=156720 CPUtime=147.95
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 45006 0 22 0 14778 17 0 0 20 0 1 0 41738627 160481280 38821 18446744073709551615 4194304 6238623 140736321436128 140736321432680 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 39180 38821 263 500 0 38677 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.71
Current children cumulated vsize (KiB) 187972

[startup+222.307 s]
/proc/loadavg: 1.08 1.03 1.01 2/68 25167
/proc/meminfo: memFree=308936/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=181136 CPUtime=205.55
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 51101 0 22 0 20532 23 0 0 20 0 1 0 41738627 185483264 44916 18446744073709551615 4194304 6238623 140736321436128 140736321433152 4407211 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 45284 44916 263 500 0 44781 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 218.31
Current children cumulated vsize (KiB) 212388

[startup+282.3 s]
/proc/loadavg: 1.09 1.05 1.01 2/63 25304
/proc/meminfo: memFree=142092/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=207832 CPUtime=262.25
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 57786 0 22 0 26194 31 0 0 20 0 1 0 41738627 212819968 51601 18446744073709551615 4194304 6238623 140736321436128 140736321433152 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 51958 51601 263 500 0 51455 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 275.01
Current children cumulated vsize (KiB) 239084



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+307.5 s]
/proc/loadavg: 1.06 1.05 1.01 2/63 25304
/proc/meminfo: memFree=130560/1022884 swapFree=0/0
[pid=25037] ppid=25036 vsize=9212 CPUtime=12.75
/proc/25037/stat : 25037 (aspcud-full) S 25036 25037 32685 0 -1 4202496 795 155775 4 48 0 0 1179 96 20 0 1 0 41737311 9433088 364 18446744073709551615 4194304 5129932 140735431400896 140735431398960 140405343880286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 4 0 0
/proc/25037/statm: 2303 364 303 229 0 63 0
[pid=25055] ppid=25037 vsize=219496 CPUtime=287.31
/proc/25055/stat : 25055 (clasp) R 25037 25037 32685 0 -1 4202496 60677 0 22 0 28698 33 0 0 20 0 1 0 41738627 224763904 54492 18446744073709551615 4194304 6238623 140736321436128 140736321433152 4371976 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/25055/statm: 54874 54492 263 500 0 54371 0
[pid=25056] ppid=25037 vsize=22040 CPUtime=0.01
/proc/25056/stat : 25056 (parse.py) S 25037 25037 32685 0 -1 4202496 1317 0 1 0 0 1 0 0 20 0 1 0 41738627 22568960 1128 18446744073709551615 4194304 6642060 140735551606112 140735551604472 140172318181152 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25056/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 250748

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): 307.553
CPU time (s): 300.155
CPU user time (s): 298.799
CPU system time (s): 1.35608
CPU usage (%): 97.5943
Max. virtual memory (cumulated for all children) (KiB): 486748

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.799
system time used= 1.35608
maximum resident set size= 414384
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 218873
page faults= 76
swaps= 0
block input operations= 80088
block output operations= 51928
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 194
involuntary context switches= 8938

runsolver used 0.676042 second user time and 1.28408 second system time

The end