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/rand0695fb.cudf.impossible.log.runsolver ./cudf2msu4paranoid-1.0 /home/misc2010/data/2010/impossible//rand0695fb.cudf /home/misc2010/tmp/201012061533/cudf2msu4paranoid-1.0/rand0695fb.cudf.impossible.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.71 1.35 0.86 5/51 3487
/proc/meminfo: memFree=312548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=2572 CPUtime=0.02
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 390 0 0 0 2 0 0 0 25 0 1 0 874365110 2633728 329 1283457024 134512640 136120023 4289529088 18446744073709551615 134712135 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 643 329 137 393 0 248 0

[startup+0.155556 s]
/proc/loadavg: 1.71 1.35 0.86 5/51 3487
/proc/meminfo: memFree=312548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=8032 CPUtime=0.16
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 1777 0 0 0 16 0 0 0 25 0 1 0 874365110 8224768 1716 1283457024 134512640 136120023 4289529088 18446744073709551615 134712061 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 2008 1716 138 393 0 1613 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 10604

[startup+0.205579 s]
/proc/loadavg: 1.71 1.35 0.86 5/51 3487
/proc/meminfo: memFree=312548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=9748 CPUtime=0.21
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 2200 0 0 0 21 0 0 0 25 0 1 0 874365110 9981952 2139 1283457024 134512640 136120023 4289529088 18446744073709551615 135530288 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 2437 2139 138 393 0 2042 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12320

[startup+0.305596 s]
/proc/loadavg: 1.71 1.35 0.86 5/51 3487
/proc/meminfo: memFree=312548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=13112 CPUtime=0.31
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 3051 0 0 0 29 2 0 0 25 0 1 0 874365110 13426688 2990 1283457024 134512640 136120023 4289529088 18446744073709551615 134711959 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 3278 2990 139 393 0 2883 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15684

[startup+0.705701 s]
/proc/loadavg: 1.71 1.35 0.86 5/51 3487
/proc/meminfo: memFree=312548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=24792 CPUtime=0.7
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 5972 0 0 0 64 6 0 0 25 0 1 0 874365110 25387008 5911 1283457024 134512640 136120023 4289529088 18446744073709551615 134711831 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 6198 5911 139 393 0 5803 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27364

[startup+1.50585 s]
/proc/loadavg: 1.65 1.34 0.86 2/52 3488
/proc/meminfo: memFree=279596/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=45180 CPUtime=1.51
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 11105 0 0 0 142 9 0 0 25 0 1 0 874365110 46264320 10995 1283457024 134512640 136120023 4289529088 18446744073709551615 135524924 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 11295 10995 139 393 0 10900 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 47752

[startup+3.10628 s]
/proc/loadavg: 1.65 1.34 0.86 2/52 3488
/proc/meminfo: memFree=224788/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=89856 CPUtime=3.09
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22331 0 0 0 298 11 0 0 25 0 1 0 874365110 92012544 22209 1283457024 134512640 136120023 4289529088 18446744073709551615 134831745 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22464 22209 178 393 0 22069 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 92428

[startup+6.30716 s]
/proc/loadavg: 1.60 1.34 0.86 2/52 3488
/proc/meminfo: memFree=224540/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=6.29
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22411 0 0 0 618 11 0 0 25 0 1 0 874365110 92282880 22289 1283457024 134512640 136120023 4289529088 18446744073709551615 134867741 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22289 182 393 0 22135 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 92692

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

[startup+6.40719 s]
/proc/loadavg: 1.60 1.34 0.86 2/52 3488
/proc/meminfo: memFree=224540/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=6.39
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22411 0 0 0 628 11 0 0 25 0 1 0 874365110 92282880 22289 1283457024 134512640 136120023 4289529088 18446744073709551615 134863582 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22289 182 393 0 22135 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 92692

[startup+9.60806 s]
/proc/loadavg: 1.60 1.34 0.86 2/52 3488
/proc/meminfo: memFree=224548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=9.59
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22411 0 0 0 948 11 0 0 25 0 1 0 874365110 92282880 22289 1283457024 134512640 136120023 4289529088 18446744073709551615 135530343 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22289 182 393 0 22135 0
Current children cumulated CPU time (s) 9.59
Current children cumulated vsize (KiB) 92692

[startup+10.4083 s]
/proc/loadavg: 1.60 1.34 0.86 2/52 3488
/proc/meminfo: memFree=224548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=10.39
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22411 0 0 0 1028 11 0 0 25 0 1 0 874365110 92282880 22289 1283457024 134512640 136120023 4289529088 18446744073709551615 134867774 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22289 182 393 0 22135 0
Current children cumulated CPU time (s) 10.39
Current children cumulated vsize (KiB) 92692

[startup+10.8084 s]
/proc/loadavg: 1.60 1.34 0.86 2/52 3488
/proc/meminfo: memFree=224548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=10.79
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22411 0 0 0 1068 11 0 0 25 0 1 0 874365110 92282880 22289 1283457024 134512640 136120023 4289529088 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22289 182 393 0 22135 0
Current children cumulated CPU time (s) 10.79
Current children cumulated vsize (KiB) 92692

[startup+11.0084 s]
/proc/loadavg: 1.55 1.33 0.86 2/52 3488
/proc/meminfo: memFree=224548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=10.99
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22411 0 0 0 1088 11 0 0 25 0 1 0 874365110 92282880 22289 1283457024 134512640 136120023 4289529088 18446744073709551615 134840147 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22289 182 393 0 22135 0
Current children cumulated CPU time (s) 10.99
Current children cumulated vsize (KiB) 92692

[startup+11.1085 s]
/proc/loadavg: 1.55 1.33 0.86 2/52 3488
/proc/meminfo: memFree=224548/1048576 swapFree=2095580/2097144
[pid=3486] ppid=3485 vsize=2572 CPUtime=0
/proc/3486/stat : 3486 (cudf2msu4parano) S 3485 3486 2059 34821 2220 4202496 376 0 0 0 0 0 0 0 22 0 1 0 874365110 2633728 272 1283457024 134512640 135304128 4287837008 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3486/statm: 643 272 231 194 0 29 0
[pid=3487] ppid=3486 vsize=90120 CPUtime=11.09
/proc/3487/stat : 3487 (cudf_msu32) R 3486 3486 2059 34821 2220 4202496 22426 0 0 0 1097 12 0 0 25 0 1 0 874365110 92282880 22304 1283457024 134512640 136120023 4289529088 18446744073709551615 135171536 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/3487/statm: 22530 22304 197 393 0 22135 0
Current children cumulated CPU time (s) 11.09
Current children cumulated vsize (KiB) 92692

Child status: 0
Real time (s): 11.1654
CPU time (s): 11.1567
CPU user time (s): 11.0167
CPU system time (s): 0.140008
CPU usage (%): 99.9217
Max. virtual memory (cumulated for all children) (KiB): 92692

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

runsolver used 0 second user time and 0 second system time

The end