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/rand252.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand252.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand252.cudf.dudf-random.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.00 1.02 1.00 3/37 3317 /proc/meminfo: memFree=931596/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=3016 CPUtime=0 /proc/3317/stat : 3317 (runsolver) D 3316 3317 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 23 0 1 0 51453055 3088384 93 1283457024 134512640 134586868 4290854240 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/3317/statm: 754 93 62 19 0 53 0 [startup+0.107855 s] /proc/loadavg: 1.00 1.02 1.00 3/37 3317 /proc/meminfo: memFree=931596/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=0 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.207859 s] /proc/loadavg: 1.00 1.02 1.00 3/37 3317 /proc/meminfo: memFree=931596/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=0 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.307831 s] /proc/loadavg: 1.00 1.02 1.00 3/37 3317 /proc/meminfo: memFree=931596/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=0 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.707246 s] /proc/loadavg: 1.00 1.02 1.00 3/37 3317 /proc/meminfo: memFree=931596/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=0 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50741 s] /proc/loadavg: 1.00 1.02 1.00 2/41 3328 /proc/meminfo: memFree=912852/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=0 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=3444 CPUtime=0 /proc/3326/stat : 3326 (unclasp) S 3317 3317 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 24 0 1 0 51453060 3526656 272 1283457024 134512640 135121179 4293541680 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3326/statm: 861 272 240 149 0 52 0 [pid=3327] ppid=3317 vsize=2692 CPUtime=0 /proc/3327/stat : 3327 (gringo) S 3317 3317 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 51453060 2756608 281 1283457024 134512640 137056543 4287242912 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3327/statm: 673 281 252 622 0 48 0 [pid=3328] ppid=3317 vsize=27484 CPUtime=1.27 /proc/3328/stat : 3328 (cudf2lp) R 3317 3317 2160 34817 2160 4202496 7552 0 15 0 124 3 0 0 25 0 1 0 51453060 28143616 6071 1283457024 134512640 135786343 4287390512 18446744073709551615 135052923 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3328/statm: 6871 6071 128 311 0 6558 0 Current children cumulated CPU time (s) 1.27 Current children cumulated vsize (KiB) 36216 [startup+3.10762 s] /proc/loadavg: 1.00 1.02 1.00 2/41 3328 /proc/meminfo: memFree=888424/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=0 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=12740 CPUtime=0.07 /proc/3326/stat : 3326 (unclasp) S 3317 3317 2160 34817 2160 4202496 3082 0 6 0 7 0 0 0 18 0 1 0 51453060 13045760 2566 1283457024 134512640 135121179 4293541680 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3326/statm: 3185 2566 275 149 0 2376 0 [pid=3327] ppid=3317 vsize=16712 CPUtime=0.42 /proc/3327/stat : 3327 (gringo) R 3317 3317 2160 34817 2160 4202496 4627 0 23 0 40 2 0 0 18 0 1 0 51453060 17113088 3089 1283457024 134512640 137056543 4287242912 18446744073709551615 136312769 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3327/statm: 4178 3089 253 622 0 3553 0 [pid=3328] ppid=3317 vsize=43884 CPUtime=2.36 /proc/3328/stat : 3328 (cudf2lp) R 3317 3317 2160 34817 2160 4202496 13527 0 15 0 230 6 0 0 25 0 1 0 51453060 44937216 10776 1283457024 134512640 135786343 4287390512 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3328/statm: 10971 10776 139 311 0 10658 0 Current children cumulated CPU time (s) 2.85 Current children cumulated vsize (KiB) 75932 [startup+6.30828 s] /proc/loadavg: 1.00 1.02 1.00 3/41 3328 /proc/meminfo: memFree=795052/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=3.01 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 15047 0 18 0 0 293 8 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=54252 CPUtime=0.28 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 15568 0 6 0 22 6 0 0 18 0 1 0 51453060 55554048 12756 1283457024 134512640 135121179 4293541680 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 13563 12756 276 149 0 12754 0 [pid=3327] ppid=3317 vsize=75712 CPUtime=2.76 /proc/3327/stat : 3327 (gringo) R 3317 3317 2160 34817 2160 4202496 25384 0 23 0 259 17 0 0 18 0 1 0 51453060 77529088 15252 1283457024 134512640 137056543 4287242912 18446744073709551615 134608504 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3327/statm: 18928 15252 268 622 0 18303 0 Current children cumulated CPU time (s) 6.05 Current children cumulated vsize (KiB) 132560 [startup+12.7116 s] /proc/loadavg: 1.07 1.03 1.00 2/39 3328 /proc/meminfo: memFree=806812/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=127880 CPUtime=4.66 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 92040 0 7 0 428 38 0 0 25 0 1 0 51453060 130949120 29639 1283457024 134512640 135121179 4293541680 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 31970 29639 319 149 0 31161 0 Current children cumulated CPU time (s) 12.43 Current children cumulated vsize (KiB) 130476 [startup+25.5061 s] /proc/loadavg: 1.06 1.03 1.00 2/39 3328 /proc/meminfo: memFree=809168/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=127884 CPUtime=17.44 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 330376 0 7 0 1592 152 0 0 25 0 1 0 51453060 130953216 29647 1283457024 134512640 135121179 4293541680 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 31971 29647 319 149 0 31162 0 Current children cumulated CPU time (s) 25.21 Current children cumulated vsize (KiB) 130480 [startup+51.1064 s] /proc/loadavg: 1.04 1.03 1.00 2/38 3328 /proc/meminfo: memFree=809176/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=132188 CPUtime=43.03 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 799332 0 7 0 3959 344 0 0 25 0 1 0 51453060 135360512 30714 1283457024 134512640 135121179 4293541680 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 33047 30714 319 149 0 32238 0 Current children cumulated CPU time (s) 50.8 Current children cumulated vsize (KiB) 134784 [startup+102.31 s] /proc/loadavg: 1.01 1.02 1.00 2/38 3328 /proc/meminfo: memFree=808928/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=130988 CPUtime=94.2 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 1717510 0 7 0 8674 746 0 0 25 0 1 0 51453060 134131712 29843 1283457024 134512640 135121179 4293541680 18446744073709551615 134990465 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 32747 29843 319 149 0 31938 0 Current children cumulated CPU time (s) 101.97 Current children cumulated vsize (KiB) 133584 [startup+162.31 s] /proc/loadavg: 1.00 1.02 1.00 2/38 3328 /proc/meminfo: memFree=806572/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=130992 CPUtime=154.16 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 2781716 0 7 0 14227 1189 0 0 25 0 1 0 51453060 134135808 30470 1283457024 134512640 135121179 4293541680 18446744073709551615 134977957 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 32748 30470 321 149 0 31939 0 Current children cumulated CPU time (s) 161.93 Current children cumulated vsize (KiB) 133588 [startup+222.309 s] /proc/loadavg: 1.00 1.01 1.00 2/38 3328 /proc/meminfo: memFree=808432/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=127912 CPUtime=214.11 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 3826460 0 7 0 19822 1589 0 0 25 0 1 0 51453060 130981888 29720 1283457024 134512640 135121179 4293541680 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 31978 29720 321 149 0 31169 0 Current children cumulated CPU time (s) 221.88 Current children cumulated vsize (KiB) 130508 [startup+282.313 s] /proc/loadavg: 1.00 1.01 1.00 2/40 3330 /proc/meminfo: memFree=804068/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=131016 CPUtime=274.05 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 4846328 0 7 0 25377 2028 0 0 25 0 1 0 51453060 134160384 30512 1283457024 134512640 135121179 4293541680 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 32754 30512 321 149 0 31945 0 Current children cumulated CPU time (s) 281.82 Current children cumulated vsize (KiB) 133612 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.508 s] /proc/loadavg: 1.00 1.00 1.00 2/40 3331 /proc/meminfo: memFree=808160/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=127928 CPUtime=282.24 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 4987256 0 7 0 26136 2088 0 0 25 0 1 0 51453060 130998272 29743 1283457024 134512640 135121179 4293541680 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 31982 29743 321 149 0 31173 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 130524 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.508 s] /proc/loadavg: 1.00 1.00 1.00 2/40 3331 /proc/meminfo: memFree=808160/1048576 swapFree=0/0 [pid=3317] ppid=3316 vsize=2596 CPUtime=7.77 /proc/3317/stat : 3317 (aspuncud-user-1) S 3316 3317 2160 34817 2160 4202496 573 62984 0 41 0 0 738 39 18 0 1 0 51453055 2658304 298 1283457024 134512640 135304128 4288570352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3317/statm: 649 298 251 194 0 36 0 [pid=3326] ppid=3317 vsize=127928 CPUtime=282.24 /proc/3326/stat : 3326 (unclasp) R 3317 3317 2160 34817 2160 4202496 4987256 0 7 0 26136 2088 0 0 25 0 1 0 51453060 130998272 29743 1283457024 134512640 135121179 4293541680 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3326/statm: 31982 29743 321 149 0 31173 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 130524 Child status: 0 Real time (s): 290.546 CPU time (s): 290.042 CPU user time (s): 268.753 CPU system time (s): 21.2893 CPU usage (%): 99.8266 Max. virtual memory (cumulated for all children) (KiB): 247960 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.753 system time used= 21.2893 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5053219 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= 9538 involuntary context switches= 11247 runsolver used 0 second user time and 0 second system time The end