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/cudf2pbo4trendy-1.0/rand49d73b.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand49d73b.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand49d73b.cudf.difficult.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: 1.13 0.99 0.92 3/35 11683 /proc/meminfo: memFree=33152/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=0 /proc/11682/stat : 11682 (cudf2pbo4trendy) R 11681 11682 9023 34817 9081 4202496 366 0 0 0 0 0 0 0 25 0 1 0 893646804 2633728 279 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/11682/statm: 643 279 238 194 0 29 0 [pid=11683] ppid=11682 vsize=2572 CPUtime=0 /proc/11683/stat : 11683 (cudf2pbo4trendy) R 11682 11682 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 893646805 2633728 41 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/11683/statm: 643 41 0 194 0 29 0 [startup+0.165366 s] /proc/loadavg: 1.13 0.99 0.92 3/35 11683 /proc/meminfo: memFree=33152/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=0 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 893646804 2633728 279 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 279 238 194 0 29 0 [pid=11683] ppid=11682 vsize=8912 CPUtime=0.16 /proc/11683/stat : 11683 (cudf_msu32) R 11682 11682 9023 34817 9081 4202496 2042 0 0 0 16 0 0 0 25 0 1 0 893646805 9125888 1934 1283457024 134512640 136125367 4294603312 18446744073709551615 134717989 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11683/statm: 2228 1934 142 394 0 1832 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 11484 [startup+0.205379 s] /proc/loadavg: 1.13 0.99 0.92 3/35 11683 /proc/meminfo: memFree=33152/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=0 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 893646804 2633728 279 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 279 238 194 0 29 0 [pid=11683] ppid=11682 vsize=10572 CPUtime=0.2 /proc/11683/stat : 11683 (cudf_msu32) R 11682 11682 9023 34817 9081 4202496 2445 0 0 0 18 2 0 0 25 0 1 0 893646805 10825728 2337 1283457024 134512640 136125367 4294603312 18446744073709551615 134728348 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11683/statm: 2643 2337 143 394 0 2247 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13144 [startup+0.305396 s] /proc/loadavg: 1.13 0.99 0.92 3/35 11683 /proc/meminfo: memFree=33152/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=0 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 893646804 2633728 279 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 279 238 194 0 29 0 [pid=11683] ppid=11682 vsize=14004 CPUtime=0.3 /proc/11683/stat : 11683 (cudf_msu32) R 11682 11682 9023 34817 9081 4202496 3307 0 0 0 27 3 0 0 25 0 1 0 893646805 14340096 3199 1283457024 134512640 136125367 4294603312 18446744073709551615 134717477 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11683/statm: 3501 3199 143 394 0 3105 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16576 [startup+0.705498 s] /proc/loadavg: 1.13 0.99 0.92 3/35 11683 /proc/meminfo: memFree=33152/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=0 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 893646804 2633728 279 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 279 238 194 0 29 0 [pid=11683] ppid=11682 vsize=26212 CPUtime=0.7 /proc/11683/stat : 11683 (cudf_msu32) R 11682 11682 9023 34817 9081 4202496 6356 0 0 0 66 4 0 0 25 0 1 0 893646805 26841088 6248 1283457024 134512640 136125367 4294603312 18446744073709551615 134717668 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11683/statm: 6553 6248 143 394 0 6157 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28784 [startup+1.50645 s] /proc/loadavg: 1.12 0.99 0.92 2/36 11684 /proc/meminfo: memFree=5908/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 1.18 Current children cumulated vsize (KiB) 2572 [startup+3.10685 s] /proc/loadavg: 1.12 0.99 0.92 2/36 11685 /proc/meminfo: memFree=26864/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=16164 CPUtime=1.91 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 5020 0 0 0 120 71 0 0 25 0 1 0 893646923 16551936 3749 1283457024 134512640 135887319 4294683216 18446744073709551615 134617715 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 4041 3749 144 336 0 3703 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 18736 [startup+6.30764 s] /proc/loadavg: 1.11 0.99 0.92 2/36 11685 /proc/meminfo: memFree=15340/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=24140 CPUtime=5.09 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 8415 0 0 0 370 139 0 0 25 0 1 0 893646923 24719360 5762 1283457024 134512640 135887319 4294683216 18446744073709551615 134615301 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 6035 5762 144 336 0 5697 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 26712 [startup+12.7114 s] /proc/loadavg: 1.10 0.99 0.92 2/36 11685 /proc/meminfo: memFree=14968/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=24536 CPUtime=11.48 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 8513 0 0 0 1007 141 0 0 25 0 1 0 893646923 25124864 5858 1283457024 134512640 135887319 4294683216 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 6134 5858 144 336 0 5796 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 27108 [startup+25.5043 s] /proc/loadavg: 1.08 0.99 0.92 2/36 11685 /proc/meminfo: memFree=14100/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=25328 CPUtime=24.27 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 8724 0 0 0 2285 142 0 0 25 0 1 0 893646923 25935872 6062 1283457024 134512640 135887319 4294683216 18446744073709551615 134606146 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 6332 6062 144 336 0 5994 0 Current children cumulated CPU time (s) 25.45 Current children cumulated vsize (KiB) 27900 [startup+51.1104 s] /proc/loadavg: 1.05 0.99 0.92 2/36 11685 /proc/meminfo: memFree=12612/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=26944 CPUtime=49.85 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 9143 0 0 0 4834 151 0 0 25 0 1 0 893646923 27590656 6452 1283457024 134512640 135887319 4294683216 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 6736 6452 144 336 0 6398 0 Current children cumulated CPU time (s) 51.03 Current children cumulated vsize (KiB) 29516 [startup+102.31 s] /proc/loadavg: 1.02 0.99 0.92 2/36 11685 /proc/meminfo: memFree=9512/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=29948 CPUtime=101.02 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 9984 0 0 0 9942 160 0 0 25 0 1 0 893646923 30666752 7195 1283457024 134512640 135887319 4294683216 18446744073709551615 134617863 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 7487 7195 144 336 0 7149 0 Current children cumulated CPU time (s) 102.2 Current children cumulated vsize (KiB) 32520 [startup+162.313 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11685 /proc/meminfo: memFree=7776/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=31688 CPUtime=160.97 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 10474 0 0 0 15927 170 0 0 25 0 1 0 893646923 32448512 7610 1283457024 134512640 135887319 4294683216 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 7922 7610 144 336 0 7584 0 Current children cumulated CPU time (s) 162.15 Current children cumulated vsize (KiB) 34260 [startup+222.304 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11685 /proc/meminfo: memFree=7776/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=31688 CPUtime=220.93 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 10479 0 0 0 21915 178 0 0 25 0 1 0 893646923 32448512 7615 1283457024 134512640 135887319 4294683216 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 7922 7615 144 336 0 7584 0 Current children cumulated CPU time (s) 222.11 Current children cumulated vsize (KiB) 34260 [startup+282.309 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11685 /proc/meminfo: memFree=5296/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=34240 CPUtime=280.84 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 11268 0 0 0 27899 185 0 0 25 0 1 0 893646923 35061760 8235 1283457024 134512640 135887319 4294683216 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 8560 8235 144 336 0 8222 0 Current children cumulated CPU time (s) 282.02 Current children cumulated vsize (KiB) 36812 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.311 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11685 /proc/meminfo: memFree=5296/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=34240 CPUtime=288.84 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 11268 0 0 0 28699 185 0 0 25 0 1 0 893646923 35061760 8235 1283457024 134512640 135887319 4294683216 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 8560 8235 144 336 0 8222 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 36812 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.311 s] /proc/loadavg: 1.00 0.99 0.92 2/36 11685 /proc/meminfo: memFree=5296/1048576 swapFree=2095372/2097144 [pid=11682] ppid=11681 vsize=2572 CPUtime=1.18 /proc/11682/stat : 11682 (cudf2pbo4trendy) S 11681 11682 9023 34817 9081 4202496 403 8322 0 0 0 0 96 22 18 0 1 0 893646804 2633728 282 1283457024 134512640 135304128 4292257680 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11682/statm: 643 282 241 194 0 29 0 [pid=11685] ppid=11682 vsize=34240 CPUtime=288.84 /proc/11685/stat : 11685 (bmo-pblex32) R 11682 11682 9023 34817 9081 4202496 11268 0 0 0 28699 185 0 0 25 0 1 0 893646923 35061760 8235 1283457024 134512640 135887319 4294683216 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11685/statm: 8560 8235 144 336 0 8222 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 36812 Child status: 0 Real time (s): 290.372 CPU time (s): 290.094 CPU user time (s): 288.014 CPU system time (s): 2.08013 CPU usage (%): 99.9044 Max. virtual memory (cumulated for all children) (KiB): 36812 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.014 system time used= 2.08013 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 21715 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= 8 involuntary context switches= 5689 runsolver used 0 second user time and 0 second system time The end