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/rand835640.cudf.impossible.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/impossible//rand835640.cudf /home/misc2010/tmp/201012091434/cudf2pbo4user-1.0/rand835640.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.16 1.15 1.07 5/40 29816
/proc/meminfo: memFree=398700/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=2572 CPUtime=0
/proc/29816/stat : 29816 (cudf2pbo4user-1) D 29815 29815 25521 34816 25544 4202560 79 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 103 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/29816/statm: 643 103 62 194 0 29 0

[startup+0.199316 s]
/proc/loadavg: 1.16 1.15 1.07 5/40 29816
/proc/meminfo: memFree=398700/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=9104 CPUtime=0.17
/proc/29816/stat : 29816 (cudf_msu32) R 29815 29815 25521 34816 25544 4202496 2081 0 0 0 17 0 0 0 25 0 1 0 900181976 9322496 1974 1283457024 134512640 136125367 4292495360 18446744073709551615 135293395 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/29816/statm: 2276 1974 146 394 0 1880 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11676

[startup+0.209718 s]
/proc/loadavg: 1.16 1.15 1.07 5/40 29816
/proc/meminfo: memFree=398700/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=9368 CPUtime=0.18
/proc/29816/stat : 29816 (cudf_msu32) R 29815 29815 25521 34816 25544 4202496 2170 0 0 0 18 0 0 0 25 0 1 0 900181976 9592832 2063 1283457024 134512640 136125367 4292495360 18446744073709551615 134717814 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/29816/statm: 2342 2063 146 394 0 1946 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 11940

[startup+0.309743 s]
/proc/loadavg: 1.16 1.15 1.07 5/40 29816
/proc/meminfo: memFree=398700/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=13088 CPUtime=0.28
/proc/29816/stat : 29816 (cudf_msu32) R 29815 29815 25521 34816 25544 4202496 3077 0 0 0 28 0 0 0 25 0 1 0 900181976 13402112 2970 1283457024 134512640 136125367 4292495360 18446744073709551615 134738107 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/29816/statm: 3272 2970 147 394 0 2876 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 15660

[startup+0.709833 s]
/proc/loadavg: 1.16 1.15 1.07 5/40 29816
/proc/meminfo: memFree=398700/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=25296 CPUtime=0.67
/proc/29816/stat : 29816 (cudf_msu32) R 29815 29815 25521 34816 25544 4202496 6135 0 0 0 63 4 0 0 25 0 1 0 900181976 25903104 6028 1283457024 134512640 136125367 4292495360 18446744073709551615 134575156 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/29816/statm: 6324 6028 147 394 0 5928 0
Current children cumulated CPU time (s) 0.67
Current children cumulated vsize (KiB) 27868

[startup+1.50999 s]
/proc/loadavg: 1.16 1.15 1.07 2/41 29817
/proc/meminfo: memFree=364456/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=46108 CPUtime=1.47
/proc/29816/stat : 29816 (cudf_msu32) R 29815 29815 25521 34816 25544 4202496 11393 0 0 0 135 12 0 0 25 0 1 0 900181976 47214592 11237 1283457024 134512640 136125367 4292495360 18446744073709551615 134710447 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/29816/statm: 11527 11237 157 394 0 11131 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 48680

[startup+3.11038 s]
/proc/loadavg: 1.16 1.15 1.07 2/41 29817
/proc/meminfo: memFree=328000/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=0
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 384 0 0 0 0 0 0 0 25 0 1 0 900181976 2633728 280 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 280 240 194 0 29 0
[pid=29816] ppid=29815 vsize=74492 CPUtime=3.07
/proc/29816/stat : 29816 (cudf_msu32) R 29815 29815 25521 34816 25544 4202496 18817 0 0 0 238 69 0 0 25 0 1 0 900181976 76279808 18366 1283457024 134512640 136125367 4292495360 18446744073709551615 135142063 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/29816/statm: 18623 18366 169 394 0 18227 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 77064

[startup+6.31253 s]
/proc/loadavg: 1.15 1.15 1.07 2/40 29818
/proc/meminfo: memFree=354916/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=40032 CPUtime=3.05
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 10251 0 0 0 255 50 0 0 25 0 1 0 900182301 40992768 9308 1283457024 134512640 135887319 4292692064 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 10008 9308 138 336 0 9670 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 42604

[startup+12.7042 s]
/proc/loadavg: 1.13 1.14 1.07 2/40 29818
/proc/meminfo: memFree=352436/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=42556 CPUtime=9.44
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 10890 0 0 0 764 180 0 0 25 0 1 0 900182301 43577344 9938 1283457024 134512640 135887319 4292692064 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 10639 9938 138 336 0 10301 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 45128

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

[startup+12.8043 s]
/proc/loadavg: 1.13 1.14 1.07 2/40 29818
/proc/meminfo: memFree=352436/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=42556 CPUtime=9.54
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 10895 0 0 0 773 181 0 0 25 0 1 0 900182301 43577344 9943 1283457024 134512640 135887319 4292692064 18446744073709551615 134617654 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 10639 9943 138 336 0 10301 0
Current children cumulated CPU time (s) 12.74
Current children cumulated vsize (KiB) 45128

[startup+16.0049 s]
/proc/loadavg: 1.12 1.14 1.07 2/40 29818
/proc/meminfo: memFree=337928/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=65804 CPUtime=12.74
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 19171 0 0 0 1064 210 0 0 25 0 1 0 900182301 67383296 15423 1283457024 134512640 135887319 4292692064 18446744073709551615 134516583 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 16451 15423 144 336 0 16113 0
Current children cumulated CPU time (s) 15.94
Current children cumulated vsize (KiB) 68376

[startup+17.6054 s]
/proc/loadavg: 1.12 1.14 1.07 2/40 29818
/proc/meminfo: memFree=309408/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=85080 CPUtime=14.33
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 28090 0 0 0 1214 219 0 0 25 0 1 0 900182301 87121920 20637 1283457024 134512640 135887319 4292692064 18446744073709551615 134615446 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 21270 20637 144 336 0 20932 0
Current children cumulated CPU time (s) 17.53
Current children cumulated vsize (KiB) 87652

[startup+18.4057 s]
/proc/loadavg: 1.12 1.14 1.07 2/40 29818
/proc/meminfo: memFree=309408/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=85512 CPUtime=15.12
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 28214 0 0 0 1288 224 0 0 25 0 1 0 900182301 87564288 20761 1283457024 134512640 135887319 4292692064 18446744073709551615 134615005 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 21378 20761 144 336 0 21040 0
Current children cumulated CPU time (s) 18.32
Current children cumulated vsize (KiB) 88084

[startup+18.8058 s]
/proc/loadavg: 1.11 1.14 1.07 2/40 29818
/proc/meminfo: memFree=308788/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=3.2
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 401 18819 0 0 0 0 244 76 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
[pid=29818] ppid=29815 vsize=85656 CPUtime=15.53
/proc/29818/stat : 29818 (bmo-pblex32) R 29815 29815 25521 34816 25544 4202496 28234 0 0 0 1327 226 0 0 25 0 1 0 900182301 87711744 20781 1283457024 134512640 135887319 4292692064 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/29818/statm: 21414 20781 144 336 0 21076 0
Current children cumulated CPU time (s) 18.73
Current children cumulated vsize (KiB) 88228

[startup+18.9058 s]
/proc/loadavg: 1.11 1.14 1.07 2/40 29818
/proc/meminfo: memFree=308788/1048576 swapFree=2095372/2097144
[pid=29815] ppid=29814 vsize=2572 CPUtime=18.79
/proc/29815/stat : 29815 (cudf2pbo4user-1) S 29814 29815 25521 34816 25544 4202496 431 47057 0 0 0 0 1576 303 18 0 1 0 900181976 2633728 281 1283457024 134512640 135304128 4292612016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/29815/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 18.79
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 18.9895
CPU time (s): 18.9212
CPU user time (s): 15.889
CPU system time (s): 3.03219
CPU usage (%): 99.6404
Max. virtual memory (cumulated for all children) (KiB): 88228

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.889
system time used= 3.03219
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49840
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= 28
involuntary context switches= 2407

runsolver used 0.012 second user time and 0 second system time

The end