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/201012081719/cudf2pbo4paranoid-1.0/rand165.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand165.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand165.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.result 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: 0.84 0.93 0.90 3/39 9804 /proc/meminfo: memFree=118428/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=0 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892585367 2629632 278 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 278 238 194 0 28 0 [pid=9804] ppid=9803 vsize=1916 CPUtime=0 /proc/9804/stat : 9804 (cudf_msu32) D 9803 9803 9023 34817 9081 4202496 263 0 0 0 0 0 0 0 18 0 1 0 892585367 1961984 156 1283457024 134512640 136125367 4286909104 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0 /proc/9804/statm: 479 156 133 394 0 83 0 [startup+0.200283 s] /proc/loadavg: 0.84 0.93 0.90 3/39 9804 /proc/meminfo: memFree=118428/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=0 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892585367 2629632 278 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 278 238 194 0 28 0 [pid=9804] ppid=9803 vsize=9776 CPUtime=0.17 /proc/9804/stat : 9804 (cudf_msu32) R 9803 9803 9023 34817 9081 4202496 2245 0 0 0 17 0 0 0 25 0 1 0 892585367 10010624 2138 1283457024 134512640 136125367 4286909104 18446744073709551615 134718131 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9804/statm: 2444 2138 143 394 0 2048 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 12344 [startup+0.304294 s] /proc/loadavg: 0.84 0.93 0.90 3/39 9804 /proc/meminfo: memFree=118428/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=0 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892585367 2629632 278 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 278 238 194 0 28 0 [pid=9804] ppid=9803 vsize=13356 CPUtime=0.27 /proc/9804/stat : 9804 (cudf_msu32) R 9803 9803 9023 34817 9081 4202496 3135 0 0 0 27 0 0 0 25 0 1 0 892585367 13676544 3028 1283457024 134512640 136125367 4286909104 18446744073709551615 134718192 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9804/statm: 3339 3028 144 394 0 2943 0 Current children cumulated CPU time (s) 0.27 Current children cumulated vsize (KiB) 15924 [startup+0.4043 s] /proc/loadavg: 0.84 0.93 0.90 3/39 9804 /proc/meminfo: memFree=118428/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=0 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892585367 2629632 278 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 278 238 194 0 28 0 [pid=9804] ppid=9803 vsize=16656 CPUtime=0.36 /proc/9804/stat : 9804 (cudf_msu32) R 9803 9803 9023 34817 9081 4202496 3959 0 0 0 36 0 0 0 25 0 1 0 892585367 17055744 3852 1283457024 134512640 136125367 4286909104 18446744073709551615 134717805 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9804/statm: 4164 3852 144 394 0 3768 0 Current children cumulated CPU time (s) 0.36 Current children cumulated vsize (KiB) 19224 [startup+0.704324 s] /proc/loadavg: 0.84 0.93 0.90 3/39 9804 /proc/meminfo: memFree=118428/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=0 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892585367 2629632 278 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 278 238 194 0 28 0 [pid=9804] ppid=9803 vsize=25300 CPUtime=0.62 /proc/9804/stat : 9804 (cudf_msu32) R 9803 9803 9023 34817 9081 4202496 6144 0 0 0 59 3 0 0 25 0 1 0 892585367 25907200 6037 1283457024 134512640 136125367 4286909104 18446744073709551615 134717925 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9804/statm: 6325 6037 144 394 0 5929 0 Current children cumulated CPU time (s) 0.62 Current children cumulated vsize (KiB) 27868 [startup+1.50494 s] /proc/loadavg: 0.84 0.93 0.90 2/40 9805 /proc/meminfo: memFree=64408/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=0 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892585367 2629632 278 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 278 238 194 0 28 0 [pid=9804] ppid=9803 vsize=47496 CPUtime=1.37 /proc/9804/stat : 9804 (cudf_msu32) R 9803 9803 9023 34817 9081 4202496 11740 0 0 0 129 8 0 0 25 0 1 0 892585367 48635904 11584 1283457024 134512640 136125367 4286909104 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9804/statm: 11874 11584 165 394 0 11478 0 Current children cumulated CPU time (s) 1.37 Current children cumulated vsize (KiB) 50064 [startup+3.10452 s] /proc/loadavg: 0.84 0.93 0.90 2/40 9806 /proc/meminfo: memFree=83504/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=16044 CPUtime=1.25 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 4333 0 0 0 103 22 0 0 25 0 1 0 892585546 16429056 3718 1283457024 134512640 135887319 4289330448 18446744073709551615 134600716 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 4011 3718 138 336 0 3673 0 Current children cumulated CPU time (s) 2.91 Current children cumulated vsize (KiB) 18612 [startup+6.30771 s] /proc/loadavg: 0.85 0.93 0.90 2/40 9806 /proc/meminfo: memFree=77180/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=22900 CPUtime=4.43 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 6709 0 0 0 358 85 0 0 25 0 1 0 892585546 23449600 5421 1283457024 134512640 135887319 4289330448 18446744073709551615 134605912 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 5725 5421 144 336 0 5387 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 25468 [startup+12.7091 s] /proc/loadavg: 0.87 0.94 0.90 2/40 9806 /proc/meminfo: memFree=74948/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=24492 CPUtime=10.83 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 7137 0 0 0 994 89 0 0 25 0 1 0 892585546 25079808 5823 1283457024 134512640 135887319 4289330448 18446744073709551615 134617636 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 6123 5823 144 336 0 5785 0 Current children cumulated CPU time (s) 12.49 Current children cumulated vsize (KiB) 27060 [startup+25.5025 s] /proc/loadavg: 0.89 0.94 0.90 2/40 9806 /proc/meminfo: memFree=70608/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=28780 CPUtime=23.62 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 8318 0 0 0 2267 95 0 0 25 0 1 0 892585546 29470720 6904 1283457024 134512640 135887319 4289330448 18446744073709551615 134605912 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 7195 6904 144 336 0 6857 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 31348 [startup+51.1077 s] /proc/loadavg: 0.93 0.94 0.90 2/40 9806 /proc/meminfo: memFree=66516/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=32892 CPUtime=49.19 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 9454 0 0 0 4816 103 0 0 25 0 1 0 892585546 33681408 7902 1283457024 134512640 135887319 4289330448 18446744073709551615 134617654 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 8223 7902 144 336 0 7885 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 35460 [startup+102.313 s] /proc/loadavg: 0.97 0.95 0.91 2/40 9806 /proc/meminfo: memFree=56968/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=42648 CPUtime=100.32 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 12220 0 0 0 9918 114 0 0 25 0 1 0 892585546 43671552 10314 1283457024 134512640 135887319 4289330448 18446744073709551615 134637935 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 10662 10314 144 336 0 10324 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 45216 [startup+162.309 s] /proc/loadavg: 0.99 0.95 0.91 2/40 9806 /proc/meminfo: memFree=52752/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=46696 CPUtime=160.24 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 13430 0 0 0 15888 136 0 0 25 0 1 0 892585546 47816704 11295 1283457024 134512640 135887319 4289330448 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 11674 11295 144 336 0 11336 0 Current children cumulated CPU time (s) 161.9 Current children cumulated vsize (KiB) 49264 [startup+222.315 s] /proc/loadavg: 0.99 0.96 0.91 2/40 9806 /proc/meminfo: memFree=46924/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=52412 CPUtime=220.21 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 15051 0 0 0 21863 158 0 0 25 0 1 0 892585546 53669888 12715 1283457024 134512640 135887319 4289330448 18446744073709551615 134605916 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 13103 12715 144 336 0 12765 0 Current children cumulated CPU time (s) 221.87 Current children cumulated vsize (KiB) 54980 [startup+282.312 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9806 /proc/meminfo: memFree=46800/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=52412 CPUtime=280.16 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 15073 0 0 0 27844 172 0 0 25 0 1 0 892585546 53669888 12737 1283457024 134512640 135887319 4289330448 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 13103 12737 144 336 0 12765 0 Current children cumulated CPU time (s) 281.82 Current children cumulated vsize (KiB) 54980 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.504 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9806 /proc/meminfo: memFree=46800/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=52412 CPUtime=288.34 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 15073 0 0 0 28662 172 0 0 25 0 1 0 892585546 53669888 12737 1283457024 134512640 135887319 4289330448 18446744073709551615 134624419 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 13103 12737 144 336 0 12765 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 54980 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.504 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9806 /proc/meminfo: memFree=46800/1048576 swapFree=2095372/2097144 [pid=9803] ppid=9802 vsize=2568 CPUtime=1.66 /proc/9803/stat : 9803 (cudf2pbo4parano) S 9802 9803 9023 34817 9081 4202496 402 11742 0 0 0 0 148 18 20 0 1 0 892585367 2629632 281 1283457024 134512640 135304128 4294891968 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9803/statm: 642 281 241 194 0 28 0 [pid=9806] ppid=9803 vsize=52412 CPUtime=288.34 /proc/9806/stat : 9806 (bmo-pblex32) R 9803 9803 9023 34817 9081 4202496 15073 0 0 0 28662 172 0 0 25 0 1 0 892585546 53669888 12737 1283457024 134512640 135887319 4289330448 18446744073709551615 134624419 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9806/statm: 13103 12737 144 336 0 12765 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 54980 Child status: 0 Real time (s): 290.575 CPU time (s): 290.078 CPU user time (s): 288.154 CPU system time (s): 1.92412 CPU usage (%): 99.8289 Max. virtual memory (cumulated for all children) (KiB): 54980 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.154 system time used= 1.92412 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 29134 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= 56 involuntary context switches= 5717 runsolver used 0 second user time and 0.008 second system time The end