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/201108300820/aspuncud-user-1.0/rand437.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand437.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand437.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: 1.14 1.10 1.04 2/36 6789 /proc/meminfo: memFree=929056/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=3016 CPUtime=0 /proc/6789/stat : 6789 (runsolver) D 6788 6789 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 53264229 3088384 93 1283457024 134512640 134586868 4288998288 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/6789/statm: 754 93 62 19 0 53 0 [startup+0.153212 s] /proc/loadavg: 1.14 1.10 1.04 2/36 6789 /proc/meminfo: memFree=929056/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.205209 s] /proc/loadavg: 1.14 1.10 1.04 2/36 6789 /proc/meminfo: memFree=929056/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.30522 s] /proc/loadavg: 1.14 1.10 1.04 2/36 6789 /proc/meminfo: memFree=929056/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.702889 s] /proc/loadavg: 1.14 1.10 1.04 2/36 6789 /proc/meminfo: memFree=929056/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50303 s] /proc/loadavg: 1.21 1.11 1.04 2/40 6800 /proc/meminfo: memFree=910560/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=3440 CPUtime=0 /proc/6798/stat : 6798 (unclasp) S 6789 6789 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 24 0 1 0 53264234 3522560 271 1283457024 134512640 135121179 4288662992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6798/statm: 860 271 240 149 0 51 0 [pid=6799] ppid=6789 vsize=2692 CPUtime=0 /proc/6799/stat : 6799 (gringo) S 6789 6789 2160 34817 2160 4202496 387 0 22 0 0 0 0 0 23 0 1 0 53264234 2756608 281 1283457024 134512640 137056543 4288659552 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6799/statm: 673 281 252 622 0 48 0 [pid=6800] ppid=6789 vsize=28112 CPUtime=1.25 /proc/6800/stat : 6800 (cudf2lp) R 6789 6789 2160 34817 2160 4202496 7903 0 15 0 123 2 0 0 25 0 1 0 53264234 28786688 6179 1283457024 134512640 135786343 4293240128 18446744073709551615 135044542 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6800/statm: 7028 6179 128 311 0 6715 0 Current children cumulated CPU time (s) 1.25 Current children cumulated vsize (KiB) 36836 [startup+3.10331 s] /proc/loadavg: 1.21 1.11 1.04 2/40 6800 /proc/meminfo: memFree=896548/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=10928 CPUtime=0.06 /proc/6798/stat : 6798 (unclasp) S 6789 6789 2160 34817 2160 4202496 2492 0 6 0 5 1 0 0 18 0 1 0 53264234 11190272 2158 1283457024 134512640 135121179 4288662992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6798/statm: 2732 2158 275 149 0 1923 0 [pid=6799] ppid=6789 vsize=12824 CPUtime=0.33 /proc/6799/stat : 6799 (gringo) S 6789 6789 2160 34817 2160 4202496 3584 0 22 0 33 0 0 0 18 0 1 0 53264234 13131776 2509 1283457024 134512640 137056543 4288659552 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6799/statm: 3206 2509 253 622 0 2581 0 [pid=6800] ppid=6789 vsize=44564 CPUtime=2.44 /proc/6800/stat : 6800 (cudf2lp) R 6789 6789 2160 34817 2160 4202496 13952 0 15 0 240 4 0 0 25 0 1 0 53264234 45633536 10935 1283457024 134512640 135786343 4293240128 18446744073709551615 134571626 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6800/statm: 11141 10935 139 311 0 10828 0 Current children cumulated CPU time (s) 2.83 Current children cumulated vsize (KiB) 70908 [startup+6.31421 s] /proc/loadavg: 1.21 1.11 1.04 3/40 6800 /proc/meminfo: memFree=795924/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=0 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=51664 CPUtime=0.31 /proc/6798/stat : 6798 (unclasp) S 6789 6789 2160 34817 2160 4202496 14872 0 6 0 26 5 0 0 18 0 1 0 53264234 52903936 12060 1283457024 134512640 135121179 4288662992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6798/statm: 12916 12060 275 149 0 12107 0 [pid=6799] ppid=6789 vsize=72092 CPUtime=2.67 /proc/6799/stat : 6799 (gringo) S 6789 6789 2160 34817 2160 4202496 24312 0 22 0 255 12 0 0 18 0 1 0 53264234 73822208 14259 1283457024 134512640 137056543 4288659552 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6799/statm: 18023 14259 253 622 0 17398 0 [pid=6800] ppid=6789 vsize=24736 CPUtime=3.06 /proc/6800/stat : 6800 (cudf2lp) R 6789 6789 2160 34817 2160 4202496 13952 0 15 0 300 6 0 0 25 0 1 0 53264234 25329664 6008 1283457024 134512640 135786343 4293240128 18446744073709551615 135191532 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6800/statm: 6184 6008 139 311 0 5871 0 Current children cumulated CPU time (s) 6.04 Current children cumulated vsize (KiB) 151084 [startup+12.709 s] /proc/loadavg: 1.25 1.13 1.05 2/38 6800 /proc/meminfo: memFree=802164/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=128644 CPUtime=4.58 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 91102 0 7 0 416 42 0 0 25 0 1 0 53264234 131731456 29886 1283457024 134512640 135121179 4288662992 18446744073709551615 134734473 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 32161 29886 321 149 0 31352 0 Current children cumulated CPU time (s) 12.41 Current children cumulated vsize (KiB) 131236 [startup+25.5128 s] /proc/loadavg: 1.21 1.12 1.04 2/38 6800 /proc/meminfo: memFree=803156/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=131712 CPUtime=17.37 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 337850 0 7 0 1600 137 0 0 25 0 1 0 53264234 134873088 30657 1283457024 134512640 135121179 4288662992 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 32928 30657 321 149 0 32119 0 Current children cumulated CPU time (s) 25.2 Current children cumulated vsize (KiB) 134304 [startup+51.1122 s] /proc/loadavg: 1.14 1.11 1.04 2/38 6800 /proc/meminfo: memFree=805512/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=128648 CPUtime=42.95 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 820968 0 7 0 3969 326 0 0 25 0 1 0 53264234 131735552 29899 1283457024 134512640 135121179 4288662992 18446744073709551615 134891769 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 32162 29899 321 149 0 31353 0 Current children cumulated CPU time (s) 50.78 Current children cumulated vsize (KiB) 131240 [startup+102.31 s] /proc/loadavg: 1.05 1.09 1.04 2/38 6800 /proc/meminfo: memFree=805264/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=128860 CPUtime=94.1 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 1776067 0 7 0 8674 736 0 0 25 0 1 0 53264234 131952640 29946 1283457024 134512640 135121179 4288662992 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 32215 29946 321 149 0 31406 0 Current children cumulated CPU time (s) 101.93 Current children cumulated vsize (KiB) 131452 [startup+162.31 s] /proc/loadavg: 1.02 1.07 1.03 2/38 6800 /proc/meminfo: memFree=805016/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=129224 CPUtime=154.03 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 2864171 0 7 0 14206 1197 0 0 25 0 1 0 53264234 132325376 29945 1283457024 134512640 135121179 4288662992 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 32306 29945 321 149 0 31497 0 Current children cumulated CPU time (s) 161.86 Current children cumulated vsize (KiB) 131816 [startup+222.31 s] /proc/loadavg: 1.00 1.05 1.02 2/40 6802 /proc/meminfo: memFree=801148/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=132312 CPUtime=213.98 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 3938718 0 7 0 19741 1657 0 0 25 0 1 0 53264234 135487488 30755 1283457024 134512640 135121179 4288662992 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 33078 30755 321 149 0 32269 0 Current children cumulated CPU time (s) 221.81 Current children cumulated vsize (KiB) 134904 [startup+282.31 s] /proc/loadavg: 1.00 1.04 1.02 2/40 6808 /proc/meminfo: memFree=804620/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=129240 CPUtime=273.93 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 5002372 0 7 0 25284 2109 0 0 25 0 1 0 53264234 132341760 29999 1283457024 134512640 135121179 4288662992 18446744073709551615 134849021 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 32310 29999 321 149 0 31501 0 Current children cumulated CPU time (s) 281.76 Current children cumulated vsize (KiB) 131832 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.612 s] /proc/loadavg: 1.00 1.04 1.02 2/40 6809 /proc/meminfo: memFree=802140/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=132316 CPUtime=282.22 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 5149204 0 7 0 26044 2178 0 0 25 0 1 0 53264234 135491584 30737 1283457024 134512640 135121179 4288662992 18446744073709551615 134990512 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 33079 30737 321 149 0 32270 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 134908 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.612 s] /proc/loadavg: 1.00 1.04 1.02 2/40 6809 /proc/meminfo: memFree=802140/1048576 swapFree=0/0 [pid=6789] ppid=6788 vsize=2592 CPUtime=7.83 /proc/6789/stat : 6789 (aspuncud-user-1) S 6788 6789 2160 34817 2160 4202496 573 63551 0 40 0 0 755 28 18 0 1 0 53264229 2654208 298 1283457024 134512640 135304128 4292179792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6789/statm: 648 298 251 194 0 35 0 [pid=6798] ppid=6789 vsize=132316 CPUtime=282.22 /proc/6798/stat : 6798 (unclasp) R 6789 6789 2160 34817 2160 4202496 5149204 0 7 0 26044 2178 0 0 25 0 1 0 53264234 135491584 30737 1283457024 134512640 135121179 4288662992 18446744073709551615 134990512 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6798/statm: 33079 30737 321 149 0 32270 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 134908 Child status: 0 Real time (s): 290.649 CPU time (s): 290.09 CPU user time (s): 268.005 CPU system time (s): 22.0854 CPU usage (%): 99.8076 Max. virtual memory (cumulated for all children) (KiB): 247436 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.005 system time used= 22.0854 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5215719 page faults= 49 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 9356 involuntary context switches= 11076 runsolver used 0 second user time and 0 second system time The end