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/201012091434/cudf2pbo4user-1.0/rand6b4d6e.cudf.impossible.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/impossible//rand6b4d6e.cudf /home/misc2010/tmp/201012091434/cudf2pbo4user-1.0/rand6b4d6e.cudf.impossible.result -changed,-removed,-unmet_recommends,-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.00 1.05 0.97 5/39 27882
/proc/meminfo: memFree=447000/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) R 27880 27881 25521 34816 25544 4202496 367 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=2576 CPUtime=0
/proc/27882/stat : 27882 (cudf2pbo4user-1) R 27881 27881 25521 34816 25544 4202560 0 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 41 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/27882/statm: 644 41 0 194 0 30 0

[startup+0.151342 s]
/proc/loadavg: 1.00 1.05 0.97 5/39 27882
/proc/meminfo: memFree=447000/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=7524 CPUtime=0.12
/proc/27882/stat : 27882 (cudf_msu32) R 27881 27881 25521 34816 25544 4202496 1694 0 0 0 11 1 0 0 25 0 1 0 900051226 7704576 1586 1283457024 134512640 136125367 4290496032 18446744073709551615 134738215 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/27882/statm: 1881 1586 146 394 0 1485 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 10100

[startup+0.212849 s]
/proc/loadavg: 1.00 1.05 0.97 5/39 27882
/proc/meminfo: memFree=447000/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=9768 CPUtime=0.18
/proc/27882/stat : 27882 (cudf_msu32) R 27881 27881 25521 34816 25544 4202496 2254 0 0 0 16 2 0 0 25 0 1 0 900051226 10002432 2146 1283457024 134512640 136125367 4290496032 18446744073709551615 134717605 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/27882/statm: 2442 2146 146 394 0 2046 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12344

[startup+0.31286 s]
/proc/loadavg: 1.00 1.05 0.97 5/39 27882
/proc/meminfo: memFree=447000/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=13356 CPUtime=0.28
/proc/27882/stat : 27882 (cudf_msu32) R 27881 27881 25521 34816 25544 4202496 3138 0 0 0 26 2 0 0 25 0 1 0 900051226 13676544 3030 1283457024 134512640 136125367 4290496032 18446744073709551615 134719387 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/27882/statm: 3339 3030 147 394 0 2943 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 15932

[startup+0.712914 s]
/proc/loadavg: 1.00 1.05 0.97 5/39 27882
/proc/meminfo: memFree=447000/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=25432 CPUtime=0.68
/proc/27882/stat : 27882 (cudf_msu32) R 27881 27881 25521 34816 25544 4202496 6185 0 0 0 66 2 0 0 25 0 1 0 900051226 26042368 6077 1283457024 134512640 136125367 4290496032 18446744073709551615 134717880 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/27882/statm: 6358 6077 147 394 0 5962 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 28008

[startup+1.51301 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27883
/proc/meminfo: memFree=412632/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=46244 CPUtime=1.48
/proc/27882/stat : 27882 (cudf_msu32) R 27881 27881 25521 34816 25544 4202496 11424 0 0 0 143 5 0 0 25 0 1 0 900051226 47353856 11267 1283457024 134512640 136125367 4290496032 18446744073709551615 134675134 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/27882/statm: 11561 11267 157 394 0 11165 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 48820

[startup+3.1132 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27883
/proc/meminfo: memFree=375432/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=0
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900051226 2637824 281 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 281 240 194 0 30 0
[pid=27882] ppid=27881 vsize=74508 CPUtime=3.08
/proc/27882/stat : 27882 (cudf_msu32) R 27881 27881 25521 34816 25544 4202496 18821 0 0 0 251 57 0 0 25 0 1 0 900051226 76296192 18369 1283457024 134512640 136125367 4290496032 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/27882/statm: 18627 18369 169 394 0 18231 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 77084

[startup+6.31367 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27884
/proc/meminfo: memFree=403084/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=40492 CPUtime=3.07
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 10378 0 0 0 246 61 0 0 25 0 1 0 900051549 41463808 9408 1283457024 134512640 135887319 4291882992 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 10123 9408 138 336 0 9785 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 43068

[startup+12.7108 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27884
/proc/meminfo: memFree=400480/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=42760 CPUtime=9.39
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 10985 0 0 0 742 197 0 0 25 0 1 0 900051549 43786240 9975 1283457024 134512640 135887319 4291882992 18446744073709551615 134598561 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 10690 9975 138 336 0 10352 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 45336

[startup+25.5135 s]
/proc/loadavg: 1.00 1.05 0.97 2/40 27884
/proc/meminfo: memFree=395396/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=47768 CPUtime=22.14
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 12254 0 0 0 1772 442 0 0 25 0 1 0 900051549 48914432 11236 1283457024 134512640 135887319 4291882992 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 11942 11236 138 336 0 11604 0
Current children cumulated CPU time (s) 25.33
Current children cumulated vsize (KiB) 50344

[startup+51.1115 s]
/proc/loadavg: 1.00 1.04 0.97 2/40 27884
/proc/meminfo: memFree=379772/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=63072 CPUtime=47.7
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 18097 0 0 0 4231 539 0 0 25 0 1 0 900051549 64585728 15100 1283457024 134512640 135887319 4291882992 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 15768 15100 144 336 0 15430 0
Current children cumulated CPU time (s) 50.89
Current children cumulated vsize (KiB) 65648

[startup+102.309 s]
/proc/loadavg: 1.00 1.03 0.97 2/40 27884
/proc/meminfo: memFree=365140/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=77392 CPUtime=98.85
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 24357 0 0 0 9317 568 0 0 25 0 1 0 900051549 79249408 18735 1283457024 134512640 135887319 4291882992 18446744073709551615 134527030 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 19348 18735 144 336 0 19010 0
Current children cumulated CPU time (s) 102.04
Current children cumulated vsize (KiB) 79968

[startup+162.308 s]
/proc/loadavg: 1.00 1.02 0.97 2/40 27884
/proc/meminfo: memFree=347532/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=94908 CPUtime=158.72
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 30943 0 0 0 15255 617 0 0 25 0 1 0 900051549 97185792 23090 1283457024 134512640 135887319 4291882992 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 23727 23090 144 336 0 23389 0
Current children cumulated CPU time (s) 161.91
Current children cumulated vsize (KiB) 97484

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

[startup+163.209 s]
/proc/loadavg: 1.00 1.02 0.97 2/40 27884
/proc/meminfo: memFree=347532/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=94908 CPUtime=159.62
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 30944 0 0 0 15345 617 0 0 25 0 1 0 900051549 97185792 23091 1283457024 134512640 135887319 4291882992 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 23727 23091 144 336 0 23389 0
Current children cumulated CPU time (s) 162.81
Current children cumulated vsize (KiB) 97484

[startup+164.009 s]
/proc/loadavg: 1.00 1.02 0.97 2/40 27884
/proc/meminfo: memFree=347532/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=94908 CPUtime=160.42
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 30948 0 0 0 15425 617 0 0 25 0 1 0 900051549 97185792 23095 1283457024 134512640 135887319 4291882992 18446744073709551615 134614905 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 23727 23095 144 336 0 23389 0
Current children cumulated CPU time (s) 163.61
Current children cumulated vsize (KiB) 97484

[startup+164.809 s]
/proc/loadavg: 1.00 1.02 0.97 2/40 27884
/proc/meminfo: memFree=347532/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=94908 CPUtime=161.22
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 30963 0 0 0 15505 617 0 0 25 0 1 0 900051549 97185792 23105 1283457024 134512640 135887319 4291882992 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 23727 23105 144 336 0 23389 0
Current children cumulated CPU time (s) 164.41
Current children cumulated vsize (KiB) 97484

[startup+165.009 s]
/proc/loadavg: 1.00 1.02 0.97 2/40 27884
/proc/meminfo: memFree=347532/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=3.19
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 402 18823 0 0 0 0 258 61 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
[pid=27884] ppid=27881 vsize=94908 CPUtime=161.42
/proc/27884/stat : 27884 (bmo-pblex32) R 27881 27881 25521 34816 25544 4202496 30965 0 0 0 15525 617 0 0 25 0 1 0 900051549 97185792 23107 1283457024 134512640 135887319 4291882992 18446744073709551615 134605656 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/27884/statm: 23727 23107 144 336 0 23389 0
Current children cumulated CPU time (s) 164.61
Current children cumulated vsize (KiB) 97484

[startup+165.102 s]
/proc/loadavg: 1.00 1.02 0.97 2/40 27884
/proc/meminfo: memFree=347532/1048576 swapFree=2095372/2097144
[pid=27881] ppid=27880 vsize=2576 CPUtime=164.64
/proc/27881/stat : 27881 (cudf2pbo4user-1) S 27880 27881 25521 34816 25544 4202496 433 49792 0 0 0 0 15785 679 18 0 1 0 900051226 2637824 282 1283457024 134512640 135304128 4292933632 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/27881/statm: 644 282 241 194 0 30 0
Current children cumulated CPU time (s) 164.64
Current children cumulated vsize (KiB) 2576

Child status: 0
Real time (s): 165.156
CPU time (s): 164.774
CPU user time (s): 157.954
CPU system time (s): 6.82043
CPU usage (%): 99.7688
Max. virtual memory (cumulated for all children) (KiB): 97484

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 157.954
system time used= 6.82043
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 52581
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= 31
involuntary context switches= 8053

runsolver used 0 second user time and 0 second system time

The end