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/rand108.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./cudf2msu4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand108.sarge-etch-lenny.cudf /home/misc2010/tmp/201012070034/cudf2msu4trendy-1.0/rand108.sarge-etch-lenny.cudf.sarge-etch-lenny.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.10 1.08 1.03 4/44 6248
/proc/meminfo: memFree=656432/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=2044 CPUtime=0.01
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 266 0 0 0 1 0 0 0 25 0 1 0 878032718 2093056 206 1283457024 134512640 136120023 4290844192 18446744073709551615 135530294 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 511 206 137 393 0 116 0

[startup+0.145889 s]
/proc/loadavg: 1.10 1.08 1.03 4/44 6248
/proc/meminfo: memFree=656432/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=7680 CPUtime=0.15
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 1696 0 0 0 15 0 0 0 25 0 1 0 878032718 7864320 1636 1283457024 134512640 136120023 4290844192 18446744073709551615 135534676 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 1920 1636 138 393 0 1525 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 10248

[startup+0.205909 s]
/proc/loadavg: 1.10 1.08 1.03 4/44 6248
/proc/meminfo: memFree=656432/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=9852 CPUtime=0.21
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 2218 0 0 0 21 0 0 0 25 0 1 0 878032718 10088448 2158 1283457024 134512640 136120023 4290844192 18446744073709551615 134732893 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 2463 2158 138 393 0 2068 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12420

[startup+0.305926 s]
/proc/loadavg: 1.10 1.08 1.03 4/44 6248
/proc/meminfo: memFree=656432/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=13084 CPUtime=0.31
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 3033 0 0 0 31 0 0 0 25 0 1 0 878032718 13398016 2973 1283457024 134512640 136120023 4290844192 18446744073709551615 134711970 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 3271 2973 139 393 0 2876 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15652

[startup+0.706032 s]
/proc/loadavg: 1.10 1.08 1.03 4/44 6248
/proc/meminfo: memFree=656432/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=24372 CPUtime=0.7
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 5843 0 0 0 70 0 0 0 25 0 1 0 878032718 24956928 5783 1283457024 134512640 136120023 4290844192 18446744073709551615 134711970 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 6093 5783 139 393 0 5698 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26940

[startup+1.50627 s]
/proc/loadavg: 1.10 1.08 1.03 2/45 6249
/proc/meminfo: memFree=620576/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=67996 CPUtime=1.51
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 23787 0 0 0 142 9 0 0 25 0 1 0 878032718 69627904 16684 1283457024 134512640 136120023 4290844192 18446744073709551615 134867567 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 16999 16684 178 393 0 16604 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 70564

[startup+3.10666 s]
/proc/loadavg: 1.09 1.08 1.03 2/45 6249
/proc/meminfo: memFree=590196/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=68288 CPUtime=3.11
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 23859 0 0 0 302 9 0 0 25 0 1 0 878032718 69926912 16743 1283457024 134512640 136120023 4290844192 18446744073709551615 134872418 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 17072 16743 182 393 0 16677 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 70856

[startup+6.30757 s]
/proc/loadavg: 1.09 1.08 1.03 2/45 6249
/proc/meminfo: memFree=590072/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=68288 CPUtime=6.31
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 23859 0 0 0 621 10 0 0 25 0 1 0 878032718 69926912 16743 1283457024 134512640 136120023 4290844192 18446744073709551615 134831717 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 17072 16743 182 393 0 16677 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 70856

[startup+12.7098 s]
/proc/loadavg: 1.08 1.07 1.03 2/45 6249
/proc/meminfo: memFree=590072/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=68288 CPUtime=12.7
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 23859 0 0 0 1260 10 0 0 25 0 1 0 878032718 69926912 16743 1283457024 134512640 136120023 4290844192 18446744073709551615 135525563 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 17072 16743 182 393 0 16677 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 70856

[startup+25.5139 s]
/proc/loadavg: 1.07 1.07 1.03 2/45 6249
/proc/meminfo: memFree=582384/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=75976 CPUtime=25.5
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 25792 0 0 0 2537 13 0 0 25 0 1 0 878032718 77799424 18671 1283457024 134512640 136120023 4290844192 18446744073709551615 134863405 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 18994 18671 182 393 0 18599 0
Current children cumulated CPU time (s) 25.5
Current children cumulated vsize (KiB) 78544

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

[startup+25.604 s]
/proc/loadavg: 1.07 1.07 1.03 2/45 6249
/proc/meminfo: memFree=582384/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=75976 CPUtime=25.59
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 25792 0 0 0 2546 13 0 0 25 0 1 0 878032718 77799424 18671 1283457024 134512640 136120023 4290844192 18446744073709551615 134849286 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 18994 18671 182 393 0 18599 0
Current children cumulated CPU time (s) 25.59
Current children cumulated vsize (KiB) 78544

[startup+28.8054 s]
/proc/loadavg: 1.06 1.07 1.03 2/45 6249
/proc/meminfo: memFree=582260/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=75976 CPUtime=28.79
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 25792 0 0 0 2866 13 0 0 25 0 1 0 878032718 77799424 18671 1283457024 134512640 136120023 4290844192 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 18994 18671 182 393 0 18599 0
Current children cumulated CPU time (s) 28.79
Current children cumulated vsize (KiB) 78544

[startup+30.4059 s]
/proc/loadavg: 1.06 1.07 1.03 2/45 6249
/proc/meminfo: memFree=580772/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=77524 CPUtime=30.39
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 27973 0 0 0 3024 15 0 0 25 0 1 0 878032718 79384576 19079 1283457024 134512640 136120023 4290844192 18446744073709551615 134863187 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 19381 19079 182 393 0 18986 0
Current children cumulated CPU time (s) 30.39
Current children cumulated vsize (KiB) 80092

[startup+31.2062 s]
/proc/loadavg: 1.06 1.07 1.03 2/45 6249
/proc/meminfo: memFree=580772/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=77524 CPUtime=31.19
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 27973 0 0 0 3104 15 0 0 25 0 1 0 878032718 79384576 19079 1283457024 134512640 136120023 4290844192 18446744073709551615 134831658 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 19381 19079 182 393 0 18986 0
Current children cumulated CPU time (s) 31.19
Current children cumulated vsize (KiB) 80092

[startup+32.0064 s]
/proc/loadavg: 1.06 1.07 1.03 2/45 6249
/proc/meminfo: memFree=580772/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=77524 CPUtime=31.99
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 27973 0 0 0 3184 15 0 0 25 0 1 0 878032718 79384576 19079 1283457024 134512640 136120023 4290844192 18446744073709551615 135545108 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 19381 19079 182 393 0 18986 0
Current children cumulated CPU time (s) 31.99
Current children cumulated vsize (KiB) 80092

[startup+32.2065 s]
/proc/loadavg: 1.06 1.07 1.03 2/45 6249
/proc/meminfo: memFree=580772/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=77524 CPUtime=32.2
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 27973 0 0 0 3205 15 0 0 25 0 1 0 878032718 79384576 19079 1283457024 134512640 136120023 4290844192 18446744073709551615 134870961 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 19381 19079 182 393 0 18986 0
Current children cumulated CPU time (s) 32.2
Current children cumulated vsize (KiB) 80092

[startup+32.3065 s]
/proc/loadavg: 1.06 1.07 1.03 2/45 6249
/proc/meminfo: memFree=580772/1048576 swapFree=2077656/2097144
[pid=6247] ppid=6246 vsize=2568 CPUtime=0
/proc/6247/stat : 6247 (cudf2msu4trendy) S 6246 6247 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 22 0 1 0 878032718 2629632 270 1283457024 134512640 135304128 4291968800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 642 270 231 194 0 28 0
[pid=6248] ppid=6247 vsize=77524 CPUtime=32.3
/proc/6248/stat : 6248 (cudf_msu32) R 6247 6247 4159 34819 4229 4202496 27973 0 0 0 3215 15 0 0 25 0 1 0 878032718 79384576 19079 1283457024 134512640 136120023 4290844192 18446744073709551615 134870711 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/6248/statm: 19381 19079 182 393 0 18986 0
Current children cumulated CPU time (s) 32.3
Current children cumulated vsize (KiB) 80092

Child status: 0
Real time (s): 32.3992
CPU time (s): 32.394
CPU user time (s): 32.218
CPU system time (s): 0.176011
CPU usage (%): 99.9841
Max. virtual memory (cumulated for all children) (KiB): 80092

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

runsolver used 0 second user time and 0 second system time

The end