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/201012061533/cudf2msu4paranoid-1.0/randf7a7e4.cudf.easy.log.runsolver ./cudf2msu4paranoid-1.0 /home/misc2010/data/2010/easy//randf7a7e4.cudf /home/misc2010/tmp/201012061533/cudf2msu4paranoid-1.0/randf7a7e4.cudf.easy.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.09 1.32 1.29 4/39 3847 /proc/meminfo: memFree=601132/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=2040 CPUtime=0 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 265 0 0 0 0 0 0 0 25 0 1 0 876747438 2088960 204 1283457024 134512640 136120023 4292534256 18446744073709551615 134711972 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 510 204 137 393 0 115 0 [startup+0.195621 s] /proc/loadavg: 1.09 1.32 1.29 4/39 3847 /proc/meminfo: memFree=601132/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=9964 CPUtime=0.19 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 2265 0 0 0 17 2 0 0 25 0 1 0 876747438 10203136 2204 1283457024 134512640 136120023 4292534256 18446744073709551615 135545119 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 2491 2204 138 393 0 2096 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 12536 [startup+0.205631 s] /proc/loadavg: 1.09 1.32 1.29 4/39 3847 /proc/meminfo: memFree=601132/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=10556 CPUtime=0.2 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 2386 0 0 0 18 2 0 0 25 0 1 0 876747438 10809344 2325 1283457024 134512640 136120023 4292534256 18446744073709551615 134722472 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 2639 2325 139 393 0 2244 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13128 [startup+0.305634 s] /proc/loadavg: 1.09 1.32 1.29 4/39 3847 /proc/meminfo: memFree=601132/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=13988 CPUtime=0.3 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 3272 0 0 0 28 2 0 0 25 0 1 0 876747438 14323712 3211 1283457024 134512640 136120023 4292534256 18446744073709551615 135538956 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 3497 3211 139 393 0 3102 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16560 [startup+0.705681 s] /proc/loadavg: 1.09 1.32 1.29 4/39 3847 /proc/meminfo: memFree=601132/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33092 CPUtime=0.7 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8091 0 0 0 66 4 0 0 25 0 1 0 876747438 33886208 8027 1283457024 134512640 136120023 4292534256 18446744073709551615 135545116 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8273 8027 176 393 0 7878 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 35664 [startup+1.50576 s] /proc/loadavg: 1.09 1.32 1.29 2/40 3848 /proc/meminfo: memFree=569864/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33092 CPUtime=1.5 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8093 0 0 0 146 4 0 0 25 0 1 0 876747438 33886208 8029 1283457024 134512640 136120023 4292534256 18446744073709551615 135524956 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8273 8029 178 393 0 7878 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 35664 [startup+3.10619 s] /proc/loadavg: 1.09 1.32 1.29 2/40 3848 /proc/meminfo: memFree=569864/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33896 CPUtime=3.1 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8330 0 0 0 306 4 0 0 25 0 1 0 876747438 34709504 8231 1283457024 134512640 136120023 4292534256 18446744073709551615 134837904 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8474 8231 182 393 0 8079 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 36468 Solver just ended. Dumping a history of the last processes samples [startup+3.20621 s] /proc/loadavg: 1.09 1.32 1.29 2/40 3848 /proc/meminfo: memFree=569864/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33896 CPUtime=3.2 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8330 0 0 0 316 4 0 0 25 0 1 0 876747438 34709504 8231 1283457024 134512640 136120023 4292534256 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8474 8231 182 393 0 8079 0 Current children cumulated CPU time (s) 3.2 Current children cumulated vsize (KiB) 36468 [startup+4.80662 s] /proc/loadavg: 1.08 1.31 1.29 2/40 3848 /proc/meminfo: memFree=569004/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33896 CPUtime=4.8 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8330 0 0 0 475 5 0 0 25 0 1 0 876747438 34709504 8231 1283457024 134512640 136120023 4292534256 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8474 8231 182 393 0 8079 0 Current children cumulated CPU time (s) 4.8 Current children cumulated vsize (KiB) 36468 [startup+5.20673 s] /proc/loadavg: 1.08 1.31 1.29 2/40 3848 /proc/meminfo: memFree=569004/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33896 CPUtime=5.2 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8330 0 0 0 515 5 0 0 25 0 1 0 876747438 34709504 8231 1283457024 134512640 136120023 4292534256 18446744073709551615 134867516 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8474 8231 182 393 0 8079 0 Current children cumulated CPU time (s) 5.2 Current children cumulated vsize (KiB) 36468 [startup+5.40679 s] /proc/loadavg: 1.08 1.31 1.29 2/40 3848 /proc/meminfo: memFree=569004/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33896 CPUtime=5.4 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8330 0 0 0 535 5 0 0 25 0 1 0 876747438 34709504 8231 1283457024 134512640 136120023 4292534256 18446744073709551615 134867777 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8474 8231 182 393 0 8079 0 Current children cumulated CPU time (s) 5.4 Current children cumulated vsize (KiB) 36468 [startup+5.50681 s] /proc/loadavg: 1.08 1.31 1.29 2/40 3848 /proc/meminfo: memFree=569004/1048576 swapFree=2084004/2097144 [pid=3846] ppid=3845 vsize=2572 CPUtime=0 /proc/3846/stat : 3846 (cudf2msu4parano) S 3845 3846 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 876747437 2633728 272 1283457024 134512640 135304128 4289951072 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/3846/statm: 643 272 231 194 0 29 0 [pid=3847] ppid=3846 vsize=33896 CPUtime=5.51 /proc/3847/stat : 3847 (cudf_msu32) R 3846 3846 2059 34821 2220 4202496 8330 0 0 0 546 5 0 0 25 0 1 0 876747438 34709504 8231 1283457024 134512640 136120023 4292534256 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0 /proc/3847/statm: 8474 8231 182 393 0 8079 0 Current children cumulated CPU time (s) 5.51 Current children cumulated vsize (KiB) 36468 Child status: 0 Real time (s): 5.56642 CPU time (s): 5.56035 CPU user time (s): 5.49634 CPU system time (s): 0.064004 CPU usage (%): 99.8909 Max. virtual memory (cumulated for all children) (KiB): 36468 getrusage(RUSAGE_CHILDREN,...) data: user time used= 5.49634 system time used= 0.064004 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 8732 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= 3 involuntary context switches= 106 runsolver used 0 second user time and 0 second system time The end