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/easy/rand268.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand268.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand268.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: 1.03 0.99 0.97 2/59 20567
/proc/meminfo: memFree=512784/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9204 CPUtime=0
/proc/20567/stat : 20567 (aspcud-full) R 20566 20567 1750 0 -1 4202496 423 0 0 0 0 0 0 0 20 0 1 0 120327995 9424896 331 18446744073709551615 4194304 5129932 140735584370704 140735584367856 140320501201605 0 65538 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2301 331 272 229 0 61 0

[startup+0.139128 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 20567
/proc/meminfo: memFree=512784/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=0.03
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 733 3615 0 0 0 0 2 1 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200323 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 20567
/proc/meminfo: memFree=512784/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=0.03
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 733 3615 0 0 0 0 2 1 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300296 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 20567
/proc/meminfo: memFree=512784/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=0.03
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 733 3615 0 0 0 0 2 1 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 20567
/proc/meminfo: memFree=512784/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=0.03
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 733 3615 0 0 0 0 2 1 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.03 0.99 0.97 1/61 20583
/proc/meminfo: memFree=478164/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=0.03
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 733 3615 0 0 0 0 2 1 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20583] ppid=20567 vsize=48864 CPUtime=1.43
/proc/20583/stat : 20583 (cudf2lp) R 20567 20567 1750 0 -1 4202496 13726 0 0 0 136 7 0 0 20 0 1 0 120327998 50036736 10328 18446744073709551615 4194304 5690517 140737392883536 140737392881176 4957075 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/20583/statm: 12216 10328 159 366 0 11847 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 58076

[startup+3.10023 s]
/proc/loadavg: 1.03 0.99 0.97 2/61 20583
/proc/meminfo: memFree=447164/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=2.9
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 759 27439 0 0 0 0 274 16 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 9212

[startup+6.30028 s]
/proc/loadavg: 1.03 0.99 0.97 2/61 20584
/proc/meminfo: memFree=352180/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=2.9
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 759 27439 0 0 0 0 274 16 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584369360 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20584] ppid=20567 vsize=234632 CPUtime=3.32
/proc/20584/stat : 20584 (gringo) R 20567 20567 1750 0 -1 4202496 56782 0 0 0 308 24 0 0 20 0 1 0 120328290 240263168 48049 18446744073709551615 4194304 6531320 140735703872800 140735703868728 4338233 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20584/statm: 58658 48049 283 571 0 58079 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 243844

[startup+12.7004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 20586
/proc/meminfo: memFree=385404/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=5
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26025 0 0 0 492 8 0 0 20 0 1 0 120328757 91779072 21949 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4371967 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21949 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 120880

[startup+25.5004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 20586
/proc/meminfo: memFree=385404/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=17.68
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 1760 8 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4407165 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 120880

[startup+51.1003 s]
/proc/loadavg: 1.01 0.99 0.97 2/62 20586
/proc/meminfo: memFree=385404/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=43.06
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 4297 9 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.6
Current children cumulated vsize (KiB) 120880

[startup+102.3 s]
/proc/loadavg: 1.00 0.99 0.97 2/62 20586
/proc/meminfo: memFree=385404/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=93.9
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 9380 10 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4406998 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.44
Current children cumulated vsize (KiB) 120880

[startup+162.3 s]
/proc/loadavg: 1.05 1.00 0.98 3/62 20734
/proc/meminfo: memFree=364192/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=151.58
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 15148 10 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4635182 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 159.12
Current children cumulated vsize (KiB) 120880

[startup+222.303 s]
/proc/loadavg: 1.08 1.03 0.99 2/62 20837
/proc/meminfo: memFree=180936/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=207.64
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 20749 15 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4676741 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 215.18
Current children cumulated vsize (KiB) 120880

[startup+282.3 s]
/proc/loadavg: 1.03 1.02 0.99 2/62 20837
/proc/meminfo: memFree=181184/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=267.15
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 26698 17 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4407044 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 274.69
Current children cumulated vsize (KiB) 120880



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+307.9 s]
/proc/loadavg: 1.02 1.02 0.99 2/62 20837
/proc/meminfo: memFree=181184/1022884 swapFree=0/0
[pid=20567] ppid=20566 vsize=9212 CPUtime=7.53
/proc/20567/stat : 20567 (aspcud-full) S 20566 20567 1750 0 -1 4202496 799 101688 0 0 0 0 698 55 20 0 1 0 120327995 9433088 364 18446744073709551615 4194304 5129932 140735584370704 140735584368768 140320501199966 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20567/statm: 2303 364 303 229 0 63 0
[pid=20585] ppid=20567 vsize=89628 CPUtime=292.5
/proc/20585/stat : 20585 (clasp) R 20567 20567 1750 0 -1 4202496 26069 0 0 0 29233 17 0 0 20 0 1 0 120328757 91779072 21993 18446744073709551615 4194304 6238623 140737013854912 140737013851936 4677452 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20585/statm: 22407 21993 263 500 0 21904 0
[pid=20586] ppid=20567 vsize=22040 CPUtime=0.01
/proc/20586/stat : 20586 (parse.py) S 20567 20567 1750 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120328757 22568960 1129 18446744073709551615 4194304 6642060 140733821808928 140733821807288 140165301118752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20586/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 120880

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.937
CPU time (s): 300.111
CPU user time (s): 299.347
CPU system time (s): 0.764047
CPU usage (%): 97.4584
Max. virtual memory (cumulated for all children) (KiB): 325300

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.347
system time used= 0.764047
maximum resident set size= 262048
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 130188
page faults= 0
swaps= 0
block input operations= 42368
block output operations= 31688
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 75
involuntary context switches= 38160

runsolver used 0.660041 second user time and 1.14007 second system time

The end