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/rand753.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2msu4paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand753.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012061533/cudf2msu4paranoid-1.0/rand753.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.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.12 1.13 1.10 4/46 19271
/proc/meminfo: memFree=614292/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=1912 CPUtime=0.01
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 240 0 0 0 1 0 0 0 25 0 1 0 875917825 1957888 180 1283457024 134512640 136120023 4291831536 18446744073709551615 134711978 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 478 180 137 393 0 83 0

[startup+0.183806 s]
/proc/loadavg: 1.12 1.13 1.10 4/46 19271
/proc/meminfo: memFree=614292/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=9496 CPUtime=0.19
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 2135 0 0 0 19 0 0 0 25 0 1 0 875917825 9723904 2075 1283457024 134512640 136120023 4291831536 18446744073709551615 134712061 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 2374 2075 138 393 0 1979 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12064

[startup+0.213833 s]
/proc/loadavg: 1.12 1.13 1.10 4/46 19271
/proc/meminfo: memFree=614292/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=10700 CPUtime=0.22
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 2422 0 0 0 22 0 0 0 25 0 1 0 875917825 10956800 2362 1283457024 134512640 136120023 4291831536 18446744073709551615 134722466 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 2675 2362 139 393 0 2280 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 13268

[startup+0.303859 s]
/proc/loadavg: 1.12 1.13 1.10 4/46 19271
/proc/meminfo: memFree=614292/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=13472 CPUtime=0.31
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 3143 0 0 0 31 0 0 0 25 0 1 0 875917825 13795328 3083 1283457024 134512640 136120023 4291831536 18446744073709551615 134721298 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 3368 3083 139 393 0 2973 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16040

[startup+0.703983 s]
/proc/loadavg: 1.12 1.13 1.10 4/46 19271
/proc/meminfo: memFree=614292/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=25416 CPUtime=0.7
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 6130 0 0 0 70 0 0 0 25 0 1 0 875917825 26025984 6070 1283457024 134512640 136120023 4291831536 18446744073709551615 135530362 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 6354 6070 139 393 0 5959 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27984

[startup+1.50424 s]
/proc/loadavg: 1.12 1.13 1.10 2/47 19272
/proc/meminfo: memFree=580148/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=64232 CPUtime=1.5
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 21686 0 0 0 144 6 0 0 25 0 1 0 875917825 65773568 15719 1283457024 134512640 136120023 4291831536 18446744073709551615 135528598 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 16058 15719 157 393 0 15663 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 66800

[startup+3.10477 s]
/proc/loadavg: 1.12 1.13 1.10 2/47 19272
/proc/meminfo: memFree=542576/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=73524 CPUtime=3.1
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 24048 0 0 0 303 7 0 0 25 0 1 0 875917825 75288576 18076 1283457024 134512640 136120023 4291831536 18446744073709551615 134862296 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18381 18076 178 393 0 17986 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 76092

[startup+6.30586 s]
/proc/loadavg: 1.11 1.13 1.10 2/47 19272
/proc/meminfo: memFree=542328/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=6.3
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 619 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134862296 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 76608

[startup+12.7077 s]
/proc/loadavg: 1.10 1.12 1.10 2/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=12.68
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 1257 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134862420 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 76608

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

[startup+12.8077 s]
/proc/loadavg: 1.10 1.12 1.10 2/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=12.78
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 1267 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134865782 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 12.78
Current children cumulated vsize (KiB) 76608

[startup+19.2095 s]
/proc/loadavg: 1.09 1.12 1.10 2/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=19.18
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 1907 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134831620 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 19.18
Current children cumulated vsize (KiB) 76608

[startup+22.4102 s]
/proc/loadavg: 1.08 1.12 1.10 2/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=22.37
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 2226 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134863744 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 22.37
Current children cumulated vsize (KiB) 76608

[startup+24.0106 s]
/proc/loadavg: 1.08 1.12 1.10 3/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=23.96
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 2385 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134865952 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 23.96
Current children cumulated vsize (KiB) 76608

[startup+24.4107 s]
/proc/loadavg: 1.08 1.12 1.09 2/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=74040 CPUtime=24.36
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28979 0 0 0 2425 11 0 0 25 0 1 0 875917825 75816960 18213 1283457024 134512640 136120023 4291831536 18446744073709551615 134850125 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18510 18213 182 393 0 18115 0
Current children cumulated CPU time (s) 24.36
Current children cumulated vsize (KiB) 76608

[startup+24.6108 s]
/proc/loadavg: 1.08 1.12 1.09 2/47 19272
/proc/meminfo: memFree=542204/1048576 swapFree=2078744/2097144
[pid=19270] ppid=19269 vsize=2568 CPUtime=0
/proc/19270/stat : 19270 (cudf2msu4parano) S 19269 19270 2059 34821 2220 4202496 374 0 0 0 0 0 0 0 21 0 1 0 875917825 2629632 271 1283457024 134512640 135304128 4286904864 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19270/statm: 642 271 231 194 0 28 0
[pid=19271] ppid=19270 vsize=73844 CPUtime=24.56
/proc/19271/stat : 19271 (cudf_msu32) R 19270 19270 2059 34821 2220 4202496 28994 0 0 0 2444 12 0 0 25 0 1 0 875917825 75616256 18179 1283457024 134512640 136120023 4291831536 18446744073709551615 135534693 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/19271/statm: 18461 18179 197 393 0 18066 0
Current children cumulated CPU time (s) 24.56
Current children cumulated vsize (KiB) 76412

Child status: 0
Real time (s): 24.6429
CPU time (s): 24.5975
CPU user time (s): 24.4615
CPU system time (s): 0.136008
CPU usage (%): 99.816
Max. virtual memory (cumulated for all children) (KiB): 76608

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

runsolver used 0 second user time and 0 second system time

The end