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/201012081719/cudf2pbo4paranoid-1.0/rand815.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand815.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand815.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.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.98 0.95 0.91 2/35 12183
/proc/meminfo: memFree=94416/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=0
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 278 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 278 238 194 0 29 0
[pid=12183] ppid=12182 vsize=2572 CPUtime=0
/proc/12183/stat : 12183 (cudf2pbo4parano) D 12182 12182 9023 34817 9081 4202560 79 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 103 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/12183/statm: 643 103 62 194 0 29 0

[startup+0.112214 s]
/proc/loadavg: 0.98 0.95 0.91 2/35 12183
/proc/meminfo: memFree=94416/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=0
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 278 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 278 238 194 0 29 0
[pid=12183] ppid=12182 vsize=5676 CPUtime=0.08
/proc/12183/stat : 12183 (cudf_msu32) R 12182 12182 9023 34817 9081 4202496 1244 0 0 0 8 0 0 0 25 0 1 0 893904154 5812224 1137 1283457024 134512640 136125367 4294265264 18446744073709551615 135684385 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12183/statm: 1419 1137 143 394 0 1023 0
Current children cumulated CPU time (s) 0.08
Current children cumulated vsize (KiB) 8248

[startup+0.20422 s]
/proc/loadavg: 0.98 0.95 0.91 2/35 12183
/proc/meminfo: memFree=94416/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=0
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 278 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 278 238 194 0 29 0
[pid=12183] ppid=12182 vsize=9372 CPUtime=0.16
/proc/12183/stat : 12183 (cudf_msu32) R 12182 12182 9023 34817 9081 4202496 2164 0 0 0 15 1 0 0 25 0 1 0 893904154 9596928 2057 1283457024 134512640 136125367 4294265264 18446744073709551615 134717766 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12183/statm: 2343 2057 143 394 0 1947 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11944

[startup+0.30673 s]
/proc/loadavg: 0.98 0.95 0.91 2/35 12183
/proc/meminfo: memFree=94416/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=0
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 278 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 278 238 194 0 29 0
[pid=12183] ppid=12182 vsize=13000 CPUtime=0.24
/proc/12183/stat : 12183 (cudf_msu32) D 12182 12182 9023 34817 9081 4202496 3056 0 0 0 23 1 0 0 25 0 1 0 893904154 13312000 2949 1283457024 134512640 136125367 4294265264 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/12183/statm: 3250 2949 144 394 0 2854 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 15572

[startup+0.704315 s]
/proc/loadavg: 0.98 0.95 0.91 2/35 12183
/proc/meminfo: memFree=94416/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=0
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 278 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 278 238 194 0 29 0
[pid=12183] ppid=12182 vsize=24944 CPUtime=0.58
/proc/12183/stat : 12183 (cudf_msu32) R 12182 12182 9023 34817 9081 4202496 6054 0 0 0 56 2 0 0 25 0 1 0 893904154 25542656 5947 1283457024 134512640 136125367 4294265264 18446744073709551615 134717880 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12183/statm: 6236 5947 144 394 0 5840 0
Current children cumulated CPU time (s) 0.58
Current children cumulated vsize (KiB) 27516

[startup+1.50819 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12184
/proc/meminfo: memFree=41768/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=0
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 893904154 2633728 278 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 278 238 194 0 29 0
[pid=12183] ppid=12182 vsize=49276 CPUtime=1.29
/proc/12183/stat : 12183 (cudf_msu32) R 12182 12182 9023 34817 9081 4202496 12199 0 0 0 120 9 0 0 25 0 1 0 893904154 50458624 12043 1283457024 134512640 136125367 4294265264 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12183/statm: 12319 12043 165 394 0 11923 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 51848

[startup+3.1095 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=57600/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=1.67
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 400 12201 0 0 0 0 140 27 18 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
[pid=12185] ppid=12182 vsize=16936 CPUtime=1.21
/proc/12185/stat : 12185 (bmo-pblex32) R 12182 12182 9023 34817 9081 4202496 4578 0 0 0 97 24 0 0 25 0 1 0 893904343 17342464 3959 1283457024 134512640 135887319 4288760960 18446744073709551615 134624768 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12185/statm: 4234 3959 138 336 0 3896 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 19508

[startup+6.30846 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=49796/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=1.67
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 400 12201 0 0 0 0 140 27 18 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
[pid=12185] ppid=12182 vsize=25320 CPUtime=4.26
/proc/12185/stat : 12185 (bmo-pblex32) R 12182 12182 9023 34817 9081 4202496 7462 0 0 0 343 83 0 0 25 0 1 0 893904343 25927680 6054 1283457024 134512640 135887319 4288760960 18446744073709551615 134624520 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12185/statm: 6330 6054 144 336 0 5992 0
Current children cumulated CPU time (s) 5.93
Current children cumulated vsize (KiB) 27892

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

[startup+6.40848 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=49796/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=1.67
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 400 12201 0 0 0 0 140 27 18 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
[pid=12185] ppid=12182 vsize=25460 CPUtime=4.36
/proc/12185/stat : 12185 (bmo-pblex32) R 12182 12182 9023 34817 9081 4202496 7494 0 0 0 353 83 0 0 25 0 1 0 893904343 26071040 6086 1283457024 134512640 135887319 4288760960 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12185/statm: 6365 6086 144 336 0 6027 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 28032

[startup+8.00902 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=47192/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=1.67
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 400 12201 0 0 0 0 140 27 18 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
[pid=12185] ppid=12182 vsize=27420 CPUtime=5.92
/proc/12185/stat : 12185 (bmo-pblex32) R 12182 12182 9023 34817 9081 4202496 7987 0 0 0 483 109 0 0 25 0 1 0 893904343 28078080 6579 1283457024 134512640 135887319 4288760960 18446744073709551615 134615005 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12185/statm: 6855 6579 144 336 0 6517 0
Current children cumulated CPU time (s) 7.59
Current children cumulated vsize (KiB) 29992

[startup+8.80924 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=45828/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=1.67
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 400 12201 0 0 0 0 140 27 18 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
[pid=12185] ppid=12182 vsize=28396 CPUtime=6.71
/proc/12185/stat : 12185 (bmo-pblex32) R 12182 12182 9023 34817 9081 4202496 8228 0 0 0 555 116 0 0 25 0 1 0 893904343 29077504 6820 1283457024 134512640 135887319 4288760960 18446744073709551615 134525296 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12185/statm: 7099 6820 144 336 0 6761 0
Current children cumulated CPU time (s) 8.38
Current children cumulated vsize (KiB) 30968

[startup+9.60954 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=45828/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=1.67
/proc/12182/stat : 12182 (cudf2pbo4parano) S 12181 12182 9023 34817 9081 4202496 400 12201 0 0 0 0 140 27 18 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
[pid=12185] ppid=12182 vsize=29376 CPUtime=7.51
/proc/12185/stat : 12185 (bmo-pblex32) R 12182 12182 9023 34817 9081 4202496 8478 0 0 0 631 120 0 0 25 0 1 0 893904343 30081024 7068 1283457024 134512640 135887319 4288760960 18446744073709551615 134617819 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12185/statm: 7344 7068 144 336 0 7006 0
Current children cumulated CPU time (s) 9.18
Current children cumulated vsize (KiB) 31948

[startup+9.80962 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 12185
/proc/meminfo: memFree=45828/1048576 swapFree=2095372/2097144
[pid=12182] ppid=12181 vsize=2572 CPUtime=9.35
/proc/12182/stat : 12182 (cudf2pbo4parano) R 12181 12182 9023 34817 9081 4202496 418 20722 0 0 0 0 787 148 20 0 1 0 893904154 2633728 281 1283457024 134512640 135304128 4292984800 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/12182/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 9.35
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 9.82429
CPU time (s): 9.41259
CPU user time (s): 7.9325
CPU system time (s): 1.48009
CPU usage (%): 95.8094
Max. virtual memory (cumulated for all children) (KiB): 51848

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.9325
system time used= 1.48009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 23024
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= 60
involuntary context switches= 4938

runsolver used 0 second user time and 0 second system time

The end