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/rand408.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand408.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand408.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.01 1.02 1.00 5/35 16383
/proc/meminfo: memFree=503692/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) R 16381 16382 1511 34817 1511 4202496 360 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=2572 CPUtime=0
/proc/16383/stat : 16383 (packup2mp4tr-0.) R 16382 16382 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 40 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/16383/statm: 643 40 0 194 0 30 0

[startup+0.213487 s]
/proc/loadavg: 1.01 1.02 1.00 5/35 16383
/proc/meminfo: memFree=503692/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=10200 CPUtime=0.21
/proc/16383/stat : 16383 (packup) R 16382 16382 1511 34817 1511 4202496 2030 0 0 0 21 0 0 0 25 0 1 0 3792265 10444800 1959 1283457024 134512640 134752139 4289021008 18446744073709551615 134681663 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/16383/statm: 2550 1959 286 59 0 1714 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12772

[startup+0.303505 s]
/proc/loadavg: 1.01 1.02 1.00 5/35 16383
/proc/meminfo: memFree=503692/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=12468 CPUtime=0.3
/proc/16383/stat : 16383 (packup) R 16382 16382 1511 34817 1511 4202496 2600 0 0 0 30 0 0 0 25 0 1 0 3792265 12767232 2529 1283457024 134512640 134752139 4289021008 18446744073709551615 134681560 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/16383/statm: 3117 2529 286 59 0 2281 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15040

[startup+0.41352 s]
/proc/loadavg: 1.01 1.02 1.00 5/35 16383
/proc/meminfo: memFree=503692/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=15240 CPUtime=0.41
/proc/16383/stat : 16383 (packup) R 16382 16382 1511 34817 1511 4202496 3300 0 0 0 41 0 0 0 25 0 1 0 3792265 15605760 3229 1283457024 134512640 134752139 4289021008 18446744073709551615 134706013 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/16383/statm: 3810 3229 286 59 0 2974 0
Current children cumulated CPU time (s) 0.41
Current children cumulated vsize (KiB) 17812

[startup+0.703569 s]
/proc/loadavg: 1.01 1.02 1.00 5/35 16383
/proc/meminfo: memFree=503692/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=21656 CPUtime=0.69
/proc/16383/stat : 16383 (packup) R 16382 16382 1511 34817 1511 4202496 4909 0 0 0 68 1 0 0 25 0 1 0 3792265 22175744 4838 1283457024 134512640 134752139 4289021008 18446744073709551615 134681676 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/16383/statm: 5414 4838 286 59 0 4578 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 24228

[startup+1.50377 s]
/proc/loadavg: 1.01 1.02 1.00 2/35 16384
/proc/meminfo: memFree=475168/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=44204 CPUtime=1.49
/proc/16383/stat : 16383 (packup) R 16382 16382 1511 34817 1511 4202496 10620 0 0 0 145 4 0 0 25 0 1 0 3792265 45264896 10500 1283457024 134512640 134752139 4289021008 18446744073709551615 4157121975 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/16383/statm: 11051 10500 317 59 0 10215 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 46776

[startup+3.10414 s]
/proc/loadavg: 1.01 1.02 1.00 2/37 16386
/proc/meminfo: memFree=447484/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46096 CPUtime=3.04
/proc/16383/stat : 16383 (packup) S 16382 16382 1511 34817 1511 4202496 11167 8183 0 0 162 31 105 6 18 0 1 0 3792265 47202304 10846 1283457024 134512640 134752139 4289021008 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/16383/statm: 11524 10846 333 59 0 10688 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 48668

[startup+6.30492 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 16390
/proc/meminfo: memFree=440044/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46100 CPUtime=4.61
/proc/16383/stat : 16383 (packup) S 16382 16382 1511 34817 1511 4202496 11252 20640 0 0 175 41 227 18 18 0 1 0 3792265 47206400 10852 1283457024 134512640 134752139 4289021008 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/16383/statm: 11525 10852 333 59 0 10689 0
[pid=16389] ppid=16383 vsize=1668 CPUtime=0
/proc/16389/stat : 16389 (sh) S 16383 16382 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 3792729 1708032 123 1283457024 134512640 134593992 4294724208 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/16389/statm: 417 123 108 20 0 44 0
[pid=16390] ppid=16389 vsize=45608 CPUtime=1.65
/proc/16390/stat : 16390 (minisatp_32) R 16389 16382 1511 34817 1511 4202496 15146 0 0 0 156 9 0 0 25 0 1 0 3792729 46702592 10140 1283457024 134512640 135413687 4293499232 18446744073709551615 134656393 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/16390/statm: 11402 10140 94 220 0 11180 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 95948

[startup+12.7069 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 16392
/proc/meminfo: memFree=353748/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46104 CPUtime=7.76
/proc/16383/stat : 16383 (packup) S 16382 16382 1511 34817 1511 4202496 11322 44432 0 0 188 50 505 33 18 0 1 0 3792265 47210496 10853 1283457024 134512640 134752139 4289021008 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/16383/statm: 11526 10853 333 59 0 10690 0
[pid=16391] ppid=16383 vsize=1676 CPUtime=0
/proc/16391/stat : 16391 (sh) S 16383 16382 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3793045 1716224 124 1283457024 134512640 134593992 4292925616 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/16391/statm: 419 124 108 20 0 46 0
[pid=16392] ppid=16391 vsize=154880 CPUtime=4.9
/proc/16392/stat : 16392 (minisatp_32) R 16391 16382 1511 34817 1511 4202496 48763 0 0 0 452 38 0 0 25 0 1 0 3793045 158597120 34132 1283457024 134512640 135413687 4290703024 18446744073709551615 134686212 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/16392/statm: 38720 34132 107 220 0 38498 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 205232

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

[startup+12.9069 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 16392
/proc/meminfo: memFree=353748/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46104 CPUtime=7.76
/proc/16383/stat : 16383 (packup) S 16382 16382 1511 34817 1511 4202496 11322 44432 0 0 188 50 505 33 18 0 1 0 3792265 47210496 10853 1283457024 134512640 134752139 4289021008 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/16383/statm: 11526 10853 333 59 0 10690 0
[pid=16391] ppid=16383 vsize=1676 CPUtime=0
/proc/16391/stat : 16391 (sh) S 16383 16382 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3793045 1716224 124 1283457024 134512640 134593992 4292925616 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/16391/statm: 419 124 108 20 0 46 0
[pid=16392] ppid=16391 vsize=164964 CPUtime=5.1
/proc/16392/stat : 16392 (minisatp_32) R 16391 16382 1511 34817 1511 4202496 50128 0 0 0 472 38 0 0 25 0 1 0 3793045 168923136 35440 1283457024 134512640 135413687 4290703024 18446744073709551615 134656313 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/16392/statm: 41241 35440 107 220 0 41019 0
Current children cumulated CPU time (s) 12.86
Current children cumulated vsize (KiB) 215316

[startup+13.7071 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 16392
/proc/meminfo: memFree=311464/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46104 CPUtime=7.76
/proc/16383/stat : 16383 (packup) S 16382 16382 1511 34817 1511 4202496 11322 44432 0 0 188 50 505 33 18 0 1 0 3792265 47210496 10853 1283457024 134512640 134752139 4289021008 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/16383/statm: 11526 10853 333 59 0 10690 0
[pid=16391] ppid=16383 vsize=1676 CPUtime=0
/proc/16391/stat : 16391 (sh) S 16383 16382 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3793045 1716224 124 1283457024 134512640 134593992 4292925616 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/16391/statm: 419 124 108 20 0 46 0
[pid=16392] ppid=16391 vsize=160616 CPUtime=5.9
/proc/16392/stat : 16392 (minisatp_32) R 16391 16382 1511 34817 1511 4202496 53853 0 0 0 549 41 0 0 25 0 1 0 3793045 164470784 35541 1283457024 134512640 135413687 4290703024 18446744073709551615 134962843 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/16392/statm: 40154 35541 107 220 0 39932 0
Current children cumulated CPU time (s) 13.66
Current children cumulated vsize (KiB) 210968

[startup+14.1072 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 16392
/proc/meminfo: memFree=311464/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46104 CPUtime=7.76
/proc/16383/stat : 16383 (packup) S 16382 16382 1511 34817 1511 4202496 11322 44432 0 0 188 50 505 33 18 0 1 0 3792265 47210496 10853 1283457024 134512640 134752139 4289021008 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/16383/statm: 11526 10853 333 59 0 10690 0
[pid=16391] ppid=16383 vsize=1676 CPUtime=0
/proc/16391/stat : 16391 (sh) S 16383 16382 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 3793045 1716224 124 1283457024 134512640 134593992 4292925616 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/16391/statm: 419 124 108 20 0 46 0
[pid=16392] ppid=16391 vsize=160988 CPUtime=6.3
/proc/16392/stat : 16392 (minisatp_32) R 16391 16382 1511 34817 1511 4202496 54120 0 0 0 589 41 0 0 25 0 1 0 3793045 164851712 35801 1283457024 134512640 135413687 4290703024 18446744073709551615 134654248 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/16392/statm: 40247 35801 109 220 0 40025 0
Current children cumulated CPU time (s) 14.06
Current children cumulated vsize (KiB) 211340

[startup+14.2088 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 16392
/proc/meminfo: memFree=311464/1048576 swapFree=0/0
[pid=16382] ppid=16381 vsize=2572 CPUtime=0
/proc/16382/stat : 16382 (packup2mp4tr-0.) S 16381 16382 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 25 0 1 0 3792265 2633728 273 1283457024 134512640 135304128 4290354624 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/16382/statm: 643 273 233 194 0 30 0
[pid=16383] ppid=16382 vsize=46108 CPUtime=14.17
/proc/16383/stat : 16383 (packup) R 16382 16382 1511 34817 1511 4202496 13189 98997 0 0 191 50 1100 76 18 0 1 0 3792265 47214592 10867 1283457024 134512640 134752139 4289021008 18446744073709551615 4157103037 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/16383/statm: 11527 10867 346 59 0 10691 0
Current children cumulated CPU time (s) 14.17
Current children cumulated vsize (KiB) 48680

Child status: 0
Real time (s): 14.2979
CPU time (s): 14.2649
CPU user time (s): 12.9888
CPU system time (s): 1.27608
CPU usage (%): 99.7689
Max. virtual memory (cumulated for all children) (KiB): 229320

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

runsolver used 0 second user time and 0.008 second system time

The end