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/201012091704/cudf2pbo4user-1.0/rand835640.cudf.impossible.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/impossible//rand835640.cudf /home/misc2010/tmp/201012091704/cudf2pbo4user-1.0/rand835640.cudf.impossible.result -changed,-notuptodate,-removed,-new 

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.12 1.08 1.02 3/39 6477
/proc/meminfo: memFree=366912/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=0
/proc/6476/stat : 6476 (cudf2pbo4user-1) R 6475 6476 25521 34816 2180 4202496 366 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 280 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/6476/statm: 644 280 240 194 0 30 0
[pid=6477] ppid=6476 vsize=2576 CPUtime=0
/proc/6477/stat : 6477 (cudf2pbo4user-1) R 6476 6476 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 40 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/6477/statm: 644 40 0 194 0 30 0

[startup+0.165047 s]
/proc/loadavg: 1.12 1.08 1.02 3/39 6477
/proc/meminfo: memFree=366912/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=0
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 384 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 280 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 280 240 194 0 30 0
[pid=6477] ppid=6476 vsize=8044 CPUtime=0.14
/proc/6477/stat : 6477 (cudf_msu32) R 6476 6476 25521 34816 2180 4202496 1833 0 0 0 14 0 0 0 25 0 1 0 901392636 8237056 1725 1283457024 134512640 136125367 4293779776 18446744073709551615 134718131 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6477/statm: 2011 1725 146 394 0 1615 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10620

[startup+0.206073 s]
/proc/loadavg: 1.12 1.08 1.02 3/39 6477
/proc/meminfo: memFree=366912/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=0
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 384 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 280 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 280 240 194 0 30 0
[pid=6477] ppid=6476 vsize=9496 CPUtime=0.18
/proc/6477/stat : 6477 (cudf_msu32) R 6476 6476 25521 34816 2180 4202496 2199 0 0 0 18 0 0 0 25 0 1 0 901392636 9723904 2091 1283457024 134512640 136125367 4293779776 18446744073709551615 135543670 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6477/statm: 2374 2091 146 394 0 1978 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12072

[startup+0.306097 s]
/proc/loadavg: 1.12 1.08 1.02 3/39 6477
/proc/meminfo: memFree=366912/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=0
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 384 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 280 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 280 240 194 0 30 0
[pid=6477] ppid=6476 vsize=13084 CPUtime=0.28
/proc/6477/stat : 6477 (cudf_msu32) R 6476 6476 25521 34816 2180 4202496 3073 0 0 0 27 1 0 0 25 0 1 0 901392636 13398016 2965 1283457024 134512640 136125367 4293779776 18446744073709551615 134720467 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6477/statm: 3271 2965 147 394 0 2875 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 15660

[startup+0.706183 s]
/proc/loadavg: 1.12 1.08 1.02 3/39 6477
/proc/meminfo: memFree=366912/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=0
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 384 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 280 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 280 240 194 0 30 0
[pid=6477] ppid=6476 vsize=25160 CPUtime=0.68
/proc/6477/stat : 6477 (cudf_msu32) R 6476 6476 25521 34816 2180 4202496 6117 0 0 0 64 4 0 0 25 0 1 0 901392636 25763840 6009 1283457024 134512640 136125367 4293779776 18446744073709551615 135176288 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6477/statm: 6290 6009 147 394 0 5894 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 27736

[startup+1.50632 s]
/proc/loadavg: 1.12 1.08 1.02 2/40 6478
/proc/meminfo: memFree=332668/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=0
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 384 0 0 0 0 0 0 0 25 0 1 0 901392636 2637824 280 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 280 240 194 0 30 0
[pid=6477] ppid=6476 vsize=46088 CPUtime=1.48
/proc/6477/stat : 6477 (cudf_msu32) R 6476 6476 25521 34816 2180 4202496 11401 0 0 0 140 8 0 0 25 0 1 0 901392636 47194112 11244 1283457024 134512640 136125367 4293779776 18446744073709551615 135548996 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6477/statm: 11522 11244 157 394 0 11126 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 48664

[startup+3.10738 s]
/proc/loadavg: 1.11 1.08 1.02 2/40 6478
/proc/meminfo: memFree=303776/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=2.44
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 402 15806 0 0 0 0 201 43 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
Current children cumulated CPU time (s) 2.44
Current children cumulated vsize (KiB) 2576
heavy processes:

[startup+6.30819 s]
/proc/loadavg: 1.11 1.08 1.02 2/40 6479
/proc/meminfo: memFree=341348/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=2.44
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 402 15806 0 0 0 0 201 43 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
[pid=6479] ppid=6476 vsize=23732 CPUtime=3.8
/proc/6479/stat : 6479 (bmo-pblex32) R 6476 6476 25521 34816 2180 4202496 6333 0 0 0 304 76 0 0 25 0 1 0 901392883 24301568 5616 1283457024 134512640 135887319 4294742624 18446744073709551615 134625069 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6479/statm: 5933 5616 138 336 0 5595 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 26308

[startup+12.7098 s]
/proc/loadavg: 1.10 1.07 1.02 2/40 6479
/proc/meminfo: memFree=331180/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=2.44
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 402 15806 0 0 0 0 201 43 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
[pid=6479] ppid=6476 vsize=40692 CPUtime=10.2
/proc/6479/stat : 6479 (bmo-pblex32) R 6476 6476 25521 34816 2180 4202496 12642 0 0 0 848 172 0 0 25 0 1 0 901392883 41668608 9870 1283457024 134512640 135887319 4294742624 18446744073709551615 135318574 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6479/statm: 10173 9870 144 336 0 9835 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 43268

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

[startup+12.8098 s]
/proc/loadavg: 1.10 1.07 1.02 2/40 6479
/proc/meminfo: memFree=331180/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=2.44
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 402 15806 0 0 0 0 201 43 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
[pid=6479] ppid=6476 vsize=41616 CPUtime=10.29
/proc/6479/stat : 6479 (bmo-pblex32) R 6476 6476 25521 34816 2180 4202496 12889 0 0 0 856 173 0 0 25 0 1 0 901392883 42614784 10099 1283457024 134512640 135887319 4294742624 18446744073709551615 134618016 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6479/statm: 10404 10099 144 336 0 10066 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 44192

[startup+13.61 s]
/proc/loadavg: 1.10 1.07 1.02 2/40 6479
/proc/meminfo: memFree=316052/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=2.44
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 402 15806 0 0 0 0 201 43 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
[pid=6479] ppid=6476 vsize=49764 CPUtime=11.08
/proc/6479/stat : 6479 (bmo-pblex32) R 6476 6476 25521 34816 2180 4202496 15875 0 0 0 934 174 0 0 25 0 1 0 901392883 50958336 12117 1283457024 134512640 135887319 4294742624 18446744073709551615 134527024 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6479/statm: 12441 12117 144 336 0 12103 0
Current children cumulated CPU time (s) 13.52
Current children cumulated vsize (KiB) 52340

[startup+13.8101 s]
/proc/loadavg: 1.10 1.07 1.02 2/40 6479
/proc/meminfo: memFree=316052/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=2.44
/proc/6476/stat : 6476 (cudf2pbo4user-1) S 6475 6476 25521 34816 2180 4202496 402 15806 0 0 0 0 201 43 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
[pid=6479] ppid=6476 vsize=49764 CPUtime=11.28
/proc/6479/stat : 6479 (bmo-pblex32) R 6476 6476 25521 34816 2180 4202496 15875 0 0 0 954 174 0 0 25 0 1 0 901392883 50958336 12117 1283457024 134512640 135887319 4294742624 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6479/statm: 12441 12117 144 336 0 12103 0
Current children cumulated CPU time (s) 13.72
Current children cumulated vsize (KiB) 52340

[startup+13.9101 s]
/proc/loadavg: 1.10 1.07 1.02 2/40 6479
/proc/meminfo: memFree=316052/1048576 swapFree=2095372/2097144
[pid=6476] ppid=6475 vsize=2576 CPUtime=13.82
/proc/6476/stat : 6476 (cudf2pbo4user-1) R 6475 6476 25521 34816 2180 4202496 405 31685 0 0 0 0 1165 217 18 0 1 0 901392636 2637824 281 1283457024 134512640 135304128 4287312544 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/6476/statm: 644 281 241 194 0 30 0
Current children cumulated CPU time (s) 13.82
Current children cumulated vsize (KiB) 2576

Child status: 0
Real time (s): 13.9819
CPU time (s): 13.9089
CPU user time (s): 11.7127
CPU system time (s): 2.19614
CPU usage (%): 99.4779
Max. virtual memory (cumulated for all children) (KiB): 65136

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

runsolver used 0 second user time and 0 second system time

The end