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/trendy-size/upgrade/difficult/rand116.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand116.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand116.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-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.92 0.98 0.99 2/59 1780
/proc/meminfo: memFree=701772/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=3152 CPUtime=0
/proc/1780/stat : 1780 (runsolver) R 1779 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119604246 3227648 32 18446744073709551615 134512640 134586868 4287497024 4287495072 4152009776 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/1780/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.106374 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 1780
/proc/meminfo: memFree=701772/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=0.06
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 711 3392 2 6 0 1 4 1 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200288 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 1780
/proc/meminfo: memFree=701772/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=0.06
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 738 3614 2 7 0 1 4 1 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 1780
/proc/meminfo: memFree=701772/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=0.06
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 738 3614 2 7 0 1 4 1 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700236 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 1780
/proc/meminfo: memFree=701772/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=0.06
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 738 3614 2 7 0 1 4 1 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.92 0.98 0.99 2/61 1796
/proc/meminfo: memFree=667648/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=0.06
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 738 3614 2 7 0 1 4 1 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1796] ppid=1780 vsize=33064 CPUtime=1.35
/proc/1796/stat : 1796 (cudf2lp) R 1780 1780 1733 0 -1 4202496 9673 0 1 0 130 5 0 0 20 0 1 0 119604257 33857536 7940 18446744073709551615 4194304 5690517 140735594965792 140735594963160 4293352 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/1796/statm: 8266 7940 160 366 0 7897 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 42276

[startup+3.10032 s]
/proc/loadavg: 0.92 0.98 0.99 2/61 1796
/proc/meminfo: memFree=635656/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=0.06
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 738 3614 2 7 0 1 4 1 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1796] ppid=1780 vsize=93028 CPUtime=2.94
/proc/1796/stat : 1796 (cudf2lp) R 1780 1780 1733 0 -1 4202496 26449 0 1 0 283 11 0 0 20 0 1 0 119604257 95260672 19722 18446744073709551615 4194304 5690517 140735594965792 140735594963448 4961324 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/1796/statm: 23257 19722 160 366 0 22888 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.93 0.98 0.99 2/61 1797
/proc/meminfo: memFree=648056/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=5.26
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 762 42936 2 8 0 1 497 28 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1797] ppid=1780 vsize=27436 CPUtime=0.9
/proc/1797/stat : 1797 (gringo) R 1780 1780 1733 0 -1 4202496 7153 0 0 0 84 6 0 0 20 0 1 0 119604785 28094464 6041 18446744073709551615 4194304 6531320 140737077096368 140737077092984 4241675 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/1797/statm: 6859 6041 259 571 0 6280 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 36648

[startup+12.7003 s]
/proc/loadavg: 0.93 0.98 0.99 2/61 1797
/proc/meminfo: memFree=365584/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=5.26
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 762 42936 2 8 0 1 497 28 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241920 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1797] ppid=1780 vsize=419772 CPUtime=7.24
/proc/1797/stat : 1797 (gringo) R 1780 1780 1733 0 -1 4202496 99991 0 0 0 676 48 0 0 20 0 1 0 119604785 429846528 83515 18446744073709551615 4194304 6531320 140737077096368 140737077092984 4350124 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/1797/statm: 104943 83515 282 571 0 104364 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 428984

[startup+25.5004 s]
/proc/loadavg: 1.02 1.00 0.99 2/62 1799
/proc/meminfo: memFree=425244/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=233980 CPUtime=6.79
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 71114 0 1 0 650 29 0 0 20 0 1 0 119606105 239595520 58007 18446744073709551615 4194304 6238623 140736464920016 140736464917040 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 58495 58007 263 500 0 57992 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.04
Current children cumulated vsize (KiB) 265232

[startup+51.1004 s]
/proc/loadavg: 1.01 1.00 0.99 2/62 1799
/proc/meminfo: memFree=425244/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=233980 CPUtime=32.11
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 71163 0 1 0 3182 29 0 0 20 0 1 0 119606105 239595520 58056 18446744073709551615 4194304 6238623 140736464920016 140736464917040 4696985 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 58495 58056 264 500 0 57992 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.36
Current children cumulated vsize (KiB) 265232

[startup+102.3 s]
/proc/loadavg: 1.00 1.00 0.99 2/62 1799
/proc/meminfo: memFree=391020/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=267956 CPUtime=82.92
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 79760 0 1 0 8260 32 0 0 20 0 1 0 119606105 274386944 66653 18446744073709551615 4194304 6238623 140736464920016 140736464916568 4305995 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 66989 66653 264 500 0 66486 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.17
Current children cumulated vsize (KiB) 299208

[startup+162.3 s]
/proc/loadavg: 1.10 1.03 1.00 2/62 1799
/proc/meminfo: memFree=319348/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=339412 CPUtime=142.47
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 97587 0 1 0 14207 40 0 0 20 0 1 0 119606105 347557888 84480 18446744073709551615 4194304 6238623 140736464920016 140736464916568 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 84853 84480 264 500 0 84350 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.72
Current children cumulated vsize (KiB) 370664

[startup+222.303 s]
/proc/loadavg: 1.18 1.06 1.01 2/62 2050
/proc/meminfo: memFree=137432/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=340876 CPUtime=196.5
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 97953 0 1 0 19608 42 0 0 20 0 1 0 119606105 349057024 84846 18446744073709551615 4194304 6238623 140736464920016 140736464917040 4687992 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 85219 84846 264 500 0 84716 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 214.75
Current children cumulated vsize (KiB) 372128

[startup+282.3 s]
/proc/loadavg: 1.06 1.05 1.01 2/62 2050
/proc/meminfo: memFree=134952/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=343532 CPUtime=256.04
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 98627 0 1 0 25562 42 0 0 20 0 1 0 119606105 351776768 85520 18446744073709551615 4194304 6238623 140736464920016 140736464917040 4355607 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 85883 85520 264 500 0 85380 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 274.29
Current children cumulated vsize (KiB) 374784



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+308.3 s]
/proc/loadavg: 1.11 1.06 1.01 2/62 2050
/proc/meminfo: memFree=134456/1022884 swapFree=0/0
[pid=1780] ppid=1779 vsize=9212 CPUtime=18.23
/proc/1780/stat : 1780 (aspcud-full) S 1779 1780 1733 0 -1 4202496 799 221770 2 8 0 1 1696 126 20 0 1 0 119604246 9433088 364 18446744073709551615 4194304 5129932 140736860243264 140736860241328 139923775628382 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/1780/statm: 2303 364 303 229 0 63 0
[pid=1798] ppid=1780 vsize=343928 CPUtime=281.84
/proc/1798/stat : 1798 (clasp) R 1780 1780 1733 0 -1 4202496 98742 0 1 0 28142 42 0 0 20 0 1 0 119606105 352182272 85635 18446744073709551615 4194304 6238623 140736464920016 140736464917040 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/1798/statm: 85982 85635 264 500 0 85479 0
[pid=1799] ppid=1780 vsize=22040 CPUtime=0.02
/proc/1799/stat : 1799 (parse.py) S 1780 1780 1733 0 -1 4202496 1304 0 13 0 1 1 0 0 20 0 1 0 119606105 22568960 1127 18446744073709551615 4194304 6642060 140737211750480 140737211748840 140147980166944 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/1799/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 375180

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): 308.368
CPU time (s): 300.179
CPU user time (s): 298.419
CPU system time (s): 1.76011
CPU usage (%): 97.3443
Max. virtual memory (cumulated for all children) (KiB): 783884

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.419
system time used= 1.76011
maximum resident set size= 649416
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 322930
page faults= 25
swaps= 0
block input operations= 70632
block output operations= 81840
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 109
involuntary context switches= 37408

runsolver used 0.528033 second user time and 1.21208 second system time

The end