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/201012091434/cudf2msu4user-1.0/rand6b4d6e.cudf.impossible.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/impossible//rand6b4d6e.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/rand6b4d6e.cudf.impossible.result -changed,-removed,-unmet_recommends,-new 

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.06 0.97 5/39 27866
/proc/meminfo: memFree=446876/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=2044 CPUtime=0
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 268 0 0 0 0 0 0 0 25 0 1 0 900048364 2093056 206 1283457024 134512640 136120023 4293189728 18446744073709551615 135687401 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 511 206 140 393 0 116 0

[startup+0.185557 s]
/proc/loadavg: 1.00 1.06 0.97 5/39 27866
/proc/meminfo: memFree=446876/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=9220 CPUtime=0.17
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 2084 0 0 0 14 3 0 0 25 0 1 0 900048364 9441280 2022 1283457024 134512640 136120023 4293189728 18446744073709551615 134721232 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 2305 2022 141 393 0 1910 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11796

[startup+0.205556 s]
/proc/loadavg: 1.00 1.06 0.97 5/39 27866
/proc/meminfo: memFree=446876/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=9880 CPUtime=0.19
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 2248 0 0 0 16 3 0 0 25 0 1 0 900048364 10117120 2186 1283457024 134512640 136120023 4293189728 18446744073709551615 134732517 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 2470 2186 141 393 0 2075 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12456

[startup+0.305576 s]
/proc/loadavg: 1.00 1.06 0.97 5/39 27866
/proc/meminfo: memFree=446876/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=13376 CPUtime=0.29
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 3123 0 0 0 25 4 0 0 25 0 1 0 900048364 13697024 3061 1283457024 134512640 136120023 4293189728 18446744073709551615 135589790 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 3344 3061 142 393 0 2949 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 15952

[startup+0.705641 s]
/proc/loadavg: 1.00 1.06 0.97 5/39 27866
/proc/meminfo: memFree=446876/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=25188 CPUtime=0.69
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 6069 0 0 0 64 5 0 0 25 0 1 0 900048364 25792512 6007 1283457024 134512640 136120023 4293189728 18446744073709551615 135169233 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 6297 6007 142 393 0 5902 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 27764

[startup+1.50578 s]
/proc/loadavg: 1.00 1.06 0.97 2/40 27867
/proc/meminfo: memFree=412880/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=45444 CPUtime=1.49
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 11168 0 0 0 142 7 0 0 25 0 1 0 900048364 46534656 11057 1283457024 134512640 136120023 4293189728 18446744073709551615 134580545 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 11361 11057 142 393 0 10966 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 48020

[startup+3.10621 s]
/proc/loadavg: 1.00 1.06 0.97 2/40 27867
/proc/meminfo: memFree=321988/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=139652 CPUtime=3.09
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 35237 0 0 0 298 11 0 0 25 0 1 0 900048364 143003648 34633 1283457024 134512640 136120023 4293189728 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 34913 34633 179 393 0 34518 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 142228

[startup+6.30725 s]
/proc/loadavg: 1.00 1.06 0.97 2/40 27867
/proc/meminfo: memFree=308472/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=139652 CPUtime=6.29
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 35239 0 0 0 618 11 0 0 25 0 1 0 900048364 143003648 34635 1283457024 134512640 136120023 4293189728 18446744073709551615 134872398 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 34913 34635 181 393 0 34518 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 142228

[startup+12.7092 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=308472/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=139652 CPUtime=12.69
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 35239 0 0 0 1255 14 0 0 25 0 1 0 900048364 143003648 34635 1283457024 134512640 136120023 4293189728 18446744073709551615 134866586 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 34913 34635 181 393 0 34518 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 142228

[startup+25.5053 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=306736/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=141776 CPUtime=25.48
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 36678 0 0 0 2534 14 0 0 25 0 1 0 900048364 145178624 35174 1283457024 134512640 136120023 4293189728 18446744073709551615 135521208 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 35444 35174 185 393 0 35049 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 144352

Solver just ended. Dumping a history of the last processes samples

[startup+25.6053 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=306736/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=141776 CPUtime=25.58
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 36678 0 0 0 2544 14 0 0 25 0 1 0 900048364 145178624 35174 1283457024 134512640 136120023 4293189728 18446744073709551615 134872508 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 35444 35174 185 393 0 35049 0
Current children cumulated CPU time (s) 25.58
Current children cumulated vsize (KiB) 144352

[startup+27.2062 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=306736/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=141776 CPUtime=27.19
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 36678 0 0 0 2705 14 0 0 25 0 1 0 900048364 145178624 35174 1283457024 134512640 136120023 4293189728 18446744073709551615 135530307 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 35444 35174 185 393 0 35049 0
Current children cumulated CPU time (s) 27.19
Current children cumulated vsize (KiB) 144352

[startup+28.0065 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=306736/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=141776 CPUtime=27.98
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 36678 0 0 0 2784 14 0 0 25 0 1 0 900048364 145178624 35174 1283457024 134512640 136120023 4293189728 18446744073709551615 134863381 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 35444 35174 185 393 0 35049 0
Current children cumulated CPU time (s) 27.98
Current children cumulated vsize (KiB) 144352

[startup+28.4066 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=306736/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=141776 CPUtime=28.38
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 36678 0 0 0 2824 14 0 0 25 0 1 0 900048364 145178624 35174 1283457024 134512640 136120023 4293189728 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 35444 35174 185 393 0 35049 0
Current children cumulated CPU time (s) 28.38
Current children cumulated vsize (KiB) 144352

[startup+28.5067 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27867
/proc/meminfo: memFree=306736/1048576 swapFree=2095372/2097144
[pid=27865] ppid=27864 vsize=2576 CPUtime=0
/proc/27865/stat : 27865 (cudf2msu4user-1) S 27864 27865 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900048364 2637824 278 1283457024 134512640 135304128 4288607200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27865/statm: 644 278 237 194 0 30 0
[pid=27866] ppid=27865 vsize=141776 CPUtime=28.48
/proc/27866/stat : 27866 (cudf_msu32) R 27865 27865 25521 34816 25544 4202496 36692 0 0 0 2834 14 0 0 25 0 1 0 900048364 145178624 35188 1283457024 134512640 136120023 4293189728 18446744073709551615 134672210 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/27866/statm: 35444 35188 199 393 0 35049 0
Current children cumulated CPU time (s) 28.48
Current children cumulated vsize (KiB) 144352

Child status: 0
Real time (s): 28.5993
CPU time (s): 28.5818
CPU user time (s): 28.4138
CPU system time (s): 0.16801
CPU usage (%): 99.9387
Max. virtual memory (cumulated for all children) (KiB): 144352

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 28.4138
system time used= 0.16801
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 37086
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= 395

runsolver used 0 second user time and 0 second system time

The end