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/rand550.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand550.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand550.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 4/39 11417
/proc/meminfo: memFree=87832/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=0
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893541049 2637824 279 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 279 238 194 0 30 0
[pid=11417] ppid=11416 vsize=1916 CPUtime=0.01
/proc/11417/stat : 11417 (cudf_msu32) R 11416 11416 9023 34817 9081 4202496 304 0 0 0 1 0 0 0 25 0 1 0 893541050 1961984 196 1283457024 134512640 136125367 4287488832 18446744073709551615 134717968 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11417/statm: 479 196 141 394 0 83 0

[startup+0.205386 s]
/proc/loadavg: 0.87 0.94 0.90 4/39 11417
/proc/meminfo: memFree=87832/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=0
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893541049 2637824 279 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 279 238 194 0 30 0
[pid=11417] ppid=11416 vsize=10384 CPUtime=0.21
/proc/11417/stat : 11417 (cudf_msu32) R 11416 11416 9023 34817 9081 4202496 2390 0 0 0 21 0 0 0 25 0 1 0 893541050 10633216 2282 1283457024 134512640 136125367 4287488832 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11417/statm: 2596 2282 142 394 0 2200 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12960

[startup+0.305402 s]
/proc/loadavg: 0.87 0.94 0.90 4/39 11417
/proc/meminfo: memFree=87832/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=0
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893541049 2637824 279 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 279 238 194 0 30 0
[pid=11417] ppid=11416 vsize=13880 CPUtime=0.3
/proc/11417/stat : 11417 (cudf_msu32) R 11416 11416 9023 34817 9081 4202496 3270 0 0 0 28 2 0 0 25 0 1 0 893541050 14213120 3162 1283457024 134512640 136125367 4287488832 18446744073709551615 135548981 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11417/statm: 3470 3162 143 394 0 3074 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16456

[startup+0.405426 s]
/proc/loadavg: 0.87 0.94 0.90 4/39 11417
/proc/meminfo: memFree=87832/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=0
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893541049 2637824 279 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 279 238 194 0 30 0
[pid=11417] ppid=11416 vsize=17180 CPUtime=0.4
/proc/11417/stat : 11417 (cudf_msu32) R 11416 11416 9023 34817 9081 4202496 4093 0 0 0 36 4 0 0 25 0 1 0 893541050 17592320 3985 1283457024 134512640 136125367 4287488832 18446744073709551615 134717648 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11417/statm: 4295 3985 143 394 0 3899 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 19756

[startup+0.705493 s]
/proc/loadavg: 0.87 0.94 0.90 4/39 11417
/proc/meminfo: memFree=87832/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=0
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893541049 2637824 279 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 279 238 194 0 30 0
[pid=11417] ppid=11416 vsize=26088 CPUtime=0.7
/proc/11417/stat : 11417 (cudf_msu32) R 11416 11416 9023 34817 9081 4202496 6335 0 0 0 65 5 0 0 25 0 1 0 893541050 26714112 6227 1283457024 134512640 136125367 4287488832 18446744073709551615 134717251 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11417/statm: 6522 6227 143 394 0 6126 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28664

[startup+1.50572 s]
/proc/loadavg: 0.87 0.94 0.90 2/40 11418
/proc/meminfo: memFree=52100/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=0
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 893541049 2637824 279 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 279 238 194 0 30 0
[pid=11417] ppid=11416 vsize=52512 CPUtime=1.5
/proc/11417/stat : 11417 (cudf_msu32) R 11416 11416 9023 34817 9081 4202496 13291 0 0 0 137 13 0 0 25 0 1 0 893541050 53772288 12842 1283457024 134512640 136125367 4287488832 18446744073709551615 134643482 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11417/statm: 13128 12842 161 394 0 12732 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 55088

[startup+3.10848 s]
/proc/loadavg: 0.87 0.94 0.90 3/40 11419
/proc/meminfo: memFree=81604/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=26608 CPUtime=0.8
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 7061 0 0 0 64 16 0 0 25 0 1 0 893541280 27246592 6206 1283457024 134512640 135887319 4287697792 18446744073709551615 134614989 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 6652 6206 138 336 0 6314 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 29184

[startup+6.30752 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 11419
/proc/meminfo: memFree=51852/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=35524 CPUtime=3.99
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 10649 0 0 0 288 111 0 0 25 0 1 0 893541280 36376576 8431 1283457024 134512640 135887319 4287697792 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 8881 8431 144 336 0 8543 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 38100

[startup+12.7093 s]
/proc/loadavg: 0.89 0.94 0.90 2/40 11419
/proc/meminfo: memFree=35856/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=49440 CPUtime=10.39
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 17105 0 0 0 853 186 0 0 25 0 1 0 893541280 50626560 11955 1283457024 134512640 135887319 4287697792 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 12360 11955 144 336 0 12022 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 52016

[startup+25.5036 s]
/proc/loadavg: 0.91 0.94 0.90 2/40 11419
/proc/meminfo: memFree=26804/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=58952 CPUtime=23.14
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 19506 0 0 0 2001 313 0 0 25 0 1 0 893541280 60366848 14338 1283457024 134512640 135887319 4287697792 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 14738 14338 144 336 0 14400 0
Current children cumulated CPU time (s) 25.43
Current children cumulated vsize (KiB) 61528

[startup+51.1085 s]
/proc/loadavg: 0.94 0.95 0.90 2/40 11419
/proc/meminfo: memFree=26060/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=59744 CPUtime=48.75
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 19702 0 0 0 4562 313 0 0 25 0 1 0 893541280 61177856 14525 1283457024 134512640 135887319 4287697792 18446744073709551615 134603601 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 14936 14525 144 336 0 14598 0
Current children cumulated CPU time (s) 51.04
Current children cumulated vsize (KiB) 62320

[startup+102.31 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 11419
/proc/meminfo: memFree=24696/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=60932 CPUtime=99.91
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 20008 0 0 0 9677 314 0 0 25 0 1 0 893541280 62394368 14829 1283457024 134512640 135887319 4287697792 18446744073709551615 134603601 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 15233 14829 144 336 0 14895 0
Current children cumulated CPU time (s) 102.2
Current children cumulated vsize (KiB) 63508

[startup+162.305 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 11419
/proc/meminfo: memFree=23704/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=61856 CPUtime=159.84
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 20232 0 0 0 15669 315 0 0 25 0 1 0 893541280 63340544 15049 1283457024 134512640 135887319 4287697792 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 15464 15049 144 336 0 15126 0
Current children cumulated CPU time (s) 162.13
Current children cumulated vsize (KiB) 64432

[startup+222.308 s]
/proc/loadavg: 0.99 0.96 0.91 2/37 11420
/proc/meminfo: memFree=26000/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=62648 CPUtime=219.8
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 20425 0 0 0 21663 317 0 0 25 0 1 0 893541280 64151552 15236 1283457024 134512640 135887319 4287697792 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 15662 15236 144 336 0 15324 0
Current children cumulated CPU time (s) 222.09
Current children cumulated vsize (KiB) 65224

[startup+282.31 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11420
/proc/meminfo: memFree=24396/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=64128 CPUtime=279.78
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 20819 0 0 0 27660 318 0 0 25 0 1 0 893541280 65667072 15625 1283457024 134512640 135887319 4287697792 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 16032 15625 144 336 0 15694 0
Current children cumulated CPU time (s) 282.07
Current children cumulated vsize (KiB) 66704



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.312 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11420
/proc/meminfo: memFree=24272/1048576 swapFree=2095372/2097144
[pid=11416] ppid=11415 vsize=2576 CPUtime=2.29
/proc/11416/stat : 11416 (cudf2pbo4trendy) S 11415 11416 9023 34817 9081 4202496 402 14283 0 0 0 0 181 48 20 0 1 0 893541049 2637824 282 1283457024 134512640 135304128 4292237120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11416/statm: 644 282 241 194 0 30 0
[pid=11419] ppid=11416 vsize=64260 CPUtime=287.78
/proc/11419/stat : 11419 (bmo-pblex32) R 11416 11416 9023 34817 9081 4202496 20840 0 0 0 28460 318 0 0 25 0 1 0 893541280 65802240 15646 1283457024 134512640 135887319 4287697792 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11419/statm: 16065 15646 144 336 0 15727 0
Current children cumulated CPU time (s) 290.07
Current children cumulated vsize (KiB) 66836

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.417
CPU time (s): 290.182
CPU user time (s): 286.502
CPU system time (s): 3.68023
CPU usage (%): 99.919
Max. virtual memory (cumulated for all children) (KiB): 66836

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 286.502
system time used= 3.68023
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 37706
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= 19
involuntary context switches= 9219

runsolver used 0 second user time and 0 second system time

The end