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/cudf2pbo4paranoid-1.0/randec88d5.cudf.impossible.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/impossible//randec88d5.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/randec88d5.cudf.impossible.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.00 1.00 0.92 4/35 13733
/proc/meminfo: memFree=54244/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=0
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894658020 2629632 278 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 278 238 194 0 28 0
[pid=13733] ppid=13732 vsize=2568 CPUtime=0
/proc/13733/stat : 13733 (cudf2pbo4parano) R 13732 13732 9023 34817 9081 4202560 4 0 0 0 0 0 0 0 25 0 1 0 894658020 2629632 42 1283457024 134512640 135304128 4287810368 18446744073709551615 4159293692 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/13733/statm: 642 42 2 194 0 28 0

[startup+0.118106 s]
/proc/loadavg: 1.00 1.00 0.92 4/35 13733
/proc/meminfo: memFree=54244/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=0
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894658020 2629632 278 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 278 238 194 0 28 0
[pid=13733] ppid=13732 vsize=5940 CPUtime=0.08
/proc/13733/stat : 13733 (cudf_msu32) R 13732 13732 9023 34817 9081 4202496 1280 0 0 0 8 0 0 0 25 0 1 0 894658020 6082560 1173 1283457024 134512640 136125367 4289295648 18446744073709551615 134738451 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13733/statm: 1485 1173 143 394 0 1089 0
Current children cumulated CPU time (s) 0.08
Current children cumulated vsize (KiB) 8508

[startup+0.206081 s]
/proc/loadavg: 1.00 1.00 0.92 4/35 13733
/proc/meminfo: memFree=54244/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=0
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894658020 2629632 278 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 278 238 194 0 28 0
[pid=13733] ppid=13732 vsize=8844 CPUtime=0.16
/proc/13733/stat : 13733 (cudf_msu32) R 13732 13732 9023 34817 9081 4202496 2016 0 0 0 16 0 0 0 25 0 1 0 894658020 9056256 1909 1283457024 134512640 136125367 4289295648 18446744073709551615 134718168 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13733/statm: 2211 1909 143 394 0 1815 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11412

[startup+0.306078 s]
/proc/loadavg: 1.00 1.00 0.92 4/35 13733
/proc/meminfo: memFree=54244/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=0
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894658020 2629632 278 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 278 238 194 0 28 0
[pid=13733] ppid=13732 vsize=11904 CPUtime=0.26
/proc/13733/stat : 13733 (cudf_msu32) R 13732 13732 9023 34817 9081 4202496 2791 0 0 0 25 1 0 0 25 0 1 0 894658020 12189696 2684 1283457024 134512640 136125367 4289295648 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13733/statm: 2976 2684 144 394 0 2580 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 14472

[startup+0.706094 s]
/proc/loadavg: 1.00 1.00 0.92 4/35 13733
/proc/meminfo: memFree=54244/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=0
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894658020 2629632 278 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 278 238 194 0 28 0
[pid=13733] ppid=13732 vsize=23188 CPUtime=0.61
/proc/13733/stat : 13733 (cudf_msu32) R 13732 13732 9023 34817 9081 4202496 5593 0 0 0 58 3 0 0 25 0 1 0 894658020 23744512 5486 1283457024 134512640 136125367 4289295648 18446744073709551615 135535003 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13733/statm: 5797 5486 144 394 0 5401 0
Current children cumulated CPU time (s) 0.61
Current children cumulated vsize (KiB) 25756

[startup+1.50617 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13734
/proc/meminfo: memFree=6296/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=0
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 894658020 2629632 278 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 278 238 194 0 28 0
[pid=13733] ppid=13732 vsize=41200 CPUtime=1.28
/proc/13733/stat : 13733 (cudf_msu32) R 13732 13732 9023 34817 9081 4202496 10160 0 0 0 122 6 0 0 25 0 1 0 894658020 42188800 10004 1283457024 134512640 136125367 4289295648 18446744073709551615 135533302 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13733/statm: 10300 10004 144 394 0 9904 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 43768

[startup+3.11393 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13734
/proc/meminfo: memFree=5356/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 2.37
Current children cumulated vsize (KiB) 2568
heavy processes:

[startup+6.30479 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=41744/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=24704 CPUtime=3.67
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 7329 0 0 0 289 78 0 0 25 0 1 0 894658282 25296896 5846 1283457024 134512640 135887319 4293036208 18446744073709551615 134624712 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 6176 5846 144 336 0 5838 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 27272

[startup+12.7068 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=37528/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=28772 CPUtime=10
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 8375 0 0 0 831 169 0 0 25 0 1 0 894658282 29462528 6873 1283457024 134512640 135887319 4293036208 18446744073709551615 134614989 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 7193 6873 144 336 0 6855 0
Current children cumulated CPU time (s) 12.37
Current children cumulated vsize (KiB) 31340

[startup+25.5107 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=34056/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=31868 CPUtime=22.79
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9205 0 0 0 2060 219 0 0 25 0 1 0 894658282 32632832 7638 1283457024 134512640 135887319 4293036208 18446744073709551615 134527030 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 7967 7638 144 336 0 7629 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 34436

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

[startup+25.6107 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=34056/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=31868 CPUtime=22.9
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9207 0 0 0 2070 220 0 0 25 0 1 0 894658282 32632832 7640 1283457024 134512640 135887319 4293036208 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 7967 7640 144 336 0 7629 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 34436

[startup+28.8116 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=33560/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=32460 CPUtime=26.09
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9369 0 0 0 2386 223 0 0 25 0 1 0 894658282 33239040 7777 1283457024 134512640 135887319 4293036208 18446744073709551615 134615460 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 8115 7777 144 336 0 7777 0
Current children cumulated CPU time (s) 28.46
Current children cumulated vsize (KiB) 35028

[startup+32.0125 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=33188/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=32724 CPUtime=29.3
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9466 0 0 0 2704 226 0 0 25 0 1 0 894658282 33509376 7865 1283457024 134512640 135887319 4293036208 18446744073709551615 134617672 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 8181 7865 144 336 0 7843 0
Current children cumulated CPU time (s) 31.67
Current children cumulated vsize (KiB) 35292

[startup+33.613 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=33064/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=32856 CPUtime=30.9
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9502 0 0 0 2863 227 0 0 25 0 1 0 894658282 33644544 7901 1283457024 134512640 135887319 4293036208 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 8214 7901 144 336 0 7876 0
Current children cumulated CPU time (s) 33.27
Current children cumulated vsize (KiB) 35424

[startup+34.0131 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=33064/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=32856 CPUtime=31.3
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9512 0 0 0 2903 227 0 0 25 0 1 0 894658282 33644544 7911 1283457024 134512640 135887319 4293036208 18446744073709551615 134525478 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 8214 7911 144 336 0 7876 0
Current children cumulated CPU time (s) 33.67
Current children cumulated vsize (KiB) 35424

[startup+34.2132 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13735
/proc/meminfo: memFree=32940/1048576 swapFree=2095372/2097144
[pid=13732] ppid=13731 vsize=2568 CPUtime=2.37
/proc/13732/stat : 13732 (cudf2pbo4parano) S 13731 13732 9023 34817 9081 4202496 401 14833 0 0 0 0 204 33 20 0 1 0 894658020 2629632 281 1283457024 134512640 135304128 4287810368 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13732/statm: 642 281 241 194 0 28 0
[pid=13735] ppid=13732 vsize=32988 CPUtime=31.5
/proc/13735/stat : 13735 (bmo-pblex32) R 13732 13732 9023 34817 9081 4202496 9517 0 0 0 2923 227 0 0 25 0 1 0 894658282 33779712 7916 1283457024 134512640 135887319 4293036208 18446744073709551615 134526509 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13735/statm: 8247 7916 144 336 0 7909 0
Current children cumulated CPU time (s) 33.87
Current children cumulated vsize (KiB) 35556

Child status: 0
Real time (s): 34.2974
CPU time (s): 33.9661
CPU user time (s): 31.354
CPU system time (s): 2.61216
CPU usage (%): 99.0341
Max. virtual memory (cumulated for all children) (KiB): 62308

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

runsolver used 0 second user time and 0 second system time

The end