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/upgrade/difficult/rand208.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand208.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand208.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.94 0.96 2/59 20956
/proc/meminfo: memFree=445352/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=3152 CPUtime=0
/proc/20956/stat : 20956 (runsolver) R 20955 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120488625 3227648 32 18446744073709551615 134512640 134586868 4291856368 4291854416 4152198192 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.184674 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 20956
/proc/meminfo: memFree=445352/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=0.03
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 733 3623 0 0 0 0 2 1 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200261 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 20956
/proc/meminfo: memFree=445352/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=0.03
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 733 3623 0 0 0 0 2 1 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300251 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 20956
/proc/meminfo: memFree=445352/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=0.03
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 733 3623 0 0 0 0 2 1 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700193 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 20956
/proc/meminfo: memFree=445352/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=0.03
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 733 3623 0 0 0 0 2 1 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50024 s]
/proc/loadavg: 0.87 0.94 0.96 2/61 20972
/proc/meminfo: memFree=388040/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=0.03
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 733 3623 0 0 0 0 2 1 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20972] ppid=20956 vsize=50676 CPUtime=1.4
/proc/20972/stat : 20972 (cudf2lp) R 20956 20956 1750 0 -1 4202496 15028 0 1 0 130 10 0 0 20 0 1 0 120488627 51892224 11631 18446744073709551615 4194304 5690517 140737285422752 140737285420392 4293666 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/20972/statm: 12669 11631 160 366 0 12300 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 59888

[startup+3.10026 s]
/proc/loadavg: 0.88 0.94 0.96 2/61 20972
/proc/meminfo: memFree=335340/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=0.03
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 733 3623 0 0 0 0 2 1 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20972] ppid=20956 vsize=114764 CPUtime=2.99
/proc/20972/stat : 20972 (cudf2lp) R 20956 20956 1750 0 -1 4202496 39320 0 1 0 279 20 0 0 20 0 1 0 120488627 117518336 28365 18446744073709551615 4194304 5690517 140737285422752 140737285420072 4265433 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/20972/statm: 28691 28365 174 366 0 28322 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 123976

[startup+6.30026 s]
/proc/loadavg: 0.88 0.94 0.96 2/61 20976
/proc/meminfo: memFree=249904/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=3.28
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 757 42945 0 1 0 0 302 26 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990442240 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20974] ppid=20956 vsize=267000 CPUtime=2.91
/proc/20974/stat : 20974 (gringo) R 20956 20956 1750 0 -1 4202496 65207 0 0 0 269 22 0 0 20 0 1 0 120488961 273408000 55928 18446744073709551615 4194304 6531320 140734993319376 140734993315992 5059328 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20974/statm: 66750 55928 283 571 0 66171 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 276212

[startup+12.7004 s]
/proc/loadavg: 0.90 0.94 0.96 2/62 20978
/proc/meminfo: memFree=272092/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=142224 CPUtime=4.19
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 41227 0 0 0 408 11 0 0 20 0 1 0 120489469 145637376 35057 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4748034 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 35556 35057 263 500 0 35053 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 173476

[startup+25.5004 s]
/proc/loadavg: 0.91 0.94 0.96 2/62 20978
/proc/meminfo: memFree=271596/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=142224 CPUtime=16.86
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 41327 0 0 0 1675 11 0 0 20 0 1 0 120489469 145637376 35157 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 35556 35157 263 500 0 35053 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 173476

[startup+51.1004 s]
/proc/loadavg: 0.94 0.95 0.96 2/62 20978
/proc/meminfo: memFree=271224/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=142224 CPUtime=42.21
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 41407 0 0 0 4209 12 0 0 20 0 1 0 120489469 145637376 35237 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 35556 35237 263 500 0 35053 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.51
Current children cumulated vsize (KiB) 173476

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.96 2/62 20978
/proc/meminfo: memFree=271100/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=142224 CPUtime=92.92
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 41407 0 0 0 9280 12 0 0 20 0 1 0 120489469 145637376 35237 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 35556 35237 263 500 0 35053 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.22
Current children cumulated vsize (KiB) 173476

[startup+162.3 s]
/proc/loadavg: 1.04 0.97 0.96 2/62 20978
/proc/meminfo: memFree=261676/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=151596 CPUtime=152.34
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 43767 0 0 0 15220 14 0 0 20 0 1 0 120489469 155234304 37597 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 37899 37597 263 500 0 37396 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.64
Current children cumulated vsize (KiB) 182848

[startup+222.305 s]
/proc/loadavg: 1.01 0.97 0.96 2/62 20978
/proc/meminfo: memFree=256840/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=156348 CPUtime=211.77
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 44980 0 0 0 21160 17 0 0 20 0 1 0 120489469 160100352 38810 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4422186 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 39087 38810 263 500 0 38584 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.07
Current children cumulated vsize (KiB) 187600

[startup+282.3 s]
/proc/loadavg: 1.06 0.99 0.97 2/62 20978
/proc/meminfo: memFree=256840/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=156348 CPUtime=271.32
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 44980 0 0 0 27114 18 0 0 20 0 1 0 120489469 160100352 38810 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 39087 38810 263 500 0 38584 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.62
Current children cumulated vsize (KiB) 187600



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.9 s]
/proc/loadavg: 1.04 0.99 0.97 2/62 20978
/proc/meminfo: memFree=239728/1022884 swapFree=0/0
[pid=20956] ppid=20955 vsize=9212 CPUtime=8.29
/proc/20956/stat : 20956 (aspcud-full) S 20955 20956 1750 0 -1 4202496 794 153313 0 1 0 0 757 72 20 0 1 0 120488625 9433088 364 18446744073709551615 4194304 5129932 140735990443584 140735990441648 139909393294430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20956/statm: 2303 364 303 229 0 63 0
[pid=20977] ppid=20956 vsize=173676 CPUtime=291.77
/proc/20977/stat : 20977 (clasp) R 20956 20956 1750 0 -1 4202496 49263 0 0 0 29157 20 0 0 20 0 1 0 120489469 177844224 43093 18446744073709551615 4194304 6238623 140737229082672 140737229079696 4687693 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20977/statm: 43419 43093 263 500 0 42916 0
[pid=20978] ppid=20956 vsize=22040 CPUtime=0.01
/proc/20978/stat : 20978 (parse.py) S 20956 20956 1750 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120489469 22568960 1128 18446744073709551615 4194304 6642060 140737349114576 140737349112936 140580704040736 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/20978/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 204928

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.936
CPU time (s): 300.139
CPU user time (s): 299.175
CPU system time (s): 0.96406
CPU usage (%): 99.0767
Max. virtual memory (cumulated for all children) (KiB): 474688

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.175
system time used= 0.96406
maximum resident set size= 404340
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 205002
page faults= 1
swaps= 0
block input operations= 68560
block output operations= 51160
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 80
involuntary context switches= 34264

runsolver used 0.520032 second user time and 1.47209 second system time

The end