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/rand97.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand97.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand97.cudf.user-upgrades.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.15 1.12 1.10 4/34 26761
/proc/meminfo: memFree=334788/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=3716 CPUtime=0
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 430 0 0 0 0 0 0 0 25 0 1 0 4838363 3805184 359 1283457024 134512640 134752139 4290041152 18446744073709551615 134706552 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 929 359 286 59 0 93 0

[startup+0.195563 s]
/proc/loadavg: 1.15 1.12 1.10 4/34 26761
/proc/meminfo: memFree=334788/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=9540 CPUtime=0.19
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 1890 0 0 0 18 1 0 0 25 0 1 0 4838363 9768960 1819 1283457024 134512640 134752139 4290041152 18446744073709551615 134694880 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 2385 1819 286 59 0 1549 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12108

[startup+0.215577 s]
/proc/loadavg: 1.15 1.12 1.10 4/34 26761
/proc/meminfo: memFree=334788/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=10068 CPUtime=0.21
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 2017 0 0 0 20 1 0 0 25 0 1 0 4838363 10309632 1946 1283457024 134512640 134752139 4290041152 18446744073709551615 134681751 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 2517 1946 286 59 0 1681 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12636

[startup+0.315594 s]
/proc/loadavg: 1.15 1.12 1.10 4/34 26761
/proc/meminfo: memFree=334788/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=12600 CPUtime=0.31
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 2650 0 0 0 30 1 0 0 25 0 1 0 4838363 12902400 2579 1283457024 134512640 134752139 4290041152 18446744073709551615 4156947703 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 3150 2579 286 59 0 2314 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15168

[startup+0.715671 s]
/proc/loadavg: 1.15 1.12 1.10 4/34 26761
/proc/meminfo: memFree=334788/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=21788 CPUtime=0.72
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 4947 0 0 0 70 2 0 0 25 0 1 0 4838363 22310912 4876 1283457024 134512640 134752139 4290041152 18446744073709551615 134683324 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 5447 4876 286 59 0 4611 0
Current children cumulated CPU time (s) 0.72
Current children cumulated vsize (KiB) 24356

[startup+1.51585 s]
/proc/loadavg: 1.15 1.12 1.10 2/35 26762
/proc/meminfo: memFree=308364/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46272 CPUtime=1.51
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 10955 0 0 0 145 6 0 0 25 0 1 0 4838363 47382528 10835 1283457024 134512640 134752139 4290041152 18446744073709551615 134664365 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 11568 10835 320 59 0 10732 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 48840

[startup+3.10619 s]
/proc/loadavg: 1.15 1.12 1.10 2/37 26764
/proc/meminfo: memFree=280680/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46100 CPUtime=3.02
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11168 8191 0 0 167 25 97 13 18 0 1 0 4838363 47206400 10846 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11525 10846 333 59 0 10689 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 48668

[startup+6.30698 s]
/proc/loadavg: 1.14 1.12 1.10 2/37 26768
/proc/meminfo: memFree=272256/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46104 CPUtime=4.6
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11246 20396 0 0 175 39 215 31 18 0 1 0 4838363 47210496 10852 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11526 10852 333 59 0 10690 0
[pid=26767] ppid=26761 vsize=1672 CPUtime=0
/proc/26767/stat : 26767 (sh) S 26761 26760 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4838825 1712128 123 1283457024 134512640 134593992 4294445600 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26767/statm: 418 123 108 20 0 45 0
[pid=26768] ppid=26767 vsize=45372 CPUtime=1.68
/proc/26768/stat : 26768 (minisatp_32) R 26767 26760 1511 34817 1511 4202496 15138 0 0 0 158 10 0 0 25 0 1 0 4838825 46460928 10133 1283457024 134512640 135413687 4290174512 18446744073709551615 134686454 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26768/statm: 11343 10133 94 220 0 11121 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 95716

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

[startup+6.40701 s]
/proc/loadavg: 1.14 1.12 1.10 2/37 26768
/proc/meminfo: memFree=272256/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46104 CPUtime=4.6
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11246 20396 0 0 175 39 215 31 18 0 1 0 4838363 47210496 10852 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11526 10852 333 59 0 10690 0
[pid=26767] ppid=26761 vsize=1672 CPUtime=0
/proc/26767/stat : 26767 (sh) S 26761 26760 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4838825 1712128 123 1283457024 134512640 134593992 4294445600 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26767/statm: 418 123 108 20 0 45 0
[pid=26768] ppid=26767 vsize=43720 CPUtime=1.78
/proc/26768/stat : 26768 (minisatp_32) R 26767 26760 1511 34817 1511 4202496 15298 0 0 0 168 10 0 0 25 0 1 0 4838825 44769280 9816 1283457024 134512640 135413687 4290174512 18446744073709551615 134688847 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26768/statm: 10930 9816 94 220 0 10708 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 94064

[startup+9.60888 s]
/proc/loadavg: 1.14 1.12 1.10 2/37 26770
/proc/meminfo: memFree=265808/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46108 CPUtime=7.76
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11314 44204 0 0 184 52 494 46 18 0 1 0 4838363 47214592 10853 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11527 10853 333 59 0 10691 0
[pid=26769] ppid=26761 vsize=1672 CPUtime=0.01
/proc/26769/stat : 26769 (sh) S 26761 26760 1511 34817 1511 4202496 146 0 0 0 1 0 0 0 18 0 1 0 4839141 1712128 124 1283457024 134512640 134593992 4293015744 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26769/statm: 418 124 108 20 0 45 0
[pid=26770] ppid=26769 vsize=68692 CPUtime=1.81
/proc/26770/stat : 26770 (minisatp_32) R 26769 26760 1511 34817 1511 4202496 20484 0 0 0 172 9 0 0 25 0 1 0 4839142 70340608 15030 1283457024 134512640 135413687 4287704016 18446744073709551615 134688839 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26770/statm: 17173 15030 94 220 0 16951 0
Current children cumulated CPU time (s) 9.58
Current children cumulated vsize (KiB) 119040

[startup+11.2094 s]
/proc/loadavg: 1.13 1.12 1.10 2/37 26770
/proc/meminfo: memFree=197236/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46108 CPUtime=7.76
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11314 44204 0 0 184 52 494 46 18 0 1 0 4838363 47214592 10853 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11527 10853 333 59 0 10691 0
[pid=26769] ppid=26761 vsize=1672 CPUtime=0.01
/proc/26769/stat : 26769 (sh) S 26761 26760 1511 34817 1511 4202496 146 0 0 0 1 0 0 0 18 0 1 0 4839141 1712128 124 1283457024 134512640 134593992 4293015744 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26769/statm: 418 124 108 20 0 45 0
[pid=26770] ppid=26769 vsize=119620 CPUtime=3.41
/proc/26770/stat : 26770 (minisatp_32) R 26769 26760 1511 34817 1511 4202496 35801 0 0 0 319 22 0 0 25 0 1 0 4839142 122490880 25151 1283457024 134512640 135413687 4287704016 18446744073709551615 134686528 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26770/statm: 29905 25151 107 220 0 29683 0
Current children cumulated CPU time (s) 11.18
Current children cumulated vsize (KiB) 169968

[startup+12.0098 s]
/proc/loadavg: 1.13 1.12 1.10 2/37 26770
/proc/meminfo: memFree=197236/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46108 CPUtime=7.76
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11314 44204 0 0 184 52 494 46 18 0 1 0 4838363 47214592 10853 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11527 10853 333 59 0 10691 0
[pid=26769] ppid=26761 vsize=1672 CPUtime=0.01
/proc/26769/stat : 26769 (sh) S 26761 26760 1511 34817 1511 4202496 146 0 0 0 1 0 0 0 18 0 1 0 4839141 1712128 124 1283457024 134512640 134593992 4293015744 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26769/statm: 418 124 108 20 0 45 0
[pid=26770] ppid=26769 vsize=121760 CPUtime=4.21
/proc/26770/stat : 26770 (minisatp_32) R 26769 26760 1511 34817 1511 4202496 39542 0 0 0 397 24 0 0 25 0 1 0 4839142 124682240 26185 1283457024 134512640 135413687 4287704016 18446744073709551615 134962843 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26770/statm: 30440 26185 107 220 0 30218 0
Current children cumulated CPU time (s) 11.98
Current children cumulated vsize (KiB) 172108

[startup+12.4099 s]
/proc/loadavg: 1.13 1.12 1.10 2/37 26770
/proc/meminfo: memFree=184960/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=46108 CPUtime=7.76
/proc/26761/stat : 26761 (packup) S 26760 26760 1511 34817 1511 4202496 11314 44204 0 0 184 52 494 46 18 0 1 0 4838363 47214592 10853 1283457024 134512640 134752139 4290041152 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26761/statm: 11527 10853 333 59 0 10691 0
[pid=26769] ppid=26761 vsize=1672 CPUtime=0.01
/proc/26769/stat : 26769 (sh) S 26761 26760 1511 34817 1511 4202496 146 0 0 0 1 0 0 0 18 0 1 0 4839141 1712128 124 1283457024 134512640 134593992 4293015744 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26769/statm: 418 124 108 20 0 45 0
[pid=26770] ppid=26769 vsize=116152 CPUtime=4.61
/proc/26770/stat : 26770 (minisatp_32) R 26769 26760 1511 34817 1511 4202496 39896 0 0 0 436 25 0 0 25 0 1 0 4839142 118939648 25153 1283457024 134512640 135413687 4287704016 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26770/statm: 29038 25153 117 220 0 28816 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 166500

[startup+12.5099 s]
/proc/loadavg: 1.13 1.12 1.10 2/37 26770
/proc/meminfo: memFree=184960/1048576 swapFree=0/0
[pid=26760] ppid=26759 vsize=2568 CPUtime=0
/proc/26760/stat : 26760 (packup2mp4tr-0.) S 26759 26760 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4838363 2629632 274 1283457024 134512640 135304128 4287412976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26760/statm: 642 274 233 194 0 29 0
[pid=26761] ppid=26760 vsize=45140 CPUtime=12.49
/proc/26761/stat : 26761 (packup) R 26760 26760 1511 34817 1511 4202496 20731 84249 0 0 191 53 932 73 18 0 1 0 4838363 46223360 10624 1283457024 134512640 134752139 4290041152 18446744073709551615 134536317 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26761/statm: 11285 10624 346 59 0 10449 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 47708

Child status: 0
Real time (s): 12.5468
CPU time (s): 12.5328
CPU user time (s): 11.2647
CPU system time (s): 1.26808
CPU usage (%): 99.8887
Max. virtual memory (cumulated for all children) (KiB): 183108

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.2647
system time used= 1.26808
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 106060
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= 19
involuntary context switches= 225

runsolver used 0 second user time and 0 second system time

The end