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/rand835640.cudf.impossible.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/impossible//rand835640.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand835640.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: 0.85 0.94 0.90 3/35 12544
/proc/meminfo: memFree=51964/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=0
/proc/12543/stat : 12543 (cudf2pbo4parano) R 12542 12543 9023 34817 9081 4202496 366 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 279 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/12543/statm: 643 279 238 194 0 29 0
[pid=12544] ppid=12543 vsize=2572 CPUtime=0
/proc/12544/stat : 12544 (cudf2pbo4parano) R 12543 12543 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 41 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/12544/statm: 643 41 0 194 0 29 0

[startup+0.196791 s]
/proc/loadavg: 0.85 0.94 0.90 3/35 12544
/proc/meminfo: memFree=51964/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=0
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 279 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 279 238 194 0 29 0
[pid=12544] ppid=12543 vsize=8844 CPUtime=0.16
/proc/12544/stat : 12544 (cudf_msu32) R 12543 12543 9023 34817 9081 4202496 2005 0 0 0 16 0 0 0 25 0 1 0 894095118 9056256 1897 1283457024 134512640 136125367 4294015392 18446744073709551615 134717932 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12544/statm: 2211 1897 143 394 0 1815 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11416

[startup+0.204872 s]
/proc/loadavg: 0.85 0.94 0.90 3/35 12544
/proc/meminfo: memFree=51964/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=0
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 279 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 279 238 194 0 29 0
[pid=12544] ppid=12543 vsize=9108 CPUtime=0.16
/proc/12544/stat : 12544 (cudf_msu32) D 12543 12543 9023 34817 9081 4202496 2075 0 0 0 16 0 0 0 25 0 1 0 894095118 9326592 1967 1283457024 134512640 136125367 4294015392 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/12544/statm: 2277 1967 143 394 0 1881 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11680

[startup+0.304785 s]
/proc/loadavg: 0.85 0.94 0.90 3/35 12544
/proc/meminfo: memFree=51964/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=0
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 279 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 279 238 194 0 29 0
[pid=12544] ppid=12543 vsize=12564 CPUtime=0.25
/proc/12544/stat : 12544 (cudf_msu32) D 12543 12543 9023 34817 9081 4202496 2953 0 0 0 25 0 0 0 25 0 1 0 894095118 12865536 2845 1283457024 134512640 136125367 4294015392 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/12544/statm: 3141 2845 144 394 0 2745 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 15136

[startup+0.704821 s]
/proc/loadavg: 0.85 0.94 0.90 3/35 12544
/proc/meminfo: memFree=51964/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=0
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 279 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 279 238 194 0 29 0
[pid=12544] ppid=12543 vsize=24640 CPUtime=0.58
/proc/12544/stat : 12544 (cudf_msu32) R 12543 12543 9023 34817 9081 4202496 5975 0 0 0 56 2 0 0 25 0 1 0 894095118 25231360 5867 1283457024 134512640 136125367 4294015392 18446744073709551615 135509985 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12544/statm: 6160 5867 144 394 0 5764 0
Current children cumulated CPU time (s) 0.58
Current children cumulated vsize (KiB) 27212

[startup+1.50487 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 12545
/proc/meminfo: memFree=5452/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=0
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 894095118 2633728 279 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 279 238 194 0 29 0
[pid=12544] ppid=12543 vsize=45160 CPUtime=1.26
/proc/12544/stat : 12544 (cudf_msu32) R 12543 12543 9023 34817 9081 4202496 11161 0 0 0 124 2 0 0 25 0 1 0 894095118 46243840 11004 1283457024 134512640 136125367 4294015392 18446744073709551615 134727103 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12544/statm: 11290 11004 144 394 0 10894 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 47732

[startup+3.11314 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 12545
/proc/meminfo: memFree=5404/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=2.08
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 404 14734 0 0 0 0 177 31 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 2.08
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.31405 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 12546
/proc/meminfo: memFree=39536/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=2.08
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 404 14734 0 0 0 0 177 31 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
[pid=12546] ppid=12543 vsize=26084 CPUtime=3.84
/proc/12546/stat : 12546 (bmo-pblex32) R 12543 12543 9023 34817 9081 4202496 7746 0 0 0 312 72 0 0 25 0 1 0 894095364 26710016 6223 1283457024 134512640 135887319 4287302464 18446744073709551615 134600912 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12546/statm: 6521 6223 144 336 0 6183 0
Current children cumulated CPU time (s) 5.92
Current children cumulated vsize (KiB) 28656

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

[startup+6.41408 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 12546
/proc/meminfo: memFree=39536/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=2.08
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 404 14734 0 0 0 0 177 31 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
[pid=12546] ppid=12543 vsize=26220 CPUtime=3.95
/proc/12546/stat : 12546 (bmo-pblex32) R 12543 12543 9023 34817 9081 4202496 7765 0 0 0 320 75 0 0 25 0 1 0 894095364 26849280 6242 1283457024 134512640 135887319 4287302464 18446744073709551615 134598364 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12546/statm: 6555 6242 144 336 0 6217 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 28792

[startup+8.01449 s]
/proc/loadavg: 0.88 0.94 0.90 3/36 12546
/proc/meminfo: memFree=37800/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=2.08
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 404 14734 0 0 0 0 177 31 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
[pid=12546] ppid=12543 vsize=27436 CPUtime=5.52
/proc/12546/stat : 12546 (bmo-pblex32) R 12543 12543 9023 34817 9081 4202496 8095 0 0 0 452 100 0 0 25 0 1 0 894095364 28094464 6568 1283457024 134512640 135887319 4287302464 18446744073709551615 134624768 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12546/statm: 6859 6568 144 336 0 6521 0
Current children cumulated CPU time (s) 7.6
Current children cumulated vsize (KiB) 30008

[startup+8.41458 s]
/proc/loadavg: 0.88 0.94 0.90 3/36 12546
/proc/meminfo: memFree=37800/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=2.08
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 404 14734 0 0 0 0 177 31 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
[pid=12546] ppid=12543 vsize=27840 CPUtime=5.91
/proc/12546/stat : 12546 (bmo-pblex32) R 12543 12543 9023 34817 9081 4202496 8184 0 0 0 486 105 0 0 25 0 1 0 894095364 28508160 6657 1283457024 134512640 135887319 4287302464 18446744073709551615 134525040 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12546/statm: 6960 6657 144 336 0 6622 0
Current children cumulated CPU time (s) 7.99
Current children cumulated vsize (KiB) 30412

[startup+8.61462 s]
/proc/loadavg: 0.88 0.94 0.90 3/36 12546
/proc/meminfo: memFree=37800/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=2.08
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 404 14734 0 0 0 0 177 31 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
[pid=12546] ppid=12543 vsize=27976 CPUtime=6.11
/proc/12546/stat : 12546 (bmo-pblex32) R 12543 12543 9023 34817 9081 4202496 8225 0 0 0 503 108 0 0 25 0 1 0 894095364 28647424 6698 1283457024 134512640 135887319 4287302464 18446744073709551615 134617710 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12546/statm: 6994 6698 144 336 0 6656 0
Current children cumulated CPU time (s) 8.19
Current children cumulated vsize (KiB) 30548

[startup+8.71463 s]
/proc/loadavg: 0.88 0.94 0.90 3/36 12546
/proc/meminfo: memFree=37800/1048576 swapFree=2095372/2097144
[pid=12543] ppid=12542 vsize=2572 CPUtime=8.26
/proc/12543/stat : 12543 (cudf2pbo4parano) S 12542 12543 9023 34817 9081 4202496 436 22968 0 0 0 0 684 142 18 0 1 0 894095118 2633728 282 1283457024 134512640 135304128 4289832240 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12543/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 8.26
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 8.74346
CPU time (s): 8.33652
CPU user time (s): 6.90843
CPU system time (s): 1.42809
CPU usage (%): 95.3458
Max. virtual memory (cumulated for all children) (KiB): 61912

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

runsolver used 0 second user time and 0 second system time

The end