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/rand733.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand733.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand733.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 1/33 10006 /proc/meminfo: memFree=947676/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=3020 CPUtime=0 /proc/10006/stat : 10006 (runsolver) D 10005 10006 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 55029025 3092480 94 1283457024 134512640 134586868 4287259120 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/10006/statm: 755 94 62 19 0 54 0 [startup+0.186146 s] /proc/loadavg: 1.00 1.02 1.00 1/33 10006 /proc/meminfo: memFree=947676/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=0 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 1521 0 3 0 0 0 0 25 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.206153 s] /proc/loadavg: 1.00 1.02 1.00 1/33 10006 /proc/meminfo: memFree=947676/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=0 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 1521 0 3 0 0 0 0 25 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.312443 s] /proc/loadavg: 1.00 1.02 1.00 1/33 10006 /proc/meminfo: memFree=947676/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=0 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 1521 0 3 0 0 0 0 25 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.712559 s] /proc/loadavg: 1.00 1.02 1.00 1/33 10006 /proc/meminfo: memFree=947676/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=0 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 1521 0 3 0 0 0 0 25 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.51274 s] /proc/loadavg: 1.00 1.02 1.00 2/37 10017 /proc/meminfo: memFree=928872/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=0 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 1521 0 3 0 0 0 0 25 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=4252 CPUtime=0 /proc/10015/stat : 10015 (unclasp) S 10006 10006 2160 34817 2160 4202496 631 0 6 0 0 0 0 0 18 0 1 0 55029030 4354048 502 1283457024 134512640 135121179 4293071504 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10015/statm: 1063 502 275 149 0 254 0 [pid=10016] ppid=10006 vsize=3888 CPUtime=0.04 /proc/10016/stat : 10016 (gringo) R 10006 10006 2160 34817 2160 4202496 695 0 23 0 4 0 0 0 18 0 1 0 55029030 3981312 558 1283457024 134512640 137056543 4293294544 18446744073709551615 136301799 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10016/statm: 972 558 253 622 0 347 0 [pid=10017] ppid=10006 vsize=26528 CPUtime=1.25 /proc/10017/stat : 10017 (cudf2lp) R 10006 10006 2160 34817 2160 4202496 8639 0 15 0 120 5 0 0 25 0 1 0 55029030 27164672 6415 1283457024 134512640 135786343 4293077200 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10017/statm: 6632 6415 139 311 0 6319 0 Current children cumulated CPU time (s) 1.29 Current children cumulated vsize (KiB) 37256 [startup+3.11297 s] /proc/loadavg: 1.00 1.02 1.00 3/37 10017 /proc/meminfo: memFree=894524/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=0 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 1521 0 3 0 0 0 0 25 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=26392 CPUtime=0.11 /proc/10015/stat : 10015 (unclasp) S 10006 10006 2160 34817 2160 4202496 7138 0 6 0 8 3 0 0 18 0 1 0 55029030 27025408 5945 1283457024 134512640 135121179 4293071504 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10015/statm: 6598 5945 275 149 0 5789 0 [pid=10016] ppid=10006 vsize=36696 CPUtime=1.24 /proc/10016/stat : 10016 (gringo) R 10006 10006 2160 34817 2160 4202496 11352 0 23 0 118 6 0 0 18 0 1 0 55029030 37576704 7218 1283457024 134512640 137056543 4293294544 18446744073709551615 134916360 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10016/statm: 9174 7218 253 622 0 8549 0 [pid=10017] ppid=10006 vsize=26528 CPUtime=1.55 /proc/10017/stat : 10017 (cudf2lp) R 10006 10006 2160 34817 2160 4202496 8639 0 15 0 150 5 0 0 25 0 1 0 55029030 27164672 6415 1283457024 134512640 135786343 4293077200 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10017/statm: 6632 6415 139 311 0 6319 0 Current children cumulated CPU time (s) 2.9 Current children cumulated vsize (KiB) 92204 [startup+6.3135 s] /proc/loadavg: 1.08 1.03 1.01 2/35 10017 /proc/meminfo: memFree=881908/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=66240 CPUtime=1.97 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 31973 0 7 0 184 13 0 0 20 0 1 0 55029030 67829760 15160 1283457024 134512640 135121179 4293071504 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16560 15160 319 149 0 15751 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 68828 [startup+12.7056 s] /proc/loadavg: 1.07 1.03 1.00 2/35 10017 /proc/meminfo: memFree=882412/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=68696 CPUtime=8.36 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 118780 0 7 0 782 54 0 0 25 0 1 0 55029030 70344704 15765 1283457024 134512640 135121179 4293071504 18446744073709551615 4158057238 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 17174 15765 319 149 0 16365 0 Current children cumulated CPU time (s) 12.48 Current children cumulated vsize (KiB) 71284 [startup+25.5099 s] /proc/loadavg: 1.06 1.03 1.00 2/35 10017 /proc/meminfo: memFree=883652/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=67288 CPUtime=21.15 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 289647 0 7 0 1987 128 0 0 25 0 1 0 55029030 68902912 15436 1283457024 134512640 135121179 4293071504 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16822 15436 321 149 0 16013 0 Current children cumulated CPU time (s) 25.27 Current children cumulated vsize (KiB) 69876 [startup+51.1091 s] /proc/loadavg: 1.04 1.03 1.00 2/35 10017 /proc/meminfo: memFree=882908/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=65740 CPUtime=46.75 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 601360 0 7 0 4411 264 0 0 25 0 1 0 55029030 67317760 15117 1283457024 134512640 135121179 4293071504 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16435 15117 321 149 0 15626 0 Current children cumulated CPU time (s) 50.87 Current children cumulated vsize (KiB) 68328 [startup+102.307 s] /proc/loadavg: 1.01 1.02 1.00 2/35 10017 /proc/meminfo: memFree=882660/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=66264 CPUtime=97.9 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 1164820 0 7 0 9276 514 0 0 25 0 1 0 55029030 67854336 15275 1283457024 134512640 135121179 4293071504 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16566 15275 321 149 0 15757 0 Current children cumulated CPU time (s) 102.02 Current children cumulated vsize (KiB) 68852 [startup+162.311 s] /proc/loadavg: 1.00 1.02 1.00 2/35 10017 /proc/meminfo: memFree=882908/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=67832 CPUtime=157.85 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 1801158 0 7 0 14970 815 0 0 25 0 1 0 55029030 69459968 15466 1283457024 134512640 135121179 4293071504 18446744073709551615 134990503 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16958 15466 321 149 0 16149 0 Current children cumulated CPU time (s) 161.97 Current children cumulated vsize (KiB) 70420 [startup+222.305 s] /proc/loadavg: 1.00 1.01 1.00 2/35 10017 /proc/meminfo: memFree=882164/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=65976 CPUtime=217.82 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 2514420 0 7 0 20649 1133 0 0 25 0 1 0 55029030 67559424 15184 1283457024 134512640 135121179 4293071504 18446744073709551615 134891093 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16494 15184 321 149 0 15685 0 Current children cumulated CPU time (s) 221.94 Current children cumulated vsize (KiB) 68564 [startup+282.308 s] /proc/loadavg: 1.00 1.00 1.00 2/37 10024 /proc/meminfo: memFree=881768/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=66260 CPUtime=277.76 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 3311124 0 7 0 26292 1484 0 0 25 0 1 0 55029030 67850240 15301 1283457024 134512640 135121179 4293071504 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16565 15301 321 149 0 15756 0 Current children cumulated CPU time (s) 281.88 Current children cumulated vsize (KiB) 68848 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.511 s] /proc/loadavg: 1.00 1.00 1.00 2/37 10025 /proc/meminfo: memFree=882016/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=66264 CPUtime=285.96 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 3418278 0 7 0 27071 1525 0 0 25 0 1 0 55029030 67854336 15305 1283457024 134512640 135121179 4293071504 18446744073709551615 134837447 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16566 15305 321 149 0 15757 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 68852 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.511 s] /proc/loadavg: 1.00 1.00 1.00 2/37 10025 /proc/meminfo: memFree=882016/1048576 swapFree=0/0 [pid=10006] ppid=10005 vsize=2588 CPUtime=4.12 /proc/10006/stat : 10006 (aspuncud-user-1) S 10005 10006 2160 34817 2160 4202496 567 37580 0 41 0 0 393 19 18 0 1 0 55029025 2650112 297 1283457024 134512640 135304128 4290993728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10006/statm: 647 297 251 194 0 34 0 [pid=10015] ppid=10006 vsize=66264 CPUtime=285.96 /proc/10015/stat : 10015 (unclasp) R 10006 10006 2160 34817 2160 4202496 3418278 0 7 0 27071 1525 0 0 25 0 1 0 55029030 67854336 15305 1283457024 134512640 135121179 4293071504 18446744073709551615 134837447 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10015/statm: 16566 15305 321 149 0 15757 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 68852 Child status: 0 Real time (s): 290.587 CPU time (s): 290.11 CPU user time (s): 274.657 CPU system time (s): 15.453 CPU usage (%): 99.8358 Max. virtual memory (cumulated for all children) (KiB): 145040 getrusage(RUSAGE_CHILDREN,...) data: user time used= 274.657 system time used= 15.453 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 3458801 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= 4299 involuntary context switches= 6848 runsolver used 0 second user time and 0.004 second system time The end