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/dist-upgrade/upgrade/easy/rand653.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand653.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/easy/rand653.cudf.result -notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

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.94 1.01 0.99 2/59 29892
/proc/meminfo: memFree=290096/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=3152 CPUtime=0
/proc/29892/stat : 29892 (runsolver) R 29891 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117970706 3227648 32 18446744073709551615 134512640 134586868 4294361216 4294359264 4151256112 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.158634 s]
/proc/loadavg: 0.94 1.01 0.99 2/59 29892
/proc/meminfo: memFree=290096/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=0.03
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 739 3620 0 0 0 0 3 0 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200563 s]
/proc/loadavg: 0.94 1.01 0.99 2/59 29892
/proc/meminfo: memFree=290096/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=0.03
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 739 3620 0 0 0 0 3 0 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300314 s]
/proc/loadavg: 0.94 1.01 0.99 2/59 29892
/proc/meminfo: memFree=290096/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=0.03
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 739 3620 0 0 0 0 3 0 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 0.94 1.01 0.99 2/59 29892
/proc/meminfo: memFree=290096/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=0.03
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 739 3620 0 0 0 0 3 0 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 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.95 1.01 0.99 2/61 29908
/proc/meminfo: memFree=255352/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=0.03
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 739 3620 0 0 0 0 3 0 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29908] ppid=29892 vsize=31624 CPUtime=1.38
/proc/29908/stat : 29908 (cudf2lp) R 29892 29892 1733 0 -1 4202496 9392 0 0 0 131 7 0 0 20 0 1 0 117970709 32382976 7659 18446744073709551615 4194304 5690517 140735155396368 140735155394008 4381444 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/29908/statm: 7906 7659 159 366 0 7537 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 40836

[startup+3.10032 s]
/proc/loadavg: 0.95 1.01 0.99 2/61 29908
/proc/meminfo: memFree=223608/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=0.03
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 739 3620 0 0 0 0 3 0 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29908] ppid=29892 vsize=77028 CPUtime=2.96
/proc/29908/stat : 29908 (cudf2lp) R 29892 29892 1733 0 -1 4202496 25055 0 0 0 282 14 0 0 20 0 1 0 117970709 78876672 18992 18446744073709551615 4194304 5690517 140735155396368 140735155393192 4631094 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/29908/statm: 19257 18992 174 366 0 18888 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 86240

[startup+6.30025 s]
/proc/loadavg: 0.95 1.01 0.99 2/61 29909
/proc/meminfo: memFree=160988/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=3.21
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 765 28677 0 0 0 0 304 17 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121259456 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29909] ppid=29892 vsize=205868 CPUtime=2.95
/proc/29909/stat : 29909 (gringo) R 29892 29892 1733 0 -1 4202496 50308 0 0 0 275 20 0 0 20 0 1 0 117971038 210808832 41029 18446744073709551615 4194304 6531320 140734344037408 140734344033752 4596969 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/29909/statm: 51467 41029 282 571 0 50888 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 215080

[startup+12.7003 s]
/proc/loadavg: 0.95 1.01 0.99 2/62 29911
/proc/meminfo: memFree=208124/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=4.35
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31265 0 0 0 423 12 0 0 20 0 1 0 117971535 107741184 25616 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4295393 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25616 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 136468

[startup+25.5003 s]
/proc/loadavg: 0.96 1.01 0.99 2/62 29911
/proc/meminfo: memFree=206760/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=17.05
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31601 0 0 0 1693 12 0 0 20 0 1 0 117971535 107741184 25952 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4635221 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25952 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.1
Current children cumulated vsize (KiB) 136468

[startup+51.1003 s]
/proc/loadavg: 0.97 1.00 0.99 2/62 29911
/proc/meminfo: memFree=206760/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=42.44
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31601 0 0 0 4232 12 0 0 20 0 1 0 117971535 107741184 25952 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4677164 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25952 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.49
Current children cumulated vsize (KiB) 136468

[startup+102.3 s]
/proc/loadavg: 0.99 1.00 0.99 2/62 29919
/proc/meminfo: memFree=205520/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=93.24
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31637 0 0 0 9312 12 0 0 20 0 1 0 117971535 107741184 25988 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25988 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.29
Current children cumulated vsize (KiB) 136468

[startup+162.3 s]
/proc/loadavg: 0.99 1.00 0.99 2/62 29919
/proc/meminfo: memFree=205520/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=152.79
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31637 0 0 0 15267 12 0 0 20 0 1 0 117971535 107741184 25988 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25988 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.84
Current children cumulated vsize (KiB) 136468

[startup+222.309 s]
/proc/loadavg: 0.99 1.00 0.99 2/62 29919
/proc/meminfo: memFree=205520/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=212.28
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31637 0 0 0 21216 12 0 0 20 0 1 0 117971535 107741184 25988 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25988 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.33
Current children cumulated vsize (KiB) 136468

[startup+282.3 s]
/proc/loadavg: 1.17 1.06 1.01 2/62 30170
/proc/meminfo: memFree=21512/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=265.42
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31637 0 0 0 26528 14 0 0 20 0 1 0 117971535 107741184 25988 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4331895 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25988 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 273.47
Current children cumulated vsize (KiB) 136468



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+309.1 s]
/proc/loadavg: 1.11 1.05 1.01 2/62 30170
/proc/meminfo: memFree=21640/1022884 swapFree=0/0
[pid=29892] ppid=29891 vsize=9212 CPUtime=8.04
/proc/29892/stat : 29892 (aspcud-full) S 29891 29892 1733 0 -1 4202496 805 113840 0 0 0 0 746 58 20 0 1 0 117970706 9433088 365 18446744073709551615 4194304 5129932 140736121260800 140736121258864 140594510296158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29892/statm: 2303 365 303 229 0 63 0
[pid=29910] ppid=29892 vsize=105216 CPUtime=292.03
/proc/29910/stat : 29910 (clasp) R 29892 29892 1733 0 -1 4202496 31637 0 0 0 29189 14 0 0 20 0 1 0 117971535 107741184 25988 18446744073709551615 4194304 6238623 140736509178496 140736509175520 4635208 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29910/statm: 26304 25988 264 500 0 25801 0
[pid=29911] ppid=29892 vsize=22040 CPUtime=0.01
/proc/29911/stat : 29911 (parse.py) S 29892 29892 1733 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 117971535 22568960 1127 18446744073709551615 4194304 6642060 140733380597952 140733380596312 139746698503968 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29911/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.08
Current children cumulated vsize (KiB) 136468

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): 309.192
CPU time (s): 300.191
CPU user time (s): 299.419
CPU system time (s): 0.772048
CPU usage (%): 97.0888
Max. virtual memory (cumulated for all children) (KiB): 367728

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.419
system time used= 0.772048
maximum resident set size= 303520
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 147912
page faults= 1
swaps= 0
block input operations= 42424
block output operations= 40832
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 74
involuntary context switches= 38064

runsolver used 0.608038 second user time and 1.14407 second system time

The end