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/rand0aa5c1.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand0aa5c1.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand0aa5c1.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: 0.88 0.93 0.89 5/39 9659 /proc/meminfo: memFree=68348/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=0 /proc/9658/stat : 9658 (cudf2pbo4trendy) R 9657 9658 9023 34817 9081 4202496 364 0 0 0 0 0 0 0 25 0 1 0 892463282 2633728 278 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/9658/statm: 643 278 238 194 0 29 0 [pid=9659] ppid=9658 vsize=2572 CPUtime=0 /proc/9659/stat : 9659 (cudf2pbo4trendy) R 9658 9658 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 892463282 2633728 40 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/9659/statm: 643 40 0 194 0 29 0 [startup+0.165568 s] /proc/loadavg: 0.88 0.93 0.89 5/39 9659 /proc/meminfo: memFree=68348/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=0 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892463282 2633728 278 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 278 238 194 0 29 0 [pid=9659] ppid=9658 vsize=8912 CPUtime=0.16 /proc/9659/stat : 9659 (cudf_msu32) R 9658 9658 9023 34817 9081 4202496 2052 0 0 0 16 0 0 0 25 0 1 0 892463282 9125888 1945 1283457024 134512640 136125367 4290862752 18446744073709551615 134717792 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9659/statm: 2228 1945 142 394 0 1832 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 11484 [startup+0.205586 s] /proc/loadavg: 0.88 0.93 0.89 5/39 9659 /proc/meminfo: memFree=68348/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=0 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892463282 2633728 278 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 278 238 194 0 29 0 [pid=9659] ppid=9658 vsize=10572 CPUtime=0.2 /proc/9659/stat : 9659 (cudf_msu32) R 9658 9658 9023 34817 9081 4202496 2443 0 0 0 20 0 0 0 25 0 1 0 892463282 10825728 2336 1283457024 134512640 136125367 4290862752 18446744073709551615 134728315 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9659/statm: 2643 2336 143 394 0 2247 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13144 [startup+0.305597 s] /proc/loadavg: 0.88 0.93 0.89 5/39 9659 /proc/meminfo: memFree=68348/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=0 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892463282 2633728 278 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 278 238 194 0 29 0 [pid=9659] ppid=9658 vsize=14136 CPUtime=0.3 /proc/9659/stat : 9659 (cudf_msu32) R 9658 9658 9023 34817 9081 4202496 3333 0 0 0 30 0 0 0 25 0 1 0 892463282 14475264 3226 1283457024 134512640 136125367 4290862752 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9659/statm: 3534 3226 143 394 0 3138 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16708 [startup+0.705671 s] /proc/loadavg: 0.88 0.93 0.89 5/39 9659 /proc/meminfo: memFree=68348/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=0 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892463282 2633728 278 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 278 238 194 0 29 0 [pid=9659] ppid=9658 vsize=26344 CPUtime=0.7 /proc/9659/stat : 9659 (cudf_msu32) R 9658 9658 9023 34817 9081 4202496 6397 0 0 0 69 1 0 0 25 0 1 0 892463282 26976256 6290 1283457024 134512640 136125367 4290862752 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9659/statm: 6586 6290 143 394 0 6190 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28916 [startup+1.50582 s] /proc/loadavg: 0.88 0.93 0.89 2/40 9660 /proc/meminfo: memFree=34972/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 Current children cumulated CPU time (s) 1.18 Current children cumulated vsize (KiB) 2572 [startup+3.11553 s] /proc/loadavg: 0.88 0.93 0.89 2/40 9661 /proc/meminfo: memFree=56176/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=16164 CPUtime=1.79 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 5005 0 0 0 112 67 0 0 25 0 1 0 892463401 16551936 3750 1283457024 134512640 135887319 4287406944 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 4041 3750 144 336 0 3703 0 Current children cumulated CPU time (s) 2.97 Current children cumulated vsize (KiB) 18736 [startup+6.30622 s] /proc/loadavg: 0.89 0.93 0.89 2/40 9661 /proc/meminfo: memFree=44520/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=24048 CPUtime=4.96 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 8376 0 0 0 347 149 0 0 25 0 1 0 892463401 24625152 5770 1283457024 134512640 135887319 4287406944 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 6012 5770 144 336 0 5674 0 Current children cumulated CPU time (s) 6.14 Current children cumulated vsize (KiB) 26620 [startup+12.7074 s] /proc/loadavg: 0.89 0.93 0.89 2/40 9661 /proc/meminfo: memFree=44148/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=24444 CPUtime=11.36 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 8472 0 0 0 984 152 0 0 25 0 1 0 892463401 25030656 5859 1283457024 134512640 135887319 4287406944 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 6111 5859 144 336 0 5773 0 Current children cumulated CPU time (s) 12.54 Current children cumulated vsize (KiB) 27016 [startup+25.5102 s] /proc/loadavg: 0.92 0.94 0.89 2/40 9661 /proc/meminfo: memFree=43404/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=25256 CPUtime=24.15 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 8680 0 0 0 2261 154 0 0 25 0 1 0 892463401 25862144 6055 1283457024 134512640 135887319 4287406944 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 6314 6055 144 336 0 5976 0 Current children cumulated CPU time (s) 25.33 Current children cumulated vsize (KiB) 27828 [startup+51.1051 s] /proc/loadavg: 0.94 0.94 0.90 2/40 9661 /proc/meminfo: memFree=41916/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=26712 CPUtime=49.73 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 9074 0 0 0 4817 156 0 0 25 0 1 0 892463401 27353088 6417 1283457024 134512640 135887319 4287406944 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 6678 6417 144 336 0 6340 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 29284 [startup+102.307 s] /proc/loadavg: 0.97 0.95 0.90 2/40 9661 /proc/meminfo: memFree=38692/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=29832 CPUtime=100.85 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 9933 0 0 0 9922 163 0 0 25 0 1 0 892463401 30547968 7187 1283457024 134512640 135887319 4287406944 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 7458 7187 144 336 0 7120 0 Current children cumulated CPU time (s) 102.03 Current children cumulated vsize (KiB) 32404 [startup+162.31 s] /proc/loadavg: 0.99 0.95 0.91 2/40 9661 /proc/meminfo: memFree=35468/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=32968 CPUtime=160.82 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 10874 0 0 0 15914 168 0 0 25 0 1 0 892463401 33759232 7978 1283457024 134512640 135887319 4287406944 18446744073709551615 134603491 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 8242 7978 144 336 0 7904 0 Current children cumulated CPU time (s) 162 Current children cumulated vsize (KiB) 35540 [startup+222.313 s] /proc/loadavg: 0.99 0.96 0.91 2/40 9661 /proc/meminfo: memFree=32244/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=36232 CPUtime=220.78 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 11888 0 0 0 21890 188 0 0 25 0 1 0 892463401 37101568 8774 1283457024 134512640 135887319 4287406944 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 9058 8774 144 336 0 8720 0 Current children cumulated CPU time (s) 221.96 Current children cumulated vsize (KiB) 38804 [startup+282.305 s] /proc/loadavg: 0.99 0.96 0.91 2/40 9661 /proc/meminfo: memFree=31996/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=36364 CPUtime=280.75 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 11906 0 0 0 27876 199 0 0 25 0 1 0 892463401 37236736 8791 1283457024 134512640 135887319 4287406944 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 9091 8791 144 336 0 8753 0 Current children cumulated CPU time (s) 281.93 Current children cumulated vsize (KiB) 38936 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.407 s] /proc/loadavg: 0.99 0.96 0.91 2/40 9661 /proc/meminfo: memFree=31996/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=36364 CPUtime=288.85 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 11906 0 0 0 28684 201 0 0 25 0 1 0 892463401 37236736 8791 1283457024 134512640 135887319 4287406944 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 9091 8791 144 336 0 8753 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 38936 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.407 s] /proc/loadavg: 0.99 0.96 0.91 2/40 9661 /proc/meminfo: memFree=31996/1048576 swapFree=2095372/2097144 [pid=9658] ppid=9657 vsize=2572 CPUtime=1.18 /proc/9658/stat : 9658 (cudf2pbo4trendy) S 9657 9658 9023 34817 9081 4202496 401 8369 0 0 0 0 99 19 18 0 1 0 892463282 2633728 281 1283457024 134512640 135304128 4294855168 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9658/statm: 643 281 241 194 0 29 0 [pid=9661] ppid=9658 vsize=36364 CPUtime=288.85 /proc/9661/stat : 9661 (bmo-pblex32) R 9658 9658 9023 34817 9081 4202496 11906 0 0 0 28684 201 0 0 25 0 1 0 892463401 37236736 8791 1283457024 134512640 135887319 4287406944 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9661/statm: 9091 8791 144 336 0 8753 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 38936 Child status: 0 Real time (s): 290.468 CPU time (s): 290.102 CPU user time (s): 287.878 CPU system time (s): 2.22414 CPU usage (%): 99.8739 Max. virtual memory (cumulated for all children) (KiB): 38936 getrusage(RUSAGE_CHILDREN,...) data: user time used= 287.878 system time used= 2.22414 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22417 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= 12 involuntary context switches= 5759 runsolver used 0 second user time and 0 second system time The end