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/201012070034/cudf2msu4trendy-1.0/randf61f65.cudf.difficult.log.runsolver ./cudf2msu4trendy-1.0 /home/misc2010/data/2010/difficult//randf61f65.cudf /home/misc2010/tmp/201012070034/cudf2msu4trendy-1.0/randf61f65.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.85 1.00 1.02 5/41 7907
/proc/meminfo: memFree=654504/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) R 7905 7906 4159 34819 4229 4202496 355 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 269 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7906/statm: 642 269 230 194 0 28 0
[pid=7907] ppid=7906 vsize=2568 CPUtime=0
/proc/7907/stat : 7907 (cudf2msu4trendy) R 7906 7906 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 39 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7907/statm: 642 39 0 194 0 28 0

[startup+0.147254 s]
/proc/loadavg: 0.85 1.00 1.02 5/41 7907
/proc/meminfo: memFree=654504/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=8100 CPUtime=0.15
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 1785 0 0 0 13 2 0 0 25 0 1 0 885731029 8294400 1725 1283457024 134512640 136120023 4292790304 18446744073709551615 135169237 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 2025 1725 138 393 0 1630 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 10668

[startup+0.20727 s]
/proc/loadavg: 0.85 1.00 1.02 5/41 7907
/proc/meminfo: memFree=654504/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=10364 CPUtime=0.21
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 2338 0 0 0 19 2 0 0 25 0 1 0 885731029 10612736 2278 1283457024 134512640 136120023 4292790304 18446744073709551615 134711972 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 2591 2278 138 393 0 2196 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12932

[startup+0.307292 s]
/proc/loadavg: 0.85 1.00 1.02 5/41 7907
/proc/meminfo: memFree=654504/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=13860 CPUtime=0.31
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 3238 0 0 0 29 2 0 0 25 0 1 0 885731029 14192640 3178 1283457024 134512640 136120023 4292790304 18446744073709551615 135528598 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 3465 3178 139 393 0 3070 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16428

[startup+0.707378 s]
/proc/loadavg: 0.85 1.00 1.02 5/41 7907
/proc/meminfo: memFree=654504/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=25804 CPUtime=0.7
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 6228 0 0 0 68 2 0 0 25 0 1 0 885731029 26423296 6168 1283457024 134512640 136120023 4292790304 18446744073709551615 134706728 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 6451 6168 139 393 0 6056 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28372

[startup+1.50765 s]
/proc/loadavg: 0.85 1.00 1.02 2/42 7908
/proc/meminfo: memFree=601688/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54620 CPUtime=1.51
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13618 0 0 0 145 6 0 0 25 0 1 0 885731029 55930880 13410 1283457024 134512640 136120023 4292790304 18446744073709551615 134849198 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13655 13410 182 393 0 13260 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 57188

[startup+3.108 s]
/proc/loadavg: 0.85 1.00 1.02 2/42 7908
/proc/meminfo: memFree=601440/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=55148 CPUtime=3.11
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13742 0 0 0 305 6 0 0 25 0 1 0 885731029 56471552 13528 1283457024 134512640 136120023 4292790304 18446744073709551615 134888872 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13787 13528 182 393 0 13392 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 57716

[startup+6.30921 s]
/proc/loadavg: 0.86 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600820/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=6.3
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 624 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 134831623 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 57300

[startup+12.7113 s]
/proc/loadavg: 0.87 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600828/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=12.7
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 1264 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 134872381 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 57300

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

[startup+12.8113 s]
/proc/loadavg: 0.87 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600828/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=12.8
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 1274 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 135545122 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 12.8
Current children cumulated vsize (KiB) 57300

[startup+13.6116 s]
/proc/loadavg: 0.87 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600828/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=13.6
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 1354 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 134831685 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 13.6
Current children cumulated vsize (KiB) 57300

[startup+14.0117 s]
/proc/loadavg: 0.87 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600828/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=14
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 1394 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 134870327 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 14
Current children cumulated vsize (KiB) 57300

[startup+14.4118 s]
/proc/loadavg: 0.88 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600828/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=14.4
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 1434 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 134887411 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 14.4
Current children cumulated vsize (KiB) 57300

[startup+14.5118 s]
/proc/loadavg: 0.88 1.00 1.02 2/42 7908
/proc/meminfo: memFree=600828/1048576 swapFree=2080288/2097144
[pid=7906] ppid=7905 vsize=2568 CPUtime=0
/proc/7906/stat : 7906 (cudf2msu4trendy) S 7905 7906 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 885731029 2629632 270 1283457024 134512640 135304128 4292562896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7906/statm: 642 270 231 194 0 28 0
[pid=7907] ppid=7906 vsize=54732 CPUtime=14.5
/proc/7907/stat : 7907 (cudf_msu32) R 7906 7906 4159 34819 4229 4202496 13770 0 0 0 1444 6 0 0 25 0 1 0 885731029 56045568 13438 1283457024 134512640 136120023 4292790304 18446744073709551615 134887407 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/7907/statm: 13683 13438 182 393 0 13288 0
Current children cumulated CPU time (s) 14.5
Current children cumulated vsize (KiB) 57300

Child status: 0
Real time (s): 14.6013
CPU time (s): 14.5889
CPU user time (s): 14.5169
CPU system time (s): 0.072004
CPU usage (%): 99.915
Max. virtual memory (cumulated for all children) (KiB): 57716

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

runsolver used 0 second user time and 0 second system time

The end