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/rand66.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand66.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand66.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.00 1.00 2/37 8486 /proc/meminfo: memFree=943864/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=3020 CPUtime=0 /proc/8486/stat : 8486 (runsolver) D 8485 8486 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 54179252 3092480 94 1283457024 134512640 134586868 4293591040 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/8486/statm: 755 94 62 19 0 54 0 [startup+0.146388 s] /proc/loadavg: 1.00 1.00 1.00 2/37 8486 /proc/meminfo: memFree=943864/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=0 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.206369 s] /proc/loadavg: 1.00 1.00 1.00 2/37 8486 /proc/meminfo: memFree=943864/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=0 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.306382 s] /proc/loadavg: 1.00 1.00 1.00 2/37 8486 /proc/meminfo: memFree=943864/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=0 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.712311 s] /proc/loadavg: 1.00 1.00 1.00 2/37 8486 /proc/meminfo: memFree=943864/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=0 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.514 s] /proc/loadavg: 1.00 1.00 1.00 2/41 8497 /proc/meminfo: memFree=925616/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=0 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=3580 CPUtime=0 /proc/8495/stat : 8495 (unclasp) S 8486 8486 2160 34817 2160 4202496 468 0 6 0 0 0 0 0 18 0 1 0 54179257 3665920 339 1283457024 134512640 135121179 4294802112 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8495/statm: 895 339 275 149 0 86 0 [pid=8496] ppid=8486 vsize=3004 CPUtime=0 /proc/8496/stat : 8496 (gringo) S 8486 8486 2160 34817 2160 4202496 449 0 22 0 0 0 0 0 18 0 1 0 54179257 3076096 344 1283457024 134512640 137056543 4294803744 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8496/statm: 751 344 253 622 0 126 0 [pid=8497] ppid=8486 vsize=26528 CPUtime=1.27 /proc/8497/stat : 8497 (cudf2lp) R 8486 8486 2160 34817 2160 4202496 8639 0 15 0 126 1 0 0 25 0 1 0 54179257 27164672 6415 1283457024 134512640 135786343 4294801008 18446744073709551615 135219490 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8497/statm: 6632 6415 139 311 0 6319 0 Current children cumulated CPU time (s) 1.27 Current children cumulated vsize (KiB) 35700 [startup+3.10442 s] /proc/loadavg: 1.00 1.00 1.00 3/41 8497 /proc/meminfo: memFree=892136/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=0 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=25464 CPUtime=0.05 /proc/8495/stat : 8495 (unclasp) S 8486 8486 2160 34817 2160 4202496 6906 0 6 0 5 0 0 0 18 0 1 0 54179257 26075136 5713 1283457024 134512640 135121179 4294802112 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8495/statm: 6366 5713 275 149 0 5557 0 [pid=8496] ppid=8486 vsize=36276 CPUtime=1.31 /proc/8496/stat : 8496 (gringo) R 8486 8486 2160 34817 2160 4202496 11109 0 22 0 122 9 0 0 18 0 1 0 54179257 37146624 6974 1283457024 134512640 137056543 4294803744 18446744073709551615 136099496 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8496/statm: 9069 6974 253 622 0 8444 0 [pid=8497] ppid=8486 vsize=26528 CPUtime=1.48 /proc/8497/stat : 8497 (cudf2lp) R 8486 8486 2160 34817 2160 4202496 8639 0 15 0 147 1 0 0 25 0 1 0 54179257 27164672 6415 1283457024 134512640 135786343 4294801008 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8497/statm: 6632 6415 139 311 0 6319 0 Current children cumulated CPU time (s) 2.84 Current children cumulated vsize (KiB) 90856 [startup+6.30715 s] /proc/loadavg: 1.00 1.00 1.00 2/39 8497 /proc/meminfo: memFree=878096/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=68516 CPUtime=1.83 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 31362 0 7 0 176 7 0 0 20 0 1 0 54179257 70160384 15733 1283457024 134512640 135121179 4294802112 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 17129 15733 319 149 0 16320 0 Current children cumulated CPU time (s) 6.03 Current children cumulated vsize (KiB) 71104 [startup+12.7097 s] /proc/loadavg: 1.00 1.00 1.00 2/39 8497 /proc/meminfo: memFree=879716/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=68016 CPUtime=8.23 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 119770 0 7 0 790 33 0 0 25 0 1 0 54179257 69648384 15605 1283457024 134512640 135121179 4294802112 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 17004 15605 319 149 0 16195 0 Current children cumulated CPU time (s) 12.43 Current children cumulated vsize (KiB) 70604 [startup+25.5137 s] /proc/loadavg: 1.00 1.00 1.00 2/39 8497 /proc/meminfo: memFree=877732/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=66472 CPUtime=21.02 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 293476 0 7 0 1990 112 0 0 25 0 1 0 54179257 68067328 15234 1283457024 134512640 135121179 4294802112 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 16618 15234 321 149 0 15809 0 Current children cumulated CPU time (s) 25.22 Current children cumulated vsize (KiB) 69060 [startup+51.1132 s] /proc/loadavg: 1.00 1.00 1.00 2/39 8497 /proc/meminfo: memFree=877856/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=67516 CPUtime=46.61 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 609770 0 7 0 4419 242 0 0 25 0 1 0 54179257 69136384 15564 1283457024 134512640 135121179 4294802112 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 16879 15564 321 149 0 16070 0 Current children cumulated CPU time (s) 50.81 Current children cumulated vsize (KiB) 70104 [startup+102.312 s] /proc/loadavg: 1.00 1.00 1.00 2/38 8497 /proc/meminfo: memFree=879104/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=65964 CPUtime=97.75 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 1169556 0 7 0 9304 471 0 0 25 0 1 0 54179257 67547136 15202 1283457024 134512640 135121179 4294802112 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 16491 15202 321 149 0 15682 0 Current children cumulated CPU time (s) 101.95 Current children cumulated vsize (KiB) 68552 [startup+162.305 s] /proc/loadavg: 1.00 1.00 1.00 2/38 8497 /proc/meminfo: memFree=877244/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=65964 CPUtime=157.65 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 1803584 0 7 0 15040 725 0 0 25 0 1 0 54179257 67547136 15230 1283457024 134512640 135121179 4294802112 18446744073709551615 134837447 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 16491 15230 321 149 0 15682 0 Current children cumulated CPU time (s) 161.85 Current children cumulated vsize (KiB) 68552 [startup+222.305 s] /proc/loadavg: 1.00 1.00 1.00 2/38 8497 /proc/meminfo: memFree=878112/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=65928 CPUtime=217.61 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 2537773 0 7 0 20719 1042 0 0 25 0 1 0 54179257 67510272 15234 1283457024 134512640 135121179 4294802112 18446744073709551615 4159349861 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 16482 15234 321 149 0 15673 0 Current children cumulated CPU time (s) 221.81 Current children cumulated vsize (KiB) 68516 [startup+282.31 s] /proc/loadavg: 1.00 1.00 1.00 2/38 8497 /proc/meminfo: memFree=877988/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=66484 CPUtime=277.53 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 3334014 0 7 0 26365 1388 0 0 25 0 1 0 54179257 68079616 15360 1283457024 134512640 135121179 4294802112 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 16621 15360 321 149 0 15812 0 Current children cumulated CPU time (s) 281.73 Current children cumulated vsize (KiB) 69072 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.613 s] /proc/loadavg: 1.00 1.00 1.00 2/38 8497 /proc/meminfo: memFree=875756/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=69152 CPUtime=285.83 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 3441299 0 7 0 27139 1444 0 0 25 0 1 0 54179257 70811648 15977 1283457024 134512640 135121179 4294802112 18446744073709551615 4157815574 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 17288 15977 321 149 0 16479 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 71740 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.613 s] /proc/loadavg: 1.00 1.00 1.00 2/38 8497 /proc/meminfo: memFree=875756/1048576 swapFree=0/0 [pid=8486] ppid=8485 vsize=2588 CPUtime=4.2 /proc/8486/stat : 8486 (aspuncud-user-1) S 8485 8486 2160 34817 2160 4202496 572 37580 0 40 0 0 399 21 18 0 1 0 54179252 2650112 297 1283457024 134512640 135304128 4287818544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8486/statm: 647 297 251 194 0 34 0 [pid=8495] ppid=8486 vsize=69152 CPUtime=285.83 /proc/8495/stat : 8495 (unclasp) R 8486 8486 2160 34817 2160 4202496 3441299 0 7 0 27139 1444 0 0 25 0 1 0 54179257 70811648 15977 1283457024 134512640 135121179 4294802112 18446744073709551615 4157815574 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8495/statm: 17288 15977 321 149 0 16479 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 71740 Child status: 0 Real time (s): 290.654 CPU time (s): 290.074 CPU user time (s): 275.389 CPU system time (s): 14.6849 CPU usage (%): 99.8005 Max. virtual memory (cumulated for all children) (KiB): 149472 getrusage(RUSAGE_CHILDREN,...) data: user time used= 275.389 system time used= 14.6849 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 3481830 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= 4314 involuntary context switches= 6845 runsolver used 0 second user time and 0 second system time The end