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/201108241238/packup2mp4tr-0.6/5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf.dudf-real.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.25 1.18 1.11 4/34 24535
/proc/meminfo: memFree=364864/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=3716 CPUtime=0
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 403 0 0 0 0 0 0 0 25 0 1 0 4732217 3805184 332 1283457024 134512640 134752139 4292962272 18446744073709551615 134681682 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 929 332 286 59 0 93 0

[startup+0.143494 s]
/proc/loadavg: 1.25 1.18 1.11 4/34 24535
/proc/meminfo: memFree=364864/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=8616 CPUtime=0.14
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 1634 0 0 0 12 2 0 0 25 0 1 0 4732217 8822784 1563 1283457024 134512640 134752139 4292962272 18446744073709551615 134682182 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 2154 1563 286 59 0 1318 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 11188

[startup+0.213511 s]
/proc/loadavg: 1.25 1.18 1.11 4/34 24535
/proc/meminfo: memFree=364864/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=10728 CPUtime=0.21
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 2161 0 0 0 19 2 0 0 25 0 1 0 4732217 10985472 2090 1283457024 134512640 134752139 4292962272 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 2682 2090 286 59 0 1846 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13300

[startup+0.303531 s]
/proc/loadavg: 1.25 1.18 1.11 4/34 24535
/proc/meminfo: memFree=364864/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=13220 CPUtime=0.3
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 2784 0 0 0 28 2 0 0 25 0 1 0 4732217 13537280 2713 1283457024 134512640 134752139 4292962272 18446744073709551615 134681812 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 3305 2713 286 59 0 2469 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15792

[startup+0.703623 s]
/proc/loadavg: 1.25 1.18 1.11 4/34 24535
/proc/meminfo: memFree=364864/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=23200 CPUtime=0.7
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 5294 0 0 0 67 3 0 0 25 0 1 0 4732217 23756800 5223 1283457024 134512640 134752139 4292962272 18446744073709551615 134705846 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 5800 5223 286 59 0 4964 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 25772

[startup+1.5038 s]
/proc/loadavg: 1.23 1.18 1.11 2/35 24536
/proc/meminfo: memFree=334100/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50832 CPUtime=1.5
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 12352 0 0 0 138 12 0 0 25 0 1 0 4732217 52051968 11935 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 12708 11935 322 59 0 11872 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 53404

[startup+3.10413 s]
/proc/loadavg: 1.23 1.18 1.11 2/37 24538
/proc/meminfo: memFree=305424/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50832 CPUtime=1.76
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12356 0 0 0 145 31 0 0 25 0 1 0 4732217 52051968 11938 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12708 11938 325 59 0 11872 0
[pid=24537] ppid=24535 vsize=1676 CPUtime=0.01
/proc/24537/stat : 24537 (sh) S 24535 24534 1511 34817 1511 4202496 147 0 0 0 0 1 0 0 25 0 1 0 4732393 1716224 124 1283457024 134512640 134593992 4287034128 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/24537/statm: 419 124 108 20 0 46 0
[pid=24538] ppid=24537 vsize=32508 CPUtime=1.32
/proc/24538/stat : 24538 (minisatp_32) R 24537 24534 1511 34817 1511 4202496 7656 0 0 0 127 5 0 0 25 0 1 0 4732395 33288192 6841 1283457024 134512640 135413687 4286722784 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/24538/statm: 8127 6841 85 220 0 7905 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 87588

[startup+6.3054 s]
/proc/loadavg: 1.23 1.18 1.11 2/35 24538
/proc/meminfo: memFree=315128/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50836 CPUtime=5.51
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12451 27805 0 0 162 53 306 30 18 0 1 0 4732217 52056064 11957 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12709 11957 333 59 0 11873 0
Current children cumulated CPU time (s) 5.51
Current children cumulated vsize (KiB) 53408

[startup+12.7074 s]
/proc/loadavg: 1.20 1.17 1.11 2/37 24540
/proc/meminfo: memFree=130592/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50836 CPUtime=5.51
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12451 27805 0 0 162 53 306 30 18 0 1 0 4732217 52056064 11957 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12709 11957 333 59 0 11873 0
[pid=24539] ppid=24535 vsize=1676 CPUtime=0
/proc/24539/stat : 24539 (sh) S 24535 24534 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 4732769 1716224 124 1283457024 134512640 134593992 4288861392 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/24539/statm: 419 124 108 20 0 46 0
[pid=24540] ppid=24539 vsize=201664 CPUtime=7.18
/proc/24540/stat : 24540 (minisatp_32) R 24539 24534 1511 34817 1511 4202496 65850 0 0 0 670 48 0 0 25 0 1 0 4732770 206503936 44527 1283457024 134512640 135413687 4287560624 18446744073709551615 134688058 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/24540/statm: 50416 44527 107 220 0 50194 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 256748

[startup+25.5099 s]
/proc/loadavg: 1.24 1.18 1.11 2/37 24544
/proc/meminfo: memFree=188996/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50844 CPUtime=20.28
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12662 146034 0 0 192 104 1602 130 18 0 1 0 4732217 52064256 11970 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12711 11970 333 59 0 11875 0
[pid=24543] ppid=24535 vsize=1676 CPUtime=0
/proc/24543/stat : 24543 (sh) S 24535 24534 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4734256 1716224 124 1283457024 134512640 134593992 4291717008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/24543/statm: 419 124 108 20 0 46 0
[pid=24544] ppid=24543 vsize=137724 CPUtime=5.11
/proc/24544/stat : 24544 (minisatp_32) R 24543 24534 1511 34817 1511 4202496 47757 0 0 0 474 37 0 0 25 0 1 0 4734257 141029376 30988 1283457024 134512640 135413687 4287603648 18446744073709551615 134689964 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/24544/statm: 34431 30988 94 220 0 34209 0
Current children cumulated CPU time (s) 25.39
Current children cumulated vsize (KiB) 192816

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

[startup+25.61 s]
/proc/loadavg: 1.24 1.18 1.11 2/37 24544
/proc/meminfo: memFree=188996/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50844 CPUtime=20.28
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12662 146034 0 0 192 104 1602 130 18 0 1 0 4732217 52064256 11970 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12711 11970 333 59 0 11875 0
[pid=24543] ppid=24535 vsize=1676 CPUtime=0
/proc/24543/stat : 24543 (sh) S 24535 24534 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4734256 1716224 124 1283457024 134512640 134593992 4291717008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/24543/statm: 419 124 108 20 0 46 0
[pid=24544] ppid=24543 vsize=135020 CPUtime=5.21
/proc/24544/stat : 24544 (minisatp_32) R 24543 24534 1511 34817 1511 4202496 48256 0 0 0 483 38 0 0 25 0 1 0 4734257 138260480 30666 1283457024 134512640 135413687 4287603648 18446744073709551615 134992593 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/24544/statm: 33755 30666 94 220 0 33533 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 190112

[startup+26.4101 s]
/proc/loadavg: 1.22 1.18 1.11 2/37 24544
/proc/meminfo: memFree=172752/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50844 CPUtime=20.28
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12662 146034 0 0 192 104 1602 130 18 0 1 0 4732217 52064256 11970 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12711 11970 333 59 0 11875 0
[pid=24543] ppid=24535 vsize=1676 CPUtime=0
/proc/24543/stat : 24543 (sh) S 24535 24534 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4734256 1716224 124 1283457024 134512640 134593992 4291717008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/24543/statm: 419 124 108 20 0 46 0
[pid=24544] ppid=24543 vsize=162224 CPUtime=6
/proc/24544/stat : 24544 (minisatp_32) R 24543 24534 1511 34817 1511 4202496 54230 0 0 0 562 38 0 0 25 0 1 0 4734257 166117376 35307 1283457024 134512640 135413687 4287603648 18446744073709551615 134699559 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/24544/statm: 40556 35307 107 220 0 40334 0
Current children cumulated CPU time (s) 26.28
Current children cumulated vsize (KiB) 217316

[startup+27.2103 s]
/proc/loadavg: 1.22 1.18 1.11 2/37 24544
/proc/meminfo: memFree=172752/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=50844 CPUtime=20.28
/proc/24535/stat : 24535 (packup) S 24534 24534 1511 34817 1511 4202496 12662 146034 0 0 192 104 1602 130 18 0 1 0 4732217 52064256 11970 1283457024 134512640 134752139 4292962272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/24535/statm: 12711 11970 333 59 0 11875 0
[pid=24543] ppid=24535 vsize=1676 CPUtime=0
/proc/24543/stat : 24543 (sh) S 24535 24534 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4734256 1716224 124 1283457024 134512640 134593992 4291717008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/24543/statm: 419 124 108 20 0 46 0
[pid=24544] ppid=24543 vsize=173532 CPUtime=6.8
/proc/24544/stat : 24544 (minisatp_32) R 24543 24534 1511 34817 1511 4202496 57798 0 0 0 638 42 0 0 25 0 1 0 4734257 177696768 36950 1283457024 134512640 135413687 4287603648 18446744073709551615 134649462 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/24544/statm: 43383 36950 108 220 0 43161 0
Current children cumulated CPU time (s) 27.08
Current children cumulated vsize (KiB) 228624

[startup+27.603 s]
/proc/loadavg: 1.22 1.18 1.11 2/35 24544
/proc/meminfo: memFree=316376/1048576 swapFree=0/0
[pid=24534] ppid=24533 vsize=2572 CPUtime=0
/proc/24534/stat : 24534 (packup2mp4tr-0.) S 24533 24534 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4732217 2633728 275 1283457024 134512640 135304128 4291471008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/24534/statm: 643 275 233 194 0 30 0
[pid=24535] ppid=24534 vsize=49680 CPUtime=27.48
/proc/24535/stat : 24535 (packup) R 24534 24534 1511 34817 1511 4202496 23006 204075 0 0 202 108 2262 176 18 0 1 0 4732217 50872320 11692 1283457024 134512640 134752139 4292962272 18446744073709551615 4157822385 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/24535/statm: 12420 11692 346 59 0 11584 0
Current children cumulated CPU time (s) 27.48
Current children cumulated vsize (KiB) 52252

Child status: 0
Real time (s): 27.6323
CPU time (s): 27.5257
CPU user time (s): 24.6655
CPU system time (s): 2.86018
CPU usage (%): 99.6142
Max. virtual memory (cumulated for all children) (KiB): 271068

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 24.6655
system time used= 2.86018
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 228002
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= 21
involuntary context switches= 411

runsolver used 0 second user time and 0 second system time

The end