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/rand180.sarge-etch.cudf.sarge-etch.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand180.sarge-etch.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand180.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.96 0.95 0.91 5/39 10303
/proc/meminfo: memFree=50640/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0
/proc/10302/stat : 10302 (cudf2pbo4trendy) R 10301 10302 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 892885656 2633728 279 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/10302/statm: 643 279 238 194 0 29 0
[pid=10303] ppid=10302 vsize=2572 CPUtime=0
/proc/10303/stat : 10303 (cudf2pbo4trendy) R 10302 10302 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 892885656 2633728 41 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/10303/statm: 643 41 0 194 0 29 0

[startup+0.115573 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10303
/proc/meminfo: memFree=50640/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892885656 2633728 279 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 279 238 194 0 29 0
[pid=10303] ppid=10302 vsize=6552 CPUtime=0.12
/proc/10303/stat : 10303 (cudf_msu32) R 10302 10302 9023 34817 9081 4202496 1462 0 0 0 12 0 0 0 25 0 1 0 892885656 6709248 1354 1283457024 134512640 136125367 4292392976 18446744073709551615 134719796 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10303/statm: 1638 1354 142 394 0 1242 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 9124

[startup+0.205596 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10303
/proc/meminfo: memFree=50640/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892885656 2633728 279 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 279 238 194 0 29 0
[pid=10303] ppid=10302 vsize=9872 CPUtime=0.21
/proc/10303/stat : 10303 (cudf_msu32) R 10302 10302 9023 34817 9081 4202496 2261 0 0 0 21 0 0 0 25 0 1 0 892885656 10108928 2153 1283457024 134512640 136125367 4292392976 18446744073709551615 135304928 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10303/statm: 2468 2153 142 394 0 2072 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12444

[startup+0.305622 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10303
/proc/meminfo: memFree=50640/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892885656 2633728 279 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 279 238 194 0 29 0
[pid=10303] ppid=10302 vsize=13236 CPUtime=0.31
/proc/10303/stat : 10303 (cudf_msu32) R 10302 10302 9023 34817 9081 4202496 3121 0 0 0 31 0 0 0 25 0 1 0 892885656 13553664 3013 1283457024 134512640 136125367 4292392976 18446744073709551615 134728315 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10303/statm: 3309 3013 143 394 0 2913 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15808

[startup+0.705684 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10303
/proc/meminfo: memFree=50640/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892885656 2633728 279 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 279 238 194 0 29 0
[pid=10303] ppid=10302 vsize=23488 CPUtime=0.7
/proc/10303/stat : 10303 (cudf_msu32) R 10302 10302 9023 34817 9081 4202496 5720 0 0 0 66 4 0 0 25 0 1 0 892885656 24051712 5612 1283457024 134512640 136125367 4292392976 18446744073709551615 134619646 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10303/statm: 5872 5612 165 394 0 5476 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26060

[startup+1.50587 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10305
/proc/meminfo: memFree=40452/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=11736 CPUtime=0.67
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 3160 0 0 0 48 19 0 0 25 0 1 0 892885739 12017664 2550 1283457024 134512640 135887319 4291757952 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 2934 2550 137 336 0 2596 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 14308

[startup+3.10622 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10305
/proc/meminfo: memFree=33756/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=21628 CPUtime=2.27
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 7603 0 0 0 170 57 0 0 25 0 1 0 892885739 22147072 5098 1283457024 134512640 135887319 4291757952 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 5407 5098 143 336 0 5069 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 24200

[startup+6.30693 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10305
/proc/meminfo: memFree=29788/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=22024 CPUtime=5.45
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 7706 0 0 0 475 70 0 0 25 0 1 0 892885739 22552576 5200 1283457024 134512640 135887319 4291757952 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 5506 5200 144 336 0 5168 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 24596

[startup+12.7083 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10305
/proc/meminfo: memFree=28300/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=23608 CPUtime=11.85
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 8082 0 0 0 1115 70 0 0 25 0 1 0 892885739 24174592 5569 1283457024 134512640 135887319 4291757952 18446744073709551615 134603443 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 5902 5569 144 336 0 5564 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 26180

[startup+25.5111 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10305
/proc/meminfo: memFree=25572/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=26252 CPUtime=24.65
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 8749 0 0 0 2391 74 0 0 25 0 1 0 892885739 26882048 6222 1283457024 134512640 135887319 4291757952 18446744073709551615 134525040 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 6563 6222 144 336 0 6225 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 28824

[startup+51.1069 s]
/proc/loadavg: 0.98 0.95 0.91 2/40 10305
/proc/meminfo: memFree=20984/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=30792 CPUtime=50.24
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 9918 0 0 0 4947 77 0 0 25 0 1 0 892885739 31531008 7369 1283457024 134512640 135887319 4291757952 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 7698 7369 144 336 0 7360 0
Current children cumulated CPU time (s) 51.06
Current children cumulated vsize (KiB) 33364

[startup+102.311 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 10305
/proc/meminfo: memFree=11684/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=39908 CPUtime=101.36
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 12270 0 0 0 10053 83 0 0 25 0 1 0 892885739 40865792 9651 1283457024 134512640 135887319 4291757952 18446744073709551615 134603581 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 9977 9651 144 336 0 9639 0
Current children cumulated CPU time (s) 102.18
Current children cumulated vsize (KiB) 42480

[startup+162.304 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 10305
/proc/meminfo: memFree=5200/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=51224 CPUtime=161.33
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 15218 0 0 0 16048 85 0 0 25 0 1 0 892885739 52453376 12467 1283457024 134512640 135887319 4291757952 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 12806 12467 144 336 0 12468 0
Current children cumulated CPU time (s) 162.15
Current children cumulated vsize (KiB) 53796

[startup+222.307 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10305
/proc/meminfo: memFree=5240/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=59228 CPUtime=221.28
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 17272 0 0 0 22033 95 0 0 25 0 1 0 892885739 60649472 14456 1283457024 134512640 135887319 4291757952 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 14807 14456 144 336 0 14469 0
Current children cumulated CPU time (s) 222.1
Current children cumulated vsize (KiB) 61800

[startup+282.311 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10305
/proc/meminfo: memFree=5240/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=59228 CPUtime=281.26
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 17272 0 0 0 28024 102 0 0 25 0 1 0 892885739 60649472 14456 1283457024 134512640 135887319 4291757952 18446744073709551615 134603670 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 14807 14456 144 336 0 14469 0
Current children cumulated CPU time (s) 282.08
Current children cumulated vsize (KiB) 61800



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.313 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10305
/proc/meminfo: memFree=5240/1048576 swapFree=2095372/2097144
[pid=10302] ppid=10301 vsize=2572 CPUtime=0.82
/proc/10302/stat : 10302 (cudf2pbo4trendy) S 10301 10302 9023 34817 9081 4202496 402 5722 0 0 0 0 72 10 18 0 1 0 892885656 2633728 282 1283457024 134512640 135304128 4292319120 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10302/statm: 643 282 241 194 0 29 0
[pid=10305] ppid=10302 vsize=59228 CPUtime=289.27
/proc/10305/stat : 10305 (bmo-pblex32) R 10302 10302 9023 34817 9081 4202496 17272 0 0 0 28824 103 0 0 25 0 1 0 892885739 60649472 14456 1283457024 134512640 135887319 4291757952 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10305/statm: 14807 14456 144 336 0 14469 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 61800

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.367
CPU time (s): 290.154
CPU user time (s): 289.01
CPU system time (s): 1.14407
CPU usage (%): 99.9266
Max. virtual memory (cumulated for all children) (KiB): 61800

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

runsolver used 0 second user time and 0 second system time

The end