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/201108311143/aspuncud-user-1.0/rand375.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand375.cudf /home/misc2010/tmp/201108311143/aspuncud-user-1.0/rand375.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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.00 1.02 1.00 5/40 23478 /proc/meminfo: memFree=613728/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2592 CPUtime=0 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 62527906 2654208 280 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/23475/statm: 648 280 234 194 0 35 0 [pid=23476] ppid=23475 vsize=2592 CPUtime=0 /proc/23476/stat : 23476 (aspuncud-user-1) S 23475 23475 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 18 0 1 0 62527907 2654208 134 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/23476/statm: 648 134 87 194 0 35 0 [pid=23477] ppid=23476 vsize=2592 CPUtime=0 /proc/23477/stat : 23477 (aspuncud-user-1) R 23476 23475 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 62527907 2654208 151 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/23477/statm: 648 151 104 194 0 35 0 [pid=23478] ppid=23477 vsize=2592 CPUtime=0 /proc/23478/stat : 23478 (aspuncud-user-1) R 23477 23475 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 62527907 2654208 47 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/23478/statm: 648 47 0 194 0 35 0 [startup+0.174987 s] /proc/loadavg: 1.00 1.02 1.00 5/40 23478 /proc/meminfo: memFree=613728/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=0 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 576 1519 0 0 0 0 0 0 25 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.204994 s] /proc/loadavg: 1.00 1.02 1.00 5/40 23478 /proc/meminfo: memFree=613728/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=0 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 576 1519 0 0 0 0 0 0 25 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.30502 s] /proc/loadavg: 1.00 1.02 1.00 5/40 23478 /proc/meminfo: memFree=613728/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=0 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 576 1519 0 0 0 0 0 0 25 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.705112 s] /proc/loadavg: 1.00 1.02 1.00 5/40 23478 /proc/meminfo: memFree=613728/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=0 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 576 1519 0 0 0 0 0 0 25 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50532 s] /proc/loadavg: 1.24 1.07 1.02 2/41 23486 /proc/meminfo: memFree=596356/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=0 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 576 1519 0 0 0 0 0 0 25 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=3440 CPUtime=0 /proc/23484/stat : 23484 (unclasp) S 23475 23475 19908 34817 19908 4202496 407 0 0 0 0 0 0 0 25 0 1 0 62527907 3522560 271 1283457024 134512640 135121179 4290686560 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/23484/statm: 860 271 240 149 0 51 0 [pid=23485] ppid=23475 vsize=2696 CPUtime=0 /proc/23485/stat : 23485 (gringo) S 23475 23475 19908 34817 19908 4202496 409 0 0 0 0 0 0 0 25 0 1 0 62527908 2760704 281 1283457024 134512640 137056543 4288445376 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/23485/statm: 674 281 252 622 0 49 0 [pid=23486] ppid=23475 vsize=28112 CPUtime=1.49 /proc/23486/stat : 23486 (cudf2lp) R 23475 23475 19908 34817 19908 4202496 8072 0 0 0 145 4 0 0 25 0 1 0 62527908 28786688 6332 1283457024 134512640 135786343 4294816320 18446744073709551615 134566184 0 0 6 0 0 0 0 17 0 0 0 0 /proc/23486/statm: 7028 6332 128 311 0 6715 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 36844 [startup+3.10571 s] /proc/loadavg: 1.24 1.07 1.02 2/41 23486 /proc/meminfo: memFree=568952/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.5 /proc/23475/stat : 23475 (aspuncud-user-1) R 23474 23475 19908 34817 19908 4202496 577 15490 0 0 0 0 242 8 19 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=9012 CPUtime=0.56 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 2012 0 0 0 56 0 0 0 18 0 1 0 62527907 9228288 1717 1283457024 134512640 135121179 4290686560 18446744073709551615 134839033 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 2253 1717 323 149 0 1444 0 [pid=23485] ppid=23475 vsize=0 CPUtime=0.03 /proc/23485/stat : 23485 (gringo) Z 23475 23475 19908 34817 19908 4202508 867 0 0 0 3 0 0 0 18 0 1 0 62527908 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/23485/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 11608 [startup+6.30675 s] /proc/loadavg: 1.22 1.06 1.02 2/39 23486 /proc/meminfo: memFree=592048/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=26756 CPUtime=3.75 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 6677 0 0 0 371 4 0 0 25 0 1 0 62527907 27398144 6102 1283457024 134512640 135121179 4290686560 18446744073709551615 134977744 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 6689 6102 323 149 0 5880 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 29352 [startup+12.7088 s] /proc/loadavg: 1.21 1.06 1.02 2/38 23486 /proc/meminfo: memFree=578052/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=40816 CPUtime=10.15 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 10266 0 0 0 1010 5 0 0 25 0 1 0 62527907 41795584 9691 1283457024 134512640 135121179 4290686560 18446744073709551615 134891805 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 10204 9691 323 149 0 9395 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 43412 [startup+25.5045 s] /proc/loadavg: 1.16 1.06 1.01 2/38 23486 /proc/meminfo: memFree=522996/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=94756 CPUtime=22.91 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 23945 0 0 0 2278 13 0 0 25 0 1 0 62527907 97030144 23118 1283457024 134512640 135121179 4290686560 18446744073709551615 4159349829 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 23689 23118 323 149 0 22880 0 Current children cumulated CPU time (s) 25.44 Current children cumulated vsize (KiB) 97352 [startup+51.1127 s] /proc/loadavg: 1.10 1.05 1.01 2/38 23486 /proc/meminfo: memFree=446736/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=171108 CPUtime=48.49 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 45169 0 0 0 4833 16 0 0 25 0 1 0 62527907 175214592 42147 1283457024 134512640 135121179 4290686560 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 42777 42147 323 149 0 41968 0 Current children cumulated CPU time (s) 51.02 Current children cumulated vsize (KiB) 173704 [startup+102.309 s] /proc/loadavg: 1.04 1.04 1.01 2/38 23486 /proc/meminfo: memFree=323480/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=293132 CPUtime=99.65 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 86421 0 0 0 9935 30 0 0 25 0 1 0 62527907 300167168 72530 1283457024 134512640 135121179 4290686560 18446744073709551615 134873589 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 73283 72530 323 149 0 72474 0 Current children cumulated CPU time (s) 102.18 Current children cumulated vsize (KiB) 295728 [startup+162.308 s] /proc/loadavg: 1.01 1.03 1.00 2/38 23486 /proc/meminfo: memFree=181996/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=436960 CPUtime=159.58 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 134171 0 0 0 15913 45 0 0 25 0 1 0 62527907 447447040 108170 1283457024 134512640 135121179 4290686560 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 109240 108170 323 149 0 108431 0 Current children cumulated CPU time (s) 162.11 Current children cumulated vsize (KiB) 439556 [startup+222.31 s] /proc/loadavg: 1.00 1.02 1.00 2/38 23486 /proc/meminfo: memFree=63576/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=555088 CPUtime=219.52 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 199802 0 0 0 21881 71 0 0 25 0 1 0 62527907 568410112 137371 1283457024 134512640 135121179 4290686560 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 138772 137371 323 149 0 137963 0 Current children cumulated CPU time (s) 222.05 Current children cumulated vsize (KiB) 557684 [startup+282.309 s] /proc/loadavg: 1.00 1.02 1.00 2/40 23491 /proc/meminfo: memFree=5260/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=683080 CPUtime=279.44 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 280792 0 0 0 27851 93 0 0 25 0 1 0 62527907 699473920 169445 1283457024 134512640 135121179 4290686560 18446744073709551615 134873589 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 170770 169445 324 149 0 169961 0 Current children cumulated CPU time (s) 281.97 Current children cumulated vsize (KiB) 685676 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.412 s] /proc/loadavg: 1.00 1.02 1.00 2/40 23491 /proc/meminfo: memFree=5340/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=703328 CPUtime=287.53 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 292425 0 0 0 28658 95 0 0 25 0 1 0 62527907 720207872 174522 1283457024 134512640 135121179 4290686560 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 175832 174522 324 149 0 175023 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 705924 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.412 s] /proc/loadavg: 1.00 1.02 1.00 2/40 23491 /proc/meminfo: memFree=5340/1048576 swapFree=0/0 [pid=23475] ppid=23474 vsize=2596 CPUtime=2.53 /proc/23475/stat : 23475 (aspuncud-user-1) S 23474 23475 19908 34817 19908 4202496 577 16357 0 0 0 0 245 8 17 0 1 0 62527906 2658304 298 1283457024 134512640 135304128 4289459392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23475/statm: 649 298 251 194 0 36 0 [pid=23484] ppid=23475 vsize=703328 CPUtime=287.53 /proc/23484/stat : 23484 (unclasp) R 23475 23475 19908 34817 19908 4202496 292425 0 0 0 28658 95 0 0 25 0 1 0 62527907 720207872 174522 1283457024 134512640 135121179 4290686560 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/23484/statm: 175832 174522 324 149 0 175023 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 705924 Child status: 0 Real time (s): 290.469 CPU time (s): 290.138 CPU user time (s): 289.042 CPU system time (s): 1.09607 CPU usage (%): 99.8861 Max. virtual memory (cumulated for all children) (KiB): 706048 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.042 system time used= 1.09607 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 311769 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 98 involuntary context switches= 3716 runsolver used 0 second user time and 0.008 second system time The end