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/rand953.cudf.s-e-l-s-s.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand953.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand953.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.57 1.26 1.09 4/35 18300 /proc/meminfo: memFree=359048/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=3556 CPUtime=0.01 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 374 0 0 0 0 1 0 0 25 0 1 0 11093932 3641344 302 1283457024 134512640 134752139 4291415696 18446744073709551615 4157465315 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 889 302 264 59 0 53 0 [startup+0.123373 s] /proc/loadavg: 1.57 1.26 1.09 4/35 18300 /proc/meminfo: memFree=359048/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=8148 CPUtime=0.13 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 1526 0 0 0 11 2 0 0 25 0 1 0 11093932 8343552 1454 1283457024 134512640 134752139 4291415696 18446744073709551615 134681663 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 2037 1454 286 59 0 1201 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 10724 [startup+0.213389 s] /proc/loadavg: 1.57 1.26 1.09 4/35 18300 /proc/meminfo: memFree=359048/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=11316 CPUtime=0.22 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 2317 0 0 0 20 2 0 0 25 0 1 0 11093932 11587584 2245 1283457024 134512640 134752139 4291415696 18446744073709551615 4157457664 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 2829 2245 286 59 0 1993 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 13892 [startup+0.3034 s] /proc/loadavg: 1.57 1.26 1.09 4/35 18300 /proc/meminfo: memFree=359048/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=14044 CPUtime=0.31 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 3013 0 0 0 29 2 0 0 25 0 1 0 11093932 14381056 2941 1283457024 134512640 134752139 4291415696 18446744073709551615 134639888 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 3511 2941 286 59 0 2675 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 16620 [startup+0.703452 s] /proc/loadavg: 1.57 1.26 1.09 4/35 18300 /proc/meminfo: memFree=359048/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=25076 CPUtime=0.71 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 5759 0 0 0 69 2 0 0 25 0 1 0 11093932 25677824 5687 1283457024 134512640 134752139 4291415696 18446744073709551615 4157442923 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 6269 5687 286 59 0 5433 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 27652 [startup+1.50362 s] /proc/loadavg: 1.57 1.26 1.09 2/36 18301 /proc/meminfo: memFree=327912/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=48756 CPUtime=1.5 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 11759 0 0 0 146 4 0 0 25 0 1 0 11093932 49926144 11638 1283457024 134512640 134752139 4291415696 18446744073709551615 4157465315 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 12189 11638 307 59 0 11353 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 51332 [startup+3.10486 s] /proc/loadavg: 1.57 1.26 1.09 2/38 18303 /proc/meminfo: memFree=297872/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=57528 CPUtime=1.95 /proc/18300/stat : 18300 (packup) S 18299 18299 4778 34817 4778 4202496 13952 0 0 0 169 26 0 0 25 0 1 0 11093932 58908672 13596 1283457024 134512640 134752139 4291415696 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/18300/statm: 14382 13596 324 59 0 13546 0 [pid=18302] ppid=18300 vsize=1676 CPUtime=0 /proc/18302/stat : 18302 (sh) S 18300 18299 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 25 0 1 0 11094126 1716224 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/18302/statm: 419 124 108 20 0 46 0 [pid=18303] ppid=18302 vsize=27176 CPUtime=1.14 /proc/18303/stat : 18303 (minisatp_32) R 18302 18299 4778 34817 4778 4202496 6245 0 0 0 106 8 0 0 25 0 1 0 11094128 27828224 5579 1283457024 134512640 135413687 4286755568 18446744073709551615 134937886 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/18303/statm: 6794 5579 85 220 0 6572 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 88956 [startup+6.31197 s] /proc/loadavg: 1.53 1.25 1.09 2/37 18305 /proc/meminfo: memFree=270104/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=57532 CPUtime=3.96 /proc/18300/stat : 18300 (packup) S 18299 18299 4778 34817 4778 4202496 14016 11063 0 0 187 41 148 20 18 0 1 0 11093932 58912768 13605 1283457024 134512640 134752139 4291415696 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/18300/statm: 14383 13605 332 59 0 13547 0 [pid=18304] ppid=18300 vsize=1668 CPUtime=0 /proc/18304/stat : 18304 (sh) S 18300 18299 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11094329 1708032 123 1283457024 134512640 134593992 4293153008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/18304/statm: 417 123 108 20 0 44 0 [pid=18305] ppid=18304 vsize=77864 CPUtime=2.24 /proc/18305/stat : 18305 (minisatp_32) R 18304 18299 4778 34817 4778 4202496 22994 0 0 0 205 19 0 0 25 0 1 0 11094330 79732736 17454 1283457024 134512640 135413687 4289469824 18446744073709551615 134971396 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/18305/statm: 19466 17454 107 220 0 19244 0 Current children cumulated CPU time (s) 6.2 Current children cumulated vsize (KiB) 139640 Solver just ended. Dumping a history of the last processes samples [startup+6.412 s] /proc/loadavg: 1.53 1.25 1.09 2/37 18305 /proc/meminfo: memFree=270104/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=57532 CPUtime=3.96 /proc/18300/stat : 18300 (packup) S 18299 18299 4778 34817 4778 4202496 14016 11063 0 0 187 41 148 20 18 0 1 0 11093932 58912768 13605 1283457024 134512640 134752139 4291415696 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/18300/statm: 14383 13605 332 59 0 13547 0 [pid=18304] ppid=18300 vsize=1668 CPUtime=0 /proc/18304/stat : 18304 (sh) S 18300 18299 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11094329 1708032 123 1283457024 134512640 134593992 4293153008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/18304/statm: 417 123 108 20 0 44 0 [pid=18305] ppid=18304 vsize=85356 CPUtime=2.34 /proc/18305/stat : 18305 (minisatp_32) R 18304 18299 4778 34817 4778 4202496 24126 0 0 0 214 20 0 0 25 0 1 0 11094330 87404544 18396 1283457024 134512640 135413687 4289469824 18446744073709551615 134656362 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/18305/statm: 21339 18396 107 220 0 21117 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 147132 [startup+7.21222 s] /proc/loadavg: 1.53 1.25 1.09 2/37 18305 /proc/meminfo: memFree=222868/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=57532 CPUtime=3.96 /proc/18300/stat : 18300 (packup) S 18299 18299 4778 34817 4778 4202496 14016 11063 0 0 187 41 148 20 18 0 1 0 11093932 58912768 13605 1283457024 134512640 134752139 4291415696 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/18300/statm: 14383 13605 332 59 0 13547 0 [pid=18304] ppid=18300 vsize=1668 CPUtime=0 /proc/18304/stat : 18304 (sh) S 18300 18299 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11094329 1708032 123 1283457024 134512640 134593992 4293153008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/18304/statm: 417 123 108 20 0 44 0 [pid=18305] ppid=18304 vsize=90268 CPUtime=3.14 /proc/18305/stat : 18305 (minisatp_32) R 18304 18299 4778 34817 4778 4202496 28691 0 0 0 294 20 0 0 25 0 1 0 11094330 92434432 20230 1283457024 134512640 135413687 4289469824 18446744073709551615 134697051 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/18305/statm: 22567 20230 107 220 0 22345 0 Current children cumulated CPU time (s) 7.1 Current children cumulated vsize (KiB) 152044 [startup+8.01245 s] /proc/loadavg: 1.49 1.25 1.09 2/37 18305 /proc/meminfo: memFree=213320/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=57532 CPUtime=3.96 /proc/18300/stat : 18300 (packup) S 18299 18299 4778 34817 4778 4202496 14016 11063 0 0 187 41 148 20 18 0 1 0 11093932 58912768 13605 1283457024 134512640 134752139 4291415696 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/18300/statm: 14383 13605 332 59 0 13547 0 [pid=18304] ppid=18300 vsize=1668 CPUtime=0 /proc/18304/stat : 18304 (sh) S 18300 18299 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11094329 1708032 123 1283457024 134512640 134593992 4293153008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/18304/statm: 417 123 108 20 0 44 0 [pid=18305] ppid=18304 vsize=102064 CPUtime=3.94 /proc/18305/stat : 18305 (minisatp_32) R 18304 18299 4778 34817 4778 4202496 33392 0 0 0 373 21 0 0 25 0 1 0 11094330 104513536 22549 1283457024 134512640 135413687 4289469824 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/18305/statm: 25516 22549 107 220 0 25294 0 Current children cumulated CPU time (s) 7.9 Current children cumulated vsize (KiB) 163840 [startup+8.21251 s] /proc/loadavg: 1.49 1.25 1.09 2/37 18305 /proc/meminfo: memFree=213320/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=57532 CPUtime=3.96 /proc/18300/stat : 18300 (packup) S 18299 18299 4778 34817 4778 4202496 14016 11063 0 0 187 41 148 20 18 0 1 0 11093932 58912768 13605 1283457024 134512640 134752139 4291415696 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/18300/statm: 14383 13605 332 59 0 13547 0 [pid=18304] ppid=18300 vsize=1668 CPUtime=0 /proc/18304/stat : 18304 (sh) S 18300 18299 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11094329 1708032 123 1283457024 134512640 134593992 4293153008 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/18304/statm: 417 123 108 20 0 44 0 [pid=18305] ppid=18304 vsize=97608 CPUtime=4.14 /proc/18305/stat : 18305 (minisatp_32) R 18304 18299 4778 34817 4778 4202496 33406 0 0 0 392 22 0 0 25 0 1 0 11094330 99950592 21627 1283457024 134512640 135413687 4289469824 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/18305/statm: 24402 21627 117 220 0 24180 0 Current children cumulated CPU time (s) 8.1 Current children cumulated vsize (KiB) 159384 [startup+8.31253 s] /proc/loadavg: 1.49 1.25 1.09 2/37 18305 /proc/meminfo: memFree=213320/1048576 swapFree=0/0 [pid=18299] ppid=18298 vsize=2576 CPUtime=0 /proc/18299/stat : 18299 (packup2mp4pa-0.) S 18298 18299 4778 34817 4778 4202496 379 0 0 0 0 0 0 0 18 0 1 0 11093932 2637824 275 1283457024 134512640 135304128 4290508256 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/18299/statm: 644 275 233 194 0 31 0 [pid=18300] ppid=18299 vsize=56564 CPUtime=8.2 /proc/18300/stat : 18300 (packup) R 18299 18299 4778 34817 4778 4202496 25589 44617 0 0 191 45 541 43 18 0 1 0 11093932 57921536 13376 1283457024 134512640 134752139 4291415696 18446744073709551615 134536379 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/18300/statm: 14141 13376 345 59 0 13305 0 Current children cumulated CPU time (s) 8.2 Current children cumulated vsize (KiB) 59140 Child status: 0 Real time (s): 8.37637 CPU time (s): 8.28052 CPU user time (s): 7.38046 CPU system time (s): 0.900056 CPU usage (%): 98.8557 Max. virtual memory (cumulated for all children) (KiB): 167716 getrusage(RUSAGE_CHILDREN,...) data: user time used= 7.38046 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= 71538 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= 14 involuntary context switches= 144 runsolver used 0 second user time and 0 second system time The end