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/4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/4e539b28-d46c-11df-8f4f-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.50 1.41 1.21 4/34 21125 /proc/meminfo: memFree=313784/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=3980 CPUtime=0 /proc/21125/stat : 21125 (packup) R 21124 21124 4778 34817 4778 4202496 478 0 0 0 0 0 0 0 25 0 1 0 11136919 4075520 407 1283457024 134512640 134752139 4292087552 18446744073709551615 134695863 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/21125/statm: 995 407 286 59 0 159 0 [startup+0.159785 s] /proc/loadavg: 1.50 1.41 1.21 4/34 21125 /proc/meminfo: memFree=313784/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=9040 CPUtime=0.16 /proc/21125/stat : 21125 (packup) R 21124 21124 4778 34817 4778 4202496 1753 0 0 0 14 2 0 0 25 0 1 0 11136919 9256960 1682 1283457024 134512640 134752139 4292087552 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/21125/statm: 2260 1682 286 59 0 1424 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 11608 [startup+0.209746 s] /proc/loadavg: 1.50 1.41 1.21 4/34 21125 /proc/meminfo: memFree=313784/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=10492 CPUtime=0.2 /proc/21125/stat : 21125 (packup) R 21124 21124 4778 34817 4778 4202496 2126 0 0 0 18 2 0 0 25 0 1 0 11136919 10743808 2055 1283457024 134512640 134752139 4292087552 18446744073709551615 4157883107 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/21125/statm: 2623 2055 286 59 0 1787 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13060 [startup+0.309772 s] /proc/loadavg: 1.50 1.41 1.21 4/34 21125 /proc/meminfo: memFree=313784/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=13344 CPUtime=0.3 /proc/21125/stat : 21125 (packup) R 21124 21124 4778 34817 4778 4202496 2833 0 0 0 28 2 0 0 25 0 1 0 11136919 13664256 2762 1283457024 134512640 134752139 4292087552 18446744073709551615 134706236 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/21125/statm: 3336 2762 286 59 0 2500 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 15912 [startup+0.709866 s] /proc/loadavg: 1.50 1.41 1.21 4/34 21125 /proc/meminfo: memFree=313784/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=23448 CPUtime=0.7 /proc/21125/stat : 21125 (packup) R 21124 21124 4778 34817 4778 4202496 5343 0 0 0 64 6 0 0 25 0 1 0 11136919 24010752 5272 1283457024 134512640 134752139 4292087552 18446744073709551615 134681639 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/21125/statm: 5862 5272 286 59 0 5026 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 26016 [startup+1.5101 s] /proc/loadavg: 1.50 1.41 1.21 2/35 21126 /proc/meminfo: memFree=280360/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=42192 CPUtime=1.41 /proc/21125/stat : 21125 (packup) S 21124 21124 4778 34817 4778 4202496 10171 0 0 0 124 17 0 0 25 0 1 0 11136919 43204608 9833 1283457024 134512640 134752139 4292087552 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/21125/statm: 10548 9833 324 59 0 9712 0 Current children cumulated CPU time (s) 1.41 Current children cumulated vsize (KiB) 44760 [startup+3.11061 s] /proc/loadavg: 1.50 1.41 1.21 2/37 21128 /proc/meminfo: memFree=257016/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=42192 CPUtime=1.41 /proc/21125/stat : 21125 (packup) S 21124 21124 4778 34817 4778 4202496 10171 0 0 0 124 17 0 0 25 0 1 0 11136919 43204608 9833 1283457024 134512640 134752139 4292087552 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/21125/statm: 10548 9833 324 59 0 9712 0 [pid=21127] ppid=21125 vsize=1672 CPUtime=0 /proc/21127/stat : 21127 (sh) S 21125 21124 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 25 0 1 0 11137061 1712128 123 1283457024 134512640 134593992 4287187776 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/21127/statm: 418 123 108 20 0 45 0 [pid=21128] ppid=21127 vsize=65848 CPUtime=1.67 /proc/21128/stat : 21128 (minisatp_32) R 21127 21124 4778 34817 4778 4202496 20220 0 0 0 145 22 0 0 25 0 1 0 11137062 67428352 15237 1283457024 134512640 135413687 4287572912 18446744073709551615 134686212 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/21128/statm: 16462 15237 107 220 0 16240 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 112280 [startup+6.31196 s] /proc/loadavg: 1.46 1.41 1.21 2/37 21130 /proc/meminfo: memFree=254420/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=42196 CPUtime=4.49 /proc/21125/stat : 21125 (packup) S 21124 21124 4778 34817 4778 4202496 10252 27403 0 0 132 34 257 26 18 0 1 0 11136919 43208704 9842 1283457024 134512640 134752139 4292087552 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/21125/statm: 10549 9842 332 59 0 9713 0 [pid=21129] ppid=21125 vsize=1672 CPUtime=0 /proc/21129/stat : 21129 (sh) S 21125 21124 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11137370 1712128 124 1283457024 134512640 134593992 4294632016 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/21129/statm: 418 124 108 20 0 45 0 [pid=21130] ppid=21129 vsize=80384 CPUtime=1.7 /proc/21130/stat : 21130 (minisatp_32) R 21129 21124 4778 34817 4778 4202496 22936 0 0 0 153 17 0 0 25 0 1 0 11137371 82313216 18337 1283457024 134512640 135413687 4293036272 18446744073709551615 134696978 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/21130/statm: 20096 18337 108 220 0 19874 0 Current children cumulated CPU time (s) 6.19 Current children cumulated vsize (KiB) 126820 Solver just ended. Dumping a history of the last processes samples [startup+6.41197 s] /proc/loadavg: 1.46 1.41 1.21 2/37 21130 /proc/meminfo: memFree=254420/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=42196 CPUtime=4.49 /proc/21125/stat : 21125 (packup) S 21124 21124 4778 34817 4778 4202496 10252 27403 0 0 132 34 257 26 18 0 1 0 11136919 43208704 9842 1283457024 134512640 134752139 4292087552 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/21125/statm: 10549 9842 332 59 0 9713 0 [pid=21129] ppid=21125 vsize=1672 CPUtime=0 /proc/21129/stat : 21129 (sh) S 21125 21124 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11137370 1712128 124 1283457024 134512640 134593992 4294632016 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/21129/statm: 418 124 108 20 0 45 0 [pid=21130] ppid=21129 vsize=83308 CPUtime=1.8 /proc/21130/stat : 21130 (minisatp_32) R 21129 21124 4778 34817 4778 4202496 24139 0 0 0 163 17 0 0 25 0 1 0 11137371 85307392 19072 1283457024 134512640 135413687 4293036272 18446744073709551615 134689931 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/21130/statm: 20827 19072 108 220 0 20605 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 129744 [startup+8.0127 s] /proc/loadavg: 1.46 1.41 1.21 2/37 21130 /proc/meminfo: memFree=180888/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=42196 CPUtime=4.49 /proc/21125/stat : 21125 (packup) S 21124 21124 4778 34817 4778 4202496 10252 27403 0 0 132 34 257 26 18 0 1 0 11136919 43208704 9842 1283457024 134512640 134752139 4292087552 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/21125/statm: 10549 9842 332 59 0 9713 0 [pid=21129] ppid=21125 vsize=1672 CPUtime=0 /proc/21129/stat : 21129 (sh) S 21125 21124 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11137370 1712128 124 1283457024 134512640 134593992 4294632016 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/21129/statm: 418 124 108 20 0 45 0 [pid=21130] ppid=21129 vsize=109912 CPUtime=3.4 /proc/21130/stat : 21130 (minisatp_32) R 21129 21124 4778 34817 4778 4202496 32280 0 0 0 317 23 0 0 25 0 1 0 11137371 112549888 24571 1283457024 134512640 135413687 4293036272 18446744073709551615 134657039 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/21130/statm: 27478 24571 108 220 0 27256 0 Current children cumulated CPU time (s) 7.89 Current children cumulated vsize (KiB) 156348 [startup+8.8042 s] /proc/loadavg: 1.42 1.40 1.21 2/37 21130 /proc/meminfo: memFree=180392/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=42196 CPUtime=4.49 /proc/21125/stat : 21125 (packup) S 21124 21124 4778 34817 4778 4202496 10252 27403 0 0 132 34 257 26 18 0 1 0 11136919 43208704 9842 1283457024 134512640 134752139 4292087552 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/21125/statm: 10549 9842 332 59 0 9713 0 [pid=21129] ppid=21125 vsize=1672 CPUtime=0 /proc/21129/stat : 21129 (sh) S 21125 21124 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11137370 1712128 124 1283457024 134512640 134593992 4294632016 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/21129/statm: 418 124 108 20 0 45 0 [pid=21130] ppid=21129 vsize=109532 CPUtime=4.15 /proc/21130/stat : 21130 (minisatp_32) R 21129 21124 4778 34817 4778 4202496 36411 0 0 0 389 26 0 0 25 0 1 0 11137371 112160768 23222 1283457024 134512640 135413687 4293036272 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/21130/statm: 27383 23222 117 220 0 27161 0 Current children cumulated CPU time (s) 8.64 Current children cumulated vsize (KiB) 155968 [startup+9.00862 s] /proc/loadavg: 1.42 1.40 1.21 2/37 21130 /proc/meminfo: memFree=180392/1048576 swapFree=0/0 [pid=21124] ppid=21123 vsize=2568 CPUtime=0 /proc/21124/stat : 21124 (packup2mp4pa-0.) S 21123 21124 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 11136919 2629632 273 1283457024 134512640 135304128 4290559424 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/21124/statm: 642 273 233 194 0 29 0 [pid=21125] ppid=21124 vsize=41424 CPUtime=8.74 /proc/21125/stat : 21125 (packup) R 21124 21124 4778 34817 4778 4202496 17590 63964 0 0 137 36 647 54 18 0 1 0 11136919 42418176 9662 1283457024 134512640 134752139 4292087552 18446744073709551615 4159672513 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/21125/statm: 10356 9662 345 59 0 9520 0 Current children cumulated CPU time (s) 8.74 Current children cumulated vsize (KiB) 43992 Child status: 0 Real time (s): 9.07771 CPU time (s): 8.81255 CPU user time (s): 7.91249 CPU system time (s): 0.900056 CPU usage (%): 97.079 Max. virtual memory (cumulated for all children) (KiB): 167680 getrusage(RUSAGE_CHILDREN,...) data: user time used= 7.91249 system time used= 0.900056 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 83643 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= 16 involuntary context switches= 161 runsolver used 0 second user time and 0.012 second system time The end