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/201108251442/packup2mp4pa-0.6/rand461.cudf.dudf-random.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-random//rand461.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand461.cudf.dudf-random.result 

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.32 1.16 1.05 4/36 17947
/proc/meminfo: memFree=319612/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=3716 CPUtime=0.01
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 432 0 0 0 1 0 0 0 25 0 1 0 11087162 3805184 361 1283457024 134512640 134752139 4290670048 18446744073709551615 134681833 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 929 361 286 59 0 93 0

[startup+0.186068 s]
/proc/loadavg: 1.32 1.16 1.05 4/36 17947
/proc/meminfo: memFree=319612/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=9564 CPUtime=0.18
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 1889 0 0 0 17 1 0 0 25 0 1 0 11087162 9793536 1818 1283457024 134512640 134752139 4290670048 18446744073709551615 134682090 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 2391 1818 286 59 0 1555 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12136

[startup+0.206083 s]
/proc/loadavg: 1.32 1.16 1.05 4/36 17947
/proc/meminfo: memFree=319612/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=10092 CPUtime=0.2
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 2027 0 0 0 19 1 0 0 25 0 1 0 11087162 10334208 1956 1283457024 134512640 134752139 4290670048 18446744073709551615 134681676 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 2523 1956 286 59 0 1687 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12664

[startup+0.306102 s]
/proc/loadavg: 1.32 1.16 1.05 4/36 17947
/proc/meminfo: memFree=319612/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=12848 CPUtime=0.3
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 2703 0 0 0 28 2 0 0 25 0 1 0 11087162 13156352 2632 1283457024 134512640 134752139 4290670048 18446744073709551615 134681682 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 3212 2632 286 59 0 2376 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15420

[startup+0.706636 s]
/proc/loadavg: 1.32 1.16 1.05 4/36 17947
/proc/meminfo: memFree=319612/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=22680 CPUtime=0.7
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 5151 0 0 0 67 3 0 0 25 0 1 0 11087162 23224320 5080 1283457024 134512640 134752139 4290670048 18446744073709551615 4157229609 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 5670 5080 286 59 0 4834 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 25252

[startup+1.50683 s]
/proc/loadavg: 1.29 1.15 1.04 2/37 17948
/proc/meminfo: memFree=291800/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=47356 CPUtime=1.5
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 11395 0 0 0 146 4 0 0 25 0 1 0 11087162 48492544 11275 1283457024 134512640 134752139 4290670048 18446744073709551615 4157408654 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 11839 11275 316 59 0 11003 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 49928

[startup+3.10714 s]
/proc/loadavg: 1.29 1.15 1.04 2/39 17950
/proc/meminfo: memFree=262504/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51068 CPUtime=1.84
/proc/17947/stat : 17947 (packup) S 17946 17946 4778 34817 4778 4202496 12339 0 0 0 163 21 0 0 25 0 1 0 11087162 52293632 12015 1283457024 134512640 134752139 4290670048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17947/statm: 12767 12015 324 59 0 11931 0
[pid=17949] ppid=17947 vsize=1676 CPUtime=0.01
/proc/17949/stat : 17949 (sh) S 17947 17946 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 25 0 1 0 11087346 1716224 124 1283457024 134512640 134593992 4289250608 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17949/statm: 419 124 108 20 0 46 0
[pid=17950] ppid=17949 vsize=30192 CPUtime=1.24
/proc/17950/stat : 17950 (minisatp_32) R 17949 17946 4778 34817 4778 4202496 7270 0 0 0 108 16 0 0 25 0 1 0 11087348 30916608 6482 1283457024 134512640 135413687 4294164992 18446744073709551615 134961561 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17950/statm: 7548 6482 85 220 0 7326 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 85508

[startup+6.30702 s]
/proc/loadavg: 1.27 1.15 1.04 2/39 17951
/proc/meminfo: memFree=197900/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51072 CPUtime=6.2
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 12414 32799 0 0 172 30 384 34 18 0 1 0 11087162 52297728 12024 1283457024 134512640 134752139 4290670048 18446744073709551615 4159120758 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 12768 12024 332 59 0 11932 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 53644

[startup+12.7088 s]
/proc/loadavg: 1.25 1.15 1.04 2/39 17953
/proc/meminfo: memFree=143720/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51072 CPUtime=6.31
/proc/17947/stat : 17947 (packup) S 17946 17946 4778 34817 4778 4202496 12415 32799 0 0 181 32 384 34 18 0 1 0 11087162 52297728 12024 1283457024 134512640 134752139 4290670048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17947/statm: 12768 12024 332 59 0 11932 0
[pid=17952] ppid=17947 vsize=1672 CPUtime=0
/proc/17952/stat : 17952 (sh) S 17947 17946 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11087804 1712128 124 1283457024 134512640 134593992 4291891120 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17952/statm: 418 124 108 20 0 45 0
[pid=17953] ppid=17952 vsize=142864 CPUtime=6.27
/proc/17953/stat : 17953 (minisatp_32) R 17952 17946 4778 34817 4778 4202496 47384 0 0 0 592 35 0 0 25 0 1 0 11087805 146292736 32366 1283457024 134512640 135413687 4288707792 18446744073709551615 134962799 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17953/statm: 35716 32366 107 220 0 35494 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 198180

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

[startup+12.8088 s]
/proc/loadavg: 1.25 1.15 1.04 2/39 17953
/proc/meminfo: memFree=143720/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51072 CPUtime=6.31
/proc/17947/stat : 17947 (packup) S 17946 17946 4778 34817 4778 4202496 12415 32799 0 0 181 32 384 34 18 0 1 0 11087162 52297728 12024 1283457024 134512640 134752139 4290670048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17947/statm: 12768 12024 332 59 0 11932 0
[pid=17952] ppid=17947 vsize=1672 CPUtime=0
/proc/17952/stat : 17952 (sh) S 17947 17946 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11087804 1712128 124 1283457024 134512640 134593992 4291891120 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17952/statm: 418 124 108 20 0 45 0
[pid=17953] ppid=17952 vsize=143276 CPUtime=6.37
/proc/17953/stat : 17953 (minisatp_32) R 17952 17946 4778 34817 4778 4202496 47661 0 0 0 602 35 0 0 25 0 1 0 11087805 146714624 32624 1283457024 134512640 135413687 4288707792 18446744073709551615 134689179 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17953/statm: 35819 32624 107 220 0 35597 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 198592

[startup+14.4093 s]
/proc/loadavg: 1.25 1.15 1.04 2/38 17953
/proc/meminfo: memFree=119804/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51072 CPUtime=6.31
/proc/17947/stat : 17947 (packup) S 17946 17946 4778 34817 4778 4202496 12415 32799 0 0 181 32 384 34 18 0 1 0 11087162 52297728 12024 1283457024 134512640 134752139 4290670048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17947/statm: 12768 12024 332 59 0 11932 0
[pid=17952] ppid=17947 vsize=1672 CPUtime=0
/proc/17952/stat : 17952 (sh) S 17947 17946 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11087804 1712128 124 1283457024 134512640 134593992 4291891120 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17952/statm: 418 124 108 20 0 45 0
[pid=17953] ppid=17952 vsize=161100 CPUtime=7.97
/proc/17953/stat : 17953 (minisatp_32) R 17952 17946 4778 34817 4778 4202496 59013 0 0 0 758 39 0 0 25 0 1 0 11087805 164966400 37164 1283457024 134512640 135413687 4288707792 18446744073709551615 134653871 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17953/statm: 40275 37164 112 220 0 40053 0
Current children cumulated CPU time (s) 14.28
Current children cumulated vsize (KiB) 216416

[startup+14.8094 s]
/proc/loadavg: 1.25 1.15 1.04 2/38 17953
/proc/meminfo: memFree=119804/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51072 CPUtime=6.31
/proc/17947/stat : 17947 (packup) S 17946 17946 4778 34817 4778 4202496 12415 32799 0 0 181 32 384 34 18 0 1 0 11087162 52297728 12024 1283457024 134512640 134752139 4290670048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17947/statm: 12768 12024 332 59 0 11932 0
[pid=17952] ppid=17947 vsize=1672 CPUtime=0
/proc/17952/stat : 17952 (sh) S 17947 17946 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11087804 1712128 124 1283457024 134512640 134593992 4291891120 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17952/statm: 418 124 108 20 0 45 0
[pid=17953] ppid=17952 vsize=193640 CPUtime=8.36
/proc/17953/stat : 17953 (minisatp_32) R 17952 17946 4778 34817 4778 4202496 63343 0 0 0 794 42 0 0 25 0 1 0 11087805 198287360 41056 1283457024 134512640 135413687 4288707792 18446744073709551615 134705601 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17953/statm: 48410 41056 108 220 0 48188 0
Current children cumulated CPU time (s) 14.67
Current children cumulated vsize (KiB) 248956

[startup+15.0094 s]
/proc/loadavg: 1.25 1.15 1.04 2/38 17953
/proc/meminfo: memFree=119804/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=51072 CPUtime=6.31
/proc/17947/stat : 17947 (packup) S 17946 17946 4778 34817 4778 4202496 12415 32799 0 0 181 32 384 34 18 0 1 0 11087162 52297728 12024 1283457024 134512640 134752139 4290670048 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17947/statm: 12768 12024 332 59 0 11932 0
[pid=17952] ppid=17947 vsize=1672 CPUtime=0
/proc/17952/stat : 17952 (sh) S 17947 17946 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11087804 1712128 124 1283457024 134512640 134593992 4291891120 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17952/statm: 418 124 108 20 0 45 0
[pid=17953] ppid=17952 vsize=184456 CPUtime=8.57
/proc/17953/stat : 17953 (minisatp_32) R 17952 17946 4778 34817 4778 4202496 64258 0 0 0 813 44 0 0 25 0 1 0 11087805 188882944 39235 1283457024 134512640 135413687 4288707792 18446744073709551615 134597327 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17953/statm: 46114 39235 117 220 0 45892 0
Current children cumulated CPU time (s) 14.88
Current children cumulated vsize (KiB) 239772

[startup+15.1094 s]
/proc/loadavg: 1.25 1.15 1.04 2/38 17953
/proc/meminfo: memFree=119804/1048576 swapFree=0/0
[pid=17946] ppid=17945 vsize=2572 CPUtime=0
/proc/17946/stat : 17946 (packup2mp4pa-0.) S 17945 17946 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11087162 2633728 274 1283457024 134512640 135304128 4292226960 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17946/statm: 643 274 233 194 0 30 0
[pid=17947] ppid=17946 vsize=50300 CPUtime=14.99
/proc/17947/stat : 17947 (packup) R 17946 17946 4778 34817 4778 4202496 20014 97206 0 0 185 36 1198 80 18 0 1 0 11087162 51507200 11844 1283457024 134512640 134752139 4290670048 18446744073709551615 134622679 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17947/statm: 12575 11844 345 59 0 11739 0
Current children cumulated CPU time (s) 14.99
Current children cumulated vsize (KiB) 52872

Child status: 0
Real time (s): 15.1868
CPU time (s): 15.0809
CPU user time (s): 13.9089
CPU system time (s): 1.17207
CPU usage (%): 99.303
Max. virtual memory (cumulated for all children) (KiB): 253312

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.9089
system time used= 1.17207
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 121058
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= 13
involuntary context switches= 237

runsolver used 0 second user time and 0 second system time

The end