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/rand446.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand446.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand446.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.95 1.00 1.03 2/59 3861
/proc/meminfo: memFree=449412/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=1068 CPUtime=0
/proc/3861/stat : 3861 (aspcud-full) D 3860 3861 1733 0 -1 4194304 76 0 0 0 0 0 0 0 20 0 1 0 120049672 1093632 1 18446744073709551615 0 0 140733484448727 4287546032 4151632944 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 267 1 0 0 0 28 0

[startup+0.138108 s]
/proc/loadavg: 0.95 1.00 1.03 2/59 3861
/proc/meminfo: memFree=449412/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=0.05
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 733 3611 2 7 0 0 3 2 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200352 s]
/proc/loadavg: 0.95 1.00 1.03 2/59 3861
/proc/meminfo: memFree=449412/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=0.05
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 733 3611 2 7 0 0 3 2 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300303 s]
/proc/loadavg: 0.95 1.00 1.03 2/59 3861
/proc/meminfo: memFree=449412/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=0.05
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 733 3611 2 7 0 0 3 2 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 0.95 1.00 1.03 2/59 3861
/proc/meminfo: memFree=449412/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=0.05
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 733 3611 2 7 0 0 3 2 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 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.95 1.00 1.03 2/61 3877
/proc/meminfo: memFree=415412/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=0.05
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 733 3611 2 7 0 0 3 2 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3877] ppid=3861 vsize=33064 CPUtime=1.36
/proc/3877/stat : 3877 (cudf2lp) R 3861 3861 1733 0 -1 4202496 9643 0 0 0 130 6 0 0 20 0 1 0 120049682 33857536 7910 18446744073709551615 4194304 5690517 140734885237504 140734885234872 4293191 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/3877/statm: 8266 7910 160 366 0 7897 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 42276

[startup+3.10032 s]
/proc/loadavg: 0.95 1.00 1.03 2/61 3877
/proc/meminfo: memFree=383420/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=0.05
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 733 3611 2 7 0 0 3 2 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3877] ppid=3861 vsize=93028 CPUtime=2.94
/proc/3877/stat : 3877 (cudf2lp) R 3861 3861 1733 0 -1 4202496 26452 0 0 0 278 16 0 0 20 0 1 0 120049682 95260672 19725 18446744073709551615 4194304 5690517 140734885237504 140734885235144 4328395 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/3877/statm: 23257 19725 160 366 0 22888 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.96 1.00 1.03 2/61 3878
/proc/meminfo: memFree=390860/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=4.92
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 759 42932 2 7 0 0 464 28 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3878] ppid=3861 vsize=39872 CPUtime=1.23
/proc/3878/stat : 3878 (gringo) R 3861 3861 1733 0 -1 4202496 11081 0 0 0 113 10 0 0 20 0 1 0 120050177 40828928 7948 18446744073709551615 4194304 6531320 140735384588224 140735384584408 4340986 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3878/statm: 9968 7948 259 571 0 9389 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 49084

[startup+12.7003 s]
/proc/loadavg: 0.96 1.00 1.03 2/61 3878
/proc/meminfo: memFree=10132/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=4.92
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 759 42932 2 7 0 0 464 28 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484440272 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3878] ppid=3861 vsize=429308 CPUtime=7.52
/proc/3878/stat : 3878 (gringo) R 3861 3861 1733 0 -1 4202496 110378 0 0 0 698 54 0 0 20 0 1 0 120050177 439611392 92909 18446744073709551615 4194304 6531320 140735384588224 140735384585912 5502363 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3878/statm: 107327 92909 284 571 0 106748 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 438520

[startup+25.5004 s]
/proc/loadavg: 1.04 1.01 1.03 2/62 3880
/proc/meminfo: memFree=270820/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=142548 CPUtime=12.45
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 41596 0 0 0 1231 14 0 0 20 0 1 0 120050961 145969152 35123 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4687670 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 35637 35123 263 500 0 35134 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.11
Current children cumulated vsize (KiB) 173800

[startup+51.1004 s]
/proc/loadavg: 1.02 1.01 1.03 2/62 3880
/proc/meminfo: memFree=270076/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=142548 CPUtime=37.8
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 41775 0 0 0 3765 15 0 0 20 0 1 0 120050961 145969152 35302 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 35637 35302 263 500 0 35134 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.46
Current children cumulated vsize (KiB) 173800

[startup+102.3 s]
/proc/loadavg: 1.01 1.00 1.03 2/62 3880
/proc/meminfo: memFree=269952/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=142548 CPUtime=88.49
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 41775 0 0 0 8834 15 0 0 20 0 1 0 120050961 145969152 35302 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4421810 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 35637 35302 263 500 0 35134 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.15
Current children cumulated vsize (KiB) 173800

[startup+162.3 s]
/proc/loadavg: 1.00 1.00 1.02 2/62 3880
/proc/meminfo: memFree=255072/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=157436 CPUtime=148.02
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 45494 0 0 0 14782 20 0 0 20 0 1 0 120050961 161214464 39021 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4306159 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 39359 39021 263 500 0 38856 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.68
Current children cumulated vsize (KiB) 188688

[startup+222.303 s]
/proc/loadavg: 1.00 1.00 1.02 2/62 3880
/proc/meminfo: memFree=228040/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=184652 CPUtime=207.57
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 52301 0 0 0 20733 24 0 0 20 0 1 0 120050961 189083648 45828 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4407044 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 46163 45828 263 500 0 45660 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.23
Current children cumulated vsize (KiB) 215904

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 1.01 2/62 3880
/proc/meminfo: memFree=172116/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=242464 CPUtime=267.13
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 66257 0 0 0 26681 32 0 0 20 0 1 0 120050961 248283136 59784 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 60616 59784 263 500 0 60113 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.79
Current children cumulated vsize (KiB) 273716



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.7 s]
/proc/loadavg: 1.07 1.02 1.01 2/62 3880
/proc/meminfo: memFree=172116/1022884 swapFree=0/0
[pid=3861] ppid=3860 vsize=9212 CPUtime=12.64
/proc/3861/stat : 3861 (aspcud-full) S 3860 3861 1733 0 -1 4202496 799 153314 2 7 0 0 1168 96 20 0 1 0 120049672 9433088 365 18446744073709551615 4194304 5129932 140733484441616 140733484439680 139930498184286 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/3861/statm: 2303 365 303 229 0 63 0
[pid=3879] ppid=3861 vsize=242464 CPUtime=287.38
/proc/3879/stat : 3879 (clasp) R 3861 3861 1733 0 -1 4202496 66257 0 0 0 28706 32 0 0 20 0 1 0 120050961 248283136 59784 18446744073709551615 4194304 6238623 140734704418368 140734704415392 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3879/statm: 60616 59784 263 500 0 60113 0
[pid=3880] ppid=3861 vsize=22040 CPUtime=0.02
/proc/3880/stat : 3880 (parse.py) S 3861 3861 1733 0 -1 4202496 1318 0 0 0 0 2 0 0 20 0 1 0 120050961 22568960 1128 18446744073709551615 4194304 6642060 140734477731760 140734477730120 139697698740000 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3880/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 273716

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.734
CPU time (s): 300.095
CPU user time (s): 298.767
CPU system time (s): 1.32808
CPU usage (%): 99.1281
Max. virtual memory (cumulated for all children) (KiB): 475392

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.767
system time used= 1.32808
maximum resident set size= 404396
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 222002
page faults= 9
swaps= 0
block input operations= 68952
block output operations= 51184
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 93
involuntary context switches= 34323

runsolver used 0.516032 second user time and 1.32008 second system time

The end