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/rand83.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand83.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand83.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.87 0.97 1.03 2/59 19891
/proc/meminfo: memFree=464536/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=3152 CPUtime=0
/proc/19891/stat : 19891 (runsolver) R 19890 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120077969 3227648 32 18446744073709551615 134512640 134586868 4292973376 4292971424 4151817264 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.204434 s]
/proc/loadavg: 0.87 0.97 1.03 2/59 19891
/proc/meminfo: memFree=464536/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=0.03
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 734 3617 0 0 0 0 2 1 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300331 s]
/proc/loadavg: 0.87 0.97 1.03 2/59 19891
/proc/meminfo: memFree=464536/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=0.03
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 734 3617 0 0 0 0 2 1 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.400307 s]
/proc/loadavg: 0.87 0.97 1.03 2/59 19891
/proc/meminfo: memFree=464536/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=0.03
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 734 3617 0 0 0 0 2 1 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700236 s]
/proc/loadavg: 0.87 0.97 1.03 2/59 19891
/proc/meminfo: memFree=464536/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=0.03
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 734 3617 0 0 0 0 2 1 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.88 0.97 1.03 2/61 19907
/proc/meminfo: memFree=429048/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=0.03
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 734 3617 0 0 0 0 2 1 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19907] ppid=19891 vsize=33064 CPUtime=1.4
/proc/19907/stat : 19907 (cudf2lp) R 19891 19891 1750 0 -1 4202496 9702 0 1 0 133 7 0 0 20 0 1 0 120077971 33857536 7970 18446744073709551615 4194304 5690517 140733214985504 140733214983144 4360758 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/19907/statm: 8266 7970 160 366 0 7897 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 42276

[startup+3.10031 s]
/proc/loadavg: 0.88 0.97 1.03 2/61 19907
/proc/meminfo: memFree=397180/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=0.03
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 734 3617 0 0 0 0 2 1 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19907] ppid=19891 vsize=93028 CPUtime=2.98
/proc/19907/stat : 19907 (cudf2lp) R 19891 19891 1750 0 -1 4202496 26440 0 1 0 286 12 0 0 20 0 1 0 120077971 95260672 19714 18446744073709551615 4194304 5690517 140733214985504 140733214983144 4960847 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/19907/statm: 23257 19714 160 366 0 22888 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.89 0.97 1.03 2/61 19908
/proc/meminfo: memFree=405612/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=4.99
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 760 42937 0 1 0 0 473 26 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011936 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19908] ppid=19891 vsize=37108 CPUtime=1.19
/proc/19908/stat : 19908 (gringo) R 19891 19891 1750 0 -1 4202496 10416 0 0 0 114 5 0 0 20 0 1 0 120078478 37998592 7283 18446744073709551615 4194304 6531320 140733664096160 140733664092776 4372240 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19908/statm: 9277 7283 259 571 0 8698 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 46320

[startup+12.7003 s]
/proc/loadavg: 0.97 0.99 1.04 2/62 19910
/proc/meminfo: memFree=418012/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=154440 CPUtime=0.55
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 43390 0 0 0 42 13 0 0 20 0 1 0 120079182 158146560 37154 18446744073709551615 4194304 6238623 140733196345856 140733196343416 4778657 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 38610 37154 211 500 0 38107 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 185692

[startup+25.5032 s]
/proc/loadavg: 0.98 0.99 1.03 2/62 19910
/proc/meminfo: memFree=287192/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=151660 CPUtime=13.26
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 45840 0 0 0 1312 14 0 0 20 0 1 0 120079182 155299840 37487 18446744073709551615 4194304 6238623 140733196345856 140733196342880 4688021 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 37915 37487 263 500 0 37412 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.18
Current children cumulated vsize (KiB) 182912

[startup+51.1003 s]
/proc/loadavg: 1.06 1.00 1.04 2/62 19910
/proc/meminfo: memFree=287192/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=151660 CPUtime=38.67
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 45840 0 0 0 3853 14 0 0 20 0 1 0 120079182 155299840 37487 18446744073709551615 4194304 6238623 140733196345856 140733196342880 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 37915 37487 263 500 0 37412 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.59
Current children cumulated vsize (KiB) 182912

[startup+102.3 s]
/proc/loadavg: 1.02 1.00 1.03 2/62 19910
/proc/meminfo: memFree=286820/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=151660 CPUtime=89.5
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 45942 0 0 0 8936 14 0 0 20 0 1 0 120079182 155299840 37589 18446744073709551615 4194304 6238623 140733196345856 140733196342880 4670149 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 37915 37589 263 500 0 37412 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.42
Current children cumulated vsize (KiB) 182912

[startup+162.3 s]
/proc/loadavg: 1.01 1.00 1.03 2/62 19910
/proc/meminfo: memFree=226804/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=216216 CPUtime=149.06
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 60968 0 0 0 14890 16 0 0 20 0 1 0 120079182 221405184 52615 18446744073709551615 4194304 6238623 140733196345856 140733196342880 4669535 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 54054 52615 263 500 0 53551 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 160.98
Current children cumulated vsize (KiB) 247468

[startup+222.3 s]
/proc/loadavg: 1.03 1.01 1.03 2/62 19910
/proc/meminfo: memFree=97596/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=345644 CPUtime=208.63
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 93214 0 0 0 20830 33 0 0 20 0 1 0 120079182 353939456 84861 18446744073709551615 4194304 6238623 140733196345856 140733196342408 4635054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 86411 84861 263 500 0 85908 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 220.55
Current children cumulated vsize (KiB) 376896

[startup+282.3 s]
/proc/loadavg: 1.01 1.01 1.02 2/62 19910
/proc/meminfo: memFree=78624/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=364276 CPUtime=268.18
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 97971 0 0 0 26784 34 0 0 20 0 1 0 120079182 373018624 89618 18446744073709551615 4194304 6238623 140733196345856 140733196342880 4422144 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 91069 89618 263 500 0 90566 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 280.1
Current children cumulated vsize (KiB) 395528



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.4 s]
/proc/loadavg: 1.01 1.00 1.02 2/62 19910
/proc/meminfo: memFree=63372/1022884 swapFree=0/0
[pid=19891] ppid=19890 vsize=9212 CPUtime=11.92
/proc/19891/stat : 19891 (aspcud-full) S 19890 19891 1750 0 -1 4202496 800 159756 0 1 0 0 1118 74 20 0 1 0 120077969 9433088 364 18446744073709551615 4194304 5129932 140736447013280 140736447011344 140620985640030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19891/statm: 2303 364 303 229 0 63 0
[pid=19909] ppid=19891 vsize=379492 CPUtime=288.15
/proc/19909/stat : 19909 (clasp) R 19891 19891 1750 0 -1 4202496 101772 0 0 0 28779 36 0 0 20 0 1 0 120079182 388599808 93419 18446744073709551615 4194304 6238623 140733196345856 140733196342880 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19909/statm: 94873 93419 263 500 0 94370 0
[pid=19910] ppid=19891 vsize=22040 CPUtime=0
/proc/19910/stat : 19910 (parse.py) S 19891 19891 1750 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 120079182 22568960 1129 18446744073709551615 4194304 6642060 140735089058256 140735089056616 139750110566176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19910/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 410744

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.451
CPU time (s): 300.147
CPU user time (s): 299.007
CPU system time (s): 1.14007
CPU usage (%): 99.2381
Max. virtual memory (cumulated for all children) (KiB): 499860

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.007
system time used= 1.14007
maximum resident set size= 430144
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263951
page faults= 1
swaps= 0
block input operations= 68560
block output operations= 54048
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 81
involuntary context switches= 34315

runsolver used 0.588036 second user time and 1.00406 second system time

The end