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/rand440.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand440.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand440.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.06 1.02 2/36 5908 /proc/meminfo: memFree=932064/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=3024 CPUtime=0 /proc/5908/stat : 5908 (runsolver) D 5907 5908 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 52878757 3096576 94 1283457024 134512640 134586868 4287345152 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/5908/statm: 756 94 62 19 0 55 0 [startup+0.118846 s] /proc/loadavg: 1.00 1.06 1.02 2/36 5908 /proc/meminfo: memFree=932064/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=0 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.206848 s] /proc/loadavg: 1.00 1.06 1.02 2/36 5908 /proc/meminfo: memFree=932064/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=0 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.306856 s] /proc/loadavg: 1.00 1.06 1.02 2/36 5908 /proc/meminfo: memFree=932064/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=0 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.708978 s] /proc/loadavg: 1.00 1.06 1.02 2/36 5908 /proc/meminfo: memFree=932064/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=0 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50921 s] /proc/loadavg: 1.08 1.07 1.03 2/40 5919 /proc/meminfo: memFree=913260/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=0 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=3444 CPUtime=0 /proc/5917/stat : 5917 (unclasp) S 5908 5908 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 52878762 3526656 272 1283457024 134512640 135121179 4292183472 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5917/statm: 861 272 240 149 0 52 0 [pid=5918] ppid=5908 vsize=2696 CPUtime=0 /proc/5918/stat : 5918 (gringo) S 5908 5908 2160 34817 2160 4202496 386 0 22 0 0 0 0 0 23 0 1 0 52878762 2760704 281 1283457024 134512640 137056543 4293421184 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5918/statm: 674 281 252 622 0 49 0 [pid=5919] ppid=5908 vsize=27484 CPUtime=1.26 /proc/5919/stat : 5919 (cudf2lp) R 5908 5908 2160 34817 2160 4202496 7544 0 15 0 122 4 0 0 25 0 1 0 52878762 28143616 6064 1283457024 134512640 135786343 4292821088 18446744073709551615 135199569 0 0 6 0 0 0 0 17 0 0 0 0 /proc/5919/statm: 6871 6064 128 311 0 6558 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 36216 [startup+3.10967 s] /proc/loadavg: 1.08 1.07 1.03 2/40 5919 /proc/meminfo: memFree=889080/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=0 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=12476 CPUtime=0.03 /proc/5917/stat : 5917 (unclasp) S 5908 5908 2160 34817 2160 4202496 3012 0 6 0 3 0 0 0 18 0 1 0 52878762 12775424 2497 1283457024 134512640 135121179 4292183472 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5917/statm: 3119 2497 275 149 0 2310 0 [pid=5918] ppid=5908 vsize=17328 CPUtime=0.47 /proc/5918/stat : 5918 (gringo) R 5908 5908 2160 34817 2160 4202496 4711 0 22 0 45 2 0 0 18 0 1 0 52878762 17743872 3173 1283457024 134512640 137056543 4293421184 18446744073709551615 134609525 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5918/statm: 4332 3173 253 622 0 3707 0 [pid=5919] ppid=5908 vsize=43700 CPUtime=2.37 /proc/5919/stat : 5919 (cudf2lp) R 5908 5908 2160 34817 2160 4202496 13482 0 15 0 228 9 0 0 25 0 1 0 52878762 44748800 10732 1283457024 134512640 135786343 4292821088 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/5919/statm: 10925 10732 139 311 0 10612 0 Current children cumulated CPU time (s) 2.87 Current children cumulated vsize (KiB) 76096 [startup+6.3106 s] /proc/loadavg: 1.23 1.10 1.04 2/40 5919 /proc/meminfo: memFree=795956/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=3.1 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 15004 0 18 0 0 297 13 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=52988 CPUtime=0.29 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 15209 0 6 0 24 5 0 0 18 0 1 0 52878762 54259712 12398 1283457024 134512640 135121179 4292183472 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 13247 12398 276 149 0 12438 0 [pid=5918] ppid=5908 vsize=74896 CPUtime=2.66 /proc/5918/stat : 5918 (gringo) R 5908 5908 2160 34817 2160 4202496 25209 0 22 0 257 9 0 0 18 0 1 0 52878762 76693504 15077 1283457024 134512640 137056543 4293421184 18446744073709551615 135851699 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5918/statm: 18724 15077 268 622 0 18099 0 Current children cumulated CPU time (s) 6.05 Current children cumulated vsize (KiB) 130476 [startup+12.7049 s] /proc/loadavg: 1.21 1.10 1.04 2/38 5919 /proc/meminfo: memFree=803188/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131132 CPUtime=4.51 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 90008 0 7 0 415 36 0 0 25 0 1 0 52878762 134279168 30449 1283457024 134512640 135121179 4292183472 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32783 30449 319 149 0 31974 0 Current children cumulated CPU time (s) 12.44 Current children cumulated vsize (KiB) 133724 [startup+25.5097 s] /proc/loadavg: 1.18 1.10 1.04 2/38 5919 /proc/meminfo: memFree=806412/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131132 CPUtime=17.31 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 329568 0 7 0 1588 143 0 0 25 0 1 0 52878762 134279168 30458 1283457024 134512640 135121179 4292183472 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32783 30458 319 149 0 31974 0 Current children cumulated CPU time (s) 25.24 Current children cumulated vsize (KiB) 133724 [startup+51.109 s] /proc/loadavg: 1.11 1.09 1.03 2/38 5919 /proc/meminfo: memFree=806288/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131144 CPUtime=42.87 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 794548 0 7 0 3949 338 0 0 25 0 1 0 52878762 134291456 30470 1283457024 134512640 135121179 4292183472 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32786 30470 319 149 0 31977 0 Current children cumulated CPU time (s) 50.8 Current children cumulated vsize (KiB) 133736 [startup+102.307 s] /proc/loadavg: 1.10 1.09 1.04 2/40 5925 /proc/meminfo: memFree=806016/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131148 CPUtime=93.92 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 1704733 0 7 0 8676 716 0 0 25 0 1 0 52878762 134295552 30476 1283457024 134512640 135121179 4292183472 18446744073709551615 4159398981 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32787 30476 321 149 0 31978 0 Current children cumulated CPU time (s) 101.85 Current children cumulated vsize (KiB) 133740 [startup+162.311 s] /proc/loadavg: 1.08 1.08 1.03 2/40 5930 /proc/meminfo: memFree=803164/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=134284 CPUtime=153.85 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 2759520 0 7 0 14211 1174 0 0 25 0 1 0 52878762 137506816 31291 1283457024 134512640 135121179 4292183472 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 33571 31291 321 149 0 32762 0 Current children cumulated CPU time (s) 161.78 Current children cumulated vsize (KiB) 136876 [startup+222.312 s] /proc/loadavg: 1.03 1.07 1.03 2/38 5930 /proc/meminfo: memFree=803064/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131164 CPUtime=213.8 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 3780377 0 7 0 19744 1636 0 0 25 0 1 0 52878762 134311936 30533 1283457024 134512640 135121179 4292183472 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32791 30533 321 149 0 31982 0 Current children cumulated CPU time (s) 221.73 Current children cumulated vsize (KiB) 133756 [startup+282.302 s] /proc/loadavg: 1.01 1.05 1.02 2/38 5930 /proc/meminfo: memFree=805544/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131536 CPUtime=273.75 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 4802167 0 7 0 25321 2054 0 0 25 0 1 0 52878762 134692864 30550 1283457024 134512640 135121179 4292183472 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32884 30550 321 149 0 32075 0 Current children cumulated CPU time (s) 281.68 Current children cumulated vsize (KiB) 134128 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.715 s] /proc/loadavg: 1.01 1.05 1.02 2/38 5930 /proc/meminfo: memFree=805544/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131540 CPUtime=282.16 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 4942396 0 7 0 26106 2110 0 0 25 0 1 0 52878762 134696960 30528 1283457024 134512640 135121179 4292183472 18446744073709551615 134747654 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32885 30528 321 149 0 32076 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 134132 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.715 s] /proc/loadavg: 1.01 1.05 1.02 2/38 5930 /proc/meminfo: memFree=805544/1048576 swapFree=0/0 [pid=5908] ppid=5907 vsize=2592 CPUtime=7.93 /proc/5908/stat : 5908 (aspuncud-user-1) S 5907 5908 2160 34817 2160 4202496 572 63407 0 40 0 0 763 30 18 0 1 0 52878757 2654208 297 1283457024 134512640 135304128 4287970128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5908/statm: 648 297 251 194 0 35 0 [pid=5917] ppid=5908 vsize=131540 CPUtime=282.16 /proc/5917/stat : 5917 (unclasp) R 5908 5908 2160 34817 2160 4202496 4942396 0 7 0 26106 2110 0 0 25 0 1 0 52878762 134696960 30528 1283457024 134512640 135121179 4292183472 18446744073709551615 134747654 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5917/statm: 32885 30528 321 149 0 32076 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 134132 Child status: 0 Real time (s): 290.75 CPU time (s): 290.126 CPU user time (s): 268.697 CPU system time (s): 21.4293 CPU usage (%): 99.7853 Max. virtual memory (cumulated for all children) (KiB): 250920 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.697 system time used= 21.4293 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5008758 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= 9594 involuntary context switches= 11314 runsolver used 0 second user time and 0.008 second system time The end