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/rand609.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand609.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand609.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.06 1.06 1.01 1/35 9833 /proc/meminfo: memFree=932244/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=3020 CPUtime=0 /proc/9833/stat : 9833 (runsolver) D 9832 9833 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 54931416 3092480 93 1283457024 134512640 134586868 4287015344 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/9833/statm: 755 93 62 19 0 54 0 [startup+0.188285 s] /proc/loadavg: 1.06 1.06 1.01 1/35 9833 /proc/meminfo: memFree=932244/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.204237 s] /proc/loadavg: 1.06 1.06 1.01 1/35 9833 /proc/meminfo: memFree=932244/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.304203 s] /proc/loadavg: 1.06 1.06 1.01 1/35 9833 /proc/meminfo: memFree=932244/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.71415 s] /proc/loadavg: 1.06 1.06 1.01 1/35 9833 /proc/meminfo: memFree=932244/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50437 s] /proc/loadavg: 1.22 1.09 1.02 2/39 9844 /proc/meminfo: memFree=914128/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=3448 CPUtime=0 /proc/9842/stat : 9842 (unclasp) S 9833 9833 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 24 0 1 0 54931421 3530752 272 1283457024 134512640 135121179 4286674304 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/9842/statm: 862 272 240 149 0 53 0 [pid=9843] ppid=9833 vsize=2692 CPUtime=0 /proc/9843/stat : 9843 (gringo) S 9833 9833 2160 34817 2160 4202496 386 0 22 0 0 0 0 0 23 0 1 0 54931422 2756608 281 1283457024 134512640 137056543 4292115872 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/9843/statm: 673 281 252 622 0 48 0 [pid=9844] ppid=9833 vsize=28116 CPUtime=1.22 /proc/9844/stat : 9844 (cudf2lp) R 9833 9833 2160 34817 2160 4202496 7885 0 15 0 119 3 0 0 25 0 1 0 54931422 28790784 6162 1283457024 134512640 135786343 4286674128 18446744073709551615 134566237 0 0 6 0 0 0 0 17 0 0 0 0 /proc/9844/statm: 7029 6162 128 311 0 6716 0 Current children cumulated CPU time (s) 1.22 Current children cumulated vsize (KiB) 36848 [startup+3.10479 s] /proc/loadavg: 1.22 1.09 1.02 2/39 9844 /proc/meminfo: memFree=900116/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=10800 CPUtime=0.03 /proc/9842/stat : 9842 (unclasp) S 9833 9833 2160 34817 2160 4202496 2476 0 6 0 2 1 0 0 18 0 1 0 54931421 11059200 2143 1283457024 134512640 135121179 4286674304 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/9842/statm: 2700 2143 275 149 0 1891 0 [pid=9843] ppid=9833 vsize=12788 CPUtime=0.38 /proc/9843/stat : 9843 (gringo) R 9833 9833 2160 34817 2160 4202496 3462 0 22 0 38 0 0 0 18 0 1 0 54931422 13094912 2486 1283457024 134512640 137056543 4292115872 18446744073709551615 136301785 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9843/statm: 3197 2486 253 622 0 2572 0 [pid=9844] ppid=9833 vsize=44576 CPUtime=2.4 /proc/9844/stat : 9844 (cudf2lp) R 9833 9833 2160 34817 2160 4202496 13961 0 15 0 235 5 0 0 25 0 1 0 54931422 45645824 10945 1283457024 134512640 135786343 4286674128 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/9844/statm: 11144 10945 139 311 0 10831 0 Current children cumulated CPU time (s) 2.81 Current children cumulated vsize (KiB) 70756 [startup+6.3046 s] /proc/loadavg: 1.28 1.10 1.03 4/39 9844 /proc/meminfo: memFree=798932/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=0 /proc/9833/stat : 9833 (aspuncud-user-1) R 9832 9833 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=51668 CPUtime=0.22 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 14862 0 6 0 20 2 0 0 18 0 1 0 54931421 52908032 12051 1283457024 134512640 135121179 4286674304 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 12917 12051 275 149 0 12108 0 [pid=9843] ppid=9833 vsize=73716 CPUtime=2.73 /proc/9843/stat : 9843 (gringo) R 9833 9833 2160 34817 2160 4202496 24719 0 22 0 258 15 0 0 18 0 1 0 54931422 75485184 14636 1283457024 134512640 137056543 4292115872 18446744073709551615 134756603 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9843/statm: 18429 14636 268 622 0 17804 0 [pid=9844] ppid=9833 vsize=0 CPUtime=3.04 /proc/9844/stat : 9844 (cudf2lp) Z 9833 9833 2160 34817 2160 4202508 13964 0 15 0 294 10 0 0 25 0 1 0 54931422 0 0 1283457024 0 0 0 0 0 0 0 6 0 18446744071564254338 0 0 17 0 0 0 0 /proc/9844/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 5.99 Current children cumulated vsize (KiB) 127976 [startup+12.7119 s] /proc/loadavg: 1.26 1.10 1.03 2/37 9845 /proc/meminfo: memFree=811064/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126516 CPUtime=4.51 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 88954 0 7 0 415 36 0 0 25 0 1 0 54931421 129552384 29360 1283457024 134512640 135121179 4286674304 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31629 29360 319 149 0 30820 0 Current children cumulated CPU time (s) 12.39 Current children cumulated vsize (KiB) 129108 [startup+25.5157 s] /proc/loadavg: 1.20 1.10 1.03 2/37 9846 /proc/meminfo: memFree=810580/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126516 CPUtime=17.31 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 326895 0 7 0 1608 123 0 0 25 0 1 0 54931421 129552384 29365 1283457024 134512640 135121179 4286674304 18446744073709551615 134734459 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31629 29365 319 149 0 30820 0 Current children cumulated CPU time (s) 25.19 Current children cumulated vsize (KiB) 129108 [startup+51.1139 s] /proc/loadavg: 1.13 1.09 1.03 2/37 9849 /proc/meminfo: memFree=810580/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126520 CPUtime=42.88 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 794539 0 7 0 3972 316 0 0 25 0 1 0 54931421 129556480 29380 1283457024 134512640 135121179 4286674304 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31630 29380 321 149 0 30821 0 Current children cumulated CPU time (s) 50.76 Current children cumulated vsize (KiB) 129112 [startup+102.311 s] /proc/loadavg: 1.06 1.07 1.02 2/36 9853 /proc/meminfo: memFree=807248/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=130412 CPUtime=94.04 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 1708299 0 7 0 8706 698 0 0 25 0 1 0 54931421 133541888 30347 1283457024 134512640 135121179 4286674304 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 32603 30347 321 149 0 31794 0 Current children cumulated CPU time (s) 101.92 Current children cumulated vsize (KiB) 133004 [startup+162.312 s] /proc/loadavg: 1.02 1.06 1.01 2/35 9853 /proc/meminfo: memFree=810232/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126896 CPUtime=153.99 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 2762299 0 7 0 14254 1145 0 0 25 0 1 0 54931421 129941504 29420 1283457024 134512640 135121179 4286674304 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31724 29420 321 149 0 30915 0 Current children cumulated CPU time (s) 161.87 Current children cumulated vsize (KiB) 129488 [startup+222.312 s] /proc/loadavg: 1.00 1.04 1.01 2/35 9853 /proc/meminfo: memFree=810108/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126908 CPUtime=213.92 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 3805425 0 7 0 19784 1608 0 0 25 0 1 0 54931421 129953792 29440 1283457024 134512640 135121179 4286674304 18446744073709551615 134837460 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31727 29440 321 149 0 30918 0 Current children cumulated CPU time (s) 221.8 Current children cumulated vsize (KiB) 129500 [startup+282.313 s] /proc/loadavg: 1.00 1.03 1.00 2/35 9853 /proc/meminfo: memFree=807380/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=129988 CPUtime=273.85 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 4830245 0 7 0 25332 2053 0 0 25 0 1 0 54931421 133107712 30228 1283457024 134512640 135121179 4286674304 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 32497 30228 321 149 0 31688 0 Current children cumulated CPU time (s) 281.73 Current children cumulated vsize (KiB) 132580 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.606 s] /proc/loadavg: 1.00 1.03 1.00 2/35 9853 /proc/meminfo: memFree=809860/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126912 CPUtime=282.15 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 4971929 0 7 0 26106 2109 0 0 25 0 1 0 54931421 129957888 29460 1283457024 134512640 135121179 4286674304 18446744073709551615 134734446 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31728 29460 321 149 0 30919 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 129504 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.606 s] /proc/loadavg: 1.00 1.03 1.00 2/35 9853 /proc/meminfo: memFree=809860/1048576 swapFree=0/0 [pid=9833] ppid=9832 vsize=2592 CPUtime=7.88 /proc/9833/stat : 9833 (aspuncud-user-1) S 9832 9833 2160 34817 2160 4202496 568 63447 0 40 0 0 746 42 18 0 1 0 54931416 2654208 298 1283457024 134512640 135304128 4292464544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9833/statm: 648 298 251 194 0 35 0 [pid=9842] ppid=9833 vsize=126912 CPUtime=282.15 /proc/9842/stat : 9842 (unclasp) R 9833 9833 2160 34817 2160 4202496 4971929 0 7 0 26106 2109 0 0 25 0 1 0 54931421 129957888 29460 1283457024 134512640 135121179 4286674304 18446744073709551615 134734446 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9842/statm: 31728 29460 321 149 0 30919 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 129504 Child status: 0 Real time (s): 290.649 CPU time (s): 290.054 CPU user time (s): 268.525 CPU system time (s): 21.5293 CPU usage (%): 99.7952 Max. virtual memory (cumulated for all children) (KiB): 248540 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.525 system time used= 21.5293 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5038338 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= 9344 involuntary context switches= 11123 runsolver used 0 second user time and 0 second system time The end