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/rand753.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand753.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-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: 0.87 0.94 0.90 5/35 11847
/proc/meminfo: memFree=74840/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=0
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893756979 2633728 278 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 278 238 194 0 29 0
[pid=11847] ppid=11846 vsize=2448 CPUtime=0.02
/proc/11847/stat : 11847 (cudf_msu32) R 11846 11846 9023 34817 9081 4202496 432 0 0 0 2 0 0 0 25 0 1 0 893756979 2506752 325 1283457024 134512640 136125367 4289762672 18446744073709551615 135301572 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11847/statm: 612 325 141 394 0 216 0

[startup+0.175001 s]
/proc/loadavg: 0.87 0.94 0.90 5/35 11847
/proc/meminfo: memFree=74840/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=0
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893756979 2633728 278 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 278 238 194 0 29 0
[pid=11847] ppid=11846 vsize=9380 CPUtime=0.17
/proc/11847/stat : 11847 (cudf_msu32) R 11846 11846 9023 34817 9081 4202496 2137 0 0 0 17 0 0 0 25 0 1 0 893756979 9605120 2030 1283457024 134512640 136125367 4289762672 18446744073709551615 135543637 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11847/statm: 2345 2030 142 394 0 1949 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11952

[startup+0.205011 s]
/proc/loadavg: 0.87 0.94 0.90 5/35 11847
/proc/meminfo: memFree=74840/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=0
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893756979 2633728 278 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 278 238 194 0 29 0
[pid=11847] ppid=11846 vsize=10388 CPUtime=0.2
/proc/11847/stat : 11847 (cudf_msu32) R 11846 11846 9023 34817 9081 4202496 2404 0 0 0 20 0 0 0 25 0 1 0 893756979 10637312 2297 1283457024 134512640 136125367 4289762672 18446744073709551615 134739672 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11847/statm: 2597 2297 142 394 0 2201 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12960

[startup+0.305016 s]
/proc/loadavg: 0.87 0.94 0.90 5/35 11847
/proc/meminfo: memFree=74840/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=0
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893756979 2633728 278 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 278 238 194 0 29 0
[pid=11847] ppid=11846 vsize=13884 CPUtime=0.3
/proc/11847/stat : 11847 (cudf_msu32) R 11846 11846 9023 34817 9081 4202496 3289 0 0 0 28 2 0 0 25 0 1 0 893756979 14217216 3182 1283457024 134512640 136125367 4289762672 18446744073709551615 135543688 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11847/statm: 3471 3182 143 394 0 3075 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16456

[startup+0.705067 s]
/proc/loadavg: 0.87 0.94 0.90 5/35 11847
/proc/meminfo: memFree=74840/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=0
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893756979 2633728 278 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 278 238 194 0 29 0
[pid=11847] ppid=11846 vsize=26224 CPUtime=0.7
/proc/11847/stat : 11847 (cudf_msu32) R 11846 11846 9023 34817 9081 4202496 6354 0 0 0 67 3 0 0 25 0 1 0 893756979 26853376 6247 1283457024 134512640 136125367 4289762672 18446744073709551615 134717805 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11847/statm: 6556 6247 143 394 0 6160 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28796

[startup+1.50531 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 11848
/proc/meminfo: memFree=40524/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=0
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893756979 2633728 278 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 278 238 194 0 29 0
[pid=11847] ppid=11846 vsize=52644 CPUtime=1.5
/proc/11847/stat : 11847 (cudf_msu32) R 11846 11846 9023 34817 9081 4202496 13318 0 0 0 141 9 0 0 25 0 1 0 893756979 53907456 12870 1283457024 134512640 136125367 4289762672 18446744073709551615 134894908 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11847/statm: 13161 12870 161 394 0 12765 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 55216

[startup+3.10909 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 11848
/proc/meminfo: memFree=15972/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 2.27
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.30982 s]
/proc/loadavg: 0.88 0.94 0.90 2/36 11849
/proc/meminfo: memFree=44872/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=27948 CPUtime=3.99
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 7375 0 0 0 294 105 0 0 25 0 1 0 893757208 28618752 6539 1283457024 134512640 135887319 4290969248 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 6987 6539 138 336 0 6649 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 30520

[startup+12.7075 s]
/proc/loadavg: 0.89 0.94 0.90 2/36 11849
/proc/meminfo: memFree=27884/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=44864 CPUtime=10.26
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 14825 0 0 0 770 256 0 0 25 0 1 0 893757208 45940736 10787 1283457024 134512640 135887319 4290969248 18446744073709551615 134600857 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 11216 10787 144 336 0 10878 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 47436

[startup+25.5108 s]
/proc/loadavg: 0.91 0.94 0.90 2/36 11849
/proc/meminfo: memFree=17220/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=55516 CPUtime=23.03
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 18867 0 0 0 1997 306 0 0 25 0 1 0 893757208 56848384 13468 1283457024 134512640 135887319 4290969248 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 13879 13468 144 336 0 13541 0
Current children cumulated CPU time (s) 25.3
Current children cumulated vsize (KiB) 58088

[startup+51.1092 s]
/proc/loadavg: 0.94 0.95 0.90 2/36 11849
/proc/meminfo: memFree=16848/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=55912 CPUtime=48.59
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 18974 0 0 0 4553 306 0 0 25 0 1 0 893757208 57253888 13575 1283457024 134512640 135887319 4290969248 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 13978 13575 144 336 0 13640 0
Current children cumulated CPU time (s) 50.86
Current children cumulated vsize (KiB) 58484

[startup+102.31 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 11849
/proc/meminfo: memFree=15608/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=57112 CPUtime=99.79
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 19283 0 0 0 9673 306 0 0 25 0 1 0 893757208 58482688 13864 1283457024 134512640 135887319 4290969248 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 14278 13864 144 336 0 13940 0
Current children cumulated CPU time (s) 102.06
Current children cumulated vsize (KiB) 59684

[startup+162.304 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 11849
/proc/meminfo: memFree=13996/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=58696 CPUtime=159.78
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 19668 0 0 0 15670 308 0 0 25 0 1 0 893757208 60104704 14247 1283457024 134512640 135887319 4290969248 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 14674 14247 144 336 0 14336 0
Current children cumulated CPU time (s) 162.05
Current children cumulated vsize (KiB) 61268

[startup+222.308 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 11849
/proc/meminfo: memFree=12632/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=60016 CPUtime=219.7
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 20008 0 0 0 21660 310 0 0 25 0 1 0 893757208 61456384 14578 1283457024 134512640 135887319 4290969248 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 15004 14578 144 336 0 14666 0
Current children cumulated CPU time (s) 221.97
Current children cumulated vsize (KiB) 62588

[startup+282.312 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11849
/proc/meminfo: memFree=11640/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=61072 CPUtime=279.67
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 20279 0 0 0 27657 310 0 0 25 0 1 0 893757208 62537728 14844 1283457024 134512640 135887319 4290969248 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 15268 14844 144 336 0 14930 0
Current children cumulated CPU time (s) 281.94
Current children cumulated vsize (KiB) 63644



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.404 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11849
/proc/meminfo: memFree=11268/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=61336 CPUtime=287.74
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 20353 0 0 0 28464 310 0 0 25 0 1 0 893757208 62808064 14915 1283457024 134512640 135887319 4290969248 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 15334 14915 144 336 0 14996 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 63908

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

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

[startup+290.404 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11849
/proc/meminfo: memFree=11268/1048576 swapFree=2095372/2097144
[pid=11846] ppid=11845 vsize=2572 CPUtime=2.27
/proc/11846/stat : 11846 (cudf2pbo4trendy) S 11845 11846 9023 34817 9081 4202496 400 14275 0 0 0 0 177 50 20 0 1 0 893756979 2633728 281 1283457024 134512640 135304128 4293415008 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11846/statm: 643 281 241 194 0 29 0
[pid=11849] ppid=11846 vsize=61336 CPUtime=287.74
/proc/11849/stat : 11849 (bmo-pblex32) R 11846 11846 9023 34817 9081 4202496 20353 0 0 0 28464 310 0 0 25 0 1 0 893757208 62808064 14915 1283457024 134512640 135887319 4290969248 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11849/statm: 15334 14915 144 336 0 14996 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 63908

Child status: 0
Real time (s): 290.51
CPU time (s): 290.134
CPU user time (s): 286.486
CPU system time (s): 3.64823
CPU usage (%): 99.8706
Max. virtual memory (cumulated for all children) (KiB): 63908

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 286.486
system time used= 3.64823
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 37239
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= 21
involuntary context switches= 6142

runsolver used 0 second user time and 0 second system time

The end