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/rand924.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand924.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand924.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.03 1.10 1.11 4/34 26093
/proc/meminfo: memFree=353792/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) R 26091 26092 1511 34817 1511 4202496 362 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=2572 CPUtime=0
/proc/26093/stat : 26093 (packup2mp4tr-0.) R 26092 26092 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 42 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/26093/statm: 643 42 0 194 0 30 0

[startup+0.126843 s]
/proc/loadavg: 1.03 1.10 1.11 4/34 26093
/proc/meminfo: memFree=353792/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=7688 CPUtime=0.12
/proc/26093/stat : 26093 (packup) R 26092 26092 1511 34817 1511 4202496 1413 0 0 0 12 0 0 0 25 0 1 0 4805823 7872512 1342 1283457024 134512640 134752139 4287029856 18446744073709551615 134681846 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26093/statm: 1922 1342 286 59 0 1086 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 10260

[startup+0.206853 s]
/proc/loadavg: 1.03 1.10 1.11 4/34 26093
/proc/meminfo: memFree=353792/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=9932 CPUtime=0.2
/proc/26093/stat : 26093 (packup) R 26092 26092 1511 34817 1511 4202496 1982 0 0 0 20 0 0 0 25 0 1 0 4805823 10170368 1911 1283457024 134512640 134752139 4287029856 18446744073709551615 134681751 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26093/statm: 2483 1911 286 59 0 1647 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12504

[startup+0.306861 s]
/proc/loadavg: 1.03 1.10 1.11 4/34 26093
/proc/meminfo: memFree=353792/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=12596 CPUtime=0.3
/proc/26093/stat : 26093 (packup) R 26092 26092 1511 34817 1511 4202496 2624 0 0 0 30 0 0 0 25 0 1 0 4805823 12898304 2553 1283457024 134512640 134752139 4287029856 18446744073709551615 134681760 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26093/statm: 3149 2553 286 59 0 2313 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15168

[startup+0.706905 s]
/proc/loadavg: 1.03 1.10 1.11 4/34 26093
/proc/meminfo: memFree=353792/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=21784 CPUtime=0.7
/proc/26093/stat : 26093 (packup) R 26092 26092 1511 34817 1511 4202496 4927 0 0 0 68 2 0 0 25 0 1 0 4805823 22306816 4856 1283457024 134512640 134752139 4287029856 18446744073709551615 4157156478 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26093/statm: 5446 4856 286 59 0 4610 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 24356

[startup+1.50698 s]
/proc/loadavg: 1.03 1.10 1.11 2/35 26094
/proc/meminfo: memFree=327148/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46132 CPUtime=1.5
/proc/26093/stat : 26093 (packup) R 26092 26092 1511 34817 1511 4202496 10880 0 0 0 146 4 0 0 25 0 1 0 4805823 47239168 10760 1283457024 134512640 134752139 4287029856 18446744073709551615 4157175215 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26093/statm: 11533 10760 320 59 0 10697 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 48704

[startup+3.10734 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26096
/proc/meminfo: memFree=299216/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46092 CPUtime=3.01
/proc/26093/stat : 26093 (packup) S 26092 26092 1511 34817 1511 4202496 11169 8129 0 0 161 31 99 10 18 0 1 0 4805823 47198208 10846 1283457024 134512640 134752139 4287029856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26093/statm: 11523 10846 333 59 0 10687 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 48664

[startup+6.30837 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26100
/proc/meminfo: memFree=299092/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46096 CPUtime=5.03
/proc/26093/stat : 26093 (packup) S 26092 26092 1511 34817 1511 4202496 11255 23303 0 0 172 42 264 25 18 0 1 0 4805823 47202304 10852 1283457024 134512640 134752139 4287029856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26093/statm: 11524 10852 333 59 0 10688 0
[pid=26099] ppid=26093 vsize=1668 CPUtime=0
/proc/26099/stat : 26099 (sh) S 26093 26092 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4806328 1708032 123 1283457024 134512640 134593992 4287261520 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26099/statm: 417 123 108 20 0 44 0
[pid=26100] ppid=26099 vsize=45132 CPUtime=1.24
/proc/26100/stat : 26100 (minisatp_32) R 26099 26092 1511 34817 1511 4202496 12823 0 0 0 110 14 0 0 24 0 1 0 4806329 46215168 9994 1283457024 134512640 135413687 4289428864 18446744073709551615 134686528 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26100/statm: 11283 9994 94 220 0 11061 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 95468

[startup+12.7099 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26102
/proc/meminfo: memFree=204364/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46100 CPUtime=8.11
/proc/26093/stat : 26093 (packup) S 26092 26092 1511 34817 1511 4202496 11325 47382 0 0 182 55 526 48 18 0 1 0 4805823 47206400 10853 1283457024 134512640 134752139 4287029856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26093/statm: 11525 10853 333 59 0 10689 0
[pid=26101] ppid=26093 vsize=1668 CPUtime=0
/proc/26101/stat : 26101 (sh) S 26093 26092 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4806635 1708032 123 1283457024 134512640 134593992 4294105552 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26101/statm: 417 123 108 20 0 44 0
[pid=26102] ppid=26101 vsize=122256 CPUtime=4.58
/proc/26102/stat : 26102 (minisatp_32) R 26101 26092 1511 34817 1511 4202496 40255 0 0 0 428 30 0 0 25 0 1 0 4806636 125190144 26544 1283457024 134512640 135413687 4291565440 18446744073709551615 134705569 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26102/statm: 30564 26544 107 220 0 30342 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 172596

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

[startup+12.8099 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26102
/proc/meminfo: memFree=204364/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46100 CPUtime=8.11
/proc/26093/stat : 26093 (packup) S 26092 26092 1511 34817 1511 4202496 11325 47382 0 0 182 55 526 48 18 0 1 0 4805823 47206400 10853 1283457024 134512640 134752139 4287029856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26093/statm: 11525 10853 333 59 0 10689 0
[pid=26101] ppid=26093 vsize=1668 CPUtime=0
/proc/26101/stat : 26101 (sh) S 26093 26092 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4806635 1708032 123 1283457024 134512640 134593992 4294105552 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26101/statm: 417 123 108 20 0 44 0
[pid=26102] ppid=26101 vsize=122256 CPUtime=4.68
/proc/26102/stat : 26102 (minisatp_32) R 26101 26092 1511 34817 1511 4202496 40287 0 0 0 438 30 0 0 25 0 1 0 4806636 125190144 26575 1283457024 134512640 135413687 4291565440 18446744073709551615 134649515 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26102/statm: 30564 26575 107 220 0 30342 0
Current children cumulated CPU time (s) 12.79
Current children cumulated vsize (KiB) 172596

[startup+13.2099 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26102
/proc/meminfo: memFree=202008/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46100 CPUtime=8.11
/proc/26093/stat : 26093 (packup) S 26092 26092 1511 34817 1511 4202496 11325 47382 0 0 182 55 526 48 18 0 1 0 4805823 47206400 10853 1283457024 134512640 134752139 4287029856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26093/statm: 11525 10853 333 59 0 10689 0
[pid=26101] ppid=26093 vsize=1668 CPUtime=0
/proc/26101/stat : 26101 (sh) S 26093 26092 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4806635 1708032 123 1283457024 134512640 134593992 4294105552 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26101/statm: 417 123 108 20 0 44 0
[pid=26102] ppid=26101 vsize=125480 CPUtime=5.08
/proc/26102/stat : 26102 (minisatp_32) R 26101 26092 1511 34817 1511 4202496 40525 0 0 0 478 30 0 0 25 0 1 0 4806636 128491520 26801 1283457024 134512640 135413687 4291565440 18446744073709551615 134653643 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26102/statm: 31370 26801 107 220 0 31148 0
Current children cumulated CPU time (s) 13.19
Current children cumulated vsize (KiB) 175820

[startup+13.4102 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26102
/proc/meminfo: memFree=202008/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=46100 CPUtime=8.11
/proc/26093/stat : 26093 (packup) S 26092 26092 1511 34817 1511 4202496 11325 47382 0 0 182 55 526 48 18 0 1 0 4805823 47206400 10853 1283457024 134512640 134752139 4287029856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26093/statm: 11525 10853 333 59 0 10689 0
[pid=26101] ppid=26093 vsize=1668 CPUtime=0
/proc/26101/stat : 26101 (sh) S 26093 26092 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4806635 1708032 123 1283457024 134512640 134593992 4294105552 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26101/statm: 417 123 108 20 0 44 0
[pid=26102] ppid=26101 vsize=0 CPUtime=5.27
/proc/26102/stat : 26102 (minisatp_32) R 26101 26092 1511 34817 1511 4202500 40539 0 0 0 496 31 0 0 25 0 1 0 4806636 0 0 1283457024 0 0 0 0 0 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26102/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 13.38
Current children cumulated vsize (KiB) 50340

[startup+13.51 s]
/proc/loadavg: 1.03 1.10 1.11 2/37 26102
/proc/meminfo: memFree=202008/1048576 swapFree=0/0
[pid=26092] ppid=26091 vsize=2572 CPUtime=0
/proc/26092/stat : 26092 (packup2mp4tr-0.) S 26091 26092 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 25 0 1 0 4805823 2633728 275 1283457024 134512640 135304128 4292114288 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26092/statm: 643 275 233 194 0 30 0
[pid=26093] ppid=26092 vsize=42664 CPUtime=13.49
/proc/26093/stat : 26093 (packup) R 26092 26092 1511 34817 1511 4202496 21333 88069 0 0 190 57 1022 80 18 0 1 0 4805823 43687936 10160 1283457024 134512640 134752139 4287029856 18446744073709551615 134555028 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26093/statm: 10666 10160 346 59 0 9830 0
Current children cumulated CPU time (s) 13.49
Current children cumulated vsize (KiB) 45236

Child status: 0
Real time (s): 13.5215
CPU time (s): 13.5208
CPU user time (s): 12.1328
CPU system time (s): 1.38809
CPU usage (%): 99.9954
Max. virtual memory (cumulated for all children) (KiB): 183120

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

runsolver used 0 second user time and 0 second system time

The end