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/rand915.sarge-etch.cudf.sarge-etch.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand915.sarge-etch.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand915.sarge-etch.cudf.sarge-etch.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.84 0.93 0.90 5/35 12723
/proc/meminfo: memFree=51276/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894217154 2629632 278 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 278 238 194 0 28 0
[pid=12723] ppid=12722 vsize=2576 CPUtime=0.02
/proc/12723/stat : 12723 (cudf_msu32) R 12722 12722 9023 34817 9081 4202496 443 0 0 0 2 0 0 0 25 0 1 0 894217155 2637824 336 1283457024 134512640 136125367 4287822768 18446744073709551615 134717668 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12723/statm: 644 336 141 394 0 248 0

[startup+0.225634 s]
/proc/loadavg: 0.84 0.93 0.90 5/35 12723
/proc/meminfo: memFree=51276/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894217154 2629632 278 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 278 238 194 0 28 0
[pid=12723] ppid=12722 vsize=10528 CPUtime=0.23
/proc/12723/stat : 12723 (cudf_msu32) R 12722 12722 9023 34817 9081 4202496 2432 0 0 0 23 0 0 0 25 0 1 0 894217155 10780672 2325 1283457024 134512640 136125367 4287822768 18446744073709551615 135549868 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12723/statm: 2632 2325 142 394 0 2236 0
Current children cumulated CPU time (s) 0.23
Current children cumulated vsize (KiB) 13096

[startup+0.305679 s]
/proc/loadavg: 0.84 0.93 0.90 5/35 12723
/proc/meminfo: memFree=51276/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894217154 2629632 278 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 278 238 194 0 28 0
[pid=12723] ppid=12722 vsize=13232 CPUtime=0.3
/proc/12723/stat : 12723 (cudf_msu32) R 12722 12722 9023 34817 9081 4202496 3120 0 0 0 30 0 0 0 25 0 1 0 894217155 13549568 3013 1283457024 134512640 136125367 4287822768 18446744073709551615 134728315 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12723/statm: 3308 3013 143 394 0 2912 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15800

[startup+0.405697 s]
/proc/loadavg: 0.84 0.93 0.90 5/35 12723
/proc/meminfo: memFree=51276/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894217154 2629632 278 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 278 238 194 0 28 0
[pid=12723] ppid=12722 vsize=16136 CPUtime=0.4
/proc/12723/stat : 12723 (cudf_msu32) R 12722 12722 9023 34817 9081 4202496 3839 0 0 0 39 1 0 0 25 0 1 0 894217155 16523264 3732 1283457024 134512640 136125367 4287822768 18446744073709551615 134719238 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12723/statm: 4034 3732 143 394 0 3638 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 18704

[startup+0.705799 s]
/proc/loadavg: 0.84 0.93 0.90 5/35 12723
/proc/meminfo: memFree=51276/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894217154 2629632 278 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 278 238 194 0 28 0
[pid=12723] ppid=12722 vsize=23496 CPUtime=0.7
/proc/12723/stat : 12723 (cudf_msu32) R 12722 12722 9023 34817 9081 4202496 5722 0 0 0 58 12 0 0 25 0 1 0 894217155 24059904 5615 1283457024 134512640 136125367 4287822768 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12723/statm: 5874 5615 165 394 0 5478 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26064

[startup+1.50603 s]
/proc/loadavg: 0.84 0.93 0.90 2/36 12725
/proc/meminfo: memFree=40644/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=11828 CPUtime=0.67
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 3220 0 0 0 42 25 0 0 24 0 1 0 894217238 12111872 2602 1283457024 134512640 135887319 4287046400 18446744073709551615 134600321 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 2957 2602 138 336 0 2619 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 14396

[startup+3.10635 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 12725
/proc/meminfo: memFree=34196/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21316 CPUtime=2.26
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7356 0 0 0 166 60 0 0 25 0 1 0 894217238 21827584 5001 1283457024 134512640 135887319 4287046400 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5329 5001 144 336 0 4991 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 23884

[startup+6.30709 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 12725
/proc/meminfo: memFree=30732/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21316 CPUtime=5.46
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7361 0 0 0 485 61 0 0 25 0 1 0 894217238 21827584 5005 1283457024 134512640 135887319 4287046400 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5329 5005 144 336 0 4991 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 23884

[startup+12.7111 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 12725
/proc/meminfo: memFree=30732/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21316 CPUtime=11.86
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7361 0 0 0 1124 62 0 0 25 0 1 0 894217238 21827584 5005 1283457024 134512640 135887319 4287046400 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5329 5005 144 336 0 4991 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 23884

[startup+25.5035 s]
/proc/loadavg: 0.89 0.94 0.90 2/36 12725
/proc/meminfo: memFree=30732/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21316 CPUtime=24.65
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7361 0 0 0 2403 62 0 0 25 0 1 0 894217238 21827584 5005 1283457024 134512640 135887319 4287046400 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5329 5005 144 336 0 4991 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 23884

[startup+51.1074 s]
/proc/loadavg: 0.93 0.94 0.90 2/36 12725
/proc/meminfo: memFree=30732/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21316 CPUtime=50.25
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7361 0 0 0 4963 62 0 0 25 0 1 0 894217238 21827584 5005 1283457024 134512640 135887319 4287046400 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5329 5005 144 336 0 4991 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 23884

[startup+102.312 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 12725
/proc/meminfo: memFree=30732/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21316 CPUtime=101.02
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7361 0 0 0 10040 62 0 0 25 0 1 0 894217238 21827584 5005 1283457024 134512640 135887319 4287046400 18446744073709551615 134526509 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5329 5005 144 336 0 4991 0
Current children cumulated CPU time (s) 101.84
Current children cumulated vsize (KiB) 23884

[startup+162.304 s]
/proc/loadavg: 0.99 0.95 0.91 2/36 12725
/proc/meminfo: memFree=29988/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=21976 CPUtime=161
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7540 0 0 0 16037 63 0 0 25 0 1 0 894217238 22503424 5175 1283457024 134512640 135887319 4287046400 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5494 5175 144 336 0 5156 0
Current children cumulated CPU time (s) 161.82
Current children cumulated vsize (KiB) 24544

[startup+222.31 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 12725
/proc/meminfo: memFree=29244/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=22772 CPUtime=220.97
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7740 0 0 0 22032 65 0 0 25 0 1 0 894217238 23318528 5357 1283457024 134512640 135887319 4287046400 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5693 5357 144 336 0 5355 0
Current children cumulated CPU time (s) 221.79
Current children cumulated vsize (KiB) 25340

[startup+282.305 s]
/proc/loadavg: 1.03 0.98 0.91 2/36 12725
/proc/meminfo: memFree=28748/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=23432 CPUtime=280.92
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7907 0 0 0 28026 66 0 0 25 0 1 0 894217238 23994368 5515 1283457024 134512640 135887319 4287046400 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5858 5515 144 336 0 5520 0
Current children cumulated CPU time (s) 281.74
Current children cumulated vsize (KiB) 26000



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.607 s]
/proc/loadavg: 1.03 0.98 0.91 2/36 12725
/proc/meminfo: memFree=28624/1048576 swapFree=2095372/2097144
[pid=12722] ppid=12721 vsize=2568 CPUtime=0.82
/proc/12722/stat : 12722 (cudf2pbo4trendy) S 12721 12722 9023 34817 9081 4202496 401 5724 0 0 0 0 64 18 20 0 1 0 894217154 2629632 281 1283457024 134512640 135304128 4294875648 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12722/statm: 642 281 241 194 0 28 0
[pid=12725] ppid=12722 vsize=23432 CPUtime=289.2
/proc/12725/stat : 12725 (bmo-pblex32) R 12722 12722 9023 34817 9081 4202496 7928 0 0 0 28853 67 0 0 25 0 1 0 894217238 23994368 5535 1283457024 134512640 135887319 4287046400 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12725/statm: 5858 5535 144 336 0 5520 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 26000

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.658
CPU time (s): 290.082
CPU user time (s): 289.214
CPU system time (s): 0.868054
CPU usage (%): 99.8018
Max. virtual memory (cumulated for all children) (KiB): 26064

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

runsolver used 0 second user time and 0 second system time

The end