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/rand496.cudf.s-e-l-s-s.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand496.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand496.cudf.s-e-l-s-s.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.31 1.20 1.07 4/34 9578
/proc/meminfo: memFree=388840/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=3716 CPUtime=0.01
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 404 0 0 0 1 0 0 0 25 0 1 0 10342237 3805184 332 1283457024 134512640 134752139 4288685040 18446744073709551615 4159320414 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 929 332 286 59 0 93 0

[startup+0.143596 s]
/proc/loadavg: 1.31 1.20 1.07 4/34 9578
/proc/meminfo: memFree=388840/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=9204 CPUtime=0.15
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 1799 0 0 0 15 0 0 0 25 0 1 0 10342237 9424896 1727 1283457024 134512640 134752139 4288685040 18446744073709551615 134706136 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 2301 1727 286 59 0 1465 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 11776

[startup+0.21361 s]
/proc/loadavg: 1.31 1.20 1.07 4/34 9578
/proc/meminfo: memFree=388840/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=11844 CPUtime=0.22
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 2437 0 0 0 20 2 0 0 25 0 1 0 10342237 12128256 2365 1283457024 134512640 134752139 4288685040 18446744073709551615 134681608 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 2961 2365 286 59 0 2125 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 14416

[startup+0.30363 s]
/proc/loadavg: 1.31 1.20 1.07 4/34 9578
/proc/meminfo: memFree=388840/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=14704 CPUtime=0.3
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 3160 0 0 0 28 2 0 0 25 0 1 0 10342237 15056896 3088 1283457024 134512640 134752139 4288685040 18446744073709551615 4157557553 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 3676 3088 286 59 0 2840 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 17276

[startup+0.703721 s]
/proc/loadavg: 1.31 1.20 1.07 4/34 9578
/proc/meminfo: memFree=388840/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=26000 CPUtime=0.71
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 5985 0 0 0 66 5 0 0 25 0 1 0 10342237 26624000 5913 1283457024 134512640 134752139 4288685040 18446744073709551615 4159320448 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 6500 5913 286 59 0 5664 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 28572

[startup+1.50391 s]
/proc/loadavg: 1.31 1.20 1.07 2/35 9579
/proc/meminfo: memFree=356464/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=51920 CPUtime=1.5
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 12565 0 0 0 144 6 0 0 25 0 1 0 10342237 53166080 12444 1283457024 134512640 134752139 4288685040 18446744073709551615 4159804796 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 12980 12444 316 59 0 12144 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 54492

[startup+3.10422 s]
/proc/loadavg: 1.31 1.20 1.07 2/37 9581
/proc/meminfo: memFree=326176/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=57628 CPUtime=1.89
/proc/9578/stat : 9578 (packup) S 9577 9577 4778 34817 4778 4202496 13982 0 0 0 159 30 0 0 25 0 1 0 10342237 59011072 13625 1283457024 134512640 134752139 4288685040 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9578/statm: 14407 13625 324 59 0 13571 0
[pid=9580] ppid=9578 vsize=1668 CPUtime=0
/proc/9580/stat : 9580 (sh) S 9578 9577 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 25 0 1 0 10342426 1708032 123 1283457024 134512640 134593992 4293788032 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9580/statm: 417 123 108 20 0 44 0
[pid=9581] ppid=9580 vsize=29596 CPUtime=1.19
/proc/9581/stat : 9581 (minisatp_32) R 9580 9577 4778 34817 4778 4202496 6844 0 0 0 113 6 0 0 25 0 1 0 10342427 30306304 6188 1283457024 134512640 135413687 4289998336 18446744073709551615 134960733 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9581/statm: 7399 6188 85 220 0 7177 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 91464

[startup+6.30597 s]
/proc/loadavg: 1.28 1.19 1.07 2/37 9583
/proc/meminfo: memFree=323200/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=57632 CPUtime=5.08
/proc/9578/stat : 9578 (packup) S 9577 9577 4778 34817 4778 4202496 14052 19717 0 0 172 50 263 23 18 0 1 0 10342237 59015168 13634 1283457024 134512640 134752139 4288685040 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9578/statm: 14408 13634 332 59 0 13572 0
[pid=9582] ppid=9578 vsize=1672 CPUtime=0
/proc/9582/stat : 9582 (sh) S 9578 9577 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10342746 1712128 124 1283457024 134512640 134593992 4291204880 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9582/statm: 418 124 108 20 0 45 0
[pid=9583] ppid=9582 vsize=29968 CPUtime=1.2
/proc/9583/stat : 9583 (minisatp_32) R 9582 9577 4778 34817 4778 4202496 6966 0 0 0 113 7 0 0 24 0 1 0 10342746 30687232 6298 1283457024 134512640 135413687 4293163280 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9583/statm: 7492 6298 85 220 0 7270 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 91844

[startup+12.7082 s]
/proc/loadavg: 1.26 1.19 1.07 2/37 9583
/proc/meminfo: memFree=189660/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=57632 CPUtime=5.08
/proc/9578/stat : 9578 (packup) S 9577 9577 4778 34817 4778 4202496 14052 19717 0 0 172 50 263 23 18 0 1 0 10342237 59015168 13634 1283457024 134512640 134752139 4288685040 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9578/statm: 14408 13634 332 59 0 13572 0
[pid=9582] ppid=9578 vsize=1672 CPUtime=0
/proc/9582/stat : 9582 (sh) S 9578 9577 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10342746 1712128 124 1283457024 134512640 134593992 4291204880 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9582/statm: 418 124 108 20 0 45 0
[pid=9583] ppid=9582 vsize=178928 CPUtime=7.61
/proc/9583/stat : 9583 (minisatp_32) R 9582 9577 4778 34817 4778 4202496 55749 0 0 0 727 34 0 0 25 0 1 0 10342746 183222272 39464 1283457024 134512640 135413687 4293163280 18446744073709551615 134649456 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9583/statm: 44732 39464 110 220 0 44510 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 240804

[startup+25.5121 s]
/proc/loadavg: 1.20 1.18 1.07 2/37 9583
/proc/meminfo: memFree=132868/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=57632 CPUtime=5.08
/proc/9578/stat : 9578 (packup) S 9577 9577 4778 34817 4778 4202496 14052 19717 0 0 172 50 263 23 18 0 1 0 10342237 59015168 13634 1283457024 134512640 134752139 4288685040 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9578/statm: 14408 13634 332 59 0 13572 0
[pid=9582] ppid=9578 vsize=1672 CPUtime=0
/proc/9582/stat : 9582 (sh) S 9578 9577 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10342746 1712128 124 1283457024 134512640 134593992 4291204880 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9582/statm: 418 124 108 20 0 45 0
[pid=9583] ppid=9582 vsize=218872 CPUtime=20.4
/proc/9583/stat : 9583 (minisatp_32) R 9582 9577 4778 34817 4778 4202496 75576 0 0 0 1996 44 0 0 25 0 1 0 10342746 224124928 49869 1283457024 134512640 135413687 4293163280 18446744073709551615 134650344 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9583/statm: 54718 49869 110 220 0 54496 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 280748

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

[startup+25.6022 s]
/proc/loadavg: 1.20 1.18 1.07 2/37 9583
/proc/meminfo: memFree=132868/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=57632 CPUtime=5.08
/proc/9578/stat : 9578 (packup) S 9577 9577 4778 34817 4778 4202496 14052 19717 0 0 172 50 263 23 18 0 1 0 10342237 59015168 13634 1283457024 134512640 134752139 4288685040 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9578/statm: 14408 13634 332 59 0 13572 0
[pid=9582] ppid=9578 vsize=1672 CPUtime=0
/proc/9582/stat : 9582 (sh) S 9578 9577 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10342746 1712128 124 1283457024 134512640 134593992 4291204880 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9582/statm: 418 124 108 20 0 45 0
[pid=9583] ppid=9582 vsize=218872 CPUtime=20.49
/proc/9583/stat : 9583 (minisatp_32) R 9582 9577 4778 34817 4778 4202496 75578 0 0 0 2005 44 0 0 25 0 1 0 10342746 224124928 49871 1283457024 134512640 135413687 4293163280 18446744073709551615 134649879 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9583/statm: 54718 49871 110 220 0 54496 0
Current children cumulated CPU time (s) 25.57
Current children cumulated vsize (KiB) 280748

[startup+26.4025 s]
/proc/loadavg: 1.20 1.18 1.07 2/37 9583
/proc/meminfo: memFree=132496/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=57632 CPUtime=5.08
/proc/9578/stat : 9578 (packup) S 9577 9577 4778 34817 4778 4202496 14052 19717 0 0 172 50 263 23 18 0 1 0 10342237 59015168 13634 1283457024 134512640 134752139 4288685040 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/9578/statm: 14408 13634 332 59 0 13572 0
[pid=9582] ppid=9578 vsize=1672 CPUtime=0
/proc/9582/stat : 9582 (sh) S 9578 9577 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 10342746 1712128 124 1283457024 134512640 134593992 4291204880 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9582/statm: 418 124 108 20 0 45 0
[pid=9583] ppid=9582 vsize=218872 CPUtime=21.29
/proc/9583/stat : 9583 (minisatp_32) R 9582 9577 4778 34817 4778 4202496 75955 0 0 0 2085 44 0 0 25 0 1 0 10342746 224124928 49896 1283457024 134512640 135413687 4293163280 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/9583/statm: 54718 49896 110 220 0 54496 0
Current children cumulated CPU time (s) 26.37
Current children cumulated vsize (KiB) 280748

[startup+26.8026 s]
/proc/loadavg: 1.20 1.18 1.07 2/37 9583
/proc/meminfo: memFree=132496/1048576 swapFree=0/0
[pid=9577] ppid=9576 vsize=2572 CPUtime=0
/proc/9577/stat : 9577 (packup2mp4pa-0.) S 9576 9577 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 10342237 2633728 275 1283457024 134512640 135304128 4288517120 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/9577/statm: 643 275 233 194 0 30 0
[pid=9578] ppid=9577 vsize=54396 CPUtime=26.77
/proc/9578/stat : 9578 (packup) R 9577 9577 4778 34817 4778 4202496 26076 95831 0 0 183 50 2374 70 18 0 1 0 10342237 55701504 13072 1283457024 134512640 134752139 4288685040 18446744073709551615 4157519181 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/9578/statm: 13599 13072 345 59 0 12763 0
Current children cumulated CPU time (s) 26.77
Current children cumulated vsize (KiB) 56968

Child status: 0
Real time (s): 26.833
CPU time (s): 26.8257
CPU user time (s): 25.5856
CPU system time (s): 1.24008
CPU usage (%): 99.9727
Max. virtual memory (cumulated for all children) (KiB): 303032

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 25.5856
system time used= 1.24008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 122809
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= 11
involuntary context switches= 381

runsolver used 0 second user time and 0 second system time

The end