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/cudf2pbo4trendy-1.0/rand316.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand316.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand316.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: 0.86 0.94 0.90 4/39 10622
/proc/meminfo: memFree=68008/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=0
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893099523 2633728 278 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 278 238 194 0 29 0
[pid=10622] ppid=10621 vsize=2052 CPUtime=0.01
/proc/10622/stat : 10622 (cudf_msu32) R 10621 10621 9023 34817 9081 4202496 306 0 0 0 1 0 0 0 25 0 1 0 893099523 2101248 199 1283457024 134512640 136125367 4290028976 18446744073709551615 134717747 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10622/statm: 513 199 141 394 0 117 0

[startup+0.195554 s]
/proc/loadavg: 0.86 0.94 0.90 4/39 10622
/proc/meminfo: memFree=68008/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=0
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893099523 2633728 278 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 278 238 194 0 29 0
[pid=10622] ppid=10621 vsize=10040 CPUtime=0.19
/proc/10622/stat : 10622 (cudf_msu32) R 10621 10621 9023 34817 9081 4202496 2331 0 0 0 19 0 0 0 25 0 1 0 893099523 10280960 2224 1283457024 134512640 136125367 4290028976 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10622/statm: 2510 2224 142 394 0 2114 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12612

[startup+0.205557 s]
/proc/loadavg: 0.86 0.94 0.90 4/39 10622
/proc/meminfo: memFree=68008/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=0
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893099523 2633728 278 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 278 238 194 0 29 0
[pid=10622] ppid=10621 vsize=10388 CPUtime=0.2
/proc/10622/stat : 10622 (cudf_msu32) R 10621 10621 9023 34817 9081 4202496 2411 0 0 0 20 0 0 0 25 0 1 0 893099523 10637312 2304 1283457024 134512640 136125367 4290028976 18446744073709551615 134717730 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10622/statm: 2597 2304 142 394 0 2201 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12960

[startup+0.305566 s]
/proc/loadavg: 0.86 0.94 0.90 4/39 10622
/proc/meminfo: memFree=68008/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=0
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893099523 2633728 278 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 278 238 194 0 29 0
[pid=10622] ppid=10621 vsize=13884 CPUtime=0.3
/proc/10622/stat : 10622 (cudf_msu32) R 10621 10621 9023 34817 9081 4202496 3291 0 0 0 30 0 0 0 25 0 1 0 893099523 14217216 3184 1283457024 134512640 136125367 4290028976 18446744073709551615 134717212 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10622/statm: 3471 3184 143 394 0 3075 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16456

[startup+0.705618 s]
/proc/loadavg: 0.86 0.94 0.90 4/39 10622
/proc/meminfo: memFree=68008/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=0
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893099523 2633728 278 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 278 238 194 0 29 0
[pid=10622] ppid=10621 vsize=26092 CPUtime=0.7
/proc/10622/stat : 10622 (cudf_msu32) R 10621 10621 9023 34817 9081 4202496 6338 0 0 0 69 1 0 0 25 0 1 0 893099523 26718208 6231 1283457024 134512640 136125367 4290028976 18446744073709551615 135399169 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10622/statm: 6523 6231 143 394 0 6127 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28664

[startup+1.50572 s]
/proc/loadavg: 0.86 0.94 0.90 2/40 10623
/proc/meminfo: memFree=33764/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=0
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893099523 2633728 278 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 278 238 194 0 29 0
[pid=10622] ppid=10621 vsize=52660 CPUtime=1.5
/proc/10622/stat : 10622 (cudf_msu32) R 10621 10621 9023 34817 9081 4202496 13322 0 0 0 143 7 0 0 25 0 1 0 893099523 53923840 12874 1283457024 134512640 136125367 4290028976 18446744073709551615 135144069 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10622/statm: 13165 12874 161 394 0 12769 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 55232

[startup+3.10592 s]
/proc/loadavg: 0.86 0.94 0.90 2/40 10623
/proc/meminfo: memFree=8964/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 2.29
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.30703 s]
/proc/loadavg: 0.87 0.94 0.90 2/40 10624
/proc/meminfo: memFree=31532/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=35764 CPUtime=3.87
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 10776 0 0 0 288 99 0 0 25 0 1 0 893099753 36622336 8502 1283457024 134512640 135887319 4289406240 18446744073709551615 134637835 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 8941 8502 144 336 0 8603 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 38336

[startup+12.7089 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10624
/proc/meminfo: memFree=15288/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=50004 CPUtime=10.26
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 17339 0 0 0 848 178 0 0 25 0 1 0 893099753 51204096 12055 1283457024 134512640 135887319 4289406240 18446744073709551615 134615163 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 12501 12055 144 336 0 12163 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 52576

[startup+25.5129 s]
/proc/loadavg: 0.91 0.94 0.91 2/40 10624
/proc/meminfo: memFree=6484/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=59336 CPUtime=22.96
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 19725 0 0 0 2006 290 0 0 25 0 1 0 893099753 60760064 14432 1283457024 134512640 135887319 4289406240 18446744073709551615 134603241 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 14834 14432 144 336 0 14496 0
Current children cumulated CPU time (s) 25.25
Current children cumulated vsize (KiB) 61908

[startup+51.1088 s]
/proc/loadavg: 0.94 0.95 0.91 2/40 10624
/proc/meminfo: memFree=6440/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=60800 CPUtime=48.55
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 20096 0 0 0 4559 296 0 0 25 0 1 0 893099753 62259200 14776 1283457024 134512640 135887319 4289406240 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 15200 14776 144 336 0 14862 0
Current children cumulated CPU time (s) 50.84
Current children cumulated vsize (KiB) 63372

[startup+102.311 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10624
/proc/meminfo: memFree=5308/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=64244 CPUtime=99.72
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 20968 0 0 0 9675 297 0 0 25 0 1 0 893099753 65785856 15629 1283457024 134512640 135887319 4289406240 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 16061 15629 144 336 0 15723 0
Current children cumulated CPU time (s) 102.01
Current children cumulated vsize (KiB) 66816

[startup+162.314 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 10624
/proc/meminfo: memFree=6208/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=67808 CPUtime=159.71
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 21899 0 0 0 15671 300 0 0 25 0 1 0 893099753 69435392 16538 1283457024 134512640 135887319 4289406240 18446744073709551615 134615443 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 16952 16538 144 336 0 16614 0
Current children cumulated CPU time (s) 162
Current children cumulated vsize (KiB) 70380

[startup+222.312 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 10624
/proc/meminfo: memFree=5488/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=69580 CPUtime=219.66
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 22364 0 0 0 21663 303 0 0 25 0 1 0 893099753 71249920 16970 1283457024 134512640 135887319 4289406240 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 17395 16970 144 336 0 17057 0
Current children cumulated CPU time (s) 221.95
Current children cumulated vsize (KiB) 72152

[startup+282.304 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10624
/proc/meminfo: memFree=5264/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=70900 CPUtime=279.6
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 22698 0 0 0 27655 305 0 0 25 0 1 0 893099753 72601600 17299 1283457024 134512640 135887319 4289406240 18446744073709551615 134603875 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 17725 17299 144 336 0 17387 0
Current children cumulated CPU time (s) 281.89
Current children cumulated vsize (KiB) 73472



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.506 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10624
/proc/meminfo: memFree=6576/1048576 swapFree=2095372/2097144
[pid=10621] ppid=10620 vsize=2572 CPUtime=2.29
/proc/10621/stat : 10621 (cudf2pbo4trendy) S 10620 10621 9023 34817 9081 4202496 401 14318 0 0 0 0 184 45 20 0 1 0 893099523 2633728 281 1283457024 134512640 135304128 4293968096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10621/statm: 643 281 241 194 0 29 0
[pid=10624] ppid=10621 vsize=71164 CPUtime=287.79
/proc/10624/stat : 10624 (bmo-pblex32) R 10621 10621 9023 34817 9081 4202496 22770 0 0 0 28471 308 0 0 25 0 1 0 893099753 72871936 17371 1283457024 134512640 135887319 4289406240 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10624/statm: 17791 17371 144 336 0 17453 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 73736

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.612
CPU time (s): 290.198
CPU user time (s): 286.654
CPU system time (s): 3.54422
CPU usage (%): 99.8577
Max. virtual memory (cumulated for all children) (KiB): 73736

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 286.654
system time used= 3.54422
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 39675
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= 24
involuntary context switches= 9423

runsolver used 0 second user time and 0 second system time

The end