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/rand815.sarge-etch.cudf.sarge-etch.log.runsolver ./cudf2msu4trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand815.sarge-etch.cudf /home/misc2010/tmp/201012070034/cudf2msu4trendy-1.0/rand815.sarge-etch.cudf.sarge-etch.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 0.99 1.04 4/45 26189
/proc/meminfo: memFree=760176/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=2312 CPUtime=0.01
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 347 0 0 0 1 0 0 0 25 0 1 0 882965481 2367488 287 1283457024 134512640 136120023 4287898480 18446744073709551615 134712101 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 578 287 137 393 0 183 0

[startup+0.191705 s]
/proc/loadavg: 0.85 0.99 1.04 4/45 26189
/proc/meminfo: memFree=760176/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=9180 CPUtime=0.19
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 2066 0 0 0 17 2 0 0 25 0 1 0 882965481 9400320 2006 1283457024 134512640 136120023 4287898480 18446744073709551615 134712063 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 2295 2006 138 393 0 1900 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 11748

[startup+0.211712 s]
/proc/loadavg: 0.85 0.99 1.04 4/45 26189
/proc/meminfo: memFree=760176/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=9860 CPUtime=0.21
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 2219 0 0 0 19 2 0 0 25 0 1 0 882965481 10096640 2159 1283457024 134512640 136120023 4287898480 18446744073709551615 134711444 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 2465 2159 138 393 0 2070 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12428

[startup+0.311754 s]
/proc/loadavg: 0.85 0.99 1.04 4/45 26189
/proc/meminfo: memFree=760176/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=13224 CPUtime=0.31
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 3067 0 0 0 29 2 0 0 25 0 1 0 882965481 13541376 3007 1283457024 134512640 136120023 4287898480 18446744073709551615 134722459 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 3306 3007 139 393 0 2911 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15792

[startup+0.71182 s]
/proc/loadavg: 0.85 0.99 1.04 4/45 26189
/proc/meminfo: memFree=760176/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=40200 CPUtime=0.71
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 13643 0 0 0 62 9 0 0 25 0 1 0 882965481 41164800 9749 1283457024 134512640 136120023 4287898480 18446744073709551615 134870990 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 10050 9749 166 393 0 9655 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 42768

[startup+1.51198 s]
/proc/loadavg: 0.85 0.99 1.04 2/46 26190
/proc/meminfo: memFree=722248/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=40200 CPUtime=1.51
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 13655 0 0 0 142 9 0 0 25 0 1 0 882965481 41164800 9761 1283457024 134512640 136120023 4287898480 18446744073709551615 134859203 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 10050 9761 178 393 0 9655 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 42768

[startup+3.11234 s]
/proc/loadavg: 0.86 0.99 1.04 2/46 26190
/proc/meminfo: memFree=721628/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=40732 CPUtime=3.11
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 13781 0 0 0 302 9 0 0 25 0 1 0 882965481 41709568 9883 1283457024 134512640 136120023 4287898480 18446744073709551615 134863405 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 10183 9883 182 393 0 9788 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 43300

[startup+6.31312 s]
/proc/loadavg: 0.86 0.99 1.04 2/46 26190
/proc/meminfo: memFree=721628/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=40732 CPUtime=6.31
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 13781 0 0 0 622 9 0 0 25 0 1 0 882965481 41709568 9883 1283457024 134512640 136120023 4287898480 18446744073709551615 134862831 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 10183 9883 182 393 0 9788 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 43300

[startup+12.7048 s]
/proc/loadavg: 0.88 0.99 1.04 2/46 26190
/proc/meminfo: memFree=715924/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=46344 CPUtime=12.7
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 16552 0 0 0 1258 12 0 0 25 0 1 0 882965481 47456256 11295 1283457024 134512640 136120023 4287898480 18446744073709551615 134871640 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 11586 11295 182 393 0 11191 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 48912

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

[startup+12.8048 s]
/proc/loadavg: 0.88 0.99 1.04 2/46 26190
/proc/meminfo: memFree=715924/1048576 swapFree=2077184/2097144
[pid=26188] ppid=26187 vsize=2568 CPUtime=0
/proc/26188/stat : 26188 (cudf2msu4trendy) S 26187 26188 4159 34819 4229 4202496 373 0 0 0 0 0 0 0 25 0 1 0 882965481 2629632 270 1283457024 134512640 135304128 4291235456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26188/statm: 642 270 231 194 0 28 0
[pid=26189] ppid=26188 vsize=46344 CPUtime=12.8
/proc/26189/stat : 26189 (cudf_msu32) R 26188 26188 4159 34819 4229 4202496 16552 0 0 0 1268 12 0 0 25 0 1 0 882965481 47456256 11295 1283457024 134512640 136120023 4287898480 18446744073709551615 134869777 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26189/statm: 11586 11295 182 393 0 11191 0
Current children cumulated CPU time (s) 12.8
Current children cumulated vsize (KiB) 48912

Child status: 0
Real time (s): 12.8635
CPU time (s): 12.8528
CPU user time (s): 12.7128
CPU system time (s): 0.140008
CPU usage (%): 99.9169
Max. virtual memory (cumulated for all children) (KiB): 48912

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.7128
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= 16951
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= 207

runsolver used 0 second user time and 0 second system time

The end