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/rand390.cudf.dudf-random.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-random//rand390.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand390.cudf.dudf-random.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.20 1.09 4/36 10660 /proc/meminfo: memFree=319648/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=3712 CPUtime=0 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 412 0 0 0 0 0 0 0 25 0 1 0 10439073 3801088 341 1283457024 134512640 134752139 4292403072 18446744073709551615 134694840 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 928 341 286 59 0 92 0 [startup+0.1343 s] /proc/loadavg: 1.50 1.20 1.09 4/36 10660 /proc/meminfo: memFree=319648/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=8108 CPUtime=0.14 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 1508 0 0 0 14 0 0 0 25 0 1 0 10439073 8302592 1437 1283457024 134512640 134752139 4292403072 18446744073709551615 134681583 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 2027 1437 286 59 0 1191 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 10676 [startup+0.204307 s] /proc/loadavg: 1.50 1.20 1.09 4/36 10660 /proc/meminfo: memFree=319648/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=10220 CPUtime=0.2 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 2029 0 0 0 20 0 0 0 25 0 1 0 10439073 10465280 1958 1283457024 134512640 134752139 4292403072 18446744073709551615 134681659 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 2555 1958 286 59 0 1719 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 12788 [startup+0.304324 s] /proc/loadavg: 1.50 1.20 1.09 4/36 10660 /proc/meminfo: memFree=319648/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=12976 CPUtime=0.3 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 2728 0 0 0 30 0 0 0 25 0 1 0 10439073 13287424 2657 1283457024 134512640 134752139 4292403072 18446744073709551615 134682011 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 3244 2657 286 59 0 2408 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 15544 [startup+0.704387 s] /proc/loadavg: 1.50 1.20 1.09 4/36 10660 /proc/meminfo: memFree=319648/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=22808 CPUtime=0.7 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 5197 0 0 0 70 0 0 0 25 0 1 0 10439073 23355392 5126 1283457024 134512640 134752139 4292403072 18446744073709551615 134682011 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 5702 5126 286 59 0 4866 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 25376 [startup+1.50452 s] /proc/loadavg: 1.46 1.20 1.09 2/37 10661 /proc/meminfo: memFree=291612/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=47860 CPUtime=1.5 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 11548 0 0 0 146 4 0 0 25 0 1 0 10439073 49008640 11428 1283457024 134512640 134752139 4292403072 18446744073709551615 4157314487 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 11965 11428 316 59 0 11129 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 50428 [startup+3.10487 s] /proc/loadavg: 1.46 1.20 1.09 2/39 10663 /proc/meminfo: memFree=262440/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=51044 CPUtime=1.83 /proc/10660/stat : 10660 (packup) S 10659 10659 4778 34817 4778 4202496 12332 0 0 0 159 24 0 0 25 0 1 0 10439073 52269056 12009 1283457024 134512640 134752139 4292403072 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/10660/statm: 12761 12009 324 59 0 11925 0 [pid=10662] ppid=10660 vsize=1668 CPUtime=0 /proc/10662/stat : 10662 (sh) S 10660 10659 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 25 0 1 0 10439256 1708032 123 1283457024 134512640 134593992 4286761680 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/10662/statm: 417 123 108 20 0 44 0 [pid=10663] ppid=10662 vsize=30536 CPUtime=1.25 /proc/10663/stat : 10663 (minisatp_32) R 10662 10659 4778 34817 4778 4202496 7352 0 0 0 107 18 0 0 25 0 1 0 10439258 31268864 6554 1283457024 134512640 135413687 4290281040 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/10663/statm: 7634 6554 85 220 0 7412 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 85816 [startup+6.30566 s] /proc/loadavg: 1.46 1.20 1.09 2/39 10666 /proc/meminfo: memFree=260332/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=51048 CPUtime=5.05 /proc/10660/stat : 10660 (packup) S 10659 10659 4778 34817 4778 4202496 12406 26283 0 0 171 42 259 33 18 0 1 0 10439073 52273152 12018 1283457024 134512640 134752139 4292403072 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/10660/statm: 12762 12018 332 59 0 11926 0 [pid=10665] ppid=10660 vsize=1672 CPUtime=0.01 /proc/10665/stat : 10665 (sh) S 10660 10659 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10439580 1712128 124 1283457024 134512640 134593992 4291112704 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/10665/statm: 418 124 108 20 0 45 0 [pid=10666] ppid=10665 vsize=29160 CPUtime=1.23 /proc/10666/stat : 10666 (minisatp_32) R 10665 10659 4778 34817 4778 4202496 6734 0 0 0 115 8 0 0 24 0 1 0 10439581 29859840 6109 1283457024 134512640 135413687 4288351344 18446744073709551615 134973377 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/10666/statm: 7290 6109 85 220 0 7068 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 84448 Solver just ended. Dumping a history of the last processes samples [startup+6.40568 s] /proc/loadavg: 1.46 1.20 1.09 2/39 10666 /proc/meminfo: memFree=260332/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=51048 CPUtime=5.05 /proc/10660/stat : 10660 (packup) S 10659 10659 4778 34817 4778 4202496 12406 26283 0 0 171 42 259 33 18 0 1 0 10439073 52273152 12018 1283457024 134512640 134752139 4292403072 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/10660/statm: 12762 12018 332 59 0 11926 0 [pid=10665] ppid=10660 vsize=1672 CPUtime=0.01 /proc/10665/stat : 10665 (sh) S 10660 10659 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10439580 1712128 124 1283457024 134512640 134593992 4291112704 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/10665/statm: 418 124 108 20 0 45 0 [pid=10666] ppid=10665 vsize=30144 CPUtime=1.33 /proc/10666/stat : 10666 (minisatp_32) R 10665 10659 4778 34817 4778 4202496 7210 0 0 0 119 14 0 0 25 0 1 0 10439581 30867456 6467 1283457024 134512640 135413687 4288351344 18446744073709551615 134688818 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/10666/statm: 7536 6467 89 220 0 7314 0 Current children cumulated CPU time (s) 6.39 Current children cumulated vsize (KiB) 85432 [startup+7.2059 s] /proc/loadavg: 1.42 1.20 1.09 2/39 10666 /proc/meminfo: memFree=232928/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=51048 CPUtime=5.05 /proc/10660/stat : 10660 (packup) S 10659 10659 4778 34817 4778 4202496 12406 26283 0 0 171 42 259 33 18 0 1 0 10439073 52273152 12018 1283457024 134512640 134752139 4292403072 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/10660/statm: 12762 12018 332 59 0 11926 0 [pid=10665] ppid=10660 vsize=1672 CPUtime=0.01 /proc/10665/stat : 10665 (sh) S 10660 10659 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10439580 1712128 124 1283457024 134512640 134593992 4291112704 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/10665/statm: 418 124 108 20 0 45 0 [pid=10666] ppid=10665 vsize=88136 CPUtime=2.12 /proc/10666/stat : 10666 (minisatp_32) R 10665 10659 4778 34817 4778 4202496 24754 0 0 0 192 20 0 0 25 0 1 0 10439581 90251264 19465 1283457024 134512640 135413687 4288351344 18446744073709551615 134686457 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/10666/statm: 22034 19465 108 220 0 21812 0 Current children cumulated CPU time (s) 7.18 Current children cumulated vsize (KiB) 143424 [startup+8.00614 s] /proc/loadavg: 1.42 1.20 1.09 2/39 10666 /proc/meminfo: memFree=188908/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=51048 CPUtime=5.05 /proc/10660/stat : 10660 (packup) S 10659 10659 4778 34817 4778 4202496 12406 26283 0 0 171 42 259 33 18 0 1 0 10439073 52273152 12018 1283457024 134512640 134752139 4292403072 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0 /proc/10660/statm: 12762 12018 332 59 0 11926 0 [pid=10665] ppid=10660 vsize=1672 CPUtime=0.01 /proc/10665/stat : 10665 (sh) S 10660 10659 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 10439580 1712128 124 1283457024 134512640 134593992 4291112704 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0 /proc/10665/statm: 418 124 108 20 0 45 0 [pid=10666] ppid=10665 vsize=94924 CPUtime=2.92 /proc/10666/stat : 10666 (minisatp_32) R 10665 10659 4778 34817 4778 4202496 28558 0 0 0 269 23 0 0 25 0 1 0 10439581 97202176 20790 1283457024 134512640 135413687 4288351344 18446744073709551615 135139726 0 0 18944 0 0 0 0 17 0 0 0 0 /proc/10666/statm: 23731 20790 108 220 0 23509 0 Current children cumulated CPU time (s) 7.98 Current children cumulated vsize (KiB) 150212 [startup+8.40622 s] /proc/loadavg: 1.42 1.20 1.09 2/39 10666 /proc/meminfo: memFree=188908/1048576 swapFree=0/0 [pid=10659] ppid=10658 vsize=2568 CPUtime=0 /proc/10659/stat : 10659 (packup2mp4pa-0.) S 10658 10659 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 10439073 2629632 273 1283457024 134512640 135304128 4292145024 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0 /proc/10659/statm: 642 273 233 194 0 29 0 [pid=10660] ppid=10659 vsize=49692 CPUtime=8.39 /proc/10660/stat : 10660 (packup) R 10659 10659 4778 34817 4778 4202496 22686 56432 0 0 178 48 554 59 18 0 1 0 10439073 50884608 11692 1283457024 134512640 134752139 4292403072 18446744073709551615 4157295544 0 0 18944 8192 0 0 0 17 0 0 0 0 /proc/10660/statm: 12423 11692 345 59 0 11587 0 Current children cumulated CPU time (s) 8.39 Current children cumulated vsize (KiB) 52260 Child status: 0 Real time (s): 8.43395 CPU time (s): 8.42853 CPU user time (s): 7.34046 CPU system time (s): 1.08807 CPU usage (%): 99.9357 Max. virtual memory (cumulated for all children) (KiB): 157288 getrusage(RUSAGE_CHILDREN,...) data: user time used= 7.34046 system time used= 1.08807 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 80271 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= 140 runsolver used 0 second user time and 0 second system time The end