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.cudf.sarge-etch.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand753.sarge-etch.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand753.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.94 0.90 5/35 11927
/proc/meminfo: memFree=45920/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0
/proc/11926/stat : 11926 (cudf2pbo4trendy) R 11925 11926 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 893817827 2633728 278 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/11926/statm: 643 278 238 194 0 29 0
[pid=11927] ppid=11926 vsize=2572 CPUtime=0
/proc/11927/stat : 11927 (cudf2pbo4trendy) R 11926 11926 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 893817827 2633728 40 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/11927/statm: 643 40 0 194 0 29 0

[startup+0.155543 s]
/proc/loadavg: 0.84 0.94 0.90 5/35 11927
/proc/meminfo: memFree=45920/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893817827 2633728 278 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 278 238 194 0 29 0
[pid=11927] ppid=11926 vsize=8004 CPUtime=0.16
/proc/11927/stat : 11927 (cudf_msu32) R 11926 11926 9023 34817 9081 4202496 1823 0 0 0 14 2 0 0 25 0 1 0 893817827 8196096 1716 1283457024 134512640 136125367 4290115040 18446744073709551615 134718128 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11927/statm: 2001 1716 142 394 0 1605 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 10576

[startup+0.20556 s]
/proc/loadavg: 0.84 0.94 0.90 5/35 11927
/proc/meminfo: memFree=45920/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893817827 2633728 278 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 278 238 194 0 29 0
[pid=11927] ppid=11926 vsize=9872 CPUtime=0.2
/proc/11927/stat : 11927 (cudf_msu32) R 11926 11926 9023 34817 9081 4202496 2260 0 0 0 18 2 0 0 25 0 1 0 893817827 10108928 2153 1283457024 134512640 136125367 4290115040 18446744073709551615 134712010 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11927/statm: 2468 2153 142 394 0 2072 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12444

[startup+0.305569 s]
/proc/loadavg: 0.84 0.94 0.90 5/35 11927
/proc/meminfo: memFree=45920/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893817827 2633728 278 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 278 238 194 0 29 0
[pid=11927] ppid=11926 vsize=13236 CPUtime=0.3
/proc/11927/stat : 11927 (cudf_msu32) R 11926 11926 9023 34817 9081 4202496 3120 0 0 0 28 2 0 0 25 0 1 0 893817827 13553664 3013 1283457024 134512640 136125367 4290115040 18446744073709551615 134728315 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11927/statm: 3309 3013 143 394 0 2913 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15808

[startup+0.705617 s]
/proc/loadavg: 0.84 0.94 0.90 5/35 11927
/proc/meminfo: memFree=45920/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893817827 2633728 278 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 278 238 194 0 29 0
[pid=11927] ppid=11926 vsize=23484 CPUtime=0.7
/proc/11927/stat : 11927 (cudf_msu32) R 11926 11926 9023 34817 9081 4202496 5718 0 0 0 60 10 0 0 25 0 1 0 893817827 24047616 5611 1283457024 134512640 136125367 4290115040 18446744073709551615 134937274 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11927/statm: 5871 5611 165 394 0 5475 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26056

[startup+1.50577 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 11929
/proc/meminfo: memFree=35608/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=14820 CPUtime=0.67
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 4523 0 0 0 41 26 0 0 24 0 1 0 893817910 15175680 3332 1283457024 134512640 135887319 4286917344 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 3705 3332 143 336 0 3367 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 17392

[startup+3.10621 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 11929
/proc/meminfo: memFree=29036/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21172 CPUtime=2.27
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7254 0 0 0 174 53 0 0 25 0 1 0 893817910 21680128 5001 1283457024 134512640 135887319 4286917344 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5293 5001 143 336 0 4955 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 23744

[startup+6.31044 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 11929
/proc/meminfo: memFree=25696/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21172 CPUtime=5.45
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7255 0 0 0 492 53 0 0 25 0 1 0 893817910 21680128 5002 1283457024 134512640 135887319 4286917344 18446744073709551615 134603354 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5293 5002 144 336 0 4955 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 23744

[startup+12.7119 s]
/proc/loadavg: 0.88 0.94 0.90 2/36 11929
/proc/meminfo: memFree=25572/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21172 CPUtime=11.86
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7255 0 0 0 1133 53 0 0 25 0 1 0 893817910 21680128 5002 1283457024 134512640 135887319 4286917344 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5293 5002 144 336 0 4955 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 23744

[startup+25.5044 s]
/proc/loadavg: 0.89 0.94 0.90 2/36 11929
/proc/meminfo: memFree=25572/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21172 CPUtime=24.65
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7255 0 0 0 2411 54 0 0 25 0 1 0 893817910 21680128 5002 1283457024 134512640 135887319 4286917344 18446744073709551615 134615042 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5293 5002 144 336 0 4955 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 23744

[startup+51.1094 s]
/proc/loadavg: 0.93 0.94 0.90 2/36 11929
/proc/meminfo: memFree=25572/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21304 CPUtime=50.22
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7289 0 0 0 4965 57 0 0 25 0 1 0 893817910 21815296 5028 1283457024 134512640 135887319 4286917344 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5326 5028 144 336 0 4988 0
Current children cumulated CPU time (s) 51.04
Current children cumulated vsize (KiB) 23876

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

[startup+51.2094 s]
/proc/loadavg: 0.93 0.94 0.90 2/36 11929
/proc/meminfo: memFree=25572/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21304 CPUtime=50.32
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7289 0 0 0 4975 57 0 0 25 0 1 0 893817910 21815296 5028 1283457024 134512640 135887319 4286917344 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5326 5028 144 336 0 4988 0
Current children cumulated CPU time (s) 51.14
Current children cumulated vsize (KiB) 23876

[startup+57.6109 s]
/proc/loadavg: 0.94 0.94 0.90 2/36 11929
/proc/meminfo: memFree=25448/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21436 CPUtime=56.69
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7327 0 0 0 5611 58 0 0 25 0 1 0 893817910 21950464 5066 1283457024 134512640 135887319 4286917344 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5359 5066 144 336 0 5021 0
Current children cumulated CPU time (s) 57.51
Current children cumulated vsize (KiB) 24008

[startup+60.8115 s]
/proc/loadavg: 0.94 0.95 0.91 2/36 11929
/proc/meminfo: memFree=25324/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21612 CPUtime=59.89
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7363 0 0 0 5931 58 0 0 25 0 1 0 893817910 22130688 5091 1283457024 134512640 135887319 4286917344 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5403 5091 144 336 0 5065 0
Current children cumulated CPU time (s) 60.71
Current children cumulated vsize (KiB) 24184

[startup+62.4117 s]
/proc/loadavg: 0.94 0.95 0.91 2/36 11929
/proc/meminfo: memFree=25324/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21612 CPUtime=61.49
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7374 0 0 0 6091 58 0 0 25 0 1 0 893817910 22130688 5102 1283457024 134512640 135887319 4286917344 18446744073709551615 134525040 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5403 5102 144 336 0 5065 0
Current children cumulated CPU time (s) 62.31
Current children cumulated vsize (KiB) 24184

[startup+63.2118 s]
/proc/loadavg: 0.94 0.95 0.91 2/36 11929
/proc/meminfo: memFree=25324/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21612 CPUtime=62.29
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7380 0 0 0 6171 58 0 0 25 0 1 0 893817910 22130688 5108 1283457024 134512640 135887319 4286917344 18446744073709551615 134614999 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5403 5108 144 336 0 5065 0
Current children cumulated CPU time (s) 63.11
Current children cumulated vsize (KiB) 24184

[startup+63.6118 s]
/proc/loadavg: 0.94 0.95 0.91 2/36 11929
/proc/meminfo: memFree=25324/1048576 swapFree=2095372/2097144
[pid=11926] ppid=11925 vsize=2572 CPUtime=0.82
/proc/11926/stat : 11926 (cudf2pbo4trendy) S 11925 11926 9023 34817 9081 4202496 401 5720 0 0 0 0 66 16 18 0 1 0 893817827 2633728 281 1283457024 134512640 135304128 4291850000 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11926/statm: 643 281 241 194 0 29 0
[pid=11929] ppid=11926 vsize=21612 CPUtime=62.69
/proc/11929/stat : 11929 (bmo-pblex32) R 11926 11926 9023 34817 9081 4202496 7382 0 0 0 6211 58 0 0 25 0 1 0 893817910 22130688 5110 1283457024 134512640 135887319 4286917344 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11929/statm: 5403 5110 144 336 0 5065 0
Current children cumulated CPU time (s) 63.51
Current children cumulated vsize (KiB) 24184

Child status: 0
Real time (s): 63.6759
CPU time (s): 63.592
CPU user time (s): 62.8319
CPU system time (s): 0.760047
CPU usage (%): 99.8682
Max. virtual memory (cumulated for all children) (KiB): 26056

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

runsolver used 0 second user time and 0 second system time

The end