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/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//4a69cf16-c731-11df-9182-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/4a69cf16-c731-11df-9182-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.47 1.38 1.18 4/36 20595
/proc/meminfo: memFree=292668/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=3432 CPUtime=0
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4194304 208 0 0 0 0 0 0 0 25 0 1 0 11126010 3514368 144 1283457024 134512640 134752139 4293779616 18446744073709551615 4160396208 0 0 0 0 0 0 0 17 0 0 0 0
/proc/20595/statm: 858 144 120 59 0 18 0

[startup+0.122862 s]
/proc/loadavg: 1.47 1.38 1.18 4/36 20595
/proc/meminfo: memFree=292668/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=7684 CPUtime=0.12
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202496 1422 0 0 0 12 0 0 0 25 0 1 0 11126010 7868416 1351 1283457024 134512640 134752139 4293779616 18446744073709551615 134694870 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 1921 1351 286 59 0 1085 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 10256

[startup+0.212877 s]
/proc/loadavg: 1.47 1.38 1.18 4/36 20595
/proc/meminfo: memFree=292668/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=10456 CPUtime=0.21
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202496 2110 0 0 0 21 0 0 0 25 0 1 0 11126010 10706944 2039 1283457024 134512640 134752139 4293779616 18446744073709551615 134681672 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 2614 2039 286 59 0 1778 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13028

[startup+0.302896 s]
/proc/loadavg: 1.47 1.38 1.18 4/36 20595
/proc/meminfo: memFree=292668/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=12948 CPUtime=0.3
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202496 2742 0 0 0 30 0 0 0 25 0 1 0 11126010 13258752 2671 1283457024 134512640 134752139 4293779616 18446744073709551615 134681513 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 3237 2671 286 59 0 2401 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15520

[startup+0.702966 s]
/proc/loadavg: 1.47 1.38 1.18 4/36 20595
/proc/meminfo: memFree=292668/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=23192 CPUtime=0.7
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202496 5291 0 0 0 69 1 0 0 25 0 1 0 11126010 23748608 5220 1283457024 134512640 134752139 4293779616 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 5798 5220 286 59 0 4962 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 25764

[startup+1.5031 s]
/proc/loadavg: 1.47 1.38 1.18 2/37 20596
/proc/meminfo: memFree=262028/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47708 CPUtime=1.5
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202496 11561 0 0 0 136 14 0 0 25 0 1 0 11126010 48852992 11175 1283457024 134512640 134752139 4293779616 18446744073709551615 4159355645 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 11927 11175 321 59 0 11091 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 50280

[startup+3.10706 s]
/proc/loadavg: 1.43 1.37 1.18 2/39 20598
/proc/meminfo: memFree=234096/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47708 CPUtime=1.64
/proc/20595/stat : 20595 (packup) S 20594 20594 4778 34817 4778 4202496 11566 0 0 0 141 23 0 0 25 0 1 0 11126010 48852992 11178 1283457024 134512640 134752139 4293779616 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20595/statm: 11927 11178 324 59 0 11091 0
[pid=20597] ppid=20595 vsize=1668 CPUtime=0
/proc/20597/stat : 20597 (sh) S 20595 20594 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 25 0 1 0 11126173 1708032 123 1283457024 134512640 134593992 4294392352 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20597/statm: 417 123 108 20 0 44 0
[pid=20598] ppid=20597 vsize=31744 CPUtime=1.31
/proc/20598/stat : 20598 (minisatp_32) R 20597 20594 4778 34817 4778 4202496 7690 0 0 0 114 17 0 0 25 0 1 0 11126175 32505856 6802 1283457024 134512640 135413687 4292134928 18446744073709551615 134686248 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20598/statm: 7936 6802 85 220 0 7714 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 83692

[startup+6.30758 s]
/proc/loadavg: 1.43 1.37 1.18 2/39 20601
/proc/meminfo: memFree=238940/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47712 CPUtime=5.04
/proc/20595/stat : 20595 (packup) S 20594 20594 4778 34817 4778 4202496 11644 27388 0 0 150 46 279 29 18 0 1 0 11126010 48857088 11187 1283457024 134512640 134752139 4293779616 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20595/statm: 11928 11187 332 59 0 11092 0
[pid=20599] ppid=20595 vsize=1672 CPUtime=0
/proc/20599/stat : 20599 (sh) S 20595 20594 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 19 0 1 0 11126530 1712128 124 1283457024 134512640 134593992 4290487904 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20599/statm: 418 124 108 20 0 45 0
[pid=20600] ppid=20599 vsize=27940 CPUtime=1.09
/proc/20600/stat : 20600 (minisatp_32) R 20599 20594 4778 34817 4778 4202496 6209 0 0 0 107 2 0 0 24 0 1 0 11126531 28610560 5665 1283457024 134512640 135413687 4294492752 18446744073709551615 134960810 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20600/statm: 6985 5665 77 220 0 6763 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 79896

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

[startup+6.40761 s]
/proc/loadavg: 1.43 1.37 1.18 2/39 20601
/proc/meminfo: memFree=238940/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47712 CPUtime=5.04
/proc/20595/stat : 20595 (packup) S 20594 20594 4778 34817 4778 4202496 11644 27388 0 0 150 46 279 29 18 0 1 0 11126010 48857088 11187 1283457024 134512640 134752139 4293779616 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20595/statm: 11928 11187 332 59 0 11092 0
[pid=20599] ppid=20595 vsize=1672 CPUtime=0
/proc/20599/stat : 20599 (sh) S 20595 20594 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 19 0 1 0 11126530 1712128 124 1283457024 134512640 134593992 4290487904 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20599/statm: 418 124 108 20 0 45 0
[pid=20600] ppid=20599 vsize=30140 CPUtime=1.2
/proc/20600/stat : 20600 (minisatp_32) R 20599 20594 4778 34817 4778 4202496 6907 0 0 0 114 6 0 0 24 0 1 0 11126531 30863360 6227 1283457024 134512640 135413687 4294492752 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20600/statm: 7535 6227 85 220 0 7313 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 82096

[startup+8.00787 s]
/proc/loadavg: 1.40 1.37 1.18 2/39 20601
/proc/meminfo: memFree=147924/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47712 CPUtime=5.04
/proc/20595/stat : 20595 (packup) S 20594 20594 4778 34817 4778 4202496 11644 27388 0 0 150 46 279 29 18 0 1 0 11126010 48857088 11187 1283457024 134512640 134752139 4293779616 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20595/statm: 11928 11187 332 59 0 11092 0
[pid=20599] ppid=20595 vsize=1672 CPUtime=0
/proc/20599/stat : 20599 (sh) S 20595 20594 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 19 0 1 0 11126530 1712128 124 1283457024 134512640 134593992 4290487904 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20599/statm: 418 124 108 20 0 45 0
[pid=20600] ppid=20599 vsize=122004 CPUtime=2.79
/proc/20600/stat : 20600 (minisatp_32) R 20599 20594 4778 34817 4778 4202496 32576 0 0 0 258 21 0 0 25 0 1 0 11126531 124932096 27254 1283457024 134512640 135413687 4294492752 18446744073709551615 134657099 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20600/statm: 30501 27254 107 220 0 30279 0
Current children cumulated CPU time (s) 7.83
Current children cumulated vsize (KiB) 173960

[startup+8.80802 s]
/proc/loadavg: 1.40 1.37 1.18 2/39 20601
/proc/meminfo: memFree=142840/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47712 CPUtime=5.04
/proc/20595/stat : 20595 (packup) S 20594 20594 4778 34817 4778 4202496 11644 27388 0 0 150 46 279 29 18 0 1 0 11126010 48857088 11187 1283457024 134512640 134752139 4293779616 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20595/statm: 11928 11187 332 59 0 11092 0
[pid=20599] ppid=20595 vsize=1672 CPUtime=0
/proc/20599/stat : 20599 (sh) S 20595 20594 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 19 0 1 0 11126530 1712128 124 1283457024 134512640 134593992 4290487904 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20599/statm: 418 124 108 20 0 45 0
[pid=20600] ppid=20599 vsize=112344 CPUtime=3.6
/proc/20600/stat : 20600 (minisatp_32) R 20599 20594 4778 34817 4778 4202496 34445 0 0 0 336 24 0 0 25 0 1 0 11126531 115040256 25890 1283457024 134512640 135413687 4294492752 18446744073709551615 134692035 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20600/statm: 28086 25890 107 220 0 27864 0
Current children cumulated CPU time (s) 8.64
Current children cumulated vsize (KiB) 164300

[startup+9.20809 s]
/proc/loadavg: 1.40 1.37 1.18 2/39 20601
/proc/meminfo: memFree=142840/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=47716 CPUtime=9.04
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202496 14169 63877 0 0 152 49 648 55 18 0 1 0 11126010 48861184 11201 1283457024 134512640 134752139 4293779616 18446744073709551615 134525484 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 11929 11201 345 59 0 11093 0
Current children cumulated CPU time (s) 9.04
Current children cumulated vsize (KiB) 50288

[startup+9.30845 s]
/proc/loadavg: 1.40 1.37 1.18 2/39 20601
/proc/meminfo: memFree=142840/1048576 swapFree=0/0
[pid=20594] ppid=20593 vsize=2572 CPUtime=0
/proc/20594/stat : 20594 (packup2mp4pa-0.) S 20593 20594 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11126009 2633728 274 1283457024 134512640 135304128 4294681008 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20594/statm: 643 274 233 194 0 30 0
[pid=20595] ppid=20594 vsize=0 CPUtime=9.15
/proc/20595/stat : 20595 (packup) R 20594 20594 4778 34817 4778 4202500 21813 63877 0 0 160 52 648 55 18 0 1 0 11126010 0 0 1283457024 0 0 0 0 0 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20595/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.15
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 9.31015
CPU time (s): 9.16057
CPU user time (s): 8.0845
CPU system time (s): 1.07607
CPU usage (%): 98.3933
Max. virtual memory (cumulated for all children) (KiB): 173960

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.08451
system time used= 1.07607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 86077
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= 159

runsolver used 0 second user time and 0 second system time

The end