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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201108311143/aspcud-1.5/rand56.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand56.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand56.cudf.user-upgrades.result -sum(installedsize) Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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: 0.95 0.99 0.99 5/35 27015 /proc/meminfo: memFree=456668/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2584 CPUtime=0 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 64301568 2646016 279 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/27013/statm: 646 279 234 194 0 33 0 [pid=27014] ppid=27013 vsize=2584 CPUtime=0 /proc/27014/stat : 27014 (aspcud-1.5) R 27013 27013 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 64301568 2646016 132 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/27014/statm: 646 132 86 194 0 33 0 [pid=27015] ppid=27014 vsize=2584 CPUtime=0 /proc/27015/stat : 27015 (aspcud-1.5) R 27014 27013 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 64301568 2646016 46 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/27015/statm: 646 46 0 194 0 33 0 [startup+0.138439 s] /proc/loadavg: 0.95 0.99 0.99 5/35 27015 /proc/meminfo: memFree=456668/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=0 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 1523 0 0 0 0 0 0 25 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.206442 s] /proc/loadavg: 0.95 0.99 0.99 5/35 27015 /proc/meminfo: memFree=456668/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=0 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 1523 0 0 0 0 0 0 25 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.315041 s] /proc/loadavg: 0.95 0.99 0.99 5/35 27015 /proc/meminfo: memFree=456668/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=0 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 1523 0 0 0 0 0 0 25 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.706476 s] /proc/loadavg: 0.95 0.99 0.99 5/35 27015 /proc/meminfo: memFree=456668/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=0 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 1523 0 0 0 0 0 0 25 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50654 s] /proc/loadavg: 0.95 0.99 0.99 2/37 27024 /proc/meminfo: memFree=423456/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=0 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 1523 0 0 0 0 0 0 25 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=1924 CPUtime=0 /proc/27022/stat : 27022 (clasp) S 27013 27013 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 64301569 1970176 159 1283457024 134512640 136285277 4293796064 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/27022/statm: 481 159 144 433 0 46 0 [pid=27023] ppid=27013 vsize=2584 CPUtime=0 /proc/27023/stat : 27023 (gringo) S 27013 27013 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 64301569 2646016 272 1283457024 134512640 136933539 4286614144 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/27023/statm: 646 272 242 592 0 51 0 [pid=27024] ppid=27013 vsize=28112 CPUtime=1.35 /proc/27024/stat : 27024 (cudf2lp) R 27013 27013 19908 34817 19908 4202496 8052 0 0 0 134 1 0 0 25 0 1 0 64301569 28786688 6308 1283457024 134512640 135786343 4294363632 18446744073709551615 134584195 0 0 6 0 0 0 0 17 0 0 0 0 /proc/27024/statm: 7028 6308 128 311 0 6715 0 Current children cumulated CPU time (s) 1.35 Current children cumulated vsize (KiB) 35212 [startup+3.10803 s] /proc/loadavg: 0.95 0.99 0.99 2/37 27024 /proc/meminfo: memFree=382888/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.26 /proc/27013/stat : 27013 (aspcud-1.5) R 27012 27013 19908 34817 19908 4202496 576 15498 0 0 0 0 223 3 19 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=3836 CPUtime=0.53 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 870 0 0 0 53 0 0 0 18 0 1 0 64301569 3928064 738 1283457024 134512640 136285277 4293796064 18446744073709551615 134735711 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 959 738 234 433 0 524 0 [pid=27023] ppid=27013 vsize=0 CPUtime=0.04 /proc/27023/stat : 27023 (gringo) Z 27013 27013 19908 34817 19908 4202508 935 0 0 0 4 0 0 0 18 0 1 0 64301569 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/27023/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.83 Current children cumulated vsize (KiB) 6428 [startup+6.30862 s] /proc/loadavg: 0.95 0.99 0.99 2/35 27024 /proc/meminfo: memFree=423592/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=4428 CPUtime=3.73 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1040 0 0 0 373 0 0 0 25 0 1 0 64301569 4534272 887 1283457024 134512640 136285277 4293796064 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1107 887 234 433 0 672 0 Current children cumulated CPU time (s) 6.03 Current children cumulated vsize (KiB) 7020 [startup+12.7095 s] /proc/loadavg: 0.96 0.99 0.99 2/35 27024 /proc/meminfo: memFree=423104/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=4740 CPUtime=10.12 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1142 0 0 0 1012 0 0 0 25 0 1 0 64301569 4853760 965 1283457024 134512640 136285277 4293796064 18446744073709551615 134734756 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1185 965 234 433 0 750 0 Current children cumulated CPU time (s) 12.42 Current children cumulated vsize (KiB) 7332 [startup+25.5117 s] /proc/loadavg: 0.97 0.99 0.99 2/35 27024 /proc/meminfo: memFree=422732/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=5072 CPUtime=22.92 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1239 0 0 0 2292 0 0 0 25 0 1 0 64301569 5193728 1062 1283457024 134512640 136285277 4293796064 18446744073709551615 134686293 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1268 1062 234 433 0 833 0 Current children cumulated CPU time (s) 25.22 Current children cumulated vsize (KiB) 7664 [startup+51.1066 s] /proc/loadavg: 0.98 0.99 0.99 2/35 27024 /proc/meminfo: memFree=422360/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=5572 CPUtime=48.49 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1376 0 0 0 4849 0 0 0 25 0 1 0 64301569 5705728 1179 1283457024 134512640 136285277 4293796064 18446744073709551615 134967401 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1393 1179 234 433 0 958 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 8164 [startup+102.307 s] /proc/loadavg: 0.99 0.99 0.99 2/35 27024 /proc/meminfo: memFree=421740/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=6072 CPUtime=99.69 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1490 0 0 0 9969 0 0 0 25 0 1 0 64301569 6217728 1293 1283457024 134512640 136285277 4293796064 18446744073709551615 134966793 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1518 1293 234 433 0 1083 0 Current children cumulated CPU time (s) 101.99 Current children cumulated vsize (KiB) 8664 [startup+162.309 s] /proc/loadavg: 0.99 0.99 0.99 2/35 27024 /proc/meminfo: memFree=421368/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=6368 CPUtime=159.66 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1585 0 0 0 15966 0 0 0 25 0 1 0 64301569 6520832 1387 1283457024 134512640 136285277 4293796064 18446744073709551615 134733715 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1592 1387 234 433 0 1157 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 8960 [startup+222.31 s] /proc/loadavg: 0.99 0.99 0.99 2/37 27031 /proc/meminfo: memFree=420972/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=6684 CPUtime=219.63 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1680 0 0 0 21963 0 0 0 25 0 1 0 64301569 6844416 1449 1283457024 134512640 136285277 4293796064 18446744073709551615 134734701 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1671 1449 234 433 0 1236 0 Current children cumulated CPU time (s) 221.93 Current children cumulated vsize (KiB) 9276 [startup+282.312 s] /proc/loadavg: 0.99 0.99 0.99 2/36 27035 /proc/meminfo: memFree=420988/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=6684 CPUtime=279.62 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1680 0 0 0 27961 1 0 0 25 0 1 0 64301569 6844416 1449 1283457024 134512640 136285277 4293796064 18446744073709551615 134733715 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1671 1449 234 433 0 1236 0 Current children cumulated CPU time (s) 281.92 Current children cumulated vsize (KiB) 9276 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.413 s] /proc/loadavg: 0.99 0.99 0.99 2/36 27035 /proc/meminfo: memFree=420988/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=6684 CPUtime=287.71 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1680 0 0 0 28770 1 0 0 25 0 1 0 64301569 6844416 1449 1283457024 134512640 136285277 4293796064 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1671 1449 234 433 0 1236 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 9276 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.413 s] /proc/loadavg: 0.99 0.99 0.99 2/36 27035 /proc/meminfo: memFree=420988/1048576 swapFree=0/0 [pid=27013] ppid=27012 vsize=2592 CPUtime=2.3 /proc/27013/stat : 27013 (aspcud-1.5) S 27012 27013 19908 34817 19908 4202496 576 16433 0 0 0 0 227 3 17 0 1 0 64301568 2654208 298 1283457024 134512640 135304128 4291116656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27013/statm: 648 298 251 194 0 35 0 [pid=27022] ppid=27013 vsize=6684 CPUtime=287.71 /proc/27022/stat : 27022 (clasp) R 27013 27013 19908 34817 19908 4202496 1680 0 0 0 28770 1 0 0 25 0 1 0 64301569 6844416 1449 1283457024 134512640 136285277 4293796064 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27022/statm: 1671 1449 234 433 0 1236 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 9276 Child status: 0 Real time (s): 290.435 CPU time (s): 290.054 CPU user time (s): 289.998 CPU system time (s): 0.056003 CPU usage (%): 99.8689 Max. virtual memory (cumulated for all children) (KiB): 57164 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.998 system time used= 0.056003 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22227 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 179 involuntary context switches= 3747 runsolver used 0 second user time and 0.012 second system time The end