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/rand0695fb.cudf.impossible.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/impossible//rand0695fb.cudf /home/misc2010/tmp/201012091434/cudf2pbo4user-1.0/rand0695fb.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.05 0.85 0.44 3/38 26006
/proc/meminfo: memFree=453868/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=2572 CPUtime=0
/proc/26006/stat : 26006 (cudf2pbo4user-1) D 26005 26005 25521 34816 25544 4202560 80 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 104 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/26006/statm: 643 104 62 194 0 29 0

[startup+0.157303 s]
/proc/loadavg: 1.05 0.85 0.44 3/38 26006
/proc/meminfo: memFree=453868/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=8048 CPUtime=0.14
/proc/26006/stat : 26006 (cudf_msu32) R 26005 26005 25521 34816 25544 4202496 1833 0 0 0 13 1 0 0 25 0 1 0 899864583 8241152 1725 1283457024 134512640 136125367 4287576912 18446744073709551615 134718136 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26006/statm: 2012 1725 146 394 0 1616 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10620

[startup+0.20536 s]
/proc/loadavg: 1.05 0.85 0.44 3/38 26006
/proc/meminfo: memFree=453868/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=9764 CPUtime=0.19
/proc/26006/stat : 26006 (cudf_msu32) R 26005 26005 25521 34816 25544 4202496 2262 0 0 0 18 1 0 0 25 0 1 0 899864583 9998336 2154 1283457024 134512640 136125367 4287576912 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26006/statm: 2441 2154 146 394 0 2045 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12336

[startup+0.305384 s]
/proc/loadavg: 1.05 0.85 0.44 3/38 26006
/proc/meminfo: memFree=453868/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=13352 CPUtime=0.29
/proc/26006/stat : 26006 (cudf_msu32) R 26005 26005 25521 34816 25544 4202496 3165 0 0 0 28 1 0 0 25 0 1 0 899864583 13672448 3057 1283457024 134512640 136125367 4287576912 18446744073709551615 134717989 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26006/statm: 3338 3057 147 394 0 2942 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 15924

[startup+0.70547 s]
/proc/loadavg: 1.05 0.85 0.44 3/38 26006
/proc/meminfo: memFree=453868/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=25560 CPUtime=0.69
/proc/26006/stat : 26006 (cudf_msu32) R 26005 26005 25521 34816 25544 4202496 6218 0 0 0 65 4 0 0 25 0 1 0 899864583 26173440 6110 1283457024 134512640 136125367 4287576912 18446744073709551615 135533302 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26006/statm: 6390 6110 147 394 0 5994 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 28132

[startup+1.50565 s]
/proc/loadavg: 1.05 0.85 0.44 2/39 26007
/proc/meminfo: memFree=419252/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=46384 CPUtime=1.48
/proc/26006/stat : 26006 (cudf_msu32) R 26005 26005 25521 34816 25544 4202496 11455 0 0 0 140 8 0 0 25 0 1 0 899864583 47497216 11298 1283457024 134512640 136125367 4287576912 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26006/statm: 11596 11298 157 394 0 11200 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 48956

[startup+3.106 s]
/proc/loadavg: 1.05 0.86 0.44 2/39 26007
/proc/meminfo: memFree=381804/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=0
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 385 0 0 0 0 0 0 0 18 0 1 0 899864583 2633728 281 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 281 240 194 0 29 0
[pid=26006] ppid=26005 vsize=74228 CPUtime=3.09
/proc/26006/stat : 26006 (cudf_msu32) R 26005 26005 25521 34816 25544 4202496 18752 0 0 0 243 66 0 0 25 0 1 0 899864583 76009472 18300 1283457024 134512640 136125367 4287576912 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/26006/statm: 18557 18300 169 394 0 18161 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 76800

[startup+6.31063 s]
/proc/loadavg: 1.05 0.86 0.44 2/39 26008
/proc/meminfo: memFree=411068/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=39256 CPUtime=3.09
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 10062 0 0 0 250 59 0 0 25 0 1 0 899864903 40198144 9098 1283457024 134512640 135887319 4290188800 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 9814 9098 138 336 0 9476 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 41828

[startup+12.7026 s]
/proc/loadavg: 1.04 0.86 0.44 2/39 26008
/proc/meminfo: memFree=395816/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=54340 CPUtime=9.46
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 15727 0 0 0 802 144 0 0 25 0 1 0 899864903 55644160 12879 1283457024 134512640 135887319 4290188800 18446744073709551615 134624367 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 13585 12879 144 336 0 13247 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 56912

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

[startup+12.8127 s]
/proc/loadavg: 1.04 0.86 0.44 2/39 26008
/proc/meminfo: memFree=395816/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=54340 CPUtime=9.57
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 15745 0 0 0 810 147 0 0 25 0 1 0 899864903 55644160 12897 1283457024 134512640 135887319 4290188800 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 13585 12897 144 336 0 13247 0
Current children cumulated CPU time (s) 12.75
Current children cumulated vsize (KiB) 56912

[startup+16.0136 s]
/proc/loadavg: 1.04 0.86 0.44 2/39 26008
/proc/meminfo: memFree=381928/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=80800 CPUtime=12.77
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 26619 0 0 0 1108 169 0 0 25 0 1 0 899864903 82739200 19580 1283457024 134512640 135887319 4290188800 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 20200 19580 144 336 0 19862 0
Current children cumulated CPU time (s) 15.95
Current children cumulated vsize (KiB) 83372

[startup+19.2047 s]
/proc/loadavg: 1.03 0.86 0.45 2/39 26008
/proc/meminfo: memFree=367172/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=82784 CPUtime=15.94
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 27215 0 0 0 1408 186 0 0 25 0 1 0 899864903 84770816 20072 1283457024 134512640 135887319 4290188800 18446744073709551615 134624367 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 20696 20072 144 336 0 20358 0
Current children cumulated CPU time (s) 19.12
Current children cumulated vsize (KiB) 85356

[startup+20.8052 s]
/proc/loadavg: 1.03 0.86 0.45 2/39 26008
/proc/meminfo: memFree=366552/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=83776 CPUtime=17.54
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 27459 0 0 0 1557 197 0 0 25 0 1 0 899864903 85786624 20316 1283457024 134512640 135887319 4290188800 18446744073709551615 134583828 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 20944 20316 144 336 0 20606 0
Current children cumulated CPU time (s) 20.72
Current children cumulated vsize (KiB) 86348

[startup+21.2054 s]
/proc/loadavg: 1.03 0.86 0.45 2/39 26008
/proc/meminfo: memFree=365808/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=83916 CPUtime=17.93
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 27518 0 0 0 1595 198 0 0 25 0 1 0 899864903 85929984 20375 1283457024 134512640 135887319 4290188800 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 20979 20375 144 336 0 20641 0
Current children cumulated CPU time (s) 21.11
Current children cumulated vsize (KiB) 86488

[startup+21.4054 s]
/proc/loadavg: 1.03 0.86 0.45 2/39 26008
/proc/meminfo: memFree=365808/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=3.18
/proc/26005/stat : 26005 (cudf2pbo4user-1) S 26004 26005 25521 34816 25544 4202496 403 18754 0 0 0 0 251 67 20 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
[pid=26008] ppid=26005 vsize=84056 CPUtime=18.13
/proc/26008/stat : 26008 (bmo-pblex32) R 26005 26005 25521 34816 25544 4202496 27537 0 0 0 1615 198 0 0 25 0 1 0 899864903 86073344 20394 1283457024 134512640 135887319 4290188800 18446744073709551615 134605912 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/26008/statm: 21014 20394 144 336 0 20676 0
Current children cumulated CPU time (s) 21.31
Current children cumulated vsize (KiB) 86628

[startup+21.5054 s]
/proc/loadavg: 1.03 0.86 0.45 2/39 26008
/proc/meminfo: memFree=365808/1048576 swapFree=2095372/2097144
[pid=26005] ppid=26004 vsize=2572 CPUtime=21.39
/proc/26005/stat : 26005 (cudf2pbo4user-1) R 26004 26005 25521 34816 25544 4202496 423 46295 0 0 0 0 1873 266 18 0 1 0 899864583 2633728 282 1283457024 134512640 135304128 4290913808 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/26005/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 21.39
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 21.6053
CPU time (s): 21.5093
CPU user time (s): 18.8332
CPU system time (s): 2.67617
CPU usage (%): 99.5556
Max. virtual memory (cumulated for all children) (KiB): 86628

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.8332
system time used= 2.67617
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49129
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= 30
involuntary context switches= 3036

runsolver used 0 second user time and 0 second system time

The end