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/rand475.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand475.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand475.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 [startup+0 s] /proc/loadavg: 1.00 1.03 1.00 2/36 7806 /proc/meminfo: memFree=929024/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=3024 CPUtime=0 /proc/7806/stat : 7806 (runsolver) R 7805 2160 2160 34817 2160 4202560 13 0 0 0 0 0 0 0 25 0 1 0 53832311 3096576 37 1283457024 134512640 134586868 4294207632 18446744073709551615 4158129912 0 0 0 24578 0 0 0 17 0 0 0 0 /proc/7806/statm: 756 37 5 19 0 55 0 Current StackSize limit: 8192 KiB [startup+0.190197 s] /proc/loadavg: 1.00 1.03 1.00 2/36 7806 /proc/meminfo: memFree=929024/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=0 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.206193 s] /proc/loadavg: 1.00 1.03 1.00 2/36 7806 /proc/meminfo: memFree=929024/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=0 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.309496 s] /proc/loadavg: 1.00 1.03 1.00 2/36 7806 /proc/meminfo: memFree=929024/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=0 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.709566 s] /proc/loadavg: 1.00 1.03 1.00 2/36 7806 /proc/meminfo: memFree=929024/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=0 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.50972 s] /proc/loadavg: 1.00 1.03 1.00 2/40 7817 /proc/meminfo: memFree=910396/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=0 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=3448 CPUtime=0 /proc/7815/stat : 7815 (unclasp) S 7806 7806 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 53832317 3530752 272 1283457024 134512640 135121179 4290234000 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7815/statm: 862 272 240 149 0 53 0 [pid=7816] ppid=7806 vsize=2692 CPUtime=0 /proc/7816/stat : 7816 (gringo) S 7806 7806 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 24 0 1 0 53832317 2756608 281 1283457024 134512640 137056543 4294104288 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7816/statm: 673 281 252 622 0 48 0 [pid=7817] ppid=7806 vsize=28112 CPUtime=1.26 /proc/7817/stat : 7817 (cudf2lp) R 7806 7806 2160 34817 2160 4202496 7913 0 15 0 123 3 0 0 25 0 1 0 53832317 28786688 6190 1283457024 134512640 135786343 4290237344 18446744073709551615 134605648 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7817/statm: 7028 6190 128 311 0 6715 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 36840 [startup+3.11002 s] /proc/loadavg: 1.00 1.03 1.00 2/40 7817 /proc/meminfo: memFree=896384/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=0 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 1522 0 3 0 0 0 0 25 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=11196 CPUtime=0 /proc/7815/stat : 7815 (unclasp) S 7806 7806 2160 34817 2160 4202496 2587 0 6 0 0 0 0 0 18 0 1 0 53832317 11464704 2254 1283457024 134512640 135121179 4290234000 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7815/statm: 2799 2254 275 149 0 1990 0 [pid=7816] ppid=7806 vsize=16240 CPUtime=0.44 /proc/7816/stat : 7816 (gringo) R 7806 7806 2160 34817 2160 4202496 4301 0 23 0 44 0 0 0 18 0 1 0 53832317 16629760 2748 1283457024 134512640 137056543 4294104288 18446744073709551615 136096421 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7816/statm: 4060 2748 253 622 0 3435 0 [pid=7817] ppid=7806 vsize=44564 CPUtime=2.4 /proc/7817/stat : 7817 (cudf2lp) R 7806 7806 2160 34817 2160 4202496 13951 0 15 0 231 9 0 0 25 0 1 0 53832317 45633536 10935 1283457024 134512640 135786343 4290237344 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7817/statm: 11141 10935 139 311 0 10828 0 Current children cumulated CPU time (s) 2.84 Current children cumulated vsize (KiB) 74588 [startup+6.31079 s] /proc/loadavg: 1.00 1.03 1.00 3/40 7817 /proc/meminfo: memFree=794580/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=3.15 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 15476 0 18 0 0 298 17 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=52064 CPUtime=0.2 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 14967 0 6 0 14 6 0 0 18 0 1 0 53832317 53313536 12156 1283457024 134512640 135121179 4290234000 18446744073709551615 134764130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 13016 12156 276 149 0 12207 0 [pid=7816] ppid=7806 vsize=74260 CPUtime=2.69 /proc/7816/stat : 7816 (gringo) R 7806 7806 2160 34817 2160 4202496 24949 0 23 0 263 6 0 0 18 0 1 0 53832317 76042240 14802 1283457024 134512640 137056543 4294104288 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7816/statm: 18565 14802 268 622 0 17940 0 Current children cumulated CPU time (s) 6.04 Current children cumulated vsize (KiB) 128912 [startup+12.7124 s] /proc/loadavg: 1.07 1.04 1.00 2/38 7817 /proc/meminfo: memFree=804108/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129296 CPUtime=4.34 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 90567 0 7 0 398 36 0 0 25 0 1 0 53832317 132399104 30021 1283457024 134512640 135121179 4290234000 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32324 30021 321 149 0 31515 0 Current children cumulated CPU time (s) 12.44 Current children cumulated vsize (KiB) 131884 [startup+25.5065 s] /proc/loadavg: 1.06 1.04 1.00 2/38 7818 /proc/meminfo: memFree=804628/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=128736 CPUtime=17.1 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 325116 0 7 0 1574 136 0 0 25 0 1 0 53832317 131825664 29892 1283457024 134512640 135121179 4290234000 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32184 29892 321 149 0 31375 0 Current children cumulated CPU time (s) 25.2 Current children cumulated vsize (KiB) 131324 [startup+51.1148 s] /proc/loadavg: 1.04 1.04 1.00 2/38 7825 /proc/meminfo: memFree=804504/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=128740 CPUtime=42.67 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 791985 0 7 0 3948 319 0 0 25 0 1 0 53832317 131829760 29904 1283457024 134512640 135121179 4290234000 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32185 29904 321 149 0 31376 0 Current children cumulated CPU time (s) 50.77 Current children cumulated vsize (KiB) 131328 [startup+102.314 s] /proc/loadavg: 1.01 1.03 1.00 2/38 7825 /proc/meminfo: memFree=804256/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129160 CPUtime=93.83 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 1702963 0 7 0 8669 714 0 0 25 0 1 0 53832317 132259840 29999 1283457024 134512640 135121179 4290234000 18446744073709551615 134917867 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32290 29999 321 149 0 31481 0 Current children cumulated CPU time (s) 101.93 Current children cumulated vsize (KiB) 131748 [startup+162.306 s] /proc/loadavg: 1.00 1.02 1.00 2/40 7828 /proc/meminfo: memFree=803740/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129524 CPUtime=153.75 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 2797720 0 7 0 14171 1204 0 0 25 0 1 0 53832317 132632576 30035 1283457024 134512640 135121179 4290234000 18446744073709551615 134734459 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32381 30035 321 149 0 31572 0 Current children cumulated CPU time (s) 161.85 Current children cumulated vsize (KiB) 132112 [startup+222.306 s] /proc/loadavg: 1.00 1.02 1.00 2/40 7834 /proc/meminfo: memFree=803492/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129536 CPUtime=213.7 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 3879077 0 7 0 19721 1649 0 0 25 0 1 0 53832317 132644864 30056 1283457024 134512640 135121179 4290234000 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32384 30056 321 149 0 31575 0 Current children cumulated CPU time (s) 221.8 Current children cumulated vsize (KiB) 132124 [startup+282.306 s] /proc/loadavg: 1.00 1.01 1.00 2/39 7837 /proc/meminfo: memFree=803384/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129540 CPUtime=273.64 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 4948476 0 7 0 25272 2092 0 0 25 0 1 0 53832317 132648960 30072 1283457024 134512640 135121179 4290234000 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32385 30072 321 149 0 31576 0 Current children cumulated CPU time (s) 281.74 Current children cumulated vsize (KiB) 132128 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.609 s] /proc/loadavg: 1.00 1.01 1.00 2/39 7837 /proc/meminfo: memFree=803508/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129540 CPUtime=281.94 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 5092681 0 7 0 26042 2152 0 0 25 0 1 0 53832317 132648960 30074 1283457024 134512640 135121179 4290234000 18446744073709551615 134837447 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32385 30074 321 149 0 31576 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 132128 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.609 s] /proc/loadavg: 1.00 1.01 1.00 2/39 7837 /proc/meminfo: memFree=803508/1048576 swapFree=0/0 [pid=7806] ppid=7805 vsize=2588 CPUtime=8.1 /proc/7806/stat : 7806 (aspuncud-user-1) S 7805 7806 2160 34817 2160 4202496 568 63526 0 41 0 0 776 34 18 0 1 0 53832311 2650112 297 1283457024 134512640 135304128 4293148736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7806/statm: 647 297 251 194 0 34 0 [pid=7815] ppid=7806 vsize=129540 CPUtime=281.94 /proc/7815/stat : 7815 (unclasp) R 7806 7806 2160 34817 2160 4202496 5092681 0 7 0 26042 2152 0 0 25 0 1 0 53832317 132648960 30074 1283457024 134512640 135121179 4290234000 18446744073709551615 134837447 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7815/statm: 32385 30074 321 149 0 31576 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 132128 Child status: 0 Real time (s): 290.652 CPU time (s): 290.082 CPU user time (s): 268.193 CPU system time (s): 21.8894 CPU usage (%): 99.804 Max. virtual memory (cumulated for all children) (KiB): 248524 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.193 system time used= 21.8894 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5159151 page faults= 50 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 9342 involuntary context switches= 11150 runsolver used 0 second user time and 0 second system time The end