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/cudf2msu4user-1.0/rand81406f.cudf.impossible.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/impossible//rand81406f.cudf /home/misc2010/tmp/201012091704/cudf2msu4user-1.0/rand81406f.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.20 1.08 1.03 4/39 5993
/proc/meminfo: memFree=419488/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=2048 CPUtime=0
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 268 0 0 0 0 0 0 0 25 0 1 0 901326369 2097152 206 1283457024 134512640 136120023 4287443696 18446744073709551615 134732575 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 512 206 140 393 0 117 0

[startup+0.205583 s]
/proc/loadavg: 1.20 1.08 1.03 4/39 5993
/proc/meminfo: memFree=419488/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=10016 CPUtime=0.2
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 2266 0 0 0 20 0 0 0 25 0 1 0 901326369 10256384 2204 1283457024 134512640 136120023 4287443696 18446744073709551615 134585315 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 2504 2204 141 393 0 2109 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12588

[startup+0.305597 s]
/proc/loadavg: 1.20 1.08 1.03 4/39 5993
/proc/meminfo: memFree=419488/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=13512 CPUtime=0.3
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 3140 0 0 0 30 0 0 0 25 0 1 0 901326369 13836288 3078 1283457024 134512640 136120023 4287443696 18446744073709551615 134721204 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 3378 3078 142 393 0 2983 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16084

[startup+0.405615 s]
/proc/loadavg: 1.20 1.08 1.03 4/39 5993
/proc/meminfo: memFree=419488/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=16680 CPUtime=0.4
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 3938 0 0 0 40 0 0 0 25 0 1 0 901326369 17080320 3876 1283457024 134512640 136120023 4287443696 18446744073709551615 135296992 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 4170 3876 142 393 0 3775 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 19252

[startup+0.705664 s]
/proc/loadavg: 1.20 1.08 1.03 4/39 5993
/proc/meminfo: memFree=419488/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=25324 CPUtime=0.7
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 6096 0 0 0 70 0 0 0 25 0 1 0 901326369 25931776 6034 1283457024 134512640 136120023 4287443696 18446744073709551615 134721247 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 6331 6034 142 393 0 5936 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27896

[startup+1.50578 s]
/proc/loadavg: 1.20 1.08 1.03 2/40 5994
/proc/meminfo: memFree=383260/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=45580 CPUtime=1.5
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 11219 0 0 0 150 0 0 0 25 0 1 0 901326369 46673920 11108 1283457024 134512640 136120023 4287443696 18446744073709551615 134711911 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 11395 11108 142 393 0 11000 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 48152

[startup+3.10611 s]
/proc/loadavg: 1.20 1.08 1.03 2/40 5994
/proc/meminfo: memFree=321260/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=100044 CPUtime=3.11
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 25182 0 0 0 302 9 0 0 25 0 1 0 901326369 102445056 24753 1283457024 134512640 136120023 4287443696 18446744073709551615 134831717 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 25011 24753 179 393 0 24616 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 102616

[startup+6.30666 s]
/proc/loadavg: 1.18 1.08 1.02 2/40 5994
/proc/meminfo: memFree=320516/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=100732 CPUtime=6.31
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 25363 0 0 0 622 9 0 0 25 0 1 0 901326369 103149568 24923 1283457024 134512640 136120023 4287443696 18446744073709551615 134872421 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 25183 24923 185 393 0 24788 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 103304

[startup+12.7082 s]
/proc/loadavg: 1.17 1.08 1.02 2/40 5994
/proc/meminfo: memFree=320516/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=100732 CPUtime=12.71
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 25363 0 0 0 1262 9 0 0 25 0 1 0 901326369 103149568 24923 1283457024 134512640 136120023 4287443696 18446744073709551615 134831668 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 25183 24923 185 393 0 24788 0
Current children cumulated CPU time (s) 12.71
Current children cumulated vsize (KiB) 103304

[startup+25.5122 s]
/proc/loadavg: 1.13 1.07 1.02 2/40 5994
/proc/meminfo: memFree=320516/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=100732 CPUtime=25.51
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 25363 0 0 0 2541 10 0 0 25 0 1 0 901326369 103149568 24923 1283457024 134512640 136120023 4287443696 18446744073709551615 134859203 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 25183 24923 185 393 0 24788 0
Current children cumulated CPU time (s) 25.51
Current children cumulated vsize (KiB) 103304

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

[startup+25.7123 s]
/proc/loadavg: 1.13 1.07 1.02 2/40 5994
/proc/meminfo: memFree=320516/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=100732 CPUtime=25.71
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 25363 0 0 0 2561 10 0 0 25 0 1 0 901326369 103149568 24923 1283457024 134512640 136120023 4287443696 18446744073709551615 134863187 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 25183 24923 185 393 0 24788 0
Current children cumulated CPU time (s) 25.71
Current children cumulated vsize (KiB) 103304

[startup+28.9129 s]
/proc/loadavg: 1.13 1.07 1.02 2/40 5994
/proc/meminfo: memFree=320516/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=100732 CPUtime=28.91
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 25363 0 0 0 2881 10 0 0 25 0 1 0 901326369 103149568 24923 1283457024 134512640 136120023 4287443696 18446744073709551615 135545137 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 25183 24923 185 393 0 24788 0
Current children cumulated CPU time (s) 28.91
Current children cumulated vsize (KiB) 103304

[startup+32.104 s]
/proc/loadavg: 1.12 1.07 1.02 2/40 5994
/proc/meminfo: memFree=315060/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=106060 CPUtime=32.09
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 26711 0 0 0 3199 10 0 0 25 0 1 0 901326369 108605440 26267 1283457024 134512640 136120023 4287443696 18446744073709551615 134831637 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 26515 26267 185 393 0 26120 0
Current children cumulated CPU time (s) 32.09
Current children cumulated vsize (KiB) 108632

[startup+33.7045 s]
/proc/loadavg: 1.12 1.07 1.02 2/40 5994
/proc/meminfo: memFree=314812/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=106432 CPUtime=33.7
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 28106 0 0 0 3360 10 0 0 25 0 1 0 901326369 108986368 26340 1283457024 134512640 136120023 4287443696 18446744073709551615 134863405 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 26608 26340 185 393 0 26213 0
Current children cumulated CPU time (s) 33.7
Current children cumulated vsize (KiB) 109004

[startup+34.1046 s]
/proc/loadavg: 1.12 1.07 1.02 2/40 5994
/proc/meminfo: memFree=314812/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=106432 CPUtime=34.1
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 28106 0 0 0 3400 10 0 0 25 0 1 0 901326369 108986368 26340 1283457024 134512640 136120023 4287443696 18446744073709551615 134866446 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 26608 26340 185 393 0 26213 0
Current children cumulated CPU time (s) 34.1
Current children cumulated vsize (KiB) 109004

[startup+34.5048 s]
/proc/loadavg: 1.12 1.07 1.02 2/40 5994
/proc/meminfo: memFree=314812/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=106432 CPUtime=34.5
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 28106 0 0 0 3440 10 0 0 25 0 1 0 901326369 108986368 26340 1283457024 134512640 136120023 4287443696 18446744073709551615 134870980 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 26608 26340 185 393 0 26213 0
Current children cumulated CPU time (s) 34.5
Current children cumulated vsize (KiB) 109004

[startup+34.6048 s]
/proc/loadavg: 1.12 1.07 1.02 2/40 5994
/proc/meminfo: memFree=314812/1048576 swapFree=2095372/2097144
[pid=5992] ppid=5991 vsize=2572 CPUtime=0
/proc/5992/stat : 5992 (cudf2msu4user-1) S 5991 5992 25521 34816 2180 4202496 382 0 0 0 0 0 0 0 18 0 1 0 901326369 2633728 278 1283457024 134512640 135304128 4289295504 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5992/statm: 643 278 237 194 0 29 0
[pid=5993] ppid=5992 vsize=106432 CPUtime=34.6
/proc/5993/stat : 5993 (cudf_msu32) R 5992 5992 25521 34816 2180 4202496 28106 0 0 0 3450 10 0 0 25 0 1 0 901326369 108986368 26340 1283457024 134512640 136120023 4287443696 18446744073709551615 134894165 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5993/statm: 26608 26340 185 393 0 26213 0
Current children cumulated CPU time (s) 34.6
Current children cumulated vsize (KiB) 109004

Child status: 0
Real time (s): 34.6972
CPU time (s): 34.6822
CPU user time (s): 34.5582
CPU system time (s): 0.124007
CPU usage (%): 99.9567
Max. virtual memory (cumulated for all children) (KiB): 109004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 34.5582
system time used= 0.124007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 28514
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= 3
involuntary context switches= 477

runsolver used 0 second user time and 0 second system time

The end