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/rand475.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand475.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand475.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.22 1.14 1.04 5/34 20782
/proc/meminfo: memFree=412640/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=4108 CPUtime=0.02
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 505 0 0 0 2 0 0 0 25 0 1 0 4603353 4206592 434 1283457024 134512640 134752139 4290821632 18446744073709551615 134681663 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 1027 434 286 59 0 191 0

[startup+0.163451 s]
/proc/loadavg: 1.22 1.14 1.04 5/34 20782
/proc/meminfo: memFree=412640/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=8612 CPUtime=0.16
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 1658 0 0 0 16 0 0 0 25 0 1 0 4603353 8818688 1587 1283457024 134512640 134752139 4290821632 18446744073709551615 134681820 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 2153 1587 286 59 0 1317 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11184

[startup+0.213461 s]
/proc/loadavg: 1.22 1.14 1.04 5/34 20782
/proc/meminfo: memFree=412640/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=10064 CPUtime=0.22
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 2007 0 0 0 22 0 0 0 25 0 1 0 4603353 10305536 1936 1283457024 134512640 134752139 4290821632 18446744073709551615 134681618 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 2516 1936 286 59 0 1680 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 12636

[startup+0.303486 s]
/proc/loadavg: 1.22 1.14 1.04 5/34 20782
/proc/meminfo: memFree=412640/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=12332 CPUtime=0.3
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 2581 0 0 0 30 0 0 0 25 0 1 0 4603353 12627968 2510 1283457024 134512640 134752139 4290821632 18446744073709551615 4157201203 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 3083 2510 286 59 0 2247 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 14904

[startup+0.703582 s]
/proc/loadavg: 1.22 1.14 1.04 5/34 20782
/proc/meminfo: memFree=412640/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=21520 CPUtime=0.7
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 4859 0 0 0 69 1 0 0 25 0 1 0 4603353 22036480 4788 1283457024 134512640 134752139 4290821632 18446744073709551615 134681583 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 5380 4788 286 59 0 4544 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 24092

[startup+1.50381 s]
/proc/loadavg: 1.22 1.14 1.04 2/35 20783
/proc/meminfo: memFree=386888/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=43800 CPUtime=1.5
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 10519 0 0 0 144 6 0 0 25 0 1 0 4603353 44851200 10399 1283457024 134512640 134752139 4290821632 18446744073709551615 4157180990 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 10950 10399 317 59 0 10114 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 46372

[startup+3.10412 s]
/proc/loadavg: 1.22 1.14 1.04 2/37 20785
/proc/meminfo: memFree=359204/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=46088 CPUtime=3.05
/proc/20782/stat : 20782 (packup) S 20781 20781 1511 34817 1511 4202496 11168 8208 0 0 164 29 94 18 18 0 1 0 4603353 47194112 10845 1283457024 134512640 134752139 4290821632 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20782/statm: 11522 10845 333 59 0 10686 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 48660

[startup+6.30495 s]
/proc/loadavg: 1.20 1.14 1.04 2/37 20789
/proc/meminfo: memFree=359452/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=46092 CPUtime=5.07
/proc/20782/stat : 20782 (packup) S 20781 20781 1511 34817 1511 4202496 11250 23396 0 0 176 39 261 31 18 0 1 0 4603353 47198208 10851 1283457024 134512640 134752139 4290821632 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20782/statm: 11523 10851 333 59 0 10687 0
[pid=20788] ppid=20782 vsize=1672 CPUtime=0.01
/proc/20788/stat : 20788 (sh) S 20782 20781 1511 34817 1511 4202496 146 0 0 0 0 1 0 0 18 0 1 0 4603863 1712128 124 1283457024 134512640 134593992 4294718048 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20788/statm: 418 124 108 20 0 45 0
[pid=20789] ppid=20788 vsize=44620 CPUtime=1.2
/proc/20789/stat : 20789 (minisatp_32) R 20788 20781 1511 34817 1511 4202496 12181 0 0 0 106 14 0 0 25 0 1 0 4603863 45690880 9856 1283457024 134512640 135413687 4294576736 18446744073709551615 134699348 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20789/statm: 11155 9856 94 220 0 10933 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 94956

[startup+12.7065 s]
/proc/loadavg: 1.19 1.14 1.04 2/37 20791
/proc/meminfo: memFree=264724/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=46096 CPUtime=8.13
/proc/20782/stat : 20782 (packup) S 20781 20781 1511 34817 1511 4202496 11320 46645 0 0 184 53 521 55 18 0 1 0 4603353 47202304 10852 1283457024 134512640 134752139 4290821632 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20782/statm: 11524 10852 333 59 0 10688 0
[pid=20790] ppid=20782 vsize=1672 CPUtime=0
/proc/20790/stat : 20790 (sh) S 20782 20781 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4604169 1712128 124 1283457024 134512640 134593992 4291333936 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20790/statm: 418 124 108 20 0 45 0
[pid=20791] ppid=20790 vsize=121692 CPUtime=4.53
/proc/20791/stat : 20791 (minisatp_32) R 20790 20781 1511 34817 1511 4202496 40248 0 0 0 425 28 0 0 25 0 1 0 4604169 124612608 26486 1283457024 134512640 135413687 4289568160 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20791/statm: 30423 26486 107 220 0 30201 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 172032

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

[startup+12.8066 s]
/proc/loadavg: 1.19 1.14 1.04 2/37 20791
/proc/meminfo: memFree=264724/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=46096 CPUtime=8.13
/proc/20782/stat : 20782 (packup) S 20781 20781 1511 34817 1511 4202496 11320 46645 0 0 184 53 521 55 18 0 1 0 4603353 47202304 10852 1283457024 134512640 134752139 4290821632 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20782/statm: 11524 10852 333 59 0 10688 0
[pid=20790] ppid=20782 vsize=1672 CPUtime=0
/proc/20790/stat : 20790 (sh) S 20782 20781 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4604169 1712128 124 1283457024 134512640 134593992 4291333936 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20790/statm: 418 124 108 20 0 45 0
[pid=20791] ppid=20790 vsize=121692 CPUtime=4.63
/proc/20791/stat : 20791 (minisatp_32) R 20790 20781 1511 34817 1511 4202496 40253 0 0 0 435 28 0 0 25 0 1 0 4604169 124612608 26491 1283457024 134512640 135413687 4289568160 18446744073709551615 134653612 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20791/statm: 30423 26491 107 220 0 30201 0
Current children cumulated CPU time (s) 12.76
Current children cumulated vsize (KiB) 172032

[startup+13.2068 s]
/proc/loadavg: 1.19 1.14 1.04 2/37 20791
/proc/meminfo: memFree=261748/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=46096 CPUtime=8.13
/proc/20782/stat : 20782 (packup) S 20781 20781 1511 34817 1511 4202496 11320 46645 0 0 184 53 521 55 18 0 1 0 4603353 47202304 10852 1283457024 134512640 134752139 4290821632 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20782/statm: 11524 10852 333 59 0 10688 0
[pid=20790] ppid=20782 vsize=1672 CPUtime=0
/proc/20790/stat : 20790 (sh) S 20782 20781 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4604169 1712128 124 1283457024 134512640 134593992 4291333936 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20790/statm: 418 124 108 20 0 45 0
[pid=20791] ppid=20790 vsize=124920 CPUtime=5.03
/proc/20791/stat : 20791 (minisatp_32) R 20790 20781 1511 34817 1511 4202496 40454 0 0 0 475 28 0 0 25 0 1 0 4604169 127918080 26684 1283457024 134512640 135413687 4289568160 18446744073709551615 134649456 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20791/statm: 31230 26684 107 220 0 31008 0
Current children cumulated CPU time (s) 13.16
Current children cumulated vsize (KiB) 175260

[startup+13.6068 s]
/proc/loadavg: 1.19 1.14 1.04 2/37 20791
/proc/meminfo: memFree=261748/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=46096 CPUtime=8.13
/proc/20782/stat : 20782 (packup) S 20781 20781 1511 34817 1511 4202496 11320 46645 0 0 184 53 521 55 18 0 1 0 4603353 47202304 10852 1283457024 134512640 134752139 4290821632 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/20782/statm: 11524 10852 333 59 0 10688 0
[pid=20790] ppid=20782 vsize=1672 CPUtime=0
/proc/20790/stat : 20790 (sh) S 20782 20781 1511 34817 1511 4202496 146 0 0 0 0 0 0 0 18 0 1 0 4604169 1712128 124 1283457024 134512640 134593992 4291333936 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/20790/statm: 418 124 108 20 0 45 0
[pid=20791] ppid=20790 vsize=118512 CPUtime=5.43
/proc/20791/stat : 20791 (minisatp_32) R 20790 20781 1511 34817 1511 4202496 40471 0 0 0 515 28 0 0 25 0 1 0 4604169 121356288 25521 1283457024 134512640 135413687 4289568160 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/20791/statm: 29628 25521 117 220 0 29406 0
Current children cumulated CPU time (s) 13.56
Current children cumulated vsize (KiB) 168852

[startup+13.7069 s]
/proc/loadavg: 1.19 1.14 1.04 2/37 20791
/proc/meminfo: memFree=261748/1048576 swapFree=0/0
[pid=20781] ppid=20780 vsize=2572 CPUtime=0
/proc/20781/stat : 20781 (packup2mp4tr-0.) S 20780 20781 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4603353 2633728 274 1283457024 134512640 135304128 4293740800 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/20781/statm: 643 274 233 194 0 30 0
[pid=20782] ppid=20781 vsize=45128 CPUtime=13.68
/proc/20782/stat : 20782 (packup) R 20781 20781 1511 34817 1511 4202496 20708 87265 0 0 189 56 1039 84 18 0 1 0 4603353 46211072 10623 1283457024 134512640 134752139 4290821632 18446744073709551615 4157167788 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/20782/statm: 11282 10623 346 59 0 10446 0
Current children cumulated CPU time (s) 13.68
Current children cumulated vsize (KiB) 47700

Child status: 0
Real time (s): 13.7464
CPU time (s): 13.7169
CPU user time (s): 12.3168
CPU system time (s): 1.40009
CPU usage (%): 99.785
Max. virtual memory (cumulated for all children) (KiB): 182540

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

runsolver used 0 second user time and 0 second system time

The end