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/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.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.93 0.97 0.98 2/64 19736
/proc/meminfo: memFree=394840/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=3152 CPUtime=0
/proc/19736/stat : 19736 (runsolver) R 19735 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120185353 3227648 32 18446744073709551615 134512640 134586868 4288204384 4288202432 4151673904 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.18322 s]
/proc/loadavg: 0.93 0.97 0.98 2/64 19736
/proc/meminfo: memFree=394840/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=0.06
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 738 3622 0 0 0 1 3 2 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200336 s]
/proc/loadavg: 0.93 0.97 0.98 2/64 19736
/proc/meminfo: memFree=394840/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=0.06
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 738 3622 0 0 0 1 3 2 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300356 s]
/proc/loadavg: 0.93 0.97 0.98 2/64 19736
/proc/meminfo: memFree=394840/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=0.06
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 738 3622 0 0 0 1 3 2 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700233 s]
/proc/loadavg: 0.93 0.97 0.98 2/64 19736
/proc/meminfo: memFree=394840/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=0.06
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 738 3622 0 0 0 1 3 2 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50034 s]
/proc/loadavg: 0.93 0.97 0.98 2/66 19752
/proc/meminfo: memFree=359476/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=0.06
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 738 3622 0 0 0 1 3 2 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19752] ppid=19736 vsize=51500 CPUtime=1.42
/proc/19752/stat : 19752 (cudf2lp) R 19736 19736 1745 0 -1 4202496 14353 0 0 0 134 8 0 0 20 0 1 0 120185357 52736000 10953 18446744073709551615 4194304 5690517 140737196758368 140737196756008 4951920 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/19752/statm: 12875 10953 160 366 0 12506 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 60712

[startup+3.10032 s]
/proc/loadavg: 0.93 0.97 0.98 2/66 19752
/proc/meminfo: memFree=326616/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=0.06
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 738 3622 0 0 0 1 3 2 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19752] ppid=19736 vsize=78192 CPUtime=3.01
/proc/19752/stat : 19752 (cudf2lp) R 19736 19736 1745 0 -1 4202496 25441 0 0 0 286 15 0 0 20 0 1 0 120185357 80068608 19274 18446744073709551615 4194304 5690517 140737196758368 140737196755736 4956126 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/19752/statm: 19548 19274 174 366 0 19179 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 87404

[startup+6.30036 s]
/proc/loadavg: 0.94 0.97 0.98 2/66 19753
/proc/meminfo: memFree=271932/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=3.19
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 762 29065 0 0 0 1 299 19 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409954160 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19753] ppid=19736 vsize=158260 CPUtime=3.05
/proc/19753/stat : 19753 (gringo) R 19736 19736 1745 0 -1 4202496 38555 0 0 0 290 15 0 0 20 0 1 0 120185674 162058240 33885 18446744073709551615 4194304 6531320 140734193669168 140734193665784 4580404 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19753/statm: 39565 33885 282 571 0 38986 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 167472

[startup+12.7003 s]
/proc/loadavg: 0.94 0.97 0.98 2/67 19755
/proc/meminfo: memFree=269188/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=141576 CPUtime=1.51
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 41286 0 0 0 142 9 0 0 20 0 1 0 120186468 144973824 34844 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 35394 34844 263 500 0 34891 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 172828

[startup+25.5003 s]
/proc/loadavg: 0.95 0.97 0.98 2/67 19755
/proc/meminfo: memFree=268692/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=141576 CPUtime=14.21
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 41426 0 0 0 1411 10 0 0 20 0 1 0 120186468 144973824 34984 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4407221 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 35394 34984 263 500 0 34891 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.15
Current children cumulated vsize (KiB) 172828

[startup+51.1003 s]
/proc/loadavg: 0.97 0.97 0.98 2/67 19755
/proc/meminfo: memFree=268320/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=141576 CPUtime=39.61
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 41504 0 0 0 3951 10 0 0 20 0 1 0 120186468 144973824 35062 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4409808 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 35394 35062 263 500 0 34891 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.55
Current children cumulated vsize (KiB) 172828

[startup+102.3 s]
/proc/loadavg: 0.98 0.97 0.98 2/67 19755
/proc/meminfo: memFree=268320/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=141576 CPUtime=90.41
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 41504 0 0 0 9031 10 0 0 20 0 1 0 120186468 144973824 35062 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4421741 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 35394 35062 263 500 0 34891 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.35
Current children cumulated vsize (KiB) 172828

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 19755
/proc/meminfo: memFree=206940/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=206200 CPUtime=149.94
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 56835 0 0 0 14974 20 0 0 20 0 1 0 120186468 211148800 50393 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4407211 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 51550 50393 263 500 0 51047 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.88
Current children cumulated vsize (KiB) 237452

[startup+222.304 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 19755
/proc/meminfo: memFree=164532/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=249580 CPUtime=209.47
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 67633 0 0 0 20924 23 0 0 20 0 1 0 120186468 255569920 61191 18446744073709551615 4194304 6238623 140734362894976 140734362891528 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 62395 61191 263 500 0 61892 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.41
Current children cumulated vsize (KiB) 280832

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 19755
/proc/meminfo: memFree=143204/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=270068 CPUtime=268.9
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 72768 0 0 0 26864 26 0 0 20 0 1 0 120186468 276549632 66326 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4331870 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 67517 66326 263 500 0 67014 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.84
Current children cumulated vsize (KiB) 301320



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.7 s]
/proc/loadavg: 0.99 0.97 0.98 2/67 19755
/proc/meminfo: memFree=143080/1022884 swapFree=0/0
[pid=19736] ppid=19735 vsize=9212 CPUtime=10.92
/proc/19736/stat : 19736 (aspcud-full) S 19735 19736 1745 0 -1 4202496 800 138102 0 0 0 1 1013 78 20 0 1 0 120185353 9433088 364 18446744073709551615 4194304 5129932 140734409955504 140734409953568 140581269492830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19736/statm: 2303 364 303 229 0 63 0
[pid=19754] ppid=19736 vsize=270068 CPUtime=289.1
/proc/19754/stat : 19754 (clasp) R 19736 19736 1745 0 -1 4202496 72768 0 0 0 28884 26 0 0 20 0 1 0 120186468 276549632 66326 18446744073709551615 4194304 6238623 140734362894976 140734362892000 4406979 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19754/statm: 67517 66326 263 500 0 67014 0
[pid=19755] ppid=19736 vsize=22040 CPUtime=0.02
/proc/19755/stat : 19755 (parse.py) S 19736 19736 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 120186468 22568960 1128 18446744073709551615 4194304 6642060 140736052103632 140736052101992 140388881721120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19755/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 301320

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.769
CPU time (s): 300.119
CPU user time (s): 298.999
CPU system time (s): 1.12007
CPU usage (%): 99.1246
Max. virtual memory (cumulated for all children) (KiB): 476516

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.999
system time used= 1.12007
maximum resident set size= 401064
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 213341
page faults= 0
swaps= 0
block input operations= 43848
block output operations= 46928
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 87
involuntary context switches= 34262

runsolver used 0.536033 second user time and 1.33608 second system time

The end