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/rand108.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand108.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand108.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: 1.01 0.91 0.53 4/39 9379
/proc/meminfo: memFree=62620/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=0
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892244402 2637824 279 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 279 238 194 0 30 0
[pid=9379] ppid=9378 vsize=1912 CPUtime=0
/proc/9379/stat : 9379 (cudf_msu32) R 9378 9378 9023 34817 9081 4202496 301 0 0 0 0 0 0 0 25 0 1 0 892244402 1957888 193 1283457024 134512640 136125367 4292145072 18446744073709551615 135594526 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9379/statm: 478 193 141 394 0 82 0

[startup+0.145426 s]
/proc/loadavg: 1.01 0.91 0.53 4/39 9379
/proc/meminfo: memFree=62620/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=0
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892244402 2637824 279 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 279 238 194 0 30 0
[pid=9379] ppid=9378 vsize=8044 CPUtime=0.14
/proc/9379/stat : 9379 (cudf_msu32) R 9378 9378 9023 34817 9081 4202496 1820 0 0 0 14 0 0 0 25 0 1 0 892244402 8237056 1712 1283457024 134512640 136125367 4292145072 18446744073709551615 134719136 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9379/statm: 2011 1712 142 394 0 1615 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10620

[startup+0.205441 s]
/proc/loadavg: 1.01 0.91 0.53 4/39 9379
/proc/meminfo: memFree=62620/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=0
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892244402 2637824 279 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 279 238 194 0 30 0
[pid=9379] ppid=9378 vsize=10420 CPUtime=0.2
/proc/9379/stat : 9379 (cudf_msu32) R 9378 9378 9023 34817 9081 4202496 2406 0 0 0 20 0 0 0 25 0 1 0 892244402 10670080 2298 1283457024 134512640 136125367 4292145072 18446744073709551615 135301696 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9379/statm: 2605 2298 142 394 0 2209 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12996

[startup+0.305444 s]
/proc/loadavg: 1.01 0.91 0.53 4/39 9379
/proc/meminfo: memFree=62620/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=0
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892244402 2637824 279 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 279 238 194 0 30 0
[pid=9379] ppid=9378 vsize=13916 CPUtime=0.3
/proc/9379/stat : 9379 (cudf_msu32) R 9378 9378 9023 34817 9081 4202496 3288 0 0 0 30 0 0 0 25 0 1 0 892244402 14249984 3180 1283457024 134512640 136125367 4292145072 18446744073709551615 134717792 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9379/statm: 3479 3180 143 394 0 3083 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16492

[startup+0.705493 s]
/proc/loadavg: 1.01 0.91 0.53 4/39 9379
/proc/meminfo: memFree=62620/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=0
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892244402 2637824 279 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 279 238 194 0 30 0
[pid=9379] ppid=9378 vsize=26256 CPUtime=0.7
/proc/9379/stat : 9379 (cudf_msu32) R 9378 9378 9023 34817 9081 4202496 6364 0 0 0 70 0 0 0 25 0 1 0 892244402 26886144 6256 1283457024 134512640 136125367 4292145072 18446744073709551615 134717789 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9379/statm: 6564 6256 143 394 0 6168 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28832

[startup+1.50562 s]
/proc/loadavg: 1.01 0.91 0.53 2/40 9380
/proc/meminfo: memFree=27880/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=0
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892244402 2637824 279 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 279 238 194 0 30 0
[pid=9379] ppid=9378 vsize=52512 CPUtime=1.5
/proc/9379/stat : 9379 (cudf_msu32) R 9378 9378 9023 34817 9081 4202496 12999 0 0 0 147 3 0 0 25 0 1 0 892244402 53772288 12841 1283457024 134512640 136125367 4292145072 18446744073709551615 134610136 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9379/statm: 13128 12841 160 394 0 12732 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 55088

[startup+3.10751 s]
/proc/loadavg: 1.01 0.91 0.53 2/40 9380
/proc/meminfo: memFree=5256/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
Current children cumulated CPU time (s) 2.41
Current children cumulated vsize (KiB) 2576
heavy processes:

[startup+6.30723 s]
/proc/loadavg: 1.01 0.91 0.53 2/40 9381
/proc/meminfo: memFree=36652/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=37620 CPUtime=3.74
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 11175 0 0 0 262 112 0 0 25 0 1 0 892244644 38522880 8952 1283457024 134512640 135887319 4286726800 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 9405 8952 144 336 0 9067 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 40196

[startup+12.7088 s]
/proc/loadavg: 1.09 0.93 0.54 2/40 9381
/proc/meminfo: memFree=27352/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=37620 CPUtime=10.12
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 11175 0 0 0 839 173 0 0 25 0 1 0 892244644 38522880 8952 1283457024 134512640 135887319 4286726800 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 9405 8952 144 336 0 9067 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 40196

[startup+25.5113 s]
/proc/loadavg: 1.07 0.93 0.55 2/40 9381
/proc/meminfo: memFree=18920/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=46096 CPUtime=22.91
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 15105 0 0 0 2104 187 0 0 25 0 1 0 892244644 47202304 11080 1283457024 134512640 135887319 4286726800 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 11524 11080 144 336 0 11186 0
Current children cumulated CPU time (s) 25.32
Current children cumulated vsize (KiB) 48672

[startup+51.1067 s]
/proc/loadavg: 1.04 0.93 0.56 2/40 9381
/proc/meminfo: memFree=6644/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=58684 CPUtime=48.46
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 19887 0 0 0 4538 308 0 0 25 0 1 0 892244644 60092416 14251 1283457024 134512640 135887319 4286726800 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 14671 14251 144 336 0 14333 0
Current children cumulated CPU time (s) 50.87
Current children cumulated vsize (KiB) 61260

[startup+102.312 s]
/proc/loadavg: 1.02 0.94 0.58 2/40 9381
/proc/meminfo: memFree=5436/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=64032 CPUtime=99.64
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 21440 0 0 0 9624 340 0 0 25 0 1 0 892244644 65568768 15576 1283457024 134512640 135887319 4286726800 18446744073709551615 134603263 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 16008 15576 144 336 0 15670 0
Current children cumulated CPU time (s) 102.05
Current children cumulated vsize (KiB) 66608

[startup+162.305 s]
/proc/loadavg: 1.00 0.95 0.60 2/40 9381
/proc/meminfo: memFree=5484/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=66152 CPUtime=159.63
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 21972 0 0 0 15617 346 0 0 25 0 1 0 892244644 67739648 16102 1283457024 134512640 135887319 4286726800 18446744073709551615 134603601 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 16538 16102 144 336 0 16200 0
Current children cumulated CPU time (s) 162.04
Current children cumulated vsize (KiB) 68728

[startup+222.308 s]
/proc/loadavg: 1.00 0.95 0.62 2/40 9381
/proc/meminfo: memFree=5220/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=68792 CPUtime=219.55
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 22654 0 0 0 21604 351 0 0 25 0 1 0 892244644 70443008 16755 1283457024 134512640 135887319 4286726800 18446744073709551615 134603565 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 17198 16755 144 336 0 16860 0
Current children cumulated CPU time (s) 221.96
Current children cumulated vsize (KiB) 71368

[startup+282.311 s]
/proc/loadavg: 1.00 0.96 0.64 2/40 9381
/proc/meminfo: memFree=5144/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=71040 CPUtime=279.5
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 23237 0 0 0 27596 354 0 0 25 0 1 0 892244644 72744960 17317 1283457024 134512640 135887319 4286726800 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 17760 17317 144 336 0 17422 0
Current children cumulated CPU time (s) 281.91
Current children cumulated vsize (KiB) 73616



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.413 s]
/proc/loadavg: 1.00 0.96 0.65 2/40 9381
/proc/meminfo: memFree=6156/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2576 CPUtime=2.41
/proc/9378/stat : 9378 (cudf2pbo4trendy) S 9377 9378 9023 34817 9081 4202496 402 14911 0 0 0 0 200 41 20 0 1 0 892244402 2637824 282 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9378/statm: 644 282 241 194 0 30 0
[pid=9381] ppid=9378 vsize=71172 CPUtime=287.6
/proc/9381/stat : 9381 (bmo-pblex32) R 9378 9378 9023 34817 9081 4202496 23275 0 0 0 28406 354 0 0 25 0 1 0 892244644 72880128 17353 1283457024 134512640 135887319 4286726800 18446744073709551615 134603601 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9381/statm: 17793 17353 144 336 0 17455 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 73748

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.525 s]
/proc/loadavg: 1.00 0.96 0.65 2/40 9381
/proc/meminfo: memFree=6156/1048576 swapFree=2095372/2097144
[pid=9378] ppid=9377 vsize=2584 CPUtime=290.03
/proc/9378/stat : 9378 (cudf2pbo4trendy) R 9377 9378 9023 34817 9081 4202496 445 38568 0 0 0 0 28606 397 20 0 1 0 892244402 2646016 288 1283457024 134512640 135304128 4292843456 18446744073709551615 4294960130 0 65536 4 82434 0 0 0 17 0 0 0 0
/proc/9378/statm: 646 288 245 194 0 32 0
Current children cumulated CPU time (s) 290.03
Current children cumulated vsize (KiB) 2584

Child status: 0
Real time (s): 290.526
CPU time (s): 290.138
CPU user time (s): 286.146
CPU system time (s): 3.99225
CPU usage (%): 99.8666
Max. virtual memory (cumulated for all children) (KiB): 73748

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 286.146
system time used= 3.99225
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40811
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= 23
involuntary context switches= 9407

runsolver used 0 second user time and 0 second system time

The end